Log4jdbc performance

[Marcin D.]

Hello,

I have recently refactored a few classes in our web service - changed
a series of brutally
concatenated SQL statements into loops utilizing the
java.sql.PreparedStatement. I
have gained a huge performance boost, but lost logging; this is how I
found your library.

I like the ease of configuration and the verbosity of output it
generates;
however its performance could use serious improvements (and I mean:
performance when absolutely no logging statement hits the log file).

The library seems to be fast only if all loggers are switched OFF
(log4j.logger.jdbc = OFF). I've run a test data batch of about 26000
records and it
takes approx. 40 seconds to insert them - both with log4jdbc with
loggers
set to OFF, and completely without it (no "jdbc:log4jdbc" in the
connection string).

When I set the log4j.logger.jdbc to ERROR, the same batch of records
takes
about 63 seconds to insert, even though there are no ERROR logs in the
log
file! This means a lot of operations are made in the library prior to
the log
level check.

One example of needless computation can be found in the method
Slf4jSpyLogDelegator.methodReturned(...). The header string is
constructed
every time, while it should be done inside "isXXXEnabled" blocks. When
I
had pushed the header construction code down to these blocks, I got 55
seconds - quite a nice improvement for its size.

I didn't have much time for minute code analysis, but I guess a more
advanced improvement would be allowing Spy implementors to know the
log level
in which they are working, so that they could check it before they
rush on to
abundant String creation.

All in all, many thanks.

--
Marcin D

[Arthur Blake]

I've mostly used log4jdbc in debug/test environments, only turning it
on in production environments for brief periods of time in order to
debug specific problems.

That is why the driver doesn't even wrap the connection at all if all
the logs are turned off (which is why the performance numbers came out
the same when you switched all the loggers off
--see DriverSpy:639 on current trunk)

This allows log4jdbc to be implanted in a production environment with
negligible performance impact and then switched on and off as needed.

Nevertheless, I am all for any simple performance enhancements that
can be made such as the one you suggested.

Also, I realize that one very valuable use of the tool is as an
auditing system of all the SQL or just to report exceptions-- in which
case it would be turned on all the time in production environments, so
I would like to improve the performance as much as possible.

The one issue you identified is quite easy to fix and I will incorporate that.

I am a little surprised at the numbers you came up with as I didn't
think the performance was nearly that bad.

If you have time to identify any more hot spots feel free to let me know.

At some point I should do some real profiling on it...

Thanks for your analysis.

> --
>
> You received this message because you are subscribed to the Google Groups "log4jdbc" group.
> To post to this group, send email to log4...@googlegroups.com.
> To unsubscribe from this group, send email to log4jdbc+u...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/log4jdbc?hl=en.
>
>
>

[Arthur Blake]

BTW, here is my re-written method:

/**
* Called when a jdbc method from a Connection, Statement, PreparedStatement,
* CallableStatement or ResultSet returns.
*
* @param spy the Spy wrapping the class that called the method that
* returned.
* @param methodCall a description of the name and call parameters of the
* method that returned.
* @param returnMsg return value converted to a String for integral types, or
* String representation for Object. Return types this will
* be null for void return types.
*/
public void methodReturned(Spy spy, String methodCall, String returnMsg)
{
Logger logger;
String classType = spy.getClassType();
if (ResultSetSpy.classTypeDescription.equals(classType))
{
logger=resultSetLogger;
}
else
{
logger=jdbcLogger;
}

if (logger.isInfoEnabled())
{
String header = spy.getConnectionNumber() + ". " + classType + "." +
methodCall + " returned " + returnMsg;
if (logger.isDebugEnabled())
{
logger.debug(header + " " + getDebugInfo());
}
else
{
logger.info(header);
}
}
}


If you still have your test setup- can you try it with this new
implementation and let me know what numbers you get?

[Marcin D.]

> If you still have your test setup- can you try it with this new
> implementation and let me know what numbers you get?

As I expected, your correction has sped up my test case to 51.5
seconds (under ERROR log level) - close to what I got with my
experiments. Recompilation under Java 1.5 brings it down by additional
3.5 seconds, to 48 (for all previous tests I used your
log4jdbc3-1.1.jar, which was compiled with 1.4 compliance) - the newer
compiler's optimization of String concatenation routines probably
helps (a wild guess).

As regards other "hot spots", well, I can't see any more quick fixes,
like the one in methodReturned(), which is indirectly executed by
almost all JDBC-call-wrapping methods. Now it's probably the matter of
plodding through tens of wrapping methods and introduce log level
checks there, before the local variables "String methodCall = ..." are
constructed. There are already SpyLogDelegator references in Spy
implementors, they could be asked in detail for log levels...

Thanks for your fast response, now I don't even have to keep my own
patched version.

[Arthur Blake]

I've been thinking about this a little bit and pondering where the
biggest performance issues might be...

One potential large boost of performance might be obtained by not
using the ResultSetSpy at all

That is, if you don't care about reporting errors that might occur
when accessing the ResultSet...
(I would think that most potential errors would occur while executing
the PreparedStatement.)

You could simply not wrap the ResultSet at all.

If that is something that you think might be worth doing-- you could
change the 4 locations (1 in PrepareStatementSpy and 3 in
StatementSpy) where the ResultSet is wrapped with a ResultSetSpy and
just use the actual ResultSet instead.

Code locations for JDBC4 version on trunk:

PreparedStatementSpy:734
StatementSpy:663
StatementSpy:585
StatementSpy:934

If you give that a try, let me know how much of a performance boost it
gets you...