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.