Unable to understand the time consumption by Java threads

103 views Asked by At

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?

3

There are 3 answers

2
Basil Bourque On BEST ANSWER

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.

0
Max Meijer On

As is, your code does not work because the processor switches away to other threads during the execution of your thread.

One way to get what you want is to do a busy loop and keep checking how much time passed since the last iteration. If it is above a certain threshold, you assume a context switch happened so the time does not count. Example:

long passedTime=0;
long i=0;
long currentTime=System.nanoTime();
while (passedTime<usageTimeInMillis*1000*1000) {
    long nextTime = System.nanoTime();
    long increase = nextTime - currentTime;
    if (increase < 1000*1000) {
        passedTime += increase;
    } else {
        passedTime += Math.min(i>0 ? passedTime/i : 0, increase);
    }
    currentTime=nextTime;
    i++;
}

Also, note that I have used nanoTime to avoid unnecessary inaccuracies due to rounding.

Context switches generally take at least a couple of milliseconds by a large margin and checking the current time, performing a couple of additions, subtractions and conditional jumps takes in the tens of nanoseconds, so that it is clear whether there was a switch or not.

0
matt On

Another way to think of this problem is not think of the task in terms of threads and cores which java tries to abstract away. Think of it in terms of resources.

You have N resources you want each task to hold a resource for 10 seconds then release it.

A good representation of a resource is a Semaphore. With this we get to explicitly tell java when we want to release a resource. With a thread, either java (virtual threads) or the OS can decide to release a thread and do something else.

You only have to make some minor changes to get the results you expect. One of them being to import java.util.concurrent.Semaphore; then at the beginning of main.

Semaphore cores = new Semaphore(6);

When you create your threads.

threads[i] = new Thread(()->{
   try{
       cores.acquire(1);
       doSomething(10);
   } catch(Exception e){
       throw new RuntimeException(e);
   } finally{
       cores.release();
   }
}

Now when you run the tasks you'll see groups of 6 getting fired off every 10 seconds. These results could vary depending on the actual number of cores and threads.