From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 22350 invoked by alias); 8 Feb 2008 13:20:38 -0000 Received: (qmail 22343 invoked by uid 22791); 8 Feb 2008 13:20:37 -0000 X-Spam-Status: No, hits=-1.8 required=5.0 tests=AWL,BAYES_05,SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: sourceware.org Received: from mx1.redhat.com (HELO mx1.redhat.com) (66.187.233.31) by sourceware.org (qpsmtpd/0.31) with ESMTP; Fri, 08 Feb 2008 13:20:19 +0000 Received: from int-mx1.corp.redhat.com (int-mx1.corp.redhat.com [172.16.52.254]) by mx1.redhat.com (8.13.8/8.13.8) with ESMTP id m18DKFrF022740 for ; Fri, 8 Feb 2008 08:20:15 -0500 Received: from lacrosse.corp.redhat.com (lacrosse.corp.redhat.com [172.16.52.154]) by int-mx1.corp.redhat.com (8.13.1/8.13.1) with ESMTP id m18DKEuB030627 for ; Fri, 8 Feb 2008 08:20:14 -0500 Received: from dhcp231-154.rdu.redhat.com (vpn-14-22.rdu.redhat.com [10.11.14.22]) by lacrosse.corp.redhat.com (8.12.11.20060308/8.11.6) with ESMTP id m18DKEXE002606 for ; Fri, 8 Feb 2008 08:20:14 -0500 Message-ID: <47AC570C.80602@redhat.com> Date: Fri, 08 Feb 2008 13:20:00 -0000 From: William Cohen User-Agent: Thunderbird 2.0.0.9 (X11/20071115) MIME-Version: 1.0 To: SystemTAP Subject: Slowness module generating for testsuite/systemtap.stress/current.stp due to elfutils-0.131 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit X-Scanned-By: MIMEDefang 2.58 on 172.16.52.254 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: 2008-q1/txt/msg00242.txt.bz2 I was looking through the nightly test results and I noticed that recently systemtap.stress/current.stp times out on all the machine running nightly tests. It uses to be that systemtap.stress/current.stp was a relatively quick test to run. I looked through the nightly testing build that checks things out at 4:30 am EST and it appears that stap is reasonably fast 20080124 then 2008125 it is literally 30 times slower. Ran the following command with various versions of systemtap in the testsuite directory: /usr/bin/time ../stap /home/wcohen/stap_testing_200802070930/src/testsuite/systemtap.stress/current.stp -g -m x -v -c 'sleep 1' Below is the table of results from the time command. date output of time 20080124 6.23user 1.25system 0:11.84elapsed 63%CPU (0avgtext+0avgdata 0maxresident)k 0inputs+0outputs (406major+196130minor)pagefaults 0swaps 20080125 230.78user 1.37system 3:55.77elapsed 98%CPU (0avgtext+0avgdata 0maxresident)k 0inputs+0outputs (29major+213027minor)pagefaults 0swaps The problem appear to be a huge amount of time spent in some of the rountines in elfutils-0.131. Also see huge amount of time with elfutils-0.132. The same systemtap code built elfutils-0.129 is much faster (30 times faster). Below is a profiling data from oprofile showing the routines that the systemtap spends its time in elfutils-0.132: $ opreport -t1 ./stap -l CPU: P4 / Xeon with 2 hyper-threads, speed 2793.08 MHz (estimated) Counted GLOBAL_POWER_EVENTS events (time during which processor is not stopped) with a unit mask of 0x01 (mandatory) count 100000 samples % image name symbol name 4355797 68.3146 libdw.so.1 relocate.5976 1679547 26.3414 libelf.so.1 gelf_getsymshndx 168836 2.6480 libc-2.5.so strcmp 94576 1.4833 libdw.so.1 anonymous symbol from section .plt -Will