I
have experiments that I collected while running
a Java application under the Java Microbenchmark
Harness (JMH). JMH forks new JVM's so that the
harness does not affect the benchmark, and can
serially fork multiple JVM to measure run-to-run
variation, startup time, etc.
I
am seeing an infinite loop in the
gprofng display gui,
I think while reading an experiment. I am using
my own build of the
https://savannah.gnu.org/projects/gprofng-gui/
repo that I built on an Ampere Altra running
Fedora 36, and using the standard OpenJDK build
of jdk-17.0.4.1 to run the
gprofng display gui
application.
I
have tried up to 5 forks under JMH and
gprofng display text
seems to be able to handle them all. Here's a
run with 1 fork showing the process view:
Altra
$
/home/pkessler/Work/GProfNG-GUI/Repos/INSTALL/bin/gprofng
display text
forks-1.er -processes
Warning:
History and command editing is not supported
on this system.
Objects
sorted by metric: Exclusive Total CPU Time
Excl.
Total Name
CPU
sec.
%
2.642
100.00 <Total>
1.631
61.74 java, Process 4, PID 1195111
0.961
36.36 java, Process 1, PID 1195043
0.030
1.14 java, Process 2, PID 1195068
0.020
0.76 java, Process 3, PID 1195090
My
benchmark is process 4, that takes around 1.6
seconds. Here is a run with 5 forks:
Altra
$
/home/pkessler/Work/GProfNG-GUI/Repos/INSTALL/bin/gprofng
display text
forks-5.er -processes
Warning:
History and command editing is not supported
on this system.
Objects
sorted by metric: Exclusive Total CPU Time
Excl.
Total Name
CPU
sec.
%
9.176
100.00 <Total>
1.651
17.99 java, Process 5, PID 1195779
1.631
17.78 java, Process 4, PID 1195751
1.581
17.23 java, Process 6, PID 1195808
1.561
17.01 java, Process 8, PID 1195865
1.551
16.90 java, Process 7, PID 1195837
1.161
12.65 java, Process 1, PID 1195684
0.020
0.22 java, Process 2, PID 1195708
0.020
0.22 java, Process 3, PID 1195730
If
I try to look at the same experiments with
gprofng display gui
it usually hangs reading the experiment.
Altra
$
/home/pkessler/Work/GProfNG-GUI/Repos/INSTALL/bin/gprofng
display gui \
--jdkhome
"/home/pkessler/Deployed/OpenJDK/jdk-17.0.4.1"
\
forks-1.er
fdhome:
/home/pkessler/Work/GProfNG-GUI/Repos/INSTALL
gp-display-text:
/home/pkessler/Work/GProfNG-GUI/Repos/INSTALL/bin/gp-display-text
That
run hung with the progress bar bouncing back and
forth saying
Loading
CallStack Data: _x1_x1.er
until
I used File/Exit to quit and then it produced
the exception stack trace
Exception
in thread "IPCReader"
java.lang.StringIndexOutOfBoundsException:
offset 18, count 16842752, length 54
at
java.base/java.lang.String.checkBoundsOffCount(String.java:4589)
at
java.base/java.lang.String.<init>(String.java:523)
at
java.base/java.lang.String.<init>(String.java:1415)
at
org.gprofng.mpmt.ipc.IPCProtocol.decodeSVal(IPCProtocol.java:109)
at
org.gprofng.mpmt.ipc.IPCResult.progress(IPCResult.java:197)
at
org.gprofng.mpmt.ipc.IPCResult.fireResponse(IPCResult.java:220)
at
org.gprofng.mpmt.ipc.IPCReader.run(IPCReader.java:228)
at
java.base/java.lang.Thread.run(Thread.java:833)
Trying
the same thing again (because :-) worked
flawlessly, allowing me to export the Process
view
ExperimentIDs
sorted by metric: Exclusive Total CPU Time
Exclusive
Total
CPU Time Name
sec.
2.642
(100.00%) <Total>
1.631
( 61.74%) java, Process 4, PID 1195111
0.961
( 36.36%) java, Process 1, PID 1195043
0.030
( 1.14%) java, Process 2, PID 1195068
0.020
( 0.76%) java, Process 3, PID 1195090
matching
the gprofng display text shown above, with
subtle formatting differences.
When
gprofng display gui hangs on input (80%
(?) of the time with my forks-1.er, 100% of the
time with my forks-5.er), the status bar in the
lower right shows different stages. Here are a
bunch of attempts to display the 5 fork
experiment
Altra
$
/home/pkessler/Work/GProfNG-GUI/Repos/INSTALL/bin/gprofng
display gui \
--jdkhome
"/home/pkessler/Deployed/OpenJDK/jdk-17.0.4.1"
\
forks-5.er
which
produced the status bars
Loading
Profile Data: _x2_x1.er
Loading
CallStack Data: _x1_x1.er
Loading
CallStack Data: _x2_x1.er
Loading
CallStack Data: _x6_x1.er
Loading
CallStack Data: _x6_x1.er 34%
Loading
CallStack Data: _x3_x1.er
Loading
CallStack Data: _x4_x1.er
Loading
CallStack Data: _x4_x1.er 69%
Loading
CallStack Data: _x5_x1.er
Loading
CallStack Data: _x4_x1.er 34%
Loading
CallStack Data: _x6_x1.er 52%
Processing
Load Object Data
I
have tried letting it run (for hours) and it
never finishes loading the experiment. But
sometimes it just works: loading the experiment
(forks-1.er) essentially instantly.
(Fortunately, the one time I was demoing it to
my manager! :-) I hate intermittent bugs.
When
I have to use File/Exit to quit the GUI, it
always reports the same exception stack trace
shown above. The
count 16842752
argument looks distinctly
wrong. (!(offset < 0) and
!(count < 0), but (offset
> length - count)). Maybe
count is an uninitialized variable?
Maybe the looping behavior is because someone is
catching the exception (or a superclass) but not
fixing the cause and trying again. I shouldn't
speculate.
The
experiments are too large to attach to an
email. I could send you the code if you have
Maven and can download JMH and try to reproduce
it yourself. Or, if you know how to write JMH
benchmarks, you might be able to reproduce the
problem on your own. Let me know if you want me
to send you anything that will help you debug
this issue.
... peter