The -Xverbose command-line option enables verbose output from the Oracle JRockit JVM. You can use the verbose output for monitoring, tuning, and diagnostics. This chapter describes some of the most useful verbose modules and how to interpret the output from them.
Note:
Output can differ between JVM releases. The exact format of the output is subject to change at any time.This chapter contains the following sections:
Table 2-1 lists the verbose log modules available in the JRockit JVM for memory management and garbage collection.
Table 2-1 Memory Management Verbose Modules
| Log Module | Description | Uses |
|---|---|---|
memory |
Basic garbage collection information |
Tuning and monitoring |
nursery |
Nursery information |
Tuning and monitoring |
memdbg |
Memory management information |
Tuning, monitoring, and diagnostics |
compaction |
Compaction information |
Tuning, monitoring, and diagnostics |
gcpause |
Garbage collection pause times |
Tuning, monitoring, and diagnostics |
gcreport |
Garbage collection summary |
Tuning and monitoring |
refobj |
Reference object information |
Monitoring and diagnostics |
alloc |
Allocation and out of memory information |
Monitoring and diagnostics |
Most verbose modules are available at several log levels. With the exception of the memdbg module, this section covers only the default (info) log level. This is the most useful level for general tuning and monitoring purposes.
The -Xverbose:memory (or -Xverbose:gc) module provides basic information about garbage collection events. The overhead for this module is very low, which means that you can enable it in a production environment.
At JVM startup, the memory module displays some basic numbers on the memory management system configuration and a guide to how to read the garbage collection output.
Example 2-1 shows an example of the initial output from the memory log module. Line numbers have been added.
Example 2-1 Initial Output of the memory Module
1: [INFO ][memory ] Running with 32 bit heap and compressed references. 2: [INFO ][memory ] GC mode: Garbage collection optimized for throughput, strategy: Generational Parallel Mark & Sweep. 3: [INFO ][memory ] Heap size: 65536KB, maximum heap size: 3145728KB, nursery size: 32768KB. 4: [INFO ][memory ] <start>-<end>: <type> <before>KB-><after>KB (<heap>KB), <time> ms, sum of pauses <pause> ms. 5: [INFO ][memory ] <start> - start time of collection (seconds since jvm start). 6: [INFO ][memory ] <type> - OC (old collection) or YC (young collection). 7: [INFO ][memory ] <end> - end time of collection (seconds since jvm start). 8: [INFO ][memory ] <before> - memory used by objects before collection (KB). 9: [INFO ][memory ] <after> - memory used by objects after collection (KB). 10: [INFO ][memory ] <heap> - size of heap after collection (KB). 11: [INFO ][memory ] <time> - total time of collection (milliseconds). 12: [INFO ][memory ] <pause> - sum of pauses during collection (milliseconds). 13: [INFO ][memory ] Run with -Xverbose:gcpause to see individual phases.
Line 1 indicates whether compressed references are used.
Line 2 describes the garbage collection mode used in this run, and the initial garbage collection strategy.
Line 3 shows the initial and maximum heap size, and the initial nursery size.
Lines 4–13 describe the format of the garbage collection output.
The memory module displays a line for each garbage collection.
Example 2-2 shows an example of verbose output from the memory module. Line numbers have been added.
Example 2-2 Garbage Collection Output of the memory Module
1: [INFO ][memory ] [YC#1] 0.981-1.019: YC 35001KB->33131KB (65536KB), 0.038 s, sum of pauses 37.851 ms, longest pause 37.851 ms. 2: [INFO ][memory ] [YC#2] 1.688-1.706: YC 58229KB->45536KB (65536KB), 0.019 s, sum of pauses 18.683 ms, longest pause 18.683 ms. 3: [INFO ][memory ] [OC#1] 1.706-1.718: OC 65536KB->57671KB (86176KB), 0.012 s, sum of pauses 10.364 ms, longest pause 10.364 ms. 4: [INFO ][memory ] [YC#3] 1.997-2.006: YC 65143KB->55299KB (86176KB), 0.008 s, sum of pauses 8.328 ms, longest pause 8.328 ms.
Each garbage collection output starts with a timestamp, which is the time in seconds since the JVM started. The format of these lines is described at line 4 in Example 2-1.
Lines 1, 2 and 4 are output from young collections. The young collection on line 1 reduced the size of the heap from 35001 KB to 33131 KB.
Line 3 is an output from an old collection, which reduced the size of the heap from 65536 KB to 57671 KB.
Page faults cause memory access to become slow, and page faults during garbage collection might increase garbage collection time. Because of this, the verbose memory log module displays a warning whenever the number of page faults during the garbage collection was more than five percent of the number of pages in the heap. This output is not available on Windows platforms.
Example 2-3 shows a page fault warning.
The -Xverbose:nursery log module provides details about 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 in a production environment.
Example 2-4 shows the output from the nursery log module during young and old collections. Line numbers have been added.
Example 2-4 Young Collection Output of the nursery Module
1: [INFO ][nursery] [YC#2] Young collection 2 started. This YC is running while the OC is in phase: not running. 2: [INFO ][nursery] [YC#2] Setting forbidden area for keeparea: 0x40ffdff0-0x417fdfe8. 3: [INFO ][nursery] [YC#2] Next keeparea will start at 0x417fdfe8 and end at 0x41ffe000. 4: [INFO ][nursery] [OC#1] Setting keepAreaMarkers[0] to 0x43883f00. 5: [INFO ][nursery] [OC#1] Setting keepAreaMarkers[1] to 0x43dc8860. 6: [INFO ][nursery] [OC#1] Setting keepAreaMarkers[2] to 0x43f9ba88. 7: [INFO ][nursery] [OC#1] Next keeparea will start at 0x43dc8860 and end at 0x43f9ba88.
Lines 1–3 are young collection output (denoted by [YC#2]); lines 4–7 are old collection output (denoted by [OC#1]).
Line 1 shows the sequence number of the young collection. It also indicates 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.
Lines 2–7 contain information related to the size and position of the keep area. This information is useful for advanced diagnostics.
Some garbage collection modes and strategies adjust the nursery size at run time for optimal performance. The nursery log module shows some information about the nursery sizing calculations and nursery size changes.
Example 2-5 shows the nursery sizing output from an old collection. Line numbers have been added.
Example 2-5 Nursery-Size-Adjustment Output of the nursery Module
1: [INFO ][nursery] [OC#1] Nursery size increased from 0KB to 7474KB. Nursery list consists of 5 parts. 2: [INFO ][nursery] [OC#1] Nursery size remains at 7474KB. Nursery list consists of 5 parts.
Line 1 shows that the extent to which the nursery size is being increased and the number of parts that the nursery contains.
Line 2 shows that the size of the nursery was not changed.
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 output from these modules is documented in the respective module. The memdbg log module sets the memory module to the debug level. Only output from memory at the debug level is documented in this section. 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.
Example 2-6 shows the initial output from the memdbg verbose module. Line numbers have been added.
Example 2-6 Initial Output of the memdbg Module
1: [DEBUG][memory ] Minimum TLA size is 2048 bytes. 2: [DEBUG][memory ] Preferred TLA size is 65536 bytes. 3: [DEBUG][memory ] TLA waste limit is 2048 bytes. 4: [DEBUG][memory ] Nursery object limit max is 65536 bytes. 5: [DEBUG][memory ] Nursery object limit percentage is 1.0%. 6: [DEBUG][memory ] Java heap regions: 7: [000000003fffe000 - 0000000043ffe000] rw-- (pagesize=0x1000) 8: [0000000043ffe000 - 000000007fffe000] ---- 9: [0000000080000000 - 0000000100000000] ---- 10: 64MB committed, 3008MB reserved. 11: [DEBUG][memory ] Initial and maximum number of gc threads: 8, of which 8 parallel threads, 4 concurrent threads, and 8 yc threads. 12: [DEBUG][memory ] Maximum nursery percentage of free heap is 95%. 13: [DEBUG][memory ] Prefetch distance in workpacket: 4. Packet size: 493 objects. 14: [DEBUG][memory ] Using prefetch linesize: 64 bytes chunks: 512 bytes pf_dist: 256 bytes.
Lines 1–5 shows the minimum and preferred thread local area sizes, the TLA waste limit, and information about the size of the objects that will be allocated in the nursery. These values depend on the heap size and the garbage collector, and the JRockit JVM release.
Lines 6–10 display a memory map over the Java heap and the amount of memory committed and reserved in the virtual address space.
There can be several heap regions. The regions might, but are not required to, be located at consecutive addresses.
Line 11 shows the number of garbage collection threads.
Line 12 shows the maximum size of the nursery.
Lines 13 and 14 show information about prefetching, which is useful for advanced diagnostics and tuning.
The memdbg module adds information to the garbage collection output. For some tuning and diagnostic work, this information is essential. The output differs among garbage collection types.
Example 2-7 shows the verbose memdbg output from a parallel old collection. Line numbers have been added.
Example 2-7 Parallel Old Collection Output of the memdbg Module
1: [DEBUG][memory ] [OC#1] GC reason: Allocation request failed. 2: [DEBUG][memory ] [OC#1] 1.706: OC started. 3: [DEBUG][memory ] [OC#1] Starting parallel marking phase. 4: [DEBUG][memory ] [OC#1] SemiRef phase Finalizers run in single threaded mode. 5: [DEBUG][memory ] [OC#1] SemiRef phase WeakJNIHandles run in single threaded mode. 6: [DEBUG][memory ] [OC#1] SemiRef phase ClassConstraints run in single threaded mode. 7: [DEBUG][memory ] [OC#1] SemiRef phase FinalMemleak run in single threaded mode. 8: [DEBUG][memory ] [OC#1] Removing 4 permanent work packets from pool, now 60 packets. 9: [DEBUG][memory ] [OC#1] Total mark time: 5.145 ms. 10: [DEBUG][memory ] [OC#1] Ending marking phase. 11: [DEBUG][memory ] [OC#1] Starting parallel sweeping phase. 12: [DEBUG][memory ] [OC#1] Total sweep time: 4.735 ms. 13: [DEBUG][memory ] [OC#1] Ending sweeping phase. 14: [DEBUG][memory ] [OC#1] Expanded the heap from 65536KB to 86176KB. 15: [DEBUG][memory ] [OC#1] Page faults before OC: 1, page faults after OC: 1, pages in heap: 21544. 16: [DEBUG][memory ] [OC#1] Nursery size after OC: 7474KB. (Free: 7472KB Parts: 5)
Line 1 displays the reason for the garbage collection.
Line 2 displays a timestamp of when the old collection was started.
Lines 3–10 describe the actions taken during the mark phase. This mark phase took 5.145 ms, including pauses and concurrent phases. In this case, the Java threads were paused during the entire mark phase.
Lines 11–13 describe the sweep phase.
Line 14 shows the extent to which the Java heap size was increased.
Line 15 indicates the number of page faults before and after the old collection. Page faults during the garbage collection may slow the garbage collection.
Line 16 shows how large the nursery is after the old collection.
The memdbg memory module adds useful information to the garbage collection output. For tuning and diagnostic evaluation, this information is essential. The output differs among garbage collection types.
Example 2-8 shows the verbose memdbg output from a concurrent old collection. Line numbers have been added.
Example 2-8 Concurrent Old Collection Output of the memdbg Module
1: [DEBUG][memory ] [OC#1] GC reason: Allocation request failed. 2: [DEBUG][memory ] [OC#1] 1.768: OC started. 3: [DEBUG][memory ] [OC#1] Starting initial marking phase (OC1). 4: [DEBUG][memory ] [OC#1] SemiRef phase Finalizers run in single threaded mode. 5: [DEBUG][memory ] [OC#1] SemiRef phase WeakJNIHandles run in single threaded mode. 6: [DEBUG][memory ] [OC#1] SemiRef phase ClassConstraints run in single threaded mode. 7: [DEBUG][memory ] [OC#1] Initial marking phase promoted 0 objects (0KB). 8: [DEBUG][memory ] [OC#1] Starting concurrent marking phase (OC2). 9: [DEBUG][memory ] [OC#1] Concurrent mark phase lasted 5.137 ms. 10: [DEBUG][memory ] [OC#1] Starting precleaning phase (OC3). 11: [DEBUG][memory ] [OC#1] Precleaning phase lasted 0.300 ms. 12: [DEBUG][memory ] [OC#1] Starting final marking phase (OC4). 13: [DEBUG][memory ] [OC#1] SemiRef phase Finalizers run in single threaded mode. 14: [DEBUG][memory ] [OC#1] SemiRef phase WeakJNIHandles run in single threaded mode. 15: [DEBUG][memory ] [OC#1] SemiRef phase ClassConstraints run in single threaded mode. 16: [DEBUG][memory ] [OC#1] SemiRef phase FinalMemleak run in single threaded mode. 17: [DEBUG][memory ] [OC#1] Final marking phase promoted 0 objects (0KB). 18: [DEBUG][memory ] [OC#1] Adding 27 temporary work packets to permanent pool, now 91 packets. 19: [DEBUG][memory ] [OC#1] Total mark time: 11.528 ms. 20: [DEBUG][memory ] [OC#1] Ending marking phase. 21: [DEBUG][memory ] [OC#1] Starting concurrent sweeping phase. 22: [DEBUG][memory ] [OC#1] Total sweep time: 1.732 ms. 23: [DEBUG][memory ] [OC#1] Ending sweeping phase. 24: [DEBUG][memory ] [OC#1] Expanded the heap from 65536KB to 93216KB. 25: [DEBUG][memory ] [OC#1] GC Trigger is now 13.2%, was 12.0%. 26: [DEBUG][memory ] [OC#1] Page faults before OC: 1, page faults after OC: 1, pages in heap: 23304. 27: [DEBUG][memory ] [OC#1] Nursery size after OC: 29260KB. (Free: 29256KB Parts: 9)
Line 1 shows the reason for the garbage collection.
Line 2 shows a timestamp for when the old collection was started.
Lines 3–20 describe the actions taken during the mark phase. Line 19 shows the time taken for the mark phase, which includes pauses and concurrent phases.
Lines 21–23 describe the sweep phase. Line 20 shows the time taken for the sweep phase.
Line 24 shows the extent to which the Java heap size was increased.
Line 25 shows information about the garbage collection trigger.
Line 26 shows the number of page faults before and after the old collection. Page faults during the garbage collection may slow the garbage collection.
Line 27 shows the nursery size after the old collection.
Example 2-9 shows the verbose memdbg output from a young collection. Line numbers have been added.
Example 2-9 Young Collection Output of the memdbg Module
1: [DEBUG][memory ] [YC#1] GC reason: Allocation request failed. 2: [DEBUG][memory ] [YC#1] 0.981: YC started. 3: [DEBUG][memory ] [YC#1] Returning duplicate cardTablePart entry 2 (0x4201e000-0x4202e000) 4: [DEBUG][memory ] [YC#1] SemiRef phase Finalizers run in single threaded mode. 5: [DEBUG][memory ] [YC#1] SemiRef phase WeakJNIHandles run in single threaded mode. 6: [DEBUG][memory ] [YC#1] SemiRef phase ClassConstraints run in single threaded mode. 7: [DEBUG][memory ] [YC#1] YC promoted 26760 objects (24201KB). 8: [DEBUG][memory ] [YC#1] Page faults before YC: 1, page faults after YC: 1, pages in heap: 16384. 9: [DEBUG][memory ] [YC#1] Nursery size after YC: 32768KB. (Free: 24574KB Parts: 1)
Line 1 shows the reason for the garbage collection. In this example, the garbage collection was started because an allocation failed. This is the typical reason for starting a young collection.
Line 2 shows a timestamp for when the young collection was started.
Line 3 shows what happens if several threads try to process the same memory. Note that this is the debug level.
Lines 4–6 show information about different phases in the young collection.
Line 7 shows the number (and size) of objects that were promoted during the young collection.
Line 8 shows statistics about page faults before and after the garbage collection. Page faults during the garbage collection may slow the garbage collection.
Line 9 shows the nursery size after the young collection.
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 a parallel sweep instead. Example 2-10 shows the output that this behavior generates.
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 information about the compaction. The overhead of this log module is low, which means that it can be enabled in production environments.
Example 2-11 shows the verbose output from the compaction log module. Line numbers have been added.
Example 2-11 Old Collection Output of the compaction Module
1: [INFO ][compact] [OC#1] Compaction reason: Normal. 2: [INFO ][compact] [OC#1] Compacting 256 of 4096 parts at index 3840. Compaction type is external. Exceptional: No. 3: [INFO ][compact] [OC#1] Compaction area start: 0x43bfe000, end: 0x43ffe000. Timeout: 100.000 ms. 4: [INFO ][compact] [OC#1] Compactset limit (per thread): 37487 (dynamic), not using matrixes. 5: [INFO ][compact] [OC#1] Adjusted compaction area to start at 0x43bfe170 and end at 0x43ffe000. 6: [INFO ][compact] [OC#1] Average compact time ratio (move phase/total time): 0.855877. 7: [INFO ][compact] [OC#1] Too few references, doubling compact ratio. 8: [INFO ][compact] [OC#1] Adjusting compactset limit to 248535. 9: [INFO ][compact] [OC#1] Pause per 1000 refs, current: 0.201178, average: 0.201178. Target pause: 50.000. 10: [INFO ][compact] [OC#1] Compaction time, total: 4.191 ms (target 100.000 ms). 11: [INFO ][compact] [OC#1] Compaction moved 3967 objects and left 0 objects. Total moved size 4125680B. 12: [INFO ][compact] [OC#1] Compaction added 4193936B of free memory in 1 parts. 13: [INFO ][compact] [OC#1] Compaction time, move phase: 3.587 ms (target 50.000 ms). 14: [INFO ][compact] [OC#1] Compaction time, update phase: 0.604 ms (target 50.000 ms). 15: [INFO ][compact] [OC#1] Found 3967 references. Internal: 0 External: 3967. 16: [INFO ][compact] [OC#1] Updated 3967 references. Internal: 0 External: 3967.
Line 1 shows the reason for the compaction. In this case, a normal compaction is triggered by the old collection. Other reasons for compaction can be that allocation requests require a larger compaction due to lack of free memory or that the heap is shrinking.
Line 2 shows a summary of the upcoming compaction. In this example, 256 out of a total of 4096 heap parts will be compacted, starting at index 3840. The compaction type is external, which means that objects will be moved away from the compaction area. The compaction is not exceptional, which means that it can be stopped if it takes too long.
Line 3 shows the physical addresses of the start and the end of the compaction area and for how long this compaction is allowed to run. This information is useful for advanced diagnostics.
Line 4 shows the current compactset limit. The compactset contains references to the compaction area, and the size of this set determines how much compaction is performed during one old collection.
Line 5 shows how the compaction area was adjusted. The heuristics adjusts the compaction area so that no active objects span the borders.
Lines 6–9 is information from the heuristics. It informs you about changes to the compactset based on how much time the compaction took.
Lines 10–12 show the result of the compaction. How much time it took, how many objects were moved, and how much free memory it returned to the allocator.
Lines 13–14 show detailed information about the two components of the pause time caused by compaction, and the current pause targets for these components. In this example, moving objects took 3.587 ms and updating references to moved objects took 0.604 ms, while the target was 50 ms for each of the components.
Lines 15–16 show the number of references found in the compaction area and updated due to moved objects. In this example, all 3967 references found were updated (which is good). Internal references are found within the compaction area, and external references originate from objects outside the compaction area. This information is useful for monitoring and tuning.
Whenever a compaction is stopped, the verbose compaction log module will display information about the reason for the skipped compaction. In Example 2-12, the compactset for a garbage collection thread reached its top limit, which means that there were too many pointers to objects within the selected compaction area. In exceptional cases, the compaction may be skipped because there is not enough native memory available when trying to expand the data structure.
The -Xverbose:gcpause log module displays information about 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 shown in Example 2-13. Line numbers have been added.
Example 2-13 Parallel Old Collection Output of the gcpause Module
1: [INFO ][gcpause] [OC#1] [---] 11.511 ms (1.706000-1.718000) OC 2: [INFO ][gcpause] [OC#1] [con] 0.039 ms (1.706000-1.707000) OC:PreGC 3: [INFO ][gcpause] [OC#1] [pau] 10.364 ms (1.707000-1.717000) OC:Main 4: [INFO ][gcpause] [OC#1] [con] 1.064 ms (1.717000-1.718000) OC:PostGC
Line 1 is a summary that shows that this old collection took 11.511 ms.
Lines 2–4 show the times for each of the parts in the collection. con means that the part is done concurrently with the Java execution, pau means a pause in the Java execution.
A mostly concurrent (or concurrent) old collection consists of several concurrent garbage collection phases interspersed by short pauses.
Example 2-14 shows the output from a mostly concurrent old collection. Line numbers have been added.
Example 2-14 Concurrent Old Collection Output of the gcpause Module
1: [INFO ][gcpause] [OC#1] [---] 14.946 ms (1.768000-1.783000) OC 2: [INFO ][gcpause] [OC#1] [con] 0.058 ms (1.768000-1.769000) OC:PreGC 3: [INFO ][gcpause] [OC#1] [pau] 5.180 ms (1.769000-1.774000) OC:Initial 4: [INFO ][gcpause] [OC#1] [con] 5.393 ms (1.774000-1.779000) OC:ConcurrentMark 5: [INFO ][gcpause] [OC#1] [pau] 3.112 ms (1.779000-1.782000) OC:Main 6: [INFO ][gcpause] [OC#1] [con] 1.128 ms (1.782000-1.783000) OC:PostGC
Line 1 shows the total time taken for the old collection.
Line 2–6 show the times for each of the parts in the collection. con means that the part is done concurrently with the Java execution; pau means a pause in the Java execution.
The -Xverbose:gcreport log module displays a summary of garbage collection activity at the end of the run.
Example 2-15 shows the verbose gcreport output. Line numbers have been added.
Example 2-15 Output of the gcreport Module
1: [INFO ][gcrepor] 2: [INFO ][gcrepor] Memory usage report: 3: [INFO ][gcrepor] 4: [INFO ][gcrepor] Young Collections: 5: [INFO ][gcrepor] number of collections = 30. 6: [INFO ][gcrepor] total promoted = 166897 (size 170523360). 7: [INFO ][gcrepor] max promoted = 26760 (size 24781800). 8: [INFO ][gcrepor] total YC time = 0.380 s (total paused 0.378 s). 9: [INFO ][gcrepor] mean YC time = 12.670 ms (mean total paused 12.596 ms). 10: [INFO ][gcrepor] maximum YC Pauses = 29.256 , 37.851, 55.795 ms. 11: [INFO ][gcrepor] 12: [INFO ][gcrepor] Old Collections: 13: [INFO ][gcrepor] number of collections = 5. 14: [INFO ][gcrepor] total promoted = 0 (size 0). 15: [INFO ][gcrepor] max promoted = 0 (size 0). 16: [INFO ][gcrepor] total OC time = 0.128 s (total paused 0.119 s). 17: [INFO ][gcrepor] mean OC time = 25.579 ms (mean total paused 23.739 ms). 18: [INFO ][gcrepor] maximum OC Pauses = 16.818 , 26.550, 51.602 ms. 19: [INFO ][gcrepor] 20: [INFO ][gcrepor] 21: [INFO ][gcrepor] number of internal compactions = 3. 22: [INFO ][gcrepor] number of external compactions = 2. 23: [INFO ][gcrepor] 1 of these were stopped because they timed out. 24: [INFO ][gcrepor]
Lines 4–10 show information about the young collections during this run.
Line 5 shows the total number of young collections.
Line 6 shows the total number of objects promoted and their total size in bytes.
Line 7 shows the largest number of objects promoted during a single young collection and their total size in bytes.
Line 8 shows the total time spent in young collections.
Line 9 shows the average time spent in a single young collection.
Line 10 shows the three longest pause times caused by a young collection.
Lines 12–18 show statistics about old collections.
Line 13 shows the total number of old collections.
Line 14 shows the number of objects promoted during old collections and their total size in bytes.
Line 15 shows the largest number of objects promoted during a single old collection and their total size in bytes.
Line 16 shows the total time spent in old collections and the sum of all garbage collection pauses caused by old collections.
Line 17 shows the average time spent in a single old collection and the average number of pauses during a single old collection.
Line 18 shows the three longest old collection pauses.
Line 21 shows the number of internal compactions.
Line 22 shows the number of external compactions.
Line 23 shows that one compaction was stopped due to a timeout.
The -Xverbose:refobj log module shows a summary of the number of reference objects and how they are handled at each garbage collection.
Example 2-16 shows the verbose refobj output. Line numbers have been added.
Example 2-16 Output of the refobj Module
1: [INFO ][refobj ] [YC#1] SoftRef: Reach: 10 Act: 0 PrevAct: 0 Null: 0 2: [INFO ][refobj ] [YC#1] WeakRef: Reach: 14 Act: 0 PrevAct: 0 Null: 0 3: [INFO ][refobj ] [YC#1] Phantom: Reach: 0 Act: 0 PrevAct: 0 Null: 0 4: [INFO ][refobj ] [YC#1] ClearPh: Reach: 0 Act: 0 PrevAct: 0 Null: 0 5: [INFO ][refobj ] [YC#1] Finaliz: Reach: 4 Act: 2 PrevAct: 0 Null: 0 6: [INFO ][refobj ] [YC#1] WeakHnd: Reach: 49 Act: 0 PrevAct: 0 Null: 0 7: [INFO ][refobj ] [YC#1] SoftRef: @Mark: 10 @Preclean: 0 @FinalMark: 0 8: [INFO ][refobj ] [YC#1] WeakRef: @Mark: 11 @Preclean: 0 @FinalMark: 3 9: [INFO ][refobj ] [YC#1] Phantom: @Mark: 0 @Preclean: 0 @FinalMark: 0 10: [INFO ][refobj ] [YC#1] ClearPh: @Mark: 0 @Preclean: 0 @FinalMark: 0 11: [INFO ][refobj ] [YC#1] Finaliz: @Mark: 0 @Preclean: 0 @FinalMark: 6 12: [INFO ][refobj ] [YC#1] WeakHnd: @Mark: 0 @Preclean: 0 @FinalMark: 49 13: [INFO ][refobj ] [YC#1] SoftRef: SoftAliveOnly: 10 SoftAliveAndReach: 0 14: [INFO ][refobj ] [YC#1] NOTE: This count only applies to a part of the heap.
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,
Reachable: Reference objects with reachable referents. A referent that is reachable on a harder level is considered reachable; for example, a referent of a soft reference is reachable if it also is hard reachable.
Activated: Activated references are such that the referent is no longer reachable on any harder level than this reference, which means that the reference can be cleared or put on a reference queue.
Previously Activated: References that have been activated at a previous garbage collection but have not yet been cleared are previously activated.
Null: Null references are such that the reference in the reference object is null, but the reference object itself still exists.
Lines 7–12 show statistics about 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 -Xverbose:alloc log module gives information about memory allocations. The module was introduced in R28.0.
Example 2-17 shows the alloc output. Line numbers have ben added.
Example 2-17 Output of the alloc Module
1: [INFO ][alloc ] [YC#1] Pending requests at 'Before YC' - Total: 1, TLAs: 1 (approx 65536 bytes), objects: 0 (0 bytes). Max age: 0. 2: [INFO ][alloc ] [YC#1] Satisfied 0 object and 1 tla allocations. Pending requests went from 1 to 0. 3: [INFO ][alloc ] [YC#1] Pending requests at 'After YC' - Total: 0, TLAs: 0 (approx 0 bytes), objects: 0 (0 bytes). Max age: 0.
Line 1 shows information about the status of the object allocation queue before the garbage collection.
Line 2 shows how many allocation requests were satisfied as a result of this collection.
Line 3 shows information about the status of the object allocation queue after the garbage collection. You can compare this information to the information in line 1 to get an idea of how well object allocation is doing. 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.
Among the various log modules available in the JRockit JVM, opt and exceptions are two of the commonly used and most useful.
The -Xverbose:opt log module displays information about code optimizations done by the optimizing compiler.
Example 2-18 shows the verbose opt output. Line numbers have been added.
Example 2-18 Output of the opt Module
1: [INFO ][opt ][00036] #1 (Opt) ObjAlloc.main([Ljava/lang/String;)V 2: [INFO ][opt ][00036] #1 3.756-3.758 0x0000000100060000-0x000000010006004E 2.10 ms 128KB 7633 bc/s (2.10 ms 7633 bc/s)
Line 1 shows the names of two methods that are optimized.
Line 2 shows 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 displays each Java exception that is thrown in the application. You can use this information to monitor and troubleshoot exceptions in your application.
Example 2-19 shows output from the verbose exceptions log module. Each line displays the name of the exception thrown and the exception message, if one is available.
Example 2-19 Output of the exceptions Module
[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 the same information and provides stack traces for each exception.