From 34029cd3afe690f8481f8921047ec39dc325d945 Mon Sep 17 00:00:00 2001
From: William Cohen <wcohen@redhat.com>
Date: Wed, 20 May 2009 17:52:44 -0400
Subject: Add the schedtimes.stp and associated schedtimes.meta files to the
 examples.

---
 testsuite/systemtap.examples/index.html            |   3 +
 testsuite/systemtap.examples/index.txt             |  10 ++
 testsuite/systemtap.examples/keyword-index.html    |  12 ++
 testsuite/systemtap.examples/keyword-index.txt     |  40 ++++++
 .../systemtap.examples/process/schedtimes.meta     |  13 ++
 .../systemtap.examples/process/schedtimes.stp      | 154 +++++++++++++++++++++
 6 files changed, 232 insertions(+)
 create mode 100644 testsuite/systemtap.examples/process/schedtimes.meta
 create mode 100755 testsuite/systemtap.examples/process/schedtimes.stp

(limited to 'testsuite/systemtap.examples')

diff --git a/testsuite/systemtap.examples/index.html b/testsuite/systemtap.examples/index.html
index 0df681ac..e5673138 100644
--- a/testsuite/systemtap.examples/index.html
+++ b/testsuite/systemtap.examples/index.html
@@ -112,6 +112,9 @@ keywords: <a href="keyword-index.html#SYSCALL">SYSCALL</a> <a href="keyword-inde
 <li><a href="process/pf2.stp">process/pf2.stp</a> - Profile kernel functions<br>
 keywords: <a href="keyword-index.html#PROFILING">PROFILING</a> <br>
 <p>The pf2.stp script sets up time-based sampling. Every five seconds it prints out a sorted list with the top ten kernel functions with samples.</p></li>
+<li><a href="process/schedtimes.stp">process/schedtimes.stp</a> - Track Time Processes Spend in Various States using Tracepoints<br>
+keywords: <a href="keyword-index.html#PROCESS">PROCESS</a> <a href="keyword-index.html#SCHEDULER">SCHEDULER</a> <a href="keyword-index.html#TIME">TIME</a> <a href="keyword-index.html#TRACEPOINT">TRACEPOINT</a> <br>
+<p>The schedtimes.stp script instruments the scheduler to track the amount of time that each process spends running, sleeping, queued, and waiting for io. On exit the script prints out the accumulated time for each state of processes observed.  Optionally, this script can be used with the '-c' or '-x' options to focus on a specific PID.</p></li>
 <li><a href="process/sig_by_pid.stp">process/sig_by_pid.stp</a> -  Signal Counts by Process ID<br>
 keywords: <a href="keyword-index.html#SIGNALS">SIGNALS</a> <br>
 <p>Print signal counts by process ID in descending order.</p></li>
diff --git a/testsuite/systemtap.examples/index.txt b/testsuite/systemtap.examples/index.txt
index fa344933..4eef904c 100644
--- a/testsuite/systemtap.examples/index.txt
+++ b/testsuite/systemtap.examples/index.txt
@@ -224,6 +224,16 @@ keywords: profiling
   samples.
 
 
+process/schedtimes.stp - Track Time Processes Spend in Various States using Tracepoints
+keywords: process scheduler time tracepoint
+
+  The schedtimes.stp script instruments the scheduler to track the
+  amount of time that each process spends running, sleeping, queued,
+  and waiting for io. On exit the script prints out the accumulated
+  time for each state of processes observed.  Optionally, this script
+  can be used with the '-c' or '-x' options to focus on a specific PID.
+
+
 process/sig_by_pid.stp -  Signal Counts by Process ID
 keywords: signals
 
diff --git a/testsuite/systemtap.examples/keyword-index.html b/testsuite/systemtap.examples/keyword-index.html
index 7edbec21..b7f52246 100644
--- a/testsuite/systemtap.examples/keyword-index.html
+++ b/testsuite/systemtap.examples/keyword-index.html
@@ -189,6 +189,9 @@ keywords: <a href="keyword-index.html#NETWORK">NETWORK</a> <a href="keyword-inde
 <li><a href="process/errsnoop.stp">process/errsnoop.stp</a> - tabulate system call errors<br>
 keywords: <a href="keyword-index.html#PROCESS">PROCESS</a> <a href="keyword-index.html#SYSCALL">SYSCALL</a> <br>
 <p>The script prints a periodic tabular report about failing system calls, by process and by syscall failure.  The first optional argument specifies the reporting interval (in seconds, default 5); the second optional argument gives a screen height (number of lines in the report, default 20).</p></li>
+<li><a href="process/schedtimes.stp">process/schedtimes.stp</a> - Track Time Processes Spend in Various States using Tracepoints<br>
+keywords: <a href="keyword-index.html#PROCESS">PROCESS</a> <a href="keyword-index.html#SCHEDULER">SCHEDULER</a> <a href="keyword-index.html#TIME">TIME</a> <a href="keyword-index.html#TRACEPOINT">TRACEPOINT</a> <br>
+<p>The schedtimes.stp script instruments the scheduler to track the amount of time that each process spends running, sleeping, queued, and waiting for io. On exit the script prints out the accumulated time for each state of processes observed.  Optionally, this script can be used with the '-c' or '-x' options to focus on a specific PID.</p></li>
 </ul>
 <h3><a name="PROFILING">PROFILING</a></h3>
 <ul>
@@ -219,6 +222,9 @@ keywords: <a href="keyword-index.html#SYSCALL">SYSCALL</a> <a href="keyword-inde
 </ul>
 <h3><a name="SCHEDULER">SCHEDULER</a></h3>
 <ul>
+<li><a href="process/schedtimes.stp">process/schedtimes.stp</a> - Track Time Processes Spend in Various States using Tracepoints<br>
+keywords: <a href="keyword-index.html#PROCESS">PROCESS</a> <a href="keyword-index.html#SCHEDULER">SCHEDULER</a> <a href="keyword-index.html#TIME">TIME</a> <a href="keyword-index.html#TRACEPOINT">TRACEPOINT</a> <br>
+<p>The schedtimes.stp script instruments the scheduler to track the amount of time that each process spends running, sleeping, queued, and waiting for io. On exit the script prints out the accumulated time for each state of processes observed.  Optionally, this script can be used with the '-c' or '-x' options to focus on a specific PID.</p></li>
 <li><a href="process/sleepingBeauties.stp">process/sleepingBeauties.stp</a> - Generating Backtraces of Threads Waiting for IO Operations<br>
 keywords: <a href="keyword-index.html#IO">IO</a> <a href="keyword-index.html#SCHEDULER">SCHEDULER</a> <a href="keyword-index.html#BACKTRACE">BACKTRACE</a> <br>
 <p>The script monitors the time that threads spend waiting for IO operations (in "D" state) in the wait_for_completion function.  If a thread spends over 10ms, its name and backtrace is printed, and later so is the total delay.</p></li>
@@ -294,6 +300,9 @@ keywords: <a href="keyword-index.html#NETWORK">NETWORK</a> <a href="keyword-inde
 <li><a href="io/iotime.stp">io/iotime.stp</a> - Trace Time Spent in Read and Write for Files <br>
 keywords: <a href="keyword-index.html#SYSCALL">SYSCALL</a> <a href="keyword-index.html#READ">READ</a> <a href="keyword-index.html#WRITE">WRITE</a> <a href="keyword-index.html#TIME">TIME</a> <a href="keyword-index.html#IO">IO</a> <br>
 <p>The script watches each open, close, read, and write syscalls on the system. For each file the scripts observes opened it accumulates the amount of wall clock time spend in read and write operations and the number of bytes read and written. When a file is closed the script prints out a pair of lines for the file. Both lines begin with a timestamp in microseconds, the PID number, and the executable name in parenthesese. The first line with the "access" keyword lists the file name, the attempted number of bytes for the read and write operations. The second line with the "iotime" keyword list the file name and the number of microseconds accumulated in the read and write syscalls.</p></li>
+<li><a href="process/schedtimes.stp">process/schedtimes.stp</a> - Track Time Processes Spend in Various States using Tracepoints<br>
+keywords: <a href="keyword-index.html#PROCESS">PROCESS</a> <a href="keyword-index.html#SCHEDULER">SCHEDULER</a> <a href="keyword-index.html#TIME">TIME</a> <a href="keyword-index.html#TRACEPOINT">TRACEPOINT</a> <br>
+<p>The schedtimes.stp script instruments the scheduler to track the amount of time that each process spends running, sleeping, queued, and waiting for io. On exit the script prints out the accumulated time for each state of processes observed.  Optionally, this script can be used with the '-c' or '-x' options to focus on a specific PID.</p></li>
 </ul>
 <h3><a name="TRACE">TRACE</a></h3>
 <ul>
@@ -306,6 +315,9 @@ keywords: <a href="keyword-index.html#TRACE">TRACE</a> <a href="keyword-index.ht
 <li><a href="network/dropwatch.stp">network/dropwatch.stp</a> - Watch Where Socket Buffers are Freed in the Kernel<br>
 keywords: <a href="keyword-index.html#NETWORK">NETWORK</a> <a href="keyword-index.html#TRACEPOINT">TRACEPOINT</a> <a href="keyword-index.html#BUFFER">BUFFER</a> <a href="keyword-index.html#FREE">FREE</a> <br>
 <p>Every five seconds the dropwatch.stp script lists the number of socket buffers freed at locations in the kernel.</p></li>
+<li><a href="process/schedtimes.stp">process/schedtimes.stp</a> - Track Time Processes Spend in Various States using Tracepoints<br>
+keywords: <a href="keyword-index.html#PROCESS">PROCESS</a> <a href="keyword-index.html#SCHEDULER">SCHEDULER</a> <a href="keyword-index.html#TIME">TIME</a> <a href="keyword-index.html#TRACEPOINT">TRACEPOINT</a> <br>
+<p>The schedtimes.stp script instruments the scheduler to track the amount of time that each process spends running, sleeping, queued, and waiting for io. On exit the script prints out the accumulated time for each state of processes observed.  Optionally, this script can be used with the '-c' or '-x' options to focus on a specific PID.</p></li>
 </ul>
 <h3><a name="TRAFFIC">TRAFFIC</a></h3>
 <ul>
diff --git a/testsuite/systemtap.examples/keyword-index.txt b/testsuite/systemtap.examples/keyword-index.txt
index b53e776f..c0082e36 100644
--- a/testsuite/systemtap.examples/keyword-index.txt
+++ b/testsuite/systemtap.examples/keyword-index.txt
@@ -337,6 +337,16 @@ keywords: process syscall
   in the report, default 20).
 
 
+process/schedtimes.stp - Track Time Processes Spend in Various States using Tracepoints
+keywords: process scheduler time tracepoint
+
+  The schedtimes.stp script instruments the scheduler to track the
+  amount of time that each process spends running, sleeping, queued,
+  and waiting for io. On exit the script prints out the accumulated
+  time for each state of processes observed.  Optionally, this script
+  can be used with the '-c' or '-x' options to focus on a specific PID.
+
+
 = PROFILING =
 
 io/iostats.stp - List Executables Reading and Writing the Most Data
@@ -417,6 +427,16 @@ keywords: syscall read write time io
 
 = SCHEDULER =
 
+process/schedtimes.stp - Track Time Processes Spend in Various States using Tracepoints
+keywords: process scheduler time tracepoint
+
+  The schedtimes.stp script instruments the scheduler to track the
+  amount of time that each process spends running, sleeping, queued,
+  and waiting for io. On exit the script prints out the accumulated
+  time for each state of processes observed.  Optionally, this script
+  can be used with the '-c' or '-x' options to focus on a specific PID.
+
+
 process/sleepingBeauties.stp - Generating Backtraces of Threads Waiting for IO Operations
 keywords: io scheduler backtrace
 
@@ -606,6 +626,16 @@ keywords: syscall read write time io
   syscalls.
 
 
+process/schedtimes.stp - Track Time Processes Spend in Various States using Tracepoints
+keywords: process scheduler time tracepoint
+
+  The schedtimes.stp script instruments the scheduler to track the
+  amount of time that each process spends running, sleeping, queued,
+  and waiting for io. On exit the script prints out the accumulated
+  time for each state of processes observed.  Optionally, this script
+  can be used with the '-c' or '-x' options to focus on a specific PID.
+
+
 = TRACE =
 
 general/para-callgraph.stp - Callgraph tracing with arguments
@@ -628,6 +658,16 @@ keywords: network tracepoint buffer free
   socket buffers freed at locations in the kernel.
 
 
+process/schedtimes.stp - Track Time Processes Spend in Various States using Tracepoints
+keywords: process scheduler time tracepoint
+
+  The schedtimes.stp script instruments the scheduler to track the
+  amount of time that each process spends running, sleeping, queued,
+  and waiting for io. On exit the script prints out the accumulated
+  time for each state of processes observed.  Optionally, this script
+  can be used with the '-c' or '-x' options to focus on a specific PID.
+
+
 = TRAFFIC =
 
 network/nettop.stp - Periodic Listing of Processes Using Network Interfaces
diff --git a/testsuite/systemtap.examples/process/schedtimes.meta b/testsuite/systemtap.examples/process/schedtimes.meta
new file mode 100644
index 00000000..0074731f
--- /dev/null
+++ b/testsuite/systemtap.examples/process/schedtimes.meta
@@ -0,0 +1,13 @@
+title: Track Time Processes Spend in Various States using Tracepoints
+name: schedtimes.stp
+version: 1.0
+author: Jason Baron
+keywords: process scheduler time tracepoint
+subsystem: scheduler
+status: production
+exit: user-controlled
+output: sorted-list
+scope: system-wide
+description: The schedtimes.stp script instruments the scheduler to track the amount of time that each process spends running, sleeping, queued, and waiting for io. On exit the script prints out the accumulated time for each state of processes observed.  Optionally, this script can be used with the '-c' or '-x' options to focus on a specific PID.
+test_check: stap -p4 schedtimes.stp
+test_installcheck: stap schedtimes.stp -c "sleep 1"
diff --git a/testsuite/systemtap.examples/process/schedtimes.stp b/testsuite/systemtap.examples/process/schedtimes.stp
new file mode 100755
index 00000000..e964dd58
--- /dev/null
+++ b/testsuite/systemtap.examples/process/schedtimes.stp
@@ -0,0 +1,154 @@
+#! /usr/bin/env stap
+
+############################################################
+# Schedtimes.stp
+# Author: Jason Baron <jbaron@redhat.com>
+# profiles threads and displays their run times, queued times,
+# wait times, including i/o wait times.
+# Has two modes. When no arguments are given it profiles all
+# threads. Alternatively, you can pass -c "program name"
+############################################################
+
+//constants
+global RUNNING=0, QUEUED=1, SLEEPING=2
+
+global traced_pid
+global run_time, queued_time,  sleep_time, io_wait_time
+global pid_state, pid_names
+global previous_timestamp
+global io_wait_count
+global io_wait_incremented
+
+function get_iowait:long(queue:long)
+{
+  return @cast(queue,"rq","kernel")->nr_iowait->counter;
+}
+
+probe kernel.trace("sched_switch") {
+  previous_pid = $prev->pid;
+  next_pid = $next->pid;
+  if (traced_pid) {
+    if (previous_pid != traced_pid) {
+      previous_pid = 0;
+    }
+    if (next_pid != traced_pid) {
+      next_pid = 0;
+    }
+  }
+  if (previous_pid) {
+    if (!([previous_pid] in pid_state)) {
+      //use this state as entry into state machine
+      previous_timestamp[previous_pid] = gettimeofday_us();
+      pid_names[previous_pid] = kernel_string($prev->comm);
+      if ($prev->state > 0) {
+        pid_state[previous_pid] = SLEEPING;
+      } else if ($prev->state == 0) {
+        pid_state[previous_pid] = QUEUED;
+      } else {
+        printf("unknown transition:\n");
+        printf("pid state: %d our state: %d\n",
+          $prev->state, pid_state[previous_pid]);
+      }
+    } else if (pid_state[previous_pid] == RUNNING) {
+      pid_names[previous_pid] = kernel_string($prev->comm);
+      t = gettimeofday_us();  
+      run_time[previous_pid] += (t - previous_timestamp[previous_pid]);
+      previous_timestamp[previous_pid] = t;
+      if ($prev->state > 0) {
+        if ((get_iowait($rq) - io_wait_count[previous_pid]) > 0)
+          io_wait_incremented[previous_pid] = 1;  
+        pid_state[previous_pid] = SLEEPING;
+      } else if ($prev->state == 0) {
+        pid_state[previous_pid] = QUEUED;
+      } else {
+        printf("unknown transition:\n");
+        printf("pid state: %d our state: %d\n",
+          $prev->state, pid_state[previous_pid]);
+      }
+    } else {
+      printf("unknown transition:\n");
+      printf("%s pid state: %d our state: %d\n",
+           pid_names[previous_pid],
+           $prev->state, pid_state[previous_pid]);
+    }
+  }
+  if (next_pid) {
+    io_wait_count[next_pid] = get_iowait($rq);
+    if (!([next_pid] in pid_state)) {
+      //use this state as entry into state machine
+      previous_timestamp[next_pid] =  gettimeofday_us();
+      pid_state[next_pid] = RUNNING;
+      pid_names[next_pid] = kernel_string($next->comm);
+    } else if (pid_state[next_pid] == QUEUED) {
+      t = gettimeofday_us();
+      queued_time[next_pid] += (t - previous_timestamp[next_pid]);
+      previous_timestamp[next_pid] = t;
+      pid_state[next_pid] = RUNNING;
+      pid_names[next_pid] = kernel_string($next->comm);
+    } else {
+      printf("unknown transition:\n");
+      printf("%s pid state: %d our state: %d\n",
+        pid_names[next_pid],
+        $next->state, pid_state[next_pid]);
+    }
+  }
+}
+
+probe kernel.trace("sched_wakeup") {
+  wakeup_pid = $p->pid;
+  if (traced_pid && (wakeup_pid != traced_pid)) next
+  if ((!$success) && (pid_state[wakeup_pid] != SLEEPING)) next
+  if (!wakeup_pid) next
+
+  if (!([wakeup_pid] in pid_state)) {
+    //use this state as entry into state machine
+    previous_timestamp[wakeup_pid] =  gettimeofday_us();
+    pid_state[wakeup_pid] = QUEUED;
+    pid_names[wakeup_pid] = kernel_string($p->comm);
+  } else if (pid_state[wakeup_pid] == SLEEPING) {
+    t = gettimeofday_us();
+    sleep_time[wakeup_pid] += (t - previous_timestamp[wakeup_pid]);
+    if (io_wait_incremented[wakeup_pid] == 1) {
+      io_wait_time[wakeup_pid] += (t - previous_timestamp[wakeup_pid]);
+      io_wait_incremented[wakeup_pid] = 0;
+    }
+    previous_timestamp[wakeup_pid] = t;
+    pid_state[wakeup_pid] = QUEUED;
+    pid_names[wakeup_pid] = kernel_string($p->comm);
+  } else {
+    printf("unknown transition:\n");
+    printf("pid state: %d our state: %d\n",
+      $p->state, pid_state[wakeup_pid]);
+  }
+}
+
+probe begin {
+  traced_pid = target();
+  if (traced_pid == 0) {
+    printf("all mode\n");
+  } else {
+    printf("target mode\n");
+    printf("traced pid: %d\n", traced_pid);
+  }
+}
+
+probe end {
+  t = gettimeofday_us();
+  foreach (pid in pid_state) {
+    if (pid_state[pid] == SLEEPING)
+      sleep_time[pid] += (t - previous_timestamp[pid]);
+    if (pid_state[pid] == QUEUED)
+      queued_time[pid] += (t - previous_timestamp[pid]);
+    if (pid_state[pid] == RUNNING)
+      run_time[pid] += (t - previous_timestamp[pid]);
+  }
+  printf ("%16s: %6s %10s %10s %10s %10s %10s\n\n",
+         "execname", "pid", "run(us)", "sleep(us)", "io_wait(us)",
+         "queued(us)", "total(us)")
+  foreach (pid+ in run_time) {
+    printf("%16s: %6d %10d %10d %10d %10d %10d\n", 
+      pid_names[pid], pid, run_time[pid], sleep_time[pid], 
+      io_wait_time[pid], queued_time[pid],
+      (run_time[pid] + sleep_time[pid] + queued_time[pid]));
+  }
+}
-- 
cgit