Is it possible to speed up log4j or slf4j outputs (and maybe also switch them off globally)?

Question

I was earlier using System.out.println to see my java console application's output in Netbeans.

The program took about 10 minutes to run and show the outputs while it was running.

Now I've substituted all System.out.println's with slf4j's logger

private final Logger logger = LoggerFactory.getLogger(MyClass.class);    
logger.info("number of rows of x: " + numberOfx);

Now the program takes 28 minutes to run and show outputs (no other changes done).

I haven't done any extra configuration in the pom file or anywhere else. I just added the local jars of slf4j-api:1.7.1 and slf4j-simple:1.7.18 into the Netbeans project and added the imports

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

Since I've done only this much, and because the outputs are showing up on the Netbeans console in red colour, I assume the outputs aren't being written to disk.

If so, two questions:
1. Is log4j or slf4j output known to be slower than System.out.println?
2. Is there any way to speed up the outputs? (perhaps it's slow because of some internal checks which could be disabled?)
3. I need my program to run fast. Is there a way to globally switch off the logging, instead of going to every file and commenting out the logger.info() statements?

Wow, if logging is adding 18 minutes of extra time, you must be generating like a gazillion log messages. — Andreas, Mar 03 '16 at 06:21
@Andreas: Yes, there are two functions; one that gets called 25000 times and another that gets called 64 million times. These functions have one output statement each. Commenting out all outputs, the program executes in just 45 seconds (as compared to the 10 min and 28 min with output enabled). But this goes on to show how expensive outputting is. Somehow I feel the outputting/log functions could have been made less computationally expensive if designed well. I will of course be removing some of my output statements... — Nav, Mar 04 '16 at 04:25
So your original code was writing 64 million lines of output to the console? They scroll off faster than you can read them and disappear, so what is the point of that? Reduce your logging. Even if you were redirecting output to a file, that is way too many log records. — Andreas, Mar 04 '16 at 06:19

score 3 · Accepted Answer · edited May 23 '17 at 10:33

Point wise: 1. Refer Do not use System.out.println in server side code It's clearly mentioned that I/O operations are slower .

2 and 3. You should use below mentioned logback.xml to configure your logging so that you have advantage of enabling/disabling logging based on the priority/requirement. In this example DEBUG is disabled, similarly you can disable INFO also, which will work in your case.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <charset>UTF-8</charset>
        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-6level%logger{0} [%X{api_id}-%X{org}-%X{user}-%X{client_req_id}]- %msg%n</pattern>
    </encoder>
</appender>

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">      
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
         <charset>UTF-8</charset>
        <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-6level%logger{0} [%X{api_id}-%X{org}-%X{user}-%X{client_req_id}]- %msg%n</Pattern>
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <FileNamePattern>${user.home}/logs/%d{yyyy_MM_dd}_server.log</FileNamePattern>
    </rollingPolicy>
</appender>

<logger name="org." level="DEBUG" additivity="false">
    <appender-ref ref="CONSOLE" />
    <appender-ref ref="FILE" />
</logger>

<root level="ERROR">
    <appender-ref ref="CONSOLE" />
    <appender-ref ref="FILE" />
</root>

Thanks Bhavesh, but it was not the `System.out` which was slowing the program. It's the slf4j logging which did it. Which is why I asked. I thought `logback` had to be specified separately for it to work with slf4j. Does it work directly? How does slf4j know the location of `logback.xml`? — Nav, Mar 03 '16 at 08:10
Add this parameter while running your jar file ===> `java -jar -Dlogging.config=file://$HOME/$PATH_TO_CONFIG/{application_name}-logback.xml xyz.jar` — Bhavesh, Mar 03 '16 at 09:08

score 2 · Answer 2 · answered Mar 03 '16 at 06:32

If you wan't to avoid cost of log message construction (String instantiation) use conditional logging on log-level and utilize level (i.e. info, warn etc) appropriately. Say you raise logging level to warn or error in you logging-configuration file, correct use of logger would be:

if(logger.isInfoEnabled()){ logger.info("some message {}",var); }

This should speedup overall code execution, and is a preferred approach for performance optimized codes.

Second, use AsyncAppender unless you have very specific synchronous logging requirement. This would further improve performance. See https://logging.apache.org/log4j/2.x/manual/async.html

Is it possible to speed up log4j or slf4j outputs (and maybe also switch them off globally)?

2 Answers2