From 0b12a8cd2ea7700fa9b96930947b7844cca0aab9 Mon Sep 17 00:00:00 2001
From: "Frank Ch. Eigler" <fche@elastic.org>
Date: Mon, 1 Feb 2010 15:39:01 -0500
Subject: [PATCH] new sample for sandeen@redhat.com: fntimes.stp

---
 .../systemtap.examples/profiling/fntimes.meta |  6 ++++
 .../systemtap.examples/profiling/fntimes.stp  | 30 +++++++++++++++++++
 2 files changed, 36 insertions(+)
 create mode 100644 testsuite/systemtap.examples/profiling/fntimes.meta
 create mode 100755 testsuite/systemtap.examples/profiling/fntimes.stp

diff --git a/testsuite/systemtap.examples/profiling/fntimes.meta b/testsuite/systemtap.examples/profiling/fntimes.meta
new file mode 100644
index 000000000..4b4ff1ed3
--- /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 000000000..e9daac773
--- /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)
+   }
+}
-- 
2.43.5