通过DBMS_MONITOR.session_trace_enable开启会话跟踪
在sys会话执行
EXEC DBMS_MONITOR.session_trace_enable(session_id =>5350, serial_num=>1620, waits=>TRUE, binds=>true);
在5350会话执行
select * from test where object_name='TEST';
select object_name from test where object_name='TEST';
select * from test order by 1,2;
在sys会话执行
EXEC DBMS_MONITOR.session_trace_disable(session_id=>5350, serial_num=>1620);
select a.sid,a.serial#,b.spid,b.tracefile from v$session a,v$process b where a.paddr=b.addr and a.sid=&sid;
SQL> select a.sid,a.serial#,b.spid,b.tracefile from v$session a,v$process b where a.paddr=b.addr and a.sid=&sid;
Enter value for sid: 5350
old 1: select a.sid,a.serial#,b.spid,b.tracefile from v$session a,v$process b where a.paddr=b.addr and a.sid=&sid
new 1: select a.sid,a.serial#,b.spid,b.tracefile from v$session a,v$process b where a.paddr=b.addr and a.sid=5350
SID SERIAL# SPID
---------- ---------- ------------------------------------------------
TRACEFILE
--------------------------------------------------------------------------------
5350 1620 15183
/oracle/db/diag/rdbms/prod/prod2/trace/prod2_ora_15183.trc
格式化trc文件
[oracle@rac2 ~]$ tkprof /oracle/db/diag/rdbms/prod/prod2/trace/prod2_ora_15183.trc 15183.txt sys=no;
TKPROF: Release 19.0.0.0.0 - Development on Mon Nov 29 16:10:33 2021
Copyright (c) 1982, 2019, Oracle and/or its affiliates. All rights reserved.
查看跟踪内容
[oracle@rac2 ~]$ cat 15183.txt | more
TKPROF: Release 19.0.0.0.0 - Development on Mon Nov 29 16:10:33 2021
Copyright (c) 1982, 2019, Oracle and/or its affiliates. All rights reserved.
Trace file: /oracle/db/diag/rdbms/prod/prod2/trace/prod2_ora_15183.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
SQL ID: g0ansbn0pgk07 Plan Hash: 3934648814
select *
from
test where object_name='TEST'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.01 4 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.02 4 2 0 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 108
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 TABLE ACCESS BY INDEX ROWID BATCHED TEST (cr=2 pr=4 pw=0 time=19944 us starts=1 cost=2 size=109 card=1)
0 0 0 INDEX RANGE SCAN IDX_TEST_NAME (cr=2 pr=4 pw=0 time=19941 us starts=1 cost=1 size=0 card=1)(object id 76166)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
gc cr multi block grant 1 0.00 0.00
db file scattered read 1 0.01 0.01
SQL*Net message from client 1 0.35 0.35
********************************************************************************
SQL ID: cwr1fsau6ybx3 Plan Hash: 1829724555
select object_name
from
test where object_name='TEST'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 108
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 INDEX RANGE SCAN IDX_TEST_NAME (cr=2 pr=0 pw=0 time=23 us starts=1 cost=1 size=15 card=1)(object id 76166)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 6.74 6.74
********************************************************************************
SQL ID: a47ds62d8bzrd Plan Hash: 2007178810
select *
from
test order by 1,2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 64 0.01 0.00 0 1393 0 940
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 66 0.01 0.01 0 1393 0 940
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 108
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
940 940 940 SORT ORDER BY (cr=1393 pr=0 pw=0 time=6690 us starts=1 cost=388 size=102460 card=940)
940 940 940 TABLE ACCESS FULL TEST (cr=1393 pr=0 pw=0 time=406 us starts=1 cost=387 size=102460 card=940)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 64 0.00 0.00
SQL*Net message from client 63 0.51 0.94
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.01 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 66 0.01 0.02 4 1397 0 940
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 72 0.02 0.03 4 1397 0 940
Misses in library cache during parse: 3
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 66 0.00 0.00
gc cr multi block grant 1 0.00 0.00
db file scattered read 1 0.01 0.01
SQL*Net message from client 65 6.74 8.04
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: /oracle/db/diag/rdbms/prod/prod2/trace/prod2_ora_15183.trc
Trace file compatibility: 12.2.0.0
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
255 lines in trace file.
8 elapsed seconds in trace file.
从中我们分析下面这条SQL执行慢
SQL ID: a47ds62d8bzrd Plan Hash: 2007178810
select *
from
test order by 1,2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 64 0.01 0.00 0 1393 0 940
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 66 0.01 0.01 0 1393 0 940
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 108
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
940 940 940 SORT ORDER BY (cr=1393 pr=0 pw=0 time=6690 us starts=1 cost=388 size=102460 card=940)
940 940 940 TABLE ACCESS FULL TEST (cr=1393 pr=0 pw=0 time=406 us starts=1 cost=387 size=102460 card=940)
可以对这个语句从业务，执行计划做进一步分析。
SQL> EXEC DBMS_MONITOR.session_trace_enable;
SQL> EXEC DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.session_trace_disable;
SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id=>1234, serial_num=>1234);
SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id =>1234, serial_num=>1234, waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.session_trace_disable(session_id=>1234, serial_num=>1234);
SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall');
SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall', waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.client_id_trace_disable(client_id=>'tim_hall');
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g', module_name=>'test_api', action_name=>'running');
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g', module_name=>'test_api', action_name=>'running', -
> waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_disable(service_name=>'db10g', module_name=>'test_api', action_name=>'running');
开启10053时间分析
相关文章