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]>
