781382 - Add timers around memcache and database accesses

Status: VERIFIED FIXED

(Cloud Services Graveyard :: Server: Sync, defect)

Comment 1

[Rob Miller [:rmiller]]

Some thoughts:

- Wrapping the `metlog.decorators.stats.timeit` decorator around any CacheManager method that does memcache access should give us generate a separate timer for each method.

- Timers can be configurable as on or off, so we can turn them off in production to minimize load if desired. Each timed method should be autogenerated a timer name. Metlog config `disabled_timers` setting can contain a list of timer names to ignore.

Comment 2

[Ryan Kelly [:rfkelly]]

Attachment: patch adding timers around memcached and db access

Initial patch, using with-statement timers because we ran into some trouble decorating methods with @timeit.

Each of get, set, delete and incr in memcache is attached to a different timer.  All database queries currently go through a single timer, because the code isn't structured to let us split them out by query name.  I will refactor to allow this in a separate patch.

Comment 3

[Ryan Kelly [:rfkelly]]

Attachment: patch adding timers around memcached and db access

Oops, also need to adjust the test_metlog tests for the new event that is being generated.  Patch updated.

Comment 4

[Rob Miller [:rmiller]]

Comment on attachment 650408 [details] [diff] [review]
patch adding timers around memcached and db access

Review of attachment 650408 [details] [diff] [review]:
-----------------------------------------------------------------

I'm curious why you decided to load the metlog client as a property rather than just storing it as an attribute on the storage objects. Not terribly much difference, except that the property will incur an extra function call every time 'self.logger' is used. Was there a case where storing it as an attribute caused a problem?

Comment 5

[Ryan Kelly [:rfkelly]]

> I'm curious why you decided to load the metlog client as a property rather
> than just storing it as an attribute on the storage objects. Not terribly
> much difference, except that the property will incur an extra function call
> every time 'self.logger' is used. Was there a case where storing it as an
> attribute caused a problem?

Yep.  In some of the test cases, the storage plugin was getting loaded before the metlog plugin, meaning that the metlog client could not just be grabbed and stored during __init__.  I should track down the underlying issue there, but didn't want to delay the patch.

Comment 6

[Ryan Kelly [:rfkelly]]

This was committed in http://hg.mozilla.org/services/server-storage/rev/37fc9f2efebc

Comment 7

[Ryan Kelly [:rfkelly]]

Attachment: attempt to use timeit decorators

With metlog 0.9.5 released, I have attempted to use the @timeit decorator instead of the timer() context manager.  However, I can't get the tests to pass properly due to (AFAICT) some global state in the decorator.

Running all tests at once reports failures from both of the metlog-related tests.  Running just the test_metlog.py tests produces one success and one failure.  And running each test from test_metlog.py in isolation results in success.

At a guess I think it's because the decorator is caching the metlog client object on first use.  Subsequent tests create a new metlog client, but it is not detected by the decorator and hence does not receive the messages.  I haven't looked into it in any detail though.

Rob, what can you suggest?

Comment 8

[Ryan Kelly [:rfkelly]]

Also I realized the @property thing in the new patch wont work, what I want is probably @reify from pyramid

Comment 9

[Rob Miller [:rmiller]]

Comment on attachment 653643 [details] [diff] [review]
attempt to use timeit decorators

Review of attachment 653643 [details] [diff] [review]:
-----------------------------------------------------------------

Yeah, I made a similar attempt (almost exactly the same code) and had the same results as you. It might be due to metlog client caching, or it might be due to the function not being decorated correctly in all cases. (The MetlogDecorator class only actually decorates the function if the predicate returns true, e.g. if the timer is active in the case of `timeit`.) I ran out of time for debugging when I hit this before, but will dig in again ASAP. In the meantime, we should proceed w/ continuing to use the context manager version.

Comment 10

[Ryan Kelly [:rfkelly]]

Assigning to Rob to continue this investigation

Comment 11

[Ryan Kelly [:rfkelly]]

Splitting the convert-to-decorators thing into a separate Bug 787287, so we can close this one out.

Comment 12

[James Bonacci [:jbonacci]]

OK. Marking as Verified.