runtime JVM options
Peter B. Kessler
Peter.Kessler at Sun.COM
Fri Dec 12 04:32:13 UTC 2008
Victor Cheung wrote:
> Hi Peter,
>
> That's a good point. If I use -Xloggc:mylog.txt will all the other GC related options go into mylog.txt?
All the GC printing is supposed to go in the -Xloggc file. If something that should go there doesn't that's a bug and please report it (or just fix in the open sources :-).
> These are my other options:
> -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime
>
> I'm not sure what I'm seeing in mylog.txt corresponds to which GC option.
>
> This is a sample from mylog.txt:
> Total time for which application threads were stopped: 0.0000723 seconds
This is from -XX:+PrintGCApplicationStoppedTime see [1] line 480 for details.
> Application time: 0.0000304 seconds
This is from -XX:+PrintGCApplicationConcurrentTime see [1] line 429 for details. This is somewhat confusing, because those two flags actually track when the virtual machine comes to a "safepoint". Since there isn't any GC activity, I surmise that the VM is coming to a safepoint for some other reason. For example, the VM has to come to a safepoint to install code it compiles at runtime.
> Total time for which application threads were stopped: 0.0000301 seconds
> Application time: 0.0146026 seconds
> Total time for which application threads were stopped: 0.0000665 seconds
> Application time: 0.0023067 seconds
> Total time for which application threads were stopped: 0.0000836 seconds
> Application time: 0.0000469 seconds
> Total time for which application threads were stopped: 0.0000361 seconds
> Application time: 0.0000112 seconds
> Total time for which application threads were stopped: 0.0000332 seconds
> Application time: 0.3270320 seconds
More of the same.
> {Heap before GC invocations=6 (full 1):
> PSYoungGen total 12736K, used 10944K [0x30750000, 0x31580000, 0x34030000)
> eden space 10944K, 100% used [0x30750000,0x31200000,0x31200000)
> from space 1792K, 0% used [0x313c0000,0x313c0000,0x31580000)
> to space 1792K, 0% used [0x31200000,0x31200000,0x313c0000)
> PSOldGen total 116544K, used 3672K [0x14030000, 0x1b200000, 0x30750000)
> object space 116544K, 3% used [0x14030000,0x143c63d0,0x1b200000)
> PSPermGen total 20992K, used 11951K [0x10030000, 0x114b0000, 0x14030000)
> object space 20992K, 56% used [0x10030000,0x10bdbe88,0x114b0000)
This is the opening of the output from -XX:+PrintHeapAtGC. See [2] line 273 for details. (Though, similar output is produced from each of the various collectors.) It shows the total number of collections, how many of collections have been full collections, and the shape of the heap with the sizes of the generations and spaces within them. "PSYoungGen" means you have a parallel scavenge young generation, which you got with -XX:+UseParallelGC. "PSOldGen" is the serial old generation collector that works with the PSYoung collector. That means, for example that you did not use -XX:+UseParallelOldGC to get the parallel old generation collector that works with the PSYoung collector. (-XX:+UseParallelOldGen might help reduce pause times if you have several processors and large heaps. I know: you can't change the parameters. Yet.)
> 2008-12-11T16:21:28.306-0500: 6.465: [GC
That's the output of -XX:+PrintGCDateStamps (2008-12-11T16:21:28.306-0500) followed by the output of -XX:+PrintGCTimeStamps (6.465) followed by the beginning of the output of -XX:+PrintGCDetails. Those are from [2] lines 297 and 299.
> Desired survivor size 1835008 bytes, new threshold 7 (max 15)
The output of -XX:+PrintTenuringDistribution. See [2] line 487.
> [PSYoungGen: 10944K->1744K(12736K)] 14616K->5417K(129280K), 0.0039334 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
The rest of the output of PrintGCDetails.
> Heap after GC invocations=6 (full 1):
> PSYoungGen total 12736K, used 1744K [0x30750000, 0x31580000, 0x34030000)
> eden space 10944K, 0% used [0x30750000,0x30750000,0x31200000)
> from space 1792K, 97% used [0x31200000,0x313b41c0,0x313c0000)
> to space 1792K, 0% used [0x313c0000,0x313c0000,0x31580000)
> PSOldGen total 116544K, used 3672K [0x14030000, 0x1b200000, 0x30750000)
> object space 116544K, 3% used [0x14030000,0x143c63d0,0x1b200000)
> PSPermGen total 20992K, used 11951K [0x10030000, 0x114b0000, 0x14030000)
> object space 20992K, 56% used [0x10030000,0x10bdbe88,0x114b0000)
> }
The closing of the output of -XX:+PrintHeapAtGC. (That's why there's a '{' at the beginning and a '}' at the end, so they are easy to match in the logs. I forgot to say that there's a '[' at the beginning of the PrintGCDetails output and a matching ']' at the end, which often isn't as interesting because the output is usually on one (long) line, but here with PrintTenuringDistribution it might be useful.
> Total time for which application threads were stopped: 0.0042340 seconds
> Application time: 0.0000612 seconds
> Total time for which application threads were stopped: 0.0001024 seconds
> Application time: 0.0000317 seconds
> Total time for which application threads were stopped: 0.0002141 seconds
> Application time: 0.0000252 seconds
> Total time for which application threads were stopped: 0.0002127 seconds
> Application time: 0.0000205 secon
Explained above.
> From the above output, how can I determine which collector is being used for each generation? I noticed JConsole says "PS MarkSweep" and "PS Scavenge". Is MarkSweep = CMS collector? What about Scavenge?
The names of the generations tell you which collector is in use where. See my reading of the PrintHeapAtGC output above. "PS MarkSweep" must be jconsole's name for PSOldGen. I guess "PS MarkSweep" is a more descriptive name. The CMS collector uses "ParNew" for the parallel young generation (both in PrintGCDetails and in jconsole) and "CMS" for the old generation collection in PrintGCDetails, but "concurrent mark-sweep" in -XX:+PrintHeapAtGC, and "ConcurrentMarkSweep" in jconsole. (What a mess.) See [3] line 28 versus [4] line 186 and following for some details.
> I'm trying to correlate the JConsole output with the -Xloggc output...
>
>
> victor
I hope that helps.
... peter
[1] http://hg.openjdk.java.net/jdk7/jdk7/hotspot/file/3c4d36b4a7ac/src/share/vm/runtime/vmThread.cpp
[2] http://hg.openjdk.java.net/jdk7/jdk7/hotspot/file/3c4d36b4a7ac/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp
[3] http://hg.openjdk.java.net/jdk7/jdk7/hotspot/file/3c4d36b4a7ac/src/share/vm/gc_implementation/parallelScavenge/psOldGen.cpp
[4] http://hg.openjdk.java.net/jdk7/jdk7/hotspot/file/3c4d36b4a7ac/src/share/vm//services/memoryManager.hpp
> -----Original Message-----
> From: Peter.Kessler at Sun.COM [mailto:Peter.Kessler at Sun.COM]
> Sent: Thursday, December 11, 2008 6:00 PM
> To: Victor Cheung
> Cc: hotspot-gc-use at openjdk.java.net
> Subject: Re: runtime JVM options
>
> With apologies for replying publicly:
>
> Can you use "ssh -X" at all? If so, even 6u5 has jconsole, and I think even has all the JMX stuff set up to allow connections. If you are poking at a live production server, though, be aware that you can do things in jconsole that will cause the server to pause, on the order of full collection times. For example: pushing the "Perform GC" button. Oh, and you can use jconsole to manage some of the options, e.g., to turn on -XX:+PrintGCDetails. I don't know how your system admins would like it if you started the JVM spewing GC logs to their stdout. (And more importantly, I don't know how you'd read that stream if they aren't saving it to a file you can read.)
>
> ... peter
>
> Victor Cheung wrote:
>> Hi Peter,
>>
>> I wish I could. Our staging and production version is only 6u5... no jvisualvm. I tried it locally on my own machine and it's a phenomenal tool to say the least.
>>
>> Victor
>>
>>
>> -----Original Message-----
>> From: Peter.Kessler at Sun.COM [mailto:Peter.Kessler at Sun.COM]
>> Sent: Thursday, December 11, 2008 4:42 PM
>> To: Victor Cheung
>> Cc: Jon.Masamitsu at Sun.COM; hotspot-gc-use at openjdk.java.net
>> Subject: Re: runtime JVM options
>>
>> Can you use "ssh -X" to your server, and use that to send the jvisualvm window back to your machine (which would have to have an X server)?
>>
>> ... peter
>>
>> Victor Cheung wrote:
>>> Hihi,
>>>
>>> Unfortunately I only have read-only ssh access to the unix environment where the server is running. I can't create or edit any files. And enabling a JMX port for remote connections is not an option for me.
>>>
>>> Are there other ways for me to get this information?
>>>
>>> victor
>>>
>>> -----Original Message-----
>>> From: Jon.Masamitsu at Sun.COM [mailto:Jon.Masamitsu at Sun.COM]
>>> Sent: Thursday, December 11, 2008 12:18 PM
>>> To: Victor Cheung
>>> Cc: hotspot-gc-use at openjdk.java.net
>>> Subject: Re: runtime JVM options
>>>
>>> I think jconsole will give you the JVM
>>> command line under the "VM Summary" tab.
>>>
>>> On 12/11/08 08:48, Victor Cheung wrote:
>>>> Hihi all,
>>>>
>>>>
>>>>
>>>> I cannot seem to find the answer to this. How can we get a list of
>>>> **all** the options and values that a running JVM is using?
>>>>
>>>>
>>>>
>>>> victor
>>>>
>>>>
>>>> ------------------------------------------------------------------------
>>>>
>>>> _______________________________________________
>>>> hotspot-gc-use mailing list
>>>> hotspot-gc-use at openjdk.java.net
>>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>> _______________________________________________
>>> hotspot-gc-use mailing list
>>> hotspot-gc-use at openjdk.java.net
>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
More information about the hotspot-gc-dev
mailing list