{"id":282,"date":"2008-11-20T13:00:48","date_gmt":"2008-11-20T17:00:48","guid":{"rendered":"http:\/\/benjamin.smedbergs.us\/blog\/?p=282"},"modified":"2008-11-20T14:12:41","modified_gmt":"2008-11-20T18:12:41","slug":"282","status":"publish","type":"post","link":"http:\/\/benjamin.smedbergs.us\/blog\/2008-11-20\/282\/","title":{"rendered":"DTrace Bugs on Mac"},"content":{"rendered":"<p>Ted and I have been looking rather closely at the performance of the Mozilla build system. In order to get a better sense of where we&#8217;re spending time, I wanted to use <a href=\"http:\/\/www.sun.com\/bigadmin\/content\/dtrace\/\">dtrace<\/a> to get statistics on an entire build.<\/p>\n<h3>Basic Process Information From DTrace<\/h3>\n<p>In theory, the dtrace proc provider lets a system administrator watch process and thread creation for a tree of processes. Using normal dtrace globals, you can track the process parent, arguments, working directory, and other information:<\/p>\n<pre class=\"code\">\r\n\/* progenyof($1) lets us trace any subprocess of a specific process, in this case the shell from\r\n   which we launch the build *\/\r\n\r\nproc:::create\r\n\/progenyof($1)\/\r\n{\r\n  printf(\"FORKED\\t%i\\t%i\\t%i\\n\", timestamp, pid, args[0]->pr_pid);\r\n}\r\n\r\nproc:::exec\r\n\/progenyof($1)\/\r\n{\r\n  printf(\"EXEC\\t%i\\t%i\\t%s\\t%s\\n\", timestamp, pid, curpsinfo->ps_args, cwd);\r\n}\r\n\r\nproc:::exit\r\n\/progenyof($1)]\r\n{\r\n  printf(\"EXIT\\t%i\\t%i\\n\", timestamp, pid);\r\n}\r\n<\/pre>\n<p>Unfortunately, the MacOS implementation of dtrace doesn&#8217;t reflect information very well:<\/p>\n<ul>\n<li>curpsinfo->ps_args doesn&#8217;t contain the entire command-line of the process; it only contains the first word\n<li>cwd doesn&#8217;t contain the entire working directory <tt>\/builds\/mddepend\/ff-debug<\/tt> but only the last component <tt>ff-debug<\/tt>. Since many of our directories within the tree share names such as <tt>src<\/tt> and <tt>public<\/tt>, the information is pretty much useless.\n<\/ul>\n<h3>Process CPU Time in DTrace<\/h3>\n<p>Dtrace doesn&#8217;t give scripts a simple way to track the CPU time used by a process: the <a href=\"http:\/\/docs.sun.com\/app\/docs\/doc\/816-5174\/proc-4?a=view\">kernel psinfo_t struct<\/a> does have a pr_time member, but this is of non-reflected struct timestruc_t.<\/p>\n<p>There is another way to calculate this: dtrace exposes a variable <tt>vtimestamp<\/tt> which represents, for each thread, a virtual timestamp when that thread was executing. By subtracting the vtimestamp at proc:::lwp-start from the vtimestamp at proc:::lwp-exit you can calculate the time spent in each thread, and use sums to calculate the per-process total.<\/p>\n<pre class=\"code\">\r\nproc:::lwp-start\r\n\/progenyof($1)\/\r\n{\r\n  self->start = vtimestamp;\r\n}\r\n\r\nproc:::lwp-exit\r\n\/self->start\/\r\n{\r\n  @[pid] = sum(vtimestamp - self->start);\r\n  self->start = 0;\r\n}\r\n\r\nEND\r\n{\r\n  printf(\"%-12s %-20s\\n\", \"PID\", \"TIME\");\r\n  printa(\"%-12i %@i\\n\", @);\r\n}\r\n<\/pre>\n<p>Unfortunately, the MacOS implementation of DTrace has a serious bug in the implementation of <tt>proc:::lwp-start<\/tt>: it isn&#8217;t fired in the context of the thread that&#8217;s being started, but in the context of the thread (and process!) that created the thread. This means that the pid and vtimestamp reported in the probe are useless. I have filed this with Apple as radar 6386219.<\/p>\n<h3>Summary<\/h3>\n<p>Overall, the bugs in the Apple implementation of DTrace make it pretty much useless for doing the build system profiling I intended. I am now trying to get an OpenSolaris virtual machine up for building, since I know that DTrace is not broken on Solaris; but never having used Solaris before, I&#8217;ll save that story for another day.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>Ted and I have been looking rather closely at the performance of the Mozilla build system. In order to get a better sense of where we&#8217;re spending time, I wanted to use dtrace to get statistics on an entire build. Basic Process Information From DTrace In theory, the dtrace proc provider lets a system administrator [&hellip;]<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[2,6],"tags":[173,174],"class_list":["post-282","post","type-post","status-publish","format-standard","hentry","category-mozilla","category-untagged","tag-dtrace","tag-solaris"],"_links":{"self":[{"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/posts\/282","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/comments?post=282"}],"version-history":[{"count":4,"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/posts\/282\/revisions"}],"predecessor-version":[{"id":288,"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/posts\/282\/revisions\/288"}],"wp:attachment":[{"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/media?parent=282"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/categories?post=282"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/benjamin.smedbergs.us\/blog\/wp-json\/wp\/v2\/tags?post=282"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}