Benutzer-Werkzeuge

Webseiten-Werkzeuge


dba:sql_trace_oracle

Oracle SQL Traces erzeugen und auswerten

Ziege lernt SQL

Alles was hinter einem ausgeführten SQL Befehle in der Datenbank steht, kann in einem Trace Files mit geschrieben werden.

Die Trace Files werden vom dem Prozess geschrieben, der das SQL Kommando parst und ausführt.

Das Tracing kann auf der gesamten Datenbank, allen Sessionen, die sich über einen bestimmten Service anmelden und auf jeder Session aktiviert werden.

Alle aktuellen SQL Statements der Instance mit schreiben

Sehr unpraktisch, da viele Dateien und viele Daten erzeugt werden, recht mühsam in der Analyse.

Einschalten mit dem Parameter sql_trace

sqlplus / AS sysdba
 
SQL>SHOW parameter sql_trace
 
NAME                                 TYPE        VALUE
------------------------------------ ----------- -------
sql_trace                            BOOLEAN     FALSE
 
 
SQL>ALTER system SET sql_trace=TRUE scope=memory;
 
# Trace Verzeichnis und Trace Datei der aktuellen SESSION:
 
SELECT  VALUE 
 FROM  v$diag_info 
WHERE  name = 'Default Trace File';
 
 
VALUE
---------------------------------------------------
D:\ORACLE\diag\rdbms\gpi\gpi\trace\gpi_ora_2748.trc
 
#wieder ausschalten 
 
SQL>ALTER system SET sql_trace=FALSE scope=memory;

Userid im Trace wieder erkennen

Wie erkenne ich nun aber von welchem User welcher Trace verursacht wurde?

Beispiel - Auszug aus dem Trace File:

PARSING IN CURSOR #368408184 len=43 dep=0 uid=88 oct=3 lid=88 tim=6948133230 hv=3912676408 ad='7ff2d6e3c58' sqlid='bbx3c0rnmdd1s'

In diesem Beispiel ist das die „uid=88“, mit der 88 als User ID dann in der dba_users suchen:

SELECT username FROM dba_users WHERE user_id=88;
 
USERNAME
--------
GPI

Trace auf alle Sessions mit speziellen Eigenschaften mit DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE

Beispiel - Alle Sessions die sich über eine Service verbinden aufzeichnen:

BEGIN
	DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE(
		 service_name  => 'SRVGPI'
		,module_name   =>  DBMS_MONITOR.ALL_MODULES
		,action_name   =>  DBMS_MONITOR.ALL_ACTIONS				
		,binds         =>  TRUE
		,instance_name =>  NULL
		,plan_stat     =>  NULL
	);
 END;
/
Überprüfen

Über die View dba_enabled_traces prüfen, ob ein Trace eingeschaltet ist:

SELECT trace_type
	  , primary_id
	  , qualifier_id1
	  , qualifier_id2
	  , waits
	  , binds
	  , plan_stats
	  , instance_name
 FROM dba_enabled_traces
ORDER BY
instance_name
/

Wieder ausschalten:

BEGIN
   DBMS_MONITOR.serv_mod_act_trace_disable(
		 service_name  => 'SRVGPI'
		,module_name   =>  DBMS_MONITOR.ALL_MODULES
		,action_name   =>  DBMS_MONITOR.ALL_ACTIONS					
	);
 END;
/

Trace auf einer Sesssion bei bekannter SID

In der eigenen Session einschalten:

BEGIN
 dbms_monitor.session_trace_enable(
    session_id   => NULL,
    serial_num   => NULL,
    waits        => TRUE,
    binds        => TRUE,
    plan_stat    => NULL);
 END;
 /
 
-- session_id  Client Identifier for which SQL trace is enabled. If omitted (or NULL), the user's own session is assumed.
-- serial_num  Serial number for this session. If omitted (or NULL), only the session ID is used to determine a session.
-- waits       If TRUE, wait information is present in the trace
-- binds       If TRUE, bind information is present in the trace
-- plan_stat   Frequency at which we dump row source statistics. Value should be 'NEVER', 'FIRST_EXECUTION' (equivalent to NULL) or 'ALL_EXECUTIONS'.
Wird mit „dbms_monitor.session_trace_enable“ eine Session getracet ist nur in der v$session die Spalte SQL_TRACE gesetzt, wird aber „mit dbms_monitor.client_id_trace_enable“ der Trace gestaret, wird der Trace in der View dba_enabled_traces angezeigt und NICHT mehr in der v$session!

Und wieder ausschalten:

BEGIN
dbms_monitor.session_trace_disable(
   session_id      => NULL,
   serial_num      => NULL);
END;
/
 
-- session_id 	Database Session Identifier for which SQL trace is disabled
-- serial_num 	Serial number for this session

see ⇒

Logon Trigger auf einem User

Per Logon Trigger wird das Tracing aktiviert:

CREATE OR REPLACE TRIGGER trg_logon
after logon
ON DATABASE
DECLARE
  PRAGMA AUTONOMOUS_TRANSACTION;
BEGIN
 --  Tracing aktivieren
 IF ora_login_user IN ('SYS','DBSNMP','SYSMAN') THEN
    -- do nothing
 	NULL;
 ELSE
 
        -- set trace file identifier to 
        EXECUTE immediate 'ALTER SESSION SET tracefile_identifier = '''||ora_login_user||'''';
 
        -- start trace
        dbms_monitor.session_trace_enable;
 
 	-- status in Log Tabelle schreiben 
 END IF;	
END;
/
 
# CHECK IF valid!
# test IN other SESSION IF it IS working BEFORE you close this SESSION?
 
SELECT STATUS 
  FROM dba_triggers 
 WHERE trigger_name='TRG_LOGON'
/

Ist der Trigger ungültig, kann keine Anmeldung an der DB erfolgen! Daher sorgfältig entwickeln!

Tip: System Trigger auschalten
Mit „ALTER SYSTEM SET „_system_trig_enabled“ = FALSE SCOPE=BOTH;“ kann ein System Trigger ausgeschaltet werden. Zur Not DB nur in nomount Status starten, spfile anpassen, DB öffnen und reparieren.

Alternativ: Geht es nur um die Ameldung, klassisches Auditing in die aud$ Tabelle verwenden!

Traces bei bestimmten Events oder bestimmten Vorgängen einschalten

11g

Ein Trace kann auch per Event eingeschaltet werden, zum Beispiel um die Details beim Erstellen eines Ausführungsplan zu erhalten.

⇒ siehe dazu Oracle 11g - Einen Trace File vom Optimizer beim Erzeugen eines Plan anlegen

  • Alle Events lassen sich in SQL*Plus mit oradebug doc event„ anzeigen
  • Alle Komponenten lassen sich in SQL*Plus mit oradebug doc componet“ anzeigen.

Mit dem Befehl ALTER SESSION SET events 'trace[<component>] disk=highest'; kann auf diese Komponente dann Trace aktiviert werden.


Trace Files auswerten

Mit trcsess können tracefiles aus mehreren Sessions zusammen fassen und mit tkprof auswerten.

Alternativ kann auch der Trace File direkt ausgewertet werden:

PARSING IN CURSOR #336124736 len=26 dep=0 uid=88 oct=3 lid=88 tim=12660074829 hv=1505019447 ad='7ff2d624ac0' sqlid='70dazgjcv9jjr'
 
select count(*) from col_t
END OF STMT
 
 
PARSE #336124736:c=0,e=1086,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2309432470,tim=12660074828
 
 
EXEC #336124736:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2309432470,tim=12660074954
 
 
WAIT #336124736: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=12660075023
 
WAIT #336124736: nam='Disk file operations I/O' ela= 114 FileOperation=2 fileno=4 filetype=2 obj#=149923 tim=12660075388
...........
 
 
...........
 
WAIT #336124736: nam='direct path read' ela= 700 file number=4 first dba=23107 block cnt=5 obj#=149923 tim=12660076257
 
 
FETCH #336124736:c=530403,e=5840160,p=63138,cr=63149,cu=0,mis=0,r=1,dep=0,og=1,plh=2309432470,tim=12665915220
 
STAT #336124736 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=63149 pr=63138 pw=0 time=5840151 us)'
STAT #336124736 id=2 cnt=1570001 pid=1 pos=1 obj=149923 op='TABLE ACCESS FULL COL_T (cr=63149 pr=63138 pw=0 time=2160157 us cost=17264 size=0 card=1570001)'
 
WAIT #336124736: nam='SQL*Net message from client' ela= 286 driver id=1111838976 #bytes=1 p3=0 obj#=149923 tim=12665915667
 
FETCH #336124736:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2309432470,tim=12665915742
 
WAIT #336124736: nam='SQL*Net message to client' ela= 1 driver id=1111838976 #bytes=1 p3=0 obj#=149923 tim=12665915787
 
WAIT #336124736: nam='SQL*Net message from client' ela= 3127 driver id=1111838976 #bytes=1 p3=0 obj#=149923 tim=12665918939
FETCH

FETCH #336124736:c=530403,e=5840160,p=63138,cr=63149,cu=0,mis=0,r=1,dep=0,og=1,plh=2309432470,tim=12665915220

#336124736 Cursor Handle für diesen Fetch
c=530403 Der Call hat 530403 +/- 10.000 uS CPU Zeit verbraucht
e=5840160 Der Call hat 5840160 +/- 1 uS verbrauchter Zeit gesamt
p=63138 Der Call hat 63138 Blöcke via OS read Call
cr=63149 Der Call hat 63149 Blöcke via „consistent mode“ aus dem Buffer Cache gelesen
cu=0 Der Call hat 0 Blöcke via „current mode“ aus dem Buffer Cache gelesen
mis=0 Der Call hat 0 misses gegen dem Oracle Library Cache
r=1 Der Call hat eine Row zurück gegeben
dep=0 Child level Falls > 0 ist es ein Call eines Child SQLs
op=1 Oracle Optimizer Goal 1=all,2=first,3=rule,4=choose
plh=2309432470 Hash Plan Value
tim=12665915220 Zeitstempel in +/- 1uS seit X, je nach Plattform, damit kann die echte Reihenfolge ermittelt werden!
OS Calls - Wait

WAIT #336124736: nam='direct path read' ela=700 file number=4 first dba=23107 block cnt=5 obj#=149923 tim=12660076257

#336124736 Cursor Handle für diesen Fetch
nam='direct path read' Event
ela=700 Der Call hat 700 700 +/- uS der verbrauchten Zeit
file number=4 Datei Nr
first dba=23107
block cnt=5
obj#=149923 Der Call wurde auf dieser Objekt Id durchgeführt
tim=12660076257 Zeitstempel in +/- 1uS seit X, je nach Plattform, damit kann die echte Reihenfolge ermittelt werden!

Quellen

Cookies helfen bei der Bereitstellung von Inhalten. Durch die Nutzung dieser Seiten erklären Sie sich damit einverstanden, dass Cookies auf Ihrem Rechner gespeichert werden. Weitere Information
"Autor: Gunther Pipperr"
dba/sql_trace_oracle.txt · Zuletzt geändert: 2015/11/22 16:00 von Gunther Pippèrr