Menu
▾
▴
Re: [Wrapper-user] -verbose:gc and wrapper log extra new lines
|
From: Leif M. <lei...@ta...> - 2011-05-27 16:30:02
|
Jakob, We have been able to reproduce and fix this problem by adding a new wrapper.log.lf_delay.threshold property which defaults to 500ms. When a single line of console output from the JVM is printed in parts with a delay in between the Wrapper was sometimes thinking that the log output was completed and logged it prematurely. For example: --- System.out.print( "BEGIN" ); Thread.sleep(250); System.out.println( " END" ); --- This should be logged as: --- BEGIN END --- But the Wrapper was breaking this up and logging it as two lines. --- BEGIN END --- When this is done from Java code, it can cause problems if more that one threads are logging at the same time. The JVM appears to do this when logging the GC output. It is fine there because the JVM suspends other threads while the GC is being run. But if the timing of the Wrapper loop was perfect, it could log in between the print and the println, thus breaking up the output into two lines. The new default will be long enough to make sure that this never happens. But we added a property so that even longer values could be defined if needed. This will be in the next release. Cheers, Leif On Fri, May 27, 2011 at 4:40 PM, Christian <chr...@ta...> wrote: > Jakob, > > I have just created this bug report on our sourceforge site: > http://sourceforge.net/tracker/?func=detail&aid=3308280&group_id=39428&atid=425187 > > Best Regards, > Christian > > -----Original Message----- > From: Jakob Ericsson <jak...@gm...> > Reply-to: wra...@li... > To: wra...@li... > Subject: Re: [Wrapper-user] -verbose:gc and wrapper log extra new lines > Date: Fri, 27 May 2011 09:31:20 +0200 > > Great to hear that you could reproduce the problem. > Have you created a issue/bug that I could link to for internal issues? > > Regards, > Jakob > > On Fri, May 27, 2011 at 9:24 AM, Christian Mueller > <chr...@ta...> wrote: >> Jakob, >> >> I was doing some tests on our machines and could reproduce the problem >> with the extra line feed you are seeing. >> >> The line feed was more likely to occur when a system is under heavy >> load, since the GC log entry is actually done by a System.print and a >> println so it looks it's one line, but actually 2 prints. On heavy >> load the time between those 2 prints is increasing and with some bad >> timing, the wrapper will read and printout stdout in between causing >> the extra line feed. >> >> We will work on fixing this for the next release. >> >> I'm very sorry for the inconveniences this might have caused you. >> >> Best Regards, >> Christian >> >> On Thu, May 26, 2011 at 5:12 PM, Jakob Ericsson >> <jak...@gm...> wrote: >>> Christian, >>> >>> It did not help. >>> >>> TATUS | wrapper | 2011/05/26 10:07:59 | Java Service Wrapper Standard >>> Edition 64-bit 3.5.7 >>> STATUS | wrapper | 2011/05/26 10:07:59 | Copyright (C) 1999-2010 >>> Tanuki Software, Ltd. All Rights Reserved. >>> STATUS | wrapper | 2011/05/26 10:07:59 | http://wrapper.tanukisoftware.com >>> STATUS | wrapper | 2011/05/26 10:07:59 | Licensed to XXXXXXXXXXXXXXXX >>> NOTICE | wrapper | 2011/05/26 10:07:59 | >>> NOTICE | wrapper | 2011/05/26 10:07:59 | >>> -------------------------------------------------------------------- >>> NOTICE | wrapper | 2011/05/26 10:07:59 | Thank you for your interest >>> in the Java Service Wrapper. >>> NOTICE | wrapper | 2011/05/26 10:07:59 | >>> NOTICE | wrapper | 2011/05/26 10:07:59 | You are running with a full >>> featured trial License Key which will >>> NOTICE | wrapper | 2011/05/26 10:07:59 | allow you to run or restart >>> the Java Service Wrapper as many times >>> NOTICE | wrapper | 2011/05/26 10:07:59 | as you like until >>> 2011/06/26. If the Wrapper is running at that >>> NOTICE | wrapper | 2011/05/26 10:07:59 | point, it will shutdown on >>> its own after an additional 24 hours. >>> NOTICE | wrapper | 2011/05/26 10:07:59 | >>> NOTICE | wrapper | 2011/05/26 10:07:59 | The Java Service Wrapper >>> requires a License Key to activate the >>> NOTICE | wrapper | 2011/05/26 10:07:59 | software. License Keys can >>> be purchased on the Java Service Wrapper >>> NOTICE | wrapper | 2011/05/26 10:07:59 | web site: >>> NOTICE | wrapper | 2011/05/26 10:07:59 | >>> http://wrapper.tanukisoftware.com/purchase >>> NOTICE | wrapper | 2011/05/26 10:07:59 | >>> NOTICE | wrapper | 2011/05/26 10:07:59 | This trial License Key in >>> intended for testing and development and >>> NOTICE | wrapper | 2011/05/26 10:07:59 | should not be used as part >>> of a production environment. >>> NOTICE | wrapper | 2011/05/26 10:07:59 | >>> -------------------------------------------------------------------- >>> NOTICE | wrapper | 2011/05/26 10:07:59 | >>> STATUS | wrapper | 2011/05/26 10:07:59 | >>> INFO | jvm 1 | 2011/05/26 10:08:15 | [Full GC 176171K->2577K(6134208K), 0.0631505 secs] >>> INFO | jvm 1 | 2011/05/26 10:08:15 | [GC 2577K(6134208K), 0.0003601 secs] >>> INFO | jvm 1 | 2011/05/26 10:08:17 | >>> INFO | jvm 1 | 2011/05/26 10:08:31 | [GC 1260945K->62371K(6134208K), 0.0745148 secs] >>> INFO | jvm 1 | 2011/05/26 10:08:36 | [GC >>> INFO | jvm 1 | 2011/05/26 10:08:36 | 637829K(6134208K), 0.3924890 secs] >>> INFO | jvm 1 | 2011/05/26 10:08:41 | [GC 1320710K->110578K(6134208K), 0.0913535 secs] >>> INFO | jvm 1 | 2011/05/26 10:08:45 | [GC >>> INFO | jvm 1 | 2011/05/26 10:08:46 | 720854K(6134208K), 0.5177127 secs] >>> INFO | jvm 1 | 2011/05/26 10:08:48 | [GC >>> INFO | jvm 1 | 2011/05/26 10:08:48 | 1368946K->154958K(6134208K), 0.4591796 secs] >>> INFO | jvm 1 | 2011/05/26 10:08:52 | [GC >>> INFO | jvm 1 | 2011/05/26 10:08:52 | 761585K(6134208K), 0.3975162 secs] >>> INFO | jvm 1 | 2011/05/26 10:08:56 | [GC 1413232K->126244K(6134208K), 0.0503159 secs] >>> INFO | jvm 1 | 2011/05/26 10:08:59 | [GC >>> INFO | jvm 1 | 2011/05/26 10:08:59 | 733916K(6134208K), 0.4527670 secs] >>> INFO | jvm 1 | 2011/05/26 10:09:03 | [GC 1384612K->158331K(6134208K), 0.0369100 secs] >>> INFO | jvm 1 | 2011/05/26 10:09:07 | [GC >>> INFO | jvm 1 | 2011/05/26 10:09:07 | 757702K(6134208K), 0.4024972 secs] >>> INFO | jvm 1 | 2011/05/26 10:09:11 | [GC 1416676K->141412K(6134208K), 0.0650510 secs] >>> INFO | jvm 1 | 2011/05/26 10:09:12 | [GC >>> INFO | jvm 1 | 2011/05/26 10:09:13 | 763342K(6134208K), 0.2949841 secs] >>> >>> >>> /Jakob >>> >>> >>> On Thu, May 26, 2011 at 9:19 AM, Jakob Ericsson >>> <jak...@gm...> wrote: >>>> Hi, >>>> >>>> We are running on bundled version in TC-server >>>> (http://www.springsource.com/products/tcserver), which seems to be >>>> 3.2.3. In 64-bit mode. >>>> I will give it a go and test on later version if possible to get it to start. >>>> >>>> /Jakob >>>> >>>> >>>> On Thu, May 26, 2011 at 8:40 AM, Christian Mueller >>>> <chr...@ta...> wrote: >>>>> Jakob, >>>>> >>>>> What version of the Wrapper are you running? >>>>> >>>>> What you report sounds familiar, and has been reported in the past. We >>>>> were working on improving this for the 3.4.0 release: >>>>> >>>>> * Fix a problem where Java log output would sometimes get extra line >>>>> feeds when under heavy load. >>>>> http://wrapper.tanukisoftware.com/doc/english/release-notes.html#3.4.0 >>>>> >>>>> Could you please try version 3.4.0 (or any later) and see if this >>>>> resolves your problem? >>>>> >>>>> Best Regards, >>>>> Christian >>>>> >>>>> On Thu, May 26, 2011 at 3:26 PM, Jakob Ericsson >>>>> <jak...@gm...> wrote: >>>>>> Hi, >>>>>> >>>>>> We are using the tanuki wrapper together with TCserver/tomcat and want >>>>>> to have -verbose:gc to the wrapper log. We used to log to specific >>>>>> file but this was overwritten during every jvm restart. Somewhat >>>>>> explained in this post, >>>>>> http://stackoverflow.com/questions/3822097/rolling-garbage-collector-logs-in-java. >>>>>> >>>>>> But now we are facing another problem. The wrapper-log is sometimes >>>>>> adding new lines in the middle of a gc log statement. Is this a flush >>>>>> issue? >>>>>> How can I prevent this in the wrapper log? >>>>>> >>>>>> INFO | jvm 1 | 2011/05/26 04:49:22 | [GC >>>>>> 1868705K->610204K(6134208K), 0.0062318 secs] >>>>>> INFO | jvm 1 | 2011/05/26 04:51:04 | [GC >>>>>> 1868572K->610487K(6134208K), 0.0055004 secs] >>>>>> INFO | jvm 1 | 2011/05/26 04:53:03 | [GC >>>>>> 1868855K->610658K(6134208K), 0.0042818 secs] >>>>>> INFO | jvm 1 | 2011/05/26 04:54:21 | [GC >>>>>> 1869026K->610890K(6134208K), 0.0049682 secs] >>>>>> INFO | jvm 1 | 2011/05/26 04:55:36 | [GC >>>>>> 1869258K->611066K(6134208K), 0.0054197 secs] >>>>>> INFO | jvm 1 | 2011/05/26 04:56:45 | [GC >>>>>> 1869434K->611094K(6134208K), 0.0041137 secs] >>>>>> INFO | jvm 1 | 2011/05/26 04:57:48 | [GC >>>>>> INFO | jvm 1 | 2011/05/26 04:57:48 | >>>>>> 1869462K->611304K(6134208K), 0.0060016 secs] >>>>>> INFO | jvm 1 | 2011/05/26 04:58:46 | [GC >>>>>> INFO | jvm 1 | 2011/05/26 04:58:46 | >>>>>> 1869672K->610972K(6134208K), 0.0053010 secs] >>>>>> INFO | jvm 1 | 2011/05/26 04:59:59 | [GC >>>>>> 1869340K->611257K(6134208K), 0.0040952 secs] >>>>>> INFO | jvm 1 | 2011/05/26 05:01:28 | [GC >>>>>> 1869625K->612006K(6134208K), 0.0079602 secs] >>>>>> INFO | jvm 1 | 2011/05/26 05:03:00 | [GC >>>>>> 1870374K->612103K(6134208K), 0.0053934 secs] >>>>>> >>>>>> >>>>>> If logging to a specific file, result looks like this. No new lines! >>>>>> >>>>>> 0.853: [GC 2405K(6134208K), 0.0003878 secs] >>>>>> 16.915: [GC 1260773K->62176K(6134208K), 0.0711920 secs] >>>>>> 21.357: [GC 637590K(6134208K), 0.4003372 secs] >>>>>> 26.548: [GC 1320507K->110141K(6134208K), 0.0879849 secs] >>>>>> 30.754: [GC 722976K(6134208K), 0.5191931 secs] >>>>>> 33.719: [GC 1368509K->137204K(6134208K), 0.2726067 secs] >>>>>> >>>>>> >>>>>> We are running Windows 2008 server R2. >>>>>> >>>>>> Regards, >>>>>> Jakob |
