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

[Alex Menkov]

Looks good.

--alex

On 09/19/2019 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
>>>>>>>>
>>>>>>
>>>>>>
>>>>
>>>>
>>>
>>>
>>
>>
> 
>