[Bug 2304] [IcedTea8] HPROF: output truncated when using doe=n option
bugzilla-daemon at icedtea.classpath.org
bugzilla-daemon at icedtea.classpath.org
Thu Jul 26 09:42:29 UTC 2018
https://icedtea.classpath.org/bugzilla/show_bug.cgi?id=2304
Severin Gehwolf <sgehwolf at redhat.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |sgehwolf at redhat.com
--- Comment #3 from Severin Gehwolf <sgehwolf at redhat.com> ---
Why was this considered a bug? In my book, the original upstream bug was this:
------------------------------------
The resultant java.hprof.txt file appears to be truncated, as not all of the
header text is output.
------------------------------------
And the key is "not all of the *header* text is output". This patch actually
makes -Xrunhprof:doe=y and -Xrunhprof:doe=n behave the same, but I can see
use-cases where I'd want doe=n. Example:
On a patched system I see this ("====================>" markers added in output
for clarity):
$ cat ~/Documents/trash/Foo.java
public class Foo{
public static void main(String[] arg){
System.out.println("Hello");
try {
while(true)
Thread.sleep(1000*60);
}catch(InterruptedException ex){
}
System.out.println("Bye");
}
}
$ java -Xrunhprof:doe=n Foo
Hello
====================> Marker A
^\2018-07-26 11:18:45
Full thread dump OpenJDK 64-Bit Server VM (25.181-b13 mixed mode):
"Service Thread" #10 daemon prio=9 os_prio=0 tid=0x00007fe184250000 nid=0x23dc
runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread3" #9 daemon prio=9 os_prio=0 tid=0x00007fe18420e800
nid=0x23db waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread2" #8 daemon prio=9 os_prio=0 tid=0x00007fe18420d000
nid=0x23da waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" #7 daemon prio=9 os_prio=0 tid=0x00007fe184203800
nid=0x23d9 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #6 daemon prio=9 os_prio=0 tid=0x00007fe184201800
nid=0x23d8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"HPROF gc_finish watcher" #5 daemon prio=10 os_prio=0 tid=0x00007fe1841fe800
nid=0x23d7 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007fe1841d7000
nid=0x23d6 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fe1841aa800 nid=0x23d5 in
Object.wait() [0x00007fe14990b000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000071bb88f70> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
- locked <0x000000071bb88f70> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fe1841a0000
nid=0x23d4 in Object.wait() [0x00007fe149a0c000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000071bb86c98> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x000000071bb86c98> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
"main" #1 prio=5 os_prio=0 tid=0x00007fe184090800 nid=0x23ca waiting on
condition [0x00007fe18b108000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at Foo.main(Foo.java:6)
"VM Thread" os_prio=0 tid=0x00007fe184178800 nid=0x23d3 runnable
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fe1840a3800 nid=0x23cb
runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fe1840a5800 nid=0x23cc
runnable
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fe1840a7000 nid=0x23cd
runnable
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fe1840a9000 nid=0x23ce
runnable
"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00007fe1840aa800 nid=0x23cf
runnable
"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00007fe1840ac800 nid=0x23d0
runnable
"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00007fe1840ae000 nid=0x23d1
runnable
"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00007fe1840b0000 nid=0x23d2
runnable
"VM Periodic Task Thread" os_prio=0 tid=0x00007fe184224800 nid=0x23dd waiting
on condition
JNI global references: 1526
Heap
PSYoungGen total 147456K, used 7587K [0x000000071bb80000,
0x0000000726000000, 0x00000007c0000000)
eden space 126464K, 6% used
[0x000000071bb80000,0x000000071c2e8fe0,0x0000000723700000)
from space 20992K, 0% used
[0x0000000724b80000,0x0000000724b80000,0x0000000726000000)
to space 20992K, 0% used
[0x0000000723700000,0x0000000723700000,0x0000000724b80000)
ParOldGen total 337408K, used 0K [0x00000005d3200000,
0x00000005e7b80000, 0x000000071bb80000)
object space 337408K, 0% used
[0x00000005d3200000,0x00000005d3200000,0x00000005e7b80000)
Metaspace used 2741K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 260K, capacity 386K, committed 512K, reserved 1048576K
Dumping Java heap ... allocation sites ... done.
====================> Marker B
^CDumping Java heap ... allocation sites ... done.
====================> Marker C
Then looking at java.hprof.txt before I've hit CTRL+\ at "Marker A" time I see
the full header (but no allocation site traces yet), which is expected:
$ cat java.hprof.txt
JAVA PROFILE 1.0.1, created Thu Jul 26 11:25:12 2018
Copyright (c) 2003, 2005, Oracle and/or its affiliates. All rights reserved.
Redistribution and use in source and binary forms, with or without
modification, are permitted provided that the following conditions
are met:
- Redistributions of source code must retain the above copyright
notice, this list of conditions and the following disclaimer.
- Redistributions in binary form must reproduce the above copyright
notice, this list of conditions and the following disclaimer in the
documentation and/or other materials provided with the distribution.
- Neither the name of Oracle nor the names of its
contributors may be used to endorse or promote products derived
from this software without specific prior written permission.
THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS
IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO,
THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR
CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL,
EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO,
PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR
PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF
LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING
NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
Header for -agentlib:hprof (or -Xrunhprof) ASCII Output (JDK 5.0 JVMTI based)
WARNING! This file format is under development, and is subject to
change without notice.
This file contains the following types of records:
THREAD START
THREAD END mark the lifetime of Java threads
TRACE represents a Java stack trace. Each trace consists
of a series of stack frames. Other records refer to
TRACEs to identify (1) where object allocations have
taken place, (2) the frames in which GC roots were
found, and (3) frequently executed methods.
HEAP DUMP is a complete snapshot of all live objects in the Java
heap. Following distinctions are made:
ROOT root set as determined by GC
CLS classes
OBJ instances
ARR arrays
SITES is a sorted list of allocation sites. This identifies
the most heavily allocated object types, and the TRACE
at which those allocations occurred.
CPU SAMPLES is a statistical profile of program execution. The VM
periodically samples all running threads, and assigns
a quantum to active TRACEs in those threads. Entries
in this record are TRACEs ranked by the percentage of
total quanta they consumed; top-ranked TRACEs are
typically hot spots in the program.
CPU TIME is a profile of program execution obtained by measuring
the time spent in individual methods (excluding the time
spent in callees), as well as by counting the number of
times each method is called. Entries in this record are
TRACEs ranked by the percentage of total CPU time. The
"count" field indicates the number of times each TRACE
is invoked.
MONITOR TIME is a profile of monitor contention obtained by measuring
the time spent by a thread waiting to enter a monitor.
Entries in this record are TRACEs ranked by the percentage
of total monitor contention time and a brief description
of the monitor. The "count" field indicates the number of
times the monitor was contended at that TRACE.
MONITOR DUMP is a complete snapshot of all the monitors and threads in
the System.
HEAP DUMP, SITES, CPU SAMPLES|TIME and MONITOR DUMP|TIME records are generated
at program exit. They can also be obtained during program execution by typing
Ctrl-\ (on Solaris) or by typing Ctrl-Break (on Win32).
--------
Then, at Marker B time, once I've hit CTRL+\ so as to get a profile, I see one
expected SITES dump in java.hprof.txt:
$ total=$(grep ^SITES java.hprof.txt | wc -l); grep ^SITES java.hprof.txt |
tail -n$(($total - 1))
SITES BEGIN (ordered by live bytes) Thu Jul 26 11:30:01 2018
SITES END
Then, at Marker C time, once I've hit CTRL+C so as to terminate the JVM, I get
another SITES dump which is unexpected! That's exactly what doe=n is supposed
to prevent if you'd ask me.
$ total=$(grep ^SITES java.hprof.txt | wc -l); grep ^SITES java.hprof.txt |
tail -n$(($total - 1))
SITES BEGIN (ordered by live bytes) Thu Jul 26 11:30:01 2018
SITES END
SITES BEGIN (ordered by live bytes) Thu Jul 26 11:35:43 2018
SITES END
On an unpatched system with doe=n at Marker A time I see the entire header:
$ cat java.hprof.txt
JAVA PROFILE 1.0.1, created Thu Jul 26 11:38:27 2018
Copyright (c) 2003, 2005, Oracle and/or its affiliates. All rights reserved.
Redistribution and use in source and binary forms, with or without
modification, are permitted provided that the following conditions
are met:
- Redistributions of source code must retain the above copyright
notice, this list of conditions and the following disclaimer.
- Redistributions in binary form must reproduce the above copyright
notice, this list of conditions and the following disclaimer in the
documentation and/or other materials provided with the distribution.
- Neither the name of Oracle nor the names of its
contributors may be used to endorse or promote products derived
from this software without specific prior written permission.
THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS
IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO,
THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR
CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL,
EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO,
PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR
PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF
LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING
NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
Header for -agentlib:hprof (or -Xrunhprof) ASCII Output (JDK 5.0 JVMTI based)
WARNING! This file format is under development, and is subject to
change without notice.
This file contains the following types of records:
THREAD START
THREAD END mark the lifetime of Java threads
TRACE represents a Java stack trace. Each trace consists
of a series of stack frames. Other records refer to
TRACEs to identify (1) where object allocations have
taken place, (2) the frames in which GC roots were
found, and (3) frequently executed methods.
HEAP DUMP is a complete snapshot of all live objects in the Java
heap. Following distinctions are made:
ROOT root set as determined by GC
CLS classes
OBJ instances
ARR arrays
SITES is a sorted list of allocation sites. This identifies
the most heavily allocated object types, and the TRACE
at which those allocations occurred.
CPU SAMPLES is a statistical profile of program execution. The VM
periodically samples all running threads, and assigns
a quantum to active TRACEs in those threads. Entries
in this record are TRACEs ranked by the percentage of
total quanta they consumed; top-ranked TRACEs are
typically hot spots in the program.
CPU TIME is a profile of program execution obtained by measuring
the time spent in individual methods (excluding the time
spent in callees), as well as by counting the number of
times each method is called. Entries in this record are
TRACEs ranked by the percentage of total CPU time. The
"count" field indicates the number of times each TRACE
is invoked.
MONITOR TIME is a profile of monitor contention obtained by measuring
the time spent by a thread waiting to enter a monitor.
Entries in this record are TRACEs ranked by the percentage
of total monitor contention time and a brief description
of the monitor. The "count" field indicates the number of
times the monitor was contended at that TRACE.
MONITOR DUMP is a complete snapshot of all the monitors and threads in
the System.
HEAP DUMP, SITES, CPU SAMPLES|TIME and MONITOR DUMP|TIME records are generated
at program exit. They can also be obtained during program execution by typing
Ctrl-\ (on Solaris) or by typing Ctrl-Break (on Win32).
--------
Then, at Marker C time, once I've completed the steps as for unpatched, I get
only *one* dump which *is* expected.
[...]
ParOldGen total 337408K, used 0K [0x00000005d3200000,
0x00000005e7b80000, 0x000000071bb80000)
object space 337408K, 0% used
[0x00000005d3200000,0x00000005d3200000,0x00000005e7b80000)
Metaspace used 2465K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 257K, capacity 386K, committed 512K, reserved 1048576K
Dumping Java heap ... allocation sites ... done.
^C
$
$ total=$(grep ^SITES java.hprof.txt | wc -l); grep ^SITES java.hprof.txt |
tail -n$(($total - 1))
SITES BEGIN (ordered by live bytes) Thu Jul 26 11:41:10 2018
SITES END
--
You are receiving this mail because:
You are on the CC list for the bug.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/distro-pkg-dev/attachments/20180726/81d4d2ed/attachment-0001.html>
More information about the distro-pkg-dev
mailing list