Chapel: Feature request : timing annotations

[npadmana]

As a Chapel programmer, I'd like a lightweight way to time parts of my code. Currently, I end up wrapping code with timer.start(), timer.stop() lines and then need to handle printing these results out. I end up finding this a little verbose, and would like a somewhat lighter weight version.

As a concept, I might imagine an annotation of the form @timer(<name>) for any statement which would time every statement, and with an appropriate runtime flag would print timing results at the end of the program execution.

[bradcray]

@chapel-lang/perf-team: At some meeting long ago, I was talking about wanting some sort of more structured way to do scoped things like timings, comm diagnostics, chplvis tracing, etc. and someone (maybe @benharsh?) threw out a Python(?) concept that they thought would be helpful with such patterns. Can anyone remind me what it was?

[ronawho]

Python with clauses / context-managers. e.g.:

with Timer("func1") as t:
    func1()

with Timer("func2") as t:
    func2()

But that does require code indention changes, and I think the decorator would be clean like:

@Timer("func1")
func1()

@Timer("func2")
func2()

[e-kayrakli]

Decorators (as they are in python) can't be used in random code sections, AFAIK. Context manager has the advantage of marking arbitrary parts for timing.

[npadmana]

I'll note that I had imagined code of the form

@Timer(<name>) <block-statement>

so one could write

@Timer("func1") func1();
@Timer("forall-1") forall ijk in Dom {}
@Timer("block-1") {} // This would of course change indentations

Also, while a scoping construct would clean things up, what I'm imagining here is that the compiler handles the printing of the timing results etc. A more complete strawperson would be

@Timer("cof") coforall loc on Locales do on loc {
   writeln("Hello world!");
   @Timer("forall-1") forall ijk in Dom { <do incredibly complicated calculation> };
}

Running this as

$ ./test --print-timings
<elided code output>
=================
Chapel Timing Report 
(all times are in seconds)
=================
cof : locale 0 : 700.000
forall-1 : locale 0 : 100.000
forall-1 : locale 1 : 150.012

[mppf]

Python with clauses / context-managers. e.g.:

Note that issue #12306 has some specific discussion of why such a feature could help with critical sections and aggregation.

[ben-albrecht]

Currently, I end up wrapping code with timer.start(), timer.stop() lines and then need to handle printing these results out. I end up finding this a little verbose, and would like a somewhat lighter weight version.

Until something like context managers are available in Chapel (which I support), I think a library (standard or mason package) using a start/stop interface could still alleviate some of the verbosity in collecting timings in user codes.

The library could improve managing multiple timers or measured sections, use a common interface for timers, comm diagnostics (bulk communication), and visual debug (fine grain communication / tasking), and print all of the measurement information in a single function call.

[npadmana]

@ben-albrecht -- were you thinking of something along the lines of (using my dummy code above)

use NiceProfilingTools;

startTiming("cof");
coforall loc on Locales do on loc {
   writeln("Hello world!");
   startTiming("forall-1");
   forall ijk in Dom { <do incredibly complicated calculation> };
   stopTiming("forall-1");
}
stopTiming("cof");

// End of program
printTimingReport(); // in fact, the module could print this if a flag were set on de-initialization.

then yes, that would be quite nice, and I agree that a library version would be simpler than a language change. I'm guessing you can wrap the timer creation into a hashmap and have 1 of these per locale, so maybe this isn't too hard....

[ben-albrecht]

Exactly what I had in mind. I have implemented a similar pattern in past projects, but never got around to publishing it as a mason package.

[e-kayrakli]

Until something like context managers are available in Chapel (which I support), I think a library (standard or mason package) using a start/stop interface could still alleviate some of the verbosity in collecting timings in user codes.

Would it be too much if we do the start/stop logic in init/deinit of some magic wrapper in that module so that you wouldn't have to actually stop?

A snippet based on @npadmana's code above could be like:

use NiceProfilingTools;

{ time("off");
coforall loc on Locales do on loc {
   writeln("Hello world!");
   startTiming("forall-1");
   forall ijk in Dom { <do incredibly complicated calculation> };
   stopTiming("forall-1");
}
}

// NiceProfilingTools' deinit prints all the stuff

I don't know what I think about this. It is just something that I think we can make work, and less verbose. Is it easier to use? I am not sure.

[npadmana]

@ronawho suggested I post the following that I just wrote setting up to profile a piece of code as a motivating example of why this would be nice to have... :-)

      // Initialize timers
      var fullT, R2T, zFwdT, xFwdT, XZT, zRevT, xRevT, R1T : Timer;
      var planT, yFwdT, yCopyT, yCopy2T, yRevT, barrierT : Timer;
      yFwdT.clear();
      yCopyT.clear();
      fullT.clear();
      R2T.clear();
      zFwdT.clear();
      xFwdT.clear();
      XZT.clear();
      zRevT.clear();
      xRevT.clear();
      planT.clear();
      yCopy2T.clear(); yRevT.clear(); barrierT.clear();

[npadmana]

Exactly what I had in mind. I have implemented a similar pattern in past projects, but never got around to publishing it as a mason package.

@ben-albrecht -- would love to see this.

@e-kayrakli -- if I understand your suggestion, it removes the need for an initial start/stop, but all nested calls would still need to be start/stop-ed.

Another design note -- we should have the option of making the timing statements into no-ops, if the user wanted to remove the timing overheads....

[e-kayrakli]

@e-kayrakli -- if I understand your suggestion, it removes the need for an initial start/stop, but all nested calls would still need to be start/stop-ed.

Sorry I missed the one inside the coforall, they'd look the same:

{ time("off");
coforall loc on Locales do on loc {
   writeln("Hello world!");
   { time("forall-1");
   forall ijk in Dom { <do incredibly complicated calculation> };
   }
}
}

(And I wouldn't indent it this way in actual code :) )

[ben-albrecht]

would love to see this.

@npadmana - it's pretty simple, I put it in a mason package (chose a generic name for now) with an example: https://github.com/ben-albrecht/Measurements

[cassella]

I think for the record-deinit() version, you'd need to capture the record (returned from time()) in a variable,

{ var stealthytimer = time("off");
coforall loc on Locales do on loc {
   writeln("Hello world!");
   { var stealthytimer2 = time("forall-1");
   forall ijk in Dom { <do incredibly complicated calculation> };
   }
}
}

The scope/deinit()-based approach has the advantage that it will automatically work with that coforall loop, or even in a local coforall, cobegin, or begin construct, without the implementation having to reason about the locale or task.

The explicit start()/stop() has the advantage of supporting cases where the region to be timed can't be coerced into a block statement. contrived example:

for i in 1..100 {
  if startingCondition(A[i])
     startTiming("inner portion");
   if endingCondition(A[i]);
     stopTiming("inner portion");
}

The module could provide both kinds.

It would be pretty easy to make either form a no-op conditionally on a param.

[npadmana]

If one needed to capture the return value of time into a named variable, it's a little less compelling visually to me. Maybe something like var _ = time('off"). But again, that's a change to the language.

I like the idea of having both an explicit start-stop version, and a version that automatically stops (which is close to the decorator version). But I'd be pretty happy with just explicit starts and stops, if that's easy (which it looks like, given @ben-albrecht's prototype).