Take real-time X-rays of your software for Fun and Performance by Leonardo_Rochael
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation Licensesys._current_frames()Take real-time X-rays of your software for Funand PerformanceLeonardo Rochael AlmeidaSimples Consultoria
View Slide
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicensePerformance Debugging Status Quo●Prevention– Functional Performance testing●testutils.org/multi-mechanize– Before production●You do that, right?!
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicensePerformance Debugging Status Quo●Production:– Wait for the angry mob●“Reproduction instructions, please?”– Proactive Monitoring
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseWith reproduction instructions●“profile/cProfile”– Heavy performance toll– Complicated output– Show calls only, not lines
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseWith Reproduction Instructions●“statprof”– Sampling of tracebacks → statistics– More relevant info than “cProfile”– And lighter– Still doesn't “tell the story”
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseWithout reproduction instructions●“profile/cProfile”– Way too slow for production●Sprinkle timing calls– log(time.time() - start_time)– Time consuming...– On the production environment?!●DeadlockDebugger
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseQuick 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
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseDeadlockDebuggerfor 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
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation Licensesys._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
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseStack Frame●Currently executing Function– file name– line number●Pointer to previous frame●Variables– locals– globals●[...]
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseDeadlockDebugger●Instant snapshot– Thread: 1●Stack trace …– Thread: 2●Stack trace …●Good for– System is slow Right Now
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseProactive 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
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseCan we do better?●DeadlockDebugger continuously●Only in slow requests●Add extra info
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseLongRequestLogger●Created at Nexedi●Design– Julien Muchembled– Sébastien Robin– Leonardo Rochael Almeida●Implementation– Leonardo Rochael Almeida
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseLongRequestLogger●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– [...]
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseLongRequestLogger shows●Which requests were slow– Not the collateral damage●Why exactly they were slow●The right spot to add optimizations
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseERP5 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
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseERP5 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
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicensePlone Case Study●Large government portal●LongRequestLogger:– Slowdowns at specific times– Culprit: database network access– Slowed down by scheduled backup
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseWhat 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
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseWhy 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
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseLongRequestLogger: patchdef wrapper(*args, **kw):m = Monitor()try:result = wrapper.original(*args, **kw)return resultfinally:m.stop()def do_patch():from ZPublisher import Publishwrapper.original = Publish.publish_module_standardPublish.publish_module_standard = wrapper
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseLongRequestLogger: Monitorclass 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.timeoutwhile self.waiting(timeout):self.dumper()timeout = self.dumper.interval
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseLongRequestLogger: Dumperdef extract_request(self, frame):from ZPublisher.Publish import call_objectfunc_code = call_object.func_codewhile frame is not None:code = frame.f_codeif (code is func_code):request = frame.f_locals.get('request')return requestframe = frame.f_backdef __call__(self):frame = sys._current_frames()[self.thread_id]output = StringIO()thread_info = self.get_thread_info(frame)print >> output, thread_infoprint >> output, "Traceback:"traceback.print_stack(frame, file=output)self.log.warning(output.getvalue())
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseLongRequestLogger: Monitordef waiting(self, timeout):r, w = self._event_piperead_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 finishreturn Truedef stop(self):"""Stop monitoring this thread"""r, w = self._event_pipeos.write(w, '\0')self.join()map(os.close, (r, w))
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseChallenges●Data volume– Parsing– De-interleaving●User Interface (or lack thereof...)– grep–
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseFuture Improvements●Reusable Library●Helpers for analytics– Searching / sorting●Better/more information extraction from frames●Structured log storage– Richer comparisons●Ignore set
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseOpen Questions●True performance impact– How short can the recurring interval be?– GIL contention if too short?– Single thread to monitor all others?
© 2012 Nexedi S/A, Some rights reserved,GNU Free Documentation LicenseReferences●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]