From 98e3200120ee4e1c5437012dd486e51ad31a0171 Mon Sep 17 00:00:00 2001 From: "Frank Ch. Eigler" Date: Fri, 13 Feb 2015 17:41:41 -0500 Subject: [PATCH] linetimes sample: revise, add sample screenshot, _bestify The callgraph-printing logic is much simplified by the recent addition of array-slice operations. --- .../profiling/linetimes.meta | 2 +- .../profiling/linetimes.stp | 32 ++---- .../profiling/linetimes.txt | 97 +++++++++++++++++++ 3 files changed, 106 insertions(+), 25 deletions(-) create mode 100644 testsuite/systemtap.examples/profiling/linetimes.txt diff --git a/testsuite/systemtap.examples/profiling/linetimes.meta b/testsuite/systemtap.examples/profiling/linetimes.meta index deda4179e..9bf791fdf 100644 --- a/testsuite/systemtap.examples/profiling/linetimes.meta +++ b/testsuite/systemtap.examples/profiling/linetimes.meta @@ -2,7 +2,7 @@ title: Show Time Spent on Each Line of a Function name: linetimes.stp version: 1.0 author: William Cohen -keywords: profiling +keywords: profiling _best subsystem: any status: production exit: user-controlled diff --git a/testsuite/systemtap.examples/profiling/linetimes.stp b/testsuite/systemtap.examples/profiling/linetimes.stp index 2d7d60df4..bb7673def 100755 --- a/testsuite/systemtap.examples/profiling/linetimes.stp +++ b/testsuite/systemtap.examples/profiling/linetimes.stp @@ -1,6 +1,6 @@ #! /usr/bin/env stap # -# Copyright (C) 2010 Red Hat, Inc. +# Copyright (C) 2010-2015 Red Hat, Inc. # Written by William Cohen # # The linetimes.stp script takes two arguments: where to find the function @@ -43,34 +43,18 @@ probe $1.statement(@2 "@*:*") { } probe end { - printf("\n%s called %d", @2, @count(calls)); + printf("\n%s %s call count: %d\n", @1, @2, @count(calls)); printf("\n%-58s %10s %10s\n", "region", "avg(us)", "max(us)"); foreach (p+ in region) { printf("%-58s %10d %10d\n", p, @avg(region[p]), @max(region[p])); } - printf("\ncontrol flow graph information\n") + printf("\n\ncontrol flow graph information\n") printf("from\n\tto\n=======================\n") - foreach ([src+, dest] in cfg) { - /* print elements */ - if (old_src != src) { - if (count == 1) printf (" %d\n", old_count); - printf ("%-s", src) - count = 1 - } else { - if (count == 1) { - if (old_dest == src) - printf ("\n\t%-s %d\n", old_dest, old_count); - else - printf ("\n\t%-s %d\n", old_dest, old_count); - } - ++count; - printf ("\t%-s %d\n", dest, @count(cfg[src,dest])); - } - old_src = src - old_dest = dest - old_count = @count(cfg[src,dest]) + foreach ([src+] in region) { + printf("%-s\n", src) + foreach ([s,dest+] in cfg[src,*]) { # slice for all dest's + printf("\t%-s %d\n", dest, @count(cfg[src,dest])); + } } - /* print last element */ - if (old_src != "" && count == 1) printf (" %d\n", old_count) } diff --git a/testsuite/systemtap.examples/profiling/linetimes.txt b/testsuite/systemtap.examples/profiling/linetimes.txt new file mode 100644 index 000000000..f9973a741 --- /dev/null +++ b/testsuite/systemtap.examples/profiling/linetimes.txt @@ -0,0 +1,97 @@ +# stap linetimes.stp kernel tcp_sendmsg -c 'sleep 30' +kernel tcp_sendmsg call count: 2366 + +region avg(us) max(us) +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1088") 1 32 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1093") 1 31 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1099") 1 16 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1100") 1 62 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1109") 1 32 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1115") 1 15 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1121") 1 62 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1135") 1 32 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1137") 1 52 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1140") 1 22 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1141") 1 15 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1142") 1 21 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1145") 1 53 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1148") 1 50 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1150") 1 42 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1151") 1 72 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1152") 1 51 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1155") 1 51 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1165") 1 57 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1167") 1 79 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1170") 1 52 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1171") 1 3 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1173") 1 2 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1176") 1 3 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1184") 1 52 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1187") 1 92 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1193") 1 62 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1194") 1 10 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1197") 1 63 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1198") 1 32 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1204") 1 42 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1209") 1 42 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1210") 1 31 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1213") 1 49 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1215") 1 62 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1259") 1 32 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1260") 1 52 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1262") 1 61 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1263") 1 112 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1264") 1 12 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1266") 1 31 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1267") 1 62 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1268") 1 52 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1273") 1 52 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1276") 1 51 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1279") 1 12 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1280") 3 55 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1298") 1 112 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1299") 5 83 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1301") 2 56 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1302") 1 52 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1321") 1 53 + + +control flow graph information +from + to +======================= +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1088") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1099") 2366 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1204") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1198") 3800 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1165") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1167") 2366 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1276") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1279") 1504 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1184") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1187") 3800 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1099") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1093") 2366 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1193") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1194") 220 + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1197") 3580 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1141") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1140") 2366 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1263") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1266") 3870 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1150") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1151") 2366 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1140") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1148") 2366 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1302") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1321") 2366 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1088") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1099") 2366 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1209") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1210") 3870 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1268") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1273") 1504 + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1298") 2366 +kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1299") + kernel.statement("tcp_sendmsg@net/ipv4/tcp.c:1301") 2366 + -- 2.43.5