From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 25364 invoked by alias); 13 Dec 2011 21:57:53 -0000 Received: (qmail 25353 invoked by uid 22791); 13 Dec 2011 21:57:52 -0000 X-SWARE-Spam-Status: No, hits=-7.7 required=5.0 tests=AWL,BAYES_00,RCVD_IN_DNSWL_HI,RP_MATCHES_RCVD,SPF_HELO_PASS,TW_FD X-Spam-Check-By: sourceware.org Received: from mx1.redhat.com (HELO mx1.redhat.com) (209.132.183.28) by sourceware.org (qpsmtpd/0.43rc1) with ESMTP; Tue, 13 Dec 2011 21:57:36 +0000 Received: from int-mx12.intmail.prod.int.phx2.redhat.com (int-mx12.intmail.prod.int.phx2.redhat.com [10.5.11.25]) by mx1.redhat.com (8.14.4/8.14.4) with ESMTP id pBDLvZrQ019187 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=OK) for ; Tue, 13 Dec 2011 16:57:35 -0500 Received: from [10.11.231.236] (deploy7.rdu.redhat.com [10.11.231.236]) by int-mx12.intmail.prod.int.phx2.redhat.com (8.14.4/8.14.4) with ESMTP id pBDLvYfX004948 for ; Tue, 13 Dec 2011 16:57:35 -0500 Message-ID: <4EE7CA4E.9080109@redhat.com> Date: Tue, 13 Dec 2011 22:29:00 -0000 From: William Cohen User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.2.24) Gecko/20111104 Red Hat/3.1.16-2.el6_1 Thunderbird/3.1.16 MIME-Version: 1.0 To: systemtap@sourceware.org Subject: Example looking at the periodic timers Content-Type: multipart/mixed; boundary="------------040505030801030805050209" X-IsSubscribed: yes Mailing-List: contact systemtap-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Post: List-Help: , Sender: systemtap-owner@sourceware.org X-SW-Source: 2011-q4/txt/msg00351.txt.bz2 This is a multi-part message in MIME format. --------------040505030801030805050209 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-length: 3848 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 --------------040505030801030805050209 Content-Type: text/plain; name="periodic.stp" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="periodic.stp" Content-length: 1225 #!/usr/bin/stap --all-modules # Copyright (C) 2011 Red Hat, Inc. # Written by William Cohen # # 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])) } } --------------040505030801030805050209--