{"id":599,"date":"2010-10-17T15:40:40","date_gmt":"2010-10-17T23:40:40","guid":{"rendered":"http:\/\/www.visophyte.org\/blog\/?p=599"},"modified":"2010-10-17T15:40:40","modified_gmt":"2010-10-17T23:40:40","slug":"fighting-oranges-with-systemtap-probes-latency-fighting-step-2","status":"publish","type":"post","link":"https:\/\/www.visophyte.org\/blog\/2010\/10\/17\/fighting-oranges-with-systemtap-probes-latency-fighting-step-2\/","title":{"rendered":"fighting oranges with systemtap probes, latency fighting; step 2"},"content":{"rendered":"<p><a href=\"http:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-vis.png\"><img loading=\"lazy\" decoding=\"async\" class=\"alignnone size-full wp-image-613\" title=\"before-vis-tiny\" src=\"http:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-vis-tiny.png\" alt=\"\" width=\"599\" height=\"600\" srcset=\"https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-vis-tiny.png 599w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-vis-tiny-300x300.png 300w\" sizes=\"auto, (max-width: 599px) 100vw, 599px\" \/><\/a><\/p>\n<p>Recap from <a href=\"http:\/\/www.visophyte.org\/blog\/2010\/10\/12\/fighting-non-deterministic-xpcshell-unit-tests-through-causality-tracking-with-systemtap-step-1\/\">step 1<\/a>: Sometimes unit test failures on the mozilla tinderboxen are (allegedly, per me) due to insufficiently constrained asynchronous processes.\u00a0 Sometimes the tests time out because of the asynchronous ordering thing, sometimes it&#8217;s just because they&#8217;re slow.\u00a0 <a href=\"http:\/\/sourceware.org\/systemtap\/wiki\">Systemtap<\/a> is awesome.\u00a0 Using systemtap we can get exciting debug output in JSON form which we can use to fight the aforementioned things.<\/p>\n<p>Advances in bullet point technology have given us the following new features:<\/p>\n<ul>\n<li>Integration of <a href=\"http:\/\/sourceware.org\/systemtap\/examples\/profiling\/latencytap.stp\">latencytap<\/a> by William Cohen.\u00a0 Latencytap is a sytemtap script that figures out why your thread\/process started blocking.\u00a0 It uses kernel probes to notice when the task gets activated\/deactivated which tells us how long it was asleep.\u00a0 It performs a kernel backtrace and uses a reasonably extensive built-in knowledge base to figure out the best explanation for why it decided to block.\u00a0 This gets us not only fsync() but memory allocation internals and other neat stuff too.\n<ul>\n<li>We ignore everything less than a microsecond because that&#8217;s what latencytap already did by virtue of dealing in microseconds and it seems like a good idea.\u00a0 (We use nanoseconds, though, so we will filter out slightly more because it&#8217;s not just quantization-derived.)<\/li>\n<li>We get JS backtraces where available for anything longer than 0.1 ms.<\/li>\n<\/ul>\n<\/li>\n<li>The visualization is now based off of wall time by default.<\/li>\n<li>Visualization of the latency and GC activities on the visualization in the UI.<\/li>\n<li>Automated summarization of latency including aggregation of JS call stacks.<\/li>\n<li>The new UI bits drove and benefit from various wmsy improvements and cleanup.\u00a0 Many thanks to my co-worker <a href=\"http:\/\/tagneto.blogspot.com\/\">James Burke<\/a> for helping me with a number of design decisions there.<\/li>\n<li>The systemtap probe compilation non-determinism <a href=\"http:\/\/sourceware.org\/bugzilla\/show_bug.cgi?id=12121\">bug<\/a> mentioned last time is not gone yet, but thanks to the friendly and responsive systemtap developers, it will be gone soon!<\/li>\n<\/ul>\n<p>Using these new and improved bullet points we were able to look at one of the tests that seemed to be intermittently timing out (the <a href=\"https:\/\/bugzilla.mozilla.org\/show_bug.cgi?id=588048\">bug<\/a>) for legitimate reasons of slowness.\u00a0 And recently, not just that one test, but many of its friends using the same test infrastructure (<a href=\"https:\/\/developer.mozilla.org\/en\/MailNews\/AsyncTestUtils_Extended_Framework\">asyncTestUtils<\/a>).<\/p>\n<p>So if you look at the top visualization, you will see lots of reds and pinks; it&#8217;s like a trip to Arizona but without all of the tour buses.\u00a0 Those are all our fsyncs.\u00a0 How many fsyncs?\u00a0 This many fsyncs:<\/p>\n<p><img loading=\"lazy\" decoding=\"async\" class=\"alignnone size-full wp-image-601\" title=\"before-zings\" src=\"http:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-zings.png\" alt=\"\" width=\"690\" height=\"195\" srcset=\"https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-zings.png 690w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-zings-600x169.png 600w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-zings-300x84.png 300w\" sizes=\"auto, (max-width: 690px) 100vw, 690px\" \/><\/p>\n<p>Why so many fsyncs?<\/p>\n<p><img loading=\"lazy\" decoding=\"async\" class=\"alignnone size-full wp-image-602\" title=\"before-fsync-stackalyzer\" src=\"http:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-fsync-stackalyzer.png\" alt=\"\" width=\"689\" height=\"236\" srcset=\"https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-fsync-stackalyzer.png 689w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-fsync-stackalyzer-600x205.png 600w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/before-fsync-stackalyzer-300x102.png 300w\" sizes=\"auto, (max-width: 689px) 100vw, 689px\" \/><\/p>\n<p>Oh dear, someone must have snuck into messageInjection.js when I was not looking!\u00a0 (Note: comment made for comedic purposes; all the blame is mine, although I have several high quality excuses up my sleeve if required.)<\/p>\n<p>What would happen if we change the underlying C++ class to support batching semantics and the injection logic to use it?<\/p>\n<p><a href=\"http:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/after-vis.png\"><img loading=\"lazy\" decoding=\"async\" class=\"alignnone size-full wp-image-614\" title=\"after-vis-tiny\" src=\"http:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/after-vis-tiny.png\" alt=\"\" width=\"600\" height=\"600\" srcset=\"https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/after-vis-tiny.png 600w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/after-vis-tiny-300x300.png 300w\" sizes=\"auto, (max-width: 600px) 100vw, 600px\" \/><\/a><\/p>\n<p><img loading=\"lazy\" decoding=\"async\" class=\"alignnone size-full wp-image-603\" title=\"after-zings\" src=\"http:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/after-zings.png\" alt=\"\" width=\"692\" height=\"179\" srcset=\"https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/after-zings.png 692w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/after-zings-600x155.png 600w, https:\/\/www.visophyte.org\/blog\/wp-content\/uploads\/2010\/10\/after-zings-300x77.png 300w\" sizes=\"auto, (max-width: 692px) 100vw, 692px\" \/><\/p>\n<p>Nice.<\/p>\n<p>NB: No, I don&#8217;t know exactly what the lock contention is.\u00a0 The label might be misleading since it is based on sys_futex\/do_futex being on the stack rather than the syscall.\u00a0 Since they only show up on one thread but the latencytap kernel probes need to self-filter because they fire for everything and are using globals to filter, I would not be surprised if it turned out that the systemtap probes used futexes and that&#8217;s what&#8217;s going on.\u00a0 It&#8217;s not trivial to find out because the latencytap probes can&#8217;t really get a good native userspace backtrace (the <a href=\"http:\/\/sourceware.org\/bugzilla\/show_bug.cgi?id=12026\">bug<\/a>) and when I dabbled in that area I managed to hard lock my system and I really dislike rebooting.\u00a0 So a mystery they will stay.\u00a0 Unless someone tells me or I read more of the systemtap source or implement hover-brushing in the visualization or otherwise figure things out.<\/p>\n<p>There is probably more to come, including me running the probes against a bunch of mozilla-central\/comm-central tests and putting the results up in interactive web-app form (with the distilled JSON available).\u00a0 It sounds like I might get access to a MoCo VM to facilitate that, which would be nice.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>Recap from step 1: Sometimes unit test failures on the mozilla tinderboxen are (allegedly, per me) due to insufficiently constrained asynchronous processes.\u00a0 Sometimes the tests time out because of the asynchronous ordering thing, sometimes it&#8217;s just because they&#8217;re slow.\u00a0 Systemtap &hellip; <a href=\"https:\/\/www.visophyte.org\/blog\/2010\/10\/17\/fighting-oranges-with-systemtap-probes-latency-fighting-step-2\/\">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":[7,8,4],"tags":[93,76],"class_list":["post-599","post","type-post","status-publish","format-standard","hentry","category-debugging","category-program-execution","category-visualizing","tag-mozperfish","tag-systemtap"],"_links":{"self":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts\/599","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=599"}],"version-history":[{"count":8,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts\/599\/revisions"}],"predecessor-version":[{"id":618,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/posts\/599\/revisions\/618"}],"wp:attachment":[{"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/media?parent=599"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/categories?post=599"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.visophyte.org\/blog\/wp-json\/wp\/v2\/tags?post=599"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}