I created a 1000 threads and each thread takes about 10 seconds to finish. During these 10 seconds the thread doesn't sleep but does a simple math operation. However, the program still finishes under 20 seconds on my PC (Intel i7 6 cores). I don't understand how. I was expecting it will take at least about 1000/6=167 seconds. Any idea what is going on ?
public class test
{
public static void main(String args[]) throws Exception
{
long startTime = System.currentTimeMillis();
Thread[] threads = new Thread[1000];
for(int i = 0; i<1000; i++){
threads[i] = new Thread(()->doSomething(10));
threads[i].start();
}
for(Thread t : threads){
t.join();
}
long endTime = System.currentTimeMillis();
System.out.println("Time taken "+(endTime - startTime)/1000);
}
public static int doSomething(int seconds){
long st = System.currentTimeMillis();
long usageTimeInMillis = seconds*1000L;
long startTime = System.currentTimeMillis();
int i = 0;
while ((System.currentTimeMillis() - startTime) < usageTimeInMillis) { i++; }
long lt = System.currentTimeMillis();
System.out.println("Done "+Thread.currentThread().getId()+" in "+(lt-st)/1000+" seconds ");
return i;
}
}
Here is the partial output:
Done 48 in 10 seconds
Done 36 in 10 seconds
Done 597 in 10 seconds
...
Done 206 in 10 seconds
Done 217 in 10 seconds
....
Done 462 in 10 seconds
Time taken 17
The output shows that every thread does run for about 10 seconds. Then how come a 1000 threads finished in 17 seconds?
As commented by Maurice Perry, you devised a task that would take ten seconds to execute, but that is ten seconds of time elapsed on the clock, not ten seconds of CPU activity.
You loop repeatedly, checking the current time on each loop. You check the time by calling System.currentTimeMillis(). Your intention was to keep the CPU core busy for the entire ten seconds. But that is not what is happening.
The host OS managing the platform threads in Java schedules a thread for execution at a time, and for a duration, of its own choosing. Your Java platform thread may be paused at any time by that host OS. So, in an extreme example case, your code may be checking the current time once, for a result of 2024-01-23T00:00:22.123Z. Then the host OS may suspend your thread. Your thread does nothing for several seconds. Eventually the host OS schedules that thread for further execution. The second time your code checks the time, the result is 2024-01-23T00:00:34.567Z. So over 12 seconds elapsed, but your code ran only briefly, just checking the current time twice.
That example is a bit extreme, as the host OS will not generally let a thread go 12 seconds without executing. But if your host computer’s CPU is severely overburdened, such as running a thousand Java threads, such long thread suspensions could indeed happen.
So the behavior you experienced is a feature, not a bug. A thousand tasks waiting for ten seconds to expire on the system clock will indeed, in total, take about ten seconds.
Running your exact code takes 20 seconds on my MacBook Pro, 16-inch, 2021, Apple M1 Pro, 10 cores (8 performance and 2 efficiency), 16 GB RAM, macOS Sonoma 14.3.1, Java 21.0.1 in IntelliJ IntelliJ IDEA 2023.3.4 (Ultimate Edition).
Then I modified your code. I show the number of loops executed in each task.
package work.basil.example.threading;
import java.time.*;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.stream.IntStream;
public class BusyBusy
{
public static void main ( String args[] ) throws Exception
{
System.out.println ( "Demo start at " + Instant.now ( ) );
final long demoStartNanos = System.nanoTime ( );
final int countTasks = 1_000;
try (
ExecutorService executorService = Executors.newFixedThreadPool ( countTasks ) ; // We want one task per thread. So one thousand tasks means one thousand threads.
)
{
IntStream
.rangeClosed ( 1 , countTasks )
.mapToObj ( TenSecondTask :: new )
.forEach ( executorService :: submit );
}
Duration demoDuration = Duration.ofNanos ( System.nanoTime ( ) - demoStartNanos );
System.out.println ( "Demo end at " + Instant.now ( ) + ". demoDuration = " + demoDuration );
}
}
class TenSecondTask implements Runnable
{
private final int sequenceNumber;
public TenSecondTask ( final int sequenceNumber )
{
this.sequenceNumber = sequenceNumber;
}
@Override
public void run ( )
{
final long tenSecondsInNanos = Duration.ofSeconds ( 10 ).toNanos ( );
final long taskStartNanos = System.nanoTime ( );
long countLoops = 0;
while (
( System.nanoTime ( ) - taskStartNanos ) < tenSecondsInNanos
)
{
countLoops++;
}
System.out.println ( "Task # " + this.sequenceNumber + " in thread ID " + Thread.currentThread ( ).threadId ( ) + " done at " + Instant.now ( ) + ". Loops: " + String.format ( "%,d" , countLoops ) );
}
}
My results showing a wide range of over a hundred thousand to over seven million. Total time elapsed is about 20 seconds, same as your code.
Demo start at 2024-02-15T09:24:13.773544Z
Task # 6 in thread ID 26 done at 2024-02-15T09:24:23.779903Z. Loops: 328,186
Task # 11 in thread ID 31 done at 2024-02-15T09:24:23.812401Z. Loops: 349,456
Task # 13 in thread ID 33 done at 2024-02-15T09:24:23.839549Z. Loops: 356,229
Task # 20 in thread ID 40 done at 2024-02-15T09:24:23.883941Z. Loops: 379,757
…
Task # 991 in thread ID 1019 done at 2024-02-15T09:24:33.561808Z. Loops: 981,788
Task # 992 in thread ID 1020 done at 2024-02-15T09:24:33.566229Z. Loops: 1,034,678
Task # 993 in thread ID 1021 done at 2024-02-15T09:24:33.572045Z. Loops: 1,172,157
Task # 994 in thread ID 1022 done at 2024-02-15T09:24:33.576395Z. Loops: 1,067,262
Task # 995 in thread ID 1023 done at 2024-02-15T09:24:33.582312Z. Loops: 1,034,725
Task # 996 in thread ID 1024 done at 2024-02-15T09:24:33.586528Z. Loops: 1,134,316
Task # 997 in thread ID 1025 done at 2024-02-15T09:24:33.592593Z. Loops: 1,112,738
Task # 998 in thread ID 1026 done at 2024-02-15T09:24:34.158249Z. Loops: 6,455,185
Task # 999 in thread ID 1027 done at 2024-02-15T09:24:34.158381Z. Loops: 6,484,593
Task # 1000 in thread ID 1028 done at 2024-02-15T09:24:34.168723Z. Loops: 7,411,728
Demo end at 2024-02-15T09:24:34.168958Z. demoDuration = PT20.392301916S
By the way, System.currentTimeMillis() was years ago supplanted by Instant.now(). Calling Instant.now captures the current moment with a resolution of microseconds rather than mere milliseconds in Java 9+ on implementations based on OpenJDK code base.