logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-506) Binary logging interface
Date Tue, 21 Jan 2014 23:28:29 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-506?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13878004#comment-13878004

Remko Popma commented on LOG4J2-506:

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
> }
> {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

To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org

View raw message