About Me

My photo
Author of Groovy modules: GBench, GProf, Co-author of a Java book パーフェクトJava, Game Developer at GREE

Friday, April 26, 2013

GProf Goodness: Profile a fork/join program written in GPars

I just started to write Goodness series for GPerfUtils (GBench and GProf) like the great Groovy Goodness series by Hubert Klein. And this is the first post of GProf Goodness.

First of all, I should explain about GProf. GProf is the profiling module for Groovy. The purpose of the module is agile profiling. It means that you can profile Groovy program whenever and wherever you want. You don't have to go through lengthy tiresome procedure.

OK, let's back to the topic. GProf supports multi-threaded programs. The following example is to profile a fork/join example of GPars from the GPars user guide.

// prof.groovy
@Grab('org.gperfutils:gprof:0.2.0')

import static groovyx.gpars.GParsPool.runForkJoin
import static groovyx.gpars.GParsPool.withPool

profile {
  withPool(2) { pool ->
      println """Number of files: ${
          runForkJoin(new File("./src")) {file ->
              long count = 0
              file.eachFile {
                  if (it.isDirectory()) {
                      forkOffChild(it)       //fork a child task
                  } else {
                      count++
                  }
              }
              return count + (childrenResults.sum(0))
              //use results of children tasks to calculate and store own result
          }
      }"""
  }
}.prettyPrint()
The results will be like this:
Number of files: 2145
%      calls  total ms  ms/call  min ms  max ms  method                   class
29.47      1    342.87   342.87  342.87  342.87  runForkJoin              groovyx.gpars.forkjoin.ForkJoinUtils
14.87   2403    173.04     0.07    0.05    4.09  doCall                   prof$_run_closure1_closure2_closure3_closure4
 9.41   2403    109.51     0.05    0.03    4.06  isDirectory              java.io.File
 9.16    259    106.61     0.41    0.11    9.08  eachFile                 java.io.File
 8.83    259    102.72     0.40    0.10   21.59  doCall                   prof$_run_closure1_closure2_closure3
 4.80   2145     55.81     0.03    0.02    2.80  next                     java.lang.Long
 3.61      1     42.00    42.00   42.00   42.00  use                      groovyx.gpars.GParsPool
 2.90      1     33.73    33.73   33.73   33.73  call                     prof$_run_closure1_closure2
 2.53      1     29.39    29.39   29.39   29.39  withExistingPool         groovyx.gpars.GParsPool
 2.46    258     28.68     0.11    0.04   14.86  forkOffChild             prof$_run_closure1_closure2_closure3
 1.92      1     22.34    22.34   22.34   22.34  createPool               groovyx.gpars.GParsPool
 1.56      2     18.12     9.06    4.99   13.13  withPool                 groovyx.gpars.GParsPool
 1.43    258     16.66     0.06    0.04    4.32  forkOffChild             prof$_run_closure1_closure2_closure3_closure4
 1.40    409     16.24     0.04    0.02    0.93  plus                     java.lang.Long
 1.28    258     14.89     0.06    0.04    0.84  forkOffChild             groovyx.gpars.forkjoin.FJWorker
 0.94      1     10.93    10.93   10.93   10.93  println                  prof$_run_closure1_closure2
 0.80    108      9.27     0.09    0.04    0.71  sum                      java.util.Arrays$ArrayList
 0.75      1      8.67     8.67    8.67    8.67  runForkJoin              groovyx.gpars.GParsPool
 0.64    151      7.48     0.05    0.02    1.86  sum                      java.util.Collections$EmptyList
 0.36      1      4.18     4.18    4.18    4.18  asType                   groovyx.gpars.GParsPool$_createDefaultUncaughtExceptionHandler_closure4
 0.25    108      2.85     0.03    0.02    0.05  plus                     java.lang.Integer
 0.20      1      2.28     2.28    2.28    2.28  getAt                    [Ljava.lang.String;
 0.10      1      1.13     1.13    1.13    1.13  ctor                     jsr166y.ForkJoinPool
 0.06      2      0.68     0.34    0.03    0.66  size                     [Ljava.lang.Object;
 0.05      1      0.61     0.61    0.61    0.61  isCase                   groovy.lang.IntRange
 0.05      1      0.61     0.61    0.61    0.61  minus                    java.lang.Integer
 0.05      1      0.61     0.61    0.61    0.61  retrieveCurrentPool      groovyx.gpars.GParsPool
 0.04      1      0.44     0.44    0.44    0.44  toInteger                java.lang.String
 0.03      1      0.32     0.32    0.32    0.32  retrieveDefaultPoolSize  groovyx.gpars.util.PoolUtils
 0.02      2      0.21     0.10    0.07    0.14  doCall                   groovyx.gpars.GParsPool$_withExistingPool_closure1
 0.01      1      0.11     0.11    0.11    0.11  leftShift                groovyx.gpars.ThreadLocalPools
 0.01      1      0.11     0.11    0.11    0.11  shutdown                 jsr166y.ForkJoinPool
 0.01      1      0.09     0.09    0.09    0.09  awaitTermination         jsr166y.ForkJoinPool
 0.01      2      0.09     0.04    0.04    0.05  getAt                    [Ljava.lang.Object;
 0.01      1      0.07     0.07    0.07    0.07  ctor                     groovyx.gpars.ThreadLocalPools
 0.01      1      0.07     0.07    0.07    0.07  pop                      groovyx.gpars.ThreadLocalPools
 0.00      1      0.05     0.05    0.05    0.05  ctor                     java.io.File
 0.00      1      0.04     0.04    0.04    0.04  asType                   prof$_run_closure1_closure2_closure3

Also, you can choose threads that you are interested in by includeThreads and excludesThreads options. The following change is to profile only worker threads which GPars gives a name starting with "ForkJoinPool". The options allow "*" and "?" wildcards. You don't have to specify the names of all the threads.

// profile {
profile(includeThreads: [ "ForkJoinPool*" ]) {
    ...
}.prettyPrint()
The results will be changed like this:
Number of files: 2145
%      calls  total ms  ms/call  min ms  max ms  method        class
27.42   2403    268.07     0.11    0.07    4.12  doCall        prof$_run_closure1_closure2_closure3_closure4
21.63   2403    211.49     0.09    0.04   52.46  isDirectory   java.io.File
14.20   2145    138.80     0.06    0.03   51.11  next          java.lang.Long
13.61    259    133.05     0.51    0.12   13.41  eachFile      java.io.File
 9.40    259     91.94     0.35    0.14   12.16  doCall        prof$_run_closure1_closure2_closure3
 3.54    258     34.61     0.13    0.05   15.03  forkOffChild  prof$_run_closure1_closure2_closure3
 2.58    409     25.22     0.06    0.03    4.28  plus          java.lang.Long
 1.98    258     19.39     0.08    0.05    1.20  forkOffChild  groovyx.gpars.forkjoin.FJWorker
 1.95    258     19.06     0.07    0.05    0.52  forkOffChild  prof$_run_closure1_closure2_closure3_closure4
 1.66    108     16.18     0.15    0.06    3.94  sum           java.util.Arrays$ArrayList
 1.15    108     11.20     0.10    0.03    6.34  plus          java.lang.Integer
 0.90    151      8.81     0.06    0.03    1.97  sum           java.util.Collections$EmptyList

Please send me pull requests at the Github page or any issues, requests to the Issue page to improve GProf.

13 comments:

  1. This is definitely one of the best articles I have read in this website! Thanks Mate.
    java training in Chennai

    ReplyDelete
  2. The information you have posted here is really useful and interesting too & here, I had a chance to gather some useful tactics in programming, thanks for sharing and I have an expectation about your future blogs keep your updates please.JAVA Training in Chennai

    ReplyDelete
  3. Thanks for sharing this valuable information to our vision. You have posted a trust worthy blog keep sharing.
    Regards,
    PHP Training in Chennai

    ReplyDelete
  4. This technical post helps me to improve my skills set, thanks for this wonder article I expect your upcoming blog, so keep sharing.
    Regards,

    ccna course in Chennai|ccna training in Chennai

    ReplyDelete
  5. Woah this blog is wonderful i like studying your posts. Keep up the great work! You understand, lots of persons are hunting around for this info, you could help them greatly.
    python training Course in chennai
    python training in Bangalore
    Python training institute in bangalore

    ReplyDelete
  6. Outstanding blog post, I have marked your site so ideally I’ll see much more on this subject in the foreseeable future.
    python training Course in chennai
    python training in Bangalore
    Python training institute in bangalore

    ReplyDelete
  7. Inspiring writings and I greatly admired what you have to say , I hope you continue to provide new ideas for us all and greetings success always for you..Keep update more information.

    rpa training in chennai
    rpa training in bangalore
    rpa course in bangalore
    best rpa training in bangalore
    rpa online training

    ReplyDelete
  8. Inspiring writings and I greatly admired what you have to say , I hope you continue to provide new ideas for us all and greetings success always for you..Keep update more information.

    rpa training in chennai
    rpa training in bangalore
    rpa course in bangalore
    best rpa training in bangalore
    rpa online training

    ReplyDelete
  9. I found your blog while searching for the updates, I am happy to be here. Very useful content and also easily understandable providing.. Believe me I did wrote an post about tutorials for beginners with reference of your blog. 
    excel advanced excel training in bangalore
    Devops Training in Chennai

    ReplyDelete
  10. This blog is the general information for the feature. You got a good work for these blog.We have a developing our creative content of this mind.Thank you for this blog. This for very interesting and useful.
    Data Science Course in Indira nagar
    Data Science Course in btm layout
    Python course in Kalyan nagar
    Data Science course in Indira nagar
    Data Science Course in Marathahalli
    Data Science Course in BTM Layout

    ReplyDelete