Return-Path: Delivered-To: apmail-incubator-uima-dev-archive@locus.apache.org Received: (qmail 3287 invoked from network); 2 Oct 2008 14:36:24 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.2) by minotaur.apache.org with SMTP; 2 Oct 2008 14:36:24 -0000 Received: (qmail 86844 invoked by uid 500); 2 Oct 2008 14:36:22 -0000 Delivered-To: apmail-incubator-uima-dev-archive@incubator.apache.org Received: (qmail 86821 invoked by uid 500); 2 Oct 2008 14:36:22 -0000 Mailing-List: contact uima-dev-help@incubator.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: uima-dev@incubator.apache.org Delivered-To: mailing list uima-dev@incubator.apache.org Received: (qmail 86808 invoked by uid 99); 2 Oct 2008 14:36:22 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 02 Oct 2008 07:36:22 -0700 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of msa@schor.com designates 69.93.38.21 as permitted sender) Received: from [69.93.38.21] (HELO gateway03.websitewelcome.com) (69.93.38.21) by apache.org (qpsmtpd/0.29) with SMTP; Thu, 02 Oct 2008 14:35:19 +0000 Received: (qmail 29944 invoked from network); 2 Oct 2008 14:50:05 -0000 Received: from gator74.hostgator.com (67.18.27.130) by gateway03.websitewelcome.com with SMTP; 2 Oct 2008 14:50:05 -0000 Received: from yktgi01e0-s5.watson.ibm.com ([129.34.20.19]:1409 helo=[9.2.34.80]) by gator74.hostgator.com with esmtpsa (SSLv3:AES256-SHA:256) (Exim 4.68) (envelope-from ) id 1KlPHO-00051E-Nl for uima-dev@incubator.apache.org; Thu, 02 Oct 2008 09:35:46 -0500 Message-ID: <48E4DC43.9090403@schor.com> Date: Thu, 02 Oct 2008 10:35:47 -0400 From: Marshall Schor User-Agent: Thunderbird 2.0.0.17 (Windows/20080914) MIME-Version: 1.0 To: uima-dev@incubator.apache.org Subject: Re: source of some unusual profiling measurements References: <48E44E2A.10106@schor.com> <48E4D890.7010701@schor.com> In-Reply-To: <48E4D890.7010701@schor.com> X-Enigmail-Version: 0.95.7 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit X-AntiAbuse: This header was added to track abuse, please include it with any abuse report X-AntiAbuse: Primary Hostname - gator74.hostgator.com X-AntiAbuse: Original Domain - incubator.apache.org X-AntiAbuse: Originator/Caller UID/GID - [47 12] / [47 12] X-AntiAbuse: Sender Address Domain - schor.com X-Virus-Checked: Checked by ClamAV on apache.org Well, putting in an if statement around the tracing call helped, but just a little - in the particular test scenario I'm running, the total time spent in this method (excluding descendant calls) droped from 150 ms to 140 ms. So the time is being spent elsewhere - not sure where... -Marshall Marshall Schor wrote: > Marshall Schor wrote: > >> While measuring / profiling uima-as - I've notices some unusually high >> time being spent in methods that are practically empty - e.g. "delegate" >> method of "HandlerBase" class. >> >> It turns out that the uima-as code has lots of tracing to the log, >> normally disabled. We had previously discovered that it payed to avoid >> calling "logrb" with all of its arguments, if logging wasn't enabled for >> that level, so in the base uima code all the logger calls are wrapped >> with an if statement testing first if that logging level is enabled, >> thus avoiding computing the arguments of logrb. >> >> This wrappping is missing in the newer uima-as code - I'm thinking that >> this might account for the unusually high % of time being observed. I >> haven't been able to test this though - my profiling experiments started >> to hang after I made this change. >> >> > Well, they didn't hang using yourkit - they just were taking 200x longer > to run (and I thought they were hung...) > -Marshall > >> -Marshall >> >> >> >> > > >