-
Notifications
You must be signed in to change notification settings - Fork 3
/
latencytap.stp
298 lines (281 loc) · 11.9 KB
/
latencytap.stp
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
#! /usr/bin/env stap
#
# Copyright (C) 2010 Red Hat, Inc.
# Written by William Cohen <wcohen@redhat.com>
#
# This script records the time that a process has spent asleep and attempt
# to provide a reason for that that sleep. The script needs to be run with the
# '--all-modules' option to map the backtrace addresses to function names
# and the function names back to reasons.
#
# stap --all-modules latencytap.stp
global priority, reason;
global traced_pid, sleep_time, dequeue;
global this_sleep;
global debug = 0;
global reason_len;
function log_event:long (p:long)
{
return (!traced_pid || traced_pid == task_pid(p))
}
#func names from hex addresses
function func_backtrace:string (ips:string)
{
ret = "";
for (ip=tokenize(ips, " "); ip!=""; ip=tokenize("", " "))
ret = ret . symname(strtol(ip,16)) . " ";
return ret;
}
# pick out a reason based on the backtrace function names
function translate:string (bt:string)
{
ip=tokenize(bt, " ");
func = symname(strtol(ip,16))
pri = 1; rea="";
while (ip!="") {
p = priority[func]
if (p >= pri) {
pri = priority[func];
rea = reason[func];
}
ip=tokenize("", " ")
func = symname(strtol(ip,16))
}
return rea;
}
probe kernel.trace("deactivate_task") !,
kernel.function("deactivate_task") {
s = task_state($p)
# check to see if task is in appropriate state:
# TASK_INTERRUPTIBLE 1
# TASK_UNINTERRUPTIBLE 2
if (log_event($p) && (s & 3)) {
dequeue[$p] = gettimeofday_us();
}
}
probe kernel.trace("activate_task") !,
kernel.function("activate_task") {
if (!log_event($p)) next
a = gettimeofday_us()
d = dequeue[$p]
delete dequeue[$p]
if (d) {
sleep = a - d
if (sleep > 0) {
this_sleep[$p] = sleep
# sleep_time[task_backtrace($p)] <<< sleep
}
}
}
#FIXME: It would be nicer to get backtrace information in activate_task probe.
# This would eliminate the overhead of probing every context switch
# and this_sleep associate array. However, this needs a properly working
# task_backtrace() to eliminate this probe.
probe scheduler.cpu_on {
p = task_current()
t = this_sleep[p]
if (t){
delete this_sleep[p]
sleep_time[backtrace()] <<< t
}
}
global sort_latencies;
function global_report_latencies() {
total = 0
foreach ([backtrace] in sleep_time) {
val = @sum(sleep_time[backtrace]);
sort_latencies[backtrace] = val;
total += val;
}
ansi_clear_screen();
printf("%-*s %12s %12s %12s %7s%%\n",
@max(reason_len)+1, "Reason", "Count", "Average(us)", "Maximum(us)", "Percent");
foreach ([backtrace] in sort_latencies- limit 20) {
#print reason count average max percentage
cause = translate (backtrace);
# if can't find reason print out a backtrace
if (cause == "" && debug)
printf("%s\n", func_backtrace(backtrace));
printf("%-*s ", @max(reason_len)+1, cause);
p = (@sum(sleep_time[backtrace])*100)/total;
printf("%12d %12d %12d %7d%%\n",
@count(sleep_time[backtrace]),
@avg(sleep_time[backtrace]),
@max(sleep_time[backtrace]),
p);
}
delete sort_latencies;
}
probe timer.s(30) {
global_report_latencies()
delete sleep_time
}
probe begin {
traced_pid = target()
}
# Set up the translations and priorities for each function.
# The vast majority of translations were mechanically generated from the
# latencytop (http://www.latencytop.org/) translation file:
# /usr/share/latencytop/latencytop.trans .
function explain(symbol,pri,blah) {
priority[symbol] = pri
reason[symbol] = blah
reason_len <<< strlen(blah)
}
probe begin {
explain("SyS_epoll_wait",3,"Waiting for event (epoll)");
explain("SyS_flock",3,"flock() on a file");
explain("SyS_nanosleep",5,"Application requested delay");
explain("SyS_pause",5,"Application requested delay");
explain("__bread",2,"Synchronous buffer read");
explain("__ext3_get_inode_loc",3,"Reading EXT3 inode");
explain("__log_wait_for_space",5,"Waiting for EXT3 journal space");
explain("__mark_inode_dirty",1,"Marking inode dirty");
explain("__pollwait",2,"Waiting for event (poll)");
explain("__stop_machine_run",3,"Freezing the kernel (for module load)");
explain("__wait_on_buffer",2,"Waiting for buffer IO to complete");
explain("acpi_ec_transaction",3,"ACPI hardware access");
explain("acquire_console_sem",3,"Waiting for console access");
explain("alloc_page_vma",3,"Allocating a VMA");
explain("ata_exec_internal_sg",3,"Executing internal ATA command");
explain("ata_scsi_ioctl",3,"ATA/SCSI disk ioctl");
explain("bdi_forker_task",2,"bdi-* kernel thread");
explain("bdi_sync_supers",1,"Sync superblock");
explain("bdi_writeback_task",2,"Flush data to backing device");
explain("bdi_writeback_thread",2,"Flush data to backing dev");
explain("blk_execute_rq",3,"Submitting block IO");
explain("blkdev_direct_IO",3,"Direct block device IO");
explain("blkdev_ioctl",2,"block device IOCTL");
explain("blocking_notifier_call_chain",1,"Blocking notifier");
explain("cdrom_open",3,"opening cdrom device");
explain("core_sys_select",2,"Waiting for event (select)");
explain("dm_wait_for_completion",2,"Waiting for device mapper ops");
explain("do_fork",3,"Fork() system call");
explain("do_fsync",5,"fsync() on a file");
explain("do_futex",3,"Userspace lock contention");
explain("do_generic_mapping_read",2,"Reading file data");
explain("do_page_fault",5,"Page fault");
explain("do_rmdir",3,"Removing directory");
explain("do_sync_write",2,"synchronous write");
explain("do_sys_open",2,"Opening file");
explain("do_sys_poll",2,"Waiting for event (poll)");
explain("do_truncate",3,"Truncating file");
explain("do_unlinkat",2,"Unlinking file");
explain("evdev_read",5,"Reading keyboard/mouse input");
explain("ext3_bread",3,"Synchronous EXT3 read");
explain("ext3_create",3,"EXT3 Creating a file");
explain("ext3_delete_inode",3,"EXT3 deleting inode");
explain("ext3_find_entry",3,"EXT3: Looking for file");
explain("ext3_free_branches",3,"Unlinking file on EXT3");
explain("ext3_get_branch",3,"Reading EXT3 indirect blocks");
explain("ext3_mark_inode_dirty ",3,"EXT3 marking inode dirty");
explain("ext3_mkdir",3,"EXT3: Creating a directory");
explain("ext3_orphan_add ",3,"EXT3 adding orphan");
explain("ext3_read_inode",3,"Reading EXT3 inode");
explain("ext3_readdir",3,"Reading EXT3 directory");
explain("ext3_unlink ",3,"EXT3 unlinking file");
explain("filemap_fault",5,"Page fault");
explain("filp_close",3,"Closing a file");
explain("generic_delete_inode",3,"Deleting an inode");
explain("generic_make_request",3,"Creating block layer request");
explain("get_request_wait",3,"Creating block layer request");
explain("handle_mm_fault",5,"Page fault");
explain("htree_dirblock_to_tree",3,"Reading EXT3 directory htree");
explain("i915_gem_throttle_ioctl",3,"Throttling GPU while waiting for commands");
explain("i915_irq_wait",3,"Waiting for GPU interrupt");
explain("i915_wait_request",2,"Waiting for GPU command to complete");
explain("inet_sendmsg",3,"Sending TCP/IP data");
explain("inotify_inode_queue_event",3,"Inotify event");
explain("input_close_device",3,"Closing input device");
explain("journal_commit_transaction",3,"EXT3: committing transaction");
explain("journal_get_undo_access",3,"Waiting for EXT3 journal undo operation");
explain("journal_get_write_access",3,"EXT3: Waiting for journal access");
explain("kauditd_thread",2,"kernel audit daemon");
explain("khugepaged",2,"khugepaged() kernel thread");
explain("kjournald",2,"kjournald() kernel thread");
explain("kjournald2",2,"jdb2() kernel thread");
explain("kmsg_read",3,"Reading from dmesg");
explain("ksoftirqd",2,"Waking ksoftirqd");
explain("kswapd",2,"kswapd() kernel thread");
explain("kthreadd",2,"kthreadd kernel thread");
explain("kvm_vcpu_ioctl",3,"KVM ioctl");
explain("link_path_walk",3,"Following symlink");
explain("lock_kernel",3,"Big Kernel Lock contention");
explain("lock_super",1,"Superblock lock contention");
explain("log_do_checkpoint",3,"EXT3 journal checkpoint");
explain("lookup_create",3,"Creating file");
explain("md_thread",2,"Raid resync kernel thread");
explain("migration_thread",2,"migration() kernel thread");
explain("mousedev_close_device",3,"Closing mouse device");
explain("mousedev_open",3,"Opening mouse device");
explain("mousedev_release",3,"Closing mouse device");
explain("page_cache_sync_readahead",3,"Pagecache sync readahead");
explain("path_walk",3,"Walking directory tree");
explain("pdflush",2,"pdflush() kernel thread");
explain("pipe_read",3,"Reading from a pipe");
explain("pipe_wait",3,"Waiting for pipe data");
explain("pipe_write",3,"Writing to a pipe");
explain("proc_delete_inode",3,"Removing /proc file");
explain("proc_lookup",3,"Looking up /proc file");
explain("proc_reg_read",2,"Reading from /proc file");
explain("proc_root_readdir",2,"Reading /proc directory");
explain("rcu_gp_kthread",2,"RCU grace period kernel thread");
explain("read_block_bitmap",3,"Reading EXT3 block bitmaps");
explain("request_module",2,"Loading a kernel module");
explain("run_ksoftirqd",2,"Waking ksoftirqd");
explain("scsi_cmd_ioctl",3,"SCSI ioctl command");
explain("scsi_error_handler",2,"SCSI error handler");
explain("scsi_execute_req",3,"Executing raw SCSI command");
explain("sd_ioctl",3,"SCSI disk ioctl");
explain("shrink_icache_memory",3,"reducing inode cache memory footprint");
explain("sigsuspend",3,"waiting for a signal");
explain("smpboot_thread_fn",2,"percpu hotplug kernel thread");
explain("sock_sendmsg",2,"Sending data over socket");
explain("sr_cd_check",3,"Checking CDROM media present");
explain("sr_do_ioctl",3,"SCSI cdrom ioctl");
explain("sr_media_change",3,"Checking for media change");
explain("sync_buffer",3,"Writing buffer to disk (synchronous)");
explain("sync_filesystems",5,"Syncing filesystem");
explain("sync_inode",3,"(f)syncing an inode to disk");
explain("sync_page",3,"Writing a page to disk");
explain("sync_sb_inodes",3,"Syncing inodes");
explain("synchronize_rcu",3,"Waiting for RCU");
explain("sys_epoll_wait",3,"Waiting for event (epoll)");
explain("sys_execve",3,"Executing a program");
explain("sys_fcntl",2,"FCNTL system call");
explain("sys_flock",3,"flock() on a file");
explain("sys_futex",3,"Userspace lock contention");
explain("sys_getdents",3,"Reading directory content");
explain("sys_mkdirat",3,"Creating directory");
explain("sys_mmap",3,"mmaping memory");
explain("sys_mprotect",3,"mprotect() system call");
explain("sys_munmap",3,"unmapping memory");
explain("sys_nanosleep",5,"Application requested delay");
explain("sys_pause",5,"Application requested delay");
explain("sys_wait4",3,"Waiting for a process to die");
explain("tcp_connect",3,"TCP/IP connect");
explain("tcp_recvmsg",3,"Receiving TCP/IP data");
explain("tty_ioctl",2,"TTY IOCTL");
explain("tty_poll",3,"Waiting for TTY data");
explain("tty_read",3,"Waiting for TTY input");
explain("tty_wait_until_sent",3,"Waiting for TTY to finish sending");
explain("tty_write",3,"Writing data to TTY");
explain("udp_recvmsg",3,"Receiving UDP/IP data");
explain("unix_stream_recvmsg",3,"Waiting for data on unix socket");
explain("update_atime",3,"Updating inode atime");
explain("usb_autoresume_device",2,"Waking up USB device");
explain("usb_port_resume",2,"Waking up USB device");
explain("usb_stor_control_thread",2,"usb storage control kernel thread");
explain("usbdev_open",3,"opening USB device");
explain("vfs_create",1,"Creating a file");
explain("vfs_read",1,"Reading from file");
explain("vfs_lock_file",1,"Locking a file");
explain("vfs_readdir",1,"Reading directory content");
explain("vfs_rmdir",3,"Removing directory");
explain("vfs_stat_fd",3,"stat() operation");
explain("vfs_unlink",1,"Unlinking file");
explain("vfs_write",1,"Writing to file");
explain("vt_waitactive",3,"vt_waitactive IOCTL");
explain("worker_thread",2,"kernel workqueue thread");
explain("writeback_inodes",3,"Writing back inodes");
}