[logback-dev] [JIRA] (LOGBACK-1238) RollingFileAppender generating a large numbers of .tmp files

[QOS.CH (JIRA)]

Title: Message Title

Richard Fearn commented on LOGBACK-1238   Re: RollingFileAppender generating a large numbers of .tmp files I think this problem has got worse with 1.1.7 because as time goes on, Logback is being changed to execute tasks using a per-context ExecutorService backed by a 2-thread pool. We use a central log server that both receives log events from other processes (through a SimpleSocketServer) and can forward those log events to other consumers (using a ServerSocketAppender). (The consumers are usually standalone log panels, running on different machines.) In our scenario the problem is that the task that accepts new connections to the ServerSocketAppender is submitted to the context executor. ServerSocketAppender extends AbstractServerSocketAppender, which does: runner = createServerRunner(listener, getContext().getExecutorService()); runner.setContext(getContext()); getContext().getExecutorService().execute(runner); and you can see this in a thread dump: "logback-1" #9 daemon prio=5 os_prio=0 tid=0x00007fcc0c239800 nid=0x42e6 runnable [0x00007fcbf7dfc000] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409) at java.net.ServerSocket.implAccept(ServerSocket.java:545) at java.net.ServerSocket.accept(ServerSocket.java:513) at ch.qos.logback.core.net.server.ServerSocketListener.acceptClient(ServerSocketListener.java:44) at ch.qos.logback.core.net.server.ConcurrentServerRunner.run(ConcurrentServerRunner.java:132) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) When a connection to the ServerSocketAppender is accepted, the task for that connection is also submitted to the context executor. In ConcurrentServerRunner: T client = listener.acceptClient(); [...] executor.execute(new ClientWrapper(client)); and this task can also be seen in a thread dump: "logback-2" #13 daemon prio=5 os_prio=0 tid=0x00007ff994001800 nid=0x48aa waiting on condition [0x00007ff9e9484000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x000000076db192d8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:403) at ch.qos.logback.core.net.server.RemoteReceiverStreamClient.run(RemoteReceiverStreamClient.java:106) at ch.qos.logback.core.net.server.ConcurrentServerRunner$ClientWrapper.run(ConcurrentServerRunner.java:209) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) With one client connected, two long-running tasks are being executed by the executor, meaning both threads in the pool are busy, and new tasks that are submitted will be queued, but not executed immediately. Log file compression is also a task that gets submitted to the executor. From Compressor: public Future<?> asyncCompress(String nameOfFile2Compress, String nameOfCompressedFile, String innerEntryName) throws RolloverFailure { CompressionRunnable runnable = new CompressionRunnable(nameOfFile2Compress, nameOfCompressedFile, innerEntryName); ExecutorService executorService = context.getExecutorService(); Future<?> future = executorService.submit(runnable); return future; } So one client connected to a ServerSocketAppender means that log files won't be compressed when they are rolled over. I'll attach an example config that can be used to test this. Add Comment   This message was sent by Atlassian JIRA (v6.4.12#64027-sha1:e3691cc)

_______________________________________________
logback-dev mailing list
logback-dev@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-dev