I have a Java project (Java 8) that should execute a task every 10ms. I use java ScheduledExecutorService to run the task:
ScheduledExecutorService executorService = Executors.newSingleThreadScheduledExecutor();
executorService.scheduleAtFixedRate(new QueueTask(), 0, 10, TimeUnit.MILLISECONDS);
The QueueTask extends Runnable and polls from a queue - not taking more than 10ms. Every run of QueueTask I log "started QueueTask".
For some reason according to the logs, the task is running at the same millisecond and I don't understand why. For example:
2022-03-09 15:24:32.362 INFO 12536 --- [pool-1-thread-1] com.example.consumer.QueueTask : started QueueTask, uuid: 40bf7e61-66f3-4869-b5f8-43b9cac8e203, nanoTime: 311179321467600
2022-03-09 15:24:32.362 INFO 12536 --- [pool-1-thread-1] com.example.consumer.QueueTask : started QueueTask, uuid: a63b814f-2016-4b1a-b17b-d870e4b38c64, nanoTime: 311179322025300
2022-03-09 15:24:32.362 INFO 12536 --- [pool-1-thread-1] com.example.consumer.QueueTask : started QueueTask, uuid: 17879b1f-96ed-4236-9902-ff98fc772b5a, nanoTime: 311179322376100
I don't understand how this is happening. I have one thread that is scheduled to run every 10ms and it runs at the same millisecond sometimes. By the way, it doesn't run exactly every 10ms, for my understanding it is impossible for the scheduler to be 100% accurate but it should not behave this way. I also tried using more than one thread in the thread pool but it didn't help.
You can see that the nanoseconds printed using System.nanoTime() is different between the logs, but the difference between the first and second logs is: 350800 nanoseconds which is 0.3508 milliseconds. So this means that the task is not running 10ms apart.
CodePudding user response：
Note that executorService.scheduleAtFixedRate() as mentioned within the Java documentation will submit the task to the thread , and that doesn't mean that the thread will execute the task in the given time exactly.
Also you cannot guarantee the time of execution of the task, it can be more than 10 ms for the firsts tasks and then less than 10 ms.
So you will have every 10 ms a new task submitted to your single thread, the time of execution of those tasks is not fixed, and probably it is more or less than 10 ms, so the number of tasks within the task pool will be more than the tasks executed and your thread will try to print all of them and that's why you see that it print the same time there. The output is not guaranteed and you cannot expect it in your case, it depends also on your machine and your thread scheduler.
Java documentation of the method scheduleAtFixedRate:
Submits a periodic action that becomes enabled first after the given initial delay, and subsequently with the given period; that is, executions will commence after initialDelay, then initialDelay period, then initialDelay 2 * period, and so on.
CodePudding user response：
Short runs make up for long runs
I built some code to experiment with the scheduling.
What I am seeing is that some runs are too short (under 10ms) in order to make up for some runs that went too long (over 10ms).
For every 100 iterations I run, I get about half that are just under 10ms, and about half that over 10 ms, with the total average being very close to 10 ms. If 47 of 100 iterations run long, then 53 run short, for example. If 46 long, then 54 short, and so on. When perusing the results data, it seems the long-short runs are interleaved.
This result makes sense given the documentation for ScheduledExecutorService#scheduleAtFixedRate . If you ask for increments of 10 ms, the service strives to meet that target of every 10 ms since the start, not 10 ms since the last iteration completed. That striving involves compensating for long runs by shortening others.
But perhaps I am wrong. Either my code may be faulty, or my reasoning. Please correct me as needed.
package work.basil.threading;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;
public class TenMs
{
public static void main ( String[] args )
{
// Setup experiment.
System.out.println( "INFO - Demo start. " System.nanoTime() );
final int runDemoForMilliseconds = 1000;
final int iterationMillis = 10;
final int initialCapacity = ( runDemoForMilliseconds / iterationMillis ) 2;
final AtomicLong momentOfExecution = new AtomicLong( System.nanoTime() );
record Moment( long then , long now , long elapsed )
{
@Override
public String toString ( )
{
return "Moment[" String.join( "|" , "then=" , Long.toString( this.then ) , "now=" , Long.toString( this.now ) , "elapsed=" , Long.toString( this.elapsed ) ,
"elapsed ms = " TimeUnit.MILLISECONDS.convert( this.elapsed , TimeUnit.NANOSECONDS ) ) "]";
}
}
final List < Moment > moments = new ArrayList <>( initialCapacity );
final Runnable task = ( ) -> {
long then = momentOfExecution.getAndSet( System.nanoTime() );
long now = momentOfExecution.get();
moments.add( new Moment( then , now , ( now - then ) ) );
//try { Thread.sleep( 5 ); } catch ( InterruptedException e ) { throw new RuntimeException( e ); }
};
// Run experiment.
final ScheduledExecutorService ses = Executors.newSingleThreadScheduledExecutor();
ses.scheduleAtFixedRate( task , 0 , 10 , TimeUnit.MILLISECONDS );
//ses.scheduleWithFixedDelay( task , 0 , 10 , TimeUnit.MILLISECONDS );
try { Thread.sleep( runDemoForMilliseconds ); } catch ( InterruptedException e ) { throw new RuntimeException( e ); }
ses.shutdownNow();
try { ses.awaitTermination( runDemoForMilliseconds * 2 , TimeUnit.MILLISECONDS ); }catch ( InterruptedException e ) { throw new RuntimeException( e ); }
// Analyze results of experiment.
moments.remove( 0 ); // Discard first run, as it involves the startup code's delay.
long averageElapsedNanos = ( long ) moments.stream().mapToLong( Moment :: elapsed ).average().orElse( - 666d );
long averageElapsedMillis = TimeUnit.MILLISECONDS.convert( averageElapsedNanos , TimeUnit.NANOSECONDS );
System.out.println( "averageElapsedNanos = " averageElapsedNanos );
System.out.println( "averageElapsedMillis = " averageElapsedMillis );
List < Moment > under10ms = moments.stream().filter( moment -> moment.elapsed < TimeUnit.NANOSECONDS.convert( 10 , TimeUnit.MILLISECONDS ) ).toList();
List < Moment > exactly10ms = moments.stream().filter( moment -> moment.elapsed == TimeUnit.NANOSECONDS.convert( 10 , TimeUnit.MILLISECONDS ) ).toList();
List < Moment > over10ms = moments.stream().filter( moment -> moment.elapsed > TimeUnit.NANOSECONDS.convert( 10 , TimeUnit.MILLISECONDS ) ).toList();
System.out.println( under10ms.size() " under 10 ms: " under10ms );
System.out.println( exactly10ms.size() " exactly 10 ms: " exactly10ms );
System.out.println( over10ms.size() " over 10 ms: " over10ms );
System.out.println( "moments.size() = " moments.size() );
System.out.println( "moments = " moments );
System.out.println( "INFO - Demo end. " System.nanoTime() );
}
}
When run on a MacBook Pro (13-inch, M1, 2020), M1 Apple Silicon chip with 4 efficiency cores and 4 performance cores, and 16 gigs memory. Executed from IntelliJ 2022.1 EAP on Java 17.0.2.
INFO - Demo start. 162867211907750
averageElapsedNanos = 10009907
averageElapsedMillis = 10
54 under 10 ms: [Moment[then=|162867232777375|now=|162867242202833|elapsed=|9425458|elapsed ms = 9], Moment[then=|162867252876333|now=|162867262335291|elapsed=|9458958|elapsed ms = 9], Moment[then=|162867262335291|now=|162867270992458|elapsed=|8657167|elapsed ms = 8], Moment[then=|162867283166791|now=|162867292620625|elapsed=|9453834|elapsed ms = 9], Moment[then=|162867292620625|now=|162867301683791|elapsed=|9063166|elapsed ms = 9], Moment[then=|162867313011041|now=|162867322679541|elapsed=|9668500|elapsed ms = 9], Moment[then=|162867342782791|now=|162867352760333|elapsed=|9977542|elapsed ms = 9], Moment[then=|162867372793958|now=|162867382731083|elapsed=|9937125|elapsed ms = 9], Moment[then=|162867392778750|now=|162867402749458|elapsed=|9970708|elapsed ms = 9], Moment[then=|162867402749458|now=|162867412179000|elapsed=|9429542|elapsed ms = 9], Moment[then=|162867422922208|now=|162867432750083|elapsed=|9827875|elapsed ms = 9], Moment[then=|162867452829250|now=|162867462773791|elapsed=|9944541|elapsed ms = 9], Moment[then=|162867462773791|now=|162867472772250|elapsed=|9998459|elapsed ms = 9], Moment[then=|162867472772250|now=|162867482735583|elapsed=|9963333|elapsed ms = 9], Moment[then=|162867492755833|now=|162867502739958|elapsed=|9984125|elapsed ms = 9], Moment[then=|162867522892250|now=|162867532706291|elapsed=|9814041|elapsed ms = 9], Moment[then=|162867532706291|now=|162867542669250|elapsed=|9962959|elapsed ms = 9], Moment[then=|162867552836500|now=|162867562807916|elapsed=|9971416|elapsed ms = 9], Moment[then=|162867562807916|now=|162867572736458|elapsed=|9928542|elapsed ms = 9], Moment[then=|162867572736458|now=|162867581052458|elapsed=|8316000|elapsed ms = 8], Moment[then=|162867593213708|now=|162867601604291|elapsed=|8390583|elapsed ms = 8], Moment[then=|162867613152250|now=|162867622672250|elapsed=|9520000|elapsed ms = 9], Moment[then=|162867632754041|now=|162867642711791|elapsed=|9957750|elapsed ms = 9], Moment[then=|162867652745125|now=|162867660950750|elapsed=|8205625|elapsed ms = 8], Moment[then=|162867673205416|now=|162867682648458|elapsed=|9443042|elapsed ms = 9], Moment[then=|162867702750208|now=|162867712719166|elapsed=|9968958|elapsed ms = 9], Moment[then=|162867722770291|now=|162867732742083|elapsed=|9971792|elapsed ms = 9], Moment[then=|162867742745750|now=|162867752721166|elapsed=|9975416|elapsed ms = 9], Moment[then=|162867752721166|now=|162867762038083|elapsed=|9316917|elapsed ms = 9], Moment[then=|162867772938291|now=|162867782701208|elapsed=|9762917|elapsed ms = 9], Moment[then=|162867792819250|now=|162867802733958|elapsed=|9914708|elapsed ms = 9], Moment[then=|162867812754916|now=|162867822730166|elapsed=|9975250|elapsed ms = 9], Moment[then=|162867852834958|now=|162867862754000|elapsed=|9919042|elapsed ms = 9], Moment[then=|162867872797875|now=|162867882771166|elapsed=|9973291|elapsed ms = 9], Moment[then=|162867882771166|now=|162867892719333|elapsed=|9948167|elapsed ms = 9], Moment[then=|162867892719333|now=|162867901537291|elapsed=|8817958|elapsed ms = 8], Moment[then=|162867913086583|now=|162867922725166|elapsed=|9638583|elapsed ms = 9], Moment[then=|162867932766916|now=|162867942723708|elapsed=|9956792|elapsed ms = 9], Moment[then=|162867942723708|now=|162867950987166|elapsed=|8263458|elapsed ms = 8], Moment[then=|162867963205000|now=|162867972662291|elapsed=|9457291|elapsed ms = 9], Moment[then=|162868002963166|now=|162868011406875|elapsed=|8443709|elapsed ms = 8], Moment[then=|162868023188125|now=|162868031231500|elapsed=|8043375|elapsed ms = 8], Moment[then=|162868043275291|now=|162868052630166|elapsed=|9354875|elapsed ms = 9], Moment[then=|162868062829125|now=|162868072762000|elapsed=|9932875|elapsed ms = 9], Moment[then=|162868082837791|now=|162868092819500|elapsed=|9981709|elapsed ms = 9], Moment[then=|162868092819500|now=|162868102766750|elapsed=|9947250|elapsed ms = 9], Moment[then=|162868112903958|now=|162868121689041|elapsed=|8785083|elapsed ms = 8], Moment[then=|162868133048041|now=|162868142725875|elapsed=|9677834|elapsed ms = 9], Moment[then=|162868142725875|now=|162868151383958|elapsed=|8658083|elapsed ms = 8], Moment[then=|162868163148958|now=|162868172674750|elapsed=|9525792|elapsed ms = 9], Moment[then=|162868182812916|now=|162868192789250|elapsed=|9976334|elapsed ms = 9], Moment[then=|162868192789250|now=|162868202785916|elapsed=|9996666|elapsed ms = 9], Moment[then=|162868202785916|now=|162868212745625|elapsed=|9959709|elapsed ms = 9], Moment[then=|162868212745625|now=|162868222741375|elapsed=|9995750|elapsed ms = 9]]
0 exactly 10 ms: []
46 over 10 ms: [Moment[then=|162867221750666|now=|162867232777375|elapsed=|11026709|elapsed ms = 11], Moment[then=|162867242202833|now=|162867252876333|elapsed=|10673500|elapsed ms = 10], Moment[then=|162867270992458|now=|162867283166791|elapsed=|12174333|elapsed ms = 12], Moment[then=|162867301683791|now=|162867313011041|elapsed=|11327250|elapsed ms = 11], Moment[then=|162867322679541|now=|162867332759166|elapsed=|10079625|elapsed ms = 10], Moment[then=|162867332759166|now=|162867342782791|elapsed=|10023625|elapsed ms = 10], Moment[then=|162867352760333|now=|162867362760500|elapsed=|10000167|elapsed ms = 10], Moment[then=|162867362760500|now=|162867372793958|elapsed=|10033458|elapsed ms = 10], Moment[then=|162867382731083|now=|162867392778750|elapsed=|10047667|elapsed ms = 10], Moment[then=|162867412179000|now=|162867422922208|elapsed=|10743208|elapsed ms = 10], Moment[then=|162867432750083|now=|162867442783500|elapsed=|10033417|elapsed ms = 10], Moment[then=|162867442783500|now=|162867452829250|elapsed=|10045750|elapsed ms = 10], Moment[then=|162867482735583|now=|162867492755833|elapsed=|10020250|elapsed ms = 10], Moment[then=|162867502739958|now=|162867512789125|elapsed=|10049167|elapsed ms = 10], Moment[then=|162867512789125|now=|162867522892250|elapsed=|10103125|elapsed ms = 10], Moment[then=|162867542669250|now=|162867552836500|elapsed=|10167250|elapsed ms = 10], Moment[then=|162867581052458|now=|162867593213708|elapsed=|12161250|elapsed ms = 12], Moment[then=|162867601604291|now=|162867613152250|elapsed=|11547959|elapsed ms = 11], Moment[then=|162867622672250|now=|162867632754041|elapsed=|10081791|elapsed ms = 10], Moment[then=|162867642711791|now=|162867652745125|elapsed=|10033334|elapsed ms = 10], Moment[then=|162867660950750|now=|162867673205416|elapsed=|12254666|elapsed ms = 12], Moment[then=|162867682648458|now=|162867692740291|elapsed=|10091833|elapsed ms = 10], Moment[then=|162867692740291|now=|162867702750208|elapsed=|10009917|elapsed ms = 10], Moment[then=|162867712719166|now=|162867722770291|elapsed=|10051125|elapsed ms = 10], Moment[then=|162867732742083|now=|162867742745750|elapsed=|10003667|elapsed ms = 10], Moment[then=|162867762038083|now=|162867772938291|elapsed=|10900208|elapsed ms = 10], Moment[then=|162867782701208|now=|162867792819250|elapsed=|10118042|elapsed ms = 10], Moment[then=|162867802733958|now=|162867812754916|elapsed=|10020958|elapsed ms = 10], Moment[then=|162867822730166|now=|162867832762791|elapsed=|10032625|elapsed ms = 10], Moment[then=|162867832762791|now=|162867842782541|elapsed=|10019750|elapsed ms = 10], Moment[then=|162867842782541|now=|162867852834958|elapsed=|10052417|elapsed ms = 10], Moment[then=|162867862754000|now=|162867872797875|elapsed=|10043875|elapsed ms = 10], Moment[then=|162867901537291|now=|162867913086583|elapsed=|11549292|elapsed ms = 11], Moment[then=|162867922725166|now=|162867932766916|elapsed=|10041750|elapsed ms = 10], Moment[then=|162867950987166|now=|162867963205000|elapsed=|12217834|elapsed ms = 12], Moment[then=|162867972662291|now=|162867982797833|elapsed=|10135542|elapsed ms = 10], Moment[then=|162867982797833|now=|162867992885583|elapsed=|10087750|elapsed ms = 10], Moment[then=|162867992885583|now=|162868002963166|elapsed=|10077583|elapsed ms = 10], Moment[then=|162868011406875|now=|162868023188125|elapsed=|11781250|elapsed ms = 11], Moment[then=|162868031231500|now=|162868043275291|elapsed=|12043791|elapsed ms = 12], Moment[then=|162868052630166|now=|162868062829125|elapsed=|10198959|elapsed ms = 10], Moment[then=|162868072762000|now=|162868082837791|elapsed=|10075791|elapsed ms = 10], Moment[then=|162868102766750|now=|162868112903958|elapsed=|10137208|elapsed ms = 10], Moment[then=|162868121689041|now=|162868133048041|elapsed=|11359000|elapsed ms = 11], Moment[then=|162868151383958|now=|162868163148958|elapsed=|11765000|elapsed ms = 11], Moment[then=|162868172674750|now=|162868182812916|elapsed=|10138166|elapsed ms = 10]]
moments.size() = 100
moments = [Moment[then=|162867221750666|now=|162867232777375|elapsed=|11026709|elapsed ms = 11], Moment[then=|162867232777375|now=|162867242202833|elapsed=|9425458|elapsed ms = 9], Moment[then=|162867242202833|now=|162867252876333|elapsed=|10673500|elapsed ms = 10], Moment[then=|162867252876333|now=|162867262335291|elapsed=|9458958|elapsed ms = 9], Moment[then=|162867262335291|now=|162867270992458|elapsed=|8657167|elapsed ms = 8], Moment[then=|162867270992458|now=|162867283166791|elapsed=|12174333|elapsed ms = 12], Moment[then=|162867283166791|now=|162867292620625|elapsed=|9453834|elapsed ms = 9], Moment[then=|162867292620625|now=|162867301683791|elapsed=|9063166|elapsed ms = 9], Moment[then=|162867301683791|now=|162867313011041|elapsed=|11327250|elapsed ms = 11], Moment[then=|162867313011041|now=|162867322679541|elapsed=|9668500|elapsed ms = 9], Moment[then=|162867322679541|now=|162867332759166|elapsed=|10079625|elapsed ms = 10], Moment[then=|162867332759166|now=|162867342782791|elapsed=|10023625|elapsed ms = 10], Moment[then=|162867342782791|now=|162867352760333|elapsed=|9977542|elapsed ms = 9], Moment[then=|162867352760333|now=|162867362760500|elapsed=|10000167|elapsed ms = 10], Moment[then=|162867362760500|now=|162867372793958|elapsed=|10033458|elapsed ms = 10], Moment[then=|162867372793958|now=|162867382731083|elapsed=|9937125|elapsed ms = 9], Moment[then=|162867382731083|now=|162867392778750|elapsed=|10047667|elapsed ms = 10], Moment[then=|162867392778750|now=|162867402749458|elapsed=|9970708|elapsed ms = 9], Moment[then=|162867402749458|now=|162867412179000|elapsed=|9429542|elapsed ms = 9], Moment[then=|162867412179000|now=|162867422922208|elapsed=|10743208|elapsed ms = 10], Moment[then=|162867422922208|now=|162867432750083|elapsed=|9827875|elapsed ms = 9], Moment[then=|162867432750083|now=|162867442783500|elapsed=|10033417|elapsed ms = 10], Moment[then=|162867442783500|now=|162867452829250|elapsed=|10045750|elapsed ms = 10], Moment[then=|162867452829250|now=|162867462773791|elapsed=|9944541|elapsed ms = 9], Moment[then=|162867462773791|now=|162867472772250|elapsed=|9998459|elapsed ms = 9], Moment[then=|162867472772250|now=|162867482735583|elapsed=|9963333|elapsed ms = 9], Moment[then=|162867482735583|now=|162867492755833|elapsed=|10020250|elapsed ms = 10], Moment[then=|162867492755833|now=|162867502739958|elapsed=|9984125|elapsed ms = 9], Moment[then=|162867502739958|now=|162867512789125|elapsed=|10049167|elapsed ms = 10], Moment[then=|162867512789125|now=|162867522892250|elapsed=|10103125|elapsed ms = 10], Moment[then=|162867522892250|now=|162867532706291|elapsed=|9814041|elapsed ms = 9], Moment[then=|162867532706291|now=|162867542669250|elapsed=|9962959|elapsed ms = 9], Moment[then=|162867542669250|now=|162867552836500|elapsed=|10167250|elapsed ms = 10], Moment[then=|162867552836500|now=|162867562807916|elapsed=|9971416|elapsed ms = 9], Moment[then=|162867562807916|now=|162867572736458|elapsed=|9928542|elapsed ms = 9], Moment[then=|162867572736458|now=|162867581052458|elapsed=|8316000|elapsed ms = 8], Moment[then=|162867581052458|now=|162867593213708|elapsed=|12161250|elapsed ms = 12], Moment[then=|162867593213708|now=|162867601604291|elapsed=|8390583|elapsed ms = 8], Moment[then=|162867601604291|now=|162867613152250|elapsed=|11547959|elapsed ms = 11], Moment[then=|162867613152250|now=|162867622672250|elapsed=|9520000|elapsed ms = 9], Moment[then=|162867622672250|now=|162867632754041|elapsed=|10081791|elapsed ms = 10], Moment[then=|162867632754041|now=|162867642711791|elapsed=|9957750|elapsed ms = 9], Moment[then=|162867642711791|now=|162867652745125|elapsed=|10033334|elapsed ms = 10], Moment[then=|162867652745125|now=|162867660950750|elapsed=|8205625|elapsed ms = 8], Moment[then=|162867660950750|now=|162867673205416|elapsed=|12254666|elapsed ms = 12], Moment[then=|162867673205416|now=|162867682648458|elapsed=|9443042|elapsed ms = 9], Moment[then=|162867682648458|now=|162867692740291|elapsed=|10091833|elapsed ms = 10], Moment[then=|162867692740291|now=|162867702750208|elapsed=|10009917|elapsed ms = 10], Moment[then=|162867702750208|now=|162867712719166|elapsed=|9968958|elapsed ms = 9], Moment[then=|162867712719166|now=|162867722770291|elapsed=|10051125|elapsed ms = 10], Moment[then=|162867722770291|now=|162867732742083|elapsed=|9971792|elapsed ms = 9], Moment[then=|162867732742083|now=|162867742745750|elapsed=|10003667|elapsed ms = 10], Moment[then=|162867742745750|now=|162867752721166|elapsed=|9975416|elapsed ms = 9], Moment[then=|162867752721166|now=|162867762038083|elapsed=|9316917|elapsed ms = 9], Moment[then=|162867762038083|now=|162867772938291|elapsed=|10900208|elapsed ms = 10], Moment[then=|162867772938291|now=|162867782701208|elapsed=|9762917|elapsed ms = 9], Moment[then=|162867782701208|now=|162867792819250|elapsed=|10118042|elapsed ms = 10], Moment[then=|162867792819250|now=|162867802733958|elapsed=|9914708|elapsed ms = 9], Moment[then=|162867802733958|now=|162867812754916|elapsed=|10020958|elapsed ms = 10], Moment[then=|162867812754916|now=|162867822730166|elapsed=|9975250|elapsed ms = 9], Moment[then=|162867822730166|now=|162867832762791|elapsed=|10032625|elapsed ms = 10], Moment[then=|162867832762791|now=|162867842782541|elapsed=|10019750|elapsed ms = 10], Moment[then=|162867842782541|now=|162867852834958|elapsed=|10052417|elapsed ms = 10], Moment[then=|162867852834958|now=|162867862754000|elapsed=|9919042|elapsed ms = 9], Moment[then=|162867862754000|now=|162867872797875|elapsed=|10043875|elapsed ms = 10], Moment[then=|162867872797875|now=|162867882771166|elapsed=|9973291|elapsed ms = 9], Moment[then=|162867882771166|now=|162867892719333|elapsed=|9948167|elapsed ms = 9], Moment[then=|162867892719333|now=|162867901537291|elapsed=|8817958|elapsed ms = 8], Moment[then=|162867901537291|now=|162867913086583|elapsed=|11549292|elapsed ms = 11], Moment[then=|162867913086583|now=|162867922725166|elapsed=|9638583|elapsed ms = 9], Moment[then=|162867922725166|now=|162867932766916|elapsed=|10041750|elapsed ms = 10], Moment[then=|162867932766916|now=|162867942723708|elapsed=|9956792|elapsed ms = 9], Moment[then=|162867942723708|now=|162867950987166|elapsed=|8263458|elapsed ms = 8], Moment[then=|162867950987166|now=|162867963205000|elapsed=|12217834|elapsed ms = 12], Moment[then=|162867963205000|now=|162867972662291|elapsed=|9457291|elapsed ms = 9], Moment[then=|162867972662291|now=|162867982797833|elapsed=|10135542|elapsed ms = 10], Moment[then=|162867982797833|now=|162867992885583|elapsed=|10087750|elapsed ms = 10], Moment[then=|162867992885583|now=|162868002963166|elapsed=|10077583|elapsed ms = 10], Moment[then=|162868002963166|now=|162868011406875|elapsed=|8443709|elapsed ms = 8], Moment[then=|162868011406875|now=|162868023188125|elapsed=|11781250|elapsed ms = 11], Moment[then=|162868023188125|now=|162868031231500|elapsed=|8043375|elapsed ms = 8], Moment[then=|162868031231500|now=|162868043275291|elapsed=|12043791|elapsed ms = 12], Moment[then=|162868043275291|now=|162868052630166|elapsed=|9354875|elapsed ms = 9], Moment[then=|162868052630166|now=|162868062829125|elapsed=|10198959|elapsed ms = 10], Moment[then=|162868062829125|now=|162868072762000|elapsed=|9932875|elapsed ms = 9], Moment[then=|162868072762000|now=|162868082837791|elapsed=|10075791|elapsed ms = 10], Moment[then=|162868082837791|now=|162868092819500|elapsed=|9981709|elapsed ms = 9], Moment[then=|162868092819500|now=|162868102766750|elapsed=|9947250|elapsed ms = 9], Moment[then=|162868102766750|now=|162868112903958|elapsed=|10137208|elapsed ms = 10], Moment[then=|162868112903958|now=|162868121689041|elapsed=|8785083|elapsed ms = 8], Moment[then=|162868121689041|now=|162868133048041|elapsed=|11359000|elapsed ms = 11], Moment[then=|162868133048041|now=|162868142725875|elapsed=|9677834|elapsed ms = 9], Moment[then=|162868142725875|now=|162868151383958|elapsed=|8658083|elapsed ms = 8], Moment[then=|162868151383958|now=|162868163148958|elapsed=|11765000|elapsed ms = 11], Moment[then=|162868163148958|now=|162868172674750|elapsed=|9525792|elapsed ms = 9], Moment[then=|162868172674750|now=|162868182812916|elapsed=|10138166|elapsed ms = 10], Moment[then=|162868182812916|now=|162868192789250|elapsed=|9976334|elapsed ms = 9], Moment[then=|162868192789250|now=|162868202785916|elapsed=|9996666|elapsed ms = 9], Moment[then=|162868202785916|now=|162868212745625|elapsed=|9959709|elapsed ms = 9], Moment[then=|162868212745625|now=|162868222741375|elapsed=|9995750|elapsed ms = 9]]
INFO - Demo end. 162868252016666