You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2014/01/22 00:32:20 UTC
[jira] [Comment Edited] (LOG4J2-506) Binary logging interface
[ https://issues.apache.org/jira/browse/LOG4J2-506?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13878004#comment-13878004 ]
Remko Popma edited comment on LOG4J2-506 at 1/21/14 11:30 PM:
--------------------------------------------------------------
Hi Gregg,
I saw your [talk|http://www.lucenerevolution.org/2013/Living-with-Garbage], nice work!
About binary logging, my original intention was to add this to log4j (and this is still an option), but as I was writing my response I realized that you don't need to wait for the next log4j2 release.
You can already start to do binary logging now, with the current version (beta9) of log4j2.
In fact, it would be great if you could try my suggestions above and give us your feedback. Perhaps there is a better API for the {{BinaryMessage}} interface, or there are more features to add to the {{BinaryLayout}} implementation?
Here are the steps to get up and running:
* Create the {{BinaryMessage}} interface (any package is fine)
* Create the {{BinaryLayout}} class
* At a minimum you would need the log4j-api-2.0.jar and the log4j-core-2.0.jar to compile and run.
* There is an adapter for the log4j-1.x API, so you should not need to modify your application to switch from log4j-1.2 to log4j-2.0. Of course, the places in your code where you log the objects that implement {{BinaryMessage}} would need to use the log4j-2.0 API. See the [FAQ|http://logging.apache.org/log4j/2.x/faq.html] for more jar details. _Be sure to remove the old log4j-1.x jar file!_
* The easiest way to configure is to name your configuration file {{log4j2.xml}} (the example above should work) and put it in the classpath.
* Do _not_ use logrotate with the RandomAccessFileAppender (this has issues: LOG4J2-354). Instead, use [RollingRandomAccessFileAppender|http://logging.apache.org/log4j/2.x/manual/appenders.html#RollingRandomAccessFileAppender] to accomplish the same.
Please let us know if there are any issues.
If this works well, it may actually be possible in the future to make binary logging completely garbage-free and copy-free by passing the {{RandomAccessFileAppender}}'s internal {{ByteBuffer}} to the {{BinaryMessage#writeInto(ByteBuffer)}} method directly. This would avoid the overhead of creating a new {{byte[]}} array and {{ByteBuffer}} object for each log event. (It would only work for {{RandomAccessFileAppender}} (and its Rolling variant).)
was (Author: remkop@yahoo.com):
Hi Gregg,
I saw your [talk|http://www.lucenerevolution.org/2013/Living-with-Garbage], nice work!
About binary logging, my original intention was to add this to log4j (and this is still an option), but as I was writing my response I realized that you don't need to wait for the next log4j2 release.
You can already start to do binary logging now, with the current version (beta9) of log4j2.
In fact, it would be great if you could try my suggestions above and give us your feedback. Perhaps there is a better API for the {{BinaryMessage}} interface, or there are more features to add to the {{BinaryLayout}} implementation?
Here are the steps to get up and running:
* Create the {{BinaryMessage}} interface (any package is fine)
* Create the {{BinaryLayout}} class
* At a minimum you would need the log4j-api-2.0.jar and the log4j-core-2.0.jar to compile and run. There is an adapter for the log4j-1.x API, so you should not need to modify your application to switch from log4j-1.2 to log4j-2.0. See the [FAQ|http://logging.apache.org/log4j/2.x/faq.html] for more jar details. _Be sure to remove the old log4j-1.x jar file!_
* The easiest way to configure is to name your configuration file {{log4j2.xml}} (the example above should work) and put it in the classpath.
* Do _not_ use logrotate with the RandomAccessFileAppender (this has issues: LOG4J2-354). Instead, use [RollingRandomAccessFileAppender|http://logging.apache.org/log4j/2.x/manual/appenders.html#RollingRandomAccessFileAppender] to accomplish the same.
Please let us know if there are any issues.
If this works well, it may actually be possible in the future to make binary logging completely garbage-free and copy-free by passing the {{RandomAccessFileAppender}}'s internal {{ByteBuffer}} to the {{BinaryMessage#writeInto(ByteBuffer)}} method directly. This would avoid the overhead of creating a new {{byte[]}} array and {{ByteBuffer}} object for each log event. (It would only work for {{RandomAccessFileAppender}} (and its Rolling variant).)
> Binary logging interface
> ------------------------
>
> Key: LOG4J2-506
> URL: https://issues.apache.org/jira/browse/LOG4J2-506
> Project: Log4j 2
> Issue Type: New Feature
> Components: Core, Layouts
> Reporter: Gregg Donovan
> Priority: Minor
>
> From [discussion|https://groups.google.com/forum/#!topic/mechanical-sympathy/7HdRCacJCDk] with Remko Pompa on the mechanical-sympathy list:
> {quote}We -- Etsy.com -- have a request logging system that we've begun to outgrow due to increased log volume and increased size of the messages we need to log. The messages are Thrift-encoded search requests from 1-100K in size. We use the logs to feed our homegrown traffic replay tools for offline performance tests and to reproduce issues found in production (GC, perf, etc.).
> For our next gen request logging system we would like the following:
> Low contention -- Minimal lock contention despite log writes from many (10s to 100s) application threads.
> Async writes -- File I/O should be outside of the actual request path.
> Binary logging -- Our current system base64 encodes the payload as a String and logs it via log4j 1.2. ;-) This creates more garbage than we would like and makes the data written twice as large. It was good enough for a while, but now we need something more efficient...
> Compression -- Either per-message or per block of messages would be great. Incurring large periodic CPU penalties from logrotate + gzip, as we do now, is less than ideal.
> Rotation -- Ideally based on file size, but time-based would also do.
> {quote}
> Remko:
> {quote}
> You can do this with log4j-2.0. The current version (log4j-2.0-beta-9) out of the box gives you 3 out of 5: Async Loggers use the Disruptor under the hood -> low contention & async writes, and RollingRandomAccessFileAppender (the fastest appender) can do rotation. This appender can also optionally do compression in a separate thread, but this happens on roll-over only, not continuously. (Still, I would guess that this is more CPU-efficient than using logrotate + gzip in a separate process...)
> The binary logging can be achieved with a bit of custom code.
> First, your objects would need to provide some way to turn themselves into bytes. I doubt that you want to use java standard serialization :-), so how about this as an interface to log4j that your objects would implement:
> {quote}
> {code:java}
> public interface BinaryMessage extends org.apache.logging.log4j.message.Message {
> int getLength(); // return byte count
> void writeInto(ByteBuffer buffer); // write length bytes from the current buffer position
> }
> {code}
> {quote}
> Log4j2 Loggers already have methods that take a Message argument (instead of a String), so in your application code you could just write
> {quote}
> {code:java}
> Logger logger = LogManager.getLogger(MyClass.class); // usually cached in static field
> logger.info(myObject); // where myObject implements BinaryMessage
> {code}
> {quote}
> Second, in the log4j2 framework, the Layout is responsible for converting a LogEvent into bytes, so you need a BinaryLayout that recognizes BinaryMessages. The layout could optionally output the timestamp (long) and log level (byte), followed by the message size (int) and the message bytes (byte[]).
> Using the log4j2 plugin model, an implementation could look something like below.
> {quote}
> {code:java}
> @Plugin(name = "BinaryLayout", category = "Core", elementType = "layout", printObject = true)
> public final class BinaryLayout extends AbstractLayout<LogEvent> {
> private static enum TimestampStrategy {
> WRITE {
> public void write(LogEvent event, ByteBuffer buffer) {
> buffer.putLong(event.getMillis());
> }
> },
> DONT {
> public void write(LogEvent event, ByteBuffer buffer) {
> }
> };
> abstract void write(LogEvent event, ByteBuffer buffer);
> }
> private static enum LevelStrategy {
> WRITE {
> public void write(LogEvent event, ByteBuffer buffer) {
> buffer.put((byte) event.getLevel().intLevel());
> }
> },
> DONT {
> public void write(LogEvent event, ByteBuffer buffer) {
> }
> };
> abstract void write(LogEvent event, ByteBuffer buffer);
> }
> private final TimestampStrategy timestamp;
> private final LevelStrategy level;
> private final int prefixLength;
> public BinaryLayout(boolean timestamp, boolean level) {
> this.timestamp = timestamp ? TimestampStrategy.WRITE : TimestampStrategy.DONT;
> this.level = level ? LevelStrategy.WRITE : LevelStrategy.DONT;
> final int stampBytes = timestamp ? 8 : 0;
> final int levelBytes = level ? 1 : 0;
> prefixLength = 4 + stampBytes + levelBytes;
> }
> @Override
> public byte[] toByteArray(LogEvent event) {
> final BinaryMessage msg = (BinaryMessage) event.getMessage();
> final byte[] result = new byte[msg.getLength() + prefixLength];
> final ByteBuffer buffer = ByteBuffer.wrap(result);
> timestamp.write(event, buffer);
> level.write(event, buffer);
> buffer.putInt(msg.getLength());
> msg.writeInto(buffer);
> return result;
> }
> @Override
> public LogEvent toSerializable(LogEvent event) {
> return event;
> }
> @Override
> public String getContentType() {
> return "application/octet-stream";
> }
> @Override
> public Map<String, String> getContentFormat() {
> return new HashMap<String, String>();
> }
> @PluginFactory
> public static BinaryLayout createLayout(
> @PluginAttribute("writeTimestamp") final String writeTimestamp,
> @PluginAttribute("writeLevel") final String writeLevel) {
> final boolean timestamp = Booleans.parseBoolean(writeTimestamp, false);
> final boolean level = Booleans.parseBoolean(writeLevel, false);
> return new BinaryLayout(timestamp, level);
> }
> }
> {code}
> {quote}
> Unfortunately the log4j API does not allow us to be completely garbage-free, you still need to allocate the byte[] array and ByteBuffer for each event...
> (The LogEvents are reused Disruptor ring buffer slots if you make all loggers AsyncLoggers.)
> Still, this should be a lot better (garbage-wise) than base64-encoding a String, and then turning that String into bytes again...
> Here is the log4j2.xml configuration that would put it all together (modify the "packages" attribute at the top to match your package):
> (Don't forget to set system property -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector to make all loggers AsyncLoggers.)
> {quote}
> {code:xml}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration status="WARN" packages="package.of.binary.layout.class">
> <Appenders>
> <RollingRandomAccessFile name="rraf" fileName="binary.log"
> filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz"
> append="false" immediateFlush="false">
> <BinaryLayout writeTimestamp="true" writeLevel="true" />
> <Policies>
> <TimeBasedTriggeringPolicy />
> <SizeBasedTriggeringPolicy size="250 MB"/>
> </Policies>
> </RollingRandomAccessFile>
> </Appenders>
>
> <Loggers>
> <Root level="trace" includeLocation="false">
> <AppenderRef ref="rraf"/>
> </Root>
> </Loggers>
> </Configuration>
> {code}
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org