Timeline traceback collection has significant overhead

Bug #961875 reported by William Grant
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Launchpad itself
Triaged
High
Unassigned

Bug Description

python-timeline generates and stores a traceback when each timeline action (SQL, memcache, librarian, etc. requests) starts. This traceback is only used if an OOPS is created.

Profiling shows that this can be around 1.5ms per action, which is around 10% of the render time for well-optimised pages like Product:+index and Product:+sharing -- significant overhead for something that's only used when things go wrong. Most of this time goes to reading in and formatting the referenced code lines, and experimentation shows that collecting just the important bits of each frame (filename, lineno, name) and skipping the IO takes it down to around 1%. Since requests are short, it seems like we could reasonably fill in the lines and format the traceback just-in-time during OOPS serialisation, if indeed an OOPS is generated at all.

We already have our own traceback collector in lp.services.stacktrace, and it looks pretty much compatible with stdib's traceback.py. It's already split into extract/format stages, but extract still pulls in the file contents, so it would need to be split further.

Tags: performance
William Grant (wgrant)
tags: added: performance
Revision history for this message
Robert Collins (lifeless) wrote : Re: [Bug 961875] [NEW] Timeline traceback collection has significant overhead

Please improve the oops-tools stock environment as well; nothing about
this needed improvement is LP specific

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.