Yes, it makes sense, and it proves the point that everyone should test their own configuration. RollingRandomAccessFile is usually faster but isn’t always. Using async logging will be a win if it is OK for the application not to know if a log message fails for some reason, and if you aren’t maxing out on disk I/o.
Ralph > On Feb 18, 2017, at 2:09 PM, DiFrango, Ronald > <[email protected]> wrote: > > Laurent, > > We had several problems: > > 1) We had two different roll-over strategies, > a. One being time based with no time specified, therefore the file rolled > over every hour > b. One being size based, which never triggered > c. We switched to just the size based trigger > 2) We had 7+ appenders that were defined when only 4 were needed > 3) We didn’t have our logging level consistently set to our production > standard of WARN > > After correcting those issues, we switched over to: > > 1) Switched over to full async logging > 2) Switched RollingRandomAccessFile as its supposed to be the most efficient > for async logging. > > Make sense? > > Ron DiFrango > > > On 2/18/17, 3:32 PM, "[email protected]" <[email protected]> wrote: > > What does it mean "make your xml config efficient"? > > > Laurent Hasson > Co-Founder & CTO, CapsicoHealth Inc. > Sent from my BlackBerry Passport. > > Research has shown that capsaicin—the substance that gives hot red peppers > (or chilies) their kick, and boosts our metabolism—keeps immature fat cells > from developing into full-fledged ones. And a study presented in April found > that a compound in some sweet peppers (called CH-19 Sweet), which resembles > capsaicin, provides similar positive metabolic effects > > > Original Message > From: DiFrango, Ronald > Sent: Saturday, February 18, 2017 15:24 > To: Log4J Users List > Reply To: Log4J Users List > Subject: Re: CPU Utilization: log4j 2.6 and great > > Ralph, > > Sorry, we just figured it all out between Thursday and Friday, basically > it came down to a combination of both version 2.6.2 and our own code ☹ > Basically, if we upgrade to 2.7 and above, the utilization was still a little > higher, but not nearly as bad as 2.6.2. Plus, like I said, we had some > inefficient code that high logging rates, that made matters. > > Basically, we found that 2.6, 2.7, and 2.8 were approximately the same CPU > load but 2.6.2 wasn’t great because of the threading issue, but like you said > it spun them off. > > We also, found some inefficiencies in our log4j2.xml file that caused more > roll-overs to happen which made matters worse with 2.6.2. > > So the net was: > > 1) Some bad code on our part > 2) Upgrade to 2.7 and beyond > 3) Ensure your log4j2.xml file is efficient > > Thanks for the sounding board. > > Ron DiFrango > > > On 2/18/17, 3:01 PM, "Apache" <[email protected]> wrote: > > Any news on this? > > Ralph > >> On Feb 13, 2017, at 5:00 PM, DiFrango, Ronald >> <[email protected]> wrote: >> >> We’re going to try and pull that for you as we’re still working through was >> is going on. >> >> One question, though what would you use in place of the >> DefaultRolloverStrategy and max? >> >> Ron DiFrango >> >> On 2/13/17, 6:43 PM, "Remko Popma" <[email protected]> wrote: >> >> I've seen cases where the "max" in <DefaultRolloverStrategy >> max="${maxLogFiles}"/> caused issues because the directory contained many >> files that all needed to be scanned to see if they matched old log files to >> delete. >> >> That said, it would be good if you can share the results of jstack and do a >> run with Java Flight Recorder. >> >> Sent from my iPhone >> >>> On Feb 14, 2017, at 8:28, Apache <[email protected]> wrote: >>> >>> If you are seeing lots of threads can you do a jstack on the process so we >>> can see what they are? >>> >>> Ralph >>> >>>> On Feb 13, 2017, at 3:50 PM, DiFrango, Ronald >>>> <[email protected]> wrote: >>>> >>>> Our policy generally looks like the following where max log files is 2 and >>>> size is 10MB and we 6 appenders configured for various use cases, though >>>> the default is WARN so other than our performance logs, nothing is written >>>> to at high volume: >>>> >>>> <RollingRandomAccessFile name="APPLOGFILE" >>>> fileName="${base.log.dir}/app.log" >>>> filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz" >>>> immediateFlush="false" append="true"> >>>> <PatternLayout pattern="${appenderPatternLayout}"/> >>>> <Policies> >>>> <TimeBasedTriggeringPolicy/> >>>> <SizeBasedTriggeringPolicy size="${maxLogFileSize}"/> >>>> </Policies> >>>> <DefaultRolloverStrategy max="${maxLogFiles}"/> >>>> </RollingRandomAccessFile> >>>> >>>> Ron DiFrango >>>> >>>> On 2/13/17, 3:25 PM, "Matt Sicker" <[email protected]> wrote: >>>> >>>> If lots of data are being logged really quickly, then I could see that >>>> happening. >>>> >>>>> On 13 February 2017 at 14:20, Apache <[email protected]> wrote: >>>>> >>>>> The only threads in Log4j that I can think of that are short lived are the >>>>> threads that compress the files at rollover. That would only consume a lot >>>>> of CPU if rollover is happening a lot. >>>>> >>>>> Ralph >>>>> >>>>>> On Feb 13, 2017, at 1:12 PM, Christopher Schultz < >>>>> [email protected]> wrote: >>>>>> >>>>>> Ronald, >>>>>> >>>>>>> On 2/13/17 2:29 PM, DiFrango, Ronald wrote: >>>>>>> Yeah, I’m aware and agreed, but this is done in the Apache HTTP Client >>>>> Component’s Code, not ours and existed as-is with log4j2 in ALL the >>>>> versions we’ve been using. >>>>>>> >>>>>>> That said, I think this is a red herring and it’s still true that at >>>>> least for our application any version of log4j2 beyond 2.5 consumes more >>>>> CPU that 2.5 this is a REST based APi using Tomcat+Jersey+Spring [again >>>>> nothing has changed] and processing around 50 transactions per second with >>>>> a guarantee of a minimum of 1 log record to request. >>>>>>> >>>>>>> We just haven’t identified WHERE its causing the issue. >>>>>>> >>>>>>> One additional data point, we are using the bridging JAR’s for the >>>>> following as not all 3rd party libraries follow any standard on what they >>>>> use: >>>>>>> >>>>>>> Classis log4j >>>>>>> SLF4J >>>>>>> commons-logging >>>>>> >>>>>> >>>>>> You mentioned that lots of threads were being created and that they were >>>>>> short-lived. What code is creating those threads? You never said... >>>>>> >>>>>> -chris >>>>>> >>>>>>> On 2/13/17, 2:11 PM, "Apache" <[email protected]> wrote: >>>>>>> >>>>>>> The log.debug call will exit quickly, but if it is constructing a >>>>> large message that will happen anyway unless one of the standard >>>>> techniques >>>>> (like wrapping in a logger.isDebugEnabled call) is used to avoid it. >>>>> Constructing debug Strings can be expensive. >>>>>>> >>>>>>> Ralph >>>>>>> >>>>>>>> On Feb 13, 2017, at 10:58 AM, DiFrango, Ronald < >>>>> [email protected]> wrote: >>>>>>>> >>>>>>>> No we are not and since it’s a log.debug() it should just get dropped >>>>> on the floor before any sort of copying occurs, right? >>>>>>>> >>>>>>>> Ron DiFrango >>>>>>>> >>>>>>>> On 2/13/17, 12:50 PM, "Matt Sicker" <[email protected]> wrote: >>>>>>>> >>>>>>>> Are you logging that info? >>>>>>>> >>>>>>>> On 13 February 2017 at 11:46, DiFrango, Ronald < >>>>>>>> [email protected]> wrote: >>>>>>>> >>>>>>>>> All, >>>>>>>>> >>>>>>>>> One thing we just noticed is that we are using Apache’s HTTP >>>>> connection >>>>>>>>> pooling for our downstream calls and in our latest performance run is >>>>> that >>>>>>>>> the READ operation on org.apache.http.impl.conn.LoggingInputStream >>>>> seems >>>>>>>>> to be taking a bulk of the time. >>>>>>>>> >>>>>>>>> If I look at the code, once the HTTP client reads the byte stream it >>>>>>>>> issues a log.debug which could be a large payload, I wonder if that’s >>>>> what >>>>>>>>> is causing the issue? >>>>>>>>> >>>>>>>>> Please note aware, the version of httpclient we’ve been using has also >>>>>>>>> been constant: >>>>>>>>> >>>>>>>>> <dependency> >>>>>>>>> <groupId>org.apache.httpcomponents</groupId> >>>>>>>>> <artifactId>httpclient</artifactId> >>>>>>>>> <version>4.5.2</version> >>>>>>>>> </dependency> >>>>>>>>> >>>>>>>>> Ron DiFrango >>>>>>>>> >>>>>>>>> >>>>>>>>> On 2/13/17, 11:44 AM, "DiFrango, Ronald" <Ronald.DiFrango@capitalone. >>>>> com> >>>>>>>>> wrote: >>>>>>>>> >>>>>>>>> This is running in Tomcat 8.0.33 in a Docker Container via AWS’s ECS >>>>>>>>> which is identical to before with log4j2 2.5. >>>>>>>>> >>>>>>>>> We’ve run the application with Visual VM and the one thing for sure >>>>>>>>> that we’ve seen is that in 2.6.2 it created tons of threads, >>>>> something like >>>>>>>>> 50+ but on 2.6 or 2.7 it was only 2. Now the threads were short >>>>> lived, but >>>>>>>>> they got created. >>>>>>>>> >>>>>>>>> We’re running another performance test today with Async loggers to >>>>> see >>>>>>>>> if that helps or exhibits the same thing though previous testing with >>>>> Async >>>>>>>>> had some of the same char >>>>>>>>> >>>>>>>>> Here’s our layout pattern: >>>>>>>>> >>>>>>>>> [%t] %d{DATE} %-5p %-15c{1} [%X]: %cm%n >>>>>>>>> >>>>>>>>> Please not the %cm is a custom message handler that we use to use to >>>>>>>>> handle security filtering of the message payload aka we extend from >>>>>>>>> LogEventPatternConverter. >>>>>>>>> >>>>>>>>> Thanks, >>>>>>>>> >>>>>>>>> Ron DiFrango >>>>>>>>> >>>>>>>>> On 2/13/17, 11:22 AM, "Matt Sicker" <[email protected]> wrote: >>>>>>>>> >>>>>>>>> What server environment are you running this in? >>>>>>>>> >>>>>>>>> On 13 February 2017 at 09:19, Remko Popma < >>>>> [email protected]> >>>>>>>>> wrote: >>>>>>>>> >>>>>>>>>> Ron, >>>>>>>>>> >>>>>>>>>> We haven't heard of any issues like you describe. >>>>>>>>>> Have you tried running your application with Java Flight Recorder >>>>>>>>>> <https://docs.oracle.com/javacomponents/jmc-5-4/jfr- >>>>>>>>>> runtime-guide/run.htm#JFRUH176>? >>>>>>>>>> This should help diagnose what is going on. >>>>>>>>>> >>>>>>>>>> Remko >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>>> On Mon, Feb 13, 2017 at 9:59 PM, DiFrango, Ronald < >>>>>>>>>> [email protected]> wrote: >>>>>>>>>> >>>>>>>>>>> All, >>>>>>>>>>> >>>>>>>>>>> We recently upgrade to 2.6 and noticed a dramatic increase in >>>>>>>>> CPU and >>>>>>>>>>> Thread utilization that seems to be tied to the new “garbage >>>>>>>>> free” mode >>>>>>>>>> of >>>>>>>>>>> log4j 2.6. Here’s some of the baseline numbers: >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> · Log4j 2.5: CPU typically ran around 25% >>>>>>>>>>> >>>>>>>>>>> · Log4j 2.6: CPU typically ran around 75% >>>>>>>>>>> >>>>>>>>>>> · Log4j 2.6.2+: CPU typically ran around 100% >>>>>>>>>>> >>>>>>>>>>> · We’ve also tried turning off garbage free mode and >>>>>>>>> that made >>>>>>>>>>> things worse as the CPU was around 120% and caused us to not >>>>>>>>> meet our >>>>>>>>>> SLA’s >>>>>>>>>>> >>>>>>>>>>> It important to note that this is a REST Api using Jersey and >>>>>>>>> typically >>>>>>>>>>> responds in about in under 50ms on a per request so its high >>>>>>>>> volume, but >>>>>>>>>>> the logging level is WARN or higher except for our single >>>>>>>>> performance log >>>>>>>>>>> record which is written once per request using the lambda base >>>>>>>>> approach. >>>>>>>>>>> >>>>>>>>>>> Our next test is going to be switching to all ASYNC loggers >>>>>>>>> and see what >>>>>>>>>>> effect that has, but I guess the general question is, has >>>>>>>>> anyone else >>>>>>>>>> seen >>>>>>>>>>> this? Any thoughts? >>>>>>>>>>> >>>>>>>>>>> Ron DiFrango >>>>>>>>>>> ________________________________________________________ >>>>>>>>>>> >>>>>>>>>>> The information contained in this e-mail is confidential and/or >>>>>>>>>>> proprietary to Capital One and/or its affiliates and may only >>>>>>>>> be used >>>>>>>>>>> solely in performance of work or services for Capital One. The >>>>>>>>>> information >>>>>>>>>>> transmitted herewith is intended only for use by the >>>>>>>>> individual or entity >>>>>>>>>>> to which it is addressed. If the reader of this message is not >>>>>>>>> the >>>>>>>>>> intended >>>>>>>>>>> recipient, you are hereby notified that any review, >>>>>>>>> retransmission, >>>>>>>>>>> dissemination, distribution, copying or other use of, or >>>>>>>>> taking of any >>>>>>>>>>> action in reliance upon this information is strictly >>>>>>>>> prohibited. If you >>>>>>>>>>> have received this communication in error, please contact the >>>>>>>>> sender and >>>>>>>>>>> delete the material from your computer. >>>>>>>>>>> >>>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> -- >>>>>>>>> Matt Sicker <[email protected]> >>>>>>>>> >>>>>>>>> >>>>>>>>> ________________________________________________________ >>>>>>>>> >>>>>>>>> The information contained in this e-mail is confidential and/or >>>>>>>>> proprietary to Capital One and/or its affiliates and may only be used >>>>>>>>> solely in performance of work or services for Capital One. The >>>>> information >>>>>>>>> transmitted herewith is intended only for use by the individual or >>>>> entity >>>>>>>>> to which it is addressed. If the reader of this message is not the >>>>> intended >>>>>>>>> recipient, you are hereby notified that any review, retransmission, >>>>>>>>> dissemination, distribution, copying or other use of, or taking of any >>>>>>>>> action in reliance upon this information is strictly prohibited. If >>>>> you >>>>>>>>> have received this communication in error, please contact the sender >>>>> and >>>>>>>>> delete the material from your computer. >>>>>>>>> >>>>>>>>> ------------------------------------------------------------ >>>>> --------- >>>>>>>>> To unsubscribe, e-mail: [email protected] >>>>>>>>> For additional commands, e-mail: [email protected] >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> ________________________________________________________ >>>>>>>>> >>>>>>>>> The information contained in this e-mail is confidential and/or >>>>>>>>> proprietary to Capital One and/or its affiliates and may only be used >>>>>>>>> solely in performance of work or services for Capital One. The >>>>> information >>>>>>>>> transmitted herewith is intended only for use by the individual or >>>>> entity >>>>>>>>> to which it is addressed. If the reader of this message is not the >>>>> intended >>>>>>>>> recipient, you are hereby notified that any review, retransmission, >>>>>>>>> dissemination, distribution, copying or other use of, or taking of any >>>>>>>>> action in reliance upon this information is strictly prohibited. If >>>>> you >>>>>>>>> have received this communication in error, please contact the sender >>>>> and >>>>>>>>> delete the material from your computer. >>>>>>>>> >>>>>>>>> --------------------------------------------------------------------- >>>>>>>>> To unsubscribe, e-mail: [email protected] >>>>>>>>> For additional commands, e-mail: [email protected] >>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>>> >>>>>>>> -- >>>>>>>> Matt Sicker <[email protected]> >>>>>>>> >>>>>>>> >>>>>>>> ________________________________________________________ >>>>>>>> >>>>>>>> The information contained in this e-mail is confidential and/or >>>>> proprietary to Capital One and/or its affiliates and may only be used >>>>> solely in performance of work or services for Capital One. The information >>>>> transmitted herewith is intended only for use by the individual or entity >>>>> to which it is addressed. If the reader of this message is not the >>>>> intended >>>>> recipient, you are hereby notified that any review, retransmission, >>>>> dissemination, distribution, copying or other use of, or taking of any >>>>> action in reliance upon this information is strictly prohibited. If you >>>>> have received this communication in error, please contact the sender and >>>>> delete the material from your computer. >>>>>>>> >>>>>>>> --------------------------------------------------------------------- >>>>>>>> To unsubscribe, e-mail: [email protected] >>>>>>>> For additional commands, e-mail: [email protected] >>>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>> ------------------------------------------------------------ >>>>> --------- >>>>>>> To unsubscribe, e-mail: [email protected] >>>>>>> For additional commands, e-mail: [email protected] >>>>>>> >>>>>>> >>>>>>> >>>>>>> ________________________________________________________ >>>>>>> >>>>>>> The information contained in this e-mail is confidential and/or >>>>> proprietary to Capital One and/or its affiliates and may only be used >>>>> solely in performance of work or services for Capital One. The information >>>>> transmitted herewith is intended only for use by the individual or entity >>>>> to which it is addressed. If the reader of this message is not the >>>>> intended >>>>> recipient, you are hereby notified that any review, retransmission, >>>>> dissemination, distribution, copying or other use of, or taking of any >>>>> action in reliance upon this information is strictly prohibited. If you >>>>> have received this communication in error, please contact the sender and >>>>> delete the material from your computer. >>>>>>> >>>>>>> --------------------------------------------------------------------- >>>>>>> To unsubscribe, e-mail: [email protected] >>>>>>> For additional commands, e-mail: [email protected] >>>>>>> >>>>>> >>>>> >>>>> >>>>> >>>>> --------------------------------------------------------------------- >>>>> To unsubscribe, e-mail: [email protected] >>>>> For additional commands, e-mail: [email protected] >>>>> >>>>> >>>> >>>> >>>> -- >>>> Matt Sicker <[email protected]> >>>> >>>> >>>> ________________________________________________________ >>>> >>>> The information contained in this e-mail is confidential and/or >>>> proprietary to Capital One and/or its affiliates and may only be used >>>> solely in performance of work or services for Capital One. The information >>>> transmitted herewith is intended only for use by the individual or entity >>>> to which it is addressed. If the reader of this message is not the >>>> intended recipient, you are hereby notified that any review, >>>> retransmission, dissemination, distribution, copying or other use of, or >>>> taking of any action in reliance upon this information is strictly >>>> prohibited. If you have received this communication in error, please >>>> contact the sender and delete the material from your computer. >>>> >>>> --------------------------------------------------------------------- >>>> To unsubscribe, e-mail: [email protected] >>>> For additional commands, e-mail: [email protected] >>>> >>> >>> >>> >>> --------------------------------------------------------------------- >>> To unsubscribe, e-mail: [email protected] >>> For additional commands, e-mail: [email protected] >>> >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: [email protected] >> For additional commands, e-mail: [email protected] >> >> >> >> ________________________________________________________ >> >> The information contained in this e-mail is confidential and/or proprietary >> to Capital One and/or its affiliates and may only be used solely in >> performance of work or services for Capital One. The information transmitted >> herewith is intended only for use by the individual or entity to which it is >> addressed. If the reader of this message is not the intended recipient, you >> are hereby notified that any review, retransmission, dissemination, >> distribution, copying or other use of, or taking of any action in reliance >> upon this information is strictly prohibited. If you have received this >> communication in error, please contact the sender and delete the material >> from your computer. >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: [email protected] >> For additional commands, e-mail: [email protected] >> > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > > > > ________________________________________________________ > > The information contained in this e-mail is confidential and/or > proprietary to Capital One and/or its affiliates and may only be used solely > in performance of work or services for Capital One. The information > transmitted herewith is intended only for use by the individual or entity to > which it is addressed. If the reader of this message is not the intended > recipient, you are hereby notified that any review, retransmission, > dissemination, distribution, copying or other use of, or taking of any action > in reliance upon this information is strictly prohibited. If you have > received this communication in error, please contact the sender and delete > the material from your computer. > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > > > > ________________________________________________________ > > The information contained in this e-mail is confidential and/or proprietary > to Capital One and/or its affiliates and may only be used solely in > performance of work or services for Capital One. The information transmitted > herewith is intended only for use by the individual or entity to which it is > addressed. If the reader of this message is not the intended recipient, you > are hereby notified that any review, retransmission, dissemination, > distribution, copying or other use of, or taking of any action in reliance > upon this information is strictly prohibited. If you have received this > communication in error, please contact the sender and delete the material > from your computer. > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
