=====Oracle SQL Traces erzeugen und auswerten===== {{ :images:ziege_lernt_sql.png?direct|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 => * http://docs.oracle.com/cd/E11882_01/appdev.112/e40758/d_monitor.htm#ARPLS67176 * Tracing Enhancements Using DBMS_MONITOR (In 10g, 11g and Above) (Doc ID 293661.1) ==== 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 [[dba:oracle_optimizer_trace|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[] 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 ==== Oracle: * http://docs.oracle.com/cd/E11882_01/appdev.112/e40758/d_monitor.htm Trace: * http://www.oracle-base.com/articles/misc/sql-trace-10046-trcsess-and-tkprof.php#generating_sql_trace_files Sehr gutes Papier für die Analyse: * http://method-r.com/papers * http://method-r.com/papers?download=72:sql-trace-data-(paper) Optimizer Trace: * http://structureddata.org/category/oracle/optimizer/