How to Measure Allocation Rate?

One way to measure the allocation rate is to turn on GC logging by specifying -XX:+PrintGCDetails -XX:+PrintGCTimeStamps flags for the JVM. The JVM now starts logging the GC pauses similar to the following:

From the GC log above, we can calculate the allocation rate as the difference between the sizes of the young generation after the completion of the last collection and before the start of the next one. Using the example above, we can extract the following information:

At 291 ms after the JVM was launched, 33,280 K of objects were created. The first minor GC event cleaned the young generation, after which there were 5,088 K of objects in the young generation left.

At 446 ms after launch, the young generation occupancy had grown to 38,368 K, triggering the next GC, which managed to reduce the young generation occupancy to 5,120 K.

At 829 ms after the launch, the size of the young generation was 71,680 K and the GC reduced it again to 5,120 K.

This data can then be expressed in the following table calculating the allocation rate as deltas of the young occupancy:

Event

Time

Young before

Young after

Allocated during

Allocation rate

1st GC

291ms

33,280KB

5,088KB

33,280KB

114MB/sec

2nd GC

446ms

38,368KB

5,120KB

33,280KB

215MB/sec

3rd GC

829ms

71,680KB

5,120KB

66,560KB

174MB/sec

Total

829ms

N/A

N/A

133,120KB

161MB/sec

Having this information allows us to say that this particular piece of software had the allocation rate of 161 MB/sec during the period of measurement.