中午正在园区新餐厅吃饭（上图中楼），手表收到DB服务器CPU告警短信。回来登录数据库后，开始了诊断优化工作。
直接查看最消耗CPU SQL：
CWBZCDB2 2021-06-24 13:46:23 M|R|E|C|Q) Choose: tophis...RN SQL_ID CPU_S READS_K ETIME_S AVG_ELAP_MS AVG_BUF AVG_ROW EXECS MIN_SCHEMA SQLTEXT---- ------------- ---------- ---------- ---------- ----------- ---------- ---------- ---------- ---------- --------------------------------------------------1 cg0f9zwznd78h 154547 31 156457 156456857 1.2890E+10 0 0 REIMBURSE select * from ( select ma.vendor_id, ma.2 82hqd2snhd7g4 27283 0 28101 4947 532017 1 5681 REIMBURSE select count(t.pay_line_detail_id) from t_pay_line3 cuzt8bgg4fnz1 5328 26 5535 32945 3511932 1 168 REIMBURSE select (select count(1) from T_CLAIM_BASE tcb whe4 b9amakuv93aw9 4806 0 5086 130 19193 7.9 39132 REIMBURSE select auditconfi0_.ROLE_CODE as col_0_0_ from T_A5 6zf50gx0hcd0y 4086 0 4268 291 44271 1 14671 REIMBURSE select count(*) as col_0_0_ from T_CLAIM_ACCOUNT_O6 3jjv6ky4r2kr5 2944 0 3036 543 5249 2.6 5588 REIMBURSE with tmpcb as(select * from t_claim_base where pro7 f2sjf5yf5rfgg 2913 0 3054 133 12860 .1 22904 REIMBURSE select b.claim_no,(select u.user_name from USERMGR8 3afwy23qk1mwh 2654 0 2799 492 92541 1 5690 REIMBURSE select count(1) from t_pay_line_detail d where d.p9 0za9fv0j1vgkk 2651 2 2721 26942 201415 1 101 SYS WITH MONITOR_DATA AS (SELECT * FROM TABLE(GV$(CURS10 61p0hwvy3ukaz 2377 0 2473 778 96785 0 3180 REIMBURSE select ID, CLAIM_NO, MESSAGE_TYPE, APPLYCWBZCDB2 2021-06-24 13:46:37 M|R|E|C|Q) Choose:
定位到问题SQL为： cg0f9zwznd78h ,其CPU耗时为15W秒。
根据SQL ID查看执行计划：
CWBZCDB2 2021-06-24 13:46:37 M|R|E|C|Q) Choose: planSql plan info:Container Info:CON_ID NAME OPEN_MODE TOTAL_SIZE_MB---------- ------------------------- -------------------- -------------1 CDB$ROOT READ WRITE 02 PDB$SEED READ ONLY 8683 ZDCWBZDB READ WRITE 1937458Choose Container(default CDB$ROOT): ZDCWBZDBPlease input SQL_ID : cg0f9zwznd78hPlease input info level (ADVanced|TYPical default TYP): typical......Current SQL plans in Cursor:PLAN_TABLE_OUTPUT----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------SQL_ID cg0f9zwznd78h, child number 0-------------------------------------select * from ( select ma.vendor_id, ma.vendor_code,ma.vendor_name, ma.vendor_type,ma.expiry_date, md.is_validity,mb.comp_name, md.vendor_site_name,mc.vendor_account_name, mc.vendor_account_no,mc.bank_name, md.liability_account,md.advance_payment_account, mb.bu_code,mc.start_datefrom t_md_vendor mainner join t_Md_Vendor_Site md on ma.vendor_id = md.vendor_idleft join t_md_vendor_account mc on md.vendor_site_id =mc.vendor_site_idinner join t_md_ou mb on md.ou = mb.comp_codewhere 1 = 1and ma.vendor_name like :1order by ma.vendor_id)where rownum <= :2Plan hash value: 345991340---------------------------------------------------------------------------------------------------------------------| Id | Operation | Name | E-Rows |E-Bytes| Cost (%CPU)| E-Time |---------------------------------------------------------------------------------------------------------------------| 0 | SELECT STATEMENT | | | | 126K(100)| ||* 1 | COUNT STOPKEY | | | | | || 2 | VIEW | | 10 | 8200 | 126K (1)| 00:00:05 || 3 | NESTED LOOPS | | 10 | 2760 | 126K (1)| 00:00:05 || 4 | NESTED LOOPS | | 10 | 2760 | 126K (1)| 00:00:05 || 5 | NESTED LOOPS OUTER | | 10 | 2270 | 126K (1)| 00:00:05 || 6 | NESTED LOOPS | | 10 | 1510 | 126K (1)| 00:00:05 || 7 | TABLE ACCESS BY INDEX ROWID| T_MD_VENDOR_SITE | 10M| 964M | 61 (0)| 00:00:01 || 8 | INDEX FULL SCAN | IDX_T_MD_VENDOR_SITE_VENDOR_ID | 78 | | 3 (0)| 00:00:01 ||* 9 | TABLE ACCESS FULL | T_MD_VENDOR | 1 | 53 | 1669 (1)| 00:00:01 || 10 | TABLE ACCESS BY INDEX ROWID | T_MD_VENDOR_ACCOUNT | 1 | 76 | 4 (0)| 00:00:01 ||* 11 | INDEX RANGE SCAN | IDX_T_MD_VENDOR_SITE_VSD | 1 | | 2 (0)| 00:00:01 ||* 12 | INDEX RANGE SCAN | IDX_T_MD_OU_COMP_CODE | 1 | | 1 (0)| 00:00:01 || 13 | TABLE ACCESS BY INDEX ROWID | T_MD_OU | 1 | 49 | 2 (0)| 00:00:01 |---------------------------------------------------------------------------------------------------------------------Predicate Information (identified by operation id):---------------------------------------------------1 - filter(ROWNUM<=:2)9 - filter(("MA"."VENDOR_ID"="MD"."VENDOR_ID" AND "MA"."VENDOR_NAME" LIKE :1))11 - access("MD"."VENDOR_SITE_ID"="MC"."VENDOR_SITE_ID")12 - access("MD"."OU"="MB"."COMP_CODE")filter("MB"."COMP_CODE" IS NOT NULL)...Current Plans Summary(gv$sql):RN PLAN_HASH_VALUE AVG_ETIME_S AVG_CPU_S AVG_BUFFERS AVG_READS AVG_ROWS TOTAL_EXEC FIRST_LOAD_TIME LAST_ACTIVE---- --------------- ------------ ------------ ----------- ---------- ---------- ---------- -------------------- --------------------1 345991340 304066.064 302545.853 1842673033 22360 0 6 2021-06-16/10:39:54 2021-06-24 13:46:582 1822788838 383185.206 381736.215 1092246454 92994 1 7 2021-06-16/10:39:54 2021-06-24 13:46:58...CWBZCDB2 2021-06-24 13:47:21 M|R|E|C|Q) Choose:
发现执行计划id=6的Cost和E-time均发生了跳变。分析id=6的两个结果集，发现ID=9的全表扫描的位置非常可疑。
根据NESTED LOOPS的工作原理，可位置的全表扫的次数，取决于ID=7结果集的行数。而ID=7的E-ROWS为10M，说明根据预估值，ID=9的表实际全表扫100w次。
查看执行计划统计，发现从10点39以来，仅执行了13（6+3）次，单次耗时都非常长，达30w秒。
通常对于执行计划中的真实结果集大小，及循环体的循环次数，都通过执行计划的A-time来看。这里为了快捷直观，通过SQL Monitor Report查看。
CWBZCDB2 2021-06-24 13:47:21 M|R|E|C|Q) Choose: monsaveSave sql monitor report:Container Info:CON_ID NAME OPEN_MODE TOTAL_SIZE_MB---------- ------------------------- -------------------- -------------1 CDB$ROOT READ WRITE 02 PDB$SEED READ ONLY 8683 ZDCWBZDB READ WRITE 1937458Choose Container(default ZDCWBZDB):Please input one or more SQL_ID : cg0f9zwznd78hPlease input report type(TEXT|HTML default: TEXT) : TEXTcg0f9zwznd78h collecting...SQL Monitoring ReportSQL Text------------------------------select * from ( select ma.vendor_id, ma.vendor_code, ma.vendor_name, ma.vendor_type, ma.expiry_date, md.is_validity, mb.comp_name, md.vendor_site_name, mc.vendor_account_name, mc.vendor_account_no, mc.bank_name, md.liability_account, md.advance_payment_account, mb.bu_code, mc.start_date from t_md_vendor ma inner join t_Md_Vendor_Site md on ma.vendor_id = md.vendor_id left join t_md_vendor_account mc on md.vendor_site_id = mc.vendor_site_id inner join t_md_ou mb on md.ou = mb.comp_code where 1 =1 and ma.vendor_name like :1 order by ma.vendor_id ) where rownum <= :2Global Information------------------------------Status : EXECUTINGInstance ID : 2Session : REIMBURSE (3136:53240)SQL ID : cg0f9zwznd78hSQL Execution ID : 33554437Execution Started : 06/23/2021 17:06:19First Refresh Time : 06/23/2021 17:06:25Last Refresh Time : 06/24/2021 13:48:04Duration : 74497sModule/Action : JDBC Thin Client/-Service : zdcwbzdbProgram : JDBC Thin ClientBinds========================================================================================================================| Name | Position | Type | Value |========================================================================================================================| :1 | 1 | VARCHAR2(32) | %励致家私% || :2 | 2 | NUMBER | 10 |========================================================================================================================Global Stats============================================================================================| Elapsed | Cpu | IO | Concurrency | Cluster | Other | Buffer | Read | Read || Time(s) | Time(s) | Waits(s) | Waits(s) | Waits(s) | Waits(s) | Gets | Reqs | Bytes |============================================================================================| 74524 | 73826 | 6.49 | 0.14 | 15 | 677 | 7G | 5176 | 40MB |============================================================================================SQL Plan Monitoring Details (Plan Hash Value=345991340)================================================================================================================================================================================================| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Activity | Activity Detail || | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | (%) | (# samples) |================================================================================================================================================================================================| 0 | SELECT STATEMENT | | | | | | 1 | | | | | || 1 | COUNT STOPKEY | | | | | | 1 | | | | | || 2 | VIEW | | 10 | 127K | | | 1 | | | | | || 3 | NESTED LOOPS | | 10 | 127K | | | 1 | | | | | || 4 | NESTED LOOPS | | 10 | 127K | | | 1 | | | | | || 5 | NESTED LOOPS OUTER | | 10 | 127K | | | 1 | | | | | || -> 6 | NESTED LOOPS | | 10 | 127K | 74524 | +6 | 1 | 0 | | | | || -> 7 | TABLE ACCESS BY INDEX ROWID | T_MD_VENDOR_SITE | 10M | 61 | 74524 | +6 | 1 | 1M | 2394 | 19MB | 0.06 | gc current block 2-way (1) || | | | | | | | | | | | | Cpu (2) || | | | | | | | | | | | | db file sequential read (3) || -> 8 | INDEX FULL SCAN | IDX_T_MD_VENDOR_SITE_VENDOR_ID | 78 | 3 | 74524 | +6 | 1 | 1M | 1971 | 15MB | | || -> 9 | TABLE ACCESS FULL | T_MD_VENDOR | 1 | 1669 | 74524 | +6 | 1M | 0 | 811 | 6MB | 99.94 | Cpu (10425) || | | | | | | | | | | | | resmgr:cpu quantum (10) || 10 | TABLE ACCESS BY INDEX ROWID | T_MD_VENDOR_ACCOUNT | 1 | 4 | | | | | | | | || 11 | INDEX RANGE SCAN | IDX_T_MD_VENDOR_SITE_VSD | 1 | 2 | | | | | | | | || 12 | INDEX RANGE SCAN | IDX_T_MD_OU_COMP_CODE | 1 | 1 | | | | | | | | || 13 | TABLE ACCESS BY INDEX ROWID | T_MD_OU | 1 | 2 | | | | | | | | |================================================================================================================================================================================================cg0f9zwznd78h collect complete. stored in op_mon_current_cg0f9zwznd78h.txtCWBZCDB2 2021-06-24 13:48:29 M|R|E|C|Q) Choose:
根据展示的SQL 报告，我们能更加直观的发现问题所在，ID=9处的全表扫活动量，占据整个SQL的99.94%，在还未执行完成的情况下，Buffer Gets已经达到7G。
此时回头来分析执行计划ID=10处的过滤关联条件。
10 - filter(("MA"."VENDOR_ID"="MD"."VENDOR_ID" AND "MA"."VENDOR_NAME" LIKE :1))
在这一步，进行了like过滤，以及关联条件的关联处理。
查看该表的详细信息：
CWBZCDB2 2021-06-24 13:48:29 M|R|E|C|Q) Choose: table......***********Table Info***********Size：OWNER SEGMENT_NAME SIZE_GB------------------------------ ---------------------------------------- ----------REIMBURSE T_MD_VENDOR .046875Hight water：OWNER TABLE_NAME TAB_SIZE_MB USED_PCT PCT REAL_SPACE_MB------------------------------ ------------------------------ ----------- -------- ---------- -------------REIMBURSE T_MD_VENDOR 48 77 23.4107169 36.7508888Statistics：TABLE_NAME NUM_ROWS BLOCKS EMPTY_BLOCKS AVG_SPACE CHAIN_CNT AVG_ROW_LEN GLO USE SAMPLE_SIZE LAST_ANALYZED------------------------------ ---------- ---------- ------------ ---------- ---------- ----------- --- --- ----------- -------------------T_MD_VENDOR 385361 6142 0 0 0 100 YES NO 385361 2021-06-24 13:00:55Column:COLUMN_NAME COL NUM_DISTINCT DENSITY NUM_BUCKETS NUM_NULLS GLO USE SAMPLE_SIZE LAST_ANALYZED------------------------------ ---------------------------------------- ------------ ---------- ----------- ---------- --- --- ----------- -------------------VENDOR_ID NUMBER(22) NOT NULL 385361 0 1 0 YES NO 385361 2021-06-24 13:00:55......Indexes:INDEX_NAME UNIQUENES BLEV LEAF_BLOCKS DISTINCT_KEYS NUM_ROWS AVG_LEAF_BLOCKS_PER_KEY AVG_DATA_BLOCKS_PER_KEY CLUSTERING_FACTOR GLO USE SAMPLE_SIZE LAST_ANALYZED------------------------------ --------- ---------- ----------- ------------- ---------- ----------------------- ----------------------- ----------------- --- --- ----------- -------------------IDX_VENDOR_CODE NONUNIQUE 2 1019 379904 385361 1 1 261762 YES NO 385361 2021-06-24 13:00:57IDX_VD_EMPLOYEE_NO NONUNIQUE 2 528 182800 186782 1 1 133958 YES NO 186782 2021-06-24 13:00:57Index columns:INDEX_NAME COLUMN_NAME COLUMN_POSITION COL------------------------------ ------------------------------ --------------- ----------------------------------------IDX_VD_EMPLOYEE_NO EMPLOYEE_NO 1 VARCHAR2(30)IDX_VENDOR_CODE VENDOR_CODE 1 VARCHAR2(20)...CWBZCDB2 2021-06-24 13:53:15 M|R|E|C|Q) Choose:
发现关联列vendor_id列缺少索引，导致对该表（48Mb)进行了百万次的全表扫。
嵌套循环的一种最佳使用场景就是小表（结果集）与大表关联，小表作为驱动表，对大表走索引快速扫描等索引扫描方式，提升循环速度。
本案例中，快速解决该问题的方法就是在ID=9的T_MD_VENDOR表的关联列vendor_id创建索引。
查看创建索引后的执行计划：
Plan hash value: 1132081306--------------------------------------------------------------------------------------------------------------------| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |--------------------------------------------------------------------------------------------------------------------| 0 | SELECT STATEMENT | | | | 62 (100)| || 1 | COUNT STOPKEY | | | | | || 2 | VIEW | | 11 | 9020 | 62 (0)| 00:00:01 || 3 | NESTED LOOPS | | 11 | 3036 | 62 (0)| 00:00:01 || 4 | NESTED LOOPS | | 11 | 3036 | 62 (0)| 00:00:01 || 5 | NESTED LOOPS OUTER | | 11 | 2497 | 40 (0)| 00:00:01 || 6 | NESTED LOOPS | | 11 | 1661 | 16 (0)| 00:00:01 || 7 | TABLE ACCESS BY INDEX ROWID| T_MD_VENDOR | 19268 | 997K| 5 (0)| 00:00:01 || 8 | INDEX FULL SCAN | T_MD_VENDOR_IDX1 | 20 | | 3 (0)| 00:00:01 || 9 | TABLE ACCESS BY INDEX ROWID| T_MD_VENDOR_SITE | 11 | 1078 | 11 (0)| 00:00:01 || 10 | INDEX RANGE SCAN | IDX_T_MD_VENDOR_SITE_VENDOR_ID | 11 | | 2 (0)| 00:00:01 || 11 | TABLE ACCESS BY INDEX ROWID | T_MD_VENDOR_ACCOUNT | 1 | 76 | 4 (0)| 00:00:01 || 12 | INDEX RANGE SCAN | IDX_T_MD_VENDOR_SITE_VSD | 1 | | 2 (0)| 00:00:01 || 13 | INDEX RANGE SCAN | IDX_T_MD_OU_COMP_CODE | 1 | | 1 (0)| 00:00:01 || 14 | TABLE ACCESS BY INDEX ROWID | T_MD_OU | 1 | 49 | 2 (0)| 00:00:01 |--------------------------------------------------------------------------------------------------------------------
创建索引后，由于访问T_MD_VENDOR变得高效，数据库自动将其作为驱动表，从而进一步提升了执行效率。
Current Plans Summary(gv$sql):RN PLAN_HASH_VALUE AVG_ETIME_S AVG_CPU_S AVG_BUFFERS AVG_READS AVG_ROWS TOTAL_EXEC FIRST_LOAD_TIME LAST_ACTIVE---- --------------- ------------ ------------ ----------- ---------- ---------- ---------- -------------------- --------------------1 1132081306 0.098 0.083 7040 0 8 4 2021-06-16/10:44:41 2021-06-24 14:46:212 345991340 307747.059 306298.545 578811674 51928 0 2 2021-06-16/10:44:41 2021-06-24 15:24:073 1822788838 326942.725 325527.045 705746716 84856 1 5 2021-06-16/10:44:41 2021-06-24 15:24:07
优化后的执行计划平均耗时仅需0.098s，相较原始的30w秒，妥妥的提升了500w倍。
通过查看TOP CPU进程对应的SQL，确认这些进程均指向了该SQL。
CWBZCDB2 2021-06-24 15:03:54 M|R|E|C|Q) Choose: spidOS top cpu and mem process:Top CPU process:-------------------------------------------------------------------------------------------------USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMANDoracle 34350 99.4 0.0 43465808 41192 ? Rs Jun18 8535:12 oracleCWBZCDB2 (LOCAL=NO)oracle 10930 99.4 0.0 43467876 42580 ? Rs Jun18 8470:09 oracleCWBZCDB2 (LOCAL=NO)oracle 57351 99.3 0.0 43499676 45684 ? Rs Jun18 8598:17 oracleCWBZCDB2 (LOCAL=NO)oracle 6697 99.0 0.0 43465596 37324 ? Rs Jun22 2661:41 oracleCWBZCDB2 (LOCAL=NO)oracle 60501 98.9 0.0 43465812 41456 ? Rs Jun23 1304:10 oracleCWBZCDB2 (LOCAL=NO)oracle 44622 96.7 0.0 43470992 40900 ? Rs 13:56 65:02 oracleCWBZCDB2 (LOCAL=NO)oracle 13567 40.3 0.0 43472664 50548 ? Ss 14:57 2:24 oracleCWBZCDB2 (LOCAL=NO)oracle 9567 37.0 0.0 43470616 48972 ? Ss 14:51 4:35 oracleCWBZCDB2 (LOCAL=NO)oracle 11448 36.3 0.0 43467884 45212 ? Ss 14:54 3:24 oracleCWBZCDB2 (LOCAL=NO)oracle 16735 32.5 0.0 43467252 33928 ? Ss 15:03 0:07 oracleCWBZCDB2 (LOCAL=NO)Please input one or more Spid : 34350 10930 57351 6697 60501 44622cg0f9zwznd78h...
在与业务沟通后，由于属于应用中管理员使用的模块，决定对其查杀。查杀后数据库负载从80%降低到正常水平。
该案例主要考察DBA对嵌套循环机索引的灵活使用。会正确使用索引，便会解决绝大多数事务型数据库的性能问题。
更多技术细节，欢迎关注公众号联系作者交流。
关注更多精彩
文章转载自MeetDB，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。
