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]
