logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ralph Goers <ralph.go...@dslextreme.com>
Subject Re: Compression of rolled files : performance issue when lots of JVMs are using timed based policy
Date Fri, 24 Mar 2017 17:47:16 GMT
I thought CronTriggeringPolicy would handle this but it is based on Quartz’ CronExpression
which doesn’t support randomizing fields. I was confused because Jenkins supports this and
I had thought it was using Quartz. Apparently not.

Ralph


> On Mar 24, 2017, at 10:15 AM, Anthony Maire <maire.anthony@gmail.com> wrote:
> 
> Basically we are hosting distributed systems for our clients. So we have
> several dozens of JVM per physical host, and several dozens of physical
> hosts. Moreover some clients are sometimes moved from one machine to
> another so having a single configuration file is a very huge requirement.
> 
> Having the file that rolls precisely at midnight is a nice to have. Having
> the rolling that happen a little later because of randomization can be
> accepted if it solve the performance issue (which stay pretty short, it's
> about 15 seconds during which we can experience a few hundreds of
> milliseconds long stalls but this is already too much in our industry )
> 
> Randomization is a common technique for that kind of issue, used in
> congestion avoidance in some network protocols for example (including
> Ethernet ). Having 2 or 3 jvm that roll at the same time is not a big deal,
> we have enough free cpu cycles for that. That's why randomization during a
> few minutes seems OK to me : we don't need to annihilate collisions,
> greatly reduce them is OK
> 
> Basically I'm open to any solution as long as it can be deployed everywhere
> without any OS/shell dependant trick and it does not involve any kind of
> per JVM configuration. The patch I submitted is an option, but I'd be glad
> to use another option that match these requirements.
> 
> Regards,
> Anthony
> 
> 
> Le 24 mars 2017 15:20, "Remko Popma" <remko.popma@gmail.com> a écrit :
> 
> Actually, there is already something like this because Log4j2 configuration
> has some support for scripting. I would prefer to enhance that over
> building conditional constructs in the configuration.
> 
> However, having to specify the exact rollover time for individual servers
> would result in a much more lengthy and involved configuration.
> Randomization is a commonly used technique to get roughly the same result
> without the inconvenience of precise configuration. I don't think it is
> such a bad idea.
> 
> Sent from my iPhone
> 
>> On Mar 24, 2017, at 19:35, Dominik Psenner <dpsenner@apache.org> wrote:
>> 
>> What if a configuration could contain conditional statements? For
> instance:
>> 
>> <Config>
>>   <Define EnvironmentVariable="Hour" Value="12" />
>>   <Define EnvironmentVariable="Minute" Value="0" />
>>   <If EnvironmentVariable="JVM" Equals="JVM1">
>>       <Define EnvironmentVariable="Minute" Value="0" />
>>   </If>
>>   <If EnvironmentVariable="JVM" Equals="JVM2">
>>       <Define EnvironmentVariable="Minute" Value="1" />
>>   </If>
>>   <RollingFileAppender>
>>       <RollingCondition>
>>           <Cron Minute="$Minute" Hour="$Hour" DayOfMonth="*" Month="*"
> DayOfWeek="*" />
>>       </RollingCondition>
>>   </RollingFileAppender>
>> </Config>
>> 
>> Cheers
>> 
>>> On 2017-03-24 11:08, Remko Popma wrote:
>>> I see what you are saying, but the use case is to have a single
> configuration, that is what drives the request.
>>> 
>>> Sent from my iPhone
>>> 
>>>> On Mar 24, 2017, at 17:22, Dominik Psenner <dpsenner@apache.org> wrote:
>>>> 
>>>> Hi there,
>>>> 
>>>> Cron proved itself very to be stable and usable over the past years.
> FWIW, I would not recommend to introduce a randomization algorithm. An
> application that does things random means that the application does things
> when nobody expects it to do so. Further it does not solve the problem. One
> just needs enough JVMs to roll around at the same time with a randomizer
> does not produce large enough values to spread the rolling over a larger
> amount of time. The available CPU is then quickly drain out. In my opinion,
> it's better to configure the several rollings to be delayed, meaning that
> JVM1 rolls at 12:00, JVM2 rolls at 12:01, ...
>>>> 
>>>> Cheers, Dominik
>>>> 
>>>>> On 2017-03-23 15:04, Anthony Maire wrote:
>>>>> https://issues.apache.org/jira/browse/LOG4J2-1855
>>>>> https://github.com/apache/logging-log4j2/pull/68
>>>>> 
>>>>> Let me know if you want me to do some changes
>>>>> 
>>>>> Regards,
>>>>> Anthony
>>>>> 
>>>>> 
>>>>> 2017-03-23 13:15 GMT+01:00 Anthony Maire <maire.anthony@gmail.com>:
>>>>> 
>>>>>> Ok,  I will open a jira ticket and provide a PR.
>>>>>> 
>>>>>> Thanks for your input.
>>>>>> 
>>>>>> Le 23 mars 2017 13:08, "Remko Popma" <remko.popma@gmail.com>
a écrit :
>>>>>> 
>>>>>>> I see what you mean now. I agree it's better to keep the rollover
> concept
>>>>>>> to mean file rename and compression that happen in sequence
> together. So
>>>>>>> the randomization affects when the _sequence_ is triggered, not
just
> one
>>>>>>> part of the sequence. Makes sense.
>>>>>>> 
>>>>>>> Sent from my iPhone
>>>>>>> 
>>>>>>>> On Mar 23, 2017, at 16:28, Anthony Maire <maire.anthony@gmail.com>
>>>>>>> wrote:
>>>>>>>> Hi Remko
>>>>>>>> 
>>>>>>>> My first idea was to have the rolling that triggers at the
expected
>>>>>>> time,
>>>>>>>> and the compression that will be delayed. That's why I wanted
the
>>>>>>> delayed
>>>>>>>> compression to occur before shutdown since the rolling already
> occurred.
>>>>>>>> 
>>>>>>>> But I think that's a bad idea. First, it will lead to "fancy
code"
> and I
>>>>>>>> would like to avoid it too. But the main issue is that this
behavior
>>>>>>> should
>>>>>>>> impact only the time based triggering when combining several
> policy. So
>>>>>>> the
>>>>>>>> code should be related to the triggering policy and not to
the
> rolling
>>>>>>>> strategy.
>>>>>>>> 
>>>>>>>> So the best thing to do is to add some property on the timed
base
>>>>>>>> triggering policy and let that class handle all the logic
and delay
> the
>>>>>>>> triggering itself instead of the compression.
>>>>>>>> 
>>>>>>>> Are you OK with that?
>>>>>>>> 
>>>>>>>> Anthony
>>>>>>>> 
>>>>>>>> Le 23 mars 2017 00:24, "Remko Popma" <remko.popma@gmail.com>
a
> écrit :
>>>>>>>> 
>>>>>>>> 
>>>>>>>>> On Mar 23, 2017, at 1:06, Anthony Maire <maire.anthony@gmail.com>
>>>>>>> wrote:
>>>>>>>>> Thanks for these answers
>>>>>>>>> 
>>>>>>>>> @Ralph : that was the kind of idea I had in mind : changing
the
>>>>>>>>> RollingFileManager.asyncExecutor to be a
> ScheduledThreadPoolExecutor,
>>>>>>> and
>>>>>>>>> based on some configuration, submitting task to be executed
after a
>>>>>>> random
>>>>>>>>> delay. However with this kind of approach, special treatment
> should be
>>>>>>>> made
>>>>>>>>> if the manager is stopped with some pending delayed tasks
in it.
>>>>>>>> I'm okay with randomization except for this last bit about
"special
>>>>>>>> treatment...". Let's not make it too fancy. If the manager
is
> stopped
>>>>>>>> before it rolled over, then it didn't roll over, just like
it works
>>>>>>>> currently. I don't see the point of adding extra logic to
trigger a
>>>>>>>> rollover when the manager is stopped within the randomized
time
> window.
>>>>>>>> 
>>>>>>>>> @Matt : Cron policy can be a solution, but I don't know
how to
> inject
>>>>>>> some
>>>>>>>>> random element in this to make the file roll at midnight
+ X random
>>>>>>>>> seconds. Since there is a lot of JVM to manage and some
of them
> can be
>>>>>>>>> moved from a machine to another, I need to have a single
log4j2.xml
>>>>>>> file
>>>>>>>>> for all environments. Moreover, our system administrators
are
>>>>>>> reluctant to
>>>>>>>>> have something based on a shell-specific feature (such
has the
> $RANDOM
>>>>>>>>> variable from bash)
>>>>>>>>> 
>>>>>>>>> Anthony
>>>>>>>>> 
>>>>>>>>> 2017-03-22 16:31 GMT+01:00 Ralph Goers <ralph.goers@dslextreme.com
>> :
>>>>>>>>> 
>>>>>>>>>> These are separate JVMs, so having a single executor
would be of
> no
>>>>>>> help.
>>>>>>>>>> I believe the only way to do what you are asking
for is to add
>>>>>>>>>> configuration so that the asynchronous thread has
a semi-random
> delay
>>>>>>>> when
>>>>>>>>>> it starts.
>>>>>>>>>> 
>>>>>>>>>> Ralph
>>>>>>>>>> 
>>>>>>>>>>> On Mar 22, 2017, at 7:58 AM, Greg Thomas <greg.d.thomas@gmail.com
>> 
>>>>>>>>>> wrote:
>>>>>>>>>>>> One common issue we have with that framework
(and I assume we
> can
>>>>>>> have
>>>>>>>>>> the
>>>>>>>>>>>> same with log4j2) is that all of our JVMs
(we can have more
> than 50
>>>>>>>>>> JVMs on
>>>>>>>>>>>> the same server in production) roll their
file at midnight.
>>>>>>>>>>>> 
>>>>>>>>>>>> When this happens, the system became often
not usable for a few
>>>>>>> seconds
>>>>>>>>>>>> because of the simultaneous zipping of all
the rolled files that
>>>>>>>>>> overload
>>>>>>>>>>>> the CPU (although zipping is done in a specific
background
> thread).
>>>>>>>>>>> ISTR that with the most recent versions of log4j,
these threads
> are
>>>>>>> in a
>>>>>>>>>>> thread pool so that they are properly shutdown
at the right
> time. I
>>>>>>>>>> wonder
>>>>>>>>>>> if it's possible (or could be possible) to somehow
inject a
> thread
>>>>>>> pool
>>>>>>>>>> in
>>>>>>>>>>> to log4j for this rollover, so that for you use
case you could
>>>>>>> inject a
>>>>>>>>>>> single thread executor, so only one thread is
ever compressing
> at a
>>>>>>>> time.
>>>>>>>>>>> Just a thought, anyway,
>>>>>>>>>>> 
>>>>>>>>>>> Greg
>>>>>>>>>>> 
>>>>>>>>>>> On 22 March 2017 at 13:47, Anthony Maire <maire.anthony@gmail.com
>> 
>>>>>>>>>> wrote:
>>>>>>>>>>>> Hi
>>>>>>>>>>>> 
>>>>>>>>>>>> We are currently using another logging framework
in production,
> but
>>>>>>> I'm
>>>>>>>>>>>> pushing to change it for log4j2.
>>>>>>>>>>>> 
>>>>>>>>>>>> One common issue we have with that framework
(and I assume we
> can
>>>>>>> have
>>>>>>>>>> the
>>>>>>>>>>>> same with log4j2) is that all of our JVMs
(we can have more
> than 50
>>>>>>>>>> JVMs on
>>>>>>>>>>>> the same server in production) roll their
file at midnight.
>>>>>>>>>>>> 
>>>>>>>>>>>> When this happens, the system became often
not usable for a few
>>>>>>> seconds
>>>>>>>>>>>> because of the simultaneous zipping of all
the rolled files that
>>>>>>>>>> overload
>>>>>>>>>>>> the CPU (although zipping is done in a specific
background
> thread).
>>>>>>> To
>>>>>>>>>>>> reduce this effect, we are combining a time
based rolling policy
>>>>>>> with a
>>>>>>>>>>>> sized based policy to zip smaller files,
but this is not enough
> to
>>>>>>> make
>>>>>>>>>> the
>>>>>>>>>>>> system fully responsive at midnight.
>>>>>>>>>>>> 
>>>>>>>>>>>> A pretty cool feature for us to avoid this
issue is to have the
>>>>>>>>>> possibility
>>>>>>>>>>>> when a rolling is triggered because of a
time based policy to
> change
>>>>>>>>>> file
>>>>>>>>>>>> immediately, but to wait for a random amount
of time (within a
>>>>>>>>>> configurable
>>>>>>>>>>>> limit) before starting the compression. This
random delay should
>>>>>>> help a
>>>>>>>>>> lot
>>>>>>>>>>>> to avoid contention on CPU cycles.
>>>>>>>>>>>> 
>>>>>>>>>>>> Does log4j2 have something to solve this
kind of issue ? If not,
>>>>>>> would
>>>>>>>>>> you
>>>>>>>>>>>> accept a pull request for this (I will open
a Jira if needed) ?
>>>>>>>>>>>> 
>>>>>>>>>>>> Regards,
>>>>>>>>>>>> Anthony
>>>>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>>> ------------------------------------------------------------
> ---------
>>>>>>>>>> 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
>>>>>>> ---------------------------------------------------------------------
>>>>>>> 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
>>>> 
>>> ---------------------------------------------------------------------
>>> 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
>> 
> 
> ---------------------------------------------------------------------
> 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


Mime
View raw message