✔ [log4] Paralleles logging für unterschiedliche Infos

S

SNOWMAN-X

Mitglied
Hallo Community,

ich hänge gerade irgendwie an log4j fest...

Was ich erreichen möchte:
Es gibt ein normales Application Log, welches die Standard-Logging-Infos in sowohl File als auch Console schreibt.
Nun möchte ich ein zweites Log öffnen, in welches ich Performance-Infos schreibe. Diese sollen in ein eigenes File und nur diese.

Aktuell habe ich folgende Konfiguration für log4j:
Code: 
###################################################################
#####  [PROJEKT] Prototyp logger configuration                   #####
###################################################################

log4j.rootLogger = ERROR, file, console, performance

log4j.logger.de.[FIRMA].[PROJEKT].client.selenium=INFO

# Selenium
log4j.logger.org.openqa.selenium=ERROR

####################### Appenders  #############################

log4j.appender.file org.apache.log4j.RollingFileAppender
log4j.appender.file.File logs/selenium.log
log4j.appender.file.layout org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern %d %m%n
log4j.appender.file.Threshold=INFO
log4j.appender.file.MaxFileSize 40MB
log4j.appender.file.MaxBackupIndex 5

log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%-5p [%d{HH:mm:ss,SSS}]: %m%n

####################### Performance ############################

log4j.category.PerformanceLogging=performance

####################### Appenders  #############################

log4j.appender.performance org.apache.log4j.RollingFileAppender
log4j.appender.performance.File logs/selenium_performance.log
log4j.appender.performance.layout org.apache.log4j.PatternLayout
log4j.appender.performance.layout.ConversionPattern %d %m%n
log4j.appender.performance.Threshold=INFO
log4j.appender.performance.MaxFileSize 40MB
log4j.appender.performance.MaxBackupIndex 5

Und eingebunden werden die Logger so:
Code: 
    private static final Log LOG = LogFactory.getLog(SeleniumActor.class);
    private static final Log PERFORMANCE_LOG = LogFactory.getLog("PerformanceLogging");

Nun ist es aber so, dass in beiden Files immer alles steht.
Wenn im normalen Log die Performance-Infos stehen, ist das eigentlich relativ schnurzt, aber im Performance-Log selbst, sollen ausschließlich die Performance-Infos stehen und nichts anderes, da diese einfach in Excel importiert werden sollen.

Wo liegt das Problem? Ich komme vom "Immer Alles" nur zum "Rein Garnichts"... aber irgendwie... häng ich da einfach...
 
Hallo,

du willst also bestimmte Log-Nachrichten in unterschiedliche Dateien schreiben.
Ich glaube ich habe da eine Lösung für dich, siehe unten. Wenn die Lösung(en) so nicht performant genug sein sollten, kannst du dir immer noch eine spezielle Loger-Klasse ableiten die "perf"-Logging Aufrufe an einen eigenen Appender delegiert.



Versuch es mal so (mit log4j-1.2.16.jar):

BusinessService:
Java: 
package de.tutorials.training;

public interface BusinessService {
	void op();
}

SimpleBusinessService:
Java: 
package de.tutorials.training;

import org.apache.log4j.Level;
import org.apache.log4j.Logger;

public class SimpleBusinessService implements BusinessService {

	private final static Logger logger = Logger.getLogger(SimpleBusinessService.class);

	@Override
	public void op() {
		logger.info("start operation");
		long timeMillisAtStart = System.currentTimeMillis();
		op1();
		op2();
		
		String perfMsg = "operation took: " + (System.currentTimeMillis() - timeMillisAtStart) + "ms";
		Logger.getLogger("perf").info(perfMsg);
				
		logger.info("end operation");
	}

	private void op2() {
		logger.info("sub operation 1");
	}

	private void op1() {
		logger.info("sub operation 2");
	}
}

log4j.properties:
Code: 
log4j.appender.applog=org.apache.log4j.RollingFileAppender
log4j.appender.applog.File=app.log
log4j.appender.applog.layout=org.apache.log4j.PatternLayout
log4j.appender.applog.layout.ConversionPattern=%d %-4r [%t] %-5p %c %x - %m%n
log4j.appender.applog.Threshold=INFO

log4j.appender.perflog=org.apache.log4j.RollingFileAppender
log4j.appender.perflog.File=perf.log
log4j.appender.perflog.layout=org.apache.log4j.PatternLayout
log4j.appender.perflog.layout.ConversionPattern=%d %-4r [%t] %-5p %C.%M %x - %m%n
log4j.appender.perflog.Threshold=INFO

log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d %-4r [%t] %-5p %c %x - %m%n

log4j.rootLogger=INFO, console, applog

log4j.logger.perf=INFO, perflog
log4j.additivity.perf=false

Ausgabe (Console):
Code: 
2012-05-03 19:25:59,467 0    [main] INFO  de.tutorials.training.SimpleBusinessService  - start operation
2012-05-03 19:25:59,468 1    [main] INFO  de.tutorials.training.SimpleBusinessService  - sub operation 2
2012-05-03 19:25:59,468 1    [main] INFO  de.tutorials.training.SimpleBusinessService  - sub operation 1
2012-05-03 19:25:59,470 3    [main] INFO  de.tutorials.training.SimpleBusinessService  - end operation

Ausgabe (app.log):
Code: 
2012-05-03 19:25:59,467 0    [main] INFO  de.tutorials.training.SimpleBusinessService  - start operation
2012-05-03 19:25:59,468 1    [main] INFO  de.tutorials.training.SimpleBusinessService  - sub operation 2
2012-05-03 19:25:59,468 1    [main] INFO  de.tutorials.training.SimpleBusinessService  - sub operation 1
2012-05-03 19:25:59,470 3    [main] INFO  de.tutorials.training.SimpleBusinessService  - end operation

Ausgabe (perf.log):
Code: 
2012-05-03 19:25:59,468 1    [main] INFO  de.tutorials.training.SimpleBusinessService.op  - operation took: 0ms

Da beim perf-Logger im Conversion Pattern bei %c nun "perf" steht habe ich dort um mehr Informationen zur ausführenden Methode zu geben mit %C.%M den Klassen- und Methodennamen mit ausgegeben.

Btw. eine ähnliche Problemstellung (Eigenes Log-File pro User) haben wir damals etwas anders gelöst (mit Log4j MDC, siehe: http://www.tutorials.de/java/320124-dynamische-logfiles-mit-log4j.html)

Gruß Tom
 
Hallo,

hier noch ein Beispiel wie man die Problemstellung (logging in unterschiedliche Log-Dateien) anhand von bestimmten Kriterien mit dem Logging-Framework Logback (Logback ist der Nachfolger von log4j) von lösen kann.
Für ein einführendes Beispiel zu Logback siehe: http://www.tutorials.de/java/365737-beispiel-fuer-flexibles-logging-mit-slf4j-und-logback.html

Java: 
package de.tutorials.training;

import static org.slf4j.MarkerFactory.getMarker;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class SimpleBusinessServiceLogback implements BusinessService {

	private final static Logger logger = LoggerFactory.getLogger(SimpleBusinessServiceLogback.class);

	@Override
	public void op() {
		logger.info("start operation");
		long timeMillisAtStart = System.currentTimeMillis();
		op1();
		op2();

		logger.info(getMarker("perf"), "operation took: "+ (System.currentTimeMillis() - timeMillisAtStart) + "ms");

		logger.info("end operation");
	}

	private void op2() {
		logger.info("sub operation 1");
	}

	private void op1() {
		logger.info("sub operation 2");
	}

}

Ausgabe (console):
Code: 
#logback.classic pattern: %d{HH:mm:ss.SSS} [%thread] %.-1level %logger{36} - %msg%n
21:44:58.530 [main] I d.t.t.SimpleBusinessServiceLogback - start operation
21:44:58.532 [main] I d.t.t.SimpleBusinessServiceLogback - sub operation 2
21:44:58.532 [main] I d.t.t.SimpleBusinessServiceLogback - sub operation 1
21:44:58.534 [main] I d.t.t.SimpleBusinessServiceLogback - operation took: 2ms
21:44:58.534 [main] I d.t.t.SimpleBusinessServiceLogback - end operation

Ausgabe (logback_app.log):
Code: 
#logback.classic pattern: %d{HH:mm:ss.SSS} [%thread] %.-1level %logger{36} - %msg%n
21:44:58.530 [main] I d.t.t.SimpleBusinessServiceLogback - start operation
21:44:58.532 [main] I d.t.t.SimpleBusinessServiceLogback - sub operation 2
21:44:58.532 [main] I d.t.t.SimpleBusinessServiceLogback - sub operation 1
21:44:58.534 [main] I d.t.t.SimpleBusinessServiceLogback - end operation

Ausgabe (logback_app_perf.log):
Code: 
#logback.classic pattern: %d{HH:mm:ss.SSS} [%thread] %.-1level %logger{36} - %msg%n
21:44:58.534 [main] I d.t.t.SimpleBusinessServiceLogback - operation took: 2ms

logback-Konfiguration (logback.xml):
XML: 
<configuration scan="true" scanPeriod="15 seconds">

	<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
		<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
			<pattern>%d{HH:mm:ss.SSS} [%thread] %.-1level %logger{36} - %msg%n</pattern>
		</encoder>
	</appender>


	<appender name="FILE_APP_LOG" class="ch.qos.logback.core.FileAppender">
		<File>logback_app.log</File>
		
		<filter class="ch.qos.logback.core.filter.EvaluatorFilter">
			<evaluator>
				<expression>return "perf".equals(java.lang.String.valueOf(marker));</expression>
			</evaluator>
			<OnMatch>DENY</OnMatch>
		</filter>
		
		<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
			<pattern>%d{HH:mm:ss.SSS} [%thread] %.-1level %logger{36} - %msg%n</pattern>
		</encoder>
	</appender>


	<appender name="FILE_APP_PERF_LOG" class="ch.qos.logback.core.FileAppender">
		<File>logback_app_perf.log</File>

		<filter class="ch.qos.logback.core.filter.EvaluatorFilter">
			<evaluator>
				<expression>return "perf".equals(java.lang.String.valueOf(marker));</expression>
			</evaluator>
			<OnMismatch>DENY</OnMismatch>
		</filter>

		<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
			<pattern>%d{HH:mm:ss.SSS} [%thread] %.-1level %logger{36} - %msg%n</pattern>
		</encoder>
	</appender>


	<root level="INFO">
		<appender-ref ref="CONSOLE" />
		<appender-ref ref="FILE_APP_LOG" />
		<appender-ref ref="FILE_APP_PERF_LOG" />
	</root>
</configuration>
Hier noch der Link zur Dokumentation von Filter in Logback:
http://logback.qos.ch/manual/filters.html

Gruß Tom
 
Zuletzt bearbeitet von einem Moderator:
Hey Tom,

vielen Dank! Dein erster Vorschlag hat wunderbar funktioniert! Genau so wollte ich es haben!
Wirklich, was du schreibst, dass hat Hand und Fuß!

Gruß
Holger
 
Um antworten zu können musst du eingeloggt sein.

Neue Beiträge

Zurück