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" <ralph.go...@dslextreme.com> wrote:
Any news on this?
Ralph
> On Feb 13, 2017, at 5:00 PM, DiFrango, Ronald
<ronald.difra...@capitalone.com> 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" <remko.po...@gmail.com> 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 <ralph.go...@dslextreme.com> 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
<ronald.difra...@capitalone.com> 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" <boa...@gmail.com> wrote:
>>>
>>> If lots of data are being logged really quickly, then I could see that
>>> happening.
>>>
>>>> On 13 February 2017 at 14:20, Apache <ralph.go...@dslextreme.com>
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 <
>>>> ch...@christopherschultz.net> 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" <ralph.go...@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.difra...@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" <boa...@gmail.com> wrote:
>>>>>>>
>>>>>>> Are you logging that info?
>>>>>>>
>>>>>>> On 13 February 2017 at 11:46, DiFrango, Ronald <
>>>>>>> ronald.difra...@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" <boa...@gmail.com> wrote:
>>>>>>>>
>>>>>>>> What server environment are you running this in?
>>>>>>>>
>>>>>>>> On 13 February 2017 at 09:19, Remko Popma <
>>>> remko.po...@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.difra...@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 <boa...@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-unsubscr...@logging.apache.org
>>>>>>>> For additional commands, e-mail: log4j-user-h...@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-unsubscr...@logging.apache.org
>>>>>>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> --
>>>>>>> Matt Sicker <boa...@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-unsubscr...@logging.apache.org
>>>>>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> ------------------------------------------------------------
>>>> ---------
>>>>>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
>>>>>> For additional commands, e-mail: log4j-user-h...@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-unsubscr...@logging.apache.org
>>>>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>>>>>>
>>>>>
>>>>
>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>>>>
>>>>
>>>
>>>
>>> --
>>> Matt Sicker <boa...@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-unsubscr...@logging.apache.org
>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
>> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
> For additional commands, e-mail: log4j-user-h...@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-unsubscr...@logging.apache.org
> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-user-h...@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.
