Issue
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.
Solution
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.
Answered By - Oussama ZAGHDOUD
0 comments:
Post a Comment
Note: Only a member of this blog may post a comment.