grant dba to osp identified by osp;
conn osp/osp
Connected.
SQL> create table testa(col1 number,col2 number);
begin
for i in 1..10000 loop
insert into testa values(i,i);
end loop;
commit;
end;
/
begin DBMS_STATS.GATHER_TABLE_STATS('SYSTEM', 'TESTA', method_opt => 'FOR ALL COLUMNS',NO_INVALIDATE=>false);
end;
Session 1:
SQL> update testa set col2=col2+1 where col1=5038;
1 row updated.
Session 2:
-- Update 18 rows data using COL1 as condition
SQL> update /*+ monitor */ testa set col2=col2+1 where col1 in (1684,2243,2802,566,1125,3920,6715,7274,4479,5038,5597,6156,3361,7833,8392,8951,9510,10000);
->>>>>>>>>> Blocking by Session and hung.
Session 3:
-- Change the COL1 value of one of target rows of Session 2 and commit.
SQL> update testa set col1=col1+1 where col1 in (10000);
1 row updated.
SQL> commit;
Commit complete.
Session 4:
-- Check the "Execs" of SQL Monitor Report of the SQL statement of Session 2, currently the "Execs" is 1.
SQL> set pagesize 1000 linesize 20000 long 100000 numwidth 10 echo on
SQL> SELECT DBMS_SQLTUNE.report_sql_monitor(sql_id => '36yyhquwybkk3', type => 'TEXT') AS report FROM dual;
REPORT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
SQL Text
------------------------------
update /*+ monitor */ testa set col2=col2+1 where col1 in (1684,2243,2802,566,1125,3920,6715,7274,4479,5038,5597,6156,3361,7833,8392,8951,9510,10000)
Global Information
------------------------------
Status : EXECUTING
Instance ID : 1
Session : OSP (55:26075)
SQL ID : 36yyhquwybkk3
SQL Execution ID : 16777217
Execution Started : 02/17/2020 11:32:11
First Refresh Time : 02/17/2020 11:32:11
Last Refresh Time : 02/17/2020 11:32:43
Duration : 35s
Module/Action : SQL*Plus/-
Service : SYS$USERS
Program : sqlplus@(HIDDEN) (TNS V1-V3)
Global Stats
============================================
| Elapsed | Cpu | Application | Buffer |
| Time(s) | Time(s) | Waits(s) | Gets |
============================================
| 32 | 0.00 | 32 | 27 |
============================================
SQL Plan Monitoring Details (Plan Hash Value=1298344373)
================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | (%) | (# samples) |
================================================================================================================================================
| 0 | UPDATE STATEMENT | | | | 1 | +3 | 1 | 0 | | |
| -> 1 | UPDATE | TESTA | | | 35 | +1 | 1 | 0 | 100.00 | enq: TX - row lock contention (34) |
| -> 2 | TABLE ACCESS FULL | TESTA | 18 | 7 | 30 | +3 | 1 | 10 | | |
================================================================================================================================================
Session 1:
SQL> commit;
Commit complete.
Session 2:
-- Because Session 1 commited and released the lock, UPDATE proceed to execute and update 17 rows data according to the latest status of target status.
SQL> update /*+ monitor */ testa set col2=col2+1 where col1 in (1684,2243,2802,566,1125,3920,6715,7274,4479,5038,5597,6156,3361,7833,8392,8951,9510,10000);
17 rows updated.
SQL>
Session 4:
-- Check the "Execs" of SQL Monitor Report of the SQL statement of Session 2, the "Execs" become larger than 1.
SQL> SELECT DBMS_SQLTUNE.report_sql_monitor(sql_id => '36yyhquwybkk3', type => 'TEXT') AS report FROM dual;
REPORT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
SQL Text
------------------------------
update /*+ monitor */ testa set col2=col2+1 where col1 in (1684,2243,2802,566,1125,3920,6715,7274,4479,5038,5597,6156,3361,7833,8392,8951,9510,10000)
Global Information
------------------------------
Status : DONE
Instance ID : 1
Session : OSP (55:26075)
SQL ID : 36yyhquwybkk3
SQL Execution ID : 16777217
Execution Started : 02/17/2020 11:32:11
First Refresh Time : 02/17/2020 11:32:11
Last Refresh Time : 02/17/2020 11:33:02
Duration : 51s
Module/Action : SQL*Plus/-
Service : SYS$USERS
Program : sqlplus@(HIDDEN) (TNS V1-V3)
Global Stats
=======================================================
| Elapsed | Cpu | Application | Other | Buffer |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Gets |
=======================================================
| 51 | 0.01 | 51 | 0.01 | 162 |
=======================================================
SQL Plan Monitoring Details (Plan Hash Value=1298344373)
==============================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | (%) | (# samples) |
==============================================================================================================================================
| 0 | UPDATE STATEMENT | | | | 49 | +3 | 3 | 1 | | |
| 1 | UPDATE | TESTA | | | 52 | +1 | 3 | 1 | 100.00 | enq: TX - row lock contention (51) |
| 2 | TABLE ACCESS FULL | TESTA | 18 | 7 | 49 | +3 | 3 | 52 | | |
==============================================================================================================================================
select 下actual rows 下一个等于52 说明多了三倍,为什么update 的rows 是1 呢,不是update了 17行
If set 10046 events trace to above Session 2, we can find the restart is showing on the row source operation as "starts=x".
SQL ID: 36yyhquwybkk3 Plan Hash: 1298344373
update /*+ monitor */ testa set col2=col2+1
where
col1 in (1684,2243,2802,566,1125,3920,6715,7274,4479,5038,5597,6156,3361,
7833,8392,8951,9510,10000)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 45.88 0 71 92 17
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 45.88 0 71 92 17
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 107
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 UPDATE TESTA (cr=71 pr=0 pw=0 time=45880583 us starts=3) <<<<<<<<<<-------starts=3 indicates this operation restarted
52 52 52 TABLE ACCESS FULL TESTA (cr=70 pr=0 pw=0 time=3386 us starts=3 cost=7 size=144 card=18) <<<<<<<<<<-------starts=3 indicates this operation restarted
就算因为上一个commit导致要重新执行,为了是3 不是2呢??
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enq: TX - row lock contention 1 45.87 45.87
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 15.88 15.88
********************************************************************************