[JIRA] Created: (LBCLASSIC-176) Asynchronous File appender
Asynchronous File appender -------------------------- Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: AsynchRollingFileAppender.java I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Konstantin Alexandrov updated LBCLASSIC-176: -------------------------------------------- Attachment: AsynchRollingFileAppender.java
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Ralph Goers commented on LBCLASSIC-176: --------------------------------------- Rather than write an asynchronous version of every appender it makes more sense to write a single AsynchAppender that can be configured with the appender to be made asynchronous. I have done that but haven't completely tested it. Also, Ceki has mentioned that he likes to avoid creating threads as they create problems. I know of no way to implement the asynchronous behavior without one. As for the attached code, I'm not sure why it doesn't implement the start and stop methods. Rather than requiring a synchronized block in subAppend, starting the threat in the start method would work better. Also, without the stop method there is no way to shutdown the thread so bad things will happen if the application is redeployed.
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Ralph Goers updated LBCLASSIC-176: ---------------------------------- Attachment: asynch.zip Here is the AsynchAppender I have lying around along with its test. This really needs more testing than this simple unit test.
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Konstantin Alexandrov commented on LBCLASSIC-176: ------------------------------------------------- About start/stop - understood. Agree this is better to implement starting and stopping here. Difference between your and mine appender is I use only one thread to write logs, your thread per appender. This is increase IO concurrency, not so good thing. Maybe this is better to configure "writer" groups, one per physical device. plus: ... // this is heavy thing, will be done in caller thread context. Rather than prepare this, it's bettrer to just create Throwable object in prepareForDeferredProcessing, // and use prepared object in getCallerData event.getCallerData(); //redundant, already done in prepareForDeferredProcessing event.getThreadName(); //if prepared, then reason of asynchronous handling is loosed, in this case we have only asynch writing event.getFormattedMessage(); ... My idea is to use one thread to prepare formatted message and for write disk file. Also, this is important for rolling file appender to cover possible blocking when logfile is rotated and compressed. I use my append for heavy loaded web application in trace enabled environment (up to 500K/sec of logs) and this is save cpu time and decrease io wait (according to vmstat under linux)
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Konstantin Alexandrov updated LBCLASSIC-176: -------------------------------------------- Attachment: AsynchRollingFileAppender.java Updated version of appender with start/stop implemented
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Ceki commented on LBCLASSIC-176: -------------------------------- AsyncAppender presents several interesting questions. One of them is what happens when the rate of service of the queue is slower than arrival the rate, that is when logs are arrive faster than they can be written. If this happens for any lengthy period of time, then events will be accumulated in the queue and eventually result in an OutOfMemoryException. Thus, AsyncAppender MUST have a bounded buffer. If non-blocking behaviror is desired, then, assuming the buffer is full, new events must be dropped. If events cannot be dropped then the caller will be blocked until room in the buffer is freed. The latest versions of log4j can drop events if configured to do so. I call this the (optionally) lossy AsyncAppender. We can have a more refined behavior prioritizing events depending on the level of incoming events. For example, for buffer size B, if occupancy is below 2/3, then accept all events, if the occupancy rate is above 2/3, then drop events of level TRACE, DEBUG, INFO, accepting events of level WARN and ERROR. If the occupancy rate is 100%, i.e. if there are B events in the buffer, then drop events of level TRACE, DEBUG and INFO and for events of level WARN and ERROR block until room becomes availalbe. I think such a policy strikes a very good balance between availability and performance. As in log4j, lossiness should be optional/configurable. Anyway, thank you for both for your contributions. Would you be interested in coding the policy outlines above?
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Ceki edited comment on LBCLASSIC-176 at 12/21/09 9:54 AM: ---------------------------------------------------------- AsyncAppender presents several interesting questions. One of them is what happens when the rate of service of the queue is slower than arrival the rate, that is when logs are arrive faster than they can be written. If this happens for any lengthy period of time, then events will be accumulated in the queue and eventually result in an OutOfMemoryException. Thus, AsyncAppender MUST have a bounded buffer. If non-blocking behaviror is desired, then, assuming the buffer is full, new events must be dropped. If events cannot be dropped then the caller will be blocked until room in the buffer is freed. The latest versions of log4j can drop events if configured to do so. I call this the (optionally) lossy AsyncAppender. We can have a more refined behavior prioritizing events depending on the level of incoming events. For example, for buffer size B, if occupancy is below 2/3, then accept all events, if the occupancy rate is above 2/3, then drop events of level TRACE, DEBUG, INFO, accepting events of level WARN and ERROR. If the occupancy rate is 100%, i.e. if there are B events in the buffer, then drop events of level TRACE, DEBUG and INFO and for events of level WARN and ERROR block until room becomes availalbe. I think such a policy strikes a very good balance between availability and performance. As in log4j, lossiness should be optional/configurable. Anyway, thank you for both for your contributions. Would you be interested in coding the policy outlined above? was (Author: ceki@qos.ch): AsyncAppender presents several interesting questions. One of them is what happens when the rate of service of the queue is slower than arrival the rate, that is when logs are arrive faster than they can be written. If this happens for any lengthy period of time, then events will be accumulated in the queue and eventually result in an OutOfMemoryException. Thus, AsyncAppender MUST have a bounded buffer. If non-blocking behaviror is desired, then, assuming the buffer is full, new events must be dropped. If events cannot be dropped then the caller will be blocked until room in the buffer is freed. The latest versions of log4j can drop events if configured to do so. I call this the (optionally) lossy AsyncAppender. We can have a more refined behavior prioritizing events depending on the level of incoming events. For example, for buffer size B, if occupancy is below 2/3, then accept all events, if the occupancy rate is above 2/3, then drop events of level TRACE, DEBUG, INFO, accepting events of level WARN and ERROR. If the occupancy rate is 100%, i.e. if there are B events in the buffer, then drop events of level TRACE, DEBUG and INFO and for events of level WARN and ERROR block until room becomes availalbe. I think such a policy strikes a very good balance between availability and performance. As in log4j, lossiness should be optional/configurable. Anyway, thank you for both for your contributions. Would you be interested in coding the policy outlines above?
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Konstantin Alexandrov commented on LBCLASSIC-176: ------------------------------------------------- I'm also worry about issue you describe, and choose ArrayBlockingQueue instead of Linked or Concurrent queue. I'm sorry, but your logic, from my point of view, is too complicated and may have lot of heuristics and raise conditions. ArrayBlockingQueue will block on put and logger behaviour will same as for RollingFileAppender. Also, this queue does not allocate new nodes to store events and use pre allocated circular buffer, which is match more fast than linked list and no need to be volatile or so, means no copying of variables from global memory to thread memory. I think such behaviour is predictable and easy to find weak chain using profiling or so. About events lose. I'm developer for financial systems, so for me, lose of events is crime ;) I'm interested for complete development of this part, but primary is using for my company applications
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Ralph Goers commented on LBCLASSIC-176: --------------------------------------- I have a couple comments. First, with regard to Konstantin's comments. "Difference between your and mine appender is I use only one thread to write logs, your thread per appender. " That is one difference. I consider the major difference to be that yours only supports the RollingFileAppender. I'm attempting to make any Appender asynchronous. Actually, with regards to the threads I think the right way to do this is to use a pool of threads. "// this is heavy thing, will be done in caller thread context. Rather than prepare this, it's bettrer to just create Throwable object in prepareForDeferredProcessing, and use prepared object in getCallerData". Yes, that would make sense except that prepareForDefferedProcessing currently doesn't do it so this code needs to. In addition, there is also nowhere to attach the new Throwable in the logging event and there is no method that would make use of it. However, whether or not to get callerData could be configurable. "//if prepared, then reason of asynchronous handling is loosed, in this case we have only asynch writing " There have been discussions that when Objects are passed as arguments that they are not necessarily static. Passing them to the worker thread may result in strange messages or odd behavior as the Objects may no longer be valid. For example, the application might be using a pool of objects to do some work and pass the current object on the logging call. By the time the worker thread processes it it could be in use for some other purpose. This problem cannot occur if the message is formatted on the same thread. As for Cekit's suggestions, yes they will make the code more complicated but they make sense to do. To be of value this Appender needs to be fairly flexible. I'm interested in doing the work, time permitting.
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Konstantin Alexandrov commented on LBCLASSIC-176: ------------------------------------------------- Ralph, you are right. Asynch or Buffered or Deffered processing match more important for rolling appender, because rolling of logfile may takes lot of time, we can talk about seconds in the case of big file (100m - why not) and compression. Thread pool - i'm not sure this is good idea. You will need to synchronize file writing, so no gain, just increase context switching. prepareForDeferredProcessing: I can not see any problem to add new Throwable(), for now - yes, will not work just add private/protected method to LoggingEvent private Throwable t = null getCallerThrowable(){ if (t==null) t = new Throwable(); return t; } Use this method instead of new Throwable() and call this method in prepareFordeferredProcessing() Pooling objects - yes, exactly, you right for flexible common usage appender. But this is responsibility of caller. Am I right conversion of content of argumentArray to string array can solve it in prepareFordeferredProcessing? ... for (int i=0;i<argumentArray.length;i++) argumentArray[i] = argumentArray[i].toString(); ... Okay, I think it's better to make behaviour configurable. I'm not so experienced in logback source code, so I will need time to implement configurable parameters. I think some parameters should be set in configuration file: - writer thread - max pending (deffered) events - differed serialization (true/false) - skip events level when max pending events reached p.s. Sorry for my English.
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Ralph Goers commented on LBCLASSIC-176: --------------------------------------- Don't worry, your English is good enough that I can understand you. I thought about pooling a bit more and I'm not sure it wouldn't introduce more problems than it is worth. Calling getCallerThrowable in prepareForDeferredProcessing doesn't work since there is nowhere in the event to store the returned Throwable. Interestingly, the changes I've made on my fork could make this simpler. That version of Logback uses Messages. A Message is an interface that has 3 methods - getFormattedMessage(), getMessageFormat() and getParameters(). getFormattedMessage() is required to always return the same result regardless of whether the Message was serialized and deserialized or is passed to a different thread. So with the version of Logback in my fork this problem doesn't exist. Since continuing to send patches is tedious any further work I do is going to end up in my fork at git://github.com/rgoers/logback.git.
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Ceki commented on LBCLASSIC-176: -------------------------------- FYI, RollingFileAppender already performs compression in a separate thread, i.e. asynchronously. It's not even an option, compression is always asynchronous.
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Torsten Juergeleit commented on LBCLASSIC-176: ---------------------------------------------- This could easily be done by using an asynchronous appender decorator. Maybe it's time now that Logback provides its own version of log4js AsyncAppender. I attached my take on this to LBCLASSIC-177.
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Konstantin Alexandrov commented on LBCLASSIC-176: ------------------------------------------------- I would like to close due http://jira.qos.ch/browse/LBCLASSIC-177
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Logback dev list Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-176?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu reassigned LBCLASSIC-176: ------------------------------------ Assignee: Ceki Gulcu (was: Logback dev list)
Asynchronous File appender --------------------------
Key: LBCLASSIC-176 URL: http://jira.qos.ch/browse/LBCLASSIC-176 Project: logback-classic Issue Type: New Feature Components: appender Reporter: Konstantin Alexandrov Assignee: Ceki Gulcu Attachments: asynch.zip, AsynchRollingFileAppender.java, AsynchRollingFileAppender.java
I implement asynch rolling file appender for my application, the reason is to decrease logging time in time critical part of application. This logger save up to 2 time logging time and decrease total IO concurrency. If you found this appender usable, then please include to distribution. Thanks
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
participants (5)
-
Ceki (JIRA) -
Ceki Gulcu (JIRA)
-
Konstantin Alexandrov (JIRA)
-
Ralph Goers (JIRA)
-
Torsten Juergeleit (JIRA)