You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@jakarta.apache.org by sebb <se...@gmail.com> on 2011/04/02 17:18:00 UTC

Re: [JMeter] JUnit sampler sample time changes

On 31 March 2011 19:41, Ben Cuthbert <be...@yahoo.co.uk> wrote:
> All
>
> I have been looking over the code in the JUnitSampler code under the jmeter source.
> I would like to make a change to use nanoTime() rather than milliseconds.

Why?

> I can see in the AnnotatedTestCase there is an elapsed time. But I can't see how it
> is returned to a results table. Any ideas?

The time in AnnotatedTestCase is only used for reporting timeout errors.

The actual sample time is calculated using SampleResult.sampleStart()
and sampleEnd() which already use nanoTime().

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: dev-help@jakarta.apache.org


Re: [JMeter] JUnit sampler sample time changes

Posted by Ben Cuthbert <be...@yahoo.co.uk>.
Thanks Sebb. This is what I have done created a new field in the file log that contains nanoSeconds
and reported from the sampler is the user selects it.

Ben
On 3 Apr 2011, at 10:28, sebb wrote:

> On 3 April 2011 08:32, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>> I see the nanotime. But the time in the sampler results is reported in ms. So when you have you data
>> it just says 0. I would like it to go one further and report a low level.
> 
> Sorry, that's not possible currently.
> 
> Changing the elapsed time to nanoSecs would break compatibility, and
> such a level of precision is illusory anyway for almost all of the
> samplers.
> 
> It might be possible to keep a separate field for nanoSeconds and
> report that, but I'm not sure there's sufficient need to warrant the
> change and additional data storage.
> 
>> Regards
>> On 2 Apr 2011, at 16:18, sebb wrote:
>> 
>>> On 31 March 2011 19:41, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>>>> All
>>>> 
>>>> I have been looking over the code in the JUnitSampler code under the jmeter source.
>>>> I would like to make a change to use nanoTime() rather than milliseconds.
>>> 
>>> Why?
>>> 
>>>> I can see in the AnnotatedTestCase there is an elapsed time. But I can't see how it
>>>> is returned to a results table. Any ideas?
>>> 
>>> The time in AnnotatedTestCase is only used for reporting timeout errors.
>>> 
>>> The actual sample time is calculated using SampleResult.sampleStart()
>>> and sampleEnd() which already use nanoTime().
>>> 
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>> 
>> 
>> 
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: dev-help@jakarta.apache.org
>> 
>> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: dev-help@jakarta.apache.org
> 


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: dev-help@jakarta.apache.org


Re: [JMeter] JUnit sampler sample time changes

Posted by Peter Lin <wo...@gmail.com>.
I've talked with BEA's JRockit team in the past regarding the
differences in Nano time on different platforms.

Given these issues, using nano time in JMeter is difficult at best.
>From what I am told by Henrik stahl, making nano time reliable and
performant isn't trivial, so using it to measure performance isn't
really recommended. As far as I know, the only way to get reliable
high performance nano time is if the OS provides it.



On Sun, Apr 3, 2011 at 9:45 AM, sebb <se...@gmail.com> wrote:
> That reminds me -
>
> Tests I've done on Windows show that nanoTime() drifts considerably
> when compared with currentTimeMillis(), i.e. its clock does not appear
> to run at the same rate.
>
> Here's a simple test you can run:
>
> public class NanoDrift {
>    public static void main(String[] args) throws InterruptedException {
>        long systemTime = System.currentTimeMillis();
>        long nanoTime = System.nanoTime() / 1000000;
>        long count=0;
>        while(true){
>            long systemDiff = System.currentTimeMillis() - systemTime;
>            long nanoDiff = System.nanoTime() / 1000000 - nanoTime;
>            long absdiff = Math.abs(systemDiff-nanoDiff);
>            if (absdiff > 100 || (count % 60 == 0)) {
>                System.out.println("@:"+count+" |S-N|:"+absdiff+"
> S:"+systemDiff + " N:" + nanoDiff);
>            }
>            Thread.sleep(1000);
>            count++;
>        }
>    }
> }
>
> Behaviour may depend on the JVM used; on
>
> java version "1.6.0_24"
> Java(TM) SE Runtime Environment (build 1.6.0_24-b07)
> Java HotSpot(TM) Client VM (build 19.1-b02, mixed mode, sharing)
>
> I just got
>
> @:0 |S-N|:0 S:0 N:0
> @:60 |S-N|:0 S:60032 N:60032
> @:120 |S-N|:1 S:120032 N:120033
> @:180 |S-N|:2 S:180032 N:180034
> @:240 |S-N|:6 S:240032 N:240038
> @:300 |S-N|:7 S:300032 N:300039
> @:360 |S-N|:13 S:360032 N:360045
> @:420 |S-N|:14 S:420032 N:420046
> @:480 |S-N|:15 S:480032 N:480047
> @:540 |S-N|:16 S:540032 N:540048
> @:600 |S-N|:17 S:600032 N:600049
> @:660 |S-N|:18 S:660032 N:660050
> @:720 |S-N|:19 S:720032 N:720051
> @:780 |S-N|:20 S:780032 N:780052
> @:840 |S-N|:21 S:840032 N:840053
> @:900 |S-N|:22 S:900032 N:900054
> @:960 |S-N|:23 S:960032 N:960055
> @:1020 |S-N|:24 S:1020032 N:1020056
> @:1080 |S-N|:21 S:1080063 N:1080084
> @:1140 |S-N|:22 S:1140063 N:1140085
> @:1200 |S-N|:23 S:1200063 N:1200086
> @:1260 |S-N|:24 S:1260063 N:1260087
> @:1320 |S-N|:21 S:1320172 N:1320193
> @:1380 |S-N|:36 S:1380172 N:1380208
> @:1440 |S-N|:37 S:1440172 N:1440209
> @:1500 |S-N|:38 S:1500172 N:1500210
> @:1560 |S-N|:40 S:1560172 N:1560212
> @:1620 |S-N|:41 S:1620172 N:1620213
> @:1680 |S-N|:42 S:1680172 N:1680214
> @:1740 |S-N|:29 S:1740188 N:1740217
> @:1800 |S-N|:30 S:1800188 N:1800218
> @:1860 |S-N|:31 S:1860188 N:1860219
> @:1920 |S-N|:31 S:1920188 N:1920219
> @:1980 |S-N|:32 S:1980188 N:1980220
> @:2040 |S-N|:33 S:2040188 N:2040221
> @:2100 |S-N|:34 S:2100188 N:2100222
> @:2160 |S-N|:35 S:2160188 N:2160223
> @:2220 |S-N|:36 S:2220188 N:2220224
> @:2280 |S-N|:37 S:2280188 N:2280225
> @:2340 |S-N|:38 S:2340188 N:2340226
> @:2400 |S-N|:39 S:2400188 N:2400227
> @:2460 |S-N|:40 S:2460188 N:2460228
> @:2520 |S-N|:41 S:2520188 N:2520229
>
> However, on a FreeBSD system using
>
> java version "1.6.0_03-p4"
> Java(TM) SE Runtime Environment (build 1.6.0_03-p4-root_17_dec_2010_05_08-b00)
> Java HotSpot(TM) 64-Bit Server VM (build
> 1.6.0_03-p4-root_17_dec_2010_05_08-b00, mixed mode)
>
> I see no drift:
>
> @:0 |S-N|:0 S:0 N:0
> @:60 |S-N|:0 S:60118 N:60118
> @:120 |S-N|:0 S:120239 N:120239
> @:180 |S-N|:1 S:180357 N:180358
> @:240 |S-N|:0 S:240476 N:240476
> @:300 |S-N|:0 S:300594 N:300594
> @:360 |S-N|:0 S:360713 N:360713
> @:420 |S-N|:0 S:420830 N:420830
> @:480 |S-N|:1 S:480948 N:480949
> @:540 |S-N|:0 S:541066 N:541066
> @:600 |S-N|:0 S:601184 N:601184
> @:660 |S-N|:0 S:661302 N:661302
> @:720 |S-N|:0 S:721419 N:721419
> @:780 |S-N|:0 S:781537 N:781537
> @:840 |S-N|:0 S:841655 N:841655
> @:900 |S-N|:0 S:901773 N:901773
> @:960 |S-N|:1 S:961890 N:961891
> @:1020 |S-N|:0 S:1022008 N:1022008
> @:1080 |S-N|:0 S:1082126 N:1082126
> @:1140 |S-N|:0 S:1142244 N:1142244
> @:1200 |S-N|:1 S:1202361 N:1202362
> @:1260 |S-N|:1 S:1262479 N:1262480
> @:1320 |S-N|:0 S:1322600 N:1322600
> @:1380 |S-N|:1 S:1382748 N:1382749
> @:1440 |S-N|:0 S:1442879 N:1442879
> @:1500 |S-N|:1 S:1502997 N:1502998
> @:1560 |S-N|:0 S:1563115 N:1563115
> @:1620 |S-N|:0 S:1623233 N:1623233
> @:1680 |S-N|:0 S:1683351 N:1683351
> @:1740 |S-N|:0 S:1743468 N:1743468
> @:1800 |S-N|:0 S:1803586 N:1803586
> @:1860 |S-N|:0 S:1863704 N:1863704
> @:1920 |S-N|:1 S:1923838 N:1923839
> @:1980 |S-N|:0 S:1983959 N:1983959
> @:2040 |S-N|:1 S:2044077 N:2044078
> @:2100 |S-N|:0 S:2104195 N:2104195
> @:2160 |S-N|:0 S:2164313 N:2164313
> @:2220 |S-N|:1 S:2224430 N:2224431
> @:2280 |S-N|:1 S:2284548 N:2284549
> @:2340 |S-N|:0 S:2344666 N:2344666
> @:2400 |S-N|:1 S:2404784 N:2404785
> @:2460 |S-N|:0 S:2464903 N:2464903
> @:2520 |S-N|:0 S:2525020 N:2525020
> @:2580 |S-N|:0 S:2585138 N:2585138
> @:2640 |S-N|:0 S:2645256 N:2645256
>
>
> On 3 April 2011 13:50, Peter Lin <wo...@gmail.com> wrote:
>> Another important thing to consider is that nano time costs a lot more
>> than System.currentTimeMillis().
>>
>> I've done some benchmarking in the past and nano time costs 30% on
>> windows. On linux, the cost is higher due to differences in how it's
>> implemented.
>>
>> On Sun, Apr 3, 2011 at 5:28 AM, sebb <se...@gmail.com> wrote:
>>> On 3 April 2011 08:32, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>>>> I see the nanotime. But the time in the sampler results is reported in ms. So when you have you data
>>>> it just says 0. I would like it to go one further and report a low level.
>>>
>>> Sorry, that's not possible currently.
>>>
>>> Changing the elapsed time to nanoSecs would break compatibility, and
>>> such a level of precision is illusory anyway for almost all of the
>>> samplers.
>>>
>>> It might be possible to keep a separate field for nanoSeconds and
>>> report that, but I'm not sure there's sufficient need to warrant the
>>> change and additional data storage.
>>>
>>>> Regards
>>>> On 2 Apr 2011, at 16:18, sebb wrote:
>>>>
>>>>> On 31 March 2011 19:41, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>>>>>> All
>>>>>>
>>>>>> I have been looking over the code in the JUnitSampler code under the jmeter source.
>>>>>> I would like to make a change to use nanoTime() rather than milliseconds.
>>>>>
>>>>> Why?
>>>>>
>>>>>> I can see in the AnnotatedTestCase there is an elapsed time. But I can't see how it
>>>>>> is returned to a results table. Any ideas?
>>>>>
>>>>> The time in AnnotatedTestCase is only used for reporting timeout errors.
>>>>>
>>>>> The actual sample time is calculated using SampleResult.sampleStart()
>>>>> and sampleEnd() which already use nanoTime().
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>>>>
>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>>>
>>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: dev-help@jakarta.apache.org
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: dev-help@jakarta.apache.org


Re: [JMeter] JUnit sampler sample time changes

Posted by Ben Cuthbert <be...@yahoo.co.uk>.
Thanks Sebb

So what would you suggest if I want to get microsecond latency measurements? I am thinking only running a freebsd box to load test?
Or maybe implement my own tool to test performance?

Regards

Ben
On 3 Apr 2011, at 14:45, sebb wrote:

> That reminds me -
> 
> Tests I've done on Windows show that nanoTime() drifts considerably
> when compared with currentTimeMillis(), i.e. its clock does not appear
> to run at the same rate.
> 
> Here's a simple test you can run:
> 
> public class NanoDrift {
>    public static void main(String[] args) throws InterruptedException {
>        long systemTime = System.currentTimeMillis();
>        long nanoTime = System.nanoTime() / 1000000;
>        long count=0;
>        while(true){
>            long systemDiff = System.currentTimeMillis() - systemTime;
>            long nanoDiff = System.nanoTime() / 1000000 - nanoTime;
>            long absdiff = Math.abs(systemDiff-nanoDiff);
>            if (absdiff > 100 || (count % 60 == 0)) {
>                System.out.println("@:"+count+" |S-N|:"+absdiff+"
> S:"+systemDiff + " N:" + nanoDiff);
>            }
>            Thread.sleep(1000);
>            count++;
>        }
>    }
> }
> 
> Behaviour may depend on the JVM used; on
> 
> java version "1.6.0_24"
> Java(TM) SE Runtime Environment (build 1.6.0_24-b07)
> Java HotSpot(TM) Client VM (build 19.1-b02, mixed mode, sharing)
> 
> I just got
> 
> @:0 |S-N|:0 S:0 N:0
> @:60 |S-N|:0 S:60032 N:60032
> @:120 |S-N|:1 S:120032 N:120033
> @:180 |S-N|:2 S:180032 N:180034
> @:240 |S-N|:6 S:240032 N:240038
> @:300 |S-N|:7 S:300032 N:300039
> @:360 |S-N|:13 S:360032 N:360045
> @:420 |S-N|:14 S:420032 N:420046
> @:480 |S-N|:15 S:480032 N:480047
> @:540 |S-N|:16 S:540032 N:540048
> @:600 |S-N|:17 S:600032 N:600049
> @:660 |S-N|:18 S:660032 N:660050
> @:720 |S-N|:19 S:720032 N:720051
> @:780 |S-N|:20 S:780032 N:780052
> @:840 |S-N|:21 S:840032 N:840053
> @:900 |S-N|:22 S:900032 N:900054
> @:960 |S-N|:23 S:960032 N:960055
> @:1020 |S-N|:24 S:1020032 N:1020056
> @:1080 |S-N|:21 S:1080063 N:1080084
> @:1140 |S-N|:22 S:1140063 N:1140085
> @:1200 |S-N|:23 S:1200063 N:1200086
> @:1260 |S-N|:24 S:1260063 N:1260087
> @:1320 |S-N|:21 S:1320172 N:1320193
> @:1380 |S-N|:36 S:1380172 N:1380208
> @:1440 |S-N|:37 S:1440172 N:1440209
> @:1500 |S-N|:38 S:1500172 N:1500210
> @:1560 |S-N|:40 S:1560172 N:1560212
> @:1620 |S-N|:41 S:1620172 N:1620213
> @:1680 |S-N|:42 S:1680172 N:1680214
> @:1740 |S-N|:29 S:1740188 N:1740217
> @:1800 |S-N|:30 S:1800188 N:1800218
> @:1860 |S-N|:31 S:1860188 N:1860219
> @:1920 |S-N|:31 S:1920188 N:1920219
> @:1980 |S-N|:32 S:1980188 N:1980220
> @:2040 |S-N|:33 S:2040188 N:2040221
> @:2100 |S-N|:34 S:2100188 N:2100222
> @:2160 |S-N|:35 S:2160188 N:2160223
> @:2220 |S-N|:36 S:2220188 N:2220224
> @:2280 |S-N|:37 S:2280188 N:2280225
> @:2340 |S-N|:38 S:2340188 N:2340226
> @:2400 |S-N|:39 S:2400188 N:2400227
> @:2460 |S-N|:40 S:2460188 N:2460228
> @:2520 |S-N|:41 S:2520188 N:2520229
> 
> However, on a FreeBSD system using
> 
> java version "1.6.0_03-p4"
> Java(TM) SE Runtime Environment (build 1.6.0_03-p4-root_17_dec_2010_05_08-b00)
> Java HotSpot(TM) 64-Bit Server VM (build
> 1.6.0_03-p4-root_17_dec_2010_05_08-b00, mixed mode)
> 
> I see no drift:
> 
> @:0 |S-N|:0 S:0 N:0
> @:60 |S-N|:0 S:60118 N:60118
> @:120 |S-N|:0 S:120239 N:120239
> @:180 |S-N|:1 S:180357 N:180358
> @:240 |S-N|:0 S:240476 N:240476
> @:300 |S-N|:0 S:300594 N:300594
> @:360 |S-N|:0 S:360713 N:360713
> @:420 |S-N|:0 S:420830 N:420830
> @:480 |S-N|:1 S:480948 N:480949
> @:540 |S-N|:0 S:541066 N:541066
> @:600 |S-N|:0 S:601184 N:601184
> @:660 |S-N|:0 S:661302 N:661302
> @:720 |S-N|:0 S:721419 N:721419
> @:780 |S-N|:0 S:781537 N:781537
> @:840 |S-N|:0 S:841655 N:841655
> @:900 |S-N|:0 S:901773 N:901773
> @:960 |S-N|:1 S:961890 N:961891
> @:1020 |S-N|:0 S:1022008 N:1022008
> @:1080 |S-N|:0 S:1082126 N:1082126
> @:1140 |S-N|:0 S:1142244 N:1142244
> @:1200 |S-N|:1 S:1202361 N:1202362
> @:1260 |S-N|:1 S:1262479 N:1262480
> @:1320 |S-N|:0 S:1322600 N:1322600
> @:1380 |S-N|:1 S:1382748 N:1382749
> @:1440 |S-N|:0 S:1442879 N:1442879
> @:1500 |S-N|:1 S:1502997 N:1502998
> @:1560 |S-N|:0 S:1563115 N:1563115
> @:1620 |S-N|:0 S:1623233 N:1623233
> @:1680 |S-N|:0 S:1683351 N:1683351
> @:1740 |S-N|:0 S:1743468 N:1743468
> @:1800 |S-N|:0 S:1803586 N:1803586
> @:1860 |S-N|:0 S:1863704 N:1863704
> @:1920 |S-N|:1 S:1923838 N:1923839
> @:1980 |S-N|:0 S:1983959 N:1983959
> @:2040 |S-N|:1 S:2044077 N:2044078
> @:2100 |S-N|:0 S:2104195 N:2104195
> @:2160 |S-N|:0 S:2164313 N:2164313
> @:2220 |S-N|:1 S:2224430 N:2224431
> @:2280 |S-N|:1 S:2284548 N:2284549
> @:2340 |S-N|:0 S:2344666 N:2344666
> @:2400 |S-N|:1 S:2404784 N:2404785
> @:2460 |S-N|:0 S:2464903 N:2464903
> @:2520 |S-N|:0 S:2525020 N:2525020
> @:2580 |S-N|:0 S:2585138 N:2585138
> @:2640 |S-N|:0 S:2645256 N:2645256
> 
> 
> On 3 April 2011 13:50, Peter Lin <wo...@gmail.com> wrote:
>> Another important thing to consider is that nano time costs a lot more
>> than System.currentTimeMillis().
>> 
>> I've done some benchmarking in the past and nano time costs 30% on
>> windows. On linux, the cost is higher due to differences in how it's
>> implemented.
>> 
>> On Sun, Apr 3, 2011 at 5:28 AM, sebb <se...@gmail.com> wrote:
>>> On 3 April 2011 08:32, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>>>> I see the nanotime. But the time in the sampler results is reported in ms. So when you have you data
>>>> it just says 0. I would like it to go one further and report a low level.
>>> 
>>> Sorry, that's not possible currently.
>>> 
>>> Changing the elapsed time to nanoSecs would break compatibility, and
>>> such a level of precision is illusory anyway for almost all of the
>>> samplers.
>>> 
>>> It might be possible to keep a separate field for nanoSeconds and
>>> report that, but I'm not sure there's sufficient need to warrant the
>>> change and additional data storage.
>>> 
>>>> Regards
>>>> On 2 Apr 2011, at 16:18, sebb wrote:
>>>> 
>>>>> On 31 March 2011 19:41, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>>>>>> All
>>>>>> 
>>>>>> I have been looking over the code in the JUnitSampler code under the jmeter source.
>>>>>> I would like to make a change to use nanoTime() rather than milliseconds.
>>>>> 
>>>>> Why?
>>>>> 
>>>>>> I can see in the AnnotatedTestCase there is an elapsed time. But I can't see how it
>>>>>> is returned to a results table. Any ideas?
>>>>> 
>>>>> The time in AnnotatedTestCase is only used for reporting timeout errors.
>>>>> 
>>>>> The actual sample time is calculated using SampleResult.sampleStart()
>>>>> and sampleEnd() which already use nanoTime().
>>>>> 
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>>>> 
>>>> 
>>>> 
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>>> 
>>>> 
>>> 
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>> 
>>> 
>> 
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: dev-help@jakarta.apache.org
>> 
>> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: dev-help@jakarta.apache.org
> 


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: dev-help@jakarta.apache.org


Re: [JMeter] JUnit sampler sample time changes

Posted by sebb <se...@gmail.com>.
That reminds me -

Tests I've done on Windows show that nanoTime() drifts considerably
when compared with currentTimeMillis(), i.e. its clock does not appear
to run at the same rate.

Here's a simple test you can run:

public class NanoDrift {
    public static void main(String[] args) throws InterruptedException {
        long systemTime = System.currentTimeMillis();
        long nanoTime = System.nanoTime() / 1000000;
        long count=0;
        while(true){
            long systemDiff = System.currentTimeMillis() - systemTime;
            long nanoDiff = System.nanoTime() / 1000000 - nanoTime;
            long absdiff = Math.abs(systemDiff-nanoDiff);
            if (absdiff > 100 || (count % 60 == 0)) {
                System.out.println("@:"+count+" |S-N|:"+absdiff+"
S:"+systemDiff + " N:" + nanoDiff);
            }
            Thread.sleep(1000);
            count++;
        }
    }
}

Behaviour may depend on the JVM used; on

java version "1.6.0_24"
Java(TM) SE Runtime Environment (build 1.6.0_24-b07)
Java HotSpot(TM) Client VM (build 19.1-b02, mixed mode, sharing)

I just got

@:0 |S-N|:0 S:0 N:0
@:60 |S-N|:0 S:60032 N:60032
@:120 |S-N|:1 S:120032 N:120033
@:180 |S-N|:2 S:180032 N:180034
@:240 |S-N|:6 S:240032 N:240038
@:300 |S-N|:7 S:300032 N:300039
@:360 |S-N|:13 S:360032 N:360045
@:420 |S-N|:14 S:420032 N:420046
@:480 |S-N|:15 S:480032 N:480047
@:540 |S-N|:16 S:540032 N:540048
@:600 |S-N|:17 S:600032 N:600049
@:660 |S-N|:18 S:660032 N:660050
@:720 |S-N|:19 S:720032 N:720051
@:780 |S-N|:20 S:780032 N:780052
@:840 |S-N|:21 S:840032 N:840053
@:900 |S-N|:22 S:900032 N:900054
@:960 |S-N|:23 S:960032 N:960055
@:1020 |S-N|:24 S:1020032 N:1020056
@:1080 |S-N|:21 S:1080063 N:1080084
@:1140 |S-N|:22 S:1140063 N:1140085
@:1200 |S-N|:23 S:1200063 N:1200086
@:1260 |S-N|:24 S:1260063 N:1260087
@:1320 |S-N|:21 S:1320172 N:1320193
@:1380 |S-N|:36 S:1380172 N:1380208
@:1440 |S-N|:37 S:1440172 N:1440209
@:1500 |S-N|:38 S:1500172 N:1500210
@:1560 |S-N|:40 S:1560172 N:1560212
@:1620 |S-N|:41 S:1620172 N:1620213
@:1680 |S-N|:42 S:1680172 N:1680214
@:1740 |S-N|:29 S:1740188 N:1740217
@:1800 |S-N|:30 S:1800188 N:1800218
@:1860 |S-N|:31 S:1860188 N:1860219
@:1920 |S-N|:31 S:1920188 N:1920219
@:1980 |S-N|:32 S:1980188 N:1980220
@:2040 |S-N|:33 S:2040188 N:2040221
@:2100 |S-N|:34 S:2100188 N:2100222
@:2160 |S-N|:35 S:2160188 N:2160223
@:2220 |S-N|:36 S:2220188 N:2220224
@:2280 |S-N|:37 S:2280188 N:2280225
@:2340 |S-N|:38 S:2340188 N:2340226
@:2400 |S-N|:39 S:2400188 N:2400227
@:2460 |S-N|:40 S:2460188 N:2460228
@:2520 |S-N|:41 S:2520188 N:2520229

However, on a FreeBSD system using

java version "1.6.0_03-p4"
Java(TM) SE Runtime Environment (build 1.6.0_03-p4-root_17_dec_2010_05_08-b00)
Java HotSpot(TM) 64-Bit Server VM (build
1.6.0_03-p4-root_17_dec_2010_05_08-b00, mixed mode)

I see no drift:

@:0 |S-N|:0 S:0 N:0
@:60 |S-N|:0 S:60118 N:60118
@:120 |S-N|:0 S:120239 N:120239
@:180 |S-N|:1 S:180357 N:180358
@:240 |S-N|:0 S:240476 N:240476
@:300 |S-N|:0 S:300594 N:300594
@:360 |S-N|:0 S:360713 N:360713
@:420 |S-N|:0 S:420830 N:420830
@:480 |S-N|:1 S:480948 N:480949
@:540 |S-N|:0 S:541066 N:541066
@:600 |S-N|:0 S:601184 N:601184
@:660 |S-N|:0 S:661302 N:661302
@:720 |S-N|:0 S:721419 N:721419
@:780 |S-N|:0 S:781537 N:781537
@:840 |S-N|:0 S:841655 N:841655
@:900 |S-N|:0 S:901773 N:901773
@:960 |S-N|:1 S:961890 N:961891
@:1020 |S-N|:0 S:1022008 N:1022008
@:1080 |S-N|:0 S:1082126 N:1082126
@:1140 |S-N|:0 S:1142244 N:1142244
@:1200 |S-N|:1 S:1202361 N:1202362
@:1260 |S-N|:1 S:1262479 N:1262480
@:1320 |S-N|:0 S:1322600 N:1322600
@:1380 |S-N|:1 S:1382748 N:1382749
@:1440 |S-N|:0 S:1442879 N:1442879
@:1500 |S-N|:1 S:1502997 N:1502998
@:1560 |S-N|:0 S:1563115 N:1563115
@:1620 |S-N|:0 S:1623233 N:1623233
@:1680 |S-N|:0 S:1683351 N:1683351
@:1740 |S-N|:0 S:1743468 N:1743468
@:1800 |S-N|:0 S:1803586 N:1803586
@:1860 |S-N|:0 S:1863704 N:1863704
@:1920 |S-N|:1 S:1923838 N:1923839
@:1980 |S-N|:0 S:1983959 N:1983959
@:2040 |S-N|:1 S:2044077 N:2044078
@:2100 |S-N|:0 S:2104195 N:2104195
@:2160 |S-N|:0 S:2164313 N:2164313
@:2220 |S-N|:1 S:2224430 N:2224431
@:2280 |S-N|:1 S:2284548 N:2284549
@:2340 |S-N|:0 S:2344666 N:2344666
@:2400 |S-N|:1 S:2404784 N:2404785
@:2460 |S-N|:0 S:2464903 N:2464903
@:2520 |S-N|:0 S:2525020 N:2525020
@:2580 |S-N|:0 S:2585138 N:2585138
@:2640 |S-N|:0 S:2645256 N:2645256


On 3 April 2011 13:50, Peter Lin <wo...@gmail.com> wrote:
> Another important thing to consider is that nano time costs a lot more
> than System.currentTimeMillis().
>
> I've done some benchmarking in the past and nano time costs 30% on
> windows. On linux, the cost is higher due to differences in how it's
> implemented.
>
> On Sun, Apr 3, 2011 at 5:28 AM, sebb <se...@gmail.com> wrote:
>> On 3 April 2011 08:32, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>>> I see the nanotime. But the time in the sampler results is reported in ms. So when you have you data
>>> it just says 0. I would like it to go one further and report a low level.
>>
>> Sorry, that's not possible currently.
>>
>> Changing the elapsed time to nanoSecs would break compatibility, and
>> such a level of precision is illusory anyway for almost all of the
>> samplers.
>>
>> It might be possible to keep a separate field for nanoSeconds and
>> report that, but I'm not sure there's sufficient need to warrant the
>> change and additional data storage.
>>
>>> Regards
>>> On 2 Apr 2011, at 16:18, sebb wrote:
>>>
>>>> On 31 March 2011 19:41, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>>>>> All
>>>>>
>>>>> I have been looking over the code in the JUnitSampler code under the jmeter source.
>>>>> I would like to make a change to use nanoTime() rather than milliseconds.
>>>>
>>>> Why?
>>>>
>>>>> I can see in the AnnotatedTestCase there is an elapsed time. But I can't see how it
>>>>> is returned to a results table. Any ideas?
>>>>
>>>> The time in AnnotatedTestCase is only used for reporting timeout errors.
>>>>
>>>> The actual sample time is calculated using SampleResult.sampleStart()
>>>> and sampleEnd() which already use nanoTime().
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: dev-help@jakarta.apache.org
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: dev-help@jakarta.apache.org


Re: [JMeter] JUnit sampler sample time changes

Posted by Peter Lin <wo...@gmail.com>.
Another important thing to consider is that nano time costs a lot more
than System.currentTimeMillis().

I've done some benchmarking in the past and nano time costs 30% on
windows. On linux, the cost is higher due to differences in how it's
implemented.

On Sun, Apr 3, 2011 at 5:28 AM, sebb <se...@gmail.com> wrote:
> On 3 April 2011 08:32, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>> I see the nanotime. But the time in the sampler results is reported in ms. So when you have you data
>> it just says 0. I would like it to go one further and report a low level.
>
> Sorry, that's not possible currently.
>
> Changing the elapsed time to nanoSecs would break compatibility, and
> such a level of precision is illusory anyway for almost all of the
> samplers.
>
> It might be possible to keep a separate field for nanoSeconds and
> report that, but I'm not sure there's sufficient need to warrant the
> change and additional data storage.
>
>> Regards
>> On 2 Apr 2011, at 16:18, sebb wrote:
>>
>>> On 31 March 2011 19:41, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>>>> All
>>>>
>>>> I have been looking over the code in the JUnitSampler code under the jmeter source.
>>>> I would like to make a change to use nanoTime() rather than milliseconds.
>>>
>>> Why?
>>>
>>>> I can see in the AnnotatedTestCase there is an elapsed time. But I can't see how it
>>>> is returned to a results table. Any ideas?
>>>
>>> The time in AnnotatedTestCase is only used for reporting timeout errors.
>>>
>>> The actual sample time is calculated using SampleResult.sampleStart()
>>> and sampleEnd() which already use nanoTime().
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: dev-help@jakarta.apache.org
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: dev-help@jakarta.apache.org


Re: [JMeter] JUnit sampler sample time changes

Posted by sebb <se...@gmail.com>.
On 3 April 2011 08:32, Ben Cuthbert <be...@yahoo.co.uk> wrote:
> I see the nanotime. But the time in the sampler results is reported in ms. So when you have you data
> it just says 0. I would like it to go one further and report a low level.

Sorry, that's not possible currently.

Changing the elapsed time to nanoSecs would break compatibility, and
such a level of precision is illusory anyway for almost all of the
samplers.

It might be possible to keep a separate field for nanoSeconds and
report that, but I'm not sure there's sufficient need to warrant the
change and additional data storage.

> Regards
> On 2 Apr 2011, at 16:18, sebb wrote:
>
>> On 31 March 2011 19:41, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>>> All
>>>
>>> I have been looking over the code in the JUnitSampler code under the jmeter source.
>>> I would like to make a change to use nanoTime() rather than milliseconds.
>>
>> Why?
>>
>>> I can see in the AnnotatedTestCase there is an elapsed time. But I can't see how it
>>> is returned to a results table. Any ideas?
>>
>> The time in AnnotatedTestCase is only used for reporting timeout errors.
>>
>> The actual sample time is calculated using SampleResult.sampleStart()
>> and sampleEnd() which already use nanoTime().
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: dev-help@jakarta.apache.org
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: dev-help@jakarta.apache.org
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: dev-help@jakarta.apache.org


Re: [JMeter] JUnit sampler sample time changes

Posted by Ben Cuthbert <be...@yahoo.co.uk>.
I see the nanotime. But the time in the sampler results is reported in ms. So when you have you data 
it just says 0. I would like it to go one further and report a low level.

Regards
On 2 Apr 2011, at 16:18, sebb wrote:

> On 31 March 2011 19:41, Ben Cuthbert <be...@yahoo.co.uk> wrote:
>> All
>> 
>> I have been looking over the code in the JUnitSampler code under the jmeter source.
>> I would like to make a change to use nanoTime() rather than milliseconds.
> 
> Why?
> 
>> I can see in the AnnotatedTestCase there is an elapsed time. But I can't see how it
>> is returned to a results table. Any ideas?
> 
> The time in AnnotatedTestCase is only used for reporting timeout errors.
> 
> The actual sample time is calculated using SampleResult.sampleStart()
> and sampleEnd() which already use nanoTime().
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: dev-help@jakarta.apache.org
> 


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: dev-help@jakarta.apache.org