Merge branch 'master' of ssh://sources.redhat.com/git/systemtap

6 files changed, 60 insertions, 0 deletions

diff --git a/testsuite/systemtap.examples/index.html b/testsuite/systemtap.examples/index.html
index 5b4ef659..294c6991 100644
--- a/testsuite/systemtap.examples/index.html
+++ b/testsuite/systemtap.examples/index.html
@@ -211,6 +211,9 @@ keywords: <a href="keyword-index.html#SYSCALL">SYSCALL</a> <br>
 <li><a href="process/wait4time.stp">process/wait4time.stp</a> - Trace Time Spent in wait4 Syscalls<br>
 keywords: <a href="keyword-index.html#SYSCALL">SYSCALL</a> <a href="keyword-index.html#WAIT4">WAIT4</a> <br>
 <p>The script watches each wait4 syscall on the system. At the end of each wait4 syscall the script prints out a line with a timestamp in microseconds, the pid, the executable name in parentheses, the "wait4:" key, the duration of the wait and the PID that the wait4 was waiting for. If the waited for PID is not specified , it is "-1".</p></li>
+<li><a href="profiling/fntimes.stp">profiling/fntimes.stp</a> - Show functions taking longer than usual<br>
+keywords: <a href="keyword-index.html#PROFILING">PROFILING</a> <br>
+<p>The fntimes.stp script monitors the execution time history of a given function family (assumed non-recursive).  Each time (beyond a warmup interval) is then compared to the historical maximum.  If it exceeds a certain threshold (250%), a message is printed.</p></li>
 <li><a href="profiling/functioncallcount.stp">profiling/functioncallcount.stp</a> - Count Times Functions Called<br>
 keywords: <a href="keyword-index.html#PROFILING">PROFILING</a> <a href="keyword-index.html#FUNCTIONS">FUNCTIONS</a> <br>
 <p>The functioncallcount.stp script takes one argument, a list of functions to probe. The script will run and count the number of times that each of the functions on the list is called. On exit the script will print a sorted list from most frequently to least frequently called function.</p></li>
diff --git a/testsuite/systemtap.examples/index.txt b/testsuite/systemtap.examples/index.txt
index 48494841..ebcd17a3 100644
--- a/testsuite/systemtap.examples/index.txt
+++ b/testsuite/systemtap.examples/index.txt
@@ -526,6 +526,15 @@ keywords: syscall wait4
   waiting for. If the waited for PID is not specified , it is "-1".
 
 
+profiling/fntimes.stp - Show functions taking longer than usual
+keywords: profiling
+
+  The fntimes.stp script monitors the execution time history of a given
+  function family (assumed non-recursive).  Each time (beyond a warmup
+  interval) is then compared to the historical maximum.  If it exceeds
+  a certain threshold (250%), a message is printed.
+
+
 profiling/functioncallcount.stp - Count Times Functions Called
 keywords: profiling functions
 
diff --git a/testsuite/systemtap.examples/keyword-index.html b/testsuite/systemtap.examples/keyword-index.html
index c33c56ef..39d29031 100644
--- a/testsuite/systemtap.examples/keyword-index.html
+++ b/testsuite/systemtap.examples/keyword-index.html
@@ -333,6 +333,9 @@ keywords: <a href="keyword-index.html#IO">IO</a> <a href="keyword-index.html#PRO
 <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="profiling/fntimes.stp">profiling/fntimes.stp</a> - Show functions taking longer than usual<br>
+keywords: <a href="keyword-index.html#PROFILING">PROFILING</a> <br>
+<p>The fntimes.stp script monitors the execution time history of a given function family (assumed non-recursive).  Each time (beyond a warmup interval) is then compared to the historical maximum.  If it exceeds a certain threshold (250%), a message is printed.</p></li>
 <li><a href="profiling/functioncallcount.stp">profiling/functioncallcount.stp</a> - Count Times Functions Called<br>
 keywords: <a href="keyword-index.html#PROFILING">PROFILING</a> <a href="keyword-index.html#FUNCTIONS">FUNCTIONS</a> <br>
 <p>The functioncallcount.stp script takes one argument, a list of functions to probe. The script will run and count the number of times that each of the functions on the list is called. On exit the script will print a sorted list from most frequently to least frequently called function.</p></li>
diff --git a/testsuite/systemtap.examples/keyword-index.txt b/testsuite/systemtap.examples/keyword-index.txt
index 4a9d5ccb..96ad06bd 100644
--- a/testsuite/systemtap.examples/keyword-index.txt
+++ b/testsuite/systemtap.examples/keyword-index.txt
@@ -697,6 +697,15 @@ keywords: profiling
   samples.
 
 
+profiling/fntimes.stp - Show functions taking longer than usual
+keywords: profiling
+
+  The fntimes.stp script monitors the execution time history of a given
+  function family (assumed non-recursive).  Each time (beyond a warmup
+  interval) is then compared to the historical maximum.  If it exceeds
+  a certain threshold (250%), a message is printed.
+
+
 profiling/functioncallcount.stp - Count Times Functions Called
 keywords: profiling functions
 
diff --git a/testsuite/systemtap.examples/profiling/fntimes.meta b/testsuite/systemtap.examples/profiling/fntimes.meta
new file mode 100644
index 00000000..4b4ff1ed
--- /dev/null
+++ b/testsuite/systemtap.examples/profiling/fntimes.meta
@@ -0,0 +1,6 @@
+title: Show functions taking longer than usual
+name: fntimes.stp
+keywords: profiling
+description: The fntimes.stp script monitors the execution time history of a given function family (assumed non-recursive).  Each time (beyond a warmup interval) is then compared to the historical maximum.  If it exceeds a certain threshold (250%), a message is printed.
+test_check: stap -p4 fntimes.stp 'kernel.function("sys_*")'
+test_installcheck: stap fntimes.stp 'kernel.function("sys_*")' -c "sleep 7"
diff --git a/testsuite/systemtap.examples/profiling/fntimes.stp b/testsuite/systemtap.examples/profiling/fntimes.stp
new file mode 100755
index 00000000..e9daac77
--- /dev/null
+++ b/testsuite/systemtap.examples/profiling/fntimes.stp
@@ -0,0 +1,30 @@
+#! /usr/bin/stap
+
+# usage:   fntimes.stp FUNCTIONPROBE
+# e.g.     fntimes.stp 'module("ext4").function("*")'
+
+global mincount = 100      # training: beneath this number of hits, only collect data
+global note_percent = 250  # percent beyond maximum-so-far to generate report for
+function time() { return gettimeofday_us() }    # time measurement function
+
+global times, entry
+
+probe $1.call {
+   entry[probefunc(),tid()] = time()
+}
+
+probe $1.return {
+   pf=probefunc()
+   tid=tid()
+   if ([pf,tid] in entry) {       # seen function entry?
+      t = time()-entry[pf,tid]    # t: elapsed time
+      delete entry[pf,tid]
+      if (@count(times[pf]) >= mincount 
+          && t >= @max(times[pf]) * note_percent / 100) {   # also consider @avg()
+          printf("function %s well over %s time (%d vs %d)\n",
+                 pf, "maximum", t, @max(times[pf]))
+          # also consider: print_backtrace()
+      }
+      times[pf] <<< t  # (increments @count, updates @max)
+   }
+}