From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 121262 invoked by alias); 9 Aug 2016 15:17:23 -0000 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 Received: (qmail 121249 invoked by uid 89); 9 Aug 2016 15:17:23 -0000 Authentication-Results: sourceware.org; auth=none X-Virus-Found: No X-Spam-SWARE-Status: No, score=-2.3 required=5.0 tests=BAYES_00,RP_MATCHES_RCVD,SPF_HELO_PASS autolearn=ham version=3.3.2 spammy= X-HELO: mx1.redhat.com Received: from mx1.redhat.com (HELO mx1.redhat.com) (209.132.183.28) by sourceware.org (qpsmtpd/0.93/v0.84-503-g423c35a) with (AES256-GCM-SHA384 encrypted) ESMTPS; Tue, 09 Aug 2016 15:17:21 +0000 Received: from int-mx11.intmail.prod.int.phx2.redhat.com (int-mx11.intmail.prod.int.phx2.redhat.com [10.5.11.24]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 5D4D343A38; Tue, 9 Aug 2016 15:17:20 +0000 (UTC) Received: from t540p.usersys.redhat.com ([10.15.1.188]) by int-mx11.intmail.prod.int.phx2.redhat.com (8.14.4/8.14.4) with ESMTP id u79FHJDm032480 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO); Tue, 9 Aug 2016 11:17:19 -0400 Subject: Re: Some newbie questions To: Avi Kivity , systemtap@sourceware.org References: From: David Smith Message-ID: Date: Tue, 09 Aug 2016 15:17:00 -0000 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Thunderbird/45.2.0 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-IsSubscribed: yes X-SW-Source: 2016-q3/txt/msg00146.txt.bz2 On 08/09/2016 01:51 AM, Avi Kivity wrote: > > > On 08/08/2016 05:58 PM, David Smith wrote: >> >>> 2. Inlined functions >>> >>> From the manual pages, it seems that inlined functions can be probed >>> (minus the .return probe), but I just get an error: >>> >>> semantic error: while resolving probe point: identifier 'process' at >>> script/home/avi/seastar/debug/task-latency.stap:3:7 >>> source: probe >>> process("scylla").function("reactor::run_tasks()") { >>> ^ >>> >>> semantic error: no match (similar functions: >>> _ZN7reactor14run_exit_tasksEv, statfs, dup, mkdir, ntohs) >> We're at the mercy of the compiler and the quality of the debuginfo it >> produces here when looking for inlined functions. >> >> If you want to investigate further here, you'll need to do the following: >> >> # eu-readelf -N --debug-dump=info scylla > scylla.log >> >> In scylla.log, look and see if you can find a subprogram with the name >> of the function you are interested in. > > [1417f4] subprogram > external (flag_present) Yes > name (strp) "run_tasks" > decl_file (data1) 5 > decl_line (data2) 812 > linkage_name (strp) > "_ZN7reactor9run_tasksER15circular_bufferISt10unique_ptrI4taskSt14default_deleteIS2_EESaIS5_EE" > > declaration (flag_present) Yes > object_pointer (ref4) [141808] > sibling (ref4) [141813] > [141808] formal_parameter > type (ref4) [1423bd] > artificial (flag_present) Yes > [14180d] formal_parameter > type (ref4) [14a8a8] According to the above, that function isn't inlined. You might just try the following to see what functions stap can see: # stap -l 'process("scylla").function("*")' | grep run_tasks > The debugger has no trouble setting breakpoints on the function or > showing it in backtraces. In any case I sprinkled some static probes > there. > >>> 3. Process CPU timers >>> >>> (more of a feature request) >>> >>> I'm trying to find causes of latency in my program. To do that, I'm >>> running a periodic timer and checking whether a function takes more time >>> than some threshold. >>> >>> Ideally, I'd be able to arm the timer on the function entry point and >>> disarm it on exit, rather than have it run continuously; this would need >>> to be a per-thread cpu-time timer (e.g. CLOCK_THREAD_CPUTIME_ID)/ >>> >>> Here's my current script for reference ("running" and "start_time" need >>> to become maps for it to be thread-safe): >>> >>> #!/usr/bin/stap >>> >>> global start_time >>> global running >>> >>> probe begin { >>> running = 0 >>> } >>> >>> probe >>> process("/home/avi/urchin/build/release/scylla").mark("reactor_run_tasks_start") >>> >>> { >>> start_time = gettimeofday_us() >>> running = 1 >>> } >>> >>> probe >>> process("/home/avi/urchin/build/release/scylla").mark("reactor_run_tasks_end") >>> >>> { >>> running = 0 >>> } >>> >>> probe timer.ms(10) { >>> now = gettimeofday_us() >>> if (running && (now - start_time) > 30000) { >>> printf("detected tasks running for >30ms\n") >>> print_usyms(ubacktrace()) >>> } >>> } >>> >>> I'd appreciate any tips as to whether there's a better way to do this. >> The above isn't really going to work well, for several reasons: >> >> 1) You've only got one global 'start_time' and 'running' variables. If >> scylla is multithreaded or more than one instance is running, that isn't >> going to work. >> >> To fix this, you'd want to do convert them to arrays and index them by >> thread ids, like this: >> >> start_time[tid()] = gettimeofday_us() > > Yes, I found that out and my latest version works like this, but I ran > into severe scaling issues. > > I also switched to timer.profile. What's its resolution on normal > machines? timer.profile probe resolution is CONFIG_HZ. Check your kernel config and see "man stapprobes" for more details. -- David Smith dsmith@redhat.com Red Hat http://www.redhat.com 256.217.0141 (direct) 256.837.0057 (fax)