logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Christopher Schultz <ch...@christopherschultz.net>
Subject Re: CPU Utilization: log4j 2.6 and great
Date Mon, 13 Feb 2017 20:12:34 GMT
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" <ralph.goers@dslextreme.com> 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 <Ronald.DiFrango@capitalone.com>
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" <boards@gmail.com> wrote:
>     > 
>     >    Are you logging that info?
>     > 
>     >    On 13 February 2017 at 11:46, DiFrango, Ronald <
>     >    Ronald.DiFrango@capitalone.com> 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" <boards@gmail.com> wrote:
>     >> 
>     >>        What server environment are you running this in?
>     >> 
>     >>        On 13 February 2017 at 09:19, Remko Popma <remko.popma@gmail.com>
>     >> 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 <
>     >>> Ronald.DiFrango@capitalone.com> 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 <boards@gmail.com>
>     >> 
>     >> 
>     >>    ________________________________________________________
>     >> 
>     >>    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: log4j-user-unsubscribe@logging.apache.org
>     >>    For additional commands, e-mail: log4j-user-help@logging.apache.org
>     >> 
>     >> 
>     >> 
>     >> ________________________________________________________
>     >> 
>     >> 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: log4j-user-unsubscribe@logging.apache.org
>     >> For additional commands, e-mail: log4j-user-help@logging.apache.org
>     >> 
>     >> 
>     > 
>     > 
>     >    -- 
>     >    Matt Sicker <boards@gmail.com>
>     > 
>     > 
>     > ________________________________________________________
>     > 
>     > 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: log4j-user-unsubscribe@logging.apache.org
>     > For additional commands, e-mail: log4j-user-help@logging.apache.org
>     > 
>     
>     
>     
>     ---------------------------------------------------------------------
>     To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>     For additional commands, e-mail: log4j-user-help@logging.apache.org
>     
>     
> 
> ________________________________________________________
> 
> 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: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
> 


Mime
View raw message