Latency in starting threads on Mac OS X

[Scott Palmer]

I doubt you are measuring what you think you are measuring. Maybe try the same while printing the GC details.
-XX:+PrintGCDetails

Scott

On 2013-04-16, at 8:57 AM, "Dr Heinz M. Kabutz" <heinz at javaspecialists.eu> wrote:

> Good day my fellow Mac OS X users!
> 
> Yesterday, whilst teaching my Concurrency Specialist Course, I wanted to
> demonstrate to my class how slow it was starting threads and how much
> better it is to use a FixedThreadPool.  The question that I wanted to
> answer was: How many microseconds does it take on average to start a
> simple thread and what is the maximum time it could take?
> 
> We all know that it can take in the milliseconds range to do the following:
> 
> Thread t = new Thread(); // even without it actually doing anything
> t.start();
> 
> This is one of the reasons why the fixed thread pool only starts the
> threads as we submit jobs to it, since the up-front cost might not be
> worth the wait.
> 
> But how long do you think the *maximum* was that I had to wait for
> t.start() to return?  100ms?  200ms?
> 
> Actually, the longest I had to wait turned out to be about 250 seconds.
> Yes.  That is *seconds*, not *milliseconds*.  Just to start a single thread.
> 
> This is most certainly a bug in the OpenJDK on Mac OS X.  We did not see
> this behaviour on Linux nor on Windows 7.
> 
> The bug started in OpenJDK 1.7.0_06.  Prior to that it hardly ever took
> longer than 30ms to start a single thread.
> 
> java version "1.7.0_05"
> heinz$ java ThreadLeakMac2
> time = 1, threads = 4
> time = 2, threads = 346
> time = 4, threads = 7378
> time = 7, threads = 9614
> time = 12, threads = 10027
> time = 14, threads = 10063
> time = 17, threads = 26965
> time = 38, threads = 27013
> time = 39, threads = 452053
> 
> java version "1.7.0_06"
> heinz$ java ThreadLeakMac2
> time = 1, threads = 6
> time = 2, threads = 256
> time = 6, threads = 373
> *snip*
> time = 111, threads = 42592
> time = 200, threads = 49419
> time = 333, threads = 58976
> *snip*
> time = 3245, threads = 202336
> time = 3706, threads = 203702
> *snip*
> time = 5835, threads = 267872
> time = 6455, threads = 269238
> time = 9170, threads = 270603
> 
> In my code, I make sure that the thread has stopped before creating the
> next one by calling join().
> 
> public class ThreadLeakMac2 {
>   public static void main(String[] args) throws InterruptedException {
>       long threads = 0;
>       long max = 0;
>       while(true) {
>           long time = System.currentTimeMillis();
>           Thread thread = new Thread();
>           thread.start(); // should finish almost immediately
>           time = System.currentTimeMillis() - time;
>           thread.join(); // short delay, hopefully
>           threads++;
>           if (time > max) {
>               max = time;
>               System.out.println("time = " + time +
>                                  ", threads = " + threads);
>           }
>       }
>   }
> }
> 
> This would be another nice test case for Alexey's concurrency stress
> test harness.
> 
> (I also posted this to the concurrency-interest list.)
> 
> Regards
> 
> Heinz
> -- 
> Dr Heinz M. Kabutz (PhD CompSci)
> Author of "The Java(tm) Specialists' Newsletter"
> Sun Java Champion
> IEEE Certified Software Development Professional
> http://www.javaspecialists.eu
> Tel: +30 69 75 595 262
> Skype: kabutz
> 
>