Shorter stack traces?

Issue #80 new
Maximilian Roos
created an issue

We love dogpile and use it extensively throughout our application (maybe too much...).

One issue we have through using it so much is our stack traces become unmanageable. Because we cache at multiple layers of our calculation, and dogpile adds five levels to the stack at each layer, a stack trace that was 8 levels deep can become 30 levels deep, almost all of which is repetitive dogpile code*.

I'd need to think more about how to go about collapsing the stack; I could imagine trying to come back up the stack within dogpile rather than burrowing deeper could be a solution.

I'd be happy to do a PR if Mike / others think it's a good idea, and can give some direction on how we could go about doing this.

*that's an extreme case, and generally we're not trying to cache at each level - but there are times we're not sure whether a result is a final result or an intermediate result, and for those we'll often cache both

Comments (6)

  1. Michael Bayer repo owner

    "shorter stack traces" can mean two things:

    1. dogpile itself uses fewer function calls to do a thing. Pretty sure that's not what you mean and it should be clear this is not realistic.

    2. when looking at a stack trace in pdb and/or a logfile, the displayed stack would be shorter. But dogpile doesn't have any "stack-trace displaying" functionality within it, that's a product of your logging / debugging tools. Things like filtering stack traces you'll see for example in Mako, because Mako actually has stack-trace-display tools within it as they are definitely needed there. But this is not anything that's in dogpile.

    So I don't really see what this ticket could be asking for in dogpile ?

  2. Maximilian Roos reporter

    I did mean something like (1). This could either happen through fewer function calls, or through returning up the stack more aggressively.

    Here's a low-hanging-fruit example, admittedly from the core package. Where there's currently:

        def __enter__(self):
            return self._enter()
    

    We could have:

        __enter__ = _enter
    

    ...and I think that should save a level on the stack.

    I had a look for log parsing tools but couldn't find anything good. That would be a great solution if available. I'll have another look - I didn't know about the ones in Mako (I haven't used the package).

    This is my stack trace where there's an error in the function. I could believe that changing the code to make this shorter is the tail wagging the dog. But this is quite a behemoth:

    @memory_cache
    def mem_cache_raise(n):
        raise Exception
    
    mem_cache_raise(5)
    
    ---------------------------------------------------------------------------
    Exception                                 Traceback (most recent call last)
    <ipython-input-3-3738f0af8e9d> in <module>()
    ----> 1 mem_cache_raise(5)
    
    /usr/local/lib/python2.7/dist-packages/dogpile/cache/region.pyc in decorate(*arg, **kw)
       1038                     else expiration_time
       1039                 return self.get_or_create(key, creator, timeout,
    -> 1040                                           should_cache_fn)
       1041 
       1042             def invalidate(*arg, **kw):
    
    /usr/local/lib/python2.7/dist-packages/dogpile/cache/region.pyc in get_or_create(self, key, creator, expiration_time, should_cache_fn)
        649                 get_value,
        650                 expiration_time,
    --> 651                 async_creator) as value:
        652             return value
        653 
    
    /usr/local/lib/python2.7/dist-packages/dogpile/core/dogpile.pyc in __enter__(self)
        156 
        157     def __enter__(self):
    --> 158         return self._enter()
        159 
        160     def __exit__(self, type, value, traceback):
    
    /usr/local/lib/python2.7/dist-packages/dogpile/core/dogpile.pyc in _enter(self)
         96             createdtime = -1
         97 
    ---> 98         generated = self._enter_create(createdtime)
         99 
        100         if generated is not NOT_REGENERATED:
    
    /usr/local/lib/python2.7/dist-packages/dogpile/core/dogpile.pyc in _enter_create(self, createdtime)
        147 
        148             log.debug("Calling creation function")
    --> 149             created = self.creator()
        150             return created
        151         finally:
    
    /usr/local/lib/python2.7/dist-packages/dogpile/cache/region.pyc in gen_value()
        617 
        618         def gen_value():
    --> 619             created_value = creator()
        620             value = self._value(created_value)
        621 
    
    /usr/local/lib/python2.7/dist-packages/dogpile/cache/region.pyc in creator()
       1034                 @wraps(fn)
       1035                 def creator():
    -> 1036                     return fn(*arg, **kw)
       1037                 timeout = expiration_time() if expiration_time_is_callable \
       1038                     else expiration_time
    
    <ipython-input-2-3f8c1d3e5ca7> in mem_cache_raise(n)
         18 @memory_cache
         19 def mem_cache_raise(n):
    ---> 20     raise Exception
         21 
         22 
    
  3. Michael Bayer repo owner

    Here's a low-hanging-fruit example, admittedly from the core package.

    No, that wouldn't be very good design. It would blow up inheritability, for one. I would in theory entertain inlining _enter() into __enter__() for performance reasons, though that's not necessary here, but making stack traces shorter for logging is simply not any kind of rationale for the design of a library to be modified (edit: by which I mean, modifying the code itself to have fewer function calls overall, rather than localizing the behavior of the trace object itself).

    I had a look for log parsing tools but couldn't find anything good. That would be a great solution if available.

    it's not even log parsing, it's taking your code at the point that stack traces are emitted, then ensuring that the way they are displayed includes filtering. Armin does a much better job than I do in Jinja, here's the code: https://github.com/mitsuhiko/jinja2/blob/master/jinja2/debug.py

  4. Michael Bayer repo owner

    Here's a simple recipe that locks out the stack trace from inside the call, this can be expanded to show more of a trace within the user-defined function itself:

    from decorator import decorator
    
    
    def shorter_stack_trace(**cache_args):
    
        @region.cache_on_arguments(**cache_args)
        @decorator
        def go(fn, *arg, **kw):
            try:
                return fn(*arg, **kw)
            except Exception as e:
                raise Exception("Function failed: %s" % e)
    
        return go
    
    from dogpile.cache import CacheRegion
    
    region = CacheRegion("memory")
    region.configure("dogpile.cache.memory")
    
    
    @shorter_stack_trace()
    def blow_it_up():
        raise Exception("hi")
    
    
    blow_it_up()
    

    Some helper or flag that's specific to the region decorators would be useful here, lets assume that the issue you have is really local to the decorators, first off.

  5. Maximilian Roos reporter

    That's awesome - thanks a lot Mike - appreciate it. LMK if you'd like me to do a PR with this - I'll at least try it in our libraries and see how it goes.

    (and agree with you re function calls, that's the 'tail wagging the dog' consideration I mentioned)

  6. Maximilian Roos reporter

    BTW, I'm not sure you're right on the inheritance issue - or am I misunderstanding your point?

    class A(object):
    
        def i(self, n):
            return n
    
        i_ = i
    
    class B(A):
    
        def i_(self, n):
            return super(B, self).i_(n)+ 1
    
    b=B()
    
    b.i_(8)
    # 9 
    
  7. Log in to comment