SQL Logging

1) Standard SQL Logging

(Hinweis: Für SQL Logging der Version 3.13.8 oder früher bitte 4. lesen.)

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

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

Dabei ist das SQLTimer-Logging optional durch Hinzufügen eines "#" abwählbar. 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 des SQL Statements vor der Ausführung erscheint dann in der Datei server.log im Verzeichnis logs und sieht z.B. folgendermaßen aus:

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]

Wenn zusätzlich der SQLTimer angeschaltet ist, wird das SQL Statement nach der Ausführung zusammen mit der Dauer ausgegeben:

2013-06-27 14:44:09,599 DEBUG pool-2-thread-1 [SQLTimer] - 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]=(32 ms)

2) JDBCAppender SQL Logging

Zusätzlich (oder alternativ) lassen sich die 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):

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,
	TIME INTEGER,
	PARAMS VARCHAR(4000)
);

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

#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=jdbcUrl=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')
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.

3) 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:

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:

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

4) 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:

#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:

2013-02-11 10:02:28,208 DEBUG localhost-startStop-1 [impl.standard.StandardSqlDBAccess] - Query to execute:
 SELECT * FROM (SELECT entity.INTID  FROM T_MD_ENTITY entity WHERE entity.STRENTITY = ?) 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:

2013-02-11 10:05:49,069 DEBUG Thread-6  [impl.standard.StandardSqlDBAccess] - Query to execute:
 SELECT t.INTID, t.ID_ADDR, t.ID_MODULE, t.ID_PROJECT, t.ID_VARIANT FROM (SELECT t.INTID, t.ID_ADDR, t.ID_MODULE, t.ID_PROJECT, t.ID_VARIANT , ROW_NUMBER() OVER ( ORDER BY t.INTID ASC) AS RN  FROM SV_CONS t WHERE 1=1) t WHERE RN > 6000 AND RN <= 7000
 []
2013-02-11 10:05:49,681 DEBUG Thread-6  [impl.standard.StandardSqlDBAccess] - Time consumed: 610 ms

Bereichsverknüpfungen

Seitenhierarchie