By Franck Pachot
.
Usually, cursor invalidations do not interrupt the current execution of the cursor. You can even drop a table while a query on it is running and the query may end successfully. However some invalidations will throw internal errors that are catch and the cursor execution restarts transparently. I’ve reproduced one here to show the symptoms: it’s a different EXEC_SQL_ID so the restarts are not accounted within the same SQL Monitoring.
I had that question because I encountered a SQL Monitoring report where the ‘executions’ count of the INSERT operation was more than one. I wondered if it can be a case of DML restart or if DML restart should be accounted in different EXEC_SQL_ID. I got the quick answer from a very reliable source:
Yep!
— Stefan Koehler (@OracleSK) November 21, 2016
However for my better understanding, I’m now reproducing a case of DML restart to show the symptoms on V$SQL and SQL Monitor.
I need a table with some rows:
SQL> create table DEMO as select rownum n from xmltable('1 to 3');
Table created.
Initially my problem was with an insert into a GTT but now I’m reproducing the case with a partitioned table:
SQL> create table DEMOGTT (n number) partition by hash(n);
Table created.
For internal reasons, when a cursor is invalidated after it has acquired a lock on a partition, a DML restart occurs. If you have a doubt, “oerr ora 14403” explains that.
The easiest way to invalidate while the cursor is running is to call a function that does it for each row. And as you will see that it can be restarted to infinity I set a timeout timestamp after 30 seconds.
SQL> column limit new_value limit
SQL> select to_char(sysdate+30/24/60/60,'yyyymmddhh24miss') limit from dual;
LIMIT
--------------
20161124212154
SQL> create function DEMOSLOW(n number) return number as
2 pragma autonomous_transaction;
3 begin
4 if sysdate > to_date('&limit','yyyymmddhh24miss')
5 then
6 dbms_stats.gather_table_stats(user,'DEMOGTT',no_invalidate=>false);
7 end if;
8 return n;
9 end;
10 /
old 4: if sysdate < to_date('&limit','yyyymmddhh24miss')
new 4: if sysdate < to_date('20161124212154','yyyymmddhh24miss')
Function created.
Time to run the insert, calling the function for each row:
SQL> alter session set statistics_level=all;
Session altered.
SQL> set timing on time on
21:21:24 SQL> insert /*+ monitor */ into DEMOGTT select n from DEMO where n=DEMOSLOW(n);
3 rows created.
Elapsed: 00:00:29.30
21:21:54 SQL>
This has taken 30 seconds. Without the timeout, it never stops.
Execution plan for last run shows only one ‘Start’:
21:21:54 SQL> select * from table(dbms_xplan.display_cursor('','','allstats last'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
SQL_ID 3fk1hyq9vnuzx, child number 0
-------------------------------------
insert /*+ monitor */ into DEMOGTT select n from DEMO where
n=DEMOSLOW(n)
Plan hash value: 4000794843
----------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 1 | | 0 |00:00:00.01 | 138 |
| 1 | LOAD TABLE CONVENTIONAL | DEMOGTT | 1 | | 0 |00:00:00.01 | 138 |
|* 2 | TABLE ACCESS FULL | DEMO | 1 | 1 | 3 |00:00:00.01 | 9 |
----------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("N"="DEMOSLOW"("N"))
This is a proof that DML restarts are not accounted within the same execution. the ‘last’ statistics are only from the last restart.
V$SQL accounts only one execution but thousands of invalidations:
21:21:54 SQL> select executions,invalidations from v$sql where sql_id='3fk1hyq9vnuzx';
EXECUTIONS INVALIDATIONS
---------- -------------
1 1571
ASH shows the different SQL_EXEC_ID:
21:21:54 SQL> select sample_time,sql_id,sql_exec_id from v$active_session_history where sql_id='3fk1hyq9vnuzx' and sample_time>sysdate-10/24/60/60 order by sample_time desc;
SAMPLE_TIME SQL_ID SQL_EXEC_ID
--------------------------------------------------------------------------- ------------- -----------
24-NOV-16 09.21.53.773 PM 3fk1hyq9vnuzx 16778774
24-NOV-16 09.21.51.773 PM 3fk1hyq9vnuzx
24-NOV-16 09.21.48.773 PM 3fk1hyq9vnuzx 16778501
24-NOV-16 09.21.46.773 PM 3fk1hyq9vnuzx 16778396
24-NOV-16 09.21.45.773 PM 3fk1hyq9vnuzx 16778341
and SQL Monitoring see different executions:
21:21:54 SQL> select sql_id,sql_exec_id,status,last_refresh_time,plan_operation,starts from v$sql_plan_monitor where sql_id='3fk1hyq9vnuzx' and plan_line_id=0 order by last_refresh_time desc fetch first 10 rows only;
SQL_ID SQL_EXEC_ID STATUS LAST_REFRESH_TI PLAN_OPERATION STARTS
------------- ----------- ------------------- --------------- ------------------------------ ----------
3fk1hyq9vnuzx 16778762 DONE 24-nov 21:21:53 INSERT STATEMENT 1
3fk1hyq9vnuzx 16778765 DONE 24-nov 21:21:53 INSERT STATEMENT 1
3fk1hyq9vnuzx 16778767 DONE 24-nov 21:21:53 INSERT STATEMENT 1
3fk1hyq9vnuzx 16778766 DONE 24-nov 21:21:53 INSERT STATEMENT 1
3fk1hyq9vnuzx 16778771 DONE 24-nov 21:21:53 INSERT STATEMENT 1
3fk1hyq9vnuzx 16778769 DONE 24-nov 21:21:53 INSERT STATEMENT 1
3fk1hyq9vnuzx 16778764 DONE 24-nov 21:21:53 INSERT STATEMENT 1
3fk1hyq9vnuzx 16778770 DONE 24-nov 21:21:53 INSERT STATEMENT 1
3fk1hyq9vnuzx 16778763 DONE 24-nov 21:21:53 INSERT STATEMENT 1
3fk1hyq9vnuzx 16778768 DONE 24-nov 21:21:53 INSERT STATEMENT 1
So those are the symptoms of DML restart. And my initial problem is still there:
- This test case does not reproduce the issue on a GTT
- My issue on the GTT had only one SQL_EXEC_ID with multiple ‘starts’ of the plan operations.
#sqlmon #puzzled
I expected to see '1' as 'executions for the first line of a plan,
Here I have executions with 1,12,19,64… ?!? pic.twitter.com/yHPZXDprgX— Franck Pachot 💙💛 🇺🇦 (@FranckPachot) November 21, 2016
Any comments greatly appreciated 🙂