Codereview request: 8050115 javax/management/monitor/GaugeMonitorDeadlockTest.java fails intermittently

[shanliang]

Daniel,

We could not be sure that the test failed of timeout, that's why I tried 
to add more checks.

The check for Step 1: all thread traces were printed out only if 
deadlock was found, and the test failed immediately.
The check for Step 2:
    1) all thread traces were printed out only if the tested thread was 
blocked, but the test did not fail because we were not sure if deadlock 
happened, but the info might be helpful;
    2) otherwise only the trace of the tested thread was printed out.

In case that the test gets interrupted again by the test harness, hope 
we can have some useful info from these 2 checks.

It must not be so heavy but still could impact the test, your suggestion 
to use test.timeout.factor is a good idea, I added the code to calculate 
the checking time based on it:
    http://cr.openjdk.java.net/~sjiang/JDK-8050115/03/

Thanks,
Shanliang

Daniel Fuchs wrote:
> Hi Shanliang,
>
> On 9/17/14 2:19 PM, shanliang wrote:
>> Daniel,
>>
>> The test does 2 steps of verifications, the new check is useful for the
>> first step, and the trace in the bug showed that the test failed on the
>> first step.
>>
>> Yes the check might not work for the second step, I added the new code
>> for the second step to check the tested thread state and hope to have
>> useful info if the test failed on the second step.
>>
>> Here is the new version:
>>     http://cr.openjdk.java.net/~sjiang/JDK-8050115/02/
>>
>> Thanks,
>> Shanliang
>
> If I understand the issue correctly - the test fails in timeout
> mostly on very slow machines/configurations (fastdebug with some
> combinations of options).
>
> I worry that printing a thread dump every seconds (1000ms) is going
> to make things worse: the test will spend its time printing thread
> dumps instead of doing what it is supposed to do - and will have
> even less CPU cycles to execute its 'real' code.
>
> I would have advised printing the thread dumps only at the end,
> when it is detected that there might be a deadlock - except that
> now we can't do that since the timeout is managed completely
> by the harness (so we don't get the upper hand at the end in
> case of timeout).
>
> I think depending on the harness to set the appropriate timeout
> rather than depending on an arbitrary timeout set in the test itself
> is the right thing to do. It's been a pattern in many tests that
> failed in timeout intermittently on some slow machines/configuration.
>
> In any case - 1s seems really too frequent.
> I suppose you could inspect the system properties set by the harness
> (timeout + timeout factor) to devise an acceptable frequency for
> your checks - if you really want to print this info.
>
> From the log I see that the timeout factor passed to the harness
> for the slow configuration that failed is
> -Dtest.timeout.factor=8.0
> There's no explicit timeout given - and jtreg -onlineHelp reveals
> that in this case the default timeout is two minutes.
>
> This means that the harness has allocated 2*8=16mins for the test to
> execute.
> I don't think you want to take the risk of printing a thread dump
> every seconds during 16 minutes ;-)
>
> Of course I'm over simplifying here. Before your changes - the test
> was deciding after 46.893 seconds that there must be a deadlock.
> 47s is obviously way too short for a possibly slow machine running
> the test in fastdebug mode.
>
> Something like the following might be more reasonable:
>
> // default timeout factor is 1.0
> double factor =
>     Double.parseDouble(
>        System.getProperty("test.timeout.factor", "1.0"));
> // default timeout is 2mins = 120s.
> double timeout = Double.parseDouble(
>        System.getProperty("test.timeout", "120"));
>
> // total time is timeout * timeout factor * 1000 ms
> long total = (long) factor * timeout * 1000;
>
> // Don't print thread dumps too often.
> // every 5s for a total timeout of 120s seems reasonable.
> // 120s/5s = 24; we will lengthen the delay if the total
> // timeout is greater than 120s, so we're taking the max between
> // 5s and total/24
> long delayBetweenThreadDumps = Math.max(5000, total/24);
>
> Of course 5s and total/24 are just arbitrary...
> But 24 full thread dumps in a log for a single test is enough data
> to analyze I think ;-)
>
> best regards,
>
> -- daniel
>
>>
>>
>> Daniel Fuchs wrote:
>>> On 9/17/14 10:55 AM, shanliang wrote:
>>>> David Holmes wrote:
>>>>> On 17/09/2014 7:01 AM, shanliang wrote:
>>>>>> David Holmes wrote:
>>>>>>> Hi Shanliang,
>>>>>>>
>>>>>>> On 16/09/2014 7:12 PM, shanliang wrote:
>>>>>>>> Hi,
>>>>>>>>
>>>>>>>> Please review the following fix:
>>>>>>>
>>>>>>> I don't see any functional change. You seem to have replaced a
>>>>>>> built-in timeout with the externally applied test harness timeout.
>>>>>> Yes no functional change here, we thought that the test needed more
>>>>>> time
>>>>>> to wait a change if a testing VM or machine was really slow, the 
>>>>>> test
>>>>>> harness timeout was the maximum time we could give the test.
>>>>>
>>>>> Do we have confidence that the harness timeout is sufficient to 
>>>>> handle
>>>>> the intermittent failures?
>>>> Really a good question :)
>>>>
>>>> Here is new version:
>>>>     http://cr.openjdk.java.net/~sjiang/JDK-8050115/01/
>>>>
>>>> I added a deadlocked check in every 1 second, hope to get more info in
>>>> case of failure.
>>>
>>> The following comment seems to imply that this check is not
>>> very useful:
>>>
>>>  112             // This won't show up as a deadlock in CTRL-\ or in
>>>  113             // ThreadMXBean.findDeadlockedThreads(), because they
>>> don't
>>>  114             // see that thread A is waiting for thread B
>>> (B.join()), and
>>>  115             // thread B is waiting for a lock held by thread A
>>>
>>> best regards,
>>>
>>> -- daniel
>>>
>>>>
>>>> I changed also the sleep time to 100ms, 10ms seems too short as Daniel
>>>> pointed out.
>>>>
>>>> Thanks,
>>>> Shanliang
>>>>>
>>>>> Thanks,
>>>>> David
>>>>>
>>>>>
>>>>>>>
>>>>>>> Style nit: add a space after 'while' -> while (cond) {
>>>>>> OK, I will do it before pushing.
>>>>>>
>>>>>> Thanks,
>>>>>> Shanliang
>>>>>>>
>>>>>>> David
>>>>>>> -----
>>>>>>>
>>>>>>>> bug: https://bugs.openjdk.java.net/browse/JDK-8050115
>>>>>>>> webrev: http://cr.openjdk.java.net/~sjiang/JDK-8050115/00/
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Shanliang
>>>>>>
>>>>
>>>
>>
>