绑定完请刷新页面
取消
刷新

分享好友

×
取消 复制
通过DBMS_MONITOR.session_trace_enable开启会话跟踪
2021-11-29 16:16:39


在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时间分析


分享好友

分享这个小栈给你的朋友们,一起进步吧。

Oracle运维新鲜事-技术与管理各占半边天
创建时间:2020-08-04 11:34:57
本技术栈旨在分享技术心得,运维趣事,故障处理经验,调优案例,故障处理涉及集群,DG,OGG,大家生产中遇到的问题基本都会囊括了,我会发布生产库遇到的故障,希望在交流中互助互益,共同提高,也希望大家讨论,如果您有生产中遇到的集群问题,也可以在这里提出来,一起讨论,现实中也帮助不少同学解决了生产库的故障。
展开
订阅须知

• 所有用户可根据关注领域订阅专区或所有专区

• 付费订阅:虚拟交易,一经交易不退款;若特殊情况,可3日内客服咨询

• 专区发布评论属默认订阅所评论专区(除付费小栈外)

栈主、嘉宾

查看更多
  • Abraham林老师
    栈主
  • 小雨滴
    嘉宾
  • hawkliu
    嘉宾
  • u_97a59a25246404
    嘉宾

小栈成员

查看更多
  • 栈栈
  • dapan
  • 小菜鸟___
  • hwayw
戳我,来吐槽~