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.

This is the logo for GProf and GBench!!

I just drew the logo for GPerfUtils project that has GProf and GBench. I am not a good artist but I personally like the logo that is based on the Groovy Duke. How about you?

And this is the sketch.

GProf 0.2.0 is out!

Today I released GProf 0.2.0! GProf is a profiling module for Groovy which is developed in GPerfUtils project at http://gperfutils.org. GBench which is a benchmarking module for Groovy is also a subproject of GPerfUtils. The release already has been available on the Maven Central repository and it means that now you can install GProf by the following one line:

@Grab('org.gperfutils:gprof:0.2.0')

The release includes big enhancements and important bug fixes. The changes are as follows (you can read it also at https://raw.github.com/gperfutils/gprof/master/NEWS):

Support multi-threaded applications

Support Grape

Add includeMethods and excludeMethods options that filter by the name of packages,
classes and methods:

    It supports the following wildcards:

        | * | zero or more characters |
        | ? | exactly one character   |

    The following example profile only methods which are of "java.*" or "groovy.*"
    package but are not constructors:

        profile(
            includeMethods: [ "java.*", "groovy.*" ],
            excludeMethods: [ "*.ctor" ]) {
            // code to be profiled
        }

Add includeThreads and excludeThreads options that filter by the name of threads:

    It supports the following wildcards:

        | * | zero or more characters |
        | ? | exactly one character   |

    The following example profile only methods which are called in the "thread-*"
    thread but not in "thread-2" or "thread-3":

        profile(
            includeThreads: [ "thread-*" ],
            excludeThreads: [ "thread-2", "thread-3" ]) {
            // code to be profiled
        }

Bug fixes:

- #3: GProf fails to profile a multi-threaded application
- #4: Contains the time of children if the depth is more than two
- #6: There are classes that are not profiled

Enjoy ;)

GProf was just born!

GProf a.k.a. Groovy gprof was just born Yesterday [https://code.google.com/p/gprof/]. GProf is a profiler for Groovy [http://groovy.codehaus.org/]. It allows you to determine which parts of a program are taking most of the execution time like GNU gprof does for C, C++.

For example, in the following code, GProf shows you that YourApp has two slow operation; one is a task that is short but repeated many times and another is a long task.

class YourApp {
    void start() {
        def foo = new Foo()
        for (int i = 0; i < 100; i++) {
            foo.doShortTask()
        }
        def bar = new Bar()
        bar.doLongTask()
    }
}

class Bar {
    void doLongTask() {
        for (int i = 0; i < 1000000; i++);
    }
}

class Foo {
    void doShortTask() {
        for (int i = 0; i < 10000; i++);
    }
}

profile {  // or new gprof.Profiler().run {
    new YourApp().start()
}.prettyPrint()

/* stdout
%      calls  total ms  ms/call  min ms  max ms  method       class
47.59      1     54.33    54.33   54.33   54.33  doLongTask   Bar
40.05    100     45.72     0.46    0.29    2.09  doShortTask  Foo
11.92      1     13.61    13.61   13.61   13.61  start        YourApp
 0.18      1      0.21     0.21    0.21    0.21  ctor         YourApp
 0.13      1      0.14     0.14    0.14    0.14  ctor         Bar
 0.13      1      0.14     0.14    0.14    0.14  ctor         Foo
*/

Please try GProf and send me your feecback. Enjoy!