Path: csiph.com!x330-a1.tempe.blueboxinc.net!usenet.pasdenom.info!aioe.org!feeder.news-service.com!fu-berlin.de!uni-berlin.de!individual.net!not-for-mail From: Nigel Wade Newsgroups: comp.lang.java.programmer Subject: Re: analysis of java application logs Date: Wed, 25 May 2011 09:53:10 +0100 Lines: 84 Message-ID: <943uboF6qmU1@mid.individual.net> References: <240520111100099912%jimsgibson@gmail.com> Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit X-Trace: individual.net fe1GAgKXX5dIvou5oLTZhwcm/ixoOJyrnhNFi78g8/JF2gppZh Cancel-Lock: sha1:uQ9mrh4iww6TCZA6leTaoY3eBpU= User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-GB; rv:1.9.1.16) Gecko/20101125 SUSE/3.0.11 Thunderbird/3.0.11 In-Reply-To: Xref: x330-a1.tempe.blueboxinc.net comp.lang.java.programmer:4565 On 24/05/11 19:35, Lew wrote: > On 05/24/2011 02:00 PM, Jim Gibson wrote: >> In article, Lew >> wrote: >> >>> Martin Gregorie wrote: >>>> Lew wrote: >>>>> Martin Gregorie wrote: >>>>>> Fair point. However, my usual debugging statement takes the form: >>>>>> >>>>>> if (debug> 0) >>>>>> debugger.trace(result + " = method(" + arg + ")"); >>>>>> >>>>>> Ugly, I know, but quite efficient, since when debugging is off >>>>>> even the >>>>>> cost of the method call cost is. I use an integer to control >>>>>> debugging >>>>>> rather than a boolean so I can control its volume: "java Application >>>>>> -dd" would be expected to provide more detailed debugging output than >>>>>> "java Application -d" >>> >>>>> What's wrong with >>>>> >>>>> if ( logger.isDebugEnabled() ) ... >>>>> >>>>> or >>>>> >>>>> if ( logger.getLevel().isGreaterOrEqual( Logger.DEBUG )) ... >>>>> ? >>> >>>> Not a lot, though that does involve method call overheads that you may >>>> not want in a tight loop. >>> >>> Seems like it's a simple equality test that would be HotSpotted away. >> >> My understanding of the log4j and java.util.Logger classes is that each >> logger exists within a hierarchy of classes, and that to determine >> whether or not a specific logger call will produce output, the library >> must test each level, starting at the specific class and traversing >> upwards in the hierarchy. >> >> So using a static variable as below to enable and disable logging >> output can save some execution time: >> >> static final boolean debug = false; >> >> if( debug ) { >> logger.debug(...); >> } >> >> Whether or not that is significant, depends upon the situation, of >> course. > > All this theory indicates what to measure in any real situation, but to > echo your "of course", you won't know what to conclude prior to that > measurement. In my specific example above I resolved the "problem" by using my own class which did pretty much exactly as Lew suggested in his follow-up post. When I subsequently profiled the code the execution time, and CPU time, required by the remaining method invocations was negligible. > > Now why you'd *ever* want to put a log statement inside a tight, > performance-critical loop in the first place is a whole 'nother question. > In my case the loop was reading messages from a network and generating responses. The logging code was to log the message received, and the response generated, during development. At this stage it wasn't deemed to be performance critical, but was essential to verify correct receipt of the network message. It wasn't until much later that I was told that the response had to be returned in less than 40uS (a fact that wasn't in the original requirements). So I profiled the code to find out where optimisation ought to be targeted. I still wanted to keep the logging in the code for debugging purposes, since it was still under active development, but be able to disable it (and its overhead) for testing. -- Nigel Wade