$30 off During Our Annual Pro Sale. View Details »

sys._current_frames(): Take real-time x-rays of your software for fun and performance by Leonardo Rochael

sys._current_frames(): Take real-time x-rays of your software for fun and performance by Leonardo Rochael

Take real-time X-rays of your software for Fun and Performance by Leonardo_Rochael

PyCon 2013

March 17, 2013
Tweet

More Decks by PyCon 2013

Other Decks in Programming

Transcript

  1. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    sys._current_frames()
    Take real-time X-rays of your software for Fun
    and Performance
    Leonardo Rochael Almeida
    Simples Consultoria

    View Slide

  2. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Performance Debugging Status Quo

    Prevention
    – Functional Performance testing

    testutils.org/multi-mechanize
    – Before production

    You do that, right?!

    View Slide

  3. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Performance Debugging Status Quo

    Production:
    – Wait for the angry mob

    “Reproduction instructions, please?”
    – Proactive Monitoring

    View Slide

  4. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    With reproduction instructions

    “profile/cProfile”
    – Heavy performance toll
    – Complicated output
    – Show calls only, not lines

    View Slide

  5. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    With Reproduction Instructions

    “statprof”
    – Sampling of tracebacks → statistics
    – More relevant info than “cProfile”
    – And lighter
    – Still doesn't “tell the story”

    View Slide

  6. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Without reproduction instructions

    “profile/cProfile”
    – Way too slow for production

    Sprinkle timing calls
    – log(time.time() - start_time)
    – Time consuming...
    – On the production environment?!

    DeadlockDebugger

    View Slide

  7. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Quick Zope Primer

    Z Object Publishing Environment

    One Listening thread
    – Parses HTTP Request

    A few Worker threads:
    – http://server/document/method?foo=bar
    – document.method(foo=“bar”)

    Transactional

    View Slide

  8. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    DeadlockDebugger
    for thread_id, frame in sys._current_frames().items():
    output = StringIO()
    traceback.print_stack(frame, file=output)
    res.append("Thread %s:\n%s" %
    (thread_id, output.getvalue()))
    res.append("End of dump")
    return '\n'.join(res)

    Directly from the Listening thread
    – At special URL
    – Works even if system stuck

    View Slide

  9. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    sys._current_frames()

    “threadframe” (Python 2.4)

    Python dict
    – Key: thread id (int)

    Same as thread.get_ident() for each thread
    – Value: Stack Frame

    Currently executing frame on this thread

    Tip of the thread's stack

    View Slide

  10. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Stack Frame

    Currently executing Function
    – file name
    – line number

    Pointer to previous frame

    Variables
    – locals
    – globals

    [...]

    View Slide

  11. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    DeadlockDebugger

    Instant snapshot
    – Thread: 1

    Stack trace …
    – Thread: 2

    Stack trace …

    Good for
    – System is slow Right Now

    View Slide

  12. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Proactive Monitoring

    Parsing of HTTP server logs
    – Reports slow URLs
    – But many “false” positives

    Maatkit (now Percona)
    – Reports slow MySQL Queries

    Still not enough info
    – Just sprinkling timing calls

    View Slide

  13. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Can we do better?

    DeadlockDebugger continuously

    Only in slow requests

    Add extra info

    View Slide

  14. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    LongRequestLogger

    Created at Nexedi

    Design
    – Julien Muchembled
    – Sébastien Robin
    – Leonardo Rochael Almeida

    Implementation
    – Leonardo Rochael Almeida

    View Slide

  15. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    LongRequestLogger

    Intercepts and Monitores each request

    Logfile:
    – Request X, thread Y, running for T seconds

    Request Info

    Stack trace
    – Request X, thread Y, running for T+2 seconds

    Request Info

    Stack trace
    – [...]

    View Slide

  16. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    LongRequestLogger shows

    Which requests were slow
    – Not the collateral damage

    Why exactly they were slow

    The right spot to add optimizations

    View Slide

  17. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    ERP5 Case Study

    “T-Shirt Custom Printing company”

    ERP5: Zope based ERP from Nexedi

    MRP, CRM, Accounting, ...

    Random peaks of horrible performance

    Never twice on the same URL

    Always at moments of high volume

    View Slide

  18. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    ERP5 Case Study

    Culprit: Sale Order Line Price

    Calculated on demand
    – Only the first time
    – Usually by background activities

    Stored on the Sale Order Line

    Death by 1000 cuts
    – Solved in 15 LOCs

    View Slide

  19. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Plone Case Study

    Large government portal

    LongRequestLogger:
    – Slowdowns at specific times
    – Culprit: database network access
    – Slowed down by scheduled backup

    View Slide

  20. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    What to optimize:
    Limit between Hot and Cold

    Stack Trace at T
    – A

    calls B
    – B

    calls C
    – C

    calls D
    – D

    calls E
    – E

    calls F

    Stack Trace at T+1
    – A

    calls B
    – B

    calls C
    – C

    calls X
    – X

    calls Y
    – Y

    calls Z

    View Slide

  21. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Why it works

    Statistic Sampling Profiling

    Pure probability
    – What is slow, shows

    Stack traces “tell the story”
    – Enriched by additional info

    Captures even the most un-reproduceable

    User Independence
    – Diagnose/Optimize before complaints

    View Slide

  22. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    LongRequestLogger: patch
    def wrapper(*args, **kw):
    m = Monitor()
    try:
    result = wrapper.original(*args, **kw)
    return result
    finally:
    m.stop()
    def do_patch():
    from ZPublisher import Publish
    wrapper.original = Publish.publish_module_standard
    Publish.publish_module_standard = wrapper

    View Slide

  23. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    LongRequestLogger: Monitor
    class Monitor(Thread):
    def __init__(self):
    Thread.__init__(self)
    self._event_pipe = os.pipe()
    self.dumper = dumper.Dumper(thread.get_ident())
    Thread.start(self)
    def run(self):
    timeout = self.dumper.timeout
    while self.waiting(timeout):
    self.dumper()
    timeout = self.dumper.interval

    View Slide

  24. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    LongRequestLogger: Dumper
    def extract_request(self, frame):
    from ZPublisher.Publish import call_object
    func_code = call_object.func_code
    while frame is not None:
    code = frame.f_code
    if (code is func_code):
    request = frame.f_locals.get('request')
    return request
    frame = frame.f_back
    def __call__(self):
    frame = sys._current_frames()[self.thread_id]
    output = StringIO()
    thread_info = self.get_thread_info(frame)
    print >> output, thread_info
    print >> output, "Traceback:"
    traceback.print_stack(frame, file=output)
    self.log.warning(output.getvalue())

    View Slide

  25. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    LongRequestLogger: Monitor
    def waiting(self, timeout):
    r, w = self._event_pipe
    read_ready_list, _, _ = select([r], [], [], timeout)
    if read_ready_list:
    os.read(r, 1)
    # stop() was called by monitored thread.
    # stop waiting:
    return False
    # still waiting for the other thread to finish
    return True
    def stop(self):
    """Stop monitoring this thread"""
    r, w = self._event_pipe
    os.write(w, '\0')
    self.join()
    map(os.close, (r, w))

    View Slide

  26. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Challenges

    Data volume
    – Parsing
    – De-interleaving

    User Interface (or lack thereof...)
    – grep

    View Slide

  27. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Future Improvements

    Reusable Library

    Helpers for analytics
    – Searching / sorting

    Better/more information extraction from frames

    Structured log storage
    – Richer comparisons

    Ignore set

    View Slide

  28. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    Open Questions

    True performance impact
    – How short can the recurring interval be?
    – GIL contention if too short?
    – Single thread to monitor all others?

    View Slide

  29. © 2012 Nexedi S/A, Some rights reserved,
    GNU Free Documentation License
    References

    Stack Overflow on sampling profiling:
    – http://stackoverflow.com/questions/375913

    “statprof”:
    – http://pypi.python.org/pypi/statprof/

    http://www.nexedi.com

    http://www.erp5.com

    @LeoRochael

    [email protected]

    [email protected]

    View Slide