Tuesday Mar 31, 2009

PackageManager getting Flash

How can I get Flash for OpenSolaris?

Well if you are running one of the latest development builds for OpenSolaris which will be released as OpenSolaris 2009.06 and you'd like to get Flash on your system I thought I'd give you a little Package Manager Web Install help :)


Web Install and Flash

Just follow the steps below to add the extra repository and install the Flash plugin. As extra is a secure repository which requires registration, the repository can't be added automatically using Web Install, unlike other non secure repositories.

Steps

  • Click on extra_flash.p5i, and accept the default action to "Open with" Package Manager.
  • Package Manager in WebInstall mode is launched, click on Proceed
    • This brings up the Add New Repository dialog for a the secure extra repository.
  • Click on the Instructions link in the dialog
    • This will bring you to the registration site, where you need to register and get your SSL key and certificates to access the repository.
    • Currently the site gives you instructions to download the keys and then use the command line to add the authority. With Web Install, just download the key and certificate to your system and follow the steps below. 

  • In Add New Repository dialog, click on the SSL Key Browse button
    • Select the key you have just downloaded on your file system (the location of the certificate is assumed to be in the same place and is added for you).
    • As Package Manager runs as root, you will need to browse to your home directory or wherever you downloaded the key and certificate.
  • Click OK, the extra repository will be added and then the Flash package installed.

Enjoy

  • Restart Firefox and check the installed version by clicking on Adobe's version checker.
  • Have fun with Flash :)


Thursday Mar 26, 2009

PackageManager for 2009.06

Package Manger What's Up for 2009.06

Well we have been busy over the past 6 months since the 2008.11 release and have added plenty of goodies. Michal has blogged about new performance improvements and Padraig's addition which gives you the ability to search across all repositories. I am going to discuss the new Start Page and WebInstall.

Start Page

So on startup, which is way faster now thanks to Michal's new caching support, you will see a Start Page instead of the list of packages. Just clicking on any category puts you into the list view and going to Help-> StartPage brings you back to the Start Page.

The Start Page gives us a way to point you at useful online resources, to find the latest packages, help and support. Just click on links in the Start Page to launch the page in Firefox. The Start Page is also something that can be updated and the system will check for updates daily as its refreshing the IPS Image catalog on the system, falling back to the default installed page if no updates are available. So say for instance when an interesting new repository is available we could point you to it from here.

Wouldn't it be nice if as well as pointing to this new repository, we were able to just have  a link on the Start Page for you to click on and have the new repository installed for you? Well that leads nicely onto Web Install.

Web Install

This is a new mode that Package Manager can be launched in to process a new mime type, namely application/vnd.pkg5.info. This mime type is bound to any .p5i file on you system or on any web page whose web server supports this mime type. All of the OpenSolaris websites will have this support added.

On an apache server its just a one line addition to the configuration file:

/etc/apache2/2.2/mime.types
   application/vnd.pkg5.info       p5i

So what's in this .p5i file? Well it contains the details of any repository you want to add and optionally any packages from this repository. Here's a sample one for installing a few packages from opensoalris.org, sunfreeware and contrib, test.p5i. When you click on the file in Nautilus on your desktop or click on it in a web page on a server with this mime type registered, the above dialog is launched, listing the new repositories that will be added (repositories are not listed if already on your system) and any packages that are to be installed.

Once you click to proceed, the repositories are automatically added, then the packages are added, using the normal install process for Package Manager. Note if its a secure repository, you are first presented with a dialog to enter its SSL key and cert, before continuing with the package installs.

Going Forward

Now the contents of the .p5i file are in JSON format for easy processing, but may take a little getting used to if you want to hand edit them :) We plan to add another feature to Package Manager which will allow you to save any selections you make in Package Manager as a .p5i file that others can use to both add the repository they come from and install the selected packages.

Shawn Walker whose IPS Publisher API made this all possible will be adding the auto creation of .p5i files to his OpenSolaris Web Search interface at some stage as well. No doubt .p5i files will start popping up all over the place in OpenSolaris land. We will certainly be adding them to the Package Repository page to make it a simple one click to add useful repositories.

We also plan to add auto discovery feature for new repository publishers, whereby repository managers can list related url's of other repositories that might be of interest to a user. Using the Update Manager Notifier process we will check for these updates and give users the option to add them, again using the Web Install. This will not make it into 2009.06, have to save a few things for the next release :)



Monday Nov 26, 2007

Python: Debugging with JEdit and JPyDebug on OpenSolaris

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

DTrace - IE-OSUG The scary world of Gnome System Monitor

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

DTrace Mozilla - [RFE] JavaScript Tracing Framework landed :)

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

DTrace Mozilla - [RFE] Dynamic Tracing Framework for Mozilla landed :)

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

DTrace Mozilla - DNS timing mystery solved :)

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

DTrace Mozilla - new patch for DNS Lookup probes

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

DTrace Mozilla - what's going on with my DNS

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

DTrace Mozilla - patch available and URI/Image timings combined

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!!

 

DTrace Mozilla - some trunc weirdness with image timings

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.


Friday Sep 14, 2007

DTrace Mozilla - some browser image timings

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]


DTrace Mozilla - some browser network timings

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

DTrace Mozilla - load probes 2 or what's my browser up to?

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

DTrace: digging into exec'd comand line args

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);
}

 




 

About

jmr

Search

Top Tags
Categories
Archives
« July 2014
MonTueWedThuFriSatSun
 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
   
       
Today