Re: Timing bugs
Hi Gary, Functional changes look okay to me. Thanks, David On 10/11/2011 5:21 AM, Gary Adams wrote: Here's an update diff for the elapsed time check. - added current CR# to @bug tag - moved capture of start time to after creation of the latches so only the schedule*() and the await() calls are included in the elapsed time check. jdk/test/java/util/Timer/Args.java /* * @test - * @bug 6571655 6571881 6574585 6571297 + * @bug 6571655 6571881 6574585 6571297 6731620 * @summary Test various args to task scheduling methods */ @@ -92,19 +92,21 @@ new F(){void f(){ t.scheduleAtFixedRate(x, (Date)null, 42); }} ); - final long start = System.currentTimeMillis(); - final Date past = new Date(start - 10500); final CountDownLatch y1 = new CountDownLatch(1); final CountDownLatch y2 = new CountDownLatch(1); final CountDownLatch y3 = new CountDownLatch(11); + final long start = System.currentTimeMillis(); + final Date past = new Date(start - 10500); + final long elapsed; schedule( t, counter(y1), past); schedule( t, counter(y2), past, 1000); scheduleAtFixedRate(t, counter(y3), past, 1000); y3.await(); y1.await(); y2.await(); - System.out.printf("elapsed=%d%n", System.currentTimeMillis() - start); - check(System.currentTimeMillis() - start < 500); + elapsed = System.currentTimeMillis() - start; + System.out.printf("elapsed=%d%n", elapsed); + check(elapsed < 500); t.cancel(); On 11/ 4/11 09:36 AM, Gary Adams wrote: I've started to look at timing related bugs that have been open for a while, but have not had sufficient priority to make it to the top of the list of bugs to be fixed. Thought I'd start with some low hanging fruit with simple bug fixes. 6731620: TEST_BUG: java/util/Timer/Args.java is too optimistic about the execution time of System.out.printf This seems like a simply problem to avoid two calls to get the current time and to eliminated the time to process the print statement from the evaluation of the test elapsed time. Replacing this sequence ; System.out.printf("elapsed=%d%n", System.currentTimeMillis() - start); check(System.currentTimeMillis() - start < 500); with elapsed = System.currentTimeMillis() - start; System.out.printf("elapsed=%d%n", elapsed); check(elapsed < 500); I plan to test the fix on a 300MHz linux/arm device. I'll provide a proper webrev as soon as I have author rights confirmed. I'm looking for reviewer and a committer, once I get the fix tested locally. Thanks Gary Adams
Re: Timing bugs
Here's an update diff for the elapsed time check. - added current CR# to @bug tag - moved capture of start time to after creation of the latches so only the schedule*() and the await() calls are included in the elapsed time check. jdk/test/java/util/Timer/Args.java /* * @test - * @bug 6571655 6571881 6574585 6571297 + * @bug 6571655 6571881 6574585 6571297 6731620 * @summary Test various args to task scheduling methods */ @@ -92,19 +92,21 @@ new F(){void f(){ t.scheduleAtFixedRate(x, (Date)null, 42); }} ); -final long start = System.currentTimeMillis(); -final Date past = new Date(start - 10500); final CountDownLatch y1 = new CountDownLatch(1); final CountDownLatch y2 = new CountDownLatch(1); final CountDownLatch y3 = new CountDownLatch(11); +final long start = System.currentTimeMillis(); +final Date past = new Date(start - 10500); +final long elapsed; schedule( t, counter(y1), past); schedule( t, counter(y2), past, 1000); scheduleAtFixedRate(t, counter(y3), past, 1000); y3.await(); y1.await(); y2.await(); -System.out.printf("elapsed=%d%n", System.currentTimeMillis() - start); -check(System.currentTimeMillis() - start < 500); +elapsed = System.currentTimeMillis() - start; +System.out.printf("elapsed=%d%n", elapsed); +check(elapsed < 500); t.cancel(); On 11/ 4/11 09:36 AM, Gary Adams wrote: I've started to look at timing related bugs that have been open for a while, but have not had sufficient priority to make it to the top of the list of bugs to be fixed. Thought I'd start with some low hanging fruit with simple bug fixes. 6731620: TEST_BUG: java/util/Timer/Args.java is too optimistic about the execution time of System.out.printf This seems like a simply problem to avoid two calls to get the current time and to eliminated the time to process the print statement from the evaluation of the test elapsed time. Replacing this sequence ; System.out.printf("elapsed=%d%n", System.currentTimeMillis() - start); check(System.currentTimeMillis() - start < 500); with elapsed = System.currentTimeMillis() - start; System.out.printf("elapsed=%d%n", elapsed); check(elapsed < 500); I plan to test the fix on a 300MHz linux/arm device. I'll provide a proper webrev as soon as I have author rights confirmed. I'm looking for reviewer and a committer, once I get the fix tested locally. Thanks Gary Adams
Re: Timing bugs
On 11/ 6/11 08:05 PM, David Holmes wrote: Hi Gary, On 4/11/2011 11:36 PM, Gary Adams wrote: I've started to look at timing related bugs that have been open for a while, but have not had sufficient priority to make it to the top of the list of bugs to be fixed. Thought I'd start with some low hanging fruit with simple bug fixes. Sometimes apparently low-hanging fruit is attached to the tree with steel wire ;-) (and sometimes barbed wire at that) Had a feeling when I pulled on the fruit the trap door would open in the floor ... 6731620: TEST_BUG: java/util/Timer/Args.java is too optimistic about the execution time of System.out.printf This seems like a simply problem to avoid two calls to get the current time and to eliminated the time to process the print statement from the evaluation of the test elapsed time. Replacing this sequence ; System.out.printf("elapsed=%d%n", System.currentTimeMillis() - start); check(System.currentTimeMillis() - start < 500); with elapsed = System.currentTimeMillis() - start; System.out.printf("elapsed=%d%n", elapsed); check(elapsed < 500); This seems reasonable on the face of it. But a couple of other observations regarding the test code: First the 500 is somewhat arbitrary - the test is preparing three timertasks with initial expiry times in the past and expecting them to all execute "immediately" (one multiple times). This immediacy is translated into "completes within 500ms". These type of timing constants should be eradicated if possible, or preferably made configurable if not. It is a difficult problem to address if you want to try and detect something taking an unexpectedly long time, but have no idea what your execution environment will be. I think I'm signing up for making this one test reliable and not taking on all of the bad timeout assumptions. The 500 millisecond constraint seems reasonable in this case for the work expected to be completed. Second, the current code won't detect a true failure that results in a hang - the testcase will hang and presumably get timed-out by the test harness. It might be better to apply a timeout to the await() calls instead and fail only if they do timeout. I thought the hung test was the responsibility of the test harness. It makes for simpler individual tests if that responsibility is delegated to the harness. Third, in this case it would also be prudent to (re-)read the start time after the setup has been done ie after creating the countDownLatches. If this is run in samevm mode or agentvm mode those constructions may trigger a full GC and the ensuing delay could cause the test to again fail. Sounds reasonable I'll add that change to the fix. That all said, I'd see combining your suggested fix with moving the point at which start is measured as definite improvements in the test. Agreed. I plan to test the fix on a 300MHz linux/arm device. I'll provide a proper webrev as soon as I have author rights confirmed. I'm looking for reviewer and a committer, once I get the fix tested locally. I presume by "committer" you mean somebody to actually do the push for you - I think we generally refer to that as a "sponsor" (even though not part of OpenJDK terminology). In any case that should be someone from TL group and I'll let them respond further on that and provide any additional review comments. I'm happy to act as another Reviewer. Thanks. Cheers, David Thanks Gary Adams
Re: Timing bugs
On 07/11/2011 01:05, David Holmes wrote: Sometimes apparently low-hanging fruit is attached to the tree with steel wire ;-) (and sometimes barbed wire at that) In the case of some of our tests then it's actually fuse wire, with a nice little surprise when you yank at it :-)
Re: Timing bugs
Hi Gary, On 4/11/2011 11:36 PM, Gary Adams wrote: I've started to look at timing related bugs that have been open for a while, but have not had sufficient priority to make it to the top of the list of bugs to be fixed. Thought I'd start with some low hanging fruit with simple bug fixes. Sometimes apparently low-hanging fruit is attached to the tree with steel wire ;-) (and sometimes barbed wire at that) 6731620: TEST_BUG: java/util/Timer/Args.java is too optimistic about the execution time of System.out.printf This seems like a simply problem to avoid two calls to get the current time and to eliminated the time to process the print statement from the evaluation of the test elapsed time. Replacing this sequence ; System.out.printf("elapsed=%d%n", System.currentTimeMillis() - start); check(System.currentTimeMillis() - start < 500); with elapsed = System.currentTimeMillis() - start; System.out.printf("elapsed=%d%n", elapsed); check(elapsed < 500); This seems reasonable on the face of it. But a couple of other observations regarding the test code: First the 500 is somewhat arbitrary - the test is preparing three timertasks with initial expiry times in the past and expecting them to all execute "immediately" (one multiple times). This immediacy is translated into "completes within 500ms". These type of timing constants should be eradicated if possible, or preferably made configurable if not. It is a difficult problem to address if you want to try and detect something taking an unexpectedly long time, but have no idea what your execution environment will be. Second, the current code won't detect a true failure that results in a hang - the testcase will hang and presumably get timed-out by the test harness. It might be better to apply a timeout to the await() calls instead and fail only if they do timeout. Third, in this case it would also be prudent to (re-)read the start time after the setup has been done ie after creating the countDownLatches. If this is run in samevm mode or agentvm mode those constructions may trigger a full GC and the ensuing delay could cause the test to again fail. That all said, I'd see combining your suggested fix with moving the point at which start is measured as definite improvements in the test. I plan to test the fix on a 300MHz linux/arm device. I'll provide a proper webrev as soon as I have author rights confirmed. I'm looking for reviewer and a committer, once I get the fix tested locally. I presume by "committer" you mean somebody to actually do the push for you - I think we generally refer to that as a "sponsor" (even though not part of OpenJDK terminology). In any case that should be someone from TL group and I'll let them respond further on that and provide any additional review comments. I'm happy to act as another Reviewer. Cheers, David Thanks Gary Adams
Timing bugs
I've started to look at timing related bugs that have been open for a while, but have not had sufficient priority to make it to the top of the list of bugs to be fixed. Thought I'd start with some low hanging fruit with simple bug fixes. 6731620: TEST_BUG: java/util/Timer/Args.java is too optimistic about the execution time of System.out.printf This seems like a simply problem to avoid two calls to get the current time and to eliminated the time to process the print statement from the evaluation of the test elapsed time. Replacing this sequence ; System.out.printf("elapsed=%d%n", System.currentTimeMillis() - start); check(System.currentTimeMillis() - start < 500); with elapsed = System.currentTimeMillis() - start; System.out.printf("elapsed=%d%n", elapsed); check(elapsed < 500); I plan to test the fix on a 300MHz linux/arm device. I'll provide a proper webrev as soon as I have author rights confirmed. I'm looking for reviewer and a committer, once I get the fix tested locally. Thanks Gary Adams