brendangregg

$ stap -v --use-server=10.140.145.195:7001 -ve 'global ops; probe syscall.* { ops[probefunc()] <<< 1; }'
Systemtap translator/driver (version 1.8/0.152 non-git sources)
Copyright (C) 2005-2012 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
enabled features: AVAHI LIBRPM LIBSQLITE3 NSS BOOST_SHARED_PTR TR1_UNORDERED_MAP NLS
Created temporary directory "/tmp/stapuKSnAK"
Session arch: x86_64 release: 3.2.41-nflx
Using a compile server.
Running sh -c cd '/tmp/stapuKSnAK/client' && zip -qr '/tmp/stapuKSnAK/client.zip' *
Spawn waitpid result (0x0): 0

brendangregg

#!/usr/bin/stap
/*
 * rwtime.stp	read/write syscalls by latency.
 *
 * USAGE: ./rwtime.stp [execname]
 *
 * An option argument of the program name, eg, "httpd", can be provided. Without
 * this, all processes are traced.
 *
 * 24-Jun-2014	Brendan Gregg	Created this.

brendangregg

#!/usr/bin/stap
/*
 * rwtime.stp	read/write syscalls by latency.
 *
 * USAGE: ./rwtime.stp [execname]
 *
 * An option argument of the program name, eg, "httpd", can be provided. Without
 * this, all processes are traced.
 *
 * 24-Jun-2014	Brendan Gregg	Created this.

brendangregg

	    13a80b1584f5 RegExp:\bwebOS(?:/[\d.]+|[ \w.]*) (/tmp/perf-7539.map)

brendangregg

G'Day, I didn't have an email addr so pasted into gist. Just wanted to explain things a bit better than could on twitter. Good luck!

1. CPU-bound

Depends what you mean by CPU bound: bound by availability or speed.

If the CPUs themselves are hot, then this is easy. "mpstat -P ALL 1" will show the hot CPUs. If single threads are causing it, then "pidstat -t 1" will identify them (although, it could be a large thread pool competing). This approach identifies if something is resource constrained by CPUs, but not bound by their speed.

Imagine a single CPU system running at 10% utilization, with an application processing 1 request per second, which is taking 100ms, all CPU time. The application's performance is CPU (speed) bounded, but the system looks mostly idle. This can be identified using walltime vs CPU time for the request. Most languages have a way to get the CPU time (something getrusage() related). Eg, if you were able to measure that the request took 100 ms, and, 100 ms of CPU time was consumed,

brendangregg

#!/usr/bin/stap
/*
 * chaintime-nd.stp	Measure off-CPU time by stack trace & wakeup stack.
 *			For Linux, uses SystemTap (non-debuginfo).
 *
 * USAGE: ./chaintime-nd.stp [duration]
 *
 * This script uses the kernel tracepoint sched:sched_switch to measure off-CPU
 * time along with the blocked stack trace, and sched:sched_wakeup to measure
 * the wakeup stack for sleeping threads, to associate with the blocked stack.

brendangregg

# stap -DMAXACTION=100000 -DMAXBACKTRACE=200 -DMAXSTRINGLEN=2048 -e 'global a; probe scheduler.wakeup { a[backtrace()] <<< 1; } probe end { foreach (s in a+) { print_stack(s); printf("%d\n", @count(a[s])); } }'
WARNING: no or bad debug frame hdr
WARNING: No binary search table for eh frame, doing slow linear search for stap_2f47e23b6460a5b15a4222492730a8f_13345
WARNING: too many pending (warning) messages
[...]
 0xffffffffa0511f1b : 0xffffffffa0511f1b [stap_2f47e23b6460a5b15a4222492730a8f_13333+0x7f1b/0x0]
 0xffffffffa0513279 : 0xffffffffa0513279 [stap_2f47e23b6460a5b15a4222492730a8f_13333+0x9279/0x0]
 0xffffffffa0515283 : 0xffffffffa0515283 [stap_2f47e23b6460a5b15a4222492730a8f_13333+0xb283/0x0]
 0xffffffffa050a011 : 0xffffffffa050a011 [stap_2f47e23b6460a5b15a4222492730a8f_13333+0x11/0x0]
 0xffffffff810982a2 : 0xffffffff810982a2

brendangregg

          <idle>-0     [002] dNh. 5790376.199595: offcpu_sched_wakeup: waker_comm=swapper/2 (0), wakee_comm=sleep (29321), wakee_offcpu_delay=6000061382, flag=0, waker_stack=ttwu_do_wakeup+0xb2/0xc0
ttwu_do_activate.constprop.74+0x5d/0x70
try_to_wake_up+0x1d2/0x2c0
wake_up_process+0x23/0x40
hrtimer_wakeup+0x22/0x40
__run_hrtimer+0x77/0x1d0
hrtimer_interrupt+0xef/0x230
local_apic_timer_interrupt+0x37/0x60
smp_apic_timer_interr
          <idle>-0     [002] d... 5790376.199618: offcpu_sched_switch: comm=sleep, pid=29321, delay=6000101834, flag=0, stack=schedule+0x29/0x70

brendangregg

# /apps/perf-tools/bin/kprobe -s 'p:taskq_dispatch +0(+16(%di)):string' | head -20
taskq_dispatch [spl]
Tracing kprobe taskq_dispatch. Ctrl-C to end.
           <...>-68258 [007] d... 1242008.371281: taskq_dispatch: (taskq_dispatch+0x0/0x170 [spl]) arg1="metaslab_group_taskq"
           <...>-68258 [007] d... 1242008.371289: <stack trace>
 => vdev_sync_done
 => spa_sync
 => txg_sync_thread
 => thread_generic_wrapper
 => kthread

brendangregg

# /apps/perf-tools/bin/funcslower -t spa_sync 100000
Tracing "spa_sync" slower than 100000 us... Ctrl-C to end.
4445151.315130 |     0) ! 151766.8 us |  } /* spa_sync [zfs] */
4445166.267272 |     8) ! 104154.9 us |  } /* spa_sync [zfs] */
4445191.382823 |     7) ! 216032.0 us |  } /* spa_sync [zfs] */
4445196.291821 |     7) ! 125089.3 us |  } /* spa_sync [zfs] */
4445201.371173 |     7) ! 204526.1 us |  } /* spa_sync [zfs] */
^C
Ending tracing...