From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 31479 invoked by alias); 12 Feb 2009 15:03:49 -0000 Received: (qmail 31472 invoked by uid 22791); 12 Feb 2009 15:03:48 -0000 X-SWARE-Spam-Status: No, hits=-1.8 required=5.0 tests=AWL,BAYES_00,J_CHICKENPOX_75,SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: sourceware.org Received: from mx2.redhat.com (HELO mx2.redhat.com) (66.187.237.31) by sourceware.org (qpsmtpd/0.43rc1) with ESMTP; Thu, 12 Feb 2009 15:03:42 +0000 Received: from int-mx2.corp.redhat.com (int-mx2.corp.redhat.com [172.16.27.26]) by mx2.redhat.com (8.13.8/8.13.8) with ESMTP id n1CF3dGt003579; Thu, 12 Feb 2009 10:03:39 -0500 Received: from ns3.rdu.redhat.com (ns3.rdu.redhat.com [10.11.255.199]) by int-mx2.corp.redhat.com (8.13.1/8.13.1) with ESMTP id n1CF3dj7010182; Thu, 12 Feb 2009 10:03:39 -0500 Received: from [10.32.10.134] (vpn-10-134.str.redhat.com [10.32.10.134]) by ns3.rdu.redhat.com (8.13.8/8.13.8) with ESMTP id n1CF3cnF008920; Thu, 12 Feb 2009 10:03:38 -0500 Subject: Re: Phase 2 takes too much time to complete From: Mark Wielaard To: Roberto Natella Cc: systemtap@sourceware.org In-Reply-To: <803cc47c0902120624t761e978kc6f15da4bee894c@mail.gmail.com> References: <803cc47c0902110756g41af0d89h9b32deea81779e51@mail.gmail.com> <1234375165.2340.139.camel@fedora.wildebeest.org> <803cc47c0902120624t761e978kc6f15da4bee894c@mail.gmail.com> Content-Type: text/plain Date: Thu, 12 Feb 2009 19:58:00 -0000 Message-Id: <1234451016.2271.144.camel@fedora.wildebeest.org> Mime-Version: 1.0 Content-Transfer-Encoding: 7bit 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: 2009-q1/txt/msg00433.txt.bz2 Hi Roberto, On Thu, 2009-02-12 at 15:24 +0100, Roberto Natella wrote: > Compile time clearly improved > after substitution of "endl" with "\n" (2552835 vs 119837 real ms). Thanks a lot for testing. I wasn't seeing any real improvements myself. But Frank suggested I look at the number of writes to see if there was some difference. And there was! So using stap on itself (using -k to bypass the cache): WITH endl: $ stap -e 'global writes=0; probe syscall.write { if (pid() == target()) writes++ } probe end { printf("writes: %d\n", writes) }' -c 'stap -k -e "probe syscall.* {exit()}"' Keeping temporary directory "/tmp/stapzNwlc9" writes: 65279 WITH "\n": $ stap -e 'global writes=0; probe syscall.write { if (pid() == target()) writes++ } probe end { printf("writes: %d\n", writes) }' -c 'stap -k -e "probe syscall.* {exit()}"' Keeping temporary directory "/tmp/stapsmJRtU" writes: 80 (Both repeated 3 times with always the exact same numbers) So that is definitely part of the slowdown. I committed the change to git. I am still somewhat puzzled by the huge real time you are seeing. I cannot explain that. One thing that we were looking at was memory usage (we should do something more clever with scanning the kernel modules and not keep them all in memory). But if you have enough memory that shouldn't really matter. Is your machine tight on memory? Cheers, Mark