Random musings from sometimes sunny Ireland John Rice's Weblog

Monday Nov 26, 2007

Hi - well off digging into Python for my sins and wanted to have an IDE for Python working on Solaris. Looking around came across JPyDebug, which has NetBeans and JEdit support.

I was able to get the JEdit support working [thanks to frred] but the NetBeans plugin is failing in NB 6.0 RC1 with a java.net.ConnectException when I try to debug a python file :( Hopefully this will be fixed. In the meantime here's the how to for JEdit on OpenSolaris (I'm on x86 nevada build 77).
 

Grab and Install the bits

  • JEdit - using 4.3pre11
    • installed using: java -jar jedit4.3pre11install.jar
  • JPyDebug - using 0.18.5
    • unpack and installed using: cp jpydebug-jedit43-0.0.18-5.jar ~/.jedit/jars
    • Note: current nbm not working in NetBeans, maybe some simple config issue, if anyone knows let me know :(
  • Jython - using 2.2.1
    • installed using: java -jar jython_installer-2.2.1.jar
    • Need to copy <jython install dir>/jython.jar to ~/.jedit/jars it's needed by JPyDebug

Configure 

Make sure Env setup, for me this in my ~/.bashrc

export JEDIT_HOME=~/jedit/4.3pre6/
export JAVA_HOME=/usr/jdk/jdk1.6.0_01/
 

Run JEdit and Configure the JPyDebug plugin: 

JEdit > Plugins > Plugin Options: JPyDebug

CPython Options:

    Python Interpreter location: /usr/bin/python

JPython Options:

    Jython JVM location: /usr/jdk/jdk1.6.0_01/bin/java

    Jython Home Path: /export/home/jr140578/jython2.2.1
 

Debug 

Shut down JEdit, relaunch and open a sample Python program to test. You should be able to set breakpoints by clicking on the left hand gutter of the View window, then Choose: 

    Plugins> JPyDebug > JPyDbg Python Debugger

I wanted to run this as a docked window, but the cursor seems to go a little crazy when I do. So for now I keep it floating, select the little Bug icon and I can debug the Python code. You can step through the code and look at variables as they are changing and so on. I'm using code from the Dive into Python online book in the image below:

 


Friday Oct 26, 2007

Hi well for my sins I got co'opted into doing a Daily DTrace demo to the Irish OpenSolaris User Group's October Meeting group last night with Sean McGrath. Tim Foster claims he was babysitting, but we'll never know for sure, I think the Guinness lured him away ;)

So what to demo. Well we wanted to show folks who didn't want to deep dive on 50 slides of DTrace bootcamp, how to do something useful pretty quickly. So we fired up a desktop with nevada build 75 to take a look at something right away, and left the slides for another day. One place that I new already was a good place to start was the Gnome System Monitor. 

Whats the problem?

To be technical GSM sucks, it's gobbling up my cpu like a mad thing !! 

What next?

Well lets compare it to prstat (similar to top for dumping out process info on the fly to the terminal) first - himm prstat is consuming 0.1% CPU, so useful benchmark to compare against. GSM is eating 5 - 20% CPU :( Now as GSM is a gnome GUI app I'd expect some overhead say 1% perhaps, but not 5 - 20 %.

So run a quick dtrace oneliner to look at syscalls for gnome-system-mon and see what's hot:

$ dtrace -n 'syscall:::entry/ execname == "gnome-system-mon"/ \
{@[probefunc] = count();}

Himm ... lots of open's, preads all looks a bit suspicious [I'm on the road on a Mac so can't dump output, you'll just have to trust me or fire up OpenSolaris yourself and have a go :)

DTraceToolkit 

OK - lets use the precanned scripts in the latest DTraceToolkit (cudos to Brendan Gregg) and dig in. Use of exesnoop, iosnoop, opensnoop and errinfo are my first ports of call normally.

Ran iosnoop and turned up zippo. So not hitting the disc, weird as I'm seeing a lot of open's, something must be in memory I guess.

Ran opensnoop:

$ opensnoop -ap `pgrep -f gnome-system-mon`

How I see a load of open's flying by on the /proc filesystem. This is a virtual file system analogous to what's on linux that contains process information on your currently running processes. Running the same thing on prstat and I only see one hit on /proc not hundreds in the space of a few seconds :(

I can use dtrace to aggregate the open calls and generally poke into them. The syscall man pages are your friend to find out what the args are that are being passed to dtrace.

$ dtrace -n 'syscall::open*:entry/execname == "gnome-system-mon"/ \
{@[copyinstr(arg0)] = count();} tick-10sec{exit(0);}

Using the tick probe allows me to get an accurate timed experiment and I can just change the execname to prstat to see what it's up to over the equivalent period.

Now for the sake of the demo I didn't go off and check the timings for the syscalls and the breakdown of on/off cpu, which I'd normally do to confirm that these large number of opens and preads was a bad thing, but I'll leave that up to the reader :) Just use the syscall entry and return probes and the on-cpu, off-cpu sched provider probes (the toolkit has plenty of examples).

Stacks

What I did next was to modify the above script to see where the open's where being made from in GSM and also in prstat.

$ dtrace -n 'syscall::open*:entry/execname == "gnome-system-mon"/ \
{@[copyinstr(arg0), ustack()] = count();} tick-10sec{exit(0);}

For GSM I could see that we where making lots of calls into libgtop for what looked like the entire contents of the /proc dir. For prstat we could see that it was not using libgtop, but doing a much more sensible dir scan to find out what had changed and checking that only.

So it's clear that on OpenSolaris libgtop is clearly doing some very suboptimal things when it comes to checking process stats, that would really need fixed.

Errorinfo 

Just for fun I thought well as GSM is doing such crazy things with /proc, lets fire up errorinfo and see if that will reveal any other strangeness. As soon as I do we see lots and lots of errors in opens, reads and so on for GSM.

Lets dig in a little more: 

$ dtrace -n 'syscall::open*:return/execname == "gnome-system-mon" && \
arg1 != 0/{@[fds[arg0].fi_pathname, arg1] = count();} tick-10sec{exit(0);}

Here we are checking the open return and only looking at the file it's dealing with if the open fails (can use errno or arg1 to get the return value of the syscall). The fds is a handy addition to dtrace to allow you to lookup file information given a file descriptor, it's base type is fileinfo_t as used in the IO provider. When we run this we can see it's hitting lots of /proc processes for processes owned by root, so we are failing on access permission. Not only that but it's doing it repeatedly on a given process id for different pieces of info. Oh well, I hope someone gives libgtop a little bit of TLC on OpenSolaris.

Why isn't this fixed? 

I know there have been some patches proposed to help, but it's one of those, well it works fine on Linux problems :( Hopefully the libgtop maintainer's can take another look to see if there are more optimal ways to query for the information taking some inspiration from prstat perhaps. Lets not maintain another OpenSolaris only patch please.

Hope you enjoyed the journey into dtrace land :)

 

 

 

Tuesday Oct 23, 2007

Happy days again - the Javascript framework patch [#388564] for Javascript tracing in mozilla has landed in CVS head :)

It's already being actively used:

"No problem -- dtrace has been a huge help for us, from what I can see. Sayre has been helping front-end hackers identify JS performance problems with it, which would be hard to find otherwise." Brendan Eich

"I don't think I can work on Mozilla without DTrace ever again. Too useful." Land of DTrace, Robert Sayre

Mike Shaver nominated the dtrace team at Sun "for giving us the first good tool we've ever had for understanding front-end performance." - Thanks Mike :)

Here are a few of the bugs it's already helped with, thanks to Robert Sayre's enthusiastic evangelism , cheers Robert :)

[#398300] instantiates livemark service on startup
[#398360] speed up onSecurityChange
[#398950] contentprefsink event registration
[#398344] utilityOverlay.js isElementVisible() is slow

I've built this from head on nevada build 74, having applied the gtk patch disconnect_handlers_and_prevent_unloading_v1.1 Unfortunately Firefox is now crashing in pango font hanlding, unrelated to the probe work :( Apparently this is ok in build 75 onwards, thanks again to Ginn Chen for the info, so will upgrade today and see how we get on. Also noticed that Johnny had to change some of the build framework to land the JavaScript patch and this has now broken the load probes patch. Ah well, bit more work for me ...

I've included some info on the JavaScript probes below. There are plenty of DTrace examples using the probes in the new 0.99 DTraceToolkit Brendan has just posted. Just unzip and look under the JavaScript subdirectory, I've referred to some of them below.

javascript provider probes

javascript*:::function-entry  
    Args: (char *filename, char *classname, char *funcname)
javascript*:::function-return   
    Args: (char *filename, char *classname, char *funcname)

The probe function-entry fires when a JavaScript function begins to execute. The probe, function-return, fires when the function completes. The probe arguments are still being designed, for now arg0 is a the file pathname, arg1 is a classname (if available), and arg2 is the function name. [See js_calls.d, js_calltime.d, js_calldist.d, js_flow.d, js_flowtime.d, js_stat.d, js_who.d]

javascript*:::function-info     
    Args: (char *filename, char *classname, char *funcname, int lineno, char *runfilename, int runlineno)

Used to get line number information. The function-info probe is best for anonymous function tracing - since it gives line numbers for identifying the anonymous function location. [See js_flowinfo.d]

javascript*:::function-args    
    Args: (char *filename, char *classname, char *funcname, int argc, void *argv, void *argv0,
                     void *argv1, void *argv2, void *argv3, void *argv4)
javascript*:::function-rval      
    Args: (char *filename, char *classname, char *funcname, int lineno, void *rval, void *rval0)

So function-args was to provide some debugging visibility for function arguments; and function-rval was for the return value. [No examples in the toolkit as these are still  experimental].
Status: args & rval currently return zero args in error, when in-built methods hit a new performance optimization in the JS engine.  It needs fixing.  If you try using them now, you'll see that they mostly work (especially for your own functions).

javascript*:::object-create      
    Args: (char *filename, char *classname, uintptr_t *object, int rlineno)

Fires when a JavaScript object has been fully created. [See js_objgc.d]

javascript*:::object-create-start
    Args: (char *filename, char *classname)
javascript*:::object-create-done
    Args: (char *filename, char *classname)

Matching probes can be used to time object creation. [See js_calltime.d, js_cpudist.d, js_objcpu.d]

javascript*:::object-finalize  
    Args: (NULL, char *classname, uintptr_t *object)

Fires when an object is garbage collected. [See js_objgc.d]

javascript*:::execute-start 
    Args: (char *filename, int lineno)
javascript*:::execute-done  
    Args: (char *filename, int lineno)

These trace when a JavaScript program or block of code begins execution and ends. [See js_execs.d]


Thursday Oct 11, 2007

Happy days - the basic framework patch [#370906] for the tracing framework in mozilla has landed in CVS head :)

I've built and put up a refreshed patch for the Browser load and dns lookup probes that work with the new framework. To test them you can run the browserspy_time_all.d script as before.

Next steps are to get the various probes themselves added, including the JavaScript probes, the load and dnslookup probes and other probes that various community members want such as Robert Sayre's xpc wrapped javascript class probes and Benjamin Smedberg's cycle collection probes.

If you want to play with the probes, you can just build firefox from cvs and apply the load and dns patch from above, no need to apply the framework patch anymore :) Note the JavaScript patch currently needs a little tlc to get it to apply cleanly to head, job for next week, sooner it's landed the better ;)

Steps to build Firefox from CVS on Solaris (nevada b74). Note: when I built from head today the browser core'd on startup, the following patch sorts it. I'm sure they'll fix it in head shortly, but if you see cores this could help, I know it saved my bacon, thanks to Ginn Chen for pointing it out to me :) disconnect_handlers_and_prevent_unloading_v1.1

GET SOURCE
export CVSROOT=":pserver:anonymous@cvs-mirror.mozilla.org:/cvsroot"
cvs co mozilla/client.mk
cd mozilla/
gmake -f client.mk checkout MOZ_CO_PROJECT=browser

Create .mozconfig under mozilla:
cat mozilla/.mozconfig:

ac_add_options --enable-xft
ac_add_options --disable-freetype2
ac_add_options --disable-tests
ac_add_options --disable-debug
ac_add_options --enable-svg
ac_add_options --enable-canvas
ac_add_options --enable-optimize
ac_add_options --enable-xinerama
ac_add_options --disable-auto-deps
ac_add_options --enable-application=browser
. $topsrcdir/browser/config/mozconfig

Patch Source for Load Probes
https://bugzilla.mozilla.org/attachment.cgi?id=284484

Save above patch to mozilla-probe.patch, in mozilla dir:
gpatch -p0 -i mozilla-probe.patch


Setup Build Environment (on Solaris - nevada b74)
export LD_LIBRARY_PATH=/usr/sfw/lib
export CC="/opt/SUNWspro/bin/cc"
export CXX="/opt/SUNWspro/bin/CC"
export CFLAGS="-xlibmil"
export CXXFLAGS="-xlibmil -xlibmopt -features=tmplife -norunpath"
export LDFLAGS="-R'\$\$ORIGIN:\$\$ORIGIN/..' -R/usr/sfw/lib"

BUILD
/usr/autoconf-2.13/bin/autoconf
./configure --enable-dtrace
gmake

RUN
export LD_LIBRARY_PATH=".:/usr/sfw/lib"
cd dist/bin
./firefox & 

Test
List probes: dtrace -lP "moz*"
Get timings: ./browserspy_time_all.d

Thursday Sep 27, 2007

Well - solving many problems is often best done by not trying to solve them at all ;) Left the mystery of my 10 sec DNS lookups after scratching my head over it for a day or so.

I was a little suspicious that my home setup with a router connected to my dsl modem might have been causing problems, so I wanted to try the probes out in work. Headed in today and fired things up but got zippo hits for my dnslookup-start/done probes. Himm what was going on? Well added in an aggregate into the dnslookup-init probe to see what hosts it was asking for and turns out to be hitting "webcache.uk.sun.com", our internal web cache for all it's lookups :)

Now getting out and around our webcache can require a little magic, but thanks to Daren Kenny I got a direct connection out bypassing the webcache server, thanks Darren! Now when I fired up the browser and did a little surfing to finance.yahoo.com with the browserspy script running I see the following:

DTrace Stats for: http://finance.yahoo.com

PROBE STATS:

TYPE TOTAL COUNT
DNS_REQ Network Requests - Done 14
DNS_REQ Network Requests - Started 14
DNS_LOAD Lookups - Network and Cache 23

TYPE TOTAL COUNT
URI Network Requests - Done 7
URI Network Requests - Started 8
IMAGE_REQ Network Requests - Done 37
IMAGE_REQ Network Requests - Started 37
IMAGE_LOAD Image Loads - Network and Cache 70

Browser DNS lookup requests,

PID UID STATUS COUNT AVG(msec) SUM(msec) IP HOST
1973 65535 1 1 0 0 72.14.203.91 sb.google.com
1973 65535 1 1 0 0 209.62.176.152 ad.doubleclick.net
1973 65535 1 1 293 293 69.8.201.107 ads.yimg.com
1973 65535 1 1 318 318 69.8.201.80 us.i1.yimg.com
1973 65535 1 1 325 325 69.8.201.75 us.news2.yimg.com
1973 65535 1 1 360 360 68.142.196.87 finance.yahoo.com
1973 65535 1 1 453 453 68.142.213.132 us.bc.yahoo.com
1973 65535 1 1 455 455 68.142.196.15 ichart.finance.yahoo.com
1973 65535 1 1 568 568 209.62.178.57 ad.uk.doubleclick.net
1973 65535 1 1 602 602 68.142.213.142 l.yimg.com
1973 65535 1 1 776 776 209.225.0.101 servedby.advertising.com
1973 65535 1 1 850 850 216.73.84.103 m.uk.2mdn.net
1973 65535 1 1 4223 4223 69.8.201.75 us.js2.yimg.com
1973 65535 1 1 5117 5117 216.252.106.98 streamerapi.finance.yahoo.com
:
:

Happy days :) It was a configuration issue, we are now seeing a much happier spread of dnslookup times. Time for me to see if I can bypass my router at home and use the dns server that the modem is using directly, should certainly make my browsing a lot faster!!

[Update]: Checked it at home changed my /etc/resolv.conf to use the netopia dsl's nameserver and all is well with the world. Now no excuse to go and get a cup of coffee, it's all so dam fast ;) Interesting that it's a lot faster at home than at work, similar times of day as well, curious indeed, must point out to our sys admins.

DTrace Stats for: http://finance.yahoo.com from Home

PROBE STATS:

TYPE TOTAL COUNT
DNS_REQ Network Requests - Done 11
DNS_REQ Network Requests - Started 11
DNS_LOAD Lookups - Network and Cache 20

TYPE TOTAL COUNT
URI Network Requests - Done 1
URI Network Requests - Started 1
IMAGE_REQ Network Requests - Done 40
IMAGE_REQ Network Requests - Started 40
IMAGE_LOAD Image Loads - Network and Cache 71

Browser DNS lookup requests,

PID UID STATUS COUNT AVG(msec) SUM(msec) IP HOST
3237 65535 1 1 30 30 217.146.179.200 us.bc.yahoo.com
3237 65535 1 1 31 31 159.134.196.102 us.js2.yimg.com
3237 65535 1 1 43 43 159.134.196.103 l.yimg.com
3237 65535 1 1 46 46 159.134.196.118 us.i1.yimg.com
3237 65535 1 1 57 57 206.190.56.229 finance.yahoo.com
3237 65535 1 1 64 64 159.134.196.117 speed.pointroll.com
3237 65535 1 1 80 80 216.73.87.74 ad.doubleclick.net
3237 65535 1 1 98 98 159.134.196.102 us.news2.yimg.com
3237 65535 1 1 128 128 159.134.196.118 ads.yimg.com
3237 65535 1 1 161 161 72.32.153.176 ads.pointroll.com
3237 65535 1 1 652 652 206.190.56.234 ichart.finance.yahoo.com

Well the probes have their uses after all, as my friend always says when we are out hiking, trust the compass, even if you are 100% sure it can't be right, it is ;) Unless of course you are standing on top of some lodestone, but that's another issue entirely!

 


 

Wednesday Sep 26, 2007

Hi - well just got around to uploading the dns lookup probes I was talking about. As always they are at bugzilla [#370906]. Changed my theme today as the font on the old one was driving me nuts :)

I wanted to make a few changes. 

When the dns lookup fires some where going to the cache and some to the network. It was a little confusing to see dnslookup-start probes firing without a matching dnslookup-done, which happened when you hit the cache. So I've added a dnslookup-init which is called for all initiated dnslookups, but only dnslookup-start and dnslookup-done get called when you go out on the net for the lookup.

I made similar changes to the load probes for the image loads. The load-init is called for all image requests, but only load-start and load-done are called when you go out on the net to fetch them.

The new load and dnslookup probes are:

Probes:
 mozilla<pid>:::load-init
 mozilla<pid>:::load-start
 mozilla<pid>:::load-done
 Args:
    arg0 is of type void * - unique_id
    arg1 is an enum nsTraceLoadType - TYPE_URI or TYPE_IMAGE
    arg2 is of type struct     nsTraceLoadInfo * - pointer to the URI info

 mozilla<pid>:::dnslookup-init
 mozilla<pid>:::dnslookup-start
 mozilla<pid>:::dnslookup-done
 Args:
    arg0 is of type void * - unique_id
    arg1 is of type struct     nsTraceDNSLookupInfo * - pointer to the DNS lookup info

I've uploaded a new script which works with these new probes, along with some sample output. We still have the mystery of the 10 sec dns lookups, but hopefully we can figure that one out down the line, with a bit of help from the mozilla engineers, biesi if you have any ideas what's going on I'd really appreciate the dig out :) Is it some internal dnslookup thread pool issue?

Anyway I'm off traveling next week, but hope to get stuck into the other page load and dynamic update stages when I get back, including parsing, DOM construction, layout and paint. Lots of fun :)

Thursday Sep 20, 2007

Hi - well as part of the work on the Mozilla Tracing framework [#370906] I've been talking about, we wanted to add probes to check when and how long dns lookups where taking as you load a page in the browser.

So I've added the following probes to monitor dns lookups ....

[Read More]

Tuesday Sep 18, 2007

Hi - well after a bit of hacking to make sure everything built under debug I've uploaded the latest patches for the Tracing Framework [#370906], which contain the new mozilla<pid>:::load-start and mozilla<pid>:::load-done probes for URI's and Images.

I changed the timing script so it will log both URI and Image requests. For a bit of fun I ran it against Jonathan's blog, both using a hard reload to avoid the cache and again but allowing the cache to kick in. You can see very clearly from the output how the cache is functioning and what is dominating the timings in both instances.

Browser requests by scheme - Using the Cache

PID UID TYPE COUNT AVG(msec) SUM(msec) SCHEME
6423 65535 IMAGE_REQ 1 0 0 https
6423 65535 IMAGE_REQ 22 3 84 http
6423 65535 URI 23 541 12448 http

Browser requests by scheme - Bypass the Cache (Hard Reload)

PID UID TYPE COUNT AVG(msec) SUM(msec) SCHEME
6423 65535 IMAGE_REQ 1 0 0 https
6423 65535 IMAGE_REQ 60 221 13269 http
6423 65535 URI 23 723 16635 http

Off to get stuck into DNS lookup probes, thanks to biesi on irc.mozilla.org #developers for the pointers yet again :)  You are a star and have shown remarkable patience with my numerous very basic questions about the mozilla code base!!

 

Well I had blogged about image timings for Mozilla using our custom load probes a few days ago, but when I looked at the output I noticed a little weirdness. The final top 10 site listing with Count, Avg and Sum had some Count entries of 0. 

      PID      UID    COUNT   AVG(msec)   SUM(msec)   SITE                                
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/133-1321718550
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/178-1321865092
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/76-1321412015
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/83-1321462309
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/84-1321463278
:
10955 65535 0 4 4 file:///usr/share/doc/soldevex/html/images/Solaris.gif
10955 65535 0 7 7 http://www.makepovertyhistory.org/whiteband_small_right.gif
10955 65535 0 7 7 file:///usr/share/doc/soldevex/html/images/New_Prod_Banner.jpg
10955 65535 0 12 12 http://www.mozilla.org/images/header_tab.gif
10955 65535 0 26 26 http://docs.sun.com/app/images/shadow_box.png
10955 65535 0 62 62 http://www.abercornbasin.com/items/ar02_eflyer.jpg
 

Now this seemed a little weird, I wondered if having the count aggregation in the start probe and the avg/ sum aggregates in the done probes was causing problems and getting things out of sync. So I changed that but no joy, still got some zero counts. I tested just listing the site aggregate and all the Counts in that looked fine, no 0's. So it was something to do with combining the aggregates that was causing the problem.

Chewing this over on irc.mozilla.org #developers with Brendan Gregg turns out that the problem is in the trunc calls, thanks for the prompting Brendan, think I'd still be looking at it :) When we trunc the count, avg and sum aggregates they have all been sorted off different things, namely count, avg or sum :) So the list of truncated sites you get for each of the aggregates will probably not be the same. When you then combine them in one aggregate printout, dtrace will just insert 0 for the Count if that particular URI is not present in the count aggregate but is in the other two aggregates. It is the aggregate you are sorting on that takes precedence.

Simple solution

If you have aggregates sorted on different values and want to combine them into one aggregate printa do not truncate them first. Or if you really need to truncate them just truncate them, but list them separately, which is what I've done. The new improved output listing is here, along with the modified script.


Saturday Sep 15, 2007

Well fired up by brendan gregg's dtrace enthusiasm :) I decided to get some load image probes in today. The load URI one's I blogged about yesterday had a nice clean entry point. The image one's not so :( The problem is that I could track the start of the image load requests in imgLoader::LoadImage, but it was hard to get the matching end points. Had you gone to a cache, had you gone to the net and so on.

Image Probe Points

Thankfully biesi on mozilla's irc #developers came to the rescue and pointed me at the imgRequest object. This is only created when you have to go out and fetch the image on the net, it's not in your cache. So I had a nice start and end point to work with, namely:  imgRequest::OnStartRequest and  imgRequest::OnStopRequest.

So with probes in these three places I can now track all image load requests and see how many had to go out on the net and how many have completed, along with timings. Makes it very easy to see how much you are or are not using your cache, as snippets from a few examples below show:

Hitting or not hitting the Cache

Loading http://www.smh.com.au/ with little or no caching:

LOAD PROBE STATS:
 
Total start  loadImage's called                99
Total start  imageRequest's called         87
Total done  imageRequest's called         82
 

Loading about 20 tabs of various opensolaris and mozilla sites with lots of caching:

LOAD PROBE STATS:

 
Total start  loadImage's called              696
Total start  imageRequest's called       205
Total done  imageRequest's called       203
 

The full listing of these examples and the timings of the load times for the images is available here. Just noticed a bug in the listing I'm getting 0 Counts in the Site summary for some images even though the timings are listed, ah well it's late and tomorrows another day :) Such are the joys of software ...

[17/09 - well looks like the script is fine, but the context I'm passing in as the unique identifier is not as unique as I'd hoped, so you can get the load-done probe fired on a given context before the load-start is fired. I had hoped to have the IMAGE_LOAD and IMAGE_REQUEST share the same context but that might not be possible, off to investigate.]

Next week I plan to get these new probes into an update of the load probe patch and will put it up on the bugzilla RFE for Dynamic Tracing [#370906]


Friday Sep 14, 2007

Hi - well playing around with the DTrace Mozilla load probes for URI's and created a timing script to give us a breakdown on average and total load times for  a URI based on it's Scheme, Content Type, Username, File Extension, Host and Site. I've uploaded a sample run and the script.

This is just looking at URI's and is only looking at network activity, but it's pretty cool to see why my page loads sometimes suck from the network side of things ;) I'll need to start adding more probes to other parts of the stack to see how much time is being spent in DNS lookups, parsing, rendering, painting and so on, but it's a start :)

LoadURI       LoadImage 
   |              |
    --------------
         |
      Network --> DNS Request
         |
      Parser
         |
      Content DOM
         |
      Layout
         |
      Painting  

Thursday Sep 13, 2007

Hi - well I bloged recently about adding in load probes to firefox. In this initial cut we where just getting the URI passed back in the probe, which was a good start, but I wanted to pass in a more useful info data structure to the probe that broke down the URI into it's constituent parts, which would be a lot more useful in a dscript.

URI Structure:

<scheme>://<username>:<password>@<hostname>:<port>//<directory><basename>.<extension>;<param>?<query>#<ref>

Getting the data into the probe

Well thanks to help from biesi on mozilla #developers I was able to use the Channel being passed into the probe function to get at the URI and URL, allowing me to break down the URI into it's various parts. I then popped these pieces into a data struct and passed this back as a probe arg. So far so good. The fun started when I then tried to pull the data back out, but thankfully with a bit of help from Brendan Gregg I got it sorted. I thought others might find this useful, so here goes.

Probes:
mozilla<pid>:::load-start
mozilla<pid>:::load-done

Args:
arg0 is of type void * - its a unique_id
arg1 is an enum nsTraceLoadType - TYPE_URI or TYPE_IMAGE
arg2 is of type struct nsTraceLoadInfo * - pointer to an info data struct

struct nsTraceLoadInfo {
char * contentType;
char * spec;
char * scheme;
char * username;
char * password;
char * hostPort;
char * host;
int port;
char * path;
char * filePath;
char * fileName;
char * fileExtension;
char * param;
char * query;
char * ref;
};

enum nsTraceLoadType {
TYPE_URI = 1,
TYPE_IMAGE
};

Getting data back out in a d script

Well the trick that is needed is to use a few of our copyin friends, to be honest it was the second one that had me stumped, thanks Brendan :)

moz*:::load-start
{
this->info = (struct nsTraceLoadInfo *) copyin(arg2, sizeof (struct nsTraceLoadInfo));
printf("spec: %s\n", copyinstr((uintptr_t)this->info->spec));
printf("port: %s\n", this->info->port));
}

this->info: the arg2 is a pointer to a nsTraceLoadInfo data blob in userland that needs to be copied into the kernel for the d script to access. The copyin does just that returning a pointer to this in-kernel-memory blob, hence the need for the cast.

printf: now you can access the data in the blob no worries, as the printf of the port data shows, but what about the strings in the data struct. Well these are just char * pointers but to userland  data, that hasn't yet been copied over. So you need to do a copyinstr to get this string data into the d script. Ahh now you tell me ;)

What's my browser up to?

Well now that we can get at the broken down URI data on all the browser page loads we can have a little fun. Check out the output from a browserspy.d script Brendan put together below.

$ browserspy.d 

Tracing... Hit Ctrl-C to end.

Browser requests by scheme,

PID UID SCHEME COUNT
1578 65535 https 1
1578 65535 file 2
1578 65535 about 6
1578 65535 http 19

Browser requests by content type,

PID UID CONTENT TYPE COUNT
1578 65535 application/x-unknown-content-type 2
1578 65535 text/html 6
1578 65535 20

Browser requests by file extension,

PID UID FILE EXT COUNT
1578 65535 cgi 1
1578 65535 jspa 1
1578 65535 php 2
1578 65535 idl 3
1578 65535 html 4
1578 65535 11

Browser requests by username (if used),

PID UID USERNAME COUNT
1578 65535 22

Browser requests by host,

PID UID COUNT HOST
1578 65535 1 blogs.sun.com
1578 65535 1 bugzilla.mozilla.org
1578 65535 1 docs.sun.com
1578 65535 1 forums.suselinuxsupport.de
1578 65535 1 lists.freebsd.org
1578 65535 1 mail.opensolaris.org
1578 65535 1 www.abercornbasin.com
1578 65535 2
1578 65535 2 blog.mozilla.com
1578 65535 2 www.mozilla.org
1578 65535 2 www.opensolaris.org
1578 65535 3 lxr.mozilla.org
1578 65535 4 www.google.ie

Top 10 sites,

PID UID COUNT SITE
1578 65535 1 http://www.google.ie/search?hl=en&q=mozilla+dtrace&btnG=Search&meta=
1578 65535 1 http://www.google.ie/search?hl=en&q=mozilla+dtrace+robert&btnG=Search&meta=
1578 65535 1 http://www.google.ie/search?q=jim+grizansio+blogs+sun&hl=en&filter=0
1578 65535 1 http://www.google.ie/search?source=ig&hl=en&q=alan+xserver+provider+dtrace&btnG=Google+Search&meta=
1578 65535 1 http://www.opensolaris.org/jive/forum.jspa?forumID=7
1578 65535 1 http://www.opensolaris.org/os/project/mozilla-dtrace/;jsessionid=D2C184F6D4B2316D68920A330AC0FB4D
1578 65535 1 https://bugzilla.mozilla.org/show_bug.cgi?id=370906
1578 65535 2 file:///usr/share/doc/soldevex/html/developer_guide.html
1578 65535 2 http://blog.mozilla.com/rob-sayre/2007/09/06/land-of-dtrace/
1578 65535 2 http://www.mozilla.org/projects/firefox/3.0a8pre/releasenotes/

What's next?

Well I want add in Image load probes and then get this patch back up to bugzilla [#370906]. At the minute I know where to put the image load start, but to figure out where to put the done probes I'll need to dig into the mozilla developer's brains :) I'll also start playing with some timing scripts which should be fun as we have load-start and load-done enabled.

 





 


 

Monday Sep 03, 2007

Brendan Gregg showed me this trick to get at command line args for commands being exec'ed that are greater than the system 80 char limit. In dtrace trying to output the command args using curpsinfo->pr_psargs hits this limit.

The solution is to catch the exec calls and use the destructive dtrace stop() and system() calls to stop the process if it's hg and dump it's args using the system pargs command.

I also wanted to get the Java executing context for the Hg commands that we where executing from our Mercurial Plugin, which is written in Java. This I could do by catching the process create in dtrace. Catching the exec call and testing for hg, allowed me to ensure that I only tracked hg commands and not other exec'ed commands such as the pargs command.

Here's the one liner:

$ dtrace -x switchrate=10 -wn 'proc:::create/execname == "java"/{jstack(20,8000);} proc:::exec/basename(args[0]) == "hg"/{self->trackhg = 1;} proc:::exec-success/self->trackhg/{stop(); system("pargs %d", pid); system("prun %d", pid); self->trackhg =0;}'

You can do a similar thing using the fork and exec syscall probes if you want, though making sure you don't get into a recursive loop when you fire off the pargs command requires a little care :)

$ dtrace -x switchrate=10 -wn syscall::fork*:entry'/execname == "java"/{jstack(20,5000); isJava[pid] = 1} syscall::exec*:return/ !progenyof($pid) && isJava[ppid]/{stop(); system("pargs %d", pid); system("prun %d", pid);}'

Here we again dump the stack, but to track the correct exec's we make sure that this exec's parent is java and it's parent is not dtrace. With pargs it's parent is dtrace so this check prevents any recursion. Note: this one liner would also track other exec's from the Java program in it's current form, not just hg.  

 

I've expanded the one liner below to add timings into the script:

 

#!/usr/sbin/dtrace -ws
/*
    mercurial_plugin_hgcalls.d
    
    Trace hg calls made from Java application (NetBeans IDE), using pargs to
    get full listing of args to hg call. 
*/
#pragma D option quiet
#pragma D option switchrate=10

proc:::create
/execname == "java"/
{
    jstack(20,8000);    
}

proc:::exec
/basename(args[0]) == "hg"/
{
    self->track = 1;
    self->startexec = timestamp;
}

proc:::exec-success
/self->track/
{
    this->timeexec = timestamp - (self->startexec > 0 ? self->startexec: 0);
    self->startexec = 0;
    printf("Elasped Start Exec Time: %d msec\n", (this->timeexec)/1000000);
    @["Total Start Exec Time: (msec) "] = sum(this->timeexec);
    stop(); 
    system("pargs %d", pid); 
    system("prun %d", pid);
    self->start = timestamp;
}

proc:::exit
/self->start/
{
    this->time = timestamp - self->start;
    printf("Elasped Hg Cmd Time: %d msec\n", (this->time)/1000000);
    @["Total Hg Cmd Time: (msec) "] = sum(this->time);
    self->startexec = 0;
    self->track = 0;
    self->start = 0;
}

proc:::exec-failure
/self->track/
{
    printf("Hg Command failed: errno: %d \n", args[0]);
    self->startexec = 0;
    self->track = 0;
    self->start = 0;
}

END
{
    normalize(@, 1000000);
}

 




 

Friday Aug 31, 2007

Hi - having fun at the minute with an onsite workshop on DTrace with the Mozilla folks in Menlo Park. Brendan Gregg treated us to a bunch of live DTrace demos that really showed how you can get that system wide view across the stack that is impossible with conventional tools :) Now if we could just clone Brendan that would be ideal. The real learning comes from doing and just watching how Brendan formulates questions then explores the problem with dtrace, doing some quick profiling, identifying areas of interest, dumping ustacks, grabbing functions, checking timings and so on. The syntax is easy, the mind set is a lot tougher to capture.

The reason we are over with Mozilla having the workshop in the first place is to help work on the DTrace Tracing framework in Mozilla, which should really help the community identify and fix performance issues in Mozilla, be it in the Javascript XUL layer, the C++ layer or in some dependent platform or system lib.

Having a framework is pretty cool, but not much use if you have no useful probes built on top of it. Brendan has created Javascript probes which hopefully will help dig into a lot of performance issues in this layer. In addition to the Javascript probes we want to add some C++ probes to track things like page loading.

With Johnny Steinbeck's help, Brendan and crew added loadURI_start / done probes.

Here's a quick brain dump of what we needed to do to add them. I'll blog later when we start using them to do some interesting timing analysis.

 

Using new Load URI Probes

$dtrace -nl mozilla*::mozdtrace_load_uri_start:load_uri_start

$ dtrace -ln "moz*:::"
   ID   PROVIDER            MODULE                          FUNCTION NAME
71986 mozilla18214         libxul.so          mozdtrace_load_uri_start load-uri-start
71987 mozilla18214         libxul.so          mozdtrace_load_uri_done load-uri-done

$ dtrace -qn moz*:::'{printf("%s\n",copyinstr(arg0));}'
http://www.mozilla.org/


Adding Load URI Probes

mozilla/mozilla-dtrace.d

Add the new dtrace probes:

/*
 * load__uri__start        (char * uri)
 * load__uri__done        (char * uri)
*/

provider mozilla {
    :
 probe load__uri__start(char * );
 probe load__uri__done(char * );
    :
};

mozilla/toolkit/library/Makefile.in

Add probe lib to MOZILLA_PROBE_LIBS:

ifdef HAVE_DTRACE
ifdef MOZ_ENABLE_LIBXUL
NEED_DTRACE_PROBE_OBJ = mozilla-dtrace.$(OBJ_SUFFIX)
MOZILLA_PROBE_LIBS = $(DEPTH)/staticlib/components/$(LIB_PREFIX)docshell.$(LIB_SUFFIX)
MOZILLA_DTRACE_SRC = $(DEPTH)/mozilla-trace.d
endif
endif
    :
include $(topsrcdir)/config/rules.mk

Note: Adding probe lib to MOZILLA_PROBE_LIBS here so object file with probe can be post processed by dtrace -G
Processing step pulled in to the make from mozilla/config/rules.mk

ifdef HAVE_DTRACE
ifdef DTRACE_PROBE_OBJ
$(DTRACE_PROBE_OBJ): $(OBJS)
    dtrace -G -C -32 -s $(MOZILLA_DTRACE_SRC) -o $(DTRACE_PROBE_OBJ) $(OBJS)
endif
endif

-G: tells dtrace to process the list of .o's looking for USDT probes, change
their status to IGNORE and generate a special <probe>.o that you should link
against so the kernel linker can correctly initialize things when the shared
lib is loaded.
-C: use the C preprocessor to process the specified .d file, allows you to have
#includes
-32: compile for 32 bit architecture, we need to change this so it
will work on 64 bit arch as well
-s: source of probes, mozilla-trace.d in this instance
-o: output special <probe>.o file, call it anything you want, just need to link
against it.

mozilla/docshell/build/Makefile.in

Note: If building debug, components of XUL shared lib are not linked into it, so need to add probe libs below.

EXTRA_DSO_LDOPTS= \
        $(LIBS_DIR) \
        $(EXTRA_DSO_LIBS) \
        $(MOZ_JS_LIBS) \
        $(MOZ_UNICHARUTIL_LIBS) \
        $(MOZ_COMPONENT_LIBS) \
        $(NULL)

ifdef HAVE_DTRACE
ifndef MOZ_ENABLE_LIBXUL
NEED_DTRACE_PROBE_OBJ = mozilla-dtrace.$(OBJ_SUFFIX)
MOZILLA_PROBE_LIBS = ../base/$(LIB_PREFIX)docshell.$(LIB_SUFFIX)
MOZILLA_DTRACE_SRC = $(DEPTH)/mozilla-trace.d
endif
endif

include $(topsrcdir)/config/rules.mk

LOCAL_INCLUDES    = \
        -I$(srcdir) \
    :

mozilla/docshell/base/nsDocShell.h

Add wrapper functions for the probes to give sensible function names, otherwise get mangled C++ enclosing function names :(

#ifdef INCLUDE_MOZILLA_DTRACE
#include "mozilla-trace.h"

extern "C" {
void mozdtrace_load_uri_start(nsIURI * aURI);
void mozdtrace_load_uri_done(nsIChannel * aChannel);
}
#endif /* INCLUDE_MOZILLA_DTRACE */

#ifdef INCLUDE_MOZILLA_DTRACE
#define TRACE_MOZILLA_LOAD_URI_START_POINT(uri_) \
  mozdtrace_load_uri_start((uri_))
#define TRACE_MOZILLA_LOAD_URI_DONE_POINT(uri_) \
  mozdtrace_load_uri_done((uri_))

#else
#define TRACE_MOZILLA_LOAD_URI_START_POINT(uri_) \
  PR_BEGIN_MACRO PR_END_MACRO
#define TRACE_MOZILLA_LOAD_URI_DONE_POINT(uri_) \
  PR_BEGIN_MACRO PR_END_MACRO

#endif /* INCLUDE_MOZILLA_DTRACE */


Note: Tried putting MOZILLA_LOAD_URI_START_ENABLED() around wrapper func, mozdtrace_load_uri_start, but get two func probes
if we do this.
6202 mozilla23090         libxul.so             __1cKnsDocShellJDoURILoad6MpnGnsIURI_2ipnLnsISupports_pkcpnOnsIInputStream_8ippnLnsIDocShell_ppnKnsIRequest_i_I_ load-uri-start
6203 mozilla23090         libxul.so             mozdtrace_load_uri_start load-uri-start

mozilla/docshell/base/nsDocShell.cpp

Define wrapper probe functions and add custom probe macros to load URI start and end points.

#include "mozilla-trace.h"
    :

// Implementation of probe func wrapper
#ifdef INCLUDE_MOZILLA_DTRACE
void mozdtrace_load_uri_start(nsIURI * aURI)
{
    if (MOZILLA_LOAD_URI_START_ENABLED()) { 
        nsCAutoString spec;
        aURI->GetASCIISpec(spec);

        MOZILLA_LOAD_URI_START((char *)spec.get());
    }
}

void mozdtrace_load_uri_done(nsIChannel * aChannel)
{
   /* XXX DTrace load-uri-done */
    if (MOZILLA_LOAD_URI_DONE_ENABLED()) {
       nsCOMPtr<nsIURI> uri;
       nsCAutoString spec;
       aChannel->GetURI(getter_AddRefs(uri));

       uri->GetASCIISpec(spec);
       MOZILLA_LOAD_URI_DONE((char *)spec.get());
    }
}
#endif

    :

nsresult
nsDocShell::DoURILoad(nsIURI * aURI, ....)
    :

     /* DTrace URI probe */
    TRACE_MOZILLA_LOAD_URI_START_POINT(aURI);

    rv = DoChannelLoad(channel, uriLoader);
    :   
}

nsresult
nsDocShell::EndPageLoad(nsIWebProgress * aProgress,
                        nsIChannel * aChannel, nsresult aStatus)
{
    :
    nsCOMPtr<nsIDocShell> kungFuDeathGrip(this);
    :
// NOTE: if this is moved to the top of the function then we get two USDT probes instead of one:
// mozilla7863         libxul.so __1cKnsDocShellLEndPageLoad6MpnOnsIWebProgress_pnKnsIChannel_I_I_ load-uri-done
// mozilla7863         libxul.so           mozdtrace_load_uri_done load-uri-done
    TRACE_MOZILLA_LOAD_URI_DONE_POINT(aChannel);

DTrace request for enhancement:

Allow an optional function name to be specified in probe description:

provider mozilla {
    :
 probe mozdtrace_load_uri_start:load__uri__start(char * );
 probe mozdtrace_load_uri_done:load__uri__done(char * );
}
 

This would be so handy when putting USDT probes into C++ code. No need for the wrapper funcs we are using above :) 

 


 

Tuesday Jun 26, 2007

Hi - just thought folks might be interested. Got the latest NetBeans 6.0 building from head which has the CND C/C++ support included and ran it using the Mercurial Plugin against a simple Mercurial Hello world project that was already under Mercurial control.

The good news is that it actually comes up and things seem to work, well kinda (check out the status window below). Now if you click on the .hg directory in the Projects window all hell breaks lose, but then no ones perfect ;) We'll work on this over the next few weeks or so to flush out the issues, but so far so good.

 Mercurial and C/C++ support