Re: Log4j2 RollingFileAppender message not in order?

[Gary Gregory]

On Wed, Feb 21, 2018 at 10:41 AM, Remko Popma  wrote:

> I could be wrong, but I think the performance impact would be
> prohibitive.  Instead I would suggest doing some post-processing on the log
> files.
>

I agree.

Gary


>
> (Shameless plug) Every java main() method deserves http://picocli.info
>
> > On Feb 22, 2018, at 2:14, Benjamin Jaton 
> wrote:
> >
> > Ah thanks for the thoughts /feedback. I was just curious to know what you
> > would think of such a design for apps that needs to guaranty ordering.
> > Thanks!
> >
> >> On Tue, Feb 20, 2018 at 2:36 PM, Remko Popma 
> wrote:
> >>
> >> To come back to our questions, what version of Log4j are you using?
> >> Are you seeing log entries that are out of order in the same thread?
> >>
> >> (Shameless plug) Every java main() method deserves http://picocli.info
> >>
> >>> On Feb 21, 2018, at 7:15, Matt Sicker  wrote:
> >>>
> >>> On 20 February 2018 at 11:32, Benjamin Jaton  >
> >>> wrote:
> >>>
>  In the case of a multi threaded application, not async, would it be
>  possible to have avoid the potential mis ordering by having a 500ms
> (for
>  example) window of collection for log events, and instead of logging
> the
>  next log event in the queue, the logic would be search for the oldest
> >> event
>  in the queue and log it.
> 
> >>>
> >>> So like a priority queue/heap, where ordering is determined by log
> event
> >>> timestamp? Sounds like that could make a neat appender meta plugin
> (meta
> >>> like the routing appender, though perhaps it could be a plugin specific
> >> to
> >>> async loggers like a policy/strategy type class), though it may be
> >> overkill
> >>> for most scenarios unless log files must absolutely be done in exact
> >>> timestamp order. Plus, if you're using async logging, this could
> >>> potentially have a noticeable affect on performance (e.g., we could use
> >>> BlockingPriorityQueue, though now we cancel out the performance gains
> of
> >>> avoiding a blocking queue; or we could use a persistent data structure,
> >> but
> >>> then we lose GC-free logging, though chances are that BPQ already
> causes
> >>> garbage as it is).
> >>>
> >>> The tl;dr of this is that if you're logging synchronously and want
> events
> >>> in order, fitting in a PriorityQueue or BlockingPriorityQueue
> (depending
> >> on
> >>> single or multi producer scenarios respectively) would be the general
> way
> >>> to go, though it's not ideal for performance probably.
> >>>
> >>>
> >>> --
> >>> Matt Sicker 
> >>
> >> -
> >> 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
>
>

Re: Log4j2 RollingFileAppender message not in order?

[Matt Sicker]

In that case, you could log to a file and have a separate process collect
and sort logs, or you can log directly to a networked appender and take the
performance hit (which is probably higher than a heap-based approach).

On 21 February 2018 at 11:41, Remko Popma  wrote:

> I could be wrong, but I think the performance impact would be
> prohibitive.  Instead I would suggest doing some post-processing on the log
> files.
>
> (Shameless plug) Every java main() method deserves http://picocli.info
>
> > On Feb 22, 2018, at 2:14, Benjamin Jaton 
> wrote:
> >
> > Ah thanks for the thoughts /feedback. I was just curious to know what you
> > would think of such a design for apps that needs to guaranty ordering.
> > Thanks!
> >
> >> On Tue, Feb 20, 2018 at 2:36 PM, Remko Popma 
> wrote:
> >>
> >> To come back to our questions, what version of Log4j are you using?
> >> Are you seeing log entries that are out of order in the same thread?
> >>
> >> (Shameless plug) Every java main() method deserves http://picocli.info
> >>
> >>> On Feb 21, 2018, at 7:15, Matt Sicker  wrote:
> >>>
> >>> On 20 February 2018 at 11:32, Benjamin Jaton  >
> >>> wrote:
> >>>
>  In the case of a multi threaded application, not async, would it be
>  possible to have avoid the potential mis ordering by having a 500ms
> (for
>  example) window of collection for log events, and instead of logging
> the
>  next log event in the queue, the logic would be search for the oldest
> >> event
>  in the queue and log it.
> 
> >>>
> >>> So like a priority queue/heap, where ordering is determined by log
> event
> >>> timestamp? Sounds like that could make a neat appender meta plugin
> (meta
> >>> like the routing appender, though perhaps it could be a plugin specific
> >> to
> >>> async loggers like a policy/strategy type class), though it may be
> >> overkill
> >>> for most scenarios unless log files must absolutely be done in exact
> >>> timestamp order. Plus, if you're using async logging, this could
> >>> potentially have a noticeable affect on performance (e.g., we could use
> >>> BlockingPriorityQueue, though now we cancel out the performance gains
> of
> >>> avoiding a blocking queue; or we could use a persistent data structure,
> >> but
> >>> then we lose GC-free logging, though chances are that BPQ already
> causes
> >>> garbage as it is).
> >>>
> >>> The tl;dr of this is that if you're logging synchronously and want
> events
> >>> in order, fitting in a PriorityQueue or BlockingPriorityQueue
> (depending
> >> on
> >>> single or multi producer scenarios respectively) would be the general
> way
> >>> to go, though it's not ideal for performance probably.
> >>>
> >>>
> >>> --
> >>> Matt Sicker 
> >>
> >> -
> >> 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 

Re: Log4j2 RollingFileAppender message not in order?

[Gary Gregory]

On Wed, Feb 21, 2018 at 12:03 PM, Matt Sicker  wrote:

> In that case, you could log to a file and have a separate process collect
> and sort logs, or you can log directly to a networked appender and take the
> performance hit (which is probably higher than a heap-based approach).
>

That what databases are good at, with an index on a timestamp column.

Gary


>
> On 21 February 2018 at 11:41, Remko Popma  wrote:
>
> > I could be wrong, but I think the performance impact would be
> > prohibitive.  Instead I would suggest doing some post-processing on the
> log
> > files.
> >
> > (Shameless plug) Every java main() method deserves http://picocli.info
> >
> > > On Feb 22, 2018, at 2:14, Benjamin Jaton 
> > wrote:
> > >
> > > Ah thanks for the thoughts /feedback. I was just curious to know what
> you
> > > would think of such a design for apps that needs to guaranty ordering.
> > > Thanks!
> > >
> > >> On Tue, Feb 20, 2018 at 2:36 PM, Remko Popma 
> > wrote:
> > >>
> > >> To come back to our questions, what version of Log4j are you using?
> > >> Are you seeing log entries that are out of order in the same thread?
> > >>
> > >> (Shameless plug) Every java main() method deserves
> http://picocli.info
> > >>
> > >>> On Feb 21, 2018, at 7:15, Matt Sicker  wrote:
> > >>>
> > >>> On 20 February 2018 at 11:32, Benjamin Jaton <
> benjamin.ja...@gmail.com
> > >
> > >>> wrote:
> > >>>
> >  In the case of a multi threaded application, not async, would it be
> >  possible to have avoid the potential mis ordering by having a 500ms
> > (for
> >  example) window of collection for log events, and instead of logging
> > the
> >  next log event in the queue, the logic would be search for the
> oldest
> > >> event
> >  in the queue and log it.
> > 
> > >>>
> > >>> So like a priority queue/heap, where ordering is determined by log
> > event
> > >>> timestamp? Sounds like that could make a neat appender meta plugin
> > (meta
> > >>> like the routing appender, though perhaps it could be a plugin
> specific
> > >> to
> > >>> async loggers like a policy/strategy type class), though it may be
> > >> overkill
> > >>> for most scenarios unless log files must absolutely be done in exact
> > >>> timestamp order. Plus, if you're using async logging, this could
> > >>> potentially have a noticeable affect on performance (e.g., we could
> use
> > >>> BlockingPriorityQueue, though now we cancel out the performance gains
> > of
> > >>> avoiding a blocking queue; or we could use a persistent data
> structure,
> > >> but
> > >>> then we lose GC-free logging, though chances are that BPQ already
> > causes
> > >>> garbage as it is).
> > >>>
> > >>> The tl;dr of this is that if you're logging synchronously and want
> > events
> > >>> in order, fitting in a PriorityQueue or BlockingPriorityQueue
> > (depending
> > >> on
> > >>> single or multi producer scenarios respectively) would be the general
> > way
> > >>> to go, though it's not ideal for performance probably.
> > >>>
> > >>>
> > >>> --
> > >>> Matt Sicker 
> > >>
> > >> -
> > >> 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 
>

Re: Log4j2 RollingFileAppender message not in order?

[Remko Popma]

I could be wrong, but I think the performance impact would be prohibitive.  
Instead I would suggest doing some post-processing on the log files. 

(Shameless plug) Every java main() method deserves http://picocli.info

> On Feb 22, 2018, at 2:14, Benjamin Jaton  wrote:
> 
> Ah thanks for the thoughts /feedback. I was just curious to know what you
> would think of such a design for apps that needs to guaranty ordering.
> Thanks!
> 
>> On Tue, Feb 20, 2018 at 2:36 PM, Remko Popma  wrote:
>> 
>> To come back to our questions, what version of Log4j are you using?
>> Are you seeing log entries that are out of order in the same thread?
>> 
>> (Shameless plug) Every java main() method deserves http://picocli.info
>> 
>>> On Feb 21, 2018, at 7:15, Matt Sicker  wrote:
>>> 
>>> On 20 February 2018 at 11:32, Benjamin Jaton 
>>> wrote:
>>> 
 In the case of a multi threaded application, not async, would it be
 possible to have avoid the potential mis ordering by having a 500ms (for
 example) window of collection for log events, and instead of logging the
 next log event in the queue, the logic would be search for the oldest
>> event
 in the queue and log it.
 
>>> 
>>> So like a priority queue/heap, where ordering is determined by log event
>>> timestamp? Sounds like that could make a neat appender meta plugin (meta
>>> like the routing appender, though perhaps it could be a plugin specific
>> to
>>> async loggers like a policy/strategy type class), though it may be
>> overkill
>>> for most scenarios unless log files must absolutely be done in exact
>>> timestamp order. Plus, if you're using async logging, this could
>>> potentially have a noticeable affect on performance (e.g., we could use
>>> BlockingPriorityQueue, though now we cancel out the performance gains of
>>> avoiding a blocking queue; or we could use a persistent data structure,
>> but
>>> then we lose GC-free logging, though chances are that BPQ already causes
>>> garbage as it is).
>>> 
>>> The tl;dr of this is that if you're logging synchronously and want events
>>> in order, fitting in a PriorityQueue or BlockingPriorityQueue (depending
>> on
>>> single or multi producer scenarios respectively) would be the general way
>>> to go, though it's not ideal for performance probably.
>>> 
>>> 
>>> --
>>> Matt Sicker 
>> 
>> -
>> 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

Re: Log4j2 RollingFileAppender message not in order?

[Benjamin Jaton]

Ah thanks for the thoughts /feedback. I was just curious to know what you
would think of such a design for apps that needs to guaranty ordering.
Thanks!

On Tue, Feb 20, 2018 at 2:36 PM, Remko Popma  wrote:

> To come back to our questions, what version of Log4j are you using?
> Are you seeing log entries that are out of order in the same thread?
>
> (Shameless plug) Every java main() method deserves http://picocli.info
>
> > On Feb 21, 2018, at 7:15, Matt Sicker  wrote:
> >
> > On 20 February 2018 at 11:32, Benjamin Jaton 
> > wrote:
> >
> >> In the case of a multi threaded application, not async, would it be
> >> possible to have avoid the potential mis ordering by having a 500ms (for
> >> example) window of collection for log events, and instead of logging the
> >> next log event in the queue, the logic would be search for the oldest
> event
> >> in the queue and log it.
> >>
> >
> > So like a priority queue/heap, where ordering is determined by log event
> > timestamp? Sounds like that could make a neat appender meta plugin (meta
> > like the routing appender, though perhaps it could be a plugin specific
> to
> > async loggers like a policy/strategy type class), though it may be
> overkill
> > for most scenarios unless log files must absolutely be done in exact
> > timestamp order. Plus, if you're using async logging, this could
> > potentially have a noticeable affect on performance (e.g., we could use
> > BlockingPriorityQueue, though now we cancel out the performance gains of
> > avoiding a blocking queue; or we could use a persistent data structure,
> but
> > then we lose GC-free logging, though chances are that BPQ already causes
> > garbage as it is).
> >
> > The tl;dr of this is that if you're logging synchronously and want events
> > in order, fitting in a PriorityQueue or BlockingPriorityQueue (depending
> on
> > single or multi producer scenarios respectively) would be the general way
> > to go, though it's not ideal for performance probably.
> >
> >
> > --
> > Matt Sicker 
>
> -
> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>
>

Re: Log4j2 RollingFileAppender message not in order?

[Remko Popma]

To come back to our questions, what version of Log4j are you using?
Are you seeing log entries that are out of order in the same thread? 

(Shameless plug) Every java main() method deserves http://picocli.info

> On Feb 21, 2018, at 7:15, Matt Sicker  wrote:
> 
> On 20 February 2018 at 11:32, Benjamin Jaton 
> wrote:
> 
>> In the case of a multi threaded application, not async, would it be
>> possible to have avoid the potential mis ordering by having a 500ms (for
>> example) window of collection for log events, and instead of logging the
>> next log event in the queue, the logic would be search for the oldest event
>> in the queue and log it.
>> 
> 
> So like a priority queue/heap, where ordering is determined by log event
> timestamp? Sounds like that could make a neat appender meta plugin (meta
> like the routing appender, though perhaps it could be a plugin specific to
> async loggers like a policy/strategy type class), though it may be overkill
> for most scenarios unless log files must absolutely be done in exact
> timestamp order. Plus, if you're using async logging, this could
> potentially have a noticeable affect on performance (e.g., we could use
> BlockingPriorityQueue, though now we cancel out the performance gains of
> avoiding a blocking queue; or we could use a persistent data structure, but
> then we lose GC-free logging, though chances are that BPQ already causes
> garbage as it is).
> 
> The tl;dr of this is that if you're logging synchronously and want events
> in order, fitting in a PriorityQueue or BlockingPriorityQueue (depending on
> single or multi producer scenarios respectively) would be the general way
> to go, though it's not ideal for performance probably.
> 
> 
> -- 
> Matt Sicker 

-
To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-user-h...@logging.apache.org

Re: Log4j2 RollingFileAppender message not in order?

[Benjamin Jaton]

In the case of a multi threaded application, not async, would it be
possible to have avoid the potential mis ordering by having a 500ms (for
example) window of collection for log events, and instead of logging the
next log event in the queue, the logic would be search for the oldest event
in the queue and log it.
I haven't looked for where that happens in the code so maybe this is not
applicable or the performance impact would be too high.


On Thu, Dec 14, 2017 at 3:52 PM, Remko Popma  wrote:

> Best to upgrade to 2.10 if you’re not on it yet.
>
> Cheers!
>
> (Shameless plug) Every java main() method deserves http://picocli.info
>
> > On Dec 15, 2017, at 8:45, Benjamin Jaton 
> wrote:
> >
> > Oh interesting. Well this one appender is not async but it is multi
> > threaded, so I think that explains it.
> > Useful to know about 2031 though.
> >
> > Thanks
> > Benjamin
> >
> >> On Thu, Dec 14, 2017 at 2:54 PM, Remko Popma 
> wrote:
> >>
> >> Are you using Log4j 2.10?
> >> The reason I’m asking is that the 2.10 release contains a fix for
> >> https://issues.apache.org/jira/browse/LOG4J2-2031.
> >>
> >> Prior to 2.10, there was a possibility that log events ended up out of
> >> order in the log when you’re using async loggers or async appender and
> the
> >> appender could not keep up with the logging rate. Once the queue is
> full,
> >> previous versions of Log4j2 would bypass the queue and log directly to
> the
> >> appender.
> >>
> >> From 2.10, this only happens if Log4j2 determines there’s a risk for
> >> deadlock, otherwise the thread will enqueue the log event (possibly
> >> blocking until space is available in the queue).
> >>
> >> Remko
> >>
> >> (Shameless plug) Every java main() method deserves http://picocli.info
> >>
> >>> On Dec 15, 2017, at 7:22, Ralph Goers 
> >> wrote:
> >>>
> >>> In a multi-threaded application it is entirely possible that log
> entries
> >> might be appear to be out of order. This is because the LogEvent will
> >> populate the timestamp field but then another thread might get control,
> >> generate its log event, and then pass it to the appender before the
> first
> >> thread got a chance to pass the event to the appender. Are you seeing
> log
> >> entries that are out of order in the same thread? That shouldn’t happen.
> >>>
> >>> Ralph
> >>>
>  On Dec 14, 2017, at 3:09 PM, Benjamin Jaton  >
> >> wrote:
> 
>  Hello,
> 
>  I am seeing logs that are not in order in the log file, it this
> expected
>  when using a RollingFile appender?
> 
>  "appenders" : {
> "appender" : [ {
>   "type" : "RollingFile",
>   "name" : "ServerAppender",
>   "PatternLayout" : {
> "pattern" : "%d{-MM-dd HH:mm:ss,SSS} %-5p %c{1}:%L - %m%n"
>   },
>   "fileName" : "server.log",
>   "filePattern" : "server-%d{-MM-dd_HH-mm-ss}.log.zip",
>   "SizeBasedTriggeringPolicy" : {
> "size" : "100MB"
>   },
>   "bufferedIO" : "true",
>   "bufferSize" : "8192",
>   "immediateFlush" : "true",
>   "DefaultRolloverStrategy" : (...)
> }
> 
>  Thanks
>  Benjamin
> >>>
> >>>
> >>>
> >>> -
> >>> 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
>
>

Re: Log4j2 RollingFileAppender message not in order?

[Remko Popma]

Best to upgrade to 2.10 if you’re not on it yet. 

Cheers!

(Shameless plug) Every java main() method deserves http://picocli.info

> On Dec 15, 2017, at 8:45, Benjamin Jaton  wrote:
> 
> Oh interesting. Well this one appender is not async but it is multi
> threaded, so I think that explains it.
> Useful to know about 2031 though.
> 
> Thanks
> Benjamin
> 
>> On Thu, Dec 14, 2017 at 2:54 PM, Remko Popma  wrote:
>> 
>> Are you using Log4j 2.10?
>> The reason I’m asking is that the 2.10 release contains a fix for
>> https://issues.apache.org/jira/browse/LOG4J2-2031.
>> 
>> Prior to 2.10, there was a possibility that log events ended up out of
>> order in the log when you’re using async loggers or async appender and the
>> appender could not keep up with the logging rate. Once the queue is full,
>> previous versions of Log4j2 would bypass the queue and log directly to the
>> appender.
>> 
>> From 2.10, this only happens if Log4j2 determines there’s a risk for
>> deadlock, otherwise the thread will enqueue the log event (possibly
>> blocking until space is available in the queue).
>> 
>> Remko
>> 
>> (Shameless plug) Every java main() method deserves http://picocli.info
>> 
>>> On Dec 15, 2017, at 7:22, Ralph Goers 
>> wrote:
>>> 
>>> In a multi-threaded application it is entirely possible that log entries
>> might be appear to be out of order. This is because the LogEvent will
>> populate the timestamp field but then another thread might get control,
>> generate its log event, and then pass it to the appender before the first
>> thread got a chance to pass the event to the appender. Are you seeing log
>> entries that are out of order in the same thread? That shouldn’t happen.
>>> 
>>> Ralph
>>> 
 On Dec 14, 2017, at 3:09 PM, Benjamin Jaton 
>> wrote:
 
 Hello,
 
 I am seeing logs that are not in order in the log file, it this expected
 when using a RollingFile appender?
 
 "appenders" : {
"appender" : [ {
  "type" : "RollingFile",
  "name" : "ServerAppender",
  "PatternLayout" : {
"pattern" : "%d{-MM-dd HH:mm:ss,SSS} %-5p %c{1}:%L - %m%n"
  },
  "fileName" : "server.log",
  "filePattern" : "server-%d{-MM-dd_HH-mm-ss}.log.zip",
  "SizeBasedTriggeringPolicy" : {
"size" : "100MB"
  },
  "bufferedIO" : "true",
  "bufferSize" : "8192",
  "immediateFlush" : "true",
  "DefaultRolloverStrategy" : (...)
}
 
 Thanks
 Benjamin
>>> 
>>> 
>>> 
>>> -
>>> 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

Re: Log4j2 RollingFileAppender message not in order?

[Ralph Goers]

In a multi-threaded application it is entirely possible that log entries might 
be appear to be out of order. This is because the LogEvent will populate the 
timestamp field but then another thread might get control, generate its log 
event, and then pass it to the appender before the first thread got a chance to 
pass the event to the appender. Are you seeing log entries that are out of 
order in the same thread? That shouldn’t happen.

Ralph

> On Dec 14, 2017, at 3:09 PM, Benjamin Jaton  wrote:
> 
> Hello,
> 
> I am seeing logs that are not in order in the log file, it this expected
> when using a RollingFile appender?
> 
> "appenders" : {
>  "appender" : [ {
>"type" : "RollingFile",
>"name" : "ServerAppender",
>"PatternLayout" : {
>  "pattern" : "%d{-MM-dd HH:mm:ss,SSS} %-5p %c{1}:%L - %m%n"
>},
>"fileName" : "server.log",
>"filePattern" : "server-%d{-MM-dd_HH-mm-ss}.log.zip",
>"SizeBasedTriggeringPolicy" : {
>  "size" : "100MB"
>},
>"bufferedIO" : "true",
>"bufferSize" : "8192",
>"immediateFlush" : "true",
>"DefaultRolloverStrategy" : (...)
>  }
> 
> Thanks
> Benjamin



-
To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-user-h...@logging.apache.org