Differences between revisions 9 and 10
Revision 9 as of 2006-08-06 22:44:41
Size: 3566
Editor: FChE
Comment:
Revision 10 as of 2008-01-10 19:47:25
Size: 3566
Editor: localhost
Comment: converted to 1.6 markup
Deletions are marked like this. Additions are marked like this.
Line 8: Line 8:
To demonstrate use of static instrumentation markers (see fche's ["OLS2006Talks"]), the To demonstrate use of static instrumentation markers (see fche's [[OLS2006Talks]]), the

Marker-based top-process listing

Problem

To demonstrate use of static instrumentation markers (see fche's OLS2006Talks), the FC5 kernel was patched with a marker in a sensitive spot (context switching).

Scripts

Here is the kernel patch: as minimal as can be.

--- kernel/sched.c.orig 2006-03-28 14:53:13.000000000 -0500
+++ kernel/sched.c      2006-03-28 14:56:05.000000000 -0500
@@ -51,6 +51,8 @@
 #include <linux/acct.h>
 #include <asm/tlb.h>

+#include "...../stapmark.h"
+
 #include <asm/unistd.h>

 /*
@@ -1596,6 +1598,7 @@
        }

        /* Here we just switch the register state and the stack. */
+       STAP_MARK_NN(context_switch, prev->pid, next->pid);
        switch_to(prev, next, prev);

        return prev;

probe kernel.mark("context_switch") {
  switches ++   # count number of context switches
  now = get_cycles()
  times[$arg1] += now-lasttime  # accumulate cycles spent in process
  execnames[$arg1] = execname() # remember name of pid
  lasttime = now
}
probe timer.ms(3000) { # every 3000 ms
  printf ("\n%5s %20s %10s  (%d switches)\n",
          "pid", "execname", "cycles", switches);
  foreach ([pid] in times-) # sort in decreasing order of cycle-count
    printf ("%5d %20s %10d\n", pid, execnames[pid], times[pid]);
  # clear data for next report
  delete times
  switches = 0
}
probe begin {
  lasttime = get_cycles()
}
global lasttime, times, execnames, switches

Output

During an idle moment on the test laptop, nothing much happened. pid 0, named "swapper" really means "idle". Note though the precision in time spent in the respective tasks: not just two digits for a rough percentage, but almost down to the nanosecond.

# stap mark-top.stp
  pid             execname     cycles  (1813 switches)
    0              swapper  764411819
 4473                    X   51465833
 4538       gnome-terminal   33217978
 4745          firefox-bin   24762308
 4540       gnome-terminal    4373587
 4932                  mhz    4293245
 4532          xfce4-panel    3111898
 4526                xfwm4    2691366
 4528           xftaskbar4    2114246
 4934                  sed    1909229
 4933                  cat    1901134
 4523      xfce-mcs-manage    1641378
 4520        xfce4-session    1484422
 4931          systemtap/0    1478318
 4530            xfdesktop    1254507
 4930                udevd     564886
 4517         xscreensaver     479184
 1110             cpuspeed     339318
 4771          firefox-bin     303033
  434                udevd     245346
 4439                 ntpd     119060
    4             events/0      99844
 4456            ssh-agent      47817
 4928                 stpd      16487
    3           watchdog/0       9797
^C

Lessons

  • A few thousand marker hits per second are not noticable.
  • Marker-based probes integrate just fine with other systemtap probes.
  • It would be easy to build from/to process-transition matrixes rather than just flat profiles, which could help tune inter-process communication code. With processor numbers mixed in, one can track the movement of a thread between processors.


WarStories

None: WSMarkerBasedTop (last edited 2008-01-10 19:47:25 by localhost)