Hi Chris,
This looks good to me.
Just one minor comment:
140 long estimatedTime = System.currentTimeMillis() - startTime;
Did you want to name this local "elapsedTime", not
"estimatedTime"? :)
Thanks,
Serguei
On 9/19/19 22:31, Chris Plummer wrote:
Here's
a new webrev:
http://cr.openjdk.java.net/~cjplummer/8228625/webrev.01/
I decided to add a 2 second delay to make sure the test always
passes and avoids the issues in JDK-8230872. After some internal
discussion there seems to be some consensus that SA is probably
not very stable when attaching to an active process, and I'd
rather not have those issues disrupting this test. I filed a CR
to write a new test without the 2 second delay so we can still
reproduce these issues. See:
https://bugs.openjdk.java.net/browse/JDK-8231288
Besides now using ProcessTools.startProcess() with a line
predicate instead of Runtime.exec(), I also did a bit of
cleaning up of variable names and added a few more diagnostic
printlns.
thanks,
Chris
On 9/19/19 2:40 PM, Chris Plummer wrote:
One thing I didn't mention before is
that using "jshell> " as the line predicate does not work
because jshell does not produce a \n after generating this
prompt, thus it's not actually a line and no attempt will be
made to match it, so eventually it times out. I fixed this by
using a snippet from one of the previous 2 lines"
Welcome to JShell -- Version 14-internal
For an introduction type: /help intro
I now search for "Welcome to JShell", which is working.
I think this is related to additional issues I am having with
this fix. I used to see JDK-8230872 happen about 1% of the
time after the original fix I had for this CR (8228625).
However, now it fails about 9% of the time. It seems that this
new fix is making it more likely that jshell will be in a
state that will uncover jmap bugs. If I add another 10 second
delay to the test, all the jmap problems go away.
This started to get me thinking that maybe "jmap --pid" is
just not reliable. We do have a few other tests for this, but
I believe they all wait until the target process has all
threads blocked before issuing the jmap command. This might be
why they don't see problems. In the case of this test, since I
don't fully wait for the jshell> prompt, there is still
probably some jshell activity when jmap attaches. Waiting an
extra 10 seconds gets us past this activity, and likely jshell
is blocked waiting for input. In fact even just waiting 1
additional second seems to be long enough.
Chris
On 9/18/19 9:44 PM, Chris Plummer wrote:
I got this to work, although it
increased the test time from about 30s to over 3m. I looked
into it a bit and it appears to be due to the size of the
generate hprof file. It used to be about 300k, but now is
nearly 7mb. I guess that's because jshell has been run for
longer and probably allocated more data.
I need to do some more testing and a bit of cleanup. I'll
get another review out tomorrow.
Chris
Suddenly the test time is taking
On 9/18/19 5:43 PM, Chris Plummer wrote:
Ok. It was a bit unclear to me why
the author went with Runtime.exec() in the first place.
I'll try ProcessTools. That will probably however, hide
8230872. I might need to write another test for it.
Chris
On 9/18/19 4:29 PM, Alex Menkov wrote:
You can use jdk.test.lib classes
to simplify the things.
Something like
ProcessBuilder pb = new
ProcessBuilder(JDKToolFinder.getTestJDKTool("jshell"));
Process p = ProcessTools.startProcess("JShell", pb,
s -> { // warm-up predicate
return s.contains(">jshell");
});
--alex
On 09/18/2019 15:44, Chris Plummer wrote:
Is there an easy way of doing
this? Currently the jshell process is just spawned
using Runtime.exec().
Chris
On 9/18/19 3:01 PM, Alex Menkov wrote:
Hi Chris,
Did you think about waiting for jshell prompt
("jshell>") before run "jhsdb jmap" command
instead of delay or re-tries?
--alex
On 09/18/2019 14:11, Chris Plummer wrote:
Hello,
Please review the following changes:
http://cr.openjdk.java.net/~cjplummer/8228625/webrev.00/
https://bugs.openjdk.java.net/browse/JDK-8228625
There are actually numerous ways that
JShellHeapDumpTest.java fails. One is a test bug,
being addressed here, and the rest all seem to be
SA bugs. Those are now being covered by
JDK-8230872. All the issues seem to stem from the
fact that the test spawns a jshell process, and
then immediately does a "jhsdb jmap" on the
process before jshell has fully started up.
The test bug happens when the jmap succeeds, but
jshell has not yet entered the main java thread.
Thus the search for "JShellToolProvider" in the
output fails. It expects "JShellToolProvider" to
be in the output because it is part of a method
name in the main thread, and the test dump all the
thread stacks contained in the jmap generated
hprof file. When the test fails in this way, you
can see the stack dump in the output, but the main
thread is missing.
There's a couple of ways to fix this. One is to
just add a delay (10s seems to be more than
enough), and the other is to retry the "jhsdb
jmap" command until the stack contains the
JShellToolProvider symbol. I chose the later
because doing a 10s delay masks the SA issues that
are now covered by JDK-8230872. In a way the 10s
delay is a better fix, because it makes this test
pass every time, but I did not like that it also
hid real SA problems in JDK-8230872. My plan for
now is to do this retry fix, and then if there are
too many failures due to JDK-8230872, then also
add a 10s delay, with the intention of removing it
once JDK-8230872 if fixed. From what I can see,
JDK-8230872 failures happen on about 1% of the
runs.
I made a few of other changes. One was to no
longer redirect stderr from the jmap process as
was done from the following:
processBuilder.redirectError(ProcessBuilder.Redirect.INHERIT);
This causes the output not to appear in the
OutputAnalyzer output, resulting in the following
not working:
output.shouldNotContain("null");
Also I added code to dump the output of the jshell
process so you can see if the jshell prompt was
ever generated.
thanks,
Chris
|
