[PATCH] (Naive) approach to make schedtimes follow the children of the traced process

[PATCH] (Naive) approach to make schedtimes follow the children of the traced process

[David Juran]

Hello!

I had a use case where I wanted to investigate how much time a build
process (in effect make) was spending waiting to be scheduled. The
schedtimes exampel was a good match, but since I wanted to check both
the make process itself but even more important, all the compile
processes it forked off, I did some rather ugly extension to the
schedtimes script. 
The modifications might come in useful for someone else as well but if
you do consider taking the patch, please do review it. My approach of
extending the script was rather simple...

 
---
 .../systemtap.examples/process/schedtimes.meta     |  2 +-
 .../systemtap.examples/process/schedtimes.stp      | 25 +++++++++++++++++++++-
 2 files changed, 25 insertions(+), 2 deletions(-)

diff --git a/testsuite/systemtap.examples/process/schedtimes.meta b/testsuite/systemtap.examples/process/schedtimes.meta
index 8a05d72..32428ee 100644
--- a/testsuite/systemtap.examples/process/schedtimes.meta
+++ b/testsuite/systemtap.examples/process/schedtimes.meta
@@ -8,7 +8,7 @@ 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 in running, sleeping, queuing, 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.
+description: The schedtimes.stp script instruments the scheduler to track the amount of time that each process spends in running, sleeping, queuing, 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 and it's children.
 test_support: stap -l 'kernel.trace("sched_switch")' && stap -l 'kernel.trace("sched_wakeup")'
 test_check: stap -p4 schedtimes.stp
 test_installcheck: stap schedtimes.stp -c "sleep 0.2"
diff --git a/testsuite/systemtap.examples/process/schedtimes.stp b/testsuite/systemtap.examples/process/schedtimes.stp
index da46cad..2731bc7 100755
--- a/testsuite/systemtap.examples/process/schedtimes.stp
+++ b/testsuite/systemtap.examples/process/schedtimes.stp
@@ -19,7 +19,7 @@
 //constants
 global RUNNING=0, QUEUED=1, SLEEPING=2
 
-global traced_pid
+global traced_pid, my_pids
 global run_time, queued_time,  sleep_time, io_wait_time
 global pid_state, pid_names
 global previous_timestamp
@@ -31,9 +31,27 @@ function get_iowait:long(queue:long)
   return @cast(queue,"rq","kernel")->nr_iowait->counter;
 }
 
+probe kprocess.create {
+
+  if ( pid() in my_pids) {
+    my_pids[new_pid]++;
+  }
+
+}
+
 probe kernel.trace("sched_switch") {
   previous_pid = $prev->pid;
   next_pid = $next->pid;
+  
+  #is either the interrupted or the interrupting pid in our set?
+  #Then we set traced pid to this one in order to do accounting
+  if (previous_pid in my_pids) {
+    traced_pid = previous_pid;
+  }
+  if (next_pid in my_pids) {
+    traced_pid = next_pid;
+  }
+
   if (traced_pid) {
     if (previous_pid != traced_pid) {
       previous_pid = 0;
@@ -104,6 +122,10 @@ probe kernel.trace("sched_switch") {
 
 probe kernel.trace("sched_wakeup") {
   wakeup_pid = $p->pid;
+  if (wakeup_pid in my_pids) {
+    traced_pid = wakeup_pid;
+  }
+
   if (traced_pid && (wakeup_pid != traced_pid)) next
   if ((!$success) && (pid_state[wakeup_pid] != SLEEPING)) next
   if (!wakeup_pid) next
@@ -137,6 +159,7 @@ probe begin {
   } else {
     printf("target mode\n");
     printf("traced pid: %d\n", traced_pid);
+    my_pids[traced_pid]++;
   }
 }
 
-- 
1.8.5.3

-- 
David Juran
Sr. Consultant
Red Hat
+46-725-345801

Re: [PATCH] (Naive) approach to make schedtimes follow the children of the traced process

[Josh Stone]

On 01/31/2014 02:46 AM, David Juran wrote:
> Hello!
> 
> I had a use case where I wanted to investigate how much time a build
> process (in effect make) was spending waiting to be scheduled. The
> schedtimes exampel was a good match, but since I wanted to check both
> the make process itself but even more important, all the compile
> processes it forked off, I did some rather ugly extension to the
> schedtimes script. 
> The modifications might come in useful for someone else as well but if
> you do consider taking the patch, please do review it. My approach of
> extending the script was rather simple...

Hi,

It's a reasonable modification, but you might like the target_set.stp
tapset to simplify it.  Call function target_set_pid(some_pid) to find
out if it's part of the target() and its children.


Josh

Re: [PATCH] (Naive) approach to make schedtimes follow the children of the traced process

[David Juran]

[-- Attachment #1: Type: text/plain, Size: 395 bytes --]

On fre, 2014-01-31 at 08:19 -0800, Josh Stone wrote:
> On 01/31/2014 02:46 AM, David Juran wrote:

> 
> It's a reasonable modification, but you might like the target_set.stp
> tapset to simplify it.  Call function target_set_pid(some_pid) to find
> out if it's part of the target() and its children.

Thanks, that does make it simpler (-:


-- 
David Juran
Sr. Consultant
Red Hat
+46-725-345801

[-- Attachment #2: 0002-simplified-using-target_set-tapset.patch --]
[-- Type: text/x-patch, Size: 1963 bytes --]

From c4f0acb0ff598cfcafa8efeef94db9af4b475e53 Mon Sep 17 00:00:00 2001
From: David Juran <djuran@redhat.com>
Date: Mon, 3 Feb 2014 12:57:55 +0100
Subject: [PATCH 2/2] simplified using target_set tapset

---
 testsuite/systemtap.examples/process/schedtimes.stp | 19 +++++--------------
 1 file changed, 5 insertions(+), 14 deletions(-)

diff --git a/testsuite/systemtap.examples/process/schedtimes.stp b/testsuite/systemtap.examples/process/schedtimes.stp
index 2731bc7..ba8282b 100755
--- a/testsuite/systemtap.examples/process/schedtimes.stp
+++ b/testsuite/systemtap.examples/process/schedtimes.stp
@@ -19,8 +19,8 @@
 //constants
 global RUNNING=0, QUEUED=1, SLEEPING=2
 
-global traced_pid, my_pids
-global run_time, queued_time,  sleep_time, io_wait_time
+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
@@ -31,24 +31,16 @@ function get_iowait:long(queue:long)
   return @cast(queue,"rq","kernel")->nr_iowait->counter;
 }
 
-probe kprocess.create {
-
-  if ( pid() in my_pids) {
-    my_pids[new_pid]++;
-  }
-
-}
-
 probe kernel.trace("sched_switch") {
   previous_pid = $prev->pid;
   next_pid = $next->pid;
   
   #is either the interrupted or the interrupting pid in our set?
   #Then we set traced pid to this one in order to do accounting
-  if (previous_pid in my_pids) {
+  if (target_set_pid(previous_pid)) {
     traced_pid = previous_pid;
   }
-  if (next_pid in my_pids) {
+  if (target_set_pid(next_pid)) {
     traced_pid = next_pid;
   }
 
@@ -122,7 +114,7 @@ probe kernel.trace("sched_switch") {
 
 probe kernel.trace("sched_wakeup") {
   wakeup_pid = $p->pid;
-  if (wakeup_pid in my_pids) {
+  if (target_set_pid(wakeup_pid)) {
     traced_pid = wakeup_pid;
   }
 
@@ -159,7 +151,6 @@ probe begin {
   } else {
     printf("target mode\n");
     printf("traced pid: %d\n", traced_pid);
-    my_pids[traced_pid]++;
   }
 }
 
-- 
1.8.5.3