From 0b12a8cd2ea7700fa9b96930947b7844cca0aab9 Mon Sep 17 00:00:00 2001 From: "Frank Ch. Eigler" Date: Mon, 1 Feb 2010 15:39:01 -0500 Subject: new sample for sandeen@redhat.com: fntimes.stp --- .../systemtap.examples/profiling/fntimes.meta | 6 +++++ testsuite/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 (limited to 'testsuite/systemtap.examples') 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) + } +} -- cgit From f503d3c056dd8cba03e0cf58a260655225ffe0b4 Mon Sep 17 00:00:00 2001 From: "Frank Ch. Eigler" Date: Mon, 1 Feb 2010 15:39:44 -0500 Subject: regen sample indexes --- testsuite/systemtap.examples/index.html | 3 +++ testsuite/systemtap.examples/index.txt | 9 +++++++++ testsuite/systemtap.examples/keyword-index.html | 3 +++ testsuite/systemtap.examples/keyword-index.txt | 9 +++++++++ 4 files changed, 24 insertions(+) (limited to 'testsuite/systemtap.examples') 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: SYSCALL
  • process/wait4time.stp - Trace Time Spent in wait4 Syscalls
    keywords: SYSCALL WAIT4

    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".

    • +
  • 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

    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.

    • 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: IO process/pf2.stp - Profile kernel functions
    keywords: PROFILING

    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.

    +
  • 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

    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.

    • 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 -- cgit