LylatWars LylatWars - 6 months ago 15
Java Question

Using java.util.logger with a separate thread to write on file?

I have 2 FileHandlers that write out to two separate files, and the amount of I/O occurring is slowing down my application quite a bit:


  1. I've decided to have the FileHandlers run on separate threads.

  2. As they are on separate threads, I needed a concept of a "queue", so that these separate threads can poll this queue and print out any incoming messages.

  3. I've preformatted messages so that any arguments used do not change before they actually reach the print out in the FileHandler.

  4. Now I've realised that I can't use the "log" methods provided by the logger, as that attempts to invoke methods on the current thread to format and print out the messages.

  5. So I simply call a method that adds my trace message to the queue.

  6. I then use run() method of the FileHandlers to print out the messages using publish().

  7. I now realise publish() only takes in a LogRecord, which is just a level + message.

  8. My traces have much more, which can't simply be placed in an overall message, I want to be able to use the "Formatter" that I've set to the FileHandler.

  9. So I create an instance of the logger in the FileHandler, so I can use the log method and format the string as designed in the Formatter.



Which works, kinda.

...

This is getting a bit silly, is it worth continuing on like this, working AROUND the java.util.Logger rather than working with it? One of the useful parts of the java.util.Logger is having a separate logger instance for each class and being able to have more control over the messages...

Any suggestions?

The code is quite long, but I think it's easily understood from the description above, if not let me know and I'll upload somewhere.

Thanks.

Answer

If I/O is truly the bottleneck and you don't need file rotation and file locking then create a Handler that queues the fully formatted output string/bytebuffer from your LogRecord + "trace message". Then hand off/queue the fully formatted output string/bytebuffer to a thread to perform the I/O.

Otherwise, if you need to use the FileHandler and want to pass a LogRecord + your trace to the publish method you can just subclass the FileHandler and then create a mapping between your LogRecord and trace that is visible to your custom formatter. A few ways to do that are:

  1. Create a Map visible to both the handler and formatter.
  2. Create a LogRecord subclass to hold the trace and convert each LogRecord to your new subclass and super.publish the LogRecord subclass. Then cast each LogRecord in your formatter to access the trace.

4.Now I've realised that I can't use the "log" methods provided by the logger, as that attempts to invoke methods on the current thread to format and print out the messages.

Logger.log creates LogRecords and invokes handler.publish for the attached handlers and parent handlers by default. It is handler.publish that is performing the I/O on the current thread. What you have to do is remove all handlers that perform I/O on publish and replace them with handlers that just queue LogRecords on publish.

Here is an example of how to create an AsyncFileHandler:

    public class AsyncFileHandler extends FileHandler implements Runnable {

        private static final int offValue = Level.OFF.intValue();
        private final BlockingQueue<LogRecord> queue = new ArrayBlockingQueue<>(5000);
        private volatile Thread worker;

        public AsyncFileHandler() throws IOException {
            super();
        }

        public AsyncFileHandler(String pattern, int limit, int count, boolean append)
                throws IOException {
            super(pattern, limit, count, append);
        }

        @Override
        public void publish(LogRecord record) {
            int levelValue = getLevel().intValue();
            if (record.getLevel().intValue() < levelValue || levelValue == offValue) {
                return;
            }

            final Thread t = checkWorker();
            record.getSourceMethodName(); //Infer caller.
            boolean interrupted = Thread.interrupted();
            try {
                for (;;) {
                    try {
                        boolean offered = queue.offer(record, 10, TimeUnit.MILLISECONDS);
                        if (t == null || !t.isAlive()) {
                            if (!offered || queue.remove(record)) {
                                handleShutdown(record);
                            }
                            break;
                        } else {
                            if (offered || handleFullQueue(record)) {
                                break;
                            }
                        }
                    } catch (InterruptedException retry) {
                        interrupted = true;
                    }
                }
            } finally {
                if (interrupted) {
                    Thread.currentThread().interrupt();
                }
            }
        }

        private boolean handleFullQueue(LogRecord r) {
            super.publish(r);
            return true; //true if handled.
        }

        private void handleShutdown(LogRecord r) {
            super.publish(r);
        }

        @Override
        public void close() {
            try {
                try {
                    final Thread t = this.worker;
                    if (t != null) {
                        t.interrupt();
                        shutdownQueue();
                        t.join();
                        shutdownQueue();
                    }
                } finally {
                    super.close();
                }
            } catch (InterruptedException reAssert) {
                Thread.currentThread().interrupt();
            }
        }

        private void shutdownQueue() {
            for (LogRecord r; (r = queue.poll()) != null;) {
                handleShutdown(r);
            }
        }

        @Override
        public void run() {
            try {
                final BlockingQueue<LogRecord> q = this.queue;
                for (;;) {
                    super.publish(q.take());
                }
            } catch (InterruptedException shutdown) {
                shutdownQueue();
                Thread.currentThread().interrupt();
            }
        }

        private Thread checkWorker() {
            Thread t = worker;
            if (t == null) {
                t = startWorker();
            }
            return t;
        }

        private synchronized Thread startWorker() {
            if (worker == null) {
                worker = Executors.defaultThreadFactory().newThread(this);
                worker.setDaemon(true);
                worker.start();
            }
            return worker;
        }
    }

There is advice in the LogRecord documentation which even the original authors fail to follow in the MemoryHandler. It reads as the following:

Therefore, if a logging Handler wants to pass off a LogRecord to another thread, or to transmit it over RMI, and if it wishes to subsequently obtain method name or class name information it should call one of getSourceClassName or getSourceMethodName to force the values to be filled in.

So if you are going to buffer LogRecords in a queue you have to call getSourceClassName or getSourceMethodName before you add the records to the queue. Otherwise your log will record the wrong source class and source method names.

Comments