Issue #19 new

better debug logging ?

jvanasco
created an issue

this is really about dogpile/core/dogpile.py , but i figured i'd ask here for the context...

my dev logs look like this:

2013-02-01 13:29:35,728 DEBUG [dogpile.core.dogpile][Dummy-2] NeedRegenerationException
2013-02-01 13:29:35,728 DEBUG [dogpile.core.dogpile][Dummy-2] no value, waiting for create lock
2013-02-01 13:29:35,728 DEBUG [dogpile.core.dogpile][Dummy-2] value creation lock <dogpile.cache.util.KeyReentrantMutex object at 0x3897fb0> acquired
2013-02-01 13:29:35,728 DEBUG [dogpile.core.dogpile][Dummy-2] Calling creation function

that's great... but it's not helpful.

could the debug calls be extended to include :

  • the name of the key ( region would be great too, but i don't think that's as easy )
  • the name of the creation function

Comments (5)

  1. Mike Bayer repo owner

    OK well that logging is all within .core, and i have it there mostly to debug the core itself as far as concurrency and all that and its really kind of left over from Beaker. If we want more app level stuff going on maybe having the logging over in dogpile.cache would be better. Otherwise there could be some kind of cooperation between cache/core as far as logging, cache passing in additional contextual information to dogpile.core.Lock.

    The logging at this point isn't too critical for my uses so i can go with whatever, if you want to play with pullreqs.

  2. jvanasco reporter

    since you're open to it, i'll give it a stab this weekend.

    i've been going crazy trying to track down what/where some caching is happening on a certain app.

  3. jvanasco reporter

    i've got some lightweight logging on core right now - where i've just added self.mutex.key to a bunch of messages. that's helped quite a bit.

    i'm not going to send any pullreqs until i get the debugging right to figure out my personal problem.

    i have some code to optimize sql loading when priming my cache. i check the cache for matching objects (by id), failures are grouped and then fetched in a single SQL query. with an empty cache on the main page, this turns 200+ sql statements into 20. the speed savings are phenomenal. in (seemingly) random situations, the cache doesn't prime and 200+ individual 'get by id' SQL queries are executed after the primed 'get by ids' are . I haven't figured out how to replicate this yet, so I'm trying to log everything and figure out how/where something is happening.

  4. Log in to comment