[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与开发之间存在一条无法跨越的鸿沟,沟通存在问题.