This is the mail archive of the
systemtap@sources.redhat.com
mailing list for the systemtap project.
runtime status
- From: Martin Hunt <hunt at redhat dot com>
- To: SystemTAP <systemtap at sources dot redhat dot com>
- Date: Thu, 02 Jun 2005 00:23:04 -0700
- Subject: runtime status
- Organization: Red Hat Inc.
I've made a lot of changes in the runtime in the last week or so.
- _stp_stdout is a special String that writes to the transport. All the
print functions are now defines. For example,
#define _stp_printf(args...) _stp_sprintf(_stp_stdout,args)
- There are now register dump functions. See current.c. I'm interested
in feedback on the format of the dump, if we have any assembly programmers.
x86_64 dump looks like:
RIP: ffffffff801c0511
RSP: ffff81003746deb0 EFLAGS: 00000282
RAX: ffffffff801c0510 RBX: 0000000000000000 RCX: 0000000000000400
RDX: 0000000000000000 RSI: ffff81003746ded8 RDI: ffff81000fe98000
RBP: ffff81000fe98000 R08: ffff81003746ded4 R09: 0000000000000000
R10: 0000000000013cc0 R11: 0000000000000000 R12: 0000000000000400
R13: 0000000000506040 R14: 0000000000000400 R15: ffff81003746df50
FS: 00002aaaaaad1b00(0000) GS:ffffffff804e7a80(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000402f50 CR3: 0000000004622000 CR4: 00000000000006e0
- I've reimplemented the _stp_map_print() function to use
a custom format string. Special sequences start with '%'
If the next char is a number, it is a key number. The next char is the
format.
--- KEYS and RESULTS ---
%p - address (hex padded to sizeof(void *))
%P - symbolic address
%x - hex int64
%X - HEX int64
%d - decimal int64
%s - string
--- STATS ---
%m - min
%M - max
%A - avg
%S - sum
%H - histogram
%C - count
--- MISC ---
%% - print '%'
So, "%d" is the value in decimal and "%1d" is key 1 in decimal.
A statistics example might look like:
"map[%1d] = count:%C sum:%S avg:%A min:%m max:%M\n%H"
And produce output like:
map[3] = count:49600 sum:3288450 avg:66 min:0 max:99
value |-------------------------------------------------- count
0 |@@ 460
10 |@@@@@@@ 1460
20 |@@@@@@@@@@@@ 2460
30 |@@@@@@@@@@@@@@@@@@ 3460
40 |@@@@@@@@@@@@@@@@@@@@@@@ 4460
50 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 5460
60 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6460
70 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 7460
80 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 8460
90 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 9460
Using the new format string, I updated the example probes. where_func
uses the following command
_stp_map_print (funct_locations, "Count: %d\tCaller: %1P");
output now looks like this:
Count: 28538 Caller: 0xffffffff803461d3 : preempt_schedule+0x53/0x80
Count: 11715 Caller: 0xffffffff8014b281 : worker_thread+0x131/0x290
Count: 6831 Caller: 0xffffffff8013c58c : do_exit+0xbac/0xbc0
Count: 3690 Caller: 0xffffffff80135822 : migration_thread+0x212/0x3b0
Count: 8960 Caller: 0xffffffff8010ebe4 : retint_careful+0xd/0x21
Count: 4331 Caller: 0xffffffff8013d765 : do_wait+0xd95/0xf60
Count: 6460 Caller: 0xffffffff80346c76 : schedule_timeout+0x66/0x150
Count: 1 Caller: 0xffffffff80139044 : do_syslog+0x164/0x460
Count: 18293 Caller: 0xffffffff8010c8a7 : cpu_idle+0x57/0x60
Count: 18254 Caller: 0xffffffff80346d34 : schedule_timeout+0x124/0x150
Count: 1759 Caller: 0xffffffff80345178 : __down+0x98/0x110
Count: 3476 Caller: 0xffffffff8018f830 : pipe_wait+0xa0/0xf0
Count: 3066 Caller: 0xffffffff80346ba1 : io_schedule+0x31/0x40
Count: 10 Caller: 0xffffffff88048a15 : log_wait_commit+0xf5/0x150 [jbd]
Count: 1157 Caller: 0xffffffff80346123 : wait_for_completion+0xb3/0x110
Count: 35 Caller: 0xffffffff88048792 : kjournald+0x252/0x2f0 [jbd]
Count: 9 Caller: 0xffffffff88043838 : do_get_write_access+0x498/0x7a0 [jbd]
Count: 50 Caller: 0xffffffff801657bb : pdflush+0xbb/0x1f0
Count: 60 Caller: 0xffffffff80346aaf : cond_resched+0x2f/0x60
Count: 32 Caller: 0xffffffff8010e604 : sysret_careful+0xd/0x10
Count: 8 Caller: 0xffffffff803452bd : __down_interruptible+0xcd/0x140
Count: 70 Caller: 0xffffffff801351af : cond_resched_lock+0x8f/0xd0
Count: 21 Caller: 0xffffffff80347170 : __down_write+0x80/0xa0
Count: 10 Caller: 0xffffffff80347212 : __down_read+0x82/0x9a
Count: 1 Caller: 0xffffffff801b4941 : __mb_cache_entry_find+0xf1/0x230
Count: 182 Caller: 0xffffffff8016b905 : kswapd+0x125/0x150
Count: 144 Caller: 0xffffffff8013ef75 : ksoftirqd+0x45/0xe0
There is also a new probe called "scf" which demonstrates using a stack
trace as a map key and counting the number of times a function (in this case
smp_call_function()) is called via a particular path. Output looks like this:
trace[trace for 4026 (hald)
0xffffffff8011a941 : smp_call_function+0x1/0x70
0xffffffff80184996 : invalidate_bdev+0x26/0x70
0xffffffff8019e148 : __invalidate_device+0x58/0x70
0xffffffff8018aee9 : check_disk_change+0x39/0xa0
0xffffffff802a89dc : cdrom_open+0xa2c/0xa70
0xffffffff801343d0 : default_wake_function+0x0/0x10
0xffffffff80347aa1 : _spin_unlock_irq+0x41/0x70
0xffffffff80132c60 : finish_task_switch+0x40/0x90
0xffffffff80347d93 : __reacquire_kernel_lock+0x73/0x90
0xffffffff8034603a : thread_return+] = 12
trace[trace for 4026 (hald)
0xffffffff8011a941 : smp_call_function+0x1/0x70
0xffffffff80184996 : invalidate_bdev+0x26/0x70
0xffffffff8018a45e : kill_bdev+0xe/0x30
0xffffffff8018b03c : blkdev_put+0x7c/0x200
0xffffffff80183bf6 : __fput+0x76/0x1a0
0xffffffff801823ee : filp_close+0x7e/0xa0
0xffffffff801824a3 : sys_close+0x93/0xc0
0xffffffff8010e59a : system_call+0x7e/0x83
] = 12
(the internal string buffer truncated output in the first trace,
which is why the formatting looks a bit odd)
- Finally, I've implemented Counters and am working on Stats, These are
per-cpu aggregations. Stats are like map stats and have the ability to
include histograms or not. If a Stat has histograms disabled, it just counts,
sums, and records min and max. Are there any other aggregations we need?
Martin