{"id":156,"date":"2008-12-14T13:20:28","date_gmt":"2008-12-14T18:20:28","guid":{"rendered":"http:\/\/www.visophyte.org\/blog\/?p=156"},"modified":"2009-04-01T08:37:34","modified_gmt":"2009-04-01T13:37:34","slug":"logsploder-logsploding-its-way-to-your-logs-soon-also-logsplosion","status":"publish","type":"post","link":"https:\/\/www.visophyte.org\/blog\/2008\/12\/14\/logsploder-logsploding-its-way-to-your-logs-soon-also-logsplosion\/","title":{"rendered":"LogSploder, logsploding its way to your logs soon! also, logsplosion!"},"content":{"rendered":"<p><a href=\"http:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2008\/12\/logsploder-logsploding-logsplosion-1.png\"><img loading=\"lazy\" decoding=\"async\" class=\"alignnone size-thumbnail wp-image-157\" title=\"logsploder screenshot with gloda\" src=\"http:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2008\/12\/logsploder-logsploding-logsplosion-1-600x322.png\" alt=\"logsploder screenshot with gloda\" width=\"600\" height=\"322\" srcset=\"https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2008\/12\/logsploder-logsploding-logsplosion-1-600x322.png 600w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2008\/12\/logsploder-logsploding-logsplosion-1-300x161.png 300w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2008\/12\/logsploder-logsploding-logsplosion-1.png 1024w\" sizes=\"auto, (max-width: 600px) 100vw, 600px\" \/><\/a><\/p>\n<p>In our last logging adventure, we <a href=\"http:\/\/www.visophyte.org\/blog\/2008\/10\/20\/log4moz-and-chainsaw-via-new-xmlformattersocketappender\/\">hooked Log4Moz up to Chainsaw<\/a>.\u00a0 As great as <a href=\"http:\/\/logging.apache.org\/chainsaw\/\">Chainsaw<\/a> is, it did not meet all of my needs, least of all easy redistribution.\u00a0 So I present another project in a long line of fantastically named projects&#8230; <a href=\"http:\/\/hg.mozilla.org\/users\/bugmail_asutherland.org\/logsploder\/\">LogSploder<\/a>!<\/p>\n<p>The general setup is this:<\/p>\n<ul>\n<li>log4moz with a concept of &#8220;contexts&#8221;, a change in logging function argument expectations (think FireBug&#8217;s console.log), a JSON formatter that knows to send the contexts over the wire as JSON rather than stringifying them, plus our SocketAppender from the ChainSaw fun.\u00a0 The JSONed messages representations get sent to&#8230;<\/li>\n<li>LogSploder (a XULRunner app) listening on localhost.\u00a0 It currently is context-centric, binning all log messages based on their context.\u00a0 The contexts (and their state transitions) are tracked and visualized (using the still-quite-hacky visophyte-js).\u00a0 Clicking on a context displays the list of log messages associated with that context and their timestamps.\u00a0 We really should also display any other metadata hiding in the context, but we don&#8217;t.\u00a0 (Although the visualization does grab stuff out of there for the dubious coloring choices.)<\/li>\n<\/ul>\n<p>So, why, and what are we looking at?<\/p>\n<p>When <a href=\"http:\/\/ascher.ca\/blog\/2008\/12\/09\/thunderbird-3-beta-1-a-platform-for-innovation-shapes-up\/\">developing\/using Thunderbird&#8217;s exciting new prototype message\/contact\/etc views<\/a>, it became obvious that performance was not all that it could be.\u00a0 As we all know, the proper way to optimize performance is to figure out what&#8217;s taking up the most time.\u00a0 And the proper way to figure that out is to write a new tool from near-scratch.\u00a0 We are interested in both comprehension of what is actually happening as well as a mechanism for performance tracking.<\/p>\n<p>The screenshot above shows the result of issuing a gloda query with a constraint of one of my Inbox folders with a fulltext search for &#8220;gloda&#8221; *before any optimization*.\u00a0 (We already have multiple optimizations in place!) The pinkish fill with greenish borders are our XBL result bindings, the blue-ish fill with more obviously blue borders are message streaming requests, and everything else (with a grey border and varying colors) is a gloda database query.\u00a0 The white bar in the middle of the display is a XBL context I hovered over and clicked on.<\/p>\n<p>The brighter colored vertical bars inside the rectangles are markers for state changes in the context.\u00a0 The bright red markers are the most significant, they are state changes we logged before large blocks of code in the XBL that we presumed might be expensive.\u00a0 And boy howdy, do they look expensive!\u00a0 The first\/top XBL bar (which ends up creating a whole bunch of other XBL bindings which result in lots of gloda queries) ties up the event thread for several seconds (from the red-bar to the end of the box).\u00a0 The one I hovered over likewise ties things up from its red bar until the green bar several seconds later.<\/p>\n<p>Now, I should point out that the heavy lifting of the database queries actually happens on a background thread, and without instrumentation of that mechanism, it&#8217;s hard for us to know when they are active or actually complete.\u00a0 (We can only see the results when the main thread&#8217;s event queue is draining, and only remotely accurately when it&#8217;s not backlogged.)\u00a0 But just from the visualization we can see that at the very least the first XBL dude is not being efficient with its queries.\u00a0 The second expensive one (the hovered one) appears to chewing up processor cycles without much help from background processes.\u00a0 (There is one recent gloda query, but we know it to be cheap.\u00a0 The message stream requests may have some impact since mailnews&#8217; IMAP code is multi-threaded, although they really only should be happening on the main thread (might not be, though!).\u00a0 Since the query was against one folder, we know that there is no mailbox reparse happening.)<\/p>\n<p>Er, so, I doubt anyone actually cares about what was inefficient, so I&#8217;ll stop now.\u00a0 My point is mainly that even with the incredibly ugly visualization and what not, this tool is already quite useful.\u00a0 It&#8217;s hard to tell that just from a screenshot, since a lot of the power is being able to click on a bar and see the log messages from that context.\u00a0 There&#8217;s obviously a lot to do.\u00a0 Probably one of the lower-hanging pieces of fruit is to display context causality and\/or ownership.\u00a0 Unfortunately this requires explicit state passing or use of a shared execution mechanism; the trick of using thread-locals that log4j gets to use for its nested diagnostic contexts is simply not an option for us.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>In our last logging adventure, we hooked Log4Moz up to Chainsaw.\u00a0 As great as Chainsaw is, it did not meet all of my needs, least of all easy redistribution.\u00a0 So I present another project in a long line of fantastically &hellip; <a href=\"https:\/\/www.visophyte.org\/blog\/2008\/12\/14\/logsploder-logsploding-its-way-to-your-logs-soon-also-logsplosion\/\">Continue reading <span class=\"meta-nav\">&rarr;<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"inline_featured_image":false,"footnotes":""},"categories":[16,7,3,8,13,6,4],"tags":[22,52,55,54],"class_list":["post-156","post","type-post","status-publish","format-standard","hentry","category-clicky","category-debugging","category-mozilla","category-program-execution","category-shiny","category-thunderbird","category-visualizing","tag-log4moz","tag-logging","tag-logsploder","tag-visophyte-js"],"_links":{"self":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts\/156","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/comments?post=156"}],"version-history":[{"count":4,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts\/156\/revisions"}],"predecessor-version":[{"id":160,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts\/156\/revisions\/160"}],"wp:attachment":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/media?parent=156"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/categories?post=156"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/tags?post=156"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}