user3382356 user3382356 - 22 days ago 6
Java Question

Java multithreaded application System.out.println generate latency

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...

Answer

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.