Java Multithreading - return statement taking too much time

Question

In multithreading (Executor framework), the sum total of all time-prints within x() method is not matching to the total time printed by doPerform. And this difference keeps on growing with increasing number of threads in threadpool (goes upto 20 secs). Can someone please figure out why? And is there any way to decrease time taken to return from x method?
I have tested it with:

a) 500 submissions to executor (poolsize =100)
b) 500 submissions to executor (poolsize =300)
c) 300 submissions to executor (poolsize =100)

public void x() {
    long startTime = System.currentTimeMillis();
    for (long l = 0; l <= 10000000; l++) {
        if (l % 1000000 == 0) {
            System.out.println("Thread id: "
                    + Thread.currentThread().getId() + "\t"
                    + (System.currentTimeMillis() - startTime));
            startTime = System.currentTimeMillis();
        }
    }
}

public void doPerform() {
    long startTime = System.currentTimeMillis();
    x();
    System.out.println("Thread id: " + Thread.currentThread().getId()
            + "\t" + (System.currentTimeMillis() - startTime));
}

``System.out.println`` is most likely synchronized, hence everything ends up running single-threaded anyway. (Whether it actually is or not depends on the implementation of the ``PrintStream``, but in the OpenJDK at least it is synchronized. See: http://stackoverflow.com/a/10468250/220381). Console output is generally very slow. — Ash, Dec 23 '12 at 10:23

score 1 · Accepted Answer · answered Dec 23 '12 at 10:24

1

That's expected. You have 100 or 300 parallel threads being executed, and only 1, 2 or 4 cores to execute them all (unless you're running this on a giant super computer). This means that each thread is assigned some CPU time, then some other thread, then some other thread, etc. giving the illusion of parallel execution. But in reality, instructions of various threads are interlaced and executed sequentially.

So, you could have a thread A's startTime computation in doPerform() executed, and then the thread could be replaced by several other ones one on the CPU. A number of milliseconds could elapse before the thread scheduler reassigns A to a CPU and the startTime computation in x() is executed.

answered Dec 23 '12 at 10:24

JB Nizet

678,734
91
1,224
1,255

Yes, that's understood. But does that mean that everytime the context switch happens exactly before the time is printed in doPerform()? Otherwise the difference b/w the sum total of time-prints in x() and time print in doPerform should not be huge. – Hemanshu Dec 23 '12 at 10:46
Yes, the context sitching can happen anywhere: before the call to `x()`, after the call to `x()`, inside the call to System.out.println, inside the loop... anywhere. – JB Nizet Dec 23 '12 at 10:52

Java Multithreading - return statement taking too much time

1 Answers1