Adding a timer in commons

[Davide Giannella <gi...@gmail.com>]

Hello team,

in the warm laziness of a summer Saturday I was thinking about a way for
having in oak a timing facility for logging/benchmarking "critical" part
of the code. Something that we could put the logging to DEBUG and we
start see the information.

I started writing this quick sample

https://gist.github.com/davidegiannella/107f1f6bd16058020b64

any feedback? By using slf4j we would be enable to replace the
System.out with a LOG.debug and most of the magic would be done.

Don't know what the actual overhead for the class creation would be but
I like the layout within the code.

Any feedbacks?

Cheers
Davide

Re: Adding a timer in commons

[Davide Giannella <da...@apache.org>]

On 04/08/2014 11:37, Michael Dürig wrote:
>> If you're fine with the amended version which already include Closeable
>> and custom logger I can file an issue ticket, and push it to trunk. We
>> can work any refactoring/improving from there on.
>
> Sure, let's go ahead!
https://issues.apache.org/jira/browse/OAK-2013

D.

Re: Adding a timer in commons

[Michael Dürig <md...@apache.org>]

On 4.8.14 11:26 , Davide Giannella wrote:
> On 04/08/2014 10:55, Michael Dürig wrote:
>> ...
>> Agreed, I think this is the better approach.
>> ...
>> Sure. This was just an idea. We can as well leave it out and add it
>> once we think such a thing is needed.
>>> Anyhow here is the amended version
>>>
>>> http://goo.gl/xUcPdY
>
> If you're fine with the amended version which already include Closeable
> and custom logger I can file an issue ticket, and push it to trunk. We
> can work any refactoring/improving from there on.

Sure, let's go ahead!

Michael

>
> A nice improvements would be to have it as OSGi service registered to
> the whiteboard for providing different implementations of the same.
>
> D.
>
>

Re: Adding a timer in commons

[Davide Giannella <da...@apache.org>]

On 04/08/2014 10:55, Michael Dürig wrote:
> ...
> Agreed, I think this is the better approach.
> ...
> Sure. This was just an idea. We can as well leave it out and add it
> once we think such a thing is needed.
>> Anyhow here is the amended version
>>
>> http://goo.gl/xUcPdY

If you're fine with the amended version which already include Closeable
and custom logger I can file an issue ticket, and push it to trunk. We
can work any refactoring/improving from there on.

A nice improvements would be to have it as OSGi service registered to
the whiteboard for providing different implementations of the same.

D.

Re: Adding a timer in commons

[Michael Dürig <md...@apache.org>]

On 4.8.14 10:47 , Davide Giannella wrote:
> On 04/08/2014 09:35, Michael Dürig wrote:
>> One thing that concerns me is the static reference to the executor
>> service. It might keep the JVM from terminating properly as it is
>> never shut down. A better approach might be to create it on the fly in
>> the start method and shut it down in the stop method. If this is too
>> much overhead we should make it an instance field and have the class
>> implement Closeable.
> I see what you mean and it was my concern as well. Anyhow I decided to
> go this way and see if anyone would have my same concern.
>
> I'm more for the class instance and the Closable interface as if you
> rely on stop() some clients might not use it (you could use only
> split()) and therefore I would implement closable anyhow.

Agreed, I think this is the better approach.

>
>> As a further improvement it might be helpful if clients could inject
>> the logger instance instead of always using the StopwatchLogger one.
> The idea was to have a single appender where you says: enable all the
> timing and then filter (grep) the log for your own cases. But adding a
> constructor with an instance variable for logging should be trivial.

Sure. This was just an idea. We can as well leave it out and add it once 
we think such a thing is needed.

Michael

>
> Anyhow here is the amended version
>
> http://goo.gl/xUcPdY
>
> D.
>
>

Re: Adding a timer in commons

[Davide Giannella <da...@apache.org>]

On 04/08/2014 09:35, Michael Dürig wrote:
> One thing that concerns me is the static reference to the executor
> service. It might keep the JVM from terminating properly as it is
> never shut down. A better approach might be to create it on the fly in
> the start method and shut it down in the stop method. If this is too
> much overhead we should make it an instance field and have the class
> implement Closeable.
I see what you mean and it was my concern as well. Anyhow I decided to
go this way and see if anyone would have my same concern.

I'm more for the class instance and the Closable interface as if you
rely on stop() some clients might not use it (you could use only
split()) and therefore I would implement closable anyhow.

> As a further improvement it might be helpful if clients could inject
> the logger instance instead of always using the StopwatchLogger one.
The idea was to have a single appender where you says: enable all the
timing and then filter (grep) the log for your own cases. But adding a
constructor with an instance variable for logging should be trivial.

Anyhow here is the amended version

http://goo.gl/xUcPdY

D.

Re: Adding a timer in commons

[Michael Dürig <md...@apache.org>]

On 2.8.14 11:27 , Davide Giannella wrote:
> StopwatchLogger sl = new StopwatchLogger(FooBar.class);
> // ...
>
> public void foo() {
>    sl.start();
>    // perform all sort of things
>    sl.split("performed some operations");
>    // perform other things
>    sl.stop("operation completed");
> }
>
> then by setting in logs the debug for o.a.j.oak.stats.StopwatchLogger
> should do the trick to have some "gross" numbers around performances.
>
> If ok, I'll create an issue an commit to trunk.
>
> thoguhts?

One thing that concerns me is the static reference to the executor 
service. It might keep the JVM from terminating properly as it is never 
shut down. A better approach might be to create it on the fly in the 
start method and shut it down in the stop method. If this is too much 
overhead we should make it an instance field and have the class 
implement Closeable.

As a further improvement it might be helpful if clients could inject the 
logger instance instead of always using the StopwatchLogger one.

Michael

Re: Adding a timer in commons

[Davide Giannella <da...@apache.org>]

On 02/08/2014 14:40, Chetan Mehrotra wrote:
> Hi Davide,
>
> Recently Ian pointed to Metrics [1] project which is related to such
> timing measurements. It might be helpful to use this (via a wrapper)
> to measure timings in critical areas in Oak. So have a look at that
> also
>
> Chetan Mehrotra
> [1] http://metrics.codahale.com/
>
Should have a look at it. Never used. For now I'd rather stay on JR
Clock and then in case move to a library. The idea was to provide
"gross" numbers in a fast way. That's why of the FAST clock in the
implementation. It's not meant to be a replacement of a profiling :)

Open to improve the implementation if it will end-up by being really
used and relied on.

D.

Re: Adding a timer in commons

[Chetan Mehrotra <ch...@gmail.com>]

Hi Davide,

Recently Ian pointed to Metrics [1] project which is related to such
timing measurements. It might be helpful to use this (via a wrapper)
to measure timings in critical areas in Oak. So have a look at that
also

Chetan Mehrotra
[1] http://metrics.codahale.com/


On Sat, Aug 2, 2014 at 2:57 PM, Davide Giannella <da...@apache.org> wrote:
> On 23/06/2014 14:26, Davide Giannella wrote:
>> On 23/06/2014 13:57, Michael Dürig wrote:
>>> +1 in general. However,
>>>
>>> - although it results in nice code on the client side, I'm a bit
>>> reluctant about putting all the code into the instance initialiser.
>> it was my concern as well. But don't see that much of a difference from
>> something
>>
>> timer = new Timer("foobar");
>> timer.start();
>> // blabla
>> timer.trackTime();
>>
>>> - how about reusing org.apache.jackrabbit.oak.stats.Clock instead of
>>> using Guava's Stopwatch? If necessary we could still implement Clock
>>> based on Stopwatch.
>> Didn't know about it. Will have a look and amend accordingly.
>>
>>> - Timer might not be the best name for the class. Should probably
>>> better be something with "Log" in its name
>> It was an example. It could be LogTimer if you prefer or whatever. Don't
>> mind the name and I'm very bad at it :)
> Had time on train to work a bit on it.
>
> here's a the final class
>
> http://goo.gl/xUcPdY
>
> The idea behind it is to have something for tracking time like
>
> // ...
> StopwatchLogger sl = new StopwatchLogger(FooBar.class);
> // ...
>
> public void foo() {
>   sl.start();
>   // perform all sort of things
>   sl.split("performed some operations");
>   // perform other things
>   sl.stop("operation completed");
> }
>
> then by setting in logs the debug for o.a.j.oak.stats.StopwatchLogger
> should do the trick to have some "gross" numbers around performances.
>
> If ok, I'll create an issue an commit to trunk.
>
> thoguhts?
>
> Cheers
> Davide
>

Re: Adding a timer in commons

[Davide Giannella <da...@apache.org>]

On 23/06/2014 14:26, Davide Giannella wrote:
> On 23/06/2014 13:57, Michael Dürig wrote:
>> +1 in general. However,
>>
>> - although it results in nice code on the client side, I'm a bit
>> reluctant about putting all the code into the instance initialiser.
> it was my concern as well. But don't see that much of a difference from
> something
>
> timer = new Timer("foobar");
> timer.start();
> // blabla
> timer.trackTime();
>
>> - how about reusing org.apache.jackrabbit.oak.stats.Clock instead of
>> using Guava's Stopwatch? If necessary we could still implement Clock
>> based on Stopwatch.
> Didn't know about it. Will have a look and amend accordingly.
>
>> - Timer might not be the best name for the class. Should probably
>> better be something with "Log" in its name
> It was an example. It could be LogTimer if you prefer or whatever. Don't
> mind the name and I'm very bad at it :)
Had time on train to work a bit on it.

here's a the final class

http://goo.gl/xUcPdY

The idea behind it is to have something for tracking time like

// ...
StopwatchLogger sl = new StopwatchLogger(FooBar.class);
// ...

public void foo() {
  sl.start();
  // perform all sort of things
  sl.split("performed some operations");
  // perform other things
  sl.stop("operation completed");
}

then by setting in logs the debug for o.a.j.oak.stats.StopwatchLogger
should do the trick to have some "gross" numbers around performances.

If ok, I'll create an issue an commit to trunk.

thoguhts?

Cheers
Davide

Re: Adding a timer in commons

[Davide Giannella <da...@apache.org>]

On 23/06/2014 13:57, Michael Dürig wrote:
>
> +1 in general. However,
>
> - although it results in nice code on the client side, I'm a bit
> reluctant about putting all the code into the instance initialiser.
it was my concern as well. But don't see that much of a difference from
something

timer = new Timer("foobar");
timer.start();
// blabla
timer.trackTime();

> - how about reusing org.apache.jackrabbit.oak.stats.Clock instead of
> using Guava's Stopwatch? If necessary we could still implement Clock
> based on Stopwatch.
Didn't know about it. Will have a look and amend accordingly.

> - Timer might not be the best name for the class. Should probably
> better be something with "Log" in its name
It was an example. It could be LogTimer if you prefer or whatever. Don't
mind the name and I'm very bad at it :)

Davide

Re: Adding a timer in commons

[Michael Dürig <md...@apache.org>]

+1 in general. However,

- although it results in nice code on the client side, I'm a bit 
reluctant about putting all the code into the instance initialiser.

- how about reusing org.apache.jackrabbit.oak.stats.Clock instead of 
using Guava's Stopwatch? If necessary we could still implement Clock 
based on Stopwatch.

- Timer might not be the best name for the class. Should probably better 
be something with "Log" in its name

Michael

On 21.6.14 6:41 , Davide Giannella wrote:
> Hello team,
>
> in the warm laziness of a summer Saturday I was thinking about a way for
> having in oak a timing facility for logging/benchmarking "critical" part
> of the code. Something that we could put the logging to DEBUG and we
> start see the information.
>
> I started writing this quick sample
>
> https://gist.github.com/davidegiannella/107f1f6bd16058020b64
>
> any feedback? By using slf4j we would be enable to replace the
> System.out with a LOG.debug and most of the magic would be done.
>
> Don't know what the actual overhead for the class creation would be but
> I like the layout within the code.
>
> Any feedbacks?
>
> Cheers
> Davide
>
>