
Hi all, I'm running some benchmarking and I've noticed that when calling logger.xxx in a loop (10,000 iterations) only about 3964 are written. I'm testing this with both MySQL and HSQLDB databases. Can someone please let me know what's seems to be a problem? Do I need to configure this in some config file? How many times I can write at once to a database? Thanks

Interesting. Could you please share your config file and code? Greg Flex wrote:
Hi all, I'm running some benchmarking and I've noticed that when calling logger.xxx in a loop (10,000 iterations) only about 3964 are written. I'm testing this with both MySQL and HSQLDB databases. Can someone please let me know what's seems to be a problem? Do I need to configure this in some config file? How many times I can write at once to a database? Thanks
-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

Absolutely... Here is the config file. <configuration> <consolePlugin /> <appender name="DB" class="ch.qos.logback.classic.db.DBAppender"> <connectionSource class="ch.qos.logback.core.db.DriverManagerConnectionSource"> <driverClass>com.mysql.jdbc.Driver</driverClass> <url>jdbc:mysql://localhost:3306/Greg</url> <user>greg</user> <password>greg</password> </connectionSource> </appender> <appender name="HSQLDB" class="ch.qos.logback.classic.db.DBAppender"> <connectionSource class="ch.qos.logback.core.db.DriverManagerConnectionSource"> <driverClass>org.hsqldb.jdbcDriver</driverClass> <url>jdbc:hsqldb:hsql://localhost/</url> <user>sa</user> <password></password> </connectionSource> </appender> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%date{HH:mm:ss.SSS} [%thread] %-5level %logger{36} [%file : %line] - %msg%n</Pattern> </layout> </appender> <appender name="FILE" class="ch.qos.logback.core.FileAppender"> <layout class="ch.qos.logback.classic.html.HTMLLayout"> <pattern>%date %relative%thread%mdc%level%logger%msg</pattern> </layout> <File>C:/tools/test.html</File> </appender> <!-- <appender name="FLAT" class="ch.qos.logback.core.FileAppender"> <File>H:/tools/testFile.log</File> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%date %relative%thread%mdc%level%logger%msg%n</Pattern> </layout> </appender> --> <!-- <appender name="FILE" class="ch.qos.logback.core.FileAppender"> <File>testFile.log</File> <Append>true</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%date [%thread] %-5level %logger{35} - %msg%n</Pattern> </layout> </appender> --> <root> <level value="debug" /> <appender-ref ref="DB" /> </root> </configuration> Right now as you can see is set to write to a DB which is a MySQl database. Here is the Java code I'm using to test this. public class DBConnector { Logger logger = null; public static void main(String[] args) { DBConnector dbc = new DBConnector(); dbc.doSomething(); } public void doSomething(){ logger = LoggerFactory.getLogger(DBConnector.class); readConfig(); PerformanceBenchmark(); } public void PerformanceBenchmark() { // Get current time long start = System.currentTimeMillis(); for (int i = 0; i < 10000; ++i) { logger.debug("INFO Entering application."); logger.info("INFO Entering application."); } Foo f = new Foo(); f.doIt(); logger.info("Exiting Application"); // Get elapsed time in milliseconds try { throw new Exception("Testing exception"); } catch(Exception e) { long elapsedTimeMillis = System.currentTimeMillis()-start; logger.info("Time in ms is: " + elapsedTimeMillis, e); } //System.out.println(elapsedTimeMillis); } private void readConfig() { LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); try { JoranConfigurator configurator = new JoranConfigurator(); lc.shutdownAndReset(); configurator.setContext(lc); configurator.doConfigure("src/DBConnectorXML.xml"); } catch (JoranException je) { StatusPrinter.print(lc); } } } public class Foo { static final Logger logger = LoggerFactory.getLogger(Foo.class); public void doIt() { logger.debug("Got in here!"); } } As you can see I'm just playing aroung with it..... The code is complete... meaning you can compile it and run it. See if you can reproduce the problem..... Thanks On Mon, Sep 22, 2008 at 2:11 PM, Ceki Gulcu <listid@qos.ch> wrote:
Interesting. Could you please share your config file and code?
Greg Flex wrote:
Hi all, I'm running some benchmarking and I've noticed that when calling logger.xxx in a loop (10,000 iterations) only about 3964 are written. I'm testing this with both MySQL and HSQLDB databases. Can someone please let me know what's seems to be a problem? Do I need to configure this in some config file? How many times I can write at once to a database? Thanks
-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user

I've also noticed that when running the code with the config file I sent you, and writting to MySQL database, the system seems to loose connection after writting about 3900 logs. I can't connect to a database anymore with myPHPAdmin. (for about 10 to 15 seconds, after that all is restored) The program doesn't execute anymore but something is locking the DB connection... Here is another observation..... When running second, immediately after the first run and writting to an HSQLDB nothing get written. I still have to wait for about 10 to 15 seconds (for the first run to finish or something) then run it again..... Hope thisi nfo will help ... On Mon, Sep 22, 2008 at 2:11 PM, Ceki Gulcu <listid@qos.ch> wrote:
Interesting. Could you please share your config file and code?
Greg Flex wrote:
Hi all, I'm running some benchmarking and I've noticed that when calling logger.xxx in a loop (10,000 iterations) only about 3964 are written. I'm testing this with both MySQL and HSQLDB databases. Can someone please let me know what's seems to be a problem? Do I need to configure this in some config file? How many times I can write at once to a database? Thanks
-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user

Greg Flex skrev:
I've also noticed that when running the code with the config file I sent you, and writting to MySQL database, the system seems to loose connection after writting about 3900 logs. I can't connect to a database anymore with myPHPAdmin. (for about 10 to 15 seconds, after that all is restored) The program doesn't execute anymore but something is locking the DB connection... Here is another observation..... When running second, immediately after the first run and writting to an HSQLDB nothing get written. I still have to wait for about 10 to 15 seconds (for the first run to finish or something) then run it again..... Hope thisi nfo will help ... What is the configuration of the MySQL box? It sounds to me as MySQL allocates more memory than is available and that it is basically swapping to death.
Do you close your HSQLDB connection properly? -- Thorbjørn

I didn't "touch" the configuration of MySQL at all. I assume it's the normal/standard configuration that comes with it..... I ran the program again for some time last night. I wrote one log.xxx then paused the thread for about 100ms then wrote another log.xxx I managed to write 39,000 logs to MySQL without any problems. It looks to me then that the "speed" has something to do here. If writting too fast (too many records at once) to the database (both MySQL and HSQLDB) they simply "choke".... I don't know however if this is the problem; just my observations..... Do you think this might cause it? Greg. On Tue, Sep 23, 2008 at 12:00 AM, Thorbjørn Ravn Andersen <ravn@runjva.com>wrote:
Greg Flex skrev:
I've also noticed that when running the code with the config file I sent you, and writting to MySQL database, the system seems to loose connection after writting about 3900 logs. I can't connect to a database anymore with myPHPAdmin. (for about 10 to 15 seconds, after that all is restored) The program doesn't execute anymore but something is locking the DB connection... Here is another observation..... When running second, immediately after the first run and writting to an HSQLDB nothing get written. I still have to wait for about 10 to 15 seconds (for the first run to finish or something) then run it again..... Hope thisi nfo will help ... What is the configuration of the MySQL box? It sounds to me as MySQL allocates more memory than is available and that it is basically swapping to death.
Do you close your HSQLDB connection properly?
-- Thorbjørn _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user

Greg Flex skrev:
I didn't "touch" the configuration of MySQL at all. I assume it's the normal/standard configuration that comes with it..... I ran the program again for some time last night. I wrote one log.xxx then paused the thread for about 100ms then wrote another log.xxx I managed to write 39,000 logs to MySQL without any problems. It looks to me then that the "speed" has something to do here. If writting too fast (too many records at once) to the database (both MySQL and HSQLDB) they simply "choke".... I don't know however if this is the problem; just my observations..... Do you think this might cause it? Greg. I am not thinking of the configuration of the database software as such but of the configuration of the computer which runs the database software.
I suspect that you have less physical memory available to the database than they think they can use, hence the operating system starts swapping which kills performance. Can you please describe your setup in detail so we can replicate the scenario? I.e. number of computers involved, connections between them, network performance, memory assigned, operating systems used, etc. /Thorbjørn

Ok no problem. I'm running the program and the database on just one computer. It's all local and no one is connecting to it.... It's a Xeon 2.66 GHz machine with 4 cores and 3GB of ram. I'm running Windows XP. (the newest service pack) I'm looking at the Task Manager right now and I see that over 2GB of memory is available. I just ran my program again but this time I've reduced the Thread.sleep to just 10ms. Instead of 40,000 records just about 8,000 got written. This means 10-ms is too fast and MySQL can't handle it or something. I'm not sure but from the documentation on line looks like the connection pooling is the way out... I don't know and I guess I don't understand that well the notion of "connection pooling" so I don't know how to set it up/create one. Any suggestions? Thanks a lot Greg. On Tue, Sep 23, 2008 at 9:06 AM, Thorbjørn Ravn Andersen <ravn@runjva.com>wrote:
Greg Flex skrev:
I didn't "touch" the configuration of MySQL at all. I assume it's the normal/standard configuration that comes with it..... I ran the program again for some time last night. I wrote one log.xxx then paused the thread for about 100ms then wrote another log.xxx I managed to write 39,000 logs to MySQL without any problems. It looks to me then that the "speed" has something to do here. If writting too fast (too many records at once) to the database (both MySQL and HSQLDB) they simply "choke".... I don't know however if this is the problem; just my observations..... Do you think this might cause it? Greg. I am not thinking of the configuration of the database software as such but of the configuration of the computer which runs the database software.
I suspect that you have less physical memory available to the database than they think they can use, hence the operating system starts swapping which kills performance.
Can you please describe your setup in detail so we can replicate the scenario? I.e. number of computers involved, connections between them, network performance, memory assigned, operating systems used, etc.
/Thorbjørn _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user

ok guys, I figured this out. It works beatifully now! All I had to do is download (per instructions on the logback website) the c3po pooling library and modify the appender's xml file to: <appender name="DB" class="ch.qos.logback.classic.db.DBAppender"> <connectionSource class="ch.qos.logback.core.db.DataSourceConnectionSource"> <dataSource class="com.mchange.v2.c3p0.ComboPooledDataSource"> <driverClass>com.mysql.jdbc.Driver</driverClass> <jdbcUrl>jdbc:mysql://localhost:3306/Greg</jdbcUrl> <user>greg</user> <password>greg</password> </dataSource> </connectionSource> </appender> In my case the database name is: Greg, password and username: greg It works great and it is in fact very fast now. I just loaded it with 50,000 records without any problems whatsoever. I guess is safe to say "read the documentation first man...!" :-) Cheers, Greg On Tue, Sep 23, 2008 at 9:38 AM, Greg Flex <greg.flex@gmail.com> wrote:
Ok no problem. I'm running the program and the database on just one computer. It's all local and no one is connecting to it.... It's a Xeon 2.66 GHz machine with 4 cores and 3GB of ram. I'm running Windows XP. (the newest service pack) I'm looking at the Task Manager right now and I see that over 2GB of memory is available. I just ran my program again but this time I've reduced the Thread.sleep to just 10ms. Instead of 40,000 records just about 8,000 got written. This means 10-ms is too fast and MySQL can't handle it or something. I'm not sure but from the documentation on line looks like the connection pooling is the way out... I don't know and I guess I don't understand that well the notion of "connection pooling" so I don't know how to set it up/create one. Any suggestions? Thanks a lot Greg.
On Tue, Sep 23, 2008 at 9:06 AM, Thorbjørn Ravn Andersen <ravn@runjva.com>wrote:
Greg Flex skrev:
I didn't "touch" the configuration of MySQL at all. I assume it's the normal/standard configuration that comes with it..... I ran the program again for some time last night. I wrote one log.xxx then paused the thread for about 100ms then wrote another log.xxx I managed to write 39,000 logs to MySQL without any problems. It looks to me then that the "speed" has something to do here. If writting too fast (too many records at once) to the database (both MySQL and HSQLDB) they simply "choke".... I don't know however if this is the problem; just my observations..... Do you think this might cause it? Greg. I am not thinking of the configuration of the database software as such but of the configuration of the computer which runs the database software.
I suspect that you have less physical memory available to the database than they think they can use, hence the operating system starts swapping which kills performance.
Can you please describe your setup in detail so we can replicate the scenario? I.e. number of computers involved, connections between them, network performance, memory assigned, operating systems used, etc.
/Thorbjørn _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user

Hi Greg, Thanks for letting us know. However, I am troubled by the fact that DriverManagerConnectionSource fails after a few thousand events. While it is known that getting connections from a driver manager is slow, it should not fail. May I ask you to create a jira issue describing the problem as observed initially. You can just refer to this discussion. Please let me know if that is too much trouble. Greg Flex wrote:
ok guys, I figured this out. It works beatifully now! All I had to do is download (per instructions on the logback website) the c3po pooling library and modify the appender's xml file to:
<appender name="DB" class="ch.qos.logback.classic.db.DBAppender"> <connectionSource class="ch.qos.logback.core.db.DataSourceConnectionSource"> <dataSource class="com.mchange.v2.c3p0.ComboPooledDataSource"> <driverClass>com.mysql.jdbc.Driver</driverClass> <jdbcUrl>jdbc:mysql://localhost:3306/Greg</jdbcUrl> <user>greg</user> <password>greg</password> </dataSource> </connectionSource> </appender>
In my case the database name is: Greg, password and username: greg It works great and it is in fact very fast now. I just loaded it with 50,000 records without any problems whatsoever. I guess is safe to say "read the documentation first man...!" :-) Cheers, Greg
On Tue, Sep 23, 2008 at 9:38 AM, Greg Flex <greg.flex@gmail.com <mailto:greg.flex@gmail.com>> wrote:
Ok no problem. I'm running the program and the database on just one computer. It's all local and no one is connecting to it.... It's a Xeon 2.66 GHz machine with 4 cores and 3GB of ram. I'm running Windows XP. (the newest service pack) I'm looking at the Task Manager right now and I see that over 2GB of memory is available. I just ran my program again but this time I've reduced the Thread.sleep to just 10ms. Instead of 40,000 records just about 8,000 got written. This means 10-ms is too fast and MySQL can't handle it or something. I'm not sure but from the documentation on line looks like the connection pooling is the way out... I don't know and I guess I don't understand that well the notion of "connection pooling" so I don't know how to set it up/create one. Any suggestions? Thanks a lot Greg.
On Tue, Sep 23, 2008 at 9:06 AM, Thorbjørn Ravn Andersen <ravn@runjva.com <mailto:ravn@runjva.com>> wrote:
Greg Flex skrev: > I didn't "touch" the configuration of MySQL at all. I assume it's the > normal/standard configuration that comes with it..... > I ran the program again for some time last night. I wrote one log.xxx > then paused the thread for about 100ms then wrote another log.xxx > I managed to write 39,000 logs to MySQL without any problems. It looks > to me then that the "speed" has something to do here. > If writting too fast (too many records at once) to the database (both > MySQL and HSQLDB) they simply "choke".... > I don't know however if this is the problem; just my observations..... > Do you think this might cause it? > Greg. I am not thinking of the configuration of the database software as such but of the configuration of the computer which runs the database software.
I suspect that you have less physical memory available to the database than they think they can use, hence the operating system starts swapping which kills performance.
Can you please describe your setup in detail so we can replicate the scenario? I.e. number of computers involved, connections between them, network performance, memory assigned, operating systems used, etc.
/Thorbjørn _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
------------------------------------------------------------------------
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

I made my decision to use LOGBack as logging framework in my OSGI Enterprise application. If you like to follow, I just started part 1 of a blog series about this and I'll also publish soon an OSGI Server example combining: * Equinox as OSGI Framework * EasyBeans OSGI as EJB3 Container w/ Hibernate JPA * Eclipse Riena (Remote OSGI Services, UI Enhancements and more) * SLF4J (LOGBack) as Logging Framework together with OSGI LogServices http://ekkes-corner.org (or german: http://ekkes-ecke.org) ekke
participants (4)
-
Ceki Gulcu
-
ekkehard
-
Greg Flex
-
Thorbjørn Ravn Andersen