Java multithreaded application System.out.println generate latency

Question

I'm writing a multi-threaded application in Java, using log4j for logging. During my benchmark, I found out that each time I output a log, that generate a latency of 1 or 2 ms. After investigating, I found out that the problem is only in the console output, and occurred even if I get rid of log4j and directly print using System.out.print. In that thread, I used the following test :

        System.out.println("===============================================================");
        long ts = java.lang.System.currentTimeMillis();
        String toPrint = "### TEST 1 " + (java.lang.System.currentTimeMillis() - ts) + " ms \n";
        toPrint = toPrint + "### TEST 2 " + (java.lang.System.currentTimeMillis() - ts) + " ms \n";
        toPrint = toPrint + "### TEST 3 " + (java.lang.System.currentTimeMillis() - ts) + " ms \n";
        toPrint = toPrint + "### TEST 4 " + (java.lang.System.currentTimeMillis() - ts) + " ms \n";
        System.out.print(toPrint);
        System.out.println("===============================================================");

        System.out.println("### TEST 1 " + (java.lang.System.currentTimeMillis() - ts) + " ms");
        System.out.println("### TEST 2 " + (java.lang.System.currentTimeMillis() - ts) + " ms");
        System.out.println("### TEST 3 " + (java.lang.System.currentTimeMillis() - ts) + " ms");
        System.out.println("### TEST 4 " + (java.lang.System.currentTimeMillis() - ts) + " ms");
        System.out.println("===============================================================");

and the output is :

===============================================================
### TEST 1 0 ms
### TEST 2 0 ms
### TEST 3 0 ms
### TEST 4 0 ms
===============================================================
### TEST 1 7 ms
### TEST 2 9 ms
### TEST 3 10 ms
### TEST 4 11 ms
===============================================================

What would be the correct way for a multithreaded application to directly output to the console without creating latency?

Can we setup log4j to do that directly?

Thanks in advance for your kind help...

In this latency is a problem - every bit of work takes some time - then maybe create a new thread that just does your printing. — Scary Wombat, Nov 18 '16 at 01:54
Writing to console takes a small amount of time. That's just the way it is. If you log so much to console that it matters, reduce your log levels, or turn off console logging entirely. You can always `tail` the log file you're likely generating too. — Andreas, Nov 18 '16 at 01:55
@Andreas Thanks a lot for your answer. However none of my cpu are saturated and 2 ms to output one line on a modern server does not sounds reasonable. Turn off the console indeed fix the pb. — deubNippon, Nov 18 '16 at 02:02
@ScaryWombat Thanks for you answer, that's why I'm using log4j 2 to output to a file and the console. However I do have latency when adding the console appender — deubNippon, Nov 18 '16 at 02:04
FYI: I had to change code to nanos to see results. Running in Eclipse I get final number of `~120,000 ns`, but running on Windows Command Prompt I get `~700,000 ns` on a clear prompt (right after a `cls` command), but `~2,000,000 ns` when it has to scroll. Writing to console is *synchronous*, and must wait for scrolling and printing to complete, so don't log to console, or only log very minimal output there. — Andreas, Nov 18 '16 at 02:05
Conclusion: Do what I said earlier. Don't log to console. If you want to see logs in a console, `tail` the log file. Logging directly to console should only be done in development, never in production. — Andreas, Nov 18 '16 at 02:09

score 1 · Accepted Answer · edited May 23 '17 at 12:07

I had to change code to nanos to see results. Running in Eclipse I get final number of ~120,000 ns. Running in Windows Command Prompt I get ~700,000 ns on a clear prompt (right after a cls command), but ~2,000,000 ns when it has to scroll.

Writing to console is synchronous, and must wait for scrolling and printing to complete, so don't log to console, or only log very minimal output there.

You said in comment that you are logging to file and the console. That is fine in development, but don't log to console in production. Why would you? Production code should be running unattended anyway, and no one is watching the console out, so why waste time logging there?

If you temporarily need to watch production logs live, use tail on the log file. For Windows, see "Looking for a windows equivalent of the unix tail command".

If you insist on logging to console, try using AsyncAppender.

Thx a lot, I didn't realized console io is so expensive. You do indeed reply to my first question. However, log4j 2 is supposed to tackle these issues, any idea how can I make sure the console io can be done in a separate thread with low priority with log4j ? (for now I'm doing as you adviced and turn off console output in prod) — deubNippon, Nov 18 '16 at 02:17

Java multithreaded application System.out.println generate latency

1 Answers1