From dadb3ad90b6f9df1ec1e7ca132a1c682fb93303c Mon Sep 17 00:00:00 2001
From: William Cohen <wcohen@redhat.com>
Date: Thu, 9 Sep 2010 12:49:22 -0400
Subject: [PATCH] Updated latencytap.stp

The updated latencytap.stp uses more portable probe points for the collecting
the data. The script also maps the functions in the traceback to reasons the
sleep. The reasons for the sleeps were mechanically generated from
latencytop-0.5 latencytop.trans file.
---
 .../profiling/latencytap.stp                  | 545 ++++++++++++++++--
 1 file changed, 499 insertions(+), 46 deletions(-)

diff --git a/testsuite/systemtap.examples/profiling/latencytap.stp b/testsuite/systemtap.examples/profiling/latencytap.stp
index 7fdbbc4e8..9e52c94a4 100755
--- a/testsuite/systemtap.examples/profiling/latencytap.stp
+++ b/testsuite/systemtap.examples/profiling/latencytap.stp
@@ -1,53 +1,506 @@
 #! /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.
 
-# Record the time that a process has spent asleep, and in what function
-
-global enqueued
-global sleep_time
-global process_names
-global sleep_agg
-
-function _get_sleep_time:long(rq_param:long, p_param:long) %{ /* pure */
-        struct rq *rq = (struct rq *)(unsigned long)THIS->rq_param;
-        struct task_struct *p = (struct task_struct *)(unsigned long)THIS->p_param;
-        struct sched_entity *se = &p->se;
-        u64 delta = cpu_clock(smp_processor_id()) - se->sleep_start;
-
-        if ((s64)delta < 0)
-                delta = 0;
-        THIS->__retvalue = delta;
-%}
-
-# Get the backtrace from an arbitrary task
-function task_backtrace:string (task:long) %{ /* pure */
-    _stp_stack_snprint_tsk(THIS->__retvalue, MAXSTRINGLEN,
-                           (struct task_struct *)(unsigned long)THIS->task, 0, MAXTRACE);
-%}
-
-probe kernel.function("enqueue_task_fair") {
-    if ($wakeup == 1) {
-        this_sleep = _get_sleep_time($rq, $p)
-        if (this_sleep > 0) {
-            sleep_time[$p->pid, task_backtrace($p)] += this_sleep
-            sleep_agg[$p->pid] <<< this_sleep
-            process_names[$p->pid] = kernel_string($p->comm)
-        }
-    }
+global priority, reason;
+global traced_pid, sleep_time, dequeue;
+global this_sleep;
+
+function log_event:long (p:long) { return (!traced_pid || traced_pid == p) }
+
+#print series of func names from hex addresses
+function print_func_backtrace (ips:string)
+{
+  for (ip=tokenize(ips, " "); ip!=""; ip=tokenize("", " "))
+     printf("%s ", symname(strtol(ip,16)));
 }
 
-global pid_sleep
-probe timer.ms(1000) {
-    foreach ([pid, backtrace] in sleep_time) {
-        pid_sleep[pid] += sleep_time[pid, backtrace]
-        printf("%s %d:\n", process_names[pid], pid)
-        print_stack(backtrace)
-        printf("\n")
+# 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="[" . func . "]";
+  while (ip!="") {
+    p = priority[func]
+    if (p >= pri) {
+      pri = priority[func];
+      rea = reason[func];
     }
-    foreach ([pid+] in pid_sleep) {
-        printf("%s %d %d\n", process_names[pid], @max(sleep_agg[pid]) / 1000000, @avg(sleep_agg[pid]) / 1000000) 
+    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->pid) && (s & 3)) {
+    dequeue[$p] = gettimeofday_us();
+  }
+}
+
+probe kernel.trace("activate_task") !,
+      kernel.function("activate_task") {
+  if (!log_event($p->pid)) 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
     }
-    # decode backtraces; unfortunately they are empty at the moment.
-    delete pid_sleep
-    delete sleep_time
-    delete process_names
+  }
+}
+
+#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
+   }
+}
+
+function report_latencies() {
+  foreach ([backtrace] in sleep_time- limit 20) {
+    printf("%d %d %d ", @count(sleep_time[backtrace]),
+           @sum(sleep_time[backtrace]),
+           @max(sleep_time[backtrace]))
+#    print_func_backtrace(backtrace)
+    printf("%s", translate (backtrace));
+    printf("\n")
+  }
+}
+
+probe timer.s(30) {
+  report_latencies()
+  delete sleep_time
+}
+
+probe begin {
+  traced_pid = target()
+}
+
+# Set up the translations and priorities for each function.
+probe begin {
+  priority["vfs_read"] = 1;
+  reason["vfs_read"] = "Reading from file";
+
+  priority["vfs_write"] = 1;
+  reason["vfs_write"] = "Writing to file";
+
+  priority["__mark_inode_dirty"] = 1;
+  reason["__mark_inode_dirty"] = "Marking inode dirty";
+
+  priority["vfs_readdir"] = 1;
+  reason["vfs_readdir"] = "Reading directory content";
+
+  priority["vfs_unlink"] = 1;
+  reason["vfs_unlink"] = "Unlinking file";
+
+  priority["blocking_notifier_call_chain"] = 1;
+  reason["blocking_notifier_call_chain"] = "Blocking notifier";
+
+  priority["lock_super"] = 1;
+  reason["lock_super"] = "Superblock lock contention";
+
+  priority["vfs_create"] = 1;
+  reason["vfs_create"] = "Creating a file";
+
+  priority["__bread"] = 2;
+  reason["__bread"] = "Synchronous buffer read";
+
+  priority["do_generic_mapping_read"] = 2;
+  reason["do_generic_mapping_read"] = "Reading file data";
+
+  priority["sock_sendmsg"] = 2;
+  reason["sock_sendmsg"] = "Sending data over socket";
+
+  priority["do_sys_open"] = 2;
+  reason["do_sys_open"] = "Opening file";
+
+  priority["do_sys_poll"] = 2;
+  reason["do_sys_poll"] = "Waiting for event (poll)";
+
+  priority["core_sys_select"] = 2;
+  reason["core_sys_select"] = "Waiting for event (select)";
+
+  priority["proc_reg_read"] = 2;
+  reason["proc_reg_read"] = "Reading from /proc file";
+
+  priority["__pollwait"] = 2;
+  reason["__pollwait"] = "Waiting for event (poll)";
+
+  priority["sys_fcntl"] = 2;
+  reason["sys_fcntl"] = "FCNTL system call";
+
+  priority["scsi_error_handler"] = 2;
+  reason["scsi_error_handler"] = "SCSI error handler";
+
+  priority["proc_root_readdir"] = 2;
+  reason["proc_root_readdir"] = "Reading /proc directory";
+
+  priority["ksoftirqd"] = 2;
+  reason["ksoftirqd"] = "Waking ksoftirqd";
+
+  priority["do_unlinkat"] = 2;
+  reason["do_unlinkat"] = "Unlinking file";
+
+  priority["__wait_on_buffer"] = 2;
+  reason["__wait_on_buffer"] = "Waiting for buffer IO to complete";
+
+  priority["pdflush"] = 2;
+  reason["pdflush"] = "pdflush() kernel thread";
+
+  priority["kjournald"] = 2;
+  reason["kjournald"] = "kjournald() kernel thread";
+
+  priority["blkdev_ioctl"] = 2;
+  reason["blkdev_ioctl"] = "block device IOCTL";
+
+  priority["kauditd_thread"] = 2;
+  reason["kauditd_thread"] = "kernel audit daemon";
+
+  priority["tty_ioctl"] = 2;
+  reason["tty_ioctl"] = "TTY IOCTL";
+
+  priority["do_sync_write"] = 2;
+  reason["do_sync_write"] = "synchronous write";
+
+  priority["kthreadd"] = 2;
+  reason["kthreadd"] = "kthreadd kernel thread";
+
+  priority["usb_port_resume"] = 2;
+  reason["usb_port_resume"] = "Waking up USB device";
+
+  priority["usb_autoresume_device"] = 2;
+  reason["usb_autoresume_device"] = "Waking up USB device";
+
+  priority["kswapd"] = 2;
+  reason["kswapd"] = "kswapd() kernel thread";
+
+  priority["md_thread"] = 2;
+  reason["md_thread"] = "Raid resync kernel thread";
+
+  priority["i915_wait_request"] = 2;
+  reason["i915_wait_request"] = "Waiting for GPU command to complete";
+
+  priority["request_module"] = 2;
+  reason["request_module"] = "Loading a kernel module";
+
+  priority["tty_wait_until_sent"] = 3;
+  reason["tty_wait_until_sent"] = "Waiting for TTY to finish sending";
+
+  priority["pipe_read"] = 3;
+  reason["pipe_read"] = "Reading from a pipe";
+
+  priority["pipe_write"] = 3;
+  reason["pipe_write"] = "Writing to a pipe";
+
+  priority["pipe_wait"] = 3;
+  reason["pipe_wait"] = "Waiting for pipe data";
+
+  priority["read_block_bitmap"] = 3;
+  reason["read_block_bitmap"] = "Reading EXT3 block bitmaps";
+
+  priority["scsi_execute_req"] = 3;
+  reason["scsi_execute_req"] = "Executing raw SCSI command";
+
+  priority["sys_wait4"] = 3;
+  reason["sys_wait4"] = "Waiting for a process to die";
+
+  priority["sr_media_change"] = 3;
+  reason["sr_media_change"] = "Checking for media change";
+
+  priority["sr_do_ioctl"] = 3;
+  reason["sr_do_ioctl"] = "SCSI cdrom ioctl";
+
+  priority["sd_ioctl"] = 3;
+  reason["sd_ioctl"] = "SCSI disk ioctl";
+
+  priority["sr_cd_check"] = 3;
+  reason["sr_cd_check"] = "Checking CDROM media present";
+
+  priority["ext3_read_inode"] = 3;
+  reason["ext3_read_inode"] = "Reading EXT3 inode";
+
+  priority["htree_dirblock_to_tree"] = 3;
+  reason["htree_dirblock_to_tree"] = "Reading EXT3 directory htree";
+
+  priority["ext3_readdir"] = 3;
+  reason["ext3_readdir"] = "Reading EXT3 directory";
+
+  priority["ext3_bread"] = 3;
+  reason["ext3_bread"] = "Synchronous EXT3 read";
+
+  priority["ext3_free_branches"] = 3;
+  reason["ext3_free_branches"] = "Unlinking file on EXT3";
+
+  priority["ext3_get_branch"] = 3;
+  reason["ext3_get_branch"] = "Reading EXT3 indirect blocks";
+
+  priority["ext3_find_entry"] = 3;
+  reason["ext3_find_entry"] = "EXT3: Looking for file";
+
+  priority["__ext3_get_inode_loc"] = 3;
+  reason["__ext3_get_inode_loc"] = "Reading EXT3 inode";
+
+  priority["ext3_delete_inode"] = 3;
+  reason["ext3_delete_inode"] = "EXT3 deleting inode";
+
+  priority["sync_page"] = 3;
+  reason["sync_page"] = "Writing a page to disk";
+
+  priority["tty_poll"] = 3;
+  reason["tty_poll"] = "Waiting for TTY data";
+
+  priority["tty_read"] = 3;
+  reason["tty_read"] = "Waiting for TTY input";
+
+  priority["tty_write"] = 3;
+  reason["tty_write"] = "Writing data to TTY";
+
+  priority["update_atime"] = 3;
+  reason["update_atime"] = "Updating inode atime";
+
+  priority["page_cache_sync_readahead"] = 3;
+  reason["page_cache_sync_readahead"] = "Pagecache sync readahead";
+
+  priority["do_fork"] = 3;
+  reason["do_fork"] = "Fork() system call";
+
+  priority["sys_mkdirat"] = 3;
+  reason["sys_mkdirat"] = "Creating directory";
+
+  priority["lookup_create"] = 3;
+  reason["lookup_create"] = "Creating file";
+
+  priority["inet_sendmsg"] = 3;
+  reason["inet_sendmsg"] = "Sending TCP/IP data";
+
+  priority["tcp_recvmsg"] = 3;
+  reason["tcp_recvmsg"] = "Receiving TCP/IP data";
+
+  priority["link_path_walk"] = 3;
+  reason["link_path_walk"] = "Following symlink";
+
+  priority["path_walk"] = 3;
+  reason["path_walk"] = "Walking directory tree";
+
+  priority["sys_getdents"] = 3;
+  reason["sys_getdents"] = "Reading directory content";
+
+  priority["unix_stream_recvmsg"] = 3;
+  reason["unix_stream_recvmsg"] = "Waiting for data on unix socket";
+
+  priority["ext3_mkdir"] = 3;
+  reason["ext3_mkdir"] = "EXT3: Creating a directory";
+
+  priority["journal_get_write_access"] = 3;
+  reason["journal_get_write_access"] = "EXT3: Waiting for journal access";
+
+  priority["synchronize_rcu"] = 3;
+  reason["synchronize_rcu"] = "Waiting for RCU";
+
+  priority["input_close_device"] = 3;
+  reason["input_close_device"] = "Closing input device";
+
+  priority["mousedev_close_device"] = 3;
+  reason["mousedev_close_device"] = "Closing mouse device";
+
+  priority["mousedev_release"] = 3;
+  reason["mousedev_release"] = "Closing mouse device";
+
+  priority["mousedev_open"] = 3;
+  reason["mousedev_open"] = "Opening mouse device";
+
+  priority["kmsg_read"] = 3;
+  reason["kmsg_read"] = "Reading from dmesg";
+
+  priority["sys_futex"] = 3;
+  reason["sys_futex"] = "Userspace lock contention";
+
+  priority["do_futex"] = 3;
+  reason["do_futex"] = "Userspace lock contention";
+
+  priority["vt_waitactive"] = 3;
+  reason["vt_waitactive"] = "vt_waitactive IOCTL";
+
+  priority["acquire_console_sem"] = 3;
+  reason["acquire_console_sem"] = "Waiting for console access";
+
+  priority["filp_close"] = 3;
+  reason["filp_close"] = "Closing a file";
+
+  priority["sync_inode"] = 3;
+  reason["sync_inode"] = "(f)syncing an inode to disk";
+
+  priority["ata_exec_internal_sg"] = 3;
+  reason["ata_exec_internal_sg"] = "Executing internal ATA command";
+
+  priority["writeback_inodes"] = 3;
+  reason["writeback_inodes"] = "Writing back inodes";
+
+  priority["ext3_orphan_add "] = 3;
+  reason["ext3_orphan_add "] = "EXT3 adding orphan";
+
+  priority["ext3_mark_inode_dirty "] = 3;
+  reason["ext3_mark_inode_dirty "] = "EXT3 marking inode dirty";
+
+  priority["ext3_unlink "] = 3;
+  reason["ext3_unlink "] = "EXT3 unlinking file";
+
+  priority["ext3_create"] = 3;
+  reason["ext3_create"] = "EXT3 Creating a file";
+
+  priority["log_do_checkpoint"] = 3;
+  reason["log_do_checkpoint"] = "EXT3 journal checkpoint";
+
+  priority["generic_delete_inode"] = 3;
+  reason["generic_delete_inode"] = "Deleting an inode";
+
+  priority["proc_delete_inode"] = 3;
+  reason["proc_delete_inode"] = "Removing /proc file";
+
+  priority["do_truncate"] = 3;
+  reason["do_truncate"] = "Truncating file";
+
+  priority["sys_execve"] = 3;
+  reason["sys_execve"] = "Executing a program";
+
+  priority["journal_commit_transaction"] = 3;
+  reason["journal_commit_transaction"] = "EXT3: committing transaction";
+
+  priority["__stop_machine_run"] = 3;
+  reason["__stop_machine_run"] = "Freezing the kernel (for module load)";
+
+  priority["sys_munmap"] = 3;
+  reason["sys_munmap"] = "unmapping memory";
+
+  priority["sys_mmap"] = 3;
+  reason["sys_mmap"] = "mmaping memory";
+
+  priority["sync_buffer"] = 3;
+  reason["sync_buffer"] = "Writing buffer to disk (synchronous)";
+
+  priority["inotify_inode_queue_event"] = 3;
+  reason["inotify_inode_queue_event"] = "Inotify event";
+
+  priority["proc_lookup"] = 3;
+  reason["proc_lookup"] = "Looking up /proc file";
+
+  priority["generic_make_request"] = 3;
+  reason["generic_make_request"] = "Creating block layer request";
+
+  priority["get_request_wait"] = 3;
+  reason["get_request_wait"] = "Creating block layer request";
+
+  priority["alloc_page_vma"] = 3;
+  reason["alloc_page_vma"] = "Allocating a VMA";
+
+  priority["blkdev_direct_IO"] = 3;
+  reason["blkdev_direct_IO"] = "Direct block device IO";
+
+  priority["sys_mprotect"] = 3;
+  reason["sys_mprotect"] = "mprotect() system call";
+
+  priority["shrink_icache_memory"] = 3;
+  reason["shrink_icache_memory"] = "reducing inode cache memory footprint";
+
+  priority["vfs_stat_fd"] = 3;
+  reason["vfs_stat_fd"] = "stat() operation";
+
+  priority["cdrom_open"] = 3;
+  reason["cdrom_open"] = "opening cdrom device";
+
+  priority["sys_epoll_wait"] = 3;
+  reason["sys_epoll_wait"] = "Waiting for event (epoll)";
+
+  priority["sync_sb_inodes"] = 3;
+  reason["sync_sb_inodes"] = "Syncing inodes";
+
+  priority["tcp_connect"] = 3;
+  reason["tcp_connect"] = "TCP/IP connect";
+
+  priority["ata_scsi_ioctl"] = 3;
+  reason["ata_scsi_ioctl"] = "ATA/SCSI disk ioctl";
+
+  priority["do_rmdir"] = 3;
+  reason["do_rmdir"] = "Removing directory";
+
+  priority["vfs_rmdir"] = 3;
+  reason["vfs_rmdir"] = "Removing directory";
+
+  priority["sys_flock"] = 3;
+  reason["sys_flock"] = "flock() on a file";
+
+  priority["usbdev_open"] = 3;
+  reason["usbdev_open"] = "opening USB device";
+
+  priority["lock_kernel"] = 3;
+  reason["lock_kernel"] = "Big Kernel Lock contention";
+
+  priority["blk_execute_rq"] = 3;
+  reason["blk_execute_rq"] = "Submitting block IO";
+
+  priority["scsi_cmd_ioctl"] = 3;
+  reason["scsi_cmd_ioctl"] = "SCSI ioctl command";
+
+  priority["acpi_ec_transaction"] = 3;
+  reason["acpi_ec_transaction"] = "ACPI hardware access";
+
+  priority["journal_get_undo_access"] = 3;
+  reason["journal_get_undo_access"] = "Waiting for EXT3 journal undo operation";
+
+  priority["i915_irq_wait"] = 3;
+  reason["i915_irq_wait"] = "Waiting for GPU interrupt";
+
+  priority["i915_gem_throttle_ioctl"] = 3;
+  reason["i915_gem_throttle_ioctl"] = "Throttling GPU while waiting for commands";
+
+  priority["do_page_fault"] = 5;
+  reason["do_page_fault"] = "Page fault";
+
+  priority["handle_mm_fault"] = 5;
+  reason["handle_mm_fault"] = "Page fault";
+
+  priority["filemap_fault"] = 5;
+  reason["filemap_fault"] = "Page fault";
+
+  priority["sync_filesystems"] = 5;
+  reason["sync_filesystems"] = "Syncing filesystem";
+
+  priority["sys_nanosleep"] = 5;
+  reason["sys_nanosleep"] = "Application requested delay";
+
+  priority["sys_pause"] = 5;
+  reason["sys_pause"] = "Application requested delay";
+
+  priority["evdev_read"] = 5;
+  reason["evdev_read"] = "Reading keyboard/mouse input";
+
+  priority["do_fsync"] = 5;
+  reason["do_fsync"] = "fsync() on a file";
+
+  priority["__log_wait_for_space"] = 5;
+  reason["__log_wait_for_space"] = "Waiting for EXT3 journal space";
+
 }
-- 
2.43.5