Perf4j Basic Example with Log4j

One of the main benefits of Perf4J is that it allows performance analysis and monitoring on live production applications through extensions to common logging frameworks like log4j and logback. These custom log4j appenders can be configured through the standard configuration mechanisms to add functionality without requiring changes to code.

1. Create a log4j.properties file and put it into the resources folder.
# Root logger option
log4j.rootLogger=INFO, file, stdout
	 
# Direct log messages to stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} [%t] %-5p:: %m%n

# Direct log messages to a log file
log4j.appender.file=org.apache.log4j.RollingFileAppender 
log4j.appender.file.File=F:\\App\\javavillage.log
log4j.appender.file.MaxFileSize=10000KB
log4j.appender.file.MaxBackupIndex=10
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} [%t] %-5p:: %m%n

2. Declares the following dependencies
 <dependency>
	<groupId>log4j</groupId>
	<artifactId>log4j</artifactId>
	<version>1.2.17</version>
 </dependency>
 <dependency>
	<groupId>org.perf4j</groupId>
	<artifactId>perf4j</artifactId>
	<version>0.9.16</version>
 </dependency>
3. To log a message, first, create a final static logger and define a name for the logger, normally, we use the full package class name.

  final static Logger logger = Logger.getLogger(classname.class);

package com.javavillage;

import org.apache.log4j.Logger;
import org.perf4j.StopWatch;
import org.perf4j.log4j.Log4JStopWatch;

public class Log4jMain {
	private final static Logger logger = Logger.getLogger(Log4jMain.class);

	private void email(){
		StopWatch stopWatch = new Log4JStopWatch("email");
		try {
			Thread.sleep((long)(Math.random() * 1000L));
		} catch (InterruptedException e) {
			e.printStackTrace();
		}
		logger.info("email");
		stopWatch.stop();
		
	}
	private void phone(){
		StopWatch stopWatch = new Log4JStopWatch("phone");
		try {
			Thread.sleep((long)(Math.random() * 2000L));
		} catch (InterruptedException e) {
			e.printStackTrace();
		}
		logger.info("phone");
		stopWatch.stop();
		
	}
	public static void main(String args[]) {
		logger.info("Welcome to Perf4j");
		Log4jMain obj = new Log4jMain();
		obj.email();
		obj.phone();

	}
}
Execute the class (Log4jMain.java) with different patterns and log4j levels. Find below result
2015-01-27 18:16:35 [main] INFO :: Welcome to Perf4j
2015-01-27 18:16:35 [main] INFO :: email
2015-01-27 18:16:35 [main] INFO :: start[1422362795232] time[245] tag[email]
2015-01-27 18:16:36 [main] INFO :: phone
2015-01-27 18:16:36 [main] INFO :: start[1422362795477] time[1180] tag[phone]
2015-01-27 18:23:51 [main] INFO :: Welcome to Perf4j
2015-01-27 18:23:51 [main] INFO :: email
2015-01-27 18:23:51 [main] INFO :: start[1422363231413] time[330] tag[email]
2015-01-27 18:23:52 [main] INFO :: phone
2015-01-27 18:23:52 [main] INFO :: start[1422363231743] time[561] tag[phone]
2015-01-27 18:24:08 [main] INFO :: Welcome to Perf4j
2015-01-27 18:24:09 [main] INFO :: email
2015-01-27 18:24:09 [main] INFO :: start[1422363248688] time[489] tag[email]
2015-01-27 18:24:09 [main] INFO :: phone
2015-01-27 18:24:09 [main] INFO :: start[1422363249182] time[244] tag[phone]
Here created two kind of tags which are doing different jobs in different time period by changing Thread sleep time as I don't have any specific execution. Based on tag will be able to calicaulate aggregated performance statistics using perf4j.
Now will see the graphic for each tag by running below commands. To execute below commands perf4j jar should be available in log file location.


1. Performance Statistics
java -jar perf4j-0.9.16.jar javavillage.log -t 900000
F:\App>java -jar perf4j-0.9.16.jar javavillage.log -t 900000
Performance Statistics   2015-01-27 18:15:00 - 2015-01-27 18:30:00
Tag                                                  Avg(ms)         Min
 Max     Std Dev       Count
email                                                  354.7         245
 489       101.1           3
phone                                                  661.7         244
1180       388.7           3
2. Graphing Statistics
java -jar perf4j-0.9.16.jar --graph perfGraphs.html javavillage.log

Perf4j Graphic

Find the --help for perf4j to know more.
Usage: LogParser [-o|--out|--output outputFile] [-g|--graph graphingOutputFile]
[-t|--timeslice timeslice] [-r] [-f|--format text|csv] [logInputFile]
Arguments:
  logInputFile - The log file to be parsed. If not specified, log data is read f
rom stdin.
  -o|--out|--output outputFile - The file where generated statistics should be w
ritten. If not specified, statistics are written to stdout.
  -g|--graph graphingOutputFile - The file where generated perf graphs should be
 written. If not specified, no graphs are written.
  -t|--timeslice timeslice - The length of time (in ms) of each timeslice for wh
ich statistics should be generated. Defaults to 30000 ms.
  -r - Whether or not statistics rollups should be generated. If not specified,
rollups are not generated.
  -f|--format text|csv - The format for the statistics output, either plain text
 or CSV. Defaults to text.
                         If format is csv, then the columns output are tag, star
t, stop, mean, min, max, stddev, and count.

Note that out, stdout, err and stderr can be used as aliases to the standard out
put streams when specifying output files.