What do large times spent in Thread#initialize and Thread#join mean in JRuby profiling?

Question

I'm trying to profile an application using JRuby's built-in profiler.

Most of the time is taken in ClassIsOfInterest.method_that_is_of_interest, which in turn has most of its time taken in Thread#initialize and Thread#join

     total        self    children       calls  method
----------------------------------------------------------------
     31.36        0.02       31.35        4525  Array#each
     31.06        0.00       31.06           2  Test::Unit::RunCount.run_once
     31.06        0.00       31.06           1  Test::Unit::RunCount.run
     31.06        0.00       31.06           1  MiniTest::Unit#run
     31.06        0.00       31.05           1  MiniTest::Unit#_run
     31.01        0.00       31.01        2219  Kernel.send
     31.00        0.00       31.00           1  MiniTest::Unit#run_tests
     31.00        0.00       31.00           1  MiniTest::Unit#_run_anything
     30.99        0.00       30.99           1  Test::Unit::Runner#_run_suites
     30.99        0.00       30.99           5  MiniTest::Unit#_run_suite
     30.99        0.00       30.98       21629  Array#map
     30.98        0.00       30.98           1  Test::Unit::TestCase#run
     30.98        0.00       30.98           1  MiniTest::Unit::TestCase#run
     30.98        0.00       30.98         659  BasicObject#__send__
     30.98        0.00       30.98           1  MyTestClass#my_test_method
     30.80        0.00       30.80          18  Enumerable.each_with_index
     30.77        0.00       30.77          15  MyTestHelper.generate_call_parser_based_on_barcoded_sequence
     30.26        0.00       30.25        4943  Class#new_proxy
     26.13        0.00       26.13          15  MyProductionClass1#my_production_method1

<snip boring methods with zero self time>

     24.27        0.00       24.27          15  ClassIsOfInterest.method_that_is_of_interest
     13.71        0.01       13.71         541  Enumerable.map
     13.48        0.86       12.63          30  Range#each
     12.62        0.22       12.41         450  Thread.new
     12.41       12.41        0.00         450  Thread#initialize
     10.78       10.78        0.00         450  Thread#join
      4.03        0.12        3.91         539  Kernel.require
      3.34        0.00        3.34         248  Kernel.require
      2.49        0.00        2.49          15  MyTestFixture.create_fixture

<snip boring methods with small total times>

Each invocation of ClassIsOfInterest.method_that_is_of_interest is creating 30 threads, which is probably overkill, but I assume it shouldn't degrade performance that much. When I only had three threads created per invocation, I got

 23.16        0.00       23.15          15  ClassIsOfInterest.method_that_is_of_interest
 22.73       22.73        0.00          45  Thread#join
  4.18        0.08        4.10         539  Kernel.require
  3.56        0.00        3.56         248  Kernel.require
  2.78        0.00        2.78          15  MyTestFixture.create_fixture

Do large time values for Thread#initialize (in the first profile) and Thread#join indicate that the code responsible for threading is taking a while, or merely that the code that is executed within the thread is taking a while?

Theo Theo · Accepted Answer · 2013-02-23T20:55:09

The reason you see Thread#join is that your main thread is spending lots of time waiting for the other threads to finish. Most of the time spent in method_that_is_of_interest is spent blocking on Thread#join because it's not doing any other work. I wouldn't worry too much about it -- the profile is just saying that one of your threads is blocking on what other threads are doing. A better performance measurement in this case is the total running time, run the code with different numbers of threads and see where the sweet spot is.

The reason why Thread.new/Thread#initialize shows up is that threads are expensive objects to create. If you're calling this method often and it creates all those threads every time I suggest you look into Java's Executors API. Create a thread pool with Executors once (when your application starts up) and submit all the tasks to the pool instead of creating new threads (you can use ExecutorCompletionService to wait for all tasks to complete, or just call #get on the FutureTask instances you get when you submit your tasks).

What do large times spent in Thread#initialize and Thread#join mean in JRuby profiling?

1 Answers