Skip to main content

java.util.logging versus log4j performance

11 replies [Last post]
weberjn
Offline
Joined: 2003-11-11
Points: 0

Hi,

I did a small benchmark of java.util.logging versus log4J (JDK 1.6.04)

The code below was run with -t 400 -n 100, i.e. 400 Threads and 100 iterations.

java.util.logging: Test time: 2141

log4J:Test time: 5219

I was quite surprised that log4J was so much faster.
Somebody cares to repeat my test?

Thanks,Juergen

logging.properties:
handlers=java.util.logging.FileHandler
.level= FINE
java.util.logging.FileHandler.pattern = jul.log
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter

log4j.properties:
log4j.rootCategory=DEBUG, A1
log4j.appender.A1=org.apache.log4j.RollingFileAppender
log4j.appender.A1.File=myapp.log
log4j.appender.A1.MaxFileSize=100MB
log4j.appender.A1.MaxBackupIndex=1
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%d [%t] %-5p %c %x - %m%n

------------------
package log;

import java.io.File;
import java.io.FileInputStream;
import java.io.FileNotFoundException;
import java.io.IOException;
import java.util.logging.LogManager;

public class LogSpeed {

static java.util.logging.Logger jullogger = java.util.logging.Logger.getLogger(LogSpeed.class.getName());
static org.apache.log4j.Logger log4jlogger = org.apache.log4j.Logger.getLogger(LogSpeed.class.getName());

static boolean useJUL = true;

static int threads = 1;
static int iterations = 1;

static long startTime;
static long endTime;

static int activeThreads = 0;

static synchronized int decActiveThreads() {
activeThreads--;
return activeThreads; }

static synchronized int incActiveThreads() {
activeThreads++;
return activeThreads; }

static class TestRunnable implements Runnable {
String name;
int iter;

public TestRunnable(String name, int iter) {
this.name = name;
this.iter = iter; }

public void run() {
incActiveThreads();
for (int i = 0; i < iter; i++) {
String m = "hello from Thread " + name + " @ iteration " + i + " of " + iter;
if (useJUL) {
jullogger.fine(m);
} else {
log4jlogger.debug(m); }
}
int n = decActiveThreads();

if (n == 0) {
endTime = System.currentTimeMillis();
System.out.println("Test time: " + (endTime - startTime));
} }
}

public static void main(String[] args) throws SecurityException, FileNotFoundException, IOException {
int i;

for (i = 0; i < args.length; i++) {
if ("-jul".equals(args[i])) {
useJUL = true; }
if ("-log4j".equals(args[i])) {
useJUL = false; }

if ("-t".equals(args[i])) {
threads = Integer.parseInt(args[i + 1]); }
if ("-n".equals(args[i])) {
iterations = Integer.parseInt(args[i + 1]); }
}

if (useJUL) {
System.out.println("Using " + jullogger.getClass().getName());
File f = new File("logging.properties");

if (f.exists()) {
LogManager.getLogManager().readConfiguration(new FileInputStream(f)); }
}
else {
System.out.println("Using " + log4jlogger.getClass().getName()); }

System.out.println("Threads: " + threads + " Iterations: " + iterations);

startTime = System.currentTimeMillis();

for (i = 0; i < threads; i++) {
(new Thread(new TestRunnable("" + i, iterations))).start();}
}}

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
helenwh
Offline
Joined: 2010-09-07
Points: 0

They are quite feasible. However, you should check the output format for both cases. Thank for your contribution!

weberjn
Offline
Joined: 2003-11-11
Points: 0

So, people might just compile my code and repeat the tests. Or, if the test code is bad, you might run other tests to compare the speed.

walterln
Offline
Joined: 2007-04-17
Points: 0

Maybe post code and properties between [ code ] ... [ /code ] tags (without spaces), there seems to be a lot missing (args parsing goes wrong, should be [code]args[i][/code] in some places).

I just get alot of system.out's (I guess thread done before next started). Neither option produces a log, and log4j also says:
log4j:WARN No appenders could be found for logger (log.LogSpeed).
log4j:WARN Please initialize the log4j system properly.

weberjn
Offline
Joined: 2003-11-11
Points: 0

OK, here is the code again using code tags:

[code]

package log;

import java.io.File;
import java.io.FileInputStream;
import java.io.FileNotFoundException;
import java.io.IOException;
import java.util.logging.LogManager;

public class LogSpeed
{

static java.util.logging.Logger jullogger = java.util.logging.Logger.getLogger(LogSpeed.class.getName());
static org.apache.log4j.Logger log4jlogger = org.apache.log4j.Logger.getLogger(LogSpeed.class.getName());

static boolean useJUL = true;

static int threads = 1;
static int iterations = 1;

static long startTime;
static long endTime;

static int activeThreads = 0;

static synchronized int decActiveThreads()
{
activeThreads--;
return activeThreads;
}

static synchronized int incActiveThreads()
{
activeThreads++;
return activeThreads;
}

static class TestRunnable implements Runnable
{
String name;
int iter;

public TestRunnable(String name, int iter)
{
this.name = name;
this.iter = iter;
}

public void run()
{
incActiveThreads();
for (int i = 0; i < iter; i++)
{
String m = "hello from Thread " + name + " @ iteration " + i + " of " + iter;
if (useJUL)
{
jullogger.fine(m);
}
else
{
log4jlogger.debug(m);
}
}
int n = decActiveThreads();

if (n == 0)
{
endTime = System.currentTimeMillis();
System.out.println("Test time: " + (endTime - startTime));
}
}
}

public static void main(String[] args) throws SecurityException, FileNotFoundException, IOException
{
int i;

for (i = 0; i < args.length; i++)
{
if ("-jul".equals(args[i]))
{
useJUL = true;
}
if ("-log4j".equals(args[i]))
{
useJUL = false;
}

if ("-t".equals(args[i]))
{
threads = Integer.parseInt(args[i + 1]);
}
if ("-n".equals(args[i]))
{
iterations = Integer.parseInt(args[i + 1]);
}
}

if (useJUL)
{
System.out.println("Using " + jullogger.getClass().getName());
File f = new File("logging.properties");

if (f.exists())
{
LogManager.getLogManager().readConfiguration(new FileInputStream(f));
}
}
else
{
System.out.println("Using " + log4jlogger.getClass().getName());
}

System.out.println("Threads: " + threads + " Iterations: " + iterations);

startTime = System.currentTimeMillis();

for (i = 0; i < threads; i++)
{
(new Thread(new TestRunnable("" + i, iterations))).start();
}
}
}
[/code]

logging.properties

[code]
handlers=java.util.logging.FileHandler
.level= FINE
java.util.logging.FileHandler.pattern = jul.log
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
[/code]

log4j.properties

[code]
log4j.rootCategory=DEBUG, A1
log4j.appender.A1=org.apache.log4j.RollingFileAppender
log4j.appender.A1.File=myapp.log
log4j.appender.A1.MaxFileSize=100MB
log4j.appender.A1.MaxBackupIndex=1
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%d [%t] %-5p %c %x - %m%n
[/code]

walterln
Offline
Joined: 2007-04-17
Points: 0

Then I get about the same result as you (assuming you got them swapped) - log4j ~2k, java.util ~4.5k.

weberjn
Offline
Joined: 2003-11-11
Points: 0

I get:
[code]
D:\eclipseworkspace\LoggerSpeed>java -version
java version "1.6.0_05"
Java(TM) SE Runtime Environment (build 1.6.0_05-b13)
Java HotSpot(TM) Client VM (build 10.0-b19, mixed mode, sharing)

D:\eclipseworkspace\LoggerSpeed>java -classpath .;build;lib/log4j-1.2.15.jar log.LogSpeed -t 400 -n
100
Using java.util.logging.Logger
Threads: 400 Iterations: 100
Test time: 4812

D:\eclipseworkspace\LoggerSpeed>java -classpath .;build;lib/log4j-1.2.15.jar log.LogSpeed -t 400 -n
100
Using java.util.logging.Logger
Threads: 400 Iterations: 100
Test time: 4828

D:\eclipseworkspace\LoggerSpeed>java -classpath .;build;lib/log4j-1.2.15.jar log.LogSpeed -t 400 -n
100 -log4j
Using org.apache.log4j.Logger
Threads: 400 Iterations: 100
Test time: 2078

D:\eclipseworkspace\LoggerSpeed>java -classpath .;build;lib/log4j-1.2.15.jar log.LogSpeed -t 400 -n
100 -log4j
Using org.apache.log4j.Logger
Threads: 400 Iterations: 100
Test time: 2032
[/code]

There was still a bug in the code, sometimes it would print out the result too often, this is better:

[code]

package log;

import java.io.File;
import java.io.FileInputStream;
import java.io.FileNotFoundException;
import java.io.IOException;
import java.util.logging.LogManager;

public class LogSpeed
{

static java.util.logging.Logger jullogger = java.util.logging.Logger.getLogger(LogSpeed.class.getName());
static org.apache.log4j.Logger log4jlogger = org.apache.log4j.Logger.getLogger(LogSpeed.class.getName());

static boolean useJUL = true;

static int threads = 1;
static int iterations = 1;

static long startTime;
static long endTime;

static int finishedThreads = 0;

static synchronized int incFinishedThreads()
{
finishedThreads++;
return finishedThreads;
}

static class TestRunnable implements Runnable
{
String name;
int iter;

public TestRunnable(String name, int iter)
{
this.name = name;
this.iter = iter;
}

public void run()
{
for (int i = 0; i < iter; i++)
{
String m = "hello from Thread " + name + " @ iteration " + i + " of " + iter;
if (useJUL)
{
jullogger.fine(m);
}
else
{
log4jlogger.debug(m);
}
}
int n = incFinishedThreads();

if (n == threads)
{
endTime = System.currentTimeMillis();
System.out.println("Test time: " + (endTime - startTime));
}
}
}

public static void main(String[] args) throws SecurityException, FileNotFoundException, IOException
{
int i;

for (i = 0; i < args.length; i++)
{
if ("-jul".equals(args[i]))
{
useJUL = true;
}
if ("-log4j".equals(args[i]))
{
useJUL = false;
}

if ("-t".equals(args[i]))
{
threads = Integer.parseInt(args[i + 1]);
}
if ("-n".equals(args[i]))
{
iterations = Integer.parseInt(args[i + 1]);
}
}

if (useJUL)
{
System.out.println("Using " + jullogger.getClass().getName());
File f = new File("logging.properties");

if (f.exists())
{
LogManager.getLogManager().readConfiguration(new FileInputStream(f));
}
}
else
{
System.out.println("Using " + log4jlogger.getClass().getName());
}

System.out.println("Threads: " + threads + " Iterations: " + iterations);

startTime = System.currentTimeMillis();

for (i = 0; i < threads; i++)
{
(new Thread(new TestRunnable("" + i, iterations))).start();
}
}
}

[/code]

mohankishore
Offline
Joined: 2003-08-21
Points: 0

You might want to check the output format for both cases. The default configuration seems to be printing the class/method name information for the java.util.logging and NOT printing the same for log4j. Once you change the log4j pattern-layout to include the %C %M, it is nearly 1.5 to 2 times slower than the java.util.logging :(

patriot1burke
Offline
Joined: 2003-06-17
Points: 0

Also, if you do a logp instead, jul will be a bit faster. Another thing I found out is that if you bump the log filter to info, and increase the iterations, the times get a lot closer.

sunil_gupta20801
Offline
Joined: 2005-01-03
Points: 0

I thought log4j was fast.

MyBlog: http://sunil-gupta.blogspot.com

mthornton
Offline
Joined: 2003-06-10
Points: 0

> java.util.logging: Test time: 2141
>
> log4J:Test time: 5219
>
> I was quite surprised that log4J was so much faster.
> Somebody cares to repeat my test?

It seems to me that java.util.logging was faster.

weberjn
Offline
Joined: 2003-11-11
Points: 0

The last lines got eaten up:

startTime = System.currentTimeMillis();

for (i = 0; i < threads; i++)
{
(new Thread(new TestRunnable("" + i, iterations))).start();
}
}
}