Logback: AsyncAppender braucht mehr Zeit als Synchronous FileAppender

Question

Ich sehe Logbuch asynchrone Protokollierung bietet schlechtere Leistung als synchrone Protokollierung. Details unten.

Was könnte ich vermissen?

Testklasse:

import org.slf4j.Logger; 
import org.slf4j.LoggerFactory; 
public class Main extends Thread { 

    public static final Logger defaultLogger = LoggerFactory.getLogger(Main.class); 

    public static void main(String[] args) throws IOException { 
     new Main().start(); 
     System.out.println("... Thread started\n"); 

     // This is to block till thread finishes writing 
     System.in.read(); 
    } 

    public void run() { 
     long start = System.currentTimeMillis(); 

     for(int i = 0; i < 1000000; i++) {   
      defaultLogger.warn("Default logger:"); 
     } 

     long end = System.currentTimeMillis(); 

     System.out.println("\n**** " + new Long(end - start)); 
    } 
} 

logback.xml:

<configuration> 

    <appender name="DEFAULT-FILE" class="ch.qos.logback.core.FileAppender"> 
     <append>true</append> 
     <file>logger.log</file> 
     <encoder charset="UTF-8"> 
      <pattern>[%date] [%thread] %msg %n</pattern> 
     </encoder> 
    </appender> 

    <appender name="DEFAULT-ASYNC" class="ch.qos.logback.classic.AsyncAppender"> 
     <!-- Have tried to play around with queue size - no major effect --> 
     <!-- <queueSize>512</queueSize> --> 
     <discardingThreshold>0</discardingThreshold> 
     <appender-ref ref="DEFAULT-FILE" /> 
    </appender> 

    <root level="all"> 
     <!-- Switch between the two appenders --> 
     <appender-ref ref="DEFAULT-FILE" /> 
     <!-- <appender-ref ref="DEFAULT-ASYNC" /> --> 
    </root> 

</configuration> 

Beobachtungen:

Sync FileAppender: ~ 5000ms AsyncAppender: ~ 7000ms

Versionen:

slf4j: 1.7.19 logback: 1.1.6

Answer 1

Ein Problem des Codes ist, dass Sie erstellen 1000000 Protokollierung Einträge in einer sehr kurzen Zeit, aber der AsyncAppender hat eine Warteschlange mit einer maximalen Kapazität von 256 (Standard).

Daher müssen Sie als ersten Schritt die Warteschlangengröße auf 1000000 erhöhen. Andernfalls ist die von Ihnen gemessene Zeit ungültig.

Außerdem sollten Sie mehrere Messungen in derselben JVM-Instanz durchführen und die erste verwerfen, da sie aufgrund von Klassen- und Pufferinitialisierungszeiten möglicherweise beschädigt ist.