logback console appender slow on windows xp
Hi, we had a problem with the performance of our application and it boiled down to very bad performance of the console appender when there is no console (in particular on windows xp). You can see the whole context of the issue here: http://www.eclipse.org/forums/index.php/m/768740/#msg_768740 Here's the conclusion and the code for my experiments: package testlogback; import java.io.FileWriter; import java.io.IOException; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class Main { public static void main(String[] args) throws IOException { Logger logger = LoggerFactory .getLogger("chapters.introduction.HelloWorld1"); long start = System.currentTimeMillis(); for (int i = 0; i < 10000; i++) { logger.debug("Hello world."); } long end = System.currentTimeMillis(); FileWriter fileWriter = new FileWriter("logbacktest.out"); fileWriter.write("Time: " + (end - start) + "\n"); fileWriter.close(); System.out.println("Time: " + (end - start)); } } On my windows box it prints out "Time: 140" when started as "java -jar testlogback.jar". If I start "javaw -jar testlogback.jar" it uses 100% CPU for about 20 seconds (for effectively doing nothing). This is the case for Sun ire 6 and 7 on windows xp. On windows 7 the situation is better: javaw uses only about 7 seconds (which is still too much, I guess). Best regards, Peter
Hi Peter, If I understand correctly, you have shown that invoking System.out.println is slow with javaw. Do you know why? If the reason was known, for example it was due to exceptions being thrown, ConsoleAppender could address that problem. Is it possible to check whether an app is running under javaw and not java? ConsoleAppender could disable itself under javaw. -- Ceki http://twitter.com/#!/ceki On 20.12.2011 18:34, Peter Kullmann wrote:
Hi,
we had a problem with the performance of our application and it boiled down to very bad performance of the console appender when there is no console (in particular on windows xp).
You can see the whole context of the issue here: http://www.eclipse.org/forums/index.php/m/768740/#msg_768740
Here's the conclusion and the code for my experiments:
package testlogback;
import java.io.FileWriter; import java.io.IOException;
import org.slf4j.Logger; import org.slf4j.LoggerFactory;
public class Main { public static void main(String[] args) throws IOException { Logger logger = LoggerFactory .getLogger("chapters.introduction.HelloWorld1"); long start = System.currentTimeMillis(); for (int i = 0; i< 10000; i++) { logger.debug("Hello world."); } long end = System.currentTimeMillis();
FileWriter fileWriter = new FileWriter("logbacktest.out"); fileWriter.write("Time: " + (end - start) + "\n"); fileWriter.close(); System.out.println("Time: " + (end - start)); } }
On my windows box it prints out "Time: 140" when started as "java -jar testlogback.jar". If I start "javaw -jar testlogback.jar" it uses 100% CPU for about 20 seconds (for effectively doing nothing). This is the case for Sun ire 6 and 7 on windows xp.
On windows 7 the situation is better: javaw uses only about 7 seconds (which is still too much, I guess).
Best regards, Peter
On 20.12.2011 18:50, ceki wrote:
Hi Peter,
If I understand correctly, you have shown that invoking System.out.println is slow with javaw. Do you know why? If the reason was known, for example it was due to exceptions being thrown, ConsoleAppender could address that problem.
Writing to System.out does not throw an exception under javaw.
Is it possible to check whether an app is running under javaw and not java? ConsoleAppender could disable itself under javaw.
I don't think it is possible to distinguish between java and javaw by System properties. In JDK 1.6, it is possible to distinguish between java and javaw by invoking System.console: http://goo.gl/Nljdl -- Ceki http://twitter.com/#!/ceki
Hi Ceki I have tried using System.out.println() instead of logger.debug(). It is fast (less than a second). Best regards, Peter Am 20.12.2011 um 18:50 schrieb ceki:
Hi Peter,
If I understand correctly, you have shown that invoking System.out.println is slow with javaw. Do you know why? If the reason was known, for example it was due to exceptions being thrown, ConsoleAppender could address that problem.
Is it possible to check whether an app is running under javaw and not java? ConsoleAppender could disable itself under javaw.
-- Ceki http://twitter.com/#!/ceki
On 20.12.2011 18:34, Peter Kullmann wrote:
Hi,
we had a problem with the performance of our application and it boiled down to very bad performance of the console appender when there is no console (in particular on windows xp).
You can see the whole context of the issue here: http://www.eclipse.org/forums/index.php/m/768740/#msg_768740
Here's the conclusion and the code for my experiments:
package testlogback;
import java.io.FileWriter; import java.io.IOException;
import org.slf4j.Logger; import org.slf4j.LoggerFactory;
public class Main { public static void main(String[] args) throws IOException { Logger logger = LoggerFactory .getLogger("chapters.introduction.HelloWorld1"); long start = System.currentTimeMillis(); for (int i = 0; i< 10000; i++) { logger.debug("Hello world."); } long end = System.currentTimeMillis();
FileWriter fileWriter = new FileWriter("logbacktest.out"); fileWriter.write("Time: " + (end - start) + "\n"); fileWriter.close(); System.out.println("Time: " + (end - start)); } }
On my windows box it prints out "Time: 140" when started as "java -jar testlogback.jar". If I start "javaw -jar testlogback.jar" it uses 100% CPU for about 20 seconds (for effectively doing nothing). This is the case for Sun ire 6 and 7 on windows xp.
On windows 7 the situation is better: javaw uses only about 7 seconds (which is still too much, I guess).
Best regards, Peter
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
Hi Peter, FYI, running the little application you provided under JDK 1.6.0_23-b05 and Windows 7, I get 4.8 seconds with java and 1.1 seconds under javaw. I am unable to reproduce the performance problem. -- Ceki http://twitter.com/#!/ceki On 21.12.2011 09:19, Peter Kullmann wrote:
Hi Ceki
I have tried using System.out.println() instead of logger.debug(). It is fast (less than a second).
Best regards, Peter
Am 20.12.2011 um 18:50 schrieb ceki:
Hi Peter,
If I understand correctly, you have shown that invoking System.out.println is slow with javaw. Do you know why? If the reason was known, for example it was due to exceptions being thrown, ConsoleAppender could address that problem.
Is it possible to check whether an app is running under javaw and not java? ConsoleAppender could disable itself under javaw.
-- Ceki http://twitter.com/#!/ceki
On 20.12.2011 18:34, Peter Kullmann wrote:
Hi,
we had a problem with the performance of our application and it boiled down to very bad performance of the console appender when there is no console (in particular on windows xp).
You can see the whole context of the issue here: http://www.eclipse.org/forums/index.php/m/768740/#msg_768740
Here's the conclusion and the code for my experiments:
package testlogback;
import java.io.FileWriter; import java.io.IOException;
import org.slf4j.Logger; import org.slf4j.LoggerFactory;
public class Main { public static void main(String[] args) throws IOException { Logger logger = LoggerFactory .getLogger("chapters.introduction.HelloWorld1"); long start = System.currentTimeMillis(); for (int i = 0; i< 10000; i++) { logger.debug("Hello world."); } long end = System.currentTimeMillis();
FileWriter fileWriter = new FileWriter("logbacktest.out"); fileWriter.write("Time: " + (end - start) + "\n"); fileWriter.close(); System.out.println("Time: " + (end - start)); } }
On my windows box it prints out "Time: 140" when started as "java -jar testlogback.jar". If I start "javaw -jar testlogback.jar" it uses 100% CPU for about 20 seconds (for effectively doing nothing). This is the case for Sun ire 6 and 7 on windows xp.
On windows 7 the situation is better: javaw uses only about 7 seconds (which is still too much, I guess).
Best regards, Peter
Hi Ceki, The problem manifests itself under windows xp. Windows 7 is much better. Peter Am 21.12.2011 um 09:47 schrieb ceki:
Hi Peter,
FYI, running the little application you provided under JDK 1.6.0_23-b05 and Windows 7, I get 4.8 seconds with java and 1.1 seconds under javaw.
I am unable to reproduce the performance problem.
-- Ceki http://twitter.com/#!/ceki
On 21.12.2011 09:19, Peter Kullmann wrote:
Hi Ceki
I have tried using System.out.println() instead of logger.debug(). It is fast (less than a second).
Best regards, Peter
Am 20.12.2011 um 18:50 schrieb ceki:
Hi Peter,
If I understand correctly, you have shown that invoking System.out.println is slow with javaw. Do you know why? If the reason was known, for example it was due to exceptions being thrown, ConsoleAppender could address that problem.
Is it possible to check whether an app is running under javaw and not java? ConsoleAppender could disable itself under javaw.
-- Ceki http://twitter.com/#!/ceki
On 20.12.2011 18:34, Peter Kullmann wrote:
Hi,
we had a problem with the performance of our application and it boiled down to very bad performance of the console appender when there is no console (in particular on windows xp).
You can see the whole context of the issue here: http://www.eclipse.org/forums/index.php/m/768740/#msg_768740
Here's the conclusion and the code for my experiments:
package testlogback;
import java.io.FileWriter; import java.io.IOException;
import org.slf4j.Logger; import org.slf4j.LoggerFactory;
public class Main { public static void main(String[] args) throws IOException { Logger logger = LoggerFactory .getLogger("chapters.introduction.HelloWorld1"); long start = System.currentTimeMillis(); for (int i = 0; i< 10000; i++) { logger.debug("Hello world."); } long end = System.currentTimeMillis();
FileWriter fileWriter = new FileWriter("logbacktest.out"); fileWriter.write("Time: " + (end - start) + "\n"); fileWriter.close(); System.out.println("Time: " + (end - start)); } }
On my windows box it prints out "Time: 140" when started as "java -jar testlogback.jar". If I start "javaw -jar testlogback.jar" it uses 100% CPU for about 20 seconds (for effectively doing nothing). This is the case for Sun ire 6 and 7 on windows xp.
On windows 7 the situation is better: javaw uses only about 7 seconds (which is still too much, I guess).
Best regards, Peter
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
On 21.12.2011 10:55, Peter Kullmann wrote:
Hi Ceki,
The problem manifests itself under windows xp. Windows 7 is much better.
I don't see anything actionable to work with here. Ideas?
Peter
-- Ceki http://twitter.com/#!/ceki
I don't know what to do except perhaps warn against the usage of the console appender when running without a console on windows xp. I'm attaching the output of the visualvm profiler so that you can see where all the time is being spent. By the way, I think log4j doesn't have this problem. We were using log4j for years in much the same setups. Peter Am 21.12.2011 um 11:03 schrieb ceki:
On 21.12.2011 10:55, Peter Kullmann wrote:
Hi Ceki,
The problem manifests itself under windows xp. Windows 7 is much better.
I don't see anything actionable to work with here. Ideas?
Peter
-- Ceki http://twitter.com/#!/ceki _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
Thank you for the output of visualvm profiler. It looks like 90.4% of the time is spent in java.io.PrintStream.write(int) called by ch.qos.logback.core.joran.spi.ConsoleTarget. There is also some time spent in java.io.IOException.<init>(String), i.e the constructor of IOException. In principle, the performance of log4j ConsoleAppender should be very similar, although its execution path might be slightly shorter. Which version of log4j are you using? -- Ceki http://twitter.com/#!/ceki On 21.12.2011 16:04, Peter Kullmann wrote:
I don't know what to do except perhaps warn against the usage of the console appender when running without a console on windows xp.
I'm attaching the output of the visualvm profiler so that you can see where all the time is being spent.
By the way, I think log4j doesn't have this problem. We were using log4j for years in much the same setups.
Peter
Am 21.12.2011 um 11:03 schrieb ceki:
On 21.12.2011 10:55, Peter Kullmann wrote:
Hi Ceki,
The problem manifests itself under windows xp. Windows 7 is much better.
I don't see anything actionable to work with here. Ideas?
Peter
I tested the same snippet with log4j and it runs fast with javaw on windows xp (700ms). The versions were log4j 1.2.15; org.slf4j.api 1.15.11 and org.slf4j.log4j12 1.4.2 The slow configuration was: org.slf4j.api 1.15.11 and org.slf4j.log4j12 1.4.2 ch.qos.logback.classic, ch.qos.logback.core, ch.qos.logback.slf4j all in version 0.9.19. Peter Am 21.12.2011 um 17:53 schrieb ceki:
Thank you for the output of visualvm profiler. It looks like 90.4% of the time is spent in java.io.PrintStream.write(int) called by ch.qos.logback.core.joran.spi.ConsoleTarget. There is also some time spent in java.io.IOException.<init>(String), i.e the constructor of IOException.
In principle, the performance of log4j ConsoleAppender should be very similar, although its execution path might be slightly shorter.
Which version of log4j are you using?
-- Ceki http://twitter.com/#!/ceki
On 21.12.2011 16:04, Peter Kullmann wrote:
I don't know what to do except perhaps warn against the usage of the console appender when running without a console on windows xp.
I'm attaching the output of the visualvm profiler so that you can see where all the time is being spent.
By the way, I think log4j doesn't have this problem. We were using log4j for years in much the same setups.
Peter
Am 21.12.2011 um 11:03 schrieb ceki:
On 21.12.2011 10:55, Peter Kullmann wrote:
Hi Ceki,
The problem manifests itself under windows xp. Windows 7 is much better.
I don't see anything actionable to work with here. Ideas?
Peter
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
participants (2)
-
ceki -
Peter Kullmann