Example looking at the periodic timers

Example looking at the periodic timers

[William Cohen]

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

One case that people would like to use SystemTap for is finding out why some latency sensitive application is slowed down every x seconds.  They know that something keeps running on the machine and slowing things down, but they don't know what it is.

I have been playing around with the timer tracepoints and came up with the attached script, periodic.stp.  When the script exits it prints out a list of the periodic timers, sorted from most frequently to least frequently fired timer. It also include the average period for the timer.  The functions that have [dg] are things put into the delayed_work_queues.

Here is the example output:


$ ./periodic.stp -c "sleep 10"
WARNING: missing unwind/symbol data for module 'uprobes'
#timer            function                              period(us)      count
0xffffe8ffffc118a8 0xffffffffa0e38d30                          1000      10000
0xffffe8ffffc918a8 0xffffffffa0e38d30                          1000      10000
0xffffe8ffffd118a8 0xffffffffa0e38d30                           999      10000
0xffffe8ffffd918a8 0xffffffffa0e38d30                           999      10000
0xffff880028216fa8 do_dbs_timer[dq]                           10000        999
0xffffffffa115e960 0xffffffffa0e38c10                         10000        999
0xffff880028296fa8 do_dbs_timer[dq]                            9999        999
0xffff880028316fa8 do_dbs_timer[dq]                           10000        999
0xffff880028396fa8 do_dbs_timer[dq]                            9999        999
0xffffffffa115e9c0 0xffffffffa0e38b50                         19999        499
0xffff880130c9fe50 monitor_timeout                           200002         49
0xffffffff81ea3b20 clocksource_watchdog                      499993         19
0xffff880028212d40 vmstat_update[dq]                         999963          9
0xffff880132cf9318 br_fdb_cleanup                            999962          9
0xffff880028292d40 vmstat_update[dq]                         999999          9
0xffff880028312d40 vmstat_update[dq]                        1000000          9
0xffff880028392d40 vmstat_update[dq]                        1000002          9
0xffff8801303c96c0 i915_gem_retire_work_handler[dq]         1000001          9
0xffff88013156e128 flush_to_ldisc[dq]                        113108          8
0xffff880130315928 flush_to_ldisc[dq]                        180399          5
0xffff8801303c97e8 intel_gpu_idle_timer                     1607001          5
0xffff880028212de0 cache_reap[dq]                           1999911          4
0xffff880132cf9228 br_hello_timer_expired                   2000003          4
0xffff880028292de0 cache_reap[dq]                           2000002          4
0xffff8801336f06e0 e1000_watchdog                           2000000          4
0xffff880028312de0 cache_reap[dq]                           1999994          4
0xffff880028392de0 cache_reap[dq]                           2000000          4
0xffff880131767e18 cupsd(10171)                             1500570          4
0xffff880130303540 intel_crtc_idle_timer                    3658003          2
0xffff8801303ca540 intel_crtc_idle_timer                    3658001          2
0xffff880134d2fdf0 bdi-default(29)                          5000032          1
0xffff8801336f0358 dev_watchdog                             5000050          1
0xffffffff81fab180 sync_supers_timer_fn                     5999999          1
0xffff88012e1b0b58 cfq_idle_slice_timer                     4152994          1
0xffff880130161dc0 ips-adjust(874)                          4999998          1
0xffff880130c21dc0 flush-253:0(1347)                        5000016          1
0xffff880130c4fdc0 flush-253:4(1348)                        5000015          1

What do people think of the script?  Any suggestion on improvements before checking it into the examples?

-Will



[-- Attachment #2: periodic.stp --]
[-- Type: text/plain, Size: 1225 bytes --]

#!/usr/bin/stap --all-modules
# Copyright (C) 2011 Red Hat, Inc.
# Written by William Cohen <wcohen@redhat.com>
#
# A little script to give an idea what periodic things are running on
# the system

global last_expire, period, funct, data

probe kernel.trace("timer_expire_entry")
{
  old_expire = last_expire[$timer]
  new_expire = gettimeofday_us()
  if (old_expire) {
    elapsed = new_expire - old_expire
    period[$timer] <<< elapsed
    funct[$timer] = $timer->function
    data[$timer] = $timer->data
  }
  last_expire[$timer] = new_expire
}

probe end
{
  printf("#%-16s %-35s %12s %10s\n", "timer", "function", "period(us)", "count")
  # print out the various timers firing
  foreach([timer] in period-) {
    fname = symname(funct[timer])
    if (fname == "process_timeout") {
      fname = sprintf("%s(%d)",
        kernel_string_n(@cast(data[timer], "struct task_struct")->comm, 16),
        @cast(data[timer], "struct task_struct")->pid)
    } else if (fname == "delayed_work_timer_fn") {
      fname = sprintf("%s[dq]", 
        symname(@cast(data[timer], "struct delayed_work")->work->func))
    }
    printf("%16p %-35s %12d %10d\n", timer, fname,
           @avg(period[timer]), @count(period[timer]))
  }
}

Re: Example looking at the periodic timers

[Mark Wielaard]

On Tue, 2011-12-13 at 16:57 -0500, William Cohen wrote:
> One case that people would like to use SystemTap for is finding out
> why some latency sensitive application is slowed down every x seconds.
> They know that something keeps running on the machine and slowing
> things down, but they don't know what it is.
> 
> I have been playing around with the timer tracepoints and came up with
> the attached script, periodic.stp.  When the script exits it prints
> out a list of the periodic timers, sorted from most frequently to
> least frequently fired timer. It also include the average period for
> the timer.  The functions that have [dg] are things put into the
> delayed_work_queues.

Looks nice. I would add a begin probe to announce the script started and
that the user must press control-C to get results and/or make the end
probe a end,timer.s(10) probe so that you get output every 10 seconds
(then you can also clean up the tables).

Are the timer addresses really useful? I just don't know how to
interpret them, does it matter on which timer some event fired?

Printing the comms on process_timeout is a nice touch. Maybe explicitly
prefix it with process: or some other string making that more clear?

You could also add modname() to the output, then people can more easily
see whether it is a kernel or module function being triggered.

I also got some functions that don't immediately make sense, they don't
seem to fall inside either the kernel nor a module. Did you figure out
where they point at? From seeing the high address I assume they are
actually dynamically allocated structures, not direct functions.

Cheers,

Mark

Re: Example looking at the periodic timers

[William Cohen]

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

On 12/14/2011 06:23 AM, Mark Wielaard wrote:
> On Tue, 2011-12-13 at 16:57 -0500, William Cohen wrote:
>> One case that people would like to use SystemTap for is finding out
>> why some latency sensitive application is slowed down every x seconds.
>> They know that something keeps running on the machine and slowing
>> things down, but they don't know what it is.
>>
>> I have been playing around with the timer tracepoints and came up with
>> the attached script, periodic.stp.  When the script exits it prints
>> out a list of the periodic timers, sorted from most frequently to
>> least frequently fired timer. It also include the average period for
>> the timer.  The functions that have [dg] are things put into the
>> delayed_work_queues.

Hi Mark,

Thanks for the feedback. I made some revisions and attached the new peroidic.stp.

> 
> Looks nice. I would add a begin probe to announce the script started and
> that the user must press control-C to get results and/or make the end
> probe a end,timer.s(10) probe so that you get output every 10 seconds
> (then you can also clean up the tables).

The begin probe would be easy enough to add. Loading in thing with the "--all-modules" can slow things down, so that would give people some useful feedback.  The timer.s(10) might not be so useful when people are looking for things that have a period longer than 10 seconds.  There are things in the kernel that run every 600 seconds or so, and timer.s(10) would miss those. Maybe make an optional argument for periodic output/cleanup.

> 
> Are the timer addresses really useful? I just don't know how to
> interpret them, does it matter on which timer some event fired?

The timer addresses are probably not that useful in the output and I was debating whether to remove them before posting the script on the mailing list. It was more for when I was creating things and I could see that the same functions were attached to different timers. Now that the script appears to be working I removed that from the output.

> Printing the comms on process_timeout is a nice touch. Maybe explicitly
> prefix it with process: or some other string making that more clear?
> 
> You could also add modname() to the output, then people can more easily
> see whether it is a kernel or module function being triggered.

The output for the function could use some tweaks. The modname() sounds like a good addition.  Maybe replace the #timer columnn with type: "module", "process", "delayed_work" as in the revised script.

> I also got some functions that don't immediately make sense, they don't
> seem to fall inside either the kernel nor a module. Did you figure out
> where they point at? From seeing the high address I assume they are
> actually dynamically allocated structures, not direct functions.

Which functions are you referring to? I think that the raw addresses in the output are might the timers related to the systemtap instrumentation module.

-Will


[-- Attachment #2: periodic.stp --]
[-- Type: text/plain, Size: 1591 bytes --]

#!/usr/bin/stap --all-modules
# Copyright (C) 2011 Red Hat, Inc.
# Written by William Cohen <wcohen@redhat.com>
#
# A little script to give an idea what periodic things are running on
# the system

global last_expire, period, funct, data

probe kernel.trace("timer_expire_entry")
{
  old_expire = last_expire[$timer]
  new_expire = gettimeofday_us()
  if (old_expire) {
    elapsed = new_expire - old_expire
    period[$timer] <<< elapsed
    funct[$timer] = $timer->function
    data[$timer] = $timer->data
  }
  last_expire[$timer] = new_expire
}

function output()
{
  printf("#%-16s %-35s %12s %10s\n", "type", "function", "period(us)", "count")
  # print out the various timers firing
  foreach([timer] in period-) {
    fname = symname(funct[timer])
    if (fname == "process_timeout") {
      fname = sprintf("%s(%d)",
        kernel_string_n(@cast(data[timer], "struct task_struct")->comm, 16),
        @cast(data[timer], "struct task_struct")->pid)
	type="process"
    } else if (fname == "delayed_work_timer_fn") {
      fname = sprintf("%s", 
        symname(@cast(data[timer], "struct delayed_work")->work->func))
	type="work_queue"
    } else {
      fname = sprintf("%s:%s", modname(funct[timer]), fname)
	type="kernel"
    }
    printf("%-16s %-35s %12d %10d\n", type, fname,
           @avg(period[timer]), @count(period[timer]))
  }
}

probe begin { printf("#monitoring timer periods\n") }
probe end { output() }

# allow optional period output from script
%( $# > 0 %?
probe timer.s($1)
{
  output();
  delete last_expire
  delete period
  delete funct
  delete data
}
%)

Re: Example looking at the periodic timers

[Frank Ch. Eigler]

wcohen wrote:

> [...]
>> Are the timer addresses really useful? I just don't know how to
>> interpret them, does it matter on which timer some event fired?
>
> The timer addresses are probably not that useful in the output [...]

If symdata() can get meaningful names from the timer addresses, then
they could be informative.


- FChE

Re: Example looking at the periodic timers

[Mark Wielaard]

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

On Wed, Dec 14, 2011 at 09:52:18AM -0500, William Cohen wrote:
> > Looks nice. I would add a begin probe to announce the script started and
> > that the user must press control-C to get results and/or make the end
> > probe a end,timer.s(10) probe so that you get output every 10 seconds
> > (then you can also clean up the tables).
> 
> The begin probe would be easy enough to add. Loading in thing with the
> "--all-modules" can slow things down, so that would give people some
> useful feedback.  The timer.s(10) might not be so useful when people
> are looking for things that have a period longer than 10 seconds.
> There are things in the kernel that run every 600 seconds or so,
> and timer.s(10) would miss those. Maybe make an optional argument
> for periodic output/cleanup.

Nice elegant solution. To nitpick, I would make the output more explicit:
-probe begin { printf("#monitoring timer periods\n") }
+probe begin { printf("# Monitoring timer periods (press ctrl-C for output)\n") }

> > I also got some functions that don't immediately make sense, they don't
> > seem to fall inside either the kernel nor a module. Did you figure out
> > where they point at? From seeing the high address I assume they are
> > actually dynamically allocated structures, not direct functions.
> 
> Which functions are you referring to? I think that the raw addresses in
> the output are might the timers related to the systemtap instrumentation
> module.

Aha. You are right.
I even have a patch for modname() to get "unknown" module names.
I haven't checked it in because I found the preempt_disable() so
incredible ugly. We cannot use the module_mutex because we could
theoretically be probing some code that holds that mutex. What do
people think, is it useful enough to warrant the ugliness?

Since stap module names are so incredibly long you do need the following
patch to truncate the module names in periodic.stp:

-      fname = sprintf("%s:%s", modname(funct[timer]), fname)
+      fname = sprintf("%.16s:%s", modname(funct[timer]), fname)


This does expose that we (systemtap) are responsible for most timer
interrupts... hmmmm.

Cheers,

Mark

[-- Attachment #2: modname.patch --]
[-- Type: text/plain, Size: 1006 bytes --]

diff --git a/tapset/context-symbols.stp b/tapset/context-symbols.stp
index 1ab3a61..79d45f5 100644
--- a/tapset/context-symbols.stp
+++ b/tapset/context-symbols.stp
@@ -154,11 +154,28 @@ function probemod:string () %{ /* pure */
  */
 function modname:string (addr: long) %{ /* pure */
 	struct _stp_module *m;
+#ifdef STAPCONF_MODULE_TEXT_ADDRESS
+	struct module *ko;
+#endif
 	m = _stp_kmod_sec_lookup (THIS->addr, NULL);
 	if (m && m->name)
-          strlcpy (THIS->__retvalue, m->name, MAXSTRINGLEN);
-	else
-	  strlcpy (THIS->__retvalue, "<unknown>", MAXSTRINGLEN);
+	  {
+	    strlcpy (THIS->__retvalue, m->name, MAXSTRINGLEN);
+	    return;
+	  }
+
+#ifdef STAPCONF_MODULE_TEXT_ADDRESS
+	preempt_disable();
+	ko = __module_text_address (THIS->addr);
+	if (ko && ko->name)
+	  {
+	    strlcpy (THIS->__retvalue, ko->name, MAXSTRINGLEN);
+	    preempt_enable_no_resched();
+	    return;
+	  }
+	preempt_enable_no_resched();
+#endif
+	strlcpy (THIS->__retvalue, "<unknown>", MAXSTRINGLEN);
 %}
 
 /**

Re: Example looking at the periodic timers

[Mark Wielaard]

On Wed, Dec 14, 2011 at 07:19:12PM +0100, Mark Wielaard wrote:
> On Wed, Dec 14, 2011 at 09:52:18AM -0500, William Cohen wrote:
> > Which functions are you referring to? I think that the raw addresses in
> > the output are might the timers related to the systemtap instrumentation
> > module.
> 
> Aha. You are right.
> I even have a patch for modname() to get "unknown" module names.
> I haven't checked it in because I found the preempt_disable() so
> incredible ugly. We cannot use the module_mutex because we could
> theoretically be probing some code that holds that mutex. What do
> people think, is it useful enough to warrant the ugliness?

Since nobody yelled and screamed about it being too ugly I cleaned
it up and made sure it also works for symdata().

commit 17373b9e59df05fb8101ec173b580d593ba65d09
Author: Mark Wielaard <mjw@redhat.com>
Date:   Fri Dec 16 16:59:00 2011 +0100

    modname/symdata: Try harder to retrieve module name when requested.
    
    When the user really wants a kernel module name with an address and
    we are unable to map it to any existing one then fall back on using
    __module_text_address() with appropriate locking.

Now the periodic.stp example will show who is really responsible
for all these timers... us...

#monitoring timer periods (press control-c for output)
#type   function                                            period(us)     count
kernel  0xffffffffa109c780 [stap_6c9caccd440e93fb9f95605bb         999      4999
kernel  0xffffffffa109c780 [stap_6c9caccd440e93fb9f95605bb        1000      4996
kernel  0xffffffffa109c780 [stap_6c9caccd440e93fb9f95605bb        1001      4992
kernel  0xffffffffa109c780 [stap_6c9caccd440e93fb9f95605bb        1001      4992
work_q  do_dbs_timer                                              9999       499
kernel  0xffffffffa109c330 [stap_6c9caccd440e93fb9f95605bb       10000       499
work_q  do_dbs_timer                                             10000       499
work_q  do_dbs_timer                                             10000       499
work_q  do_dbs_timer                                             10000       499
kernel  0xffffffffa109c270 [stap_6c9caccd440e93fb9f95605bb       20003       249
kernel  flush_unmaps_timeout+0x0/0x40 [kernel]                   80573        61
kernel  clocksource_watchdog+0x0/0x210 [kernel]                 500001         9
work_q  i915_gem_retire_work_handler                           1001999         4
work_q  sync_cmos_clock                                         999999         4
work_q  vmstat_update                                          1000002         4
work_q  vmstat_update                                          1000002         4
work_q  vmstat_update                                           999999         4
work_q  vmstat_update                                           999997         4
kernel  intel_gpu_idle_timer+0x0/0x80 [i915]                    601000         3
kernel  br_hello_timer_expired+0x0/0x80 [bridge]               2000015         1
kernel  iwl_bg_watchdog+0x0/0x110 [iwlagn]                     2504008         1
kernel  e1000_watchdog+0x0/0x20 [e1000e]                       2000016         1

Cheers,

Mark