From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 24356 invoked by alias); 14 Dec 2011 14:52:44 -0000 Received: (qmail 24333 invoked by uid 22791); 14 Dec 2011 14:52:41 -0000 X-SWARE-Spam-Status: No, hits=-5.3 required=5.0 tests=AWL,BAYES_00,RP_MATCHES_RCVD,SPF_HELO_PASS 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; Wed, 14 Dec 2011 14:52:20 +0000 Received: from int-mx10.intmail.prod.int.phx2.redhat.com (int-mx10.intmail.prod.int.phx2.redhat.com [10.5.11.23]) by mx1.redhat.com (8.14.4/8.14.4) with ESMTP id pBEEqJlG029328 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=OK) for ; Wed, 14 Dec 2011 09:52:19 -0500 Received: from [10.11.231.236] (deploy7.rdu.redhat.com [10.11.231.236]) by int-mx10.intmail.prod.int.phx2.redhat.com (8.14.4/8.14.4) with ESMTP id pBEEqIqq027157; Wed, 14 Dec 2011 09:52:19 -0500 Message-ID: <4EE8B822.5010202@redhat.com> Date: Wed, 14 Dec 2011 15:32: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: Mark Wielaard CC: systemtap@sourceware.org Subject: Re: Example looking at the periodic timers References: <4EE7CA4E.9080109@redhat.com> <1323861834.3567.27.camel@springer.wildebeest.org> In-Reply-To: <1323861834.3567.27.camel@springer.wildebeest.org> Content-Type: multipart/mixed; boundary="------------060208080505030705080008" 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/msg00356.txt.bz2 This is a multi-part message in MIME format. --------------060208080505030705080008 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit Content-length: 2960 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 --------------060208080505030705080008 Content-Type: text/plain; name="periodic.stp" Content-Transfer-Encoding: base64 Content-Disposition: attachment; filename="periodic.stp" Content-length: 2160 IyEvdXNyL2Jpbi9zdGFwIC0tYWxsLW1vZHVsZXMKIyBDb3B5cmlnaHQgKEMp IDIwMTEgUmVkIEhhdCwgSW5jLgojIFdyaXR0ZW4gYnkgV2lsbGlhbSBDb2hl biA8d2NvaGVuQHJlZGhhdC5jb20+CiMKIyBBIGxpdHRsZSBzY3JpcHQgdG8g Z2l2ZSBhbiBpZGVhIHdoYXQgcGVyaW9kaWMgdGhpbmdzIGFyZSBydW5uaW5n IG9uCiMgdGhlIHN5c3RlbQoKZ2xvYmFsIGxhc3RfZXhwaXJlLCBwZXJpb2Qs IGZ1bmN0LCBkYXRhCgpwcm9iZSBrZXJuZWwudHJhY2UoInRpbWVyX2V4cGly ZV9lbnRyeSIpCnsKICBvbGRfZXhwaXJlID0gbGFzdF9leHBpcmVbJHRpbWVy XQogIG5ld19leHBpcmUgPSBnZXR0aW1lb2ZkYXlfdXMoKQogIGlmIChvbGRf ZXhwaXJlKSB7CiAgICBlbGFwc2VkID0gbmV3X2V4cGlyZSAtIG9sZF9leHBp cmUKICAgIHBlcmlvZFskdGltZXJdIDw8PCBlbGFwc2VkCiAgICBmdW5jdFsk dGltZXJdID0gJHRpbWVyLT5mdW5jdGlvbgogICAgZGF0YVskdGltZXJdID0g JHRpbWVyLT5kYXRhCiAgfQogIGxhc3RfZXhwaXJlWyR0aW1lcl0gPSBuZXdf ZXhwaXJlCn0KCmZ1bmN0aW9uIG91dHB1dCgpCnsKICBwcmludGYoIiMlLTE2 cyAlLTM1cyAlMTJzICUxMHNcbiIsICJ0eXBlIiwgImZ1bmN0aW9uIiwgInBl cmlvZCh1cykiLCAiY291bnQiKQogICMgcHJpbnQgb3V0IHRoZSB2YXJpb3Vz IHRpbWVycyBmaXJpbmcKICBmb3JlYWNoKFt0aW1lcl0gaW4gcGVyaW9kLSkg ewogICAgZm5hbWUgPSBzeW1uYW1lKGZ1bmN0W3RpbWVyXSkKICAgIGlmIChm bmFtZSA9PSAicHJvY2Vzc190aW1lb3V0IikgewogICAgICBmbmFtZSA9IHNw cmludGYoIiVzKCVkKSIsCiAgICAgICAga2VybmVsX3N0cmluZ19uKEBjYXN0 KGRhdGFbdGltZXJdLCAic3RydWN0IHRhc2tfc3RydWN0IiktPmNvbW0sIDE2 KSwKICAgICAgICBAY2FzdChkYXRhW3RpbWVyXSwgInN0cnVjdCB0YXNrX3N0 cnVjdCIpLT5waWQpCgl0eXBlPSJwcm9jZXNzIgogICAgfSBlbHNlIGlmIChm bmFtZSA9PSAiZGVsYXllZF93b3JrX3RpbWVyX2ZuIikgewogICAgICBmbmFt ZSA9IHNwcmludGYoIiVzIiwgCiAgICAgICAgc3ltbmFtZShAY2FzdChkYXRh W3RpbWVyXSwgInN0cnVjdCBkZWxheWVkX3dvcmsiKS0+d29yay0+ZnVuYykp Cgl0eXBlPSJ3b3JrX3F1ZXVlIgogICAgfSBlbHNlIHsKICAgICAgZm5hbWUg PSBzcHJpbnRmKCIlczolcyIsIG1vZG5hbWUoZnVuY3RbdGltZXJdKSwgZm5h bWUpCgl0eXBlPSJrZXJuZWwiCiAgICB9CiAgICBwcmludGYoIiUtMTZzICUt MzVzICUxMmQgJTEwZFxuIiwgdHlwZSwgZm5hbWUsCiAgICAgICAgICAgQGF2 ZyhwZXJpb2RbdGltZXJdKSwgQGNvdW50KHBlcmlvZFt0aW1lcl0pKQogIH0K fQoKcHJvYmUgYmVnaW4geyBwcmludGYoIiNtb25pdG9yaW5nIHRpbWVyIHBl cmlvZHNcbiIpIH0KcHJvYmUgZW5kIHsgb3V0cHV0KCkgfQoKIyBhbGxvdyBv cHRpb25hbCBwZXJpb2Qgb3V0cHV0IGZyb20gc2NyaXB0CiUoICQjID4gMCAl Pwpwcm9iZSB0aW1lci5zKCQxKQp7CiAgb3V0cHV0KCk7CiAgZGVsZXRlIGxh c3RfZXhwaXJlCiAgZGVsZXRlIHBlcmlvZAogIGRlbGV0ZSBmdW5jdAogIGRl bGV0ZSBkYXRhCn0KJSkKCg== --------------060208080505030705080008--