SQL Logging

(Hinweis: Ab 34.14.9 werden auch schreibende SQLs, DDLs und MetaFetches geloggt. Für SQL Logging der Version 3.13.8 oder früher bitte 6. lesen.)

Um alle SQL Statements zu loggen, müssen folgende Zeilen in der log4j.properties hinzugefügt werden:

Codeblock
#SQL logging log4j.logger.SQLLogger=DEBUG

Die Datei log4j.propierties ist im "conf" Verzeichnis des Servers zu finden, zusammen mit den Dateien jdbc.properties und server.properties. Die Ausgabe des SQL Statements vor der Ausführung erscheint dann in der Datei server.log im Verzeichnis logs und sieht z.B. folgendermaßen aus:

Codeblock

2013-06-27 14:44:09,567 DEBUG pool-2-thread-1 [SQLLogger] - SELECT t.INTID, t.DATCREATED, t.STRCREATED, t.DATCHANGED, t.STRCHANGED, t.INTVERSION, t.INTNUCLETVERSION, t.STRPACKAGE, t.STRNAMESPACE, t.DESCRIPTION, t.NAME FROM T_AD_APPLICATION t WHERE (1=1 AND t.INTID IN (?))
=[40013466]

2) SQL Performance Logging

Zusätzlich kann noch die Zeit der einzelnen SQL-Statmens gemessen werden. Dazu muss der SQLTimer aktiviert werden:

Codeblock
#SQL logging log4j.logger.SQLTimer=DEBUG

Damit wird das SQL Statement nach der Ausführung zusammen mit der Dauer ausgegeben:

19.0 und 4.18.2: Im Webclient kann der Super-User das Logging während des Betriebs an- und ausschalten, rechts unter dem Zahnrad-Dropdown Menüpunkt "Server Info". Log level für den gewünschten Logger auf "DEBUG" setzen:

Image Added

SQL Timer per REST einschalten:

Codeblock

curl --cookie-jar cookies.txt http://localhost:8080/nuclos-war/rest -X POST -H "Content-Type: application/json" -d '{"username":"'nuclos'", "password":"''"}';
curl --cookie cookies.txt http://localhost:8080/nuclos-war/rest/maintenance/logging/SQLTimer/level -X PUT -H "Content-Type: application/json" -d '{"level":"'debug'"}';

bzw. reines SQL Logging vor der Ausführung ohne Timer mit "SQLLogger" statt "SQLTimer" bzw. mit "SQLUpdate" für das ausschließliche Loggen von "UDPATE/INSERT/DELETE"-Statements. Zum Abschalten des Logging den Level wieder von "debug" auf "info" setzen.

Standard SQL Logging

Um alle SQL Statements zu loggen: So sieht die Konfiguration der log4j2.xml aus, wenn einfache SQLLogging (vor dem Ausführen des SQL Statements) eingeschalten werden soll:

Codeblock

title	log4j2 - Ausgabe des SQL-Logging im Server-Log

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="%d %p [%c] - %m%n"/>
    </Console>
    <RollingFile name="Logfile" fileName="<Nuclos-Log-Verzeichnis>/server.log"
            filePattern="<Nuclos-Log-Verzeichnis>/server-%i.log" append="true">
      <PatternLayout pattern="%d %p [%c] - %m%n"/>
      <Policies>
        <SizeBasedTriggeringPolicy size="5 MB"/>
      </Policies>
      <DefaultRolloverStrategy max="20"/>
    </RollingFile>
  </Appenders>
  <Loggers>
    <Logger name="org.apache.log4j.xml" level="info"/>
    <Logger name="SQLLogger" level="debug"/> 
	<Root level="info">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="Logfile"/>
    </Root>
  </Loggers>
</Configuration>

Die Datei log4j2.xml ist im "conf" Verzeichnis des Servers zu finden, zusammen mit den Dateien jdbc.properties und server.properties. Alternativ (oder additional) kann noch "SQLTiming" angeschalten werden:

Codeblock
<Logger name="org.apache.log4j.xml" level="info"/> <Logger name="SQLTimer" level="debug"/>

Damit wird das SQL nach der Ausführung des Statements auf der Datenbank geloggt und die Ausführungszeit in Millisekunden mit angeben. Hier ist eine typische Ausgabe des SQLTimers:

Codeblock

2018-01-04 18:10:54,844 DEBUG

Codeblock

2013-06-27 14:44:09,599 DEBUG pool-2-thread-1 [SQLTimer] - SELECT COUNT (t.INTID, t.DATCREATED, t.STRCREATED, t.DATCHANGED, t.STRCHANGED, t.INTVERSION, t.INTNUCLETVERSION, t.STRPACKAGE, t.STRNAMESPACE, t.DESCRIPTION, t.NAME FROM T_AD_APPLICATION) FROM D2SC_FH_LASTPOSITION t WHERE (1=1 AND t.INTID IN (?))
=[40013466]=(322 ms)

Hinweis: Es kann hilfreich sein, sowohl das Statement vor, als auch nach der Ausführung zu loggen. Insbesondere wenn Statements besonders lange dauern. Dafür werden einfach die beiden Zeilen kombiniert:

Codeblock
#SQL logging log4j.logger.SQLLogger=DEBUG log4j.logger.SQLTimer=DEBUG

...

SQL StackTrace

...

Logging

Es kann zusätzlich noch der StackTrace, sowohl vom Server, als auch vom Client, bis zur Ausführung des SQL-Statements geloggt werden.

Codeblock
#SQL logging log4j.logger.SQLLogger=DEBUG log4j.logger.ClientStackTrace=DEBUG log4j.logger.ServerStackTrace=DEBUG

Mit der Option "DEBUG" werden nur StackTrace Elemente, welche mit "org.nuclos" beginnen geloggt. Wenn alle Element ausgegeben werden sollen, dann sollte die Option "TRACE" verwenden werden:

Codeblock
#SQL logging log4j.logger.SQLLogger=DEBUG log4j.logger.ClientStackTrace=TRACE log4j.logger.ServerStackTrace=TRACE

4) JDBCAppender SQL Logging

Zusätzlich (oder alternativ) lassen sich die SELECT SQL Statements direkt in eine Datenbank schreiben. Dies erledigt das Apache log4j-Framework. Dazu braucht man eine Datenbank, die nicht notwendigerweise identisch mit der Nuclos-DB sein muss. Dort muss eine Tabelle angelegt werden, z.B. für PostgreSQL (bei Oracle sollte die Spalte "MESSAGE" ein CLOB sein):

Codeblock

CREATE TABLE <SCHEMA>.LOGS(
	DATED TIMESTAMP NOT NULL PRIMARY KEY,
	LOGGER VARCHAR(127) NOT NULL,
	LEVEL VARCHAR(15) NOT NULL,
	MESSAGE VARCHAR(10485760) NOT NULL,
	THREAD VARCHAR(4000) NOT NULL,
	TIME INTEGER,
	PARAMS VARCHAR(4000)
);

Dazu sind folgende Parameter in die o.g. log4j.propierties hinzuzufügen und entsprechend anzupassen.

Codeblock

#SQL logging
log4j.logger.SQLLogger=DEBUG, DB
log4j.logger.SQLTimer=DEBUG, DB
 
#JDBCAppender
log4j.appender.DB=org.apache.log4j.jdbc.JDBCAppender
log4j.appender.DB.driver=org.postgresql.Driver
log4j.appender.DB.URL=jdbc\:postgresql\://datenbankip\:5432/postgres
log4j.appender.DB.user=nuclos
log4j.appender.DB.password=nuclos
log4j.appender.DB.sql=INSERT INTO <SCHEMA>.LOGS VALUES('%d{yyyy-MM-dd HH:mm:ss.SSS}','%c','%p','%m','%t')
log4j.appender.DB.layout=org.apache.log4j.PatternLayout

Es ist zu empfehlen, den Log-Level möglichst hoch zu setzten (wie hier "WARN") damit die DB beim Loggin nicht überlastet wird. Durch entfernen von "stdout" oder "logfile" kann das Logging auf die DB selber beschränkt werden.

5) Auswertung der SQLTimer Werte aus der Datenbank

Mit "SQLTimer" werden die Angaben zur verbrauchten Zeit an die Message gehängt. Um diese einfacher auszuwerten, kann folgendes DB-Statements durchgeführt werden:

Codeblock

UPDATE <SCHEMA>.LOGS SET TIME = CAST(SUBSTRING(
MESSAGE FROM POSITION('=(' IN MESSAGE)+2 FOR POSITION(' ms)' IN MESSAGE)-POSITION('=(' IN MESSAGE)-2) AS INTEGER),
PARAMS = SUBSTRING(MESSAGE FROM POSITION('=[' IN MESSAGE)+2 FOR POSITION(']=' IN MESSAGE)-POSITION('=[' IN MESSAGE)-2),
MESSAGE = RTRIM(SUBSTRING(MESSAGE FROM 0 FOR POSITION('=[' IN MESSAGE)-1))
WHERE LOGGER = 'SQLTimer'

Hinweis: Die Syntax der Statements ist PostgreSQL-Spezifisch. Für andere Datenbanken müssen die Statements angepasst werden.

Beispiel einer möglichen Auswertung:

Codeblock
DELETE FROM <SCHEMA>.LOGS WHERE LOGGER != 'SQLTimer' SELECT SUM(TIME) AS SUM, COUNT(TIME) AS COUNT, MESSAGE FROM <SCHEMA>.LOGS GROUP BY MESSAGE ORDER BY SUM DESC

6) Standard SQL Logging (3.13.8 oder früher)

Um alle SQL Statements zu loggen, müssen folgende Zeilen in der log4j.properties hinzugefügt werden:

Codeblock
#SQL logging log4j.logger.org.nuclos.server.dblayer=DEBUG log4j.logger.org.nuclos.server.dal.processor.jdbc.impl.standard.StandardSqlDBAccess=DEBUG

Damit die neuen Parameter wirksam werden, muss der Server neu gestartet werden. Die Datei log4j.propierties ist im "conf" Verzeichnis des Servers zu finden, zusammen mit den Dateien jdbc.properties und server.properties.

Die Ausgabe erscheint dann in der Datei server.log im Verzeichnis logs und sieht z.B. folgendermaßen aus:

Codeblock

2013-02-11 10:02:28,208 DEBUG localhost-startStop-1 [impl.standard.StandardSqlDBAccess] - Query to execute:
 SELECT * FROM (SELECT businessobject.INTID  FROM T_MD_businessobject businessobject WHERE businessobject.STRbusinessobject = ?) WHERE ROWNUM <= 2
 [PSDH_Typ]

Wenn die Ausführung des SQL Statements länger als 0.1 Sekunden braucht, wird anschließend noch eine Zeitangabe (in Millisekunden) ausgegeben:

...

Dafür kann der Textfilter unter "Server Info" im Webclient verwendet werden (siehe oben): Außerdem kann in der Klasse "DataSourceExecuter" ein String-Suchbegriff angegeben werden, entweder über einen Debugger durch setzen des Strings in folgender Methode

Codeblock
public static String getDebugSQL() { return "SELECT COUNT"; }

oder durch setzen aus dem Programm mit der statischen Methoden DataSourceExeceuter.setDebugSQL(String debugSQL)

Codeblock
DataSourceExeceuter.setDebugSQL("SELECT COUNT");

Dann werden für alle SQL Statements die "SELECT COUNT" beinhaltet zwei erweiterte Stacktraces ausgegeben:

Codeblock

2018-01-04 18:10:54,843 DEBUG [ServerStackTrace] - Server Stack Trace:
org.nuclos.server.dblayer.impl.DataSourceExecutor.logStackTrace(DataSourceExecutor.java:179)
org.nuclos.server.dblayer.impl.DataSourceExecutor.beforeExecution(DataSourceExecutor.java:139)
org.nuclos.server.dblayer.impl.DataSourceExecutor.execute(DataSourceExecutor.java:230)
org.nuclos.server.dblayer.impl.standard.StandardSqlDBAccess.executeQueryImpl(StandardSqlDBAccess.java:295)
org.nuclos.server.dblayer.impl.standard.StandardSqlDBAccess.executeQuery(StandardSqlDBAccess.java:274)
org.nuclos.server.dblayer.impl.standard.StandardSqlDBAccess.executeQuery(StandardSqlDBAccess.java:262)
org.nuclos.server.dblayer.impl.standard.StandardSqlDBAccess.executeQuerySingleResult(StandardSqlDBAccess.java:400)
org.nuclos.server.dal.processor.jdbc.impl.EntityObjectProcessor.countExact(EntityObjectProcessor.java:647)
org.nuclos.server.dal.processor.jdbc.impl.EntityObjectProcessor.count(EntityObjectProcessor.java:625)
org.nuclos.server.common.ejb3.EntityObjectFacadeBean.countEntityObjectRows_aroundBody14(EntityObjectFacadeBean.java:297)
org.nuclos.server.common.ejb3.EntityObjectFacadeBean$AjcClosure15.run(EntityObjectFacadeBean.java:1)
org.nuclos.server.common.ejb3.EntityObjectFacadeBean.countEntityObjectRows(EntityObjectFacadeBean.java:293)
org.nuclos.server.common.NuclosRemoteInvocationExecutor.invoke(NuclosRemoteInvocationExecutor.java:207)
org.nuclos.server.common.NuclosHttpInvokerServiceExporter.invokeAndCreateResult(NuclosHttpInvokerServiceExporter.java:13)
 
2018-01-04 18:10:54,843 DEBUG [ServerStackTrace] - Client Stack Trace:
org.nuclos.client.remote.http.NuclosHttpInvokerProxyFactoryBean.executeRequest(NuclosHttpInvokerProxyFactoryBean.java:93)
org.nuclos.common.cache.AllEntityObjectsCache.refill(AllEntityObjectsCache.java:125)
org.nuclos.common.cache.AllEntityObjectsCache.register(AllEntityObjectsCache.java:118)
org.nuclos.common.cache.AllEntityObjectsCache.register(AllEntityObjectsCache.java:105)
de.bmw.fdm.common.fh.gaal.LastfallCommonCache.init(LastfallCommonCache.java:76)
org.nuclos.client.main.StartUp$1.run(StartUp.java:388)

Hinweis: Der Client Stack Trace ist nur erhältlich, wenn der Server im Entwicklungsmodus (-Dfunctionblock.dev=true) gestartet worden ist.

SQL Logging in separates Log-File

Hier steht, wie man SQL Logging in separates Log-File konfiguriert.

SQL Logging für alte Nuclos-Versionen (bis 4.5)

Hier sind die Logging-Einstellung für Nuclos bis 4.5 zu finden: Altes SQL Logging (Bis Nuclos 4.5)

Bereichsverknüpfungen

Seitenhierarchie

Versionen im Vergleich

Alte Version 27

Neue Version Aktuell

Schlüssel

SQL Logging

SQL Timer per REST einschalten:

Standard SQL Logging

SQL StackTrace

Logging

SQL Logging in separates Log-File

Bereichsverknüpfungen

Seitenhierarchie

Seitenhistorie

Versionen im Vergleich

Alte Version 27

Neue Version Aktuell

Schlüssel

SQL Logging

SQL Timer per REST einschalten:

Standard SQL Logging

SQL StackTrace

Logging

SQL Logging in separates Log-File