EventTimer and pcp counters

[Paul Smith]

I'm missing a link here somewhere drastic in EventTimer, because when I instrument ElasticSearch with Parfait, I now get lovely logs like this:

[2010-12-24 15:14:37,688][INFO ][ParfaitService ] Top index:bulk index:bulk Elapsed time: own 1855608000 ns, total 1855609000 ns Total CPU: own 1210772000 ns, total 1210784000 ns User CPU: own 1151209000 ns, total 1151211000 ns System CPU: own 59567000 ns, total 59571000 ns Blocked count: own 2, total 2 Blocked time: own 0 ms, total 0 ms Wait count: own 0, total 0 Wait time: own 0 ms, total 0 ms
[2010-12-24 15:14:37,951][INFO ][ParfaitService ] Top index:flush:Index Shard [aconex][2] index:flush:Index Shard [aconex][2] Elapsed time: own 1061428000 ns, total 1061429000 ns Total CPU: own 245678000 ns, total 245687000 ns User CPU: own 228897000 ns, total 228898000 ns System CPU: own 16788000 ns, total 16791000 ns Blocked count: own 0, total 0 Blocked time: own 0 ms, total 0 ms Wait count: own 1, total 1 Wait time: own 0 ms, total 0 ms
[2010-12-24 15:14:37,994][INFO ][ParfaitService ] Top index:flush:Index Shard [aconex][1] index:flush:Index Shard [aconex][1] Elapsed time: own 468780000 ns, total 468781000 ns Total CPU: own 248926000 ns, total 248939000 ns User CPU: own 232962000 ns, total 232964000 ns System CPU: own 15975000 ns, total 15978000 ns Blocked count: own 0, total 0 Blocked time: own 0 ms, total 0 ms Wait count: own 1, total 1 Wait time: own 0 ms, total 0 ms
[2010-12-24 15:14:44,853][INFO ][ParfaitService ] Top index:bulk index:bulk Elapsed time: own 2027463000 ns, total 2027464000 ns Total CPU: own 1087334000 ns, total 1087345000 ns User CPU: own 1037017000 ns, total 1037019000 ns System CPU: own 50310000 ns, total 50314000 ns Blocked count: own 2, total 2 Blocked time: own 0 ms, total 0 ms Wait count: own 0, total 0 Wait time: own 0 ms, total 0 ms
[2010-12-24 15:14:45,234][INFO ][ParfaitService ] Top index:flush:Index Shard [aconex][0] index:flush:Index Shard [aconex][0] Elapsed time: own 466337000 ns, total 466338000 ns Total CPU: own 258027000 ns, total 258038000 ns User CPU: own 241435000 ns, total 241436000 ns System CPU: own 16601000 ns, total 16606000 ns Blocked count: own 0, total 0 Blocked time: own 0 ms, total 0 ms Wait count: own 1, total 1 Wait time: own 0 ms, total 0 ms
[2010-12-24 15:14:45,271][INFO ][ParfaitService ] Top index:bulk index:bulk Elapsed time: own 2151986000 ns, total 2151987000 ns Total CPU: own 1293439000 ns, total 1293450000 ns User CPU: own 1234381000 ns, total 1234383000 ns System CPU: own 59059000 ns, total 59063000 ns Blocked count: own 2, total 2 Blocked time: own 0 ms, total 0 ms Wait count: own 0, total 0 Wait time: own 0 ms, total 0 ms
[2010-12-24 15:14:45,335][INFO ][ParfaitService ] Top index:bulk index:bulk Elapsed time: own 2102809000 ns, total 2102810000 ns Total CPU: own 1311606000 ns, total 1311619000 ns User CPU: own 1253227000 ns, total 1253229000 ns System CPU: own 58388000 ns, total 58392000 ns Blocked count: own 2, total 2 Blocked time: own 0 ms, total 0 ms Wait count: own 0, total 0 Wait time: own 0 ms, total 0 ms

that's awesome.

I was surprised to NOT find any PCP counters though, and I'm winding my way through trying to work out where they've gone.. ? shouldn't MonitoredCounters get created for these ? what am I missing.. ?

Paul

[Paul Cowan]

Sorry for late reply, holidays and then Zurich... :)

I was surprised to NOT find any PCP counters though, and I'm winding my way through trying to work out where they've gone.. ?  shouldn't MonitoredCounters get created for these ?  what am I missing.. ?

Assuming you haven't worked this out yet, I think the thing you're missing is the need for something to call EventTimer.registerTimeable()? This is what creates the PCP counter set (and also injects the EventTimer back into the Timeable)

In the case of Aconex, this is done by SpringEventTimerInjector, which finds all the Spring beans which should be monitored, and then calls registerTimeable() using the Spring bean name as the name to use for metric creation, etc.

Yes, this is crap. Why do we do this? Because we need to know, in advance, the names of all the Timeable things so that we can create the metrics, because we need all the metrics in advance to be able to freeze the MonitoringView..... 

... except now we don't! HUZZAH!

So for now, registerTimeable() is your friend. Ongoing, however, I'd much rather completely remove registerTimeable(), you should just be able to start timing and get all your new metrics automatically. Then the Timeables could use constructor-injection of their EventTimer instead of having a callback method. Except, wait... after that you probably don't need the Timeable interface at all! Extra win!

Hope that makes sense, let me know if that's not the problem.

Cow

[Paul Smith]

I like the Huzzah, specially coming all the way from Zurich.  Hope you're not caught in a blizzard or something.

I think I'll first go back and try that registerTimeable, then start looking to rid ourselves of that timeable thing I think in a different release.  I'll create an issue for that.