某客戶每天凌晨會(huì)有根據(jù)前一日分區(qū)，多表關(guān)連生成臨時(shí)表（CTAS ）批量SQL任務(wù)， 數(shù)據(jù)量每天相差并不大，平時(shí)時(shí)間也基本相同，此次同一批次中的1個(gè)SQL 運(yùn)行時(shí)間從原來半小時(shí)左右增加了近3個(gè)小時(shí)，最終是SQL的table創(chuàng)建成功，需要分析當(dāng)時(shí)的原因。環(huán)境oracle 11g 4-node RAC on Linux

分析

這類問題通常可以從以下幾個(gè)方面分析

• system load
• wait event
• session statistics
• process callstack

GV$ ASH 記錄

確認(rèn)是否有采集快照缺失

SQL> select inst_id,min(sample_time) starttime,max(sample_time)endtime,count(distinct sample_time) snaps from ash0709 group by inst_id;

   INST_ID STARTTIME                    ENDTIME                           SNAPS
---------- ---------------------------- ---------------------------- ----------
         1 09-JUL-22 05.00.00.361 AM    09-JUL-22 08.54.07.608 AM         12298
         2 09-JUL-22 05.00.00.904 AM    09-JUL-22 08.54.07.716 AM         13837
         4 09-JUL-22 05.00.00.784 AM    09-JUL-22 08.54.08.038 AM         13948
         3 09-JUL-22 05.00.00.249 AM    09-JUL-22 08.54.08.085 AM         13948


select inst_id,extract (hour from sample_time) hh,min(sample_time) starttime,max(sample_time)endtime,count(distinct sample_time) snaps 
from ash0709 
group by inst_id,extract (hour from sample_time)
order by 1,2;

   INST_ID         HH STARTTIME                    ENDTIME                           SNAPS
---------- ---------- ---------------------------- ---------------------------- ----------
         1          5 09-JUL-22 05.00.00.361 AM    09-JUL-22 05.59.59.015 AM          3485
         1          6 09-JUL-22 06.00.00.025 AM    09-JUL-22 06.59.59.212 AM          3557
         1          7 09-JUL-22 07.00.00.222 AM    09-JUL-22 07.59.57.066 AM          2601
         1          8 09-JUL-22 08.00.01.116 AM    09-JUL-22 08.54.07.608 AM          2655
         2          5 09-JUL-22 05.00.00.904 AM    09-JUL-22 05.59.59.274 AM          3551
         2          6 09-JUL-22 06.00.00.284 AM    09-JUL-22 06.59.59.251 AM          3550
         2          7 09-JUL-22 07.00.00.261 AM    09-JUL-22 07.59.59.964 AM          3551
         2          8 09-JUL-22 08.00.00.964 AM    09-JUL-22 08.54.07.716 AM          3185
         3          5 09-JUL-22 05.00.00.249 AM    09-JUL-22 05.59.59.458 AM          3575
         3          6 09-JUL-22 06.00.00.468 AM    09-JUL-22 06.59.59.461 AM          3574
         3          7 09-JUL-22 07.00.00.461 AM    09-JUL-22 07.59.59.823 AM          3574
         3          8 09-JUL-22 08.00.00.833 AM    09-JUL-22 08.54.08.085 AM          3225
         4          5 09-JUL-22 05.00.00.784 AM    09-JUL-22 05.59.59.692 AM          3575
         4          6 09-JUL-22 06.00.00.692 AM    09-JUL-22 06.59.59.039 AM          3573
         4          7 09-JUL-22 07.00.00.039 AM    09-JUL-22 07.59.59.268 AM          3574
         4          8 09-JUL-22 08.00.00.268 AM    09-JUL-22 08.54.08.038 AM          3226

-- 檢查SQL運(yùn)行時(shí)長(zhǎng)
select inst_id,sql_id,min(sample_time) starttime,max(sample_time)endtime,max(sample_time)-min(sample_time) during
 from  ash0709 where SQL_PLAN_HASH_VALUE=2391750817 group by inst_id,sql_id
  3  order by 2,3;

   INST_ID SQL_ID        STARTTIME                    ENDTIME                      DURING
---------- ------------- ---------------------------- ---------------------------- ---------------------------------------------------------------------------
         1 0h31pzh4m1rxb 09-JUL-22 05.43.32.089 AM    09-JUL-22 06.15.26.468 AM    +000000000 00:31:54.379
         2 0h31pzh4m1rxb 09-JUL-22 05.44.50.881 AM    09-JUL-22 06.15.36.270 AM    +000000000 00:30:45.389
         1 3zr5yfq5039dx 09-JUL-22 05.43.27.019 AM    09-JUL-22 06.27.40.978 AM    +000000000 00:44:13.959
         3 3zr5yfq5039dx 09-JUL-22 05.44.50.880 AM    09-JUL-22 06.27.34.010 AM    +000000000 00:42:43.130
         4 3zr5yfq5039dx 09-JUL-22 05.44.51.678 AM    09-JUL-22 06.27.40.259 AM    +000000000 00:42:48.581
         1 4005sxkg5ag51 09-JUL-22 05.43.14.929 AM    09-JUL-22 06.03.02.400 AM    +000000000 00:19:47.471    
         1 48cbmz2htvjg7 09-JUL-22 05.43.27.019 AM    09-JUL-22 06.15.36.578 AM    +000000000 00:32:09.559
         2 48cbmz2htvjg7 09-JUL-22 05.44.50.881 AM    09-JUL-22 06.15.46.650 AM    +000000000 00:30:55.769
         1 4hff619j0w11m 09-JUL-22 05.43.38.129 AM    09-JUL-22 06.15.01.222 AM    +000000000 00:31:23.093
         4 4hff619j0w11m 09-JUL-22 05.44.51.678 AM    09-JUL-22 06.15.06.303 AM    +000000000 00:30:14.625
         1 888n9jcb93krn 09-JUL-22 05.43.37.129 AM    09-JUL-22 06.24.18.718 AM    +000000000 00:40:41.589
         3 888n9jcb93krn 09-JUL-22 05.44.50.880 AM    09-JUL-22 06.24.06.478 AM    +000000000 00:39:15.598
         2 888n9jcb93krn 09-JUL-22 05.44.50.881 AM    09-JUL-22 06.24.18.516 AM    +000000000 00:39:27.635
         1 8f9vpq05nzf5b 09-JUL-22 05.43.36.119 AM    09-JUL-22 06.24.05.598 AM    +000000000 00:40:29.479
         3 8f9vpq05nzf5b 09-JUL-22 05.44.50.880 AM    09-JUL-22 06.23.56.418 AM    +000000000 00:39:05.538
         2 8f9vpq05nzf5b 09-JUL-22 05.44.50.881 AM    09-JUL-22 06.24.05.366 AM    +000000000 00:39:14.485
         1 8wcnndfapzzn9 09-JUL-22 05.43.14.929 AM    09-JUL-22 07.16.47.932 AM    +000000000 01:33:33.003    
         4 8wcnndfapzzn9 09-JUL-22 05.44.51.678 AM    09-JUL-22 08.28.10.860 AM    +000000000 02:43:19.182
         3 8wcnndfapzzn9 09-JUL-22 05.44.52.890 AM    09-JUL-22 08.28.11.872 AM    +000000000 02:43:18.982
         1 bhw9ycm20dw48 09-JUL-22 05.43.38.129 AM    09-JUL-22 05.44.50.089 AM    +000000000 00:01:11.960
         3 bhw9ycm20dw48 09-JUL-22 05.44.50.880 AM    09-JUL-22 06.18.46.183 AM    +000000000 00:33:55.303
         4 bhw9ycm20dw48 09-JUL-22 05.44.51.678 AM    09-JUL-22 06.18.41.011 AM    +000000000 00:33:49.333
         1 dm6wgxdcs73w1 09-JUL-22 05.43.31.079 AM    09-JUL-22 06.13.21.972 AM    +000000000 00:29:50.893
         4 dm6wgxdcs73w1 09-JUL-22 05.44.51.678 AM    09-JUL-22 06.13.17.478 AM    +000000000 00:28:25.800

NOTE:
因?yàn)槊刻炫幚鞢TAS的執(zhí)行計(jì)劃一樣，只是分區(qū)名區(qū)別，可以看到同批次8wcnndfapzzn9 SQLID的運(yùn)行時(shí)間近3小時(shí)，其它都在30分鐘左右， 并且同一個(gè)sql ID是跨實(shí)例運(yùn)行，說明SQL使用了parallel， 并且parallel force local應(yīng)該是false。從現(xiàn)場(chǎng)得知調(diào)度都是連接實(shí)例1發(fā)起，部分SQL parallel slave process跨節(jié)點(diǎn)完成。 這種部署方式是不建議的，建議以其它業(yè)務(wù)維度分解單SQL任務(wù)在多個(gè)實(shí)例上，每個(gè)實(shí)例并行只在本節(jié)點(diǎn)完成，減少跨節(jié)點(diǎn)的調(diào)度，從上面可以看出SQL ID 4005sxkg5ag51 只在node1 完成，并且是用時(shí)最短。

 分析問題SQL 8wcnndfapzzn9

-- 時(shí)間消耗的執(zhí)行計(jì)劃
 select  inst_id, IS_SQLID_CURRENT,SQL_PLAN_HASH_VALUE,SQL_PLAN_LINE_ID,SQL_PLAN_OPERATION,count(*) es_sec
-- ,SQL_EXEC_ID,SQL_EXEC_START,
-- QC_INSTANCE_ID,QC_SESSION_ID,SEQ# ,
-- SESSION_STATE,TIME_WAITED,BLOCKING_SESSION,
-- CURRENT_OBJ# ,CURRENT_FILE# ,CURRENT_BLOCK# ,
-- TOP_LEVEL_CALL_NAME,IN_PARSE,IN_SQL_EXECUTION,event, time_waited/1000 threshold_in_ms,
-- DELTA_READ_IO_REQUESTS,DELTA_READ_IO_BYTES,PGA_ALLOCATED,TEMP_SPACE_ALLOCATED
 from ash0709
 where sql_id='8wcnndfapzzn9'
 group by inst_id, IS_SQLID_CURRENT,SQL_PLAN_HASH_VALUE,SQL_PLAN_LINE_ID,SQL_PLAN_OPERATION
 11   order by 6 desc;

   INST_ID I SQL_PLAN_HASH_VALUE SQL_PLAN_LINE_ID SQL_PLAN_OPERATION                 ES_SEC
---------- - ------------------- ---------------- ------------------------------ ----------
         3 Y          2391750817               36 TABLE ACCESS                         8931

   INST_ID I SQL_PLAN_HASH_VALUE SQL_PLAN_LINE_ID SQL_PLAN_OPERATION                 ES_SEC
---------- - ------------------- ---------------- ------------------------------ ----------
         4 Y          2391750817               36 TABLE ACCESS                         8441
           Y          2391750817               34 PX SEND                               224
           Y          2391750817               28 HASH JOIN                             195

   INST_ID I SQL_PLAN_HASH_VALUE SQL_PLAN_LINE_ID SQL_PLAN_OPERATION                 ES_SEC
---------- - ------------------- ---------------- ------------------------------ ----------
         3 Y          2391750817               28 HASH JOIN                             173

  select  -- inst_id, IS_SQLID_CURRENT,SQL_PLAN_HASH_VALUE,SQL_PLAN_LINE_ID,SQL_PLAN_OPERATION,count(*) es_sec
 SQL_EXEC_ID,SQL_EXEC_START, count(*) es_sec
-- QC_INSTANCE_ID,QC_SESSION_ID,SEQ# ,
-- SESSION_STATE,TIME_WAITED,BLOCKING_SESSION,
-- CURRENT_OBJ# ,CURRENT_FILE# ,CURRENT_BLOCK# ,
-- TOP_LEVEL_CALL_NAME,IN_PARSE,IN_SQL_EXECUTION,event, time_waited/1000 threshold_in_ms,
-- DELTA_READ_IO_REQUESTS,DELTA_READ_IO_BYTES,PGA_ALLOCATED,TEMP_SPACE_ALLOCATED
 from ash0709
 where sql_id='8wcnndfapzzn9'
 group by SQL_EXEC_ID,SQL_EXEC_START
 11   order by 3 desc;

SQL_EXEC_ID SQL_EXEC_START          ES_SEC
----------- ------------------- ----------
   16777216 2022-07-09 05:43:17      19033
                                         3

note
最耗時(shí)的是執(zhí)行計(jì)劃的36# full table scan. 消耗近90%, SQL并且確認(rèn)運(yùn)行了一次。

SQL MONITOR

SQL Plan Monitoring Details (Plan Hash Value=2391750817)
=========================================================================================================================================================================================================================================
| Id |               Operation               |             Name             |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read  | Read  | Write | Write |  Mem  | Temp  | Activity |           Activity Detail            |
|    |                                       |                              | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs  | Bytes | Reqs  | Bytes | (Max) | (Max) |   (%)    |             (# samples)              |
=========================================================================================================================================================================================================================================
|  0 | CREATE TABLE STATEMENT                |                              |         |       |      2138 |  +6712 |     5 |        2 |       |       |       |       |       |       |     0.01 | Cpu (1)                              |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | enq: TT - contention (1)             |
|  1 |   PX COORDINATOR                      |                              |         |       |      8849 |     +1 |     5 |        2 |       |       |       |       |       |       |     0.02 | enq: KO - fast object checkpoint (2) |
...
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | direct path read (44)                |
| 33 |               PX RECEIVE              |                              |    305M |  514K |      8231 |   +111 |     2 |     428M |       |       |       |       |       |       |     0.39 | Cpu (66)                             |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | PX Deq: reap credit (3)              |
| 34 |                PX SEND HASH           | :TQ10005                     |    305M |  514K |      8521 |   +111 |     2 |     428M |       |       |       |       |       |       |     1.46 | Cpu (254)                            |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | PX Deq: reap credit (5)              |
| 35 |                 PX PARTITION LIST ALL |                              |    305M |  514K |      8521 |   +111 |     2 |     428M |       |       |       |       |       |       |     0.31 | Cpu (55)                             |
| 36 |                  TABLE ACCESS FULL    | MID_xxx_xxx_xxx_DAY          |    305M |  514K |      8522 |   +110 | 14355 |     428M |  227K | 211GB |       |       |       |       |    89.99 | gc cr block lost (1)                 |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | gc cr grant 2-way (5)                |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | gc cr multi block request (4)        |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | gc current block 2-way (1)           |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | gc current block 3-way (1)           |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | Cpu (15228)                          |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | db file scattered read (13)          |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | db file sequential read (49)         |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | direct path read (656)               |
|    |                                       |                              |         |       |           |        |       |          |       |       |       |       |       |       |          | read by other session (6)            |
=========================================================================================================================================================================================================================================

Global Stats
====================================================================================================================================
| Elapsed |   Cpu   |    IO    | Application | Concurrency | Cluster  | PL/SQL  |  Other   | Buffer | Read | Read  | Write | Write |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Time(s) | Waits(s) |  Gets  | Reqs | Bytes | Reqs  | Bytes |
====================================================================================================================================
|   17934 |    1367 |     1285 |        0.40 |        0.15 |       12 |    0.01 |    15269 |     7M | 263K | 224GB | 33481 |  10GB |
====================================================================================================================================

note: 從SQLmonitor中的 buffer gets比平時(shí)并未增加，時(shí)間是消耗在other waits.

OS 負(fù)載

----system---- ----total-cpu-usage---- -dsk/total- -net/total- ------memory-usage----- ----swap--- ---load-avg---
     time     |usr sys idl wai hiq siq| read  writ| recv  send| used  buff  cach  free| used  free| 1m   5m  15m
08-07 05:59:09|  2   2  89   6   0   0|1169M 2917M|  18M   33M| 155G 1213M  267G  587G|   0    17G|21.2 21.8 21.6
08-07 05:59:10|  3   2  93   1   0   0|2908M  200M|  14M   23M| 155G 1213M  267G  587G|   0    17G|21.2 21.8 21.6
08-07 05:59:11|  3   2  94   1   0   0|1650M  136M|9809k   15M| 155G 1213M  267G  587G|   0    17G|20.9 21.7 21.6
08-07 05:59:12|  3   1  94   1   0   0|2287M  368M|  34M   59M| 155G 1213M  267G  587G|   0    17G|20.9 21.7 21.6
08-07 05:59:13|  3   2  93   2   0   0|3091M  296M|  12M   25M| 155G 1213M  267G  587G|   0    17G|20.9 21.7 21.6
08-07 05:59:14|  3   2  94   1   0   0|1632M  168M|  17M   32M| 155G 1213M  267G  587G|   0    17G|20.9 21.7 21.6
08-07 05:59:15|  3   2  94   1   0   0|2370M  363M|  20M   38M| 155G 1213M  267G  587G|   0    17G|20.6 21.6 21.6
08-07 05:59:16|  3   2  94   1   0   0|2408M  153M|  11M   20M| 155G 1213M  267G  587G|   0    17G|20.6 21.6 21.6
08-07 05:59:17|  3   2  94   1   0   0|1492M  149M|  23M   27M| 155G 1213M  267G  587G|   0    17G|20.6 21.6 21.6
08-07 05:59:18|  3   2  94   1   0   0|2755M  483M|  95M   53M| 155G 1213M  267G  587G|   0    17G|20.6 21.6 21.6
08-07 05:59:19|  3   2  94   1   0   0|2749M  339M|  23M   38M| 155G 1213M  267G  587G|   0    17G|20.6 21.6 21.6
08-07 05:59:21|  3   2  93   1   0   0|3370M  473M| 146M   64M| 155G 1213M  267G  587G|   0    17G|22.1 21.9 21.7
08-07 05:59:23|  3   2  93   1   0   0|4604M  593M| 162M   59M| 155G 1213M  267G  587G|   0    17G|22.1 21.9 21.7 missed 3 ticks
08-07 05:59:25|  3   3  93   1   0   0|3835M  525M|  92M   39M| 155G 1213M  267G  587G|   0    17G|22.1 21.9 21.7 missed 2 ticks
08-07 05:59:27|  2   2  94   1   0   0|2336M  216M|  56M   56M| 155G 1213M  267G  587G|   0    17G|22.1 21.9 21.7
08-07 05:59:29|  2   2  94   2   0   0|3497M  395M|  60M   51M| 155G 1213M  267G  587G|   0    17G|22.1 21.9 21.7 missed 3 ticks
08-07 05:59:31|  2   2  94   1   0   0|3217M  456M|  63M   60M| 155G 1213M  267G  587G|   0    17G|22.4 22.0 21.7 missed 2 ticks
08-07 05:59:33|  2   2  94   2   0   0|3823M  461M|  29M   51M| 155G 1213M  267G  587G|   0    17G|22.4 22.0 21.7 missed 2 ticks
08-07 05:59:35|  3   2  93   2   0   0|3131M  376M|  26M   40M| 155G 1213M  267G  587G|   0    17G|23.8 22.3 21.8 missed 2 ticks


----system---- ----total-cpu-usage---- -dsk/total- -net/total- ------memory-usage----- ----swap--- ---load-avg---
     time     |usr sys idl wai hiq siq| read  writ| recv  send| used  buff  cach  free| used  free| 1m   5m  15m
09-07 05:59:29|  3   1  95   1   0   0|1394M  124M| 100M  120M| 157G 1217M  267G  584G|   0    17G|19.6 19.7 17.9
09-07 05:59:30|  3   1  95   0   0   0|1378M   66M| 102M   82M| 157G 1217M  267G  584G|   0    17G|19.6 19.7 17.9
09-07 05:59:31|  3   2  95   0   0   0|1114M   69M|  97M   96M| 157G 1217M  267G  584G|   0    17G|19.6 19.7 17.9
09-07 05:59:32|  3   2  95   1   0   0|1728M  119M| 147M  172M| 157G 1217M  267G  584G|   0    17G|18.9 19.5 17.8
09-07 05:59:34|  3   2  94   1   0   0|2564M  136M| 212M  189M| 157G 1217M  267G  584G|   0    17G|18.9 19.5 17.8
09-07 05:59:36|  3   2  94   1   0   0|2560M  195M|  65M   86M| 157G 1217M  267G  584G|   0    17G|18.9 19.5 17.8 missed 2 ticks
09-07 05:59:37|  3   2  94   1   0   0|1492M   87M| 163M  140M| 157G 1217M  267G  584G|   0    17G|18.9 19.5 17.8
09-07 05:59:38|  3   2  94   1   0   0|2445M  197M| 199M  206M| 157G 1217M  267G  584G|   0    17G|18.7 19.5 17.8 missed 2 ticks
09-07 05:59:40|  3   3  94   1   0   0|3014M  215M| 191M  161M| 157G 1217M  267G  584G|   0    17G|18.7 19.5 17.8 missed 2 ticks
09-07 05:59:42|  3   2  94   1   0   0|2378M  146M|  83M   88M| 157G 1217M  267G  584G|   0    17G|18.7 19.5 17.8 missed 2 ticks
09-07 05:59:43|  3   2  94   1   0   0|1745M  117M| 247M  205M| 157G 1217M  267G  584G|   0    17G|18.4 19.4 17.8
09-07 05:59:46|  3   2  94   1   0   0|3229M  228M| 232M  218M| 157G 1217M  267G  584G|   0    17G|18.4 19.4 17.8 missed 2 ticks
09-07 05:59:48|  3   3  94   1   0   0|3091M  247M|  90M   80M| 157G 1217M  267G  584G|   0    17G|18.1 19.3 17.8 missed 3 ticks
09-07 05:59:49|  3   2  94   1   0   0|1363M   87M| 141M  125M| 157G 1217M  267G  584G|   0    17G|18.1 19.3 17.8
09-07 05:59:50|  3   2  93   1   0   0|1931M  153M| 145M  114M| 157G 1217M  267G  584G|   0    17G|18.1 19.3 17.8
09-07 05:59:52|  3   2  94   1   0   0|1647M   99M|  53M   63M| 157G 1217M  267G  584G|   0    17G|18.1 19.3 17.8
09-07 05:59:53|  4   2  93   1   0   0| 825M  107M|  72M   72M| 156G 1217M  267G  585G|   0    17G|18.1 19.3 17.8

note : 7/9問題時(shí)間和7/8正常時(shí)間負(fù)載并無(wú)太大差異。

top event

  select   inst_id,
  --IS_SQLID_CURRENT,SQL_PLAN_HASH_VALUE,SQL_PLAN_LINE_ID,SQL_PLAN_OPERATION,count(*) es_sec
-- SQL_EXEC_ID,SQL_EXEC_START, count(*) es_sec
 --QC_INSTANCE_ID,QC_SESSION_ID,
 CASE WHEN h.SESSION_STATE != 'WAITING' THEN 'On CPU / runqueue'  ELSE event end as event ,  SUM(h.wait_time + h.time_waited)/1000000 "Total Wait Time", SESSION_STATE, BLOCKING_SESSION,count(*) es_sec
-- CURRENT_OBJ# ,CURRENT_FILE# ,CURRENT_BLOCK# ,SEQ# ,
-- TOP_LEVEL_CALL_NAME,IN_PARSE,IN_SQL_EXECUTION,event, time_waited/1000 threshold_in_ms,
-- DELTA_READ_IO_REQUESTS,DELTA_READ_IO_BYTES,PGA_ALLOCATED,TEMP_SPACE_ALLOCATED
 from ash0709 h
 where sql_id='8wcnndfapzzn9'
 group by inst_id,event,SESSION_STATE, BLOCKING_SESSION
 12   order by 6 desc;

   INST_ID EVENT                            Total Wait Time SESSION BLOCKING_SESSION     ES_SEC
---------- -------------------------------- --------------- ------- ---------------- ----------
         3 On CPU / runqueue                        .163804 ON CPU                         9061

   INST_ID EVENT                            Total Wait Time SESSION BLOCKING_SESSION     ES_SEC
---------- -------------------------------- --------------- ------- ---------------- ----------
         4 On CPU / runqueue                         .73538 ON CPU                         8812

   INST_ID EVENT                            Total Wait Time SESSION BLOCKING_SESSION     ES_SEC
---------- -------------------------------- --------------- ------- ---------------- ----------
         3 direct path read                       28.776845 WAITING                         458

   INST_ID EVENT                            Total Wait Time SESSION BLOCKING_SESSION     ES_SEC
---------- -------------------------------- --------------- ------- ---------------- ----------
         4 direct path read                       23.998951 WAITING                         407
           direct path read temp                    .492271 WAITING                          40

-- top call

  select inst_id, CASE WHEN h.SESSION_STATE != 'WAITING' THEN 'On CPU / runqueue'  ELSE event end as event ,  SUM(h.wait_time + h.time_waited)/1000000 "Total Wait Time",
TOP_LEVEL_CALL_NAME,IN_PARSE,IN_SQL_EXECUTION
 ,count(*) es_sec
 from ash0709 h
 where sql_id='8wcnndfapzzn9' and SQL_PLAN_LINE_ID=36
  6   group by inst_id,SESSION_STATE,event, TOP_LEVEL_CALL_NAME,IN_PARSE,IN_SQL_EXECUTION;

   INST_ID EVENT                                    Total Wait Time TOP_LEVEL_CALL_NAME                                              I I     ES_SEC
---------- ---------------------------------------- --------------- ---------------------------------------------------------------- - - ----------
         4 On CPU / runqueue                                .102406 LOGOFF                                                           N Y       8059

   INST_ID EVENT                                    Total Wait Time TOP_LEVEL_CALL_NAME                                              I I     ES_SEC
---------- ---------------------------------------- --------------- ---------------------------------------------------------------- - - ----------
         3 On CPU / runqueue                                 .06867 VERSION2                                                         N Y       8498
           direct path read                               20.722015 VERSION2                                                         N Y        361

   INST_ID EVENT                                    Total Wait Time TOP_LEVEL_CALL_NAME                                              I I     ES_SEC
---------- ---------------------------------------- --------------- ---------------------------------------------------------------- - - ----------
         4 direct path read                               21.756692 LOGOFF                                                           N Y        380

   INST_ID EVENT                                    Total Wait Time TOP_LEVEL_CALL_NAME                                              I I     ES_SEC
---------- ---------------------------------------- --------------- ---------------------------------------------------------------- - - ----------
         3 gc cr block lost                                  .77136 VERSION2                                                         N Y          1

   INST_ID EVENT                                    Total Wait Time TOP_LEVEL_CALL_NAME                                              I I     ES_SEC
---------- ---------------------------------------- --------------- ---------------------------------------------------------------- - - ----------
         4 db file sequential read                          .006389 LOGOFF                                                           N Y          1

   INST_ID EVENT                                    Total Wait Time TOP_LEVEL_CALL_NAME                                              I I     ES_SEC
---------- ---------------------------------------- --------------- ---------------------------------------------------------------- - - ----------
         3 db file sequential read                          1.40969 VERSION2                                                         N Y         37

NOTE:
大部分時(shí)間是 ON CPU. node4 是調(diào)用logoff, node3為version2, 查看歷史正常時(shí)間段top level call name均是version2. 暫不不確認(rèn)logoff原因（猜測(cè)可能是slave進(jìn)程退出）。

到現(xiàn)在是邏輯讀沒增加，又存在2個(gè)并行slave節(jié)點(diǎn)進(jìn)程大部時(shí)間是on cpu, 系統(tǒng)負(fù)載并不高，問題出在哪里？

分析OS層進(jìn)程狀態(tài)

SQL> r
    select inst_id, CASE WHEN h.SESSION_STATE != 'WAITING' THEN 'On CPU / runqueue'  ELSE event end as event ,  SUM(h.wait_time + h.time_waited)/1000000 "Total Wait Time",
  program,TOP_LEVEL_CALL_NAME
   ,count(*) es_sec
   from ash0709 h
   where sql_id='8wcnndfapzzn9' and SQL_PLAN_LINE_ID=36
   group by inst_id,program,event,TOP_LEVEL_CALL_NAME,SESSION_STATE
 
   INST_ID EVENT                                    Total Wait Time PROGRAM                        TOP_LEVEL_CALL_NAME                ES_SEC
---------- ---------------------------------------- --------------- ------------------------------ ------------------------------ ----------
         3 On CPU / runqueue                                 .06867 oracle@anbob3 (P027)        VERSION2                             8498
         3 gc cr block lost                                  .77136 oracle@anbob3 (P027)        VERSION2                                1
         3 gc current block 3-way                           .001514 oracle@anbob3 (P027)        VERSION2                                1
         4 gc current block 2-way                           .002936 oracle@anbob4 (P009)        LOGOFF                                  1
         3 db file sequential read                          1.40969 oracle@anbob3 (P027)        VERSION2                               37
         3 gc cr grant 2-way                                .093752 oracle@anbob3 (P027)        VERSION2                                6
         3 gc current block 2-way                           .011192 oracle@anbob3 (P027)        VERSION2                                5
         4 On CPU / runqueue                                .102406 oracle@anbob4 (P009)        LOGOFF                               8059
         4 direct path read                               21.756692 oracle@anbob4 (P009)        LOGOFF                                380
         4 db file sequential read                          .006389 oracle@anbob4 (P009)        LOGOFF                                  1
         3 direct path read                               20.722015 oracle@anbob3 (P027)        VERSION2                              361
         3 db file scattered read                           .579141 oracle@anbob3 (P027)        VERSION2                               16
         3 gc cr multi block request                        .012058 oracle@anbob3 (P027)        VERSION2                                6

13 rows selected.

NOTE:
節(jié)點(diǎn)4的p009進(jìn)程和節(jié)點(diǎn)3的p027進(jìn)程。

OSW ps 分析

$ egrep '^zzz|ora_p027' anbob3_ps_22.07.09.0500.dat
zzz ***Sat Jul 9 05:42:59 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169854500 poll_s S   Jun 30 06:11:01 ora_p027_anbob3
zzz ***Sat Jul 9 05:43:29 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169854972 poll_s S   Jun 30 06:11:01 ora_p027_anbob3
zzz ***Sat Jul 9 05:43:59 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169857232 read_e S   Jun 30 06:11:03 ora_p027_anbob3
zzz ***Sat Jul 9 05:44:29 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169874284 blockd D   Jun 30 06:11:04 ora_p027_anbob3
zzz ***Sat Jul 9 05:44:59 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169955448 synchr D   Jun 30 06:11:06 ora_p027_anbob3
zzz ***Sat Jul 9 05:45:29 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169956480 synchr D   Jun 30 06:11:09 ora_p027_anbob3
zzz ***Sat Jul 9 05:45:59 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169956356 read_e S   Jun 30 06:11:12 ora_p027_anbob3
zzz ***Sat Jul 9 05:46:29 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169956380 read_e S   Jun 30 06:11:15 ora_p027_anbob3
zzz ***Sat Jul 9 05:46:59 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169956384 read_e S   Jun 30 06:11:18 ora_p027_anbob3
zzz ***Sat Jul 9 05:47:29 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169956516 synchr D   Jun 30 06:11:21 ora_p027_anbob3
zzz ***Sat Jul 9 05:47:59 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169956400 poll_s S   Jun 30 06:11:24 ora_p027_anbob3
zzz ***Sat Jul 9 05:48:29 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169956404 poll_s S   Jun 30 06:11:29 ora_p027_anbob3
zzz ***Sat Jul 9 05:49:00 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169956408 poll_s S   Jun 30 06:11:35 ora_p027_anbob3
zzz ***Sat Jul 9 05:49:30 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169958472 ? R   Jun 30 06:11:44 ora_p027_anbob3
zzz ***Sat Jul 9 05:50:00 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169958476 ? R   Jun 30 06:11:54 ora_p027_anbob3
zzz ***Sat Jul 9 05:50:30 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169958496 poll_s S   Jun 30 06:12:03 ora_p027_anbob3
zzz ***Sat Jul 9 05:51:00 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169958688 synchr D   Jun 30 06:12:08 ora_p027_anbob3
zzz ***Sat Jul 9 05:51:30 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169958832 synchr D   Jun 30 06:12:09 ora_p027_anbob3
zzz ***Sat Jul 9 05:52:00 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169958968 synchr D   Jun 30 06:12:10 ora_p027_anbob3
zzz ***Sat Jul 9 05:52:30 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169958916 synchr D   Jun 30 06:12:12 ora_p027_anbob3
zzz ***Sat Jul 9 05:53:00 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169959140 synchr D   Jun 30 06:12:13 ora_p027_anbob3


$ egrep '^zzz|ora_p027' anbob3_ps_22.07.09.0600.dat                                                             
zzz ***Sat Jul 9 06:00:01 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169969468 ? R   Jun 30 06:12:28 ora_p027_anbob3
zzz ***Sat Jul 9 06:00:31 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169970548 synchr D   Jun 30 06:12:29 ora_p027_anbob3
zzz ***Sat Jul 9 06:01:01 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169971792 synchr D   Jun 30 06:12:30 ora_p027_anbob3
zzz ***Sat Jul 9 06:01:31 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169973676 synchr D   Jun 30 06:12:31 ora_p027_anbob3
zzz ***Sat Jul 9 06:02:01 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169975644 synchr D   Jun 30 06:12:32 ora_p027_anbob3
zzz ***Sat Jul 9 06:02:31 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169980104 synchr D   Jun 30 06:12:33 ora_p027_anbob3
zzz ***Sat Jul 9 06:03:01 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169981468 synchr D   Jun 30 06:12:33 ora_p027_anbob3
zzz ***Sat Jul 9 06:03:31 CST 2022
oracle    23539      1  19  2.7 16.0 263043928 169982628 blockd D   Jun 30 06:12:34 ora_p027_anbob3
zzz ***Sat Jul 9 06:04:02 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169983820 synchr D   Jun 30 06:12:35 ora_p027_anbob3
zzz ***Sat Jul 9 06:04:32 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169985096 synchr D   Jun 30 06:12:35 ora_p027_anbob3
zzz ***Sat Jul 9 06:05:02 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169987172 synchr D   Jun 30 06:12:36 ora_p027_anbob3
zzz ***Sat Jul 9 06:05:32 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169988824 synchr D   Jun 30 06:12:37 ora_p027_anbob3
zzz ***Sat Jul 9 06:06:02 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169989524 synchr D   Jun 30 06:12:38 ora_p027_anbob3
zzz ***Sat Jul 9 06:06:32 CST 2022
oracle    23539      1  19  2.7 16.0 263044052 169989864 synchr D   Jun 30 06:12:40 ora_p027_anbob3
...

	行 83871: oracle   119729      1  19  5.2 12.9 263064632 136586392 blockd D   Jul 05 04:07:02 ora_p009_anbob4
	行 89096: oracle   119729      1  19  5.2 12.9 263064632 136586456 blockd D   Jul 05 04:07:08 ora_p009_anbob4
	行 94320: oracle   119729      1  19  5.2 12.9 263064632 136586508 blockd D   Jul 05 04:07:13 ora_p009_anbob4
	行 99543: oracle   119729      1  19  5.2 12.9 263064632 136586568 blockd D   Jul 05 04:07:18 ora_p009_anbob4
	行 104762: oracle   119729      1  19  5.2 12.9 263064632 136586624 ? R   Jul 05 04:07:23 ora_p009_anbob4
	行 110001: oracle   119729      1  19  5.2 12.9 263064632 136586700 blockd D   Jul 05 04:07:30 ora_p009_anbob4
	行 115238: oracle   119729      1  19  5.2 12.9 263064640 136587044 ? R   Jul 05 04:07:36 ora_p009_anbob4
	行 120458: oracle   119729      1  19  5.2 12.9 263064640 136587220 synchr D   Jul 05 04:07:39 ora_p009_anbob4
	行 125681: oracle   119729      1  19  5.2 12.9 263064764 136587572 synchr D   Jul 05 04:07:39 ora_p009_anbob4
	行 130894: oracle   119729      1  19  5.2 12.9 263064632 136587596 blockd D   Jul 05 04:07:39 ora_p009_anbob4
	行 136106: oracle   119729      1  19  5.2 12.9 263064640 136587844 synchr D   Jul 05 04:07:40 ora_p009_anbob4
	行 141315: oracle   119729      1  19  5.2 12.9 263064764 136588132 synchr D   Jul 05 04:07:41 ora_p009_anbob4
	行 146533: oracle   119729      1  19  5.2 12.9 263064764 136588312 synchr D   Jul 05 04:07:41 ora_p009_anbob4
	行 151745: oracle   119729      1  19  5.2 12.9 263064764 136588488 synchr D   Jul 05 04:07:42 ora_p009_anbob4
	行 156959: oracle   119729      1  19  5.2 12.9 263064764 136588636 synchr D   Jul 05 04:07:42 ora_p009_anbob4
	行 162175: oracle   119729      1  19  5.2 12.9 263064764 136589868 synchr D   Jul 05 04:07:43 ora_p009_anbob4
	行 167398: oracle   119729      1  19  5.2 12.9 263064764 136589940 synchr D   Jul 05 04:07:44 ora_p009_anbob4
	行 172646: oracle   119729      1  19  5.2 12.9 263064640 136590328 synchr D   Jul 05 04:07:45 ora_p009_anbob4
	行 177881: oracle   119729      1  19  5.2 12.9 263064640 136590480 synchr D   Jul 05 04:07:45 ora_p009_anbob4
	行 183109: oracle   119729      1  19  5.2 12.9 263064764 136590852 synchr D   Jul 05 04:07:45 ora_p009_anbob4
	行 188344: oracle   119729      1  19  5.2 12.9 263064632 136590872 blockd D   Jul 05 04:07:46 ora_p009_anbob4
	行 193567: oracle   119729      1  19  5.2 12.9 263064764 136591096 synchr D   Jul 05 04:07:46 ora_p009_anbob4
	行 198787: oracle   119729      1  19  5.2 12.9 263064764 136591264 synchr D   Jul 05 04:07:47 ora_p009_anbob4
	行 204007: oracle   119729      1  19  5.2 12.9 263064640 136591312 synchr D   Jul 05 04:07:47 ora_p009_anbob4
	行 209240: oracle   119729      1  19  5.2 12.9 263064764 136591608 synchr D   Jul 05 04:07:48 ora_p009_anbob4
	行 214467: oracle   119729      1  19  5.2 12.9 263064764 136591780 synchr D   Jul 05 04:07:48 ora_p009_anbob4
	行 219707: oracle   119729      1  19  5.2 12.9 263064764 136591952 synchr D   Jul 05 04:07:49 ora_p009_anbob4

NOTE:
從osw ps每30秒快照可見存在近1-2個(gè)小時(shí)并行進(jìn)程連續(xù)處于”D” 狀態(tài)。

“D” 狀態(tài)進(jìn)程

A process in Linux can be in several states: running, sleeping, etc. Running process runs on a CPU just now, sleeping process waits for its turn on CPU or for some other event. First big S stands for Sleeping, R stands for running (“+” means that the process is foreground and small “s” means that the process is session leader, but it is not relevant for this article).

D state occurs then the process is in uninterruptible sleep，Processes in a “D” or uninterruptible sleep state are usually waiting on I/O. The ps command shows a “D” on processes in an uninterruptible sleep state. This state is bad, because you can’t do anything with the process in D state. Fortunately, process normally remains in such state not for so long. But if you have a heap of D state processes then some logic in system is disrupt. If that is happening, the very important thing is to determine where this unlucky sleep occurs. It is easy to do with ps command with l option. WCHAN column shows the name of the kernel function where the process is sleeping，You cannot kill “D” state processes, even with SIGKILL or kill -9. As the name implies, they are uninterruptible. You can only clear them by rebooting the server or waiting for the I/O to respond.

“D”狀態(tài)進(jìn)程通常是在等待I/O，無(wú)法終止只到i/o返回， 出現(xiàn)該問題時(shí)通常查看WCHAN列判斷內(nèi)核調(diào)用函數(shù)。但是像本安例中能確認(rèn)是synchr開頭，顯示不完整，查看以synchr開頭的所有函數(shù)。

[oracle@oel7db1 ~]$ cat /boot/System.map-$(uname -r)|awk '$3 ~ "^synchr"'
ffffffff810fd130 T synchronize_hardirq
ffffffff810fd240 T synchronize_irq
ffffffff81106ed0 t synchronize_rcu
ffffffff81108b30 T synchronize_srcu_expedited
ffffffff81108b60 T synchronize_srcu
ffffffff8110ac80 T synchronize_sched_expedited
ffffffff8110acb0 T synchronize_sched
ffffffff8110ad70 T synchronize_rcu_bh
ffffffff8110adf0 T synchronize_rcu_expedited
ffffffff811f7620 t synchronous_wake_function
ffffffff8170e630 T synchronize_net

[oracle@oel7db1 ~]$ cat /boot/System.map-$(uname -r)|awk '$3 ~ "^blockd"'
ffffffff8264a3f0 D blockdev_superblock

因?yàn)闅v史無(wú)法再查看，可以查看當(dāng)前問題節(jié)點(diǎn)是否存在synchr開頭進(jìn)程。

# ps -eo pid,tid,class,state,pcpu,wchan:30,comm|grep ora_|awk '$4="D"&& $6 ~ "sync"'

發(fā)現(xiàn)存在幾個(gè)D狀態(tài)的oracle server進(jìn)程，函數(shù)為synchronize_sched

-/**
– * synchronize_sched – block until all CPUs have exited any non-preemptive
– * kernel code sequences.
– *
– * This means that all preempt_disable code sequences, including NMI and
– * hardware-interrupt handlers, in progress on entry will have completed
– * before this primitive returns. However, this does not guarantee that
– * softirq handlers will have completed, since in some kernels, these
– * handlers can run in process context, and can block.
– *
– * This primitive provides the guarantees made by the (now removed)
– * synchronize_kernel() API. In contrast, synchronize_rcu() only
– * guarantees that rcu_read_lock() sections will have completed.
– * In “classic RCU”, these two guarantees happen to be one and
– * the same, but can differ in realtime RCU implementations.
– */
-#define synchronize_sched() __synchronize_sched()

cause

不確認(rèn)當(dāng)時(shí)CPU在做什么， 或是內(nèi)核存在邏輯缺陷原因， 至少這樣可以解釋，在數(shù)據(jù)庫(kù)層看到的長(zhǎng)時(shí)間 ON CPU，是因?yàn)镺S 層的進(jìn)程處理D 狀態(tài)，一直在等待內(nèi)核某個(gè)調(diào)用完成。

OS層的內(nèi)核調(diào)用未響應(yīng)，導(dǎo)致DB 層會(huì)話為on cpu狀態(tài)，SQL運(yùn)行時(shí)間增加，直到OS響應(yīng)后自動(dòng)恢復(fù)。

Solution

建議找主機(jī)工程師或存儲(chǔ)工程師分析問題時(shí)間點(diǎn)的存儲(chǔ)性能 或 OS是否有瓶頸。