In my last blog post I expressed frustation with slowness induced by library IO. Then I went on a mission to measure it. I have been wanting to this for a while, but I figured that only DTrace can get this info without recompiling my kernel. So I tried to build Mozilla under Slowlaris (but the linker got up to 3GB and then set there swapping, ensuring that the nickname is justified). Then I fired up DTrace on the mini, but ran screaming because it seemed like fbt DTrace provider refused to let me dereference structs (later Joel told me that I’m supposed to copy data explicitly like here).
But while googling for a fbt workaround, I stumbled upon a DTrace/SystemTap comparision wiki. SystemTap? The DTrace knockoff I have been hearing about? It works? This was a lightbulb moment where I realized that Linux was about to provide me with more information than I thought was possible.
So here is the data I got out of it:
Writing scripts in systemtap felt really natural after I figured out that pointers are to be dereferenced as arrays and what some of the error messages really meant. In the script I watch vfs_read() for io done via read() syscall, but it turns out that mmap() io actually happens via readahead. Here is the systemtap script. I believe I accounted for all io. ext4_get_block (which seems to be the main function ext4 reads file data with) did not spend any time outside of that called by the functions I was tapping into.
I haven’t had much time to draw too many conclusions out of the data, posting it as an example of systemtap use. libxul accounts for most io both in terms of bytes and time spent. We’ll be fixing that, not yet sure as to what strategy to employ for the rest of the libraries.
SELECT file, sum(size) as bytesread, sum(time)/1000 as ms from startup group by file order by bytesread desc ;
file | bytesread | ms -------------------------------------------------------------------------+-----------+----- /home/taras/firefox/libxul.so/ | 19530240 | 103 /usr/lib/libgtk-x11-2.0.so.0.1800.2/ | 3277312 | 15 /home/taras/firefox/chrome/toolkit.jar/ | 2097152 | 8 /home/taras/firefox/libmozjs.so/ | 1835520 | 36 /home/taras/.mozilla/firefox/imph4tsg.default/XPC.mfasl/ | 1671168 | 3 /home/taras/firefox/chrome/browser.jar/ | 1572864 | 5 /usr/share/icons/gnome/icon-theme.cache/ | 1441792 | 7 /home/taras/firefox/libnss3.so/ | 1311232 | 18 /usr/lib/libX11.so.6.3.0/ | 1049088 | 5 /home/taras/.mozilla/firefox/imph4tsg.default/XUL.mfasl/ | 995328 | 2 /usr/lib/libgnomeui-2.so.0.2400.1/ | 918016 | 3 /usr/lib/libfreetype.so.6.3.20/ | 786944 | 3 /home/taras/firefox/libsqlite3.so/ | 655872 | 10 /usr/lib/libgconf-2.so.4.1.5/ | 655872 | 1 /usr/lib/libbonoboui-2.so.0.0.0/ | 655872 | 2 /usr/lib/libgdk-x11-2.0.so.0.1800.2/ | 655872 | 2 /usr/lib/libcrypto.so.1.0.0/ | 655872 | 2 /home/taras/firefox/chrome/en-US.jar/ | 655360 | 2 /usr/lib/libORBit-2.so.0.1.0/ | 524800 | 2 /lib/libasound.so.2.0.0/ | 524800 | 18 /home/taras/firefox/libnspr4.so/ | 524800 | 17 /usr/lib/libxml2.so.2.7.5/ | 524800 | 1 /usr/lib/libbonobo-activation.so.4.0.0/ | 524800 | 1 /usr/lib/libgnomecanvas-2.so.0.2600.0/ | 524800 | 1 /usr/lib/libXt.so.6.0.0/ | 524800 | 14 /lib/libgssapi_krb5.so.2.2/ | 524800 | 1 /usr/lib/libatk-1.0.so.0.2809.1/ | 524800 | 2 /home/taras/firefox/libnssckbi.so/ | 524800 | 6 /usr/lib/libbonobo-2.so.0.0.0/ | 524800 | 1 /usr/lib/libgnomevfs-2.so.0.2400.2/ | 524800 | 2 /home/taras/firefox/libsmime3.so/ | 393728 | 15 /usr/lib/libart_lgpl_2.so.2.3.20/ | 393728 | 1 /usr/lib/libvorbis.so.0.4.3/ | 393728 | 1 /home/taras/firefox/components/libbrowsercomps.so/ | 393728 | 12 /lib/libresolv-2.10.90.so/ | 393728 | 0 /home/taras/firefox/libnssdbm3.so/ | 393728 | 15 /home/taras/firefox/libfreebl3.so/ | 393728 | 13 /home/taras/firefox/libssl3.so/ | 393728 | 8 /usr/lib/libssl.so.1.0.0/ | 393728 | 1 /lib/libkrb5.so.3.3/ | 393728 | 24 /lib/libglib-2.0.so.0.2200.2/ | 393728 | 1 /usr/share/fonts/dejavu/DejaVuSans.ttf/ | 393216 | 1 /home/taras/firefox/components/browser.xpt/ | 378141 | 6 /usr/lib/gtk-2.0/2.10.0/engines/libclearlooks.so/ | 262656 | 1 /lib/libexpat.so.1.5.2/ | 262656 | 1 /usr/lib/libfontconfig.so.1.4.3/ | 262656 | 0 /home/taras/firefox/components/libimgicon.so/ | 262656 | 1 /lib/libkeyutils-1.2.so/ | 262656 | 0 /usr/lib/libgnome-keyring.so.0.1.1/ | 262656 | 1 /usr/lib/libgnome-2.so.0.2800.0/ | 262656 | 0 /usr/lib/libXau.so.6.0.0/ | 262656 | 0 /usr/lib/libXinerama.so.1.0.0/ | 262656 | 0 /usr/lib/libXdamage.so.1.1.0/ | 262656 | 0 /usr/lib/libXcomposite.so.1.0.0/ | 262656 | 0 /usr/lib/libfam.so.0.0.0/ | 262656 | 22 /home/taras/firefox/components/libdbusservice.so/ | 262656 | 12 /home/taras/firefox/components/libmozgnome.so/ | 262656 | 11 /usr/lib/libICE.so.6.3.0/ | 262656 | 1 /home/taras/firefox/libnssutil3.so/ | 262656 | 22 /usr/lib/libpangoft2-1.0.so.0.2600.0/ | 262656 | 0 /lib/libk5crypto.so.3.1/ | 262656 | 1 /home/taras/firefox/components/libbrowserdirprovider.so/ | 262656 | 9 /home/taras/firefox/libsoftokn3.so/ | 262656 | 10 /usr/lib/libxcb.so.1.1.0/ | 262656 | 1 /home/taras/firefox/components/libnkgnomevfs.so/ | 262656 | 14 /home/taras/firefox/firefox-bin/ | 262547 | 13 /usr/share/fonts/dejavu/DejaVuSerif.ttf/ | 262144 | 0 /home/taras/.mozilla/firefox/imph4tsg.default/compreg.dat/ | 147563 | 0 /usr/share/X11/locale/locale.alias/ | 134322 | 18 /lib/libc-2.10.90.so/ | 132608 | 1 /lib/libtinfo.so.5.7/ | 132096 | 0 /usr/lib/gio/modules/libgioremote-volume-monitor.so/ | 131584 | 0 /lib/libuuid.so.1.3.0/ | 131584 | 0 /usr/lib/libvorbisfile.so.3.3.2/ | 131584 | 0 /lib/libkrb5support.so.0.1/ | 131584 | 0 /usr/lib/libgvfscommon.so.0.0.0/ | 131584 | 0 /lib/librt-2.10.90.so/ | 131584 | 0 /usr/lib/libavahi-common.so.3.5.1/ | 131584 | 0 /usr/lib/libnotify.so.1.1.3/ | 131584 | 0 /usr/lib/libavahi-glib.so.1.0.1/ | 131584 | 0 /usr/lib/gio/modules/libgvfsdbus.so/ | 131584 | 0 /usr/lib/libXcursor.so.1.0.2/ | 131584 | 0 /usr/lib/libXi.so.6.1.0/ | 131584 | 3 /usr/lib/libgailutil.so.18.0.1/ | 131584 | 0 /usr/lib/libXrender.so.1.3.0/ | 131584 | 0 /lib/libcap-ng.so.0.0.0/ | 131584 | 0 /usr/lib/libSM.so.6.0.0/ | 131584 | 0 /lib/libudev.so.0.4.2/ | 131584 | 0 /lib/libgmodule-2.0.so.0.2200.2/ | 131584 | 0 /usr/lib/libXfixes.so.3.1.0/ | 131584 | 0 /lib/libgobject-2.0.so.0.2200.2/ | 131584 | 0 /usr/lib/libXrandr.so.2.2.0/ | 131584 | 1 /lib/libgio-2.0.so.0.2200.2/ | 131584 | 1 /lib/libpopt.so.0.0.0/ | 131584 | 0 /lib/libz.so.1.2.3/ | 131584 | 0 /usr/lib/libXext.so.6.4.0/ | 131584 | 0 /usr/lib/libpangocairo-1.0.so.0.2600.0/ | 131584 | 0 /usr/lib/libogg.so.0.6.0/ | 131584 | 0 /usr/lib/libcairo.so.2.10800.8/ | 131584 | 0 /usr/lib/libavahi-client.so.3.2.5/ | 131584 | 1 /usr/lib/libtdb.so.1.1.5/ | 131584 | 0 /usr/lib/libORBitCosNaming-2.so.0.1.0/ | 131584 | 0 /usr/lib/libstdc++.so.6.0.13/ | 131584 | 1 /lib/libgthread-2.0.so.0.2200.2/ | 131584 | 0 /lib/libgcc_s-4.4.1-20091008.so.1/ | 131584 | 0 /lib/libdbus-1.so.3.4.0/ | 131584 | 0 /usr/lib/libcanberra-gtk.so.0.1.4/ | 131584 | 0 /usr/lib/libpango-1.0.so.0.2600.0/ | 131584 | 0 /usr/lib/libpng12.so.0.39.0/ | 131584 | 0 /usr/lib/libltdl.so.7.2.0/ | 131584 | 0 /usr/lib/gtk-2.0/modules/libcanberra-gtk-module.so/ | 131584 | 0 /lib/libnss_files-2.10.90.so/ | 131584 | 0 /lib/libcom_err.so.2.1/ | 131584 | 0 /usr/lib/libcanberra.so.0.2.1/ | 131584 | 0 /usr/lib/libdbus-glib-1.so.2.1.0/ | 131584 | 0 /usr/lib/gtk-2.0/modules/libpk-gtk-module.so/ | 131584 | 0 /usr/lib/libpixman-1.so.0.16.2/ | 131584 | 0 /usr/lib/libgdk_pixbuf-2.0.so.0.1800.2/ | 131584 | 0 /home/taras/.fontconfig/3830d5c3ddfd5cd38a049b759396e72e-x86.cache-2/ | 131072 | 0 /usr/lib/gconv/gconv-modules.cache/ | 131072 | 0 /home/taras/.mozilla/firefox/imph4tsg.default/xpti.dat/ | 101060 | 14 /home/taras/firefox/greprefs.js/ | 74132 | 12 /home/taras/.mozilla/firefox/imph4tsg.default/urlclassifier3.sqlite/ | 65832 | 85 /home/taras/.mozilla/firefox/imph4tsg.default/places.sqlite/ | 53396 | 43 /home/taras/firefox/defaults/pref/firefox.js/ | 40803 | 17 /usr/lib/gio/modules/libgiofam.so/ | 33280 | 13 /usr/lib/gio/modules/libgiogconf.so/ | 33280 | 13 /home/taras/firefox/libxpcom.so/ | 33280 | 13 /usr/lib/gconv/UTF-16.so/ | 33280 | 16 /usr/lib/libXss.so.1.0.0/ | 33280 | 14 /home/taras/firefox/libplc4.so/ | 33280 | 5 /home/taras/firefox/libplds4.so/ | 33280 | 0 /usr/share/X11/locale/locale.dir/ | 32768 | 16 /home/taras/firefox/run-mozilla.sh/ | 27368 | 12 /usr/share/icons/hicolor/index.theme/ | 24293 | 25 /home/taras/firefox/chrome/icons/default/default48.png/ | 22164 | 1 /home/taras/.mozilla/firefox/imph4tsg.default/cert8.db/ | 16644 | 13 /usr/share/icons/gnome/index.theme/ | 12657 | 41 /home/taras/firefox/chrome/icons/default/default32.png/ | 11964 | 1 /home/taras/.mozilla/firefox/imph4tsg.default/search.json/ | 11392 | 14 /usr/share/themes/Clearlooks/gtk-2.0/gtkrc/ | 11287 | 18 /etc/fonts/conf.avail/65-fonts-persian.conf/ | 9880 | 1 /dev/urandom/ | 8468 | 4 /home/taras/.mozilla/firefox/imph4tsg.default/secmod.db/ | 8452 | 1 /usr/share/icons/Bluecurve/cursors/xterm/ | 8192 | 12 /usr/share/icons/Bluecurve/cursors/bottom_right_corner/ | 8192 | 7 /etc/fonts/conf.avail/65-nonlatin.conf/ | 7706 | 0 /home/taras/firefox/firefox/ | 7695 | 0 /etc/fonts/fonts.conf/ | 5325 | 17 /usr/share/locale/locale.alias/ | 5024 | 8 /usr/share/icons/Mist/index.theme/ | 4771 | 7 /home/taras/.mozilla/firefox/imph4tsg.default/key3.db/ | 4356 | 1 /home/taras/firefox/chrome/icons/default/default16.png/ | 4332 | 21 /usr/share/X11/locale/en_US.UTF-8/XLC_LOCALE/ | 4287 | 12 /proc/meminfo/ | 4096 | 0 /etc/fonts/conf.avail/30-metric-aliases.conf/ | 3939 | 0 /etc/passwd/ | 3766 | 0 /etc/gtk-2.0/i386-redhat-linux-gnu/gdk-pixbuf.loaders/ | 3618 | 16 /etc/pango/i386-redhat-linux-gnu/pango.modules/ | 3452 | 16 /home/taras/.mozilla/firefox/imph4tsg.default/content-prefs.sqlite/ | 3252 | 8 /etc/fonts/conf.avail/25-unhint-nonlatin.conf/ | 2941 | 12 /etc/localtime/ | 2899 | 0 /home/taras/.mozilla/firefox/imph4tsg.default/permissions.sqlite/ | 2228 | 3 /home/taras/.mozilla/firefox/imph4tsg.default/cookies.sqlite/ | 2212 | 15 /home/taras/firefox/application.ini/ | 2128 | 18 /etc/fonts/conf.avail/40-nonlatin.conf/ | 2069 | 0 /usr/share/fontconfig/conf.avail/57-dejavu-sans.conf/ | 2011 | 0 /etc/fonts/conf.avail/45-latin.conf/ | 1837 | 0 /home/taras/.mozilla/firefox/imph4tsg.default/prefs.js/ | 1827 | 29 /etc/nsswitch.conf/ | 1734 | 20 /etc/fonts/conf.avail/60-latin.conf/ | 1701 | 0 /etc/fonts/conf.avail/90-synthetic.conf/ | 1691 | 6 /usr/share/fontconfig/conf.avail/57-dejavu-serif.conf/ | 1649 | 0 /lib/libdl-2.10.90.so/ | 1536 | 0 /usr/share/fontconfig/conf.avail/57-dejavu-sans-mono.conf/ | 1509 | 1 /home/taras/firefox/chrome/toolkit.manifest/ | 1418 | 8 /usr/share/fontconfig/conf.avail/65-google-droid-sans.conf/ | 1403 | 0 /home/taras/firefox/chrome/en-US.manifest/ | 1251 | 0 /usr/share/fontconfig/conf.avail/25-ttf-arphic-uming-bitmaps.conf/ | 1221 | 10 /home/taras/firefox/defaults/pref/firefox-branding.js/ | 1186 | 11 /etc/fonts/conf.avail/30-urw-aliases.conf/ | 1164 | 0 /etc/fonts/conf.d/25-no-bitmap-fedora.conf/ | 1160 | 0 /etc/fonts/conf.avail/20-unhint-small-vera.conf/ | 1157 | 0 /home/taras/.mozilla/firefox/imph4tsg.default/formhistory.sqlite/ | 1156 | 14 /usr/share/icons/Fedora/index.theme/ | 1128 | 32 /usr/share/fontconfig/conf.avail/90-smc-fonts.conf/ | 1094 | 15 /usr/share/fontconfig/conf.avail/41-ttf-arphic-uming.conf/ | 1043 | 0 /home/taras/firefox/chrome/browser.manifest/ | 963 | 0 /usr/share/fontconfig/conf.avail/64-ttf-arphic-uming.conf/ | 951 | 0 /etc/fonts/conf.avail/20-fix-globaladvance.conf/ | 912 | 0 /usr/share/fontconfig/conf.avail/20-unhint-small-dejavu-sans-mono.conf/ | 866 | 20 /home/taras/startup.html/ | 864 | 17 /usr/share/fontconfig/conf.avail/20-unhint-small-dejavu-serif.conf/ | 858 | 0 /usr/share/fontconfig/conf.avail/20-unhint-small-dejavu-sans.conf/ | 856 | 0 /home/taras/.mozilla/firefox/imph4tsg.default/localstore.rdf/ | 850 | 11 /home/taras/.mozilla/firefox/imph4tsg.default/sessionstore.js/ | 762 | 13 /usr/share/fontconfig/conf.avail/65-ipa-pgothic.conf/ | 705 | 8 /lib/ld-2.10.90.so/ | 704 | 0 /etc/fonts/conf.avail/69-unifont.conf/ | 672 | 0 /usr/share/fontconfig/conf.avail/75-ttf-arphic-ukai-select.conf/ | 611 | 22 /etc/gtk-2.0/i386-redhat-linux-gnu/gtk.immodules/ | 598 | 11 /etc/fonts/conf.avail/49-sansserif.conf/ | 545 | 0 /usr/share/fontconfig/conf.avail/90-ttf-arphic-uming-embolden.conf/ | 541 | 14 /usr/share/fontconfig/conf.avail/90-ttf-arphic-ukai-embolden.conf/ | 540 | 0 /lib/libselinux.so.1/ | 512 | 0 /lib/libpthread-2.10.90.so/ | 512 | 0 /lib/libutil-2.10.90.so/ | 512 | 0 /lib/libm-2.10.90.so/ | 512 | 0 /usr/share/fontconfig/conf.avail/66-lohit-kashmiri@devanagari.conf/ | 488 | 0 /usr/share/fontconfig/conf.avail/66-lohit-sindhi@devanagari.conf/ | 484 | 0 /usr/share/fontconfig/conf.avail/66-lohit-maithili.conf/ | 478 | 3 /usr/share/fontconfig/conf.avail/66-lohit-assamese.conf/ | 477 | 18 /usr/share/fontconfig/conf.avail/66-lohit-gujarati.conf/ | 477 | 9 /usr/share/fontconfig/conf.avail/66-lohit-konkani.conf/ | 476 | 14 /usr/share/fontconfig/conf.avail/66-lohit-bengali.conf/ | 475 | 15 /usr/share/fontconfig/conf.avail/66-lohit-marathi.conf/ | 475 | 7 /usr/share/fontconfig/conf.avail/66-lohit-kannada.conf/ | 475 | 0 /usr/share/fontconfig/conf.avail/66-lohit-punjabi.conf/ | 475 | 0 /proc/cpuinfo/ | 474 | 0 /usr/share/fontconfig/conf.avail/67-lohit-nepali.conf/ | 473 | 0 /usr/share/fontconfig/conf.avail/66-lohit-telugu.conf/ | 473 | 1 /usr/share/fontconfig/conf.avail/66-lohit-tamil.conf/ | 471 | 0 /usr/share/fontconfig/conf.avail/66-lohit-hindi.conf/ | 471 | 0 /usr/share/fontconfig/conf.avail/66-lohit-oriya.conf/ | 471 | 0 /bin/bash/ | 403 | 0 /usr/share/fontconfig/conf.avail/41-ttf-arphic-ukai.conf/ | 400 | 0 /etc/gnome-vfs-2.0/modules/default-modules.conf/ | 399 | 6 /etc/fonts/conf.avail/80-delicious.conf/ | 388 | 1 /usr/share/fontconfig/conf.avail/25-ttf-arphic-uming-render.conf/ | 362 | 0 /usr/share/fontconfig/conf.avail/25-ttf-arphic-ukai-render.conf/ | 361 | 18 /usr/share/fontconfig/conf.avail/35-ttf-arphic-uming-aliases.conf/ | 353 | 0 /usr/share/fontconfig/conf.avail/60-google-droid-sans-mono.conf/ | 345 | 16 /usr/share/fontconfig/conf.avail/35-ttf-arphic-ukai-aliases.conf/ | 343 | 1 /usr/share/fontconfig/conf.avail/61-stix.conf/ | 332 | 10 /usr/share/fontconfig/conf.avail/59-google-droid-serif.conf/ | 329 | 4 /home/taras/firefox/defaults/pref/firefox-l10n.js/ | 257 | 9 /etc/fonts/conf.avail/50-user.conf/ | 245 | 0 /home/taras/firefox/defaults/pref/reporter.js/ | 205 | 16 /etc/fonts/conf.avail/51-local.conf/ | 189 | 0 /var/cache/fontconfig/0251a5afa6ac727a1e32b7d4d4aa7cf0-x86.cache-2/ | 160 | 15 /home/taras/.mozilla/firefox/imph4tsg.default/compatibility.ini/ | 159 | 15 /home/taras/.mozilla/firefox/imph4tsg.default/urlclassifierkey3.txt/ | 154 | 13 /etc/hosts/ | 147 | 13 /home/taras/firefox/defaults/pref/channel-prefs.js/ | 143 | 0 /etc/resolv.conf/ | 134 | 10 /home/taras/firefox/platform.ini/ | 132 | 7 /usr/share/gvfs/remote-volume-monitors/hal.monitor/ | 123 | 0 /usr/share/gvfs/remote-volume-monitors/gdu.monitor/ | 123 | 7 /usr/share/gvfs/remote-volume-monitors/gphoto2.monitor/ | 115 | 32 /home/taras/.mozilla/firefox/imph4tsg.default/extensions.ini/ | 112 | 12 /home/taras/.mozilla/firefox/imph4tsg.default/extensions.cache/ | 106 | 14 /etc/gtk-2.0/gtkrc/ | 97 | 20 /home/taras/.mozilla/firefox/profiles.ini/ | 94 | 21 /usr/share/themes/Default/gtk-2.0-key/gtkrc/ | 82 | 20 /home/taras/firefox/chrome/pippki.manifest/ | 69 | 0 /home/taras/firefox/browserconfig.properties/ | 68 | 37 /home/taras/.Xauthority/ | 52 | 13 /var/lib/dbus/machine-id/ | 33 | 13 /etc/host.conf/ | 26 | 13 /etc/gnome-vfs-2.0/modules/ssl-modules.conf/ | 12 | 1 /home/taras/.mozilla/firefox/Crash Reports/InstallTime20091022031207/ | 10 | 22 /home/taras/.mozilla/firefox/Crash Reports/LastCrash/ | 10 | 1 /home/taras/.mozilla/firefox/imph4tsg.default/cookies.sqlite-journal/ | 5 | 1 (263 rows)
I see some of the deprecated gnome libraries near the top of the list, mainly gnomeui and bonoboui, those are dragging in quite a lot of other libraries.
That may be another reason to get rid of those.
Holy crap SystemTap is awesome; thanks for mentioning this