[concurrency-interest] Fwd: : Re: Latency in starting threads

william.louth at jinspired.com william.louth at jinspired.com
Wed Apr 17 12:22:30 EDT 2013


-----Original Message-----
From: william.louth at jinspired.com [mailto:william.louth at jinspired.com]
Sent: Wednesday, April 17, 2013 11:45 AM
To: concurrency-interest-bounces at cs.oswego.edu
Subject: Re: : Re: [concurrency-interest] Latency in starting threads

I did a quick test using the following changed code to shed a little bit more light on the behavior and there is a pattern in all of this looking at the count increments in the table listed here.

http://www.jinspired.com/wp-content/uploads/2013/04/heinz.thread.start_.metering.jpg

Very strange to see the counts (representing threads created between max increments) cluster around 136x. Notice also the min at each new stage is relatively low so the impact is not in constant at an average level but more so outlier. I could turn on distributions if need be but maybe what I have seen can be first repeated on some other machine using another measurement library.

import com.jinspired.jxinsight.probes.Probes;

import java.text.DecimalFormat;
import java.text.NumberFormat;

public class ThreadTest {
  public static void main(String[] args) throws Throwable {
    long threads = 0;
    long max = 0;

    final NumberFormat fmt = new DecimalFormat("000,000");
    final Probes.Context ctx = Probes.context();
    final Probes.Name mn = Probes.parse("clock.time");

    Probes.Probe p = ctx.create(Probes.name(fmt.format(max)));
    Probes.Reading r = p.reading(mn);

    while(true) {

      p.begin();

      final Thread thread = new Thread();
      thread.start(); // should finish almost immediately
      thread.join();// short delay, hopefully

      p.end();

      threads++;

      long time = r.getDelta() / 1000; // microseconds to milliseconds

      if (time > max) {

        max = time;
        System.out.println("time = " + time + ", threads = " + threads);

        r = (p = ctx.create(Probes.name(fmt.format(max)))).reading(mn);

      }

    }
  }
}

-----Original Message-----
To: 'William Louth'
Subject: Fwd: Re: [concurrency-interest] Latency in starting threads

-------------------------------------------------------------
 Hi David,

 I understand it is valid for t.start() to wait until the new thread has really started. I was just surprised, as I expected it to be basically an asynchronous call that spawns something but does not wait for it to actually start.

 Also, with the join(), I realize that this is at the end of the Java view of the thread. However, I did check that the threads were indeed shutting down by looking at the process in top and also dumping threads.

 Heinz

 David Holmes wrote: Heinz,

It is perfected valid for t.start() to start and context switch to the new thread. That is up to the OS scheduler.

Thread.join only indicates logical termination at the Java level. The native thread will still have to exit at the VM level and OS level, both of which can hit bottlenecks and cause unexpected numbers of threads to still be active. That in turn can impact thread creation - which happens in start().

Cheers,
David
-----Original Message-----
From:concurrency-interest-bounces at cs.oswego.edu [mailto:concurrency-interest-bounces at cs.oswego.edu]On Behalf Of Dr Heinz M. Kabutz
Sent: Wednesday, 17 April 2013 5:31 AM
To: Nathan Reynolds
Cc:concurrency-interest at cs.oswego.edu
Subject: Re: [concurrency-interest] Latency in starting threads


 Right, I would not have sent a notifyAll() if it had just been 250ms for the thread to wake up. However, I was always under the wrong impression that thread.start() would return pretty much immediately. That is the slow part, not the constructor call. Try it out if you find a Mac OS X machine with at least 1.7.0_06 on it.

 And just to eliminate any confusion - I waited for each thread to die before I start the next one. So we never have an excessively large number of threads around at any one time.
RegardsHeinz-- Dr Heinz M. Kabutz (PhD CompSci)Author of "The Java(tm) Specialists' Newsletter"Sun Java ChampionIEEE Certified Software Development Professionalhttp://www.javaspecialists.euTel: +30 69 75 595 262Skype: kabutz 

 Nathan Reynolds wrote: When I started reading your email, I figured you meant the time from calling start() to the time the created thread actually started running. I've seen this take a considerable amount of time on Windows XP (not 250 seconds though) and has to be considered if one is trying to account for latency. I was surprised to find that you meant the time for the constructor and start() call itself.

Nathan Reynolds | Architect | 602.333.9091
OraclePSR Engineering | Server Technology

 On 4/16/2013 5:54 AM, Dr Heinz M. Kabutz wrote:

Good day my fellow concurrency enthusiasts! 

 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 will also post this to the macosx-port-dev list.) 

 Regards 

 Heinz 


------------------------------------------------------------
_______________________________________________Concurrency-interest mailing listConcurrency-interest at cs.oswego.eduhttp://cs.oswego.edu/mailman/listinfo/concurrency-interest









More information about the Concurrency-interest mailing list