Before any JRockit performance tuning, you need to assess the sizes of the objects allocated by your application.[4] One way to access live data size is to view object allocation statistics from the GC log file.
In this article, we will show you how to access object allocation statistics by enabling the JRockit verbose output:
The -Xverbose:memdbg log module is an alias that starts several memory-related log modules to provide a complete picture of the memory management. The memdbg log module sets the memory module to the debug level. This information can also be obtained by setting:
The overhead of the verbose memdbg output is low, which means it can be used in production environments. For example, after enabling -Xverbose:memdb, the overhead has caused the Average Response Time (ART) to deteriorate by 2.25% using our benchmark.
After setting the memory module to the debug level, JRockit provides us tons of information. To understand its formats, read [1]. Here we will focus only on OC's (old collections). For example, here is a typical output from the memory log module at the debug level:
Note that we have used the following JRockit options:
Old collections can be triggered by different events. For example, in the above example, it shows the reason for OC#41 is:
In this article, we will show you how to access object allocation statistics by enabling the JRockit verbose output:
- -Xverbose:memdbg
Verbose memdbg Log Module[1]
The -Xverbose:memdbg log module is an alias that starts several memory-related log modules to provide a complete picture of the memory management. The memdbg log module sets the memory module to the debug level. This information can also be obtained by setting:
- -Xverbose:memory=debug
The overhead of the verbose memdbg output is low, which means it can be used in production environments. For example, after enabling -Xverbose:memdb, the overhead has caused the Average Response Time (ART) to deteriorate by 2.25% using our benchmark.
Understanding Verbose Output
After setting the memory module to the debug level, JRockit provides us tons of information. To understand its formats, read [1]. Here we will focus only on OC's (old collections). For example, here is a typical output from the memory log module at the debug level:
[DEBUG][memory ][06310] [OC#41] GC reason: Allocation request failed (1048592 bytes).
[DEBUG][memory ][06310] [OC#41] 2607.371: OC started.
[INFO ][alloc ][06310] [OC#41] Pending requests at 'Before OC' - Total: 1, TLAs: 0(approx 0 bytes), objects: 1 (1048592 bytes). Max age: 0.
[INFO ][compact][06310] [OC#41] Compaction reason: Normal.
[INFO ][compact][06310] [OC#41] Compacting 128 of 4096 parts at index 384. Compaction type is internal. Exceptional: No.
[INFO ][compact][06310] [OC#41] Compaction area start: 0x8c000000, end: 0x90000000.
Timeout: 411.471 ms.
[INFO ][compact][06310] [OC#41] Compactset limit (per thread): 316839 (dynamic), not using matrixes.
[DEBUG][memory ][06310] [OC#41] Starting parallel marking phase.
[DEBUG][memory ][06310] [OC#41] SemiRef phase WeakJNIHandles run in single threadedmode.
[DEBUG][memory ][06310] [OC#41] SemiRef phase ClassConstraints run in single threaded mode.
[DEBUG][memory ][06310] [OC#41] SemiRef phase FinalMemleak run in single threaded mode.
[DEBUG][memory ][06310] [OC#41] Adding 48 temporary work packets to permanent pool,now 811 packets.
[DEBUG][memory ] [OC#41] Total mark time: 307.204 ms.
[DEBUG][memory ] [OC#41] Ending marking phase.
[DEBUG][memory ] [OC#41] Starting parallel sweeping phase.
[INFO ][nursery] [OC#41] Setting keepAreaMarkers[0] to 0xc9872bc0.
[INFO ][nursery] [OC#41] Setting keepAreaMarkers[1] to 0xcc97f7a0.
[INFO ][nursery] [OC#41] Setting keepAreaMarkers[2] to 0xd20f6088.
[INFO ][nursery] [OC#41] Next keeparea will start at 0xcc97f7a0 and end at 0xd20f6088.
[INFO ][nursery] [OC#41] Nursery size increased from 0KB to 120414KB. Nursery list consists of 2760 parts.
[INFO ][nursery] [OC#41] Average part size: 44KB. Contraharmonic mean (CHM):946KB. CHM per part: 0KB. Normalized CHM: 0.007856.
[DEBUG][memory ][ [OC#41] Total sweep time: 159.954 ms.
[DEBUG][memory ] [OC#41] Ending sweeping phase.
[INFO ][nursery] [OC#41] Nursery size remains at 120414KB. Nursery list consists of 2760 parts.
[INFO ][nursery] [OC#41] Average part size: 44KB. Contraharmonic mean (CHM):946KB. CHM per part: 0KB. Normalized CHM: 0.007856.
[INFO ][alloc ] [OC#41] Satisfied 0 object and 0 tla allocations. Pending requests went from 1 to 1.
[INFO ][compact] [OC#41] Average compact time ratio (move phase/total time):0.655049.
[INFO ][compact] [OC#41] Compaction time, total: 158.705 ms (target 411.471 ms).
[INFO ][compact] [OC#41] Compaction moved 1295486 objects and left 349 objects. Total moved size 64028976B.
[INFO ][compact] [OC#41] Compaction added 3047752B of free memory in 2 parts.
[INFO ][compact] [OC#41] Compaction time, move phase: 58.023 ms (target 205.735 ms).
[INFO ][compact] [OC#41] Compaction time, update phase: 100.669 ms (target 205.735 ms).
[INFO ][compact] [OC#41] Found 3350566 references. Internal: 1807732 External: 1542834.
[INFO ][compact] [OC#41] Updated 3339159 references. Internal: 1807048 External: 1532111.
[INFO ][alloc ] [OC#41] Pending requests at 'After OC' - Total: 1, TLAs: 0 (approx 0 bytes), objects: 1 (1048592 bytes). Max age: 1.
[DEBUG][memory ] [OC#41] Page faults before OC: 1, page faults after OC: 1, pages in heap: 524288.
[DEBUG][memory ] [OC#41] Nursery size after OC: 120414KB. (Free: 120371KB Parts: 2760)
[INFO ][memory ] [OC#41] 2607.371-2607.928: OC 1890153KB->1756549KB (2097152KB), 0.558 s, sum of pauses 472.469 ms, longest pause 472.469 ms.
Note that we have used the following JRockit options:
- -Xverbose:memdbg -Xverbose:gc -Xverbosedecorations=level,module,timestamp,millis,pid
GC Reason
Old collections can be triggered by different events. For example, in the above example, it shows the reason for OC#41 is:
- Allocation request failed
There are other events can trigger an OC. For example, it can be:
- GC reason: Artificial, description: Print Heap Summary
- GC reason: Artificial, description: Print Heap Diagnostics
From our GC log file, we have found the following OC statistics (total: 235)
- GC reason: Allocation request failed (total: 219)
- GC reason: Artificial, description: Print Heap Summary (total: 8)
- GC reason: Artificial, description: Print Heap Diagnostics (total: 8)
Among all events, you can count those artificial heap printing events as the overhead of enabling:
- -Xverbose:memdbg
No comments:
Post a Comment