Canonical Voices

Posts tagged with 'debug'

pitti

The current default D-BUS configuration (at least on Ubuntu) disallows monitoring method calls on the system D-BUS (dbus-monitor --system), which makes debugging rather cumbersome; this has worked years ago, but apparently got changed for security reasons. It took me a half an hour to figure out how to enable this for debugging, and as this has annoyingly little Google juice (I didn’t find any solution), let’s add some.

The trick seems to be to set a global policy to be able to eavesdrop any method call after the individual /etc/dbus-1/system.d/*.conf files applied their restrictions, for which there is already a convenient facility. Create a file /etc/dbus-1/system-local.conf with

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE busconfig PUBLIC
  "-//freedesktop//DTD D-BUS Bus Configuration 1.0//EN"
  "http://www.freedesktop.org/standards/dbus/1.0/busconfig.dtd">

<busconfig>
  <policy user="root">
    <!-- Allow everything to be sent -->
    <allow send_destination="*" eavesdrop="true"/>
    <!-- Allow everything to be received -->
    <allow eavesdrop="true"/>
    <allow send_type="method_call"/>
  </policy>
</busconfig>

Then sudo dbus-monitor --system displays everything. Needless to say that you don’t want this file on any production system!

Does anyone know an easier way? My first naive stab was to run dbus-monitor as root, but that doesn’t make any difference at all.

Update: Turns out this is already described in a better way at https://wiki.ubuntu.com/DebuggingDBus. Yay me for not finding that.. I updated above recipe to limit access to root, which is much better indeed.

Read more
pitti

Paul Wise poked me this morning about uploading fatrace (“file access trace”, see the original announcement for details) to Debian, thanks for the reminder!

So I filed an Intent To Package, and will upload it in a few days, unless some discussion evolves.

I also took the opportunity to do some modernization: The power-usage-report script now uses the current PowerTop 2.x instead of the old 1.13, uses Python 3 now, and includes the “process device activity” in the report. I released this as 0.5. The actual fatrace binary didn’t change its behaviour, it just got some code optimizations; thanks to Yann Droneaud for those.

Read more
pitti

Part of our efforts to reduce power consumption in Ubuntu is to provide an easy tool to hunt down which programs and devices are to blame for inordinate power consumption. powertop’s interactive mode is pretty good for this if you are sitting in a train and want to tweak some knobs to max out battery life, but we need something more reproducible and noninteractive for developers who want to file proper bug reports.

So I wrote a little script power-usage-report which calls fatrace for measuring file access activity from programs, and powertop-1.13 to measure process and device wakeups, clean up and sort their ouput, and generate a report which is appropriate to attach to bug reports, send around, put into Jenkins for measuring daily progress, etc. It is now part of fatrace version 0.4, so today’s Precise upgrades will have it.

The output has several sections for disk access (which prevent the disk from spinning down), wakeups (causing CPU power usage), and device activity. Disk/wakeups are sorted in descending order by process:

$ sudo power-usage-report
Measurement will begin in 5 seconds. Please make sure that the
computer is idle, i. e. do not press keys, start or operate programs, and that
programs are not busy with active tasks other than the one you want to examine.
Starting measurement for 60 seconds...
Measurement complete. Generating report...
======= unity-panel-ser: 5 file access events ======
/usr/share/zoneinfo/UTC: 1 reads
/etc/timezone:
/usr/share/zoneinfo/posix/Europe/Berlin: 1 reads
/etc/localtime: 3 reads

======= gnome-settings-: 1 file access events ======
/etc/fstab: 1 reads

======= telepathy-gabbl: 1 file access events ======
/home/martin/.cache/wocky/caps/caps-cache.db: 1 reads

====== Wakeups ======
  30,9% ( 52,0)   compiz
  16,3% ( 27,4)   [iwlwifi] 
  12,5% ( 21,0)   [i915] 
   3,7% (  6,3)   [ahci] 
   2,3% (  3,9)   swapper/3
   1,2% (  2,0)   gvfs-afc-volume
[...]

====== Devices ======
An audio device is active 100,0% of the time:
hwC0D0 Conexant CX20585 

Recent USB suspend statistics
Active  Device name
100,0%	USB device 1-1.5.4.4 : USB Mouse (A4Tech)
100,0%	/sys/bus/usb/devices/1-1.5.4.2
100,0%	USB device 1-1.5.4 : Kinesis Keyboard Hub (PI Engineering)
  0,0%	USB device 1-1.5.2 : USB2.0 Hub Controller (NEC Corporation)

[...]

You can redirect output to a file, of course. The top header (“Starting measurement..” etc.) will go to stderr and thus not be part of the redirected output.

Read more
pitti

Part of our efforts to reduce power consumption is to identify processes which keep waking up the disk even when the computer is idle. This already resulted in a few bug reports (and some fixes, too), but we only really just began with this.

Unfortunately there is no really good tool to trace file access events system-wide. powertop claims to, but its output is both very incomplete, and also wrong (e. g. it claims that read accesses are writes). strace gives you everything you do and don’t want to know about what’s going on, but is per-process, and attaching strace to all running and new processes is cumbersome. blktrace is system-wide, but operates at a way too low level for this task: its output has nothing to do any more with files or even inodes, just raw block numbers which are impossible to convert back to an inode and file path.

So I created a little tool called fatrace (“file access trace”, not “fat race” :-) ) which uses fanotify, a couple of /proc lookups and some glue to provide this. By default it monitors the whole system, i. e. all mounts (except the virtual ones like /proc, tmpfs, etc.), but you can also tell it to just consider the mount of the current directory. You can write the log into a file (stdout by default), and run it for a specified number of seconds. Optional time stamps and PID filters are also provided.

$ sudo fatrace
rsyslogd(967): W /var/log/auth.log
notify-osd(2264): O /usr/share/pixmaps/weechat.xpm
compiz(2001): R device 8:2 inode 658203
[...]

It shows the process name and pid, the event type (Rread, Write, Open, or Close), and the path. Sometimes its’ not possible to determine a path (usually because it’s a temporary file which already got deleted, and I suspect mmaps as well), in that case it shows the device and inode number; such programs then need closer inspection with strace.

If you run this in gnome-terminal, there is an annoying feedback loop, as gnome-terminal causes a disk access with each output line, which then causes another output line, ad infinitum. To fix this, you can either redirect output to a file (-o /tmp/trace) or ignore the PID of gnome-terminal (-p `pidof gnome-terminal`).

So to investigate which programs are keeping your disk spinning, run something like

  $ sudo fatrace -o /tmp/trace -s 60

and then do nothing until it finishes.

My next task will be to write an integration program which calls fatrace and powertop, and creates a nice little report out of that raw data, sorted by number of accesses and process name, and all that. But it might already help some folks as it is right now.

The code lives in bzr branch lp:fatrace (web view), you can just run make and sudo ./fatrace. I also uploaded a package to Ubuntu Precise, but it still needs to go through the NEW queue. I also made a 0.1 release, so you can just grab the release tarball if you prefer. Have a look at the manpage and --help, it should be pretty self-explanatory.

Read more