[20231012]奇怪的執行時長(sql_id=dtt2yfpx8jhp4).txt

--//今天例行檢查,我發現一個奇怪的sql語句,實際上以前也遇到過,太久不做維護了,有點忘記了!!

1.環境:
SYS@192.168.100.235:1521/orcl> @ver1
SYS@192.168.100.235:1521/orcl> @ pr
==============================
PORT_STRING                   : x86_64/Linux 2.4.xx
VERSION                       : 19.0.0.0.0
BANNER                        : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
BANNER_FULL                   : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0
BANNER_LEGACY                 : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
CON_ID                        : 0
PL/SQL procedure successfully completed.

2.分析:
SYS@192.168.100.235:1521/orcl> @ ashtop sql_id 1=1 &day
    Total                                                                         Distinct Distinct
Seconds     AAS %This   SQL_ID        FIRST_SEEN          LAST_SEEN           Execs Seen Tstamps
--------- ------- ------- ------------- ------------------- ------------------- ---------- --------
    43254      .5   51% |               2023-10-11 08:35:40 2023-10-12 08:35:35          3    19604
     3687      .0    4% | dtt2yfpx8jhp4 2023-10-11 15:40:01 2023-10-11 16:41:35          1     3687
     2696      .0    3% | cyqv7gknyf7bh 2023-10-12 01:41:36 2023-10-12 08:34:38       1533     2696
     1864      .0    2% | 1p68ys9y3582r 2023-10-11 08:40:25 2023-10-12 08:30:44       1857     1521
     1393      .0    2% | g1v8dts358gq5 2023-10-11 08:35:39 2023-10-12 08:30:18        316     1205
     1152      .0    1% | 8p09mg2dsvvfa 2023-10-11 08:40:07 2023-10-12 08:33:38        606     1015
     1074      .0    1% | 3uzhsvstyytm2 2023-10-11 08:58:23 2023-10-11 23:52:26        148     1044
     1052      .0    1% | bfcjfb3yhz8rt 2023-10-11 08:36:07 2023-10-12 08:34:57        779     1032
      987      .0    1% | gxak7guzxkwbh 2023-10-11 08:37:05 2023-10-12 08:35:27        747      951
      880      .0    1% | 89u3urxj9zs1x 2023-10-11 08:37:50 2023-10-12 08:33:04        179      880
...
30 rows selected.
--//dtt2yfpx8jhp4僅僅執行1次,竟然要1個小時，而且是w3wp.exe執行的。

SYS@192.168.100.235:1521/orcl> @ sql_id dtt2yfpx8jhp4
--SQL_ID = dtt2yfpx8jhp4
select *from lis_sample_operate where barcode=:Barcode and EXECUTE_STATE_TEXT='鎖定報告'
--//建立了barcode的索引,應該執行很快啊.

SYS@192.168.100.235:1521/orcl> @ dpc dtt2yfpx8jhp4 '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID dtt2yfpx8jhp4, child number 0
-------------------------------------
select *from lis_sample_operate where barcode=:Barcode and
EXECUTE_STATE_TEXT='鎖定報告'
Plan hash value: 2118786184
----------------------------------------------------------------------------------------------------------------------
| Id | Operation                           | Name                          | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                               |        |       |    12 (100)|          |
|* 1 | TABLE ACCESS BY INDEX ROWID BATCHED| LIS_SAMPLE_OPERATE            |      1 |   127 |    12   (0)| 00:00:01 |
|* 2 |   INDEX RANGE SCAN                  | IX_LIS_SAMPLE_OPERATE_BARCODE |      8 |       |     4   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
   1 - SEL$1 / LIS_SAMPLE_OPERATE@SEL$1
   2 - SEL$1 / LIS_SAMPLE_OPERATE@SEL$1
Peeked Binds (identified by position):
--------------------------------------
   1 - :1 (VARCHAR2(30), CSID=852): '1801158810'
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("EXECUTE_STATE_TEXT"=U'\9501\5B9A\62A5\544A')
   2 - access("BARCODE"=SYS_OP_C2C(:BARCODE))
Note
-----
   - Warning: basic plan statistics not available. These are only collected when:
       * hint 'gather_plan_statistics' is used for the statement or
       * parameter 'statistics_level' is set to 'ALL', at session or system level
--//應該執行很快啊.

--//檢視傳入的繫結變數值。
SYS@192.168.100.235:1521/orcl> @ bind_cap_awr dtt2yfpx8jhp4 ''
@bind_cap_awr sql_id [column]
SNAP_ID INSTANCE_NUMBER SQL_ID        WAS LAST_CAPTURED       NAME       POSITION MAX_LENGTH DATATYPE_STRING VALUE_STRING
------- --------------- ------------- --- ------------------- -------- ---------- ---------- --------------- ---------------
24195               1 dtt2yfpx8jhp4 YES 2023-09-01 17:12:17 :BARCODE          1         32 VARCHAR2(32)    _
24196               1 dtt2yfpx8jhp4 YES 2023-09-01 17:12:17 :BARCODE          1         32 VARCHAR2(32)    _
24310               1 dtt2yfpx8jhp4 YES 2023-09-06 12:52:53 :BARCODE          1         32 VARCHAR2(32)    _
24311               1 dtt2yfpx8jhp4 YES 2023-09-06 12:52:53 :BARCODE          1         32 VARCHAR2(32)    _
24886               1 dtt2yfpx8jhp4 YES 2023-09-30 12:11:24 :BARCODE          1         32 VARCHAR2(32)    7211153713
24887               1 dtt2yfpx8jhp4 YES 2023-09-30 12:11:24 :BARCODE          1         32 VARCHAR2(32)    7211153713
25153               1 dtt2yfpx8jhp4 YES 2023-10-11 15:59:32 :BARCODE          1         32 VARCHAR2(32)    20231011001256
25154               1 dtt2yfpx8jhp4 YES 2023-10-11 15:59:32 :BARCODE          1         32 VARCHAR2(32)    20231011001256
8 rows selected.

--//查詢帶入繫結變數的值馬上明白為什麼,存在帶入'_'的情況,開發程式將'_'當作空值.(注意是下劃線而非減號)
SYS@192.168.100.235:1521/orcl> select count(*) from lis.LIS_SAMPLE_OPERATE where barcode='_';
COUNT(*)
----------
    598071

SYS@192.168.100.235:1521/orcl> select count(*) from lis.LIS_SAMPLE_OPERATE;
COUNT(*)
----------
136678697

--//598071/136678697 = .00437574408541515434
--//程式在操作時沒有做輸入檢查或者需求就是這樣,導致索引要掃描大量資料,導致執行緩慢,我記憶裡以前也遇到過.再次做一個記錄.
--//我順便查了幾個資料塊，幾乎每個資料塊都有barcode='_'的記錄,走索引比全表掃描還慢.再看看錶大小.

SYS@192.168.100.235:1521/orcl> @ segsum lis.lis_sample_operate
    SEG_MB OWNER                SEGMENT_NAME                   SEGMENT_TYPE         SEG_TABLESPACE_NAME            SUM(BLOCKS)
---------- -------------------- ------------------------------ -------------------- ------------------------------ -----------
     21062 LIS                  LIS_SAMPLE_OPERATE             TABLE                LIS_DATA                           2695936

--//21G呢? 要建立索引估計給包括EXECUTE_STATE_TEXT欄位,放棄!!
--//正常的業務應該看不到帶入_的查詢,開發應該在程式中限制這樣的情況出現.
--//我自己做一個推測，這個值應該不是鍵盤輸入的，而是透過手持掃描器輸入的，可能在掃描時出現問題，比如出現非法字元，應用自動重置為_.
--//操作員沒看繼續查詢，出現問題，或者是掃描後馬上自動執行。不過從執行次數上看僅僅1次，說明這個功能很少使用。

SYS@192.168.100.235:1521/orcl> select count(*), EXECUTE_STATE_TEXT from lis.LIS_SAMPLE_OPERATE where barcode='_'   group by EXECUTE_STATE_TEXT;
COUNT(*) EXECUTE_STATE_TEXT
---------- ------------------------
    156204 標本歸檔
     10382 鎖定報告
   ~~~~~~~~~~~~~~~~~

339 複製樣本

...

54 rows selected.
--//如果查詢返回10382條,這樣的操作屬於無效查詢,沒有任何意義.
--//我總覺的在dba與開發之間存在一條無法跨越的鴻溝,溝通存在問題.

[20231012]奇怪的執行時長.txt

相關文章