RFR(S): 8228625: [TESTBUG] sun/tools/jhsdb/JShellHeapDumpTest.java fails with RuntimeException 'JShellToolProvider' missing from stdout/stderr

[Chris Plummer]

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
>>>>>>>
>>>>>
>>>>>
>>>
>>>
>>
>>
>
>