|
|
The
-Xverbose command line option enables verbose outputs from the Oracle JRockit JVM. You can use these verbose outputs for monitoring, tuning and diagnostics. This chapter describes some of the most useful verbose modules and how to interpret the outputs from them.
| Note: | Outputs may differ between JVM versions and that the exact format is subject to changes at any time. |
This chapter is divided into two sections:
Many of the verbose modules available in the JRockit JVM are dedicated to memory management and garbage collection.Table 19-1 lists the verbose modules described in this section.
Most verbose modules are available in several log levels. This section covers only the default (info) log level, which is the most useful for general tuning and monitoring purposes.
The -Xverbose:memory (or -Xverbose:gc) module provides basic information on garbage collection events. The overhead for this module is very low, which means that you can enable it even in a production environment.
At JVM startup the memory log module outputs some basic numbers on the memory management system configuration and a guide to how to read the garbage collection printouts.
Listing 19-1 shows an example of the initial output from the memory log module. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [memory ] GC mode: Garbage collection optimized for throughput, initial strategy: Generational Parallel Mark & Sweep
2: [memory ] heap size: 307200K, maximal heap size: 307200K, nursery size: 153600K
3: [memory ] <s>-<end>: GC <before>K-><after>K (<heap>K), <pause> ms
4: [memory ] <s/start> - start time of collection (seconds since jvm start)
5: [memory ] <end> - end time of collection (seconds since jvm start)
6: [memory ] <before> - memory used by objects before collection (KB)
7: [memory ] <after> - memory used by objects after collection (KB)
8: [memory ] <heap> - size of heap after collection (KB)
9: [memory ] <pause> - total sum of pauses during collection (milliseconds)
10: [memory ] run with -Xverbose:gcpause to see individual pauses
Line 1 describes the garbage collection mode used in this run, as well as the initial garbage collection strategy.
Line 2 shows you the initial and maximum heap size, as well as the initial nursery size.
Lines 3-10 describe the format of the garbage collection outputs.
The memory log module prints out a line for each garbage collection.
Listing 19-2 shows a snippet of verbose outputs from the memory log module. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [memory ] 83.976: parallel nursery GC 307200K->191044K (307200K), 35.584 ms
2: [memory ] 84.772-85.766: GC 288200K->73425K (307200K), 994.090 ms
3: [memory ] 87.036: parallel nursery GC 233783K->119655K (307200K), 57.716 ms
4: [memory ] 87.974: parallel nursery GC 233655K->119527K (307200K), 35.876 ms
Each garbage collection output starts with a timestamp, which is the time in seconds since the JVM started. At the end of each line you can also see the total heap size within parenthesis, and the total garbage collection duration for each garbage collection. Note that the garbage collection duration may consist of both pauses and concurrent garbage collection phases.
Lines 1, 3 and 4 are outputs from young collections. The young collection on line 1 reduced the amount of occupied heap from 307200 KB to 191044 KB.
Line 2 is an output from an old collection, which reduced the amount of occupied heap from 288200 KB to 73425 KB.
Page faults cause memory access to become slow, and page faults during garbage collection may cause long garbage collection times. Because of this, the verbose memory log module prints out a warning whenever the number of page faults during the garbage collection was more than 5% of the number of pages in the heap.
Listing 19-3 shows an example of a page fault warning. This example is from the JRockit JVM R27.4.
[memory ] Warning: Your computer has generated 9435 page faults during the last garbage collection.
[memory ] If you find this swapping problematic, please consider running JRockit with a smaller heap.
The -Xverbose:nursery log module provides details on young collections and nursery sizing. Some of this information is useful for monitoring and tuning the JRockit JVM. The overhead is very low, which means that you can enable this module even in a production environment.
The nursery log module is available in the JRockit JVM R27.2 and later releases.
Listing 19-4 shows an example of an output from the nursery log module during a young collection. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [nursery] KeepAreaStart: 0x015FFFF0 KeepAreaEnd: 0x01AFFFF0
2: [nursery] Young collection 86 started. This YC is running while the OC is in phase: not running.
3: [nursery] Setting mmNurseryMarker[0] to 0x015FFFF0
4: [nursery] Setting mmNurseryMarker[1] to 0x01AFFFF0
Lines 1, 3 and 4 contain information related to the keep area size and position. This information is only interesting for advanced diagnostics.
Line 2 shows you the sequence number of the young collection. It also informs you that the old collection is not running while this young collection is running. Other possible old collection phases are marking, precleaning and sweeping, which are the concurrent phases of the concurrent old collection.
Some garbage collection modes and strategies will adjust the nursery size in runtime for optimal performance. The nursery log module shows some information on the nursery sizing calculations and nursery size changes.
Listing 19-5 shows an example of nursery sizing outputs from an old collection. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [nursery] Optimal nursery size: 157286400, free heap: 314572800
2: [nursery] Nursery size increased from 0kb to 153600kb. Parts: 4023
Line 1 shows you that the heuristics have found that an optimal nursery size would be 157286400 bytes. The memory management system may however not be able to create a nursery of exactly this size.
Line 2 states that the nursery size is being increased from 0 (no nursery) to 153600 KB, and that the nursery consists of 4023 chunks.
The -Xverbose:memdbg log module provides details on garbage collection and memory management. Enabling this log module also enables some other log modules, for example the nursery log module. This section only describes the outputs labeled memdbg, all other verbose outputs have been removed from the examples.
The overhead of the verbose memdbg outputs is low, and thus it can be used in production environments.
Listing 19-6 shows an example of the initial output from the memdbg verbose module. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [memdbg ] Memory layout after heap allocation:
2: [memdbg ] ' ' - free, '-' - OS reserved range, 'r' - reserved, 'x' - committed,
3: [memdbg ] '+' - committed/read, 'e' - committed/executable
4: [memdbg ] 'J' - java heap, 'j' - java heap data structures
5: [memdbg ] 00 0.00Gb -eeJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ
6: [memdbg ] 10 0.25Gb JJJJJJJJJJJJJJ
7: [memdbg ] 20 0.50Gb
8: [memdbg ] 30 0.75Gb
9: [memdbg ] 40 1.00Gb
10: [memdbg ] 50 1.25Gb
11: [memdbg ] 60 1.50Gb
12: [memdbg ] 70 1.75Gb e e - e e e ejj
13: [memdbg ] 80 2.00Gb ----------------------------------------------------------------
14: [memdbg ] 90 2.25Gb ----------------------------------------------------------------
15: [memdbg ] a0 2.50Gb ----------------------------------------------------------------
16: [memdbg ] b0 2.75Gb ----------------------------------------------------------------
17: [memdbg ] c0 3.00Gb ----------------------------------------------------------------
18: [memdbg ] d0 3.25Gb ----------------------------------------------------------------
19: [memdbg ] e0 3.50Gb ----------------------------------------------------------------
20: [memdbg ] f0 3.75Gb ----------------------------------------------------------------
21: [memdbg ] Minimum TLA size is 2048 bytes
22: [memdbg ] Preferred TLA size is 38912 bytes
23: [memdbg ] Large object limit is 2048 bytes
24: [memdbg ] Minimal blocksize on the freelist is 2048 bytes
25: [memdbg ] Initial and maximum number of gc threads: 2, of which 2 parallel threads, 1 concurrent threads, and 2 yc threads
26: [memdbg ] Prefetch distance in balanced tree: 4
27: [memdbg ] Using prefetch linesize: 32 bytes chunks: 512 bytes pf_dist: 64 bytes
Lines 1-20 describe the memory lay-out in the machine after the Java heap has been allocated. This information can be used for diagnosing problems related to heap positioning.
Lines 21-24 show you the minimum and preferred Thread Local Area sizes, the large object limit and the minimum block size on the freelist. These values may depend on the heap size and the garbage collector, as well as the JRockit JVM version.
Line 25 informs you of the number of garbage collection threads.
Line 26 and 27 contain information on prefetching, which is mostly useful for advanced diagnosing and tuning.
The memdbg module adds a lot of useful information to the garbage collection outputs. For most tuning and diagnosing, this information is essential. The outputs differ between garbage collection types.
Listing 19-7 shows an example of a verbose memdbg output from a single generational parallel old collection. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [memdbg ] GC reason: System.gc() called, cause: System.gc()
2: [memdbg ] Stopping of javathreads took 0.213 ms
3: [memdbg ] old collection 1 started
4: [memdbg ] Alloc Queue size before GC: 0, tlas: 0, oldest: 0
5: [memdbg ] Compacting 8 heap parts at index 120 (type external) (exceptional false)
6: [memdbg ] Starting parallel marking phase.
7: [memdbg ] Hard handles: Processed 1946 handles during normal processing.
8: [memdbg ] Weak handles: Processed 104 handles during normal processing.
9: [memdbg ] total mark time: 7.440 ms
10: [memdbg ] ending marking phase
11: [memdbg ] starting parallel sweeping phase
12: [memdbg ] total sweep time: 3.844 ms
13: [memdbg ] ending sweeping phase
14: [memdbg ] Alloc Queue size after GC: 0, tlas: 0, oldest: 0
15: [memdbg ] Page faults before GC: 6618, page faults after GC: 7938, pagesin heap: 76800
16: [memdbg ] Restarting of javathreads took 0.023 ms
Line 1 displays the reason for the garbage collection. In this example the garbage collection was triggered by a System.gc() call.
Line 2 displays the time it took to stop all Java threads for garbage collection, in this case 0.213 ms. This information is useful for latency diagnosing.
Line 3 shows the sequence number of the garbage collection.
Line 4 contains information on the object allocation queue status at the start of the garbage collection. The allocation queue contains all pending object allocation requests that have not yet been satisfied. In this example the allocation queue is empty, which is normal when the garbage collection is started by System.gc().
Line 5 shows you the compaction planned for this garbage collection. In this example 8 heap parts will be compacted starting at heap part 120. The compaction type is external, which means that objects are moved out of the compaction area, and the compaction is not exceptional, which means that it may be aborted or interrupted if the compaction heuristics decide that it will take too long to perform the compaction.
Line 6 marks the start of the mark phase.
Lines 7 and 8 show information on weak and hard handles. This is mostly useful for advanced diagnostics and monitoring.
Line 9 shows you the total time for the mark phase. This time can include both pauses and concurrent phases, although in this case the entire mark phase is done while the Java threads are paused.
Line 10 marks the end of the mark phase.
Line 11 marks the start of the sweep phase.
Line 12 shows you the total time for the sweep phase. This time can include both pauses and concurrent phases, although in this case the entire mark phase is done while the Java threads are paused.
Line 13 marks the end of the sweep phase.
Line 14 displays information on the status of the object allocation queue after the garbage collection. You can compare this information to the information on line 4 to get an idea of how well object allocation is faring. Many objects in the allocation queue at the end of a garbage collection may be an indication that object allocation is difficult, for example due to heavy fragmentation.
Line 15 shows statistics on page faults before and after the garbage collection. Page faults during the garbage collection may slow down the garbage collection severely.
Line 16 displays the time it took to restart all Java threads after garbage collection. This information is useful for latency diagnosing.
The memdbg module adds a lot of useful information to the garbage collection outputs. For most tuning and diagnosing, this information is essential. The outputs differ between garbage collection types.
Listing 19-8 shows an example of a verbose memdbg output from a single generational mostly concurrent old collection. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [memdbg ] GC reason: GC trigger reached, cause: Heap too full
2: [memdbg ] Stopping of javathreads took 0.425 ms
3: [memdbg ] old collection 5 started
4: [memdbg ] Alloc Queue size before GC: 0, tlas: 0, oldest: 0
5: [memdbg ] Compacting 16 heap parts at index 112 (type internal) (exceptional false)
6: [memdbg ] Starting initial marking phase (OC1).
7: [memdbg ] Restarting of javathreads took 31.908 ms
8: [memdbg ] Starting concurrent marking phase (OC2).
9: [memdbg ] Hard handles: Processed 4251 handles during concurrent processing.
10: [memdbg ] Starting precleaning phase (OC3).
11: [memdbg ] Weak handles: Processed 146 handles during concurrent processing.
12: [memdbg ] Stopping of javathreads took 0.219 ms
13: [memdbg ] Starting final marking phase (OC4).
14: [memdbg ] Hard handles: Processed 8 handles during remaining processing.
15: [memdbg ] Weak handles: Processed 40 handles during remaining processing.
16: [memdbg ] total concurrent mark time: 512.526 ms
17: [memdbg ] ending marking phase
18: [memdbg ] starting concurrent sweeping phase
19: [memdbg ] total concurrent sweep time: 54.623 ms
20: [memdbg ] ending sweeping phase
21: [memdbg ] Alloc Queue size after GC: 0, tlas: 0, oldest: 0
22: [memdbg ] gc-trigger is 13.200 %
23: [memdbg ] Page faults before GC: 89592, page faults after GC: 92886, pages in heap: 76800
24: [memdbg ] Restarting of javathreads took 0.030 ms
Line 1 displays the reason for the garbage collection. In this example the garbage collection was started because the heap occupancy reached the limit for when a concurrent garbage collection should be started.
Line 2 displays the time it took to stop all Java threads for garbage collection, in this case 0.425 ms. Similar information is displayed on line 12. This information is useful for latency diagnosing.
Line 3 shows the sequence number of the garbage collection.
Line 4 contains information on the object allocation queue status at the start of the garbage collection. The allocation queue contains all pending object allocation requests that have not yet been satisfied. In this example the allocation queue is empty.
Line 5 shows you the compaction planned for this garbage collection. In this example 16 heap parts will be compacted starting at heap part 112. The compaction type is internal, which means that objects are moved within the compaction area, and the compaction is not exceptional, which means that it may be aborted or interrupted if the compaction heuristics decide that it will take too long to perform the compaction.
Line 6 marks the start of the initial mark phase.
Line 7 displays the time it took to start the Java threads for the concurrent marking phase. Similar information is displayed on line 24.
Line 8 marks the start of the concurrent mark phase.
Lines 9, 11, 14 and 15 show information on weak and hard handles. This is mostly useful for advanced diagnostics and monitoring.
Line 10 marks the start of the concurrent precleaning phase.
Line 13 marks the start of the final marking phase.
Line 16 shows you the total time for the mark phase. This time includes both pauses and concurrent phases.
Line 17 marks the end of the mark phase.
Line 18 marks the start of the sweep phase.
Line 19 shows you the total time for the sweep phase. This time includes both pauses and concurrent phases.
Line 20 marks the end of the sweep phase.
Line 21 displays information on the status of the object allocation queue after the garbage collection. You can compare this information to the information on line 4 to get an idea of how well object allocation is faring. Many objects in the allocation queue at the end of a garbage collection may be an indication that object allocation is difficult, for example due to heavy fragmentation.
Line 22 displays the value of the GC trigger. The next concurrent old collection will start when less than this percentage of the heap is free.
Line 23 shows statistics on page faults before and after the garbage collection. Page faults during the garbage collection may slow down the garbage collection severely.
Listing 19-9 shows an example of a verbose memdbg output from a young collection. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [memdbg ] GC reason: TLA allocation failed, cause: Get TLA From Nursery
2: [memdbg ] Stopping of javathreads took 0.198 ms
3: [memdbg ] Hard handles: Processed 4259 handles during normal processing.
4: [memdbg ] Weak handles: Processed 144 handles during normal processing.
5: [memdbg ] nursery GC 86: promoted 48984 objects (1718K) in 39.310 ms
6: [memdbg ] Page faults before GC: 89240, page faults after GC: 89754, pages in heap: 76800
7: [memdbg ] Nursery size after YC: 20971520
8: [memdbg ] Restarting of javathreads took 0.030 ms
Line 1 displays the reason for the garbage collection. In this example the garbage collection was started because allocation of a thread local area failed. This is the normal reason for starting a young collection.
Line 2 displays the time it took to stop all Java threads for garbage collection, in this case 0.198 ms. This information is useful for latency diagnosing.
Lines 3 and 4 show information on weak and hard handles. This is mostly useful for advanced diagnostics and monitoring.
Line 5 shows details on the young collection. 48984 objects of a total size of 1718 KB were promoted during this young collection. The young collection took 39.310 ms.
Line 6 shows statistics on page faults before and after the garbage collection. Page faults during the garbage collection may slow down the garbage collection severely.
Line 7 shows the nursery size after the young collection.
Line 8 displays the time it took to start all Java threads after the garbage collection, in this case 0.030 ms.
Verbose memdbg outputs tell you if compaction is aborted due to too many pointers to the compaction area. When that happens, the following output is printed:
[memdbg ] Pointerset limit hit, compaction aborted.
If the heap becomes full during the mark phase of a concurrent old collection, the garbage collector will by default override the concurrent sweep phase and use parallel sweep instead. When that happens, the following output is printed:
[memdbg ] The heap became full during concurrent mark. Running parallel sweep.
The JRockit JVM performs partial compaction of the heap at each old collection. Compaction reduces fragmentation in the heap, which makes object allocation faster. The verbose compaction log module displays details on compaction. The overhead of this log module is low, which means that it can be enabled in production environments.
Listing 19-10 shows an example of a verbose output from the compaction log module. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [compact] OC 4: 8 parts (max 128), index 8. Type internal, (exceptional false)
2: [compact] Area start: 0x01EC0000, end: 0x03180000
3: [compact] Updated 14130 references in 0 nonmoved and 11700 moved objects
4: [compact] Average compact time ratio: 0.442280
5: [compact] Compaction pause: 2.548 (target 50.000), update ref pause: 10.025 (target 50.000)
6: [compact] Updated 59048 refs (limit: 84386).
7: [compact] Compaction ended at index 15, object end address 0x03179A00.
8: [compact] Summary: 4;8;15;8;1;0;2.548;50.000;10.025;50.000;59048;84386
9: [compact] Adjusting compactsetlimit: 102698
10: [compact] Pause per 1000 refs, current: 0.169920, average: 0.486862. Target pause: 50.000
Line 1 shows a summary of the upcoming compaction. In this example the sequence number of the old collection is 4. 8 heap parts out of a total of 128 heap parts will be compacted, starting at index 8. The compaction type is internal, which means that objects will be moved within the compaction area. The compaction is not exceptional, which means that it can be aborted or interrupted if it takes too long.
Line 2 shows the physical addresses of the start and the end of the compaction area. This information is useful for advanced diagnostics.
Line 3 displays statistics on the number of references updated within the compaction area due to moved objects. In this example 14130 references were updated in 11700 moved objects.
Line 4 informs you that the average ratio between time spent in moving objects and updating references to moved objects is 0.44.
Line 5 shows detailed information on the two components of the pause time caused by compaction, as well as the current pause targets for these components. In this example, moving objects took only 2.548 ms and updating references to moved objects took 10.025 ms, while the target was 50 ms for each of the components.
Line 6 shows the total number of references updated, both those within the compaction area and those outside the compaction area that pointed at objects within the compaction area. This information is useful for monitoring and tuning.
Line 7 shows the end index and physical address of the compaction. This information is useful for diagnostics.
Line 8 contains a machine readable summary of some of the statistics from this compaction. This line is useful for collecting statistics.
Line 9 informs you that the compaction heuristics have adjusted the compact set limit. The compact set limit determines the amount of compaction that can be done at each old collection.
Line 10 shows statistics on the average time for updating 1000 references. This value is used as a base for the compact set limit calculation.
Whenever a compaction is aborted, the verbose compaction log module will display information on the reason for the aborted compaction. In the following example the pointer matrix for a garbage collection thread reached its top limit, which means that there were too many pointers to objects within the selected compaction area.
[compact] Pointermatrix for thread '(GC Worker Thread 1)' failed to extend beyond 25817 elements.
The -Xverbose:gcpause log module displays information on individual garbage collection pauses. For monitoring, tuning and diagnosing latencies this information is essential. The overhead of the log module is low, which means that it can be used in production environments.
A parallel old collection pauses all Java threads during the entire garbage collection. The output from -Xverbose:gcpause during a parallel old collection is thus fairly simple, as seen in Listing 19-11. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [gcpause] Threads waited for memory 147.424 ms starting at 6.398 s
2: [gcpause] old collection phase 1-0 pause time: 146.861682 ms, (start time: 6.398 s)
3: [gcpause] (pause includes compaction: 10.169 ms (external), update ref: 14.390 ms)
Line 1 tells you that Java threads waited 147.424 ms for memory due to the old collection. This value can be different than the old collection pause time.
Line 2 shows the pause time for “phase 1-0” of the old collection. Phase 1 is the first phase, while phase 0 is the default phase while the garbage collection isn’t running. This means that the timing started in phase 1 and ended after the garbage collector was finished, and thus includes the entire garbage collection.
Line 3 shows some details on how much of the pause time consisted of compaction and reference updates due to compaction.
A mostly concurrent (or “concurrent”) old collection consists of several concurrent garbage collection phases with short pauses in between.
Listing 19-12 shows an example of an output from a mostly concurrent old collection. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [gcpause] old collection phase 1 pause time: 19.184561 ms, (start time: 24.027 s)
2: [gcpause] old collection phase 4-5 pause time: 25.100956 ms, (start time: 24.720 s)
3: [gcpause] (pause includes yc: 24.456 ms, compaction: 0.230 ms (external), update ref: 0.003 ms)
4: [gcpause] old collection phase 5 pause time: 0.253384 ms, (start time: 24.769 s)
5: [gcpause] old collection phase 5-0 pause time: 1.751061 ms, (start time: 1.391 s)
Line 1 shows the pause time for phase 1 of the old collection. Phase 1 is the initial marking phase.
Line 2 shows the pause time for the pause that starts with phase 4 and ends at the beginning of phase 5 of the old collection. This phase is the final marking phase and compaction.
Line 3 shows some details of the phase 4-5 pause. The young collection performed in phase 4 took 24.456 ms, the compaction took 0.23 ms and reference updates after compaction took 0.003 ms. This information is useful for tuning and diagnosing compaction pause times.
Line 4 shows the pause time for the pause in the middle of phase 5. Phase 5 is the concurrent sweep phase. The heap is swept in two parts, and the short pause is for switching parts to sweep.
Line 5 shows the pause time for the pause at the end of phase 5, where final statistics are collected and the garbage collection is wrapped up.
A young collection consists of a single pause. Thus the verbose gcpause output for a young collection is very simple, as seen in this example:
[gcpause] nursery collection pause time: 37.832462 ms
The -Xverbose:gcreport log module prints out a summary of garbage collection activity at the end of the run.
Listing 19-13 shows an example of a verbose gcreport output. This example is from the JRockit JVM R27.4. Line numbers have been added.
1: [memory ] Memory usage report
2: [memory ]
3: [memory ] young collections
4: [memory ] number of collections = 5647
5: [memory ] total promoted = 58920467 (size 2144906056)
6: [memory ] max promoted = 219349 (size 10249784)
7: [memory ] total GC time = 37.543 s
8: [memory ] mean GC time = 6.648 ms
9: [memory ] maximum GC Pauses = 59.602 , 71.426, 75.759 ms
10: [memory ]
11: [memory ] old collections
12: [memory ] number of collections = 34
13: [memory ] total promoted = 776698 (size 28208080)
14: [memory ] max promoted = 72997 (size 2655216)
15: [memory ] total GC time = 13.970 s (pause 4.583 s)
16: [memory ] mean GC time = 410.872 ms (pause 134.790 ms)
17: [memory ] maximum GC Pauses = 147.064 , 172.153, 209.094 ms
18: [memory ]
19: [memory ] number of concurrent mark phases = 21
20: [memory ] number of parallel mark phases = 13
21: [memory ] number of concurrent sweep phases = 18
22: [memory ] number of parallel sweep phases = 16
Lines 3-9 display information on the young collections during this run.
Line 4 shows the total number of young collections.
Line 5 shows the total number of objects promoted and their total size in bytes.
Line 6 shows the largest number of objects promoted during a single young collection and their total size in bytes.
Line 7 shows the total time spent in young collections.
Line 8 shows the average time spent in a single young collection.
Line 9 shows the three longest pause times caused by young collection.
Lines 11-17 show statistics on old collections.
Line 12 shows the total number of old collections.
Line 13 shows the number of objects promoted during old collections and their total size in bytes.
Line 14 shows the largest number of objects promoted during a single old collection and their total size in bytes.
Line 15 shows the total time spent in old collections and the sum of all garbage collection pauses caused by old collections.
Line 16 shows the average time spent in a single old collection and the average sum of pauses during a single old collection.
Line 17 shows the three longest old collection pauses.
Line 19 displays the number of concurrent mark phases. In this example 21 of the old collections used concurrent mark.
Line 20 shows the number of parallel mark phases. In this example 13 of the old collections used parallel mark.
Line 21 shows the number of concurrent sweep phases. In this example 18 of the old collections used concurrent sweep.
Line 22 shows the number of parallel sweep phases. In this example 16 of the old collections used parallel sweep.
The -Xverbose:referents log module was introduced in the JRockit JVM R27.2, while -Xverbose:refobj was introduced in the JRockit JVM R27.5 and will replace the verbose referents module.
The verbose referents module introduces some overhead and is not suitable for production environments. The verbose refobj info level output in R27.2 is much cheaper and can be used in production environments. The debug level output of refobjs corresponds to the old verbose referents information on info level and should not be used in production.
The -Xverbose:refobj log module shows a summary of the number of reference objects and how they are handled at each garbage collection.
Listing 19-14 shows an example of a verbose refobj output. This example is from the JRockit JVM R27.5. Line numbers have been added.
1: [refobj ] SoftRef: Reach: 2 Act: 0 PrevAct: 11 Null: 50
2: [refobj ] WeakRef: Reach: 183 Act: 0 PrevAct: 0 Null: 10
3: [refobj ] Phantom: Reach: 0 Act: 0 PrevAct: 0 Null: 0
4: [refobj ] ObjMoni: Reach: 2 Act: 0 PrevAct: 0 Null: 0
5: [refobj ] Finaliz: Reach: 17 Act: 0 PrevAct: 0 Null: 0
6: [refobj ] WeakHnd: Reach: 306 Act: 0 PrevAct: 0 Null: 0
7: [refobj ] SoftRef: @Mark: 62 @Preclean: 1 @FinalMark: 0
8: [refobj ] WeakRef: @Mark: 178 @Preclean: 15 @FinalMark: 0
9: [refobj ] Phantom: @Mark: 0 @Preclean: 0 @FinalMark: 0
10: [refobj ] ObjMoni: @Mark: 2 @Preclean: 0 @FinalMark: 0
11: [refobj ] Finaliz: @Mark: 0 @Preclean: 17 @FinalMark: 0
12: [refobj ] WeakHnd: @Mark: 0 @Preclean: 105 @FinalMark: 201
13: [refobj ] SoftRef: SoftAliveOnly: 0 SoftAliveAndReach: 0
Lines 1-6 show the number of occurrences of each reference object type, finalizers, weak handles and object monitors. The references objects are categorized by status, as follows:
Lines 7-12 show statistics on in which garbage collection phases the reference objects were handled.
Line 13 shows how many soft references are soft alive only and how many are also hard reachable.
The old verbose referents log module and the debug level of the refobj log module displays detailed information on reference objects and referents, as seen in Listing 19-15. This example is from the JRockit JVM R27.2. Note that the output may look different in later releases.
Each reference type is broken down by reference class and referent. In the case of handles, only referents are shown; there are no references. The different counters tell how many instances of each type exists and how they are reachable (or cleared).
Additional information is that the header/footer of the report informs what type of collection took place. In the header you can see the time since the last old collection and the amount of free at that time. If any soft references are present you will also find information on which softly reachable referents are collected based on when they where last looked up through get().
| Note: | These verbose outputs have a significant negative impact on the performance. |
--- Verbose reference objects statistics - heap collection -------
63.7 MB free memory (of 64.0 MB) after last heap GC, finished 0.177 s ago.
Soft references: 0 (0 only soft reachable, 2 cleared this GC)
java/lang/ref/SoftReference: 0 (0, 2)
0 (0, 1) java/lang/StringCoding$CharsetSD
0 (0, 1) [Ljava/lang/String;
Softly reachable referents not used for at least 0.000 s cleared.
Weak references: 10 (0 cleared this GC)
java/lang/ref/WeakReference: 9 (0)
9 (0) java/lang/Class
java/lang/ThreadLocal$ThreadLocalMap$Entry: 1 (0)
1 (0) java/lang/ThreadLocal
Weak object handles: 63 (0 cleared this GC)
35 (0) sun/misc/Launcher$AppClassLoader
28 (0) java/lang/String
Final handles: 10 (0 pending finalization, 0 became pending this GC)
4 (0, 0) java/util/jar/JarFile
3 (0, 0) java/util/zip/Inflater
2 (0, 0) java/io/FileOutputStream
1 (0, 0) java/io/FileInputStream
Phantom references: 2 (0 only phantom reachable, 0 became phantom reachable this
GC)
jrockit/vm/ObjectMonitor: 2 (0, 0)
1 (0, 0) java/lang/Object
1 (0, 0) java/io/PrintStream
--- End of reference objects statistics - heap collection --------
In this example the garbage collection has cleared two soft references referring to objects or arrays of the types java.lang.StringCoding and java.lang.String, respectively.
There are 10 weak references, 63 weak object handles, 10 final handles and 2 phantom references.
Among the various log modules available in the JRockit JVM, opt and exceptions are two of the most used and most useful.
The -Xverbose:opt log module displays information on code optimizations done by the optimizing compiler.
Listing 19-16 shows an example of a verbose opt output. This example is from the JRockit JVM R27.5. Line numbers have been added.
1: [opt ] #1 5 (0x1c) o0 java/util/Random.acquireSeedLock()V
2: [opt ] #1 5 (0x1c) o0 @0x13AA0000-0x13AA003F 2.43 ms (2.43 ms)
3: [opt ] #2 5 (0x1c) o0 java/util/Random.next(I)I
4: [opt ] #2 5 (0x1c) o0 @0x13AA0370-0x13AA03FF 2.66 ms (20.19 ms)
Lines 1 and 3 show the names of two methods that are optimized.
Lines 2 and 4 show the addresses of the methods and the time it took to optimize them.
You can use the verbose opt information to diagnose and monitor the optimizations.
The -Xverbose:exceptions log module prints each Java exception that is thrown in the application. You can use this information to monitor and troubleshoot exceptions in your application.
Listing 19-17 shows some example outputs from the verbose exceptions log module. This example is from the Oracle JRockit JVM R27.5. Each line displays the name of the exception thrown as well as the exception message, if such is available.
[excepti][00004] java/lang/NullPointerException
[excepti][00004] java/lang/NullPointerException: null array passed into arraycopy
[excepti][00004] java/lang/ArrayIndexOutOfBoundsException
[excepti][00004] java/lang/ArrayIndexOutOfBoundsException
[excepti][00004] java/lang/NullPointerException: null array passed into arraycopy
-Xverbose:exceptions=debug prints out the same information but also provides stack traces for each exception.
|