Oracle开发者性能课第9课（如何查找慢 SQL）实验
Posted dingdingfish
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了Oracle开发者性能课第9课（如何查找慢 SQL）实验相关的知识，希望对你有一定的参考价值。
概述
本实验参考DevGym中的实验指南。
创建环境
创建表和过程，其中我加了注释：
create table schools (
school_id integer not null primary key,
school_name varchar2(30) not null
);
create table students (
student_id integer not null primary key,
parent_id integer not null,
school_id integer not null
);
create table school_attendance (
school_id
references schools ( school_id ) not null,
student_id
references students ( student_id ) not null,
primary key (
school_id, student_id
)
);
create or replace procedure init as
num_students constant pls_integer := 5000;
begin
delete school_attendance;
delete schools;
delete students;
insert into students
with rws as (
select level student_id,
mod ( level, ( num_students / 2 ) ) + 1 parent_id,
mod ( level, 5 ) + 1 school_id
from dual
connect by level <= num_students
)
select * from rws;
insert into schools values ( 1, 'Java Junior' );
insert into schools values ( 2, 'Haskell High' );
insert into schools values ( 3, 'SQL School' );
insert into schools values ( 4, 'C College' );
insert into schools values ( 5, 'Ada Academy' );
commit;
end init;
/
exec init();
查看数据：
-- 有5个学校
SQL> select * from schools;
SCHOOL_ID SCHOOL_NAME
____________ _______________
1 Java Junior
2 Haskell High
3 SQL School
4 C College
5 Ada Academy
-- 5000个学生
SQL> select * from students where rownum < 10;
STUDENT_ID PARENT_ID SCHOOL_ID
_____________ ____________ ____________
921 922 2
922 923 3
923 924 4
924 925 5
925 926 1
926 927 2
927 928 3
928 929 4
929 930 5
9 rows selected.
SQL> select count(*) from students;
COUNT(*)
___________
5000
SQL> select count(*) from school_attendance;
COUNT(*)
___________
0
简介
到目前为止，本系列中的教程都侧重于调优单个 SQL 语句。但通常你需要分析才能找出最慢的 SQL ！
为此，您需要分析在“数据库运行缓慢”时运行的代码。这将捕获运行客户抱怨的SQL语句的会话时的详细执行信息。
本教程介绍了 Oracle 数据库中的工具，以帮助您分析 SQL 和 PL/SQL 执行情况。
创建要跟踪的程序
创建此过程以添加学校的学生出勤条目：
create or replace procedure drop_off_students (
school integer
) as
att_count pls_integer;
begin
for studs in (
select student_id
from students
where school_id = school
) loop
select count (*) into att_count
from school_attendance
where student_id = studs.student_id
and school_id = school;
if att_count = 0 then
insert into school_attendance ( student_id, school_id )
values ( studs.student_id, school );
end if;
end loop;
end drop_off_students;
/
create or replace procedure start_school as
begin
for s in (
select school_id from schools
) loop
drop_off_students ( s.school_id );
end loop;
end start_school;
/
跟踪 SQL 执行
要捕获会话中所有语句的 SQL 执行详细信息，您可以运行 SQL Trace。使用 DBMS_monitor.session_trace_enable 执行此操作：
exec sys.dbms_monitor.session_trace_enable ( waits => true, binds => true );
exec start_school ();
exec sys.dbms_monitor.session_trace_disable ();
以上将产生Trace文件。
访问SQL Trace文件
SQL Trace文件位于数据库服务器。
或者也可以用SQL访问系统视图V$DIAG_TRACE_FILE_CONTENTS:
set lines 200
set serveroutput off
set pagesize 0
set echo off
set feedback off
set trimspool on
set heading off
set tab off
spool /tmp/trace-file.trc
select payload
from v$diag_trace_file_contents
where trace_filename = (
select substr (
value,
instr ( value, '/', -1 ) + 1
) filename
from v$diag_info
where name = 'Default Trace File'
)
order by line_number;
spool off
需要删除输出文件头部和尾部记录的SQL语句
格式化 SQL Trace文件
SQL Trace文件一般都比较大，注意文件头部有trace文件的具体位置：
$ wc -l /tmp/trace-file.trc
85185 /tmp/trace-file.trc
$ more trace-file.trc
Trace file /opt/oracle/diag/rdbms/orclcdb/ORCLCDB/trace/ORCLCDB_ora_24406.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.11.0.0.0
Build label: RDBMS_19.11.0.0.0DBRU_LINUX.X64_210412
ORACLE_HOME: /opt/oracle/product/19c/dbhome_1
System name: Linux
Node name: oracle-19c-vagrant
Release: 5.4.17-2102.202.5.el7uek.x86_64
Version: #2 SMP Sat May 22 16:17:06 PDT 2021
Machine: x86_64
Instance name: ORCLCDB
Redo thread mounted by this instance: 1
Oracle process number: 29
Unix process pid: 24406, image: oracle@oracle-19c-vagrant
*** 2021-10-30T21:39:19.697766+08:00 (ORCLPDB1(3))
*** SESSION ID:(264.23699) 2021-10-30T21:39:19.697789+08:00
*** CLIENT ID:() 2021-10-30T21:39:19.697793+08:00
*** SERVICE NAME:(orclpdb1) 2021-10-30T21:39:19.697795+08:00
*** MODULE NAME:(SQL*Plus) 2021-10-30T21:39:19.697798+08:00
*** ACTION NAME:() 2021-10-30T21:39:19.697800+08:00
*** CLIENT DRIVER:(SQL*PLUS) 2021-10-30T21:39:19.697802+08:00
*** CONTAINER ID:(3) 2021-10-30T21:39:19.697804+08:00
=====================
PARSING IN CURSOR #140298864054008 len=83 dep=0 uid=113 oct=47 lid=113 tim=42004037595 hv=666663546 ad='b8aa1b90' sqlid='575acgwmvsymu'
BEGIN sys.dbms_monitor.session_trace_enable ( waits => true, binds => true ); END;
...
需要格式化使其易读：
cd /tmp
tkprof trace-file.trc trace-file.txt
格式化后居然只有200多行了：
$ wc -l trace-file.txt
215 trace-file.txt
$ cat trace-file.txt
TKPROF: Release 19.0.0.0.0 - Development on Sat Oct 30 21:41:11 2021
Copyright (c) 1982, 2019, Oracle and/or its affiliates. All rights reserved.
Trace file: trace-file.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: 575acgwmvsymu Plan Hash: 0
BEGIN sys.dbms_monitor.session_trace_enable ( waits => true, binds => true );
END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 113
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 0.17 0.17
********************************************************************************
SQL ID: bu5kprjcz46js Plan Hash: 0
BEGIN start_school (); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.09 0.10 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.09 0.10 0 0 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 113
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 0.61 0.61
********************************************************************************
SQL ID: 87rppdhxpw693 Plan Hash: 1367354807
SELECT SCHOOL_ID
FROM
SCHOOLS
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 4 0 5
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 4 0 5
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 113 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
5 5 5 INDEX FAST FULL SCAN SYS_C008677 (cr=4 pr=0 pw=0 time=60 us starts=1 cost=2 size=13 card=1)(object id 75943)
********************************************************************************
SQL ID: 35sscdb8ca6uh Plan Hash: 4078133427
SELECT STUDENT_ID
FROM
STUDENTS WHERE SCHOOL_ID = :B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 5 0.00 0.00 0 0 0 0
Fetch 55 0.00 0.00 0 129 0 5000
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 61 0.00 0.00 0 129 0 5000
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 113 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1000 1000 1000 TABLE ACCESS FULL STUDENTS (cr=25 pr=0 pw=0 time=164 us starts=1 cost=5 size=26000 card=1000)
********以上是关于Oracle开发者性能课第9课（如何查找慢 SQL）实验的主要内容，如果未能解决你的问题，请参考以下文章