Saturday, July 28, 2018

Blog List

row cache mutex in Oracle 12.2.0.1.0

In Oracle 12.2.0.1.0 (12cR2), "row cache mutex" replaced 12.1.0.2.0 (12cR1) "latch: row cache objects", similar to "latch: library cache" substitution by "library cache: mutex X" in the previous release.

Oracle Global Customer Support Document: Oracle Database 12c Release 2 Support Lessons Learned from Early Adopters wrote:
    "row cache mutex" replaces "latch: row cache objects" but rarely seen

As a start point to be acquainted with this new mechanism, this Blog takes the same Test Code in Blog: nls_database_parameters, dc_props, latch: row cache objects to focus only on Dictionary Cache dc_props.

We will run tests in both 12cR2 and 12cR1 by varying the number of parallel sessions, compare their behaviors, and then try to measure their scalability.

Note: All tests are done in 12.2.0.1.0 (12cR2) and 12.1.0.2.0 (12cR1) on Linux with 6 physical processors.


1. 12cR2 "row cache mutex" vs. 12cR1 "latch: row cache objects"


The new Event "row cache mutex" is exposed with row cache parameters:

  P1TEXT = cache id 
  P2TEXT = where requested

select event, p1text, p1, p2text, p2, p3text, p3
  from v$session v where event in ('row cache mutex');
  
EVENT            P1TEXT    P1  P2TEXT           P2  P3TEXT  P3
---------------  --------  --  ---------------  --  ------  --
row cache mutex  cache id  15  where requested  19          0
"cache id" can be used to directly pinpoint the exact contention row cache objects.

Whereas in lower Releases, Event "latch: row cache objects" is exposed with latch parameters, and v$latch_children.child# is used to join with x$kqrst.kqrstcln and filtered by v$latch_children.addr = :P1RAW to find row cache info.

select event, p1text, p1, p1raw, p2text, p2, p2raw, p3text, p3, p3raw
  from v$session v where event in ('latch: row cache objects');

EVENT                     P1TEXT   P1          P1RAW             P2TEXT  P2   P2RAW             P3TEXT  P3  P3RAW
------------------------  -------  ----------  ----------------  ------  ---  ----------------  ------  --  -----
latch: row cache objects  address  5970309816  0000000163DBB2B8  number  411  000000000000019B  tries   0   00

select la.child# latch_child, kqrstcid cache#, kqrsttxt parameter, la.addr latch_addr --, dc.*, la.*
from x$kqrst dc, v$latch_children la 
where dc.kqrstcln = la.child# 
  and la.name     = 'row cache objects'
  and la.addr     = '0000000182D98958'; 

LATCH_CHILD  CACHE#  PARAMETER  LATCH_ADDR
-----------  ------  ---------  ----------------
18           15      dc_props   0000000163DBB2B8
12cR2 v$rowcache contains 71 rows, one new dictionary cache: 'dc_cdbprops' is added.

By the way, 'row cache objects' LATCH# is numbered as "506" (12cR1 is "411"), but hardly used.

select name, latch# from v$latch where name in ('row cache objects');

NAME               LATCH#  GETS
-----------------  ------  ----
row cache objects  506     456


2. Test


Run following test script in 12cR2 and 12cR1 on a Linux with 6 physical processors.
The script consists of 8 cases with 1, 2, 3, 4, 5, 6, 9 and 12 parallel sessions respectively.
Each case runs for 10 minutes.

declare
  type    t_num_tab is table of number;
  l_nums  t_num_tab := new t_num_tab(1, 2, 3, 4, 5, 6, 9, 12);
begin
  clean_jobs; 
  sys.dbms_workload_repository.create_snapshot('ALL');
  
  for n in 1..l_nums.count loop
    nls_select_jobs(l_nums(n), 1e9);    -- n Sessions
    dbms_lock.sleep(600);               -- 10 minutes
    clean_jobs; 
    sys.dbms_workload_repository.create_snapshot('ALL');
  end loop;
end;
/  


3. Test Result


After test, collect all 8 AWR reports in 12cR2 and 12cR1, extract relevant 4 Sections to compare.


3.1 12cR2


Top 10 Foreground Events by Total Wait Time

Session# Event            Waits     Total Wait Time (sec)   Avg Wait   % DB time  Wait Class
-------- ---------------  --------  ---------------------  --------   ---------   -----------
1        row cache mutex  9         0                       10.33us    0.0        Concurrency
2        row cache mutex  12,836    18                      1.46ms     1.6        Concurrency
3        row cache mutex  48,390    111                     2.31ms     5.9        Concurrency
4        row cache mutex  111,312   280                     2.52ms     10.5       Concurrency
5        row cache mutex  199,253   491                     2.47ms     14.6       Concurrency
6        row cache mutex  322,542   886                     2.75ms     20.1       Concurrency
9        row cache mutex  418,819   3030                    7.24ms     35.6       Concurrency
12       row cache mutex  573,556   4673                    8.15ms     38.7       Concurrency

SQL ordered by Elapsed Time
(SQL Id:   7mgsfc44trnr8
 SQL Text: SELECT VALUE FROM NLS_DATABASE_PARAMETERS WHERE PARAMETER = 'NLS_CHARACTERSET')

Session# Elapsed Time (s) Executions  Elapsed Time per Exec (s)  %Total  %CPU     %IO 
-------- ---------------- ----------  -------------------------  ------  -------  ----
1        498              3,174,194   0.00                       81.47   100.40   0.00
2        983              5,876,575   0.00                       83.48   98.52    0.00
3        1,515            8,383,434   0.00                       79.99   93.22    0.00
4        2,087            10,518,830  0.00                       77.82   87.48    0.00
5        2,533            11,688,284  0.00                       74.97   81.51    0.00
6        3,112            12,242,878  0.00                       70.67   71.93    0.00
9        4,894            9,121,274   0.00                       57.49   34.12    0.00
12       6,685            9,300,453   0.00                       55.32   25.77    0.00

Mutex Sleep Summary 

Session# Mutex Type  Location     Sleeps     Wait Time (ms)
-------- ----------  -----------  ---------  --------------
1        Row Cache   [19] kqrpre  12         0   
2        Row Cache   [19] kqrpre  16,734     18,744  
3        Row Cache   [19] kqrpre  70,398     108,322
4        Row Cache   [19] kqrpre  164,963    266,506
5        Row Cache   [19] kqrpre  290,989    466,843
6        Row Cache   [19] kqrpre  478,910    831,835
9        Row Cache   [19] kqrpre  890,437    2,929,696   
16       Row Cache   [19] kqrpre  1,268,073  4,499,378

1        Row Cache   [13] kqreqd  8          0 
2        Row Cache   [13] kqreqd  415        75
3        Row Cache   [13] kqreqd  1,536      300
4        Row Cache   [13] kqreqd  4,555      850
5        Row Cache   [13] kqreqd  9,913      1,625
6        Row Cache   [13] kqreqd  27,487     3,565
9        Row Cache   [13] kqreqd  20,223     14,429
16       Row Cache   [13] kqreqd  24,497     22,772

(Row Cache  [19] kqrpre: find obj 
 Row Cache  [13] kqreqd: reget)

Dictionary Cache Stats

Session# Cache     Get Requests  Pc t Miss  Scan Reqs  Pct Miss  Mod Reqs  Final Usage
-------- --------  ------------  ---------  ---------  --------  --------  -----------
1        dc_props  222,194,045   0.00       0                    0         70
2        dc_props  406,987,135   0.00       0                    0         70
3        dc_props  572,806,160   0.00       0                    0         70
4        dc_props  708,102,414   0.00       0                    0         70
5        dc_props  776,478,519   0.00       0                    0         70
6        dc_props  807,080,147   0.00       0                    0         70
9        dc_props  605,040,134   0.00       0                    0         70
12       dc_props  616,520,863   0.00       0                    0         70


3.2 12cR1


Top 10 Foreground Events by Total Wait Time

Session# Event                      Waits      Total Wait Time (sec)  Avg Wait(ms)   % DB time   Wait Class
-------- ------------------------   ---------  ---------------------  ------------   ---------   -----------
1        latch: row cache objects   12         0                      0.02           0.0         Concurrency
2        latch: row cache objects   19,775     1                      0.03           0.1         Concurrency
3        latch: row cache objects   259,069    6                      0.02           0.3         Concurrency
4        latch: row cache objects   612,329    16                     0.03           0.7         Concurrency
5        latch: row cache objects   1,008,481  36                     0.04           1.2         Concurrency
6        latch: row cache objects   1,189,823  116                    0.10           3.1         Concurrency
9        latch: row cache objects   1,036,139  2441                   2.36           30.2        Concurrency
12       latch: row cache objects   948,170    3861                   4.07           34.5        Concurrency

SQL ordered by Elapsed Time

Session# Elapsed Time (s)  Executions  Elapsed Time per Exec (s)  %Total  %CPU    %IO 
-------- ----------------  ----------  -------------------------  ------  ------  ----
1        506               6,164,161   0.00                       85.76   100.53  0.00
2        1,056             10,848,660  0.00                       88.01   100.32  0.00
3        1,614             9,977,224   0.00                       91.07   99.91   0.00
4        2,227             8,172,259   0.00                       93.72   99.69   0.00
5        2,843             6,951,871   0.00                       94.78   99.06   0.00
6        3,493             6,890,154   0.00                       93.93   96.45   0.00
9        5,243             7,245,168   0.00                       64.80   49.04   0.00
12       6,728             7,562,209   0.00                       60.19   36.65   0.00

Latch Sleep Breakdown

Session# Latch Name         Get Requests   Misses       Sleeps     Spin Gets
-------- -----------------  -------------  -----------  ---------  -----------
1        row cache objects  1,109,597,151  633          14         619   
2        row cache objects  1,953,334,110  105,279,309  20,757     105,259,556
3        row cache objects  1,796,543,339  378,078,181  269,547    377,819,261
4        row cache objects  1,471,777,609  541,981,017  632,528    541,369,153
5        row cache objects -3,043,081,012  596,060,413  1,034,539  595,053,127
6        row cache objects  1,229,364,378  689,496,609  1,200,975  688,326,423
9        row cache objects  1,304,630,648  561,205,207  1,091,371  560,171,774
16       row cache objects  1,361,872,758  607,120,518  1,007,494  606,174,258

 * -3,043,081,012 is due to 32-bit overflow, it should be 1,251,886,284 (=2^32 - 3,043,081,012).

Dictionary Cache Stats

Session# Cache     Get Requests  Pc t Miss  Scan Reqs  Pct Miss  Mod Reqs  Final Usage
-------- --------  ------------  ---------  ---------  --------  --------  -----------
1        dc_props  369,850,105   0.00       0                    0         60
2        dc_props  651,060,932   0.00       0                    0         60
3        dc_props  598,832,676   0.00       0                    0         60
4        dc_props  490,574,970   0.00       0                    0         60
5        dc_props  417,291,212   0.00       0                    0         60
6        dc_props  413,622,949   0.00       0                    0         60
9        dc_props  434,872,658   0.00       0                    0         60
12       dc_props  453,953,683   0.00       0                    0         60


4. Discussions


4.1 Top 10 Foreground Events by Total Wait Time


    12cR2 "row cache mutex" has about 2 times less "Waits" than 12cR1 "latch: row cache objects".
    That is the advantage of light-weight "Mutex" over "Latch".
    "Total Wait Time" and "Avg Wait" increase linearly when Session# <= 6 (number of physical processors), non-linearly when > 6.
    12cR2 "row cache mutex" has higher concurrency ("% DB time") than 12cR1 "latch: row cache objects".

    Strangely 12cR2 Mutex "Avg Wait" is much higher than taht of 12cR1 Latch.


4.2 SQL ordered by Elapsed Time


    "Executions" in 12cR2 reaches maximum at Session# = 6, 20% higher than 12cR1 peak value at Session# = 2.
    It means 12cR1 can use less CPU resource to reach its peak value.

    12cR1 has higher throughput than 12cR2 when less Sessions (less than 4); but lower when more Sessions.


4.3 Mutex Sleep Summary vs Latch Sleep Breakdown


    12cR2 "row cache mutex" Sleeps and Wait Time increase non-linearly.
    12cR1 "latch: row cache objects" Misses and Sleeps increase non-linearly although "Get Requests" are almost similar.

    In 12cR1, "Waits" in AWR "Top 10 Foreground Events by Total Wait Time" is close to "Sleeps" in "Latch Sleep Breakdown".
    in 12cR2, it is far from "Sleeps" in "Mutex Sleep Summary".


4.4 Dictionary Cache Stats


    dc_props "Get Requests" depends on query "Executions".
    Each query (SQL Id: 7mgsfc44trnr8) Execution triggers 70 "Get Requests" in 12cR2, and 60 in 12cR1
    since dc_props rows (Field "Final Usage") increased from 60 in 2cR1 to 70 in 12cR2.


5. Test Code


create or replace procedure nls_select(p_cnt number) as
  l_val VARCHAR2 (256 Byte);
begin
for i in 1..p_cnt loop
  select value into l_val from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
end loop;
end;
/

create or replace procedure nls_select_jobs(p_job_cnt number, p_cnt number) as
  l_job_id pls_integer;
begin
  for i in 1.. p_job_cnt loop
    dbms_job.submit(l_job_id, 'begin while true loop nls_select('||p_cnt||'); end loop; end;');
  end loop;
  commit;
end;    
/

create or replace procedure clean_jobs as
begin
  for c in (select job from dba_jobs) loop
    begin
       dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;

  for c in (select d.job, d.sid, (select serial# from v$session where sid = d.sid) ser 
              from dba_jobs_running d) loop
    begin
      execute immediate
             'alter system kill session '''|| c.sid|| ',' || c.ser|| ''' immediate';
      dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;
  
  dbms_lock.sleep(2);
  
  -- select * from dba_jobs;
  -- select * from dba_jobs_running;
end;
/

-- exec nls_select_jobs(2, 1e9);
-- exec clean_jobs; -- stop all jobs

plshprof command-line utility in Oracle 12.2.0.1.0

The plshprof command-line utility generates HTML reports from raw profiler output files.

In Oracle 12.2.0.1.0 (12cR2), plshprof is changed in three aspects:
    (1). only one single HTML file is generated. However, in 12.1.0.2.0 and lower versions, 16 HTML files are generated.
    (2). new Section: SQL ID Elapsed Time (microsecs) Data sorted by SQL ID.
    (3). throws Memory fault when there exist new line characters in raw profiler output files.


1. 16 HTML files assemble in 12.1.0.2.0


In 12.1.0.2.0, plshprof generates 16 HTML files. To faciliate deploying and displaying, they can be congregated into one single file by following shell script (publicly presented in Oracle Open World 2015).


#!/bin/ksh
# USAGE: plshprof.ksh <directory-of-raw-profile> <profile-name>
# Basic script without input checking / exception handling. Use at your own risk. Environment variable ORACLE_BIN must be defined and user must have necessary OS privileges
# Produces even less compliant HTML than plshprof, but all browsers display it nicely.
HPROF_PATH_NAME=$1
HPROF_ROOT_FILE=$2
HPROF_ROOT_FILE_PURE=${HPROF_ROOT_FILE%.*}

cd ${HPROF_PATH_NAME}

${ORACLE_BIN}/plshprof -output ${HPROF_ROOT_FILE_PURE} ${HPROF_ROOT_FILE}

HPROF_INTM_FILE="${HPROF_ROOT_FILE_PURE}"_intm
HPROF_AGGR_FILE="${HPROF_ROOT_FILE_PURE}"_aggr.html

BACK_TOP="<H2 align=\"center\"> <A HREF = ${HPROF_ROOT_FILE_PURE}.html> ↑ Back To Top ↑ </A></H2>"

echo "<P ID=${HPROF_ROOT_FILE_PURE}.html>" > "${HPROF_INTM_FILE}"
cat "${HPROF_ROOT_FILE_PURE}".html >> "${HPROF_INTM_FILE}"
echo "${BACK_TOP}" >> "${HPROF_INTM_FILE}"

keys="ts tf fn td tc ms mf md 2f 2n 2c nsf nsp nsc pc"
for key in $keys
do
    echo "<P ID=${HPROF_ROOT_FILE_PURE}_${key}.html>" >> "${HPROF_INTM_FILE}"
    cat "${HPROF_ROOT_FILE_PURE}"_${key}.html >> "${HPROF_INTM_FILE}"
    echo "${BACK_TOP}" >> "${HPROF_INTM_FILE}"
done

rm "${HPROF_ROOT_FILE_PURE}"_*.html
rm "${HPROF_ROOT_FILE_PURE}".html

sed -e "s/<A HREF = \([^#]\)/<A HREF = #\1/g" \
    -e "s/#"${HPROF_ROOT_FILE_PURE}"_pc.html#/#/g" \
    "${HPROF_INTM_FILE}" > "${HPROF_AGGR_FILE}"

rm "${HPROF_INTM_FILE}"

mv ${HPROF_AGGR_FILE} ${HPROF_ROOT_FILE_PURE}.html
It seems that Oracle 12.2.0.1.0 is trying to incorporate my idea/script into its new plshprof.


2. SQL ID Elapsed Time (microsecs) Data sorted by SQL ID


A new Section:
     SQL ID Elapsed Time (microsecs) Data sorted by SQL ID
is added, which contains:
     SQL ID      SQL TEXT
for SQL statements and dynamic_string in EXECUTE IMMEDIATE Statement (SQL TEXT is cut off to a length of 50).


3. Memory fault in 12.2.0.1.0


Oracle MOS:
     Bug 26789742 : NEW LINE IN DYNAMIC STRING MAKES DBMS_HPROF TO CRASH WITH ORA 3113/7445
reveals Memory fault/SIGSEGV exceptions when there exist new line characters in raw profiler output files.

This BUG is probably related to the above 12cR2 new introduced Section:
     SQL ID Elapsed Time (microsecs) Data sorted by SQL ID
in which "SQL TEXT" could be a dynamic_string containing new line characters.

As documented in Bug 26789742, the Bug can be reproduced with following test:

declare
  l_plshprof_dir     varchar2(20) := 'PLSHPROF_DIR';
  l_filename         varchar2(50) := 'hprof_Bug_26789742.trc';
  l_txt              varchar2(50);
begin
  dbms_hprof.start_profiling(l_plshprof_dir, l_filename, null, true, true);
  
  --put a New Line in the start of dynamic_string.
  execute immediate 
q'[

select 'New Line Bug 26789742 Demo' from dual

]' into l_txt;
  dbms_hprof.stop_profiling;
  
  dbms_output.put_line(l_txt);
 
  --analyzed HTML report in location/filename.html
  --Bug 26789742
  dbms_hprof.analyze(location => l_plshprof_dir, filename => l_filename);
end;
/
Process (Session) abnormally terminated, and trace/incident file showed:

ORA-07445: exception encountered: 
   core dump [PrintSymbolEntriesSymbol1P()+82] [SIGSEGV] 
   [ADDR:0x0] [PC:0xF4405A2] [Address not mapped to object] []
12.2.0.1.0 Test

$ORACLE_HOME/bin/plshprof -output test_4mb test_4mb.trc

PLSHPROF: Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
[7223 symbols processed]
Memory fault
12.1.0.2.0 Test

$ORACLE_HOME/bin/plshprof -output test_4mb test_4mb.trc

PLSHPROF: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
[7223 symbols processed]
[Report written to 'test_4mb.html']


4. New APIs


dbms_hprof in 12cR2 is enhanced with 3 new APIs, demonstrated as follows:

declare
  l_plshprof_dir     varchar2(20) := 'PLSHPROF_DIR';
  l_filename         varchar2(20) := 'hprof_ksun_1.trc';
  l_cnt              number;
  l_sqlmonitor_repot clob;
  l_report_clob      clob;
begin
  dbms_hprof.start_profiling(l_plshprof_dir, l_filename, null, true, true);
  select 123 into l_cnt from dual;
  l_sqlmonitor_repot := dbms_hprof.stop_profiling;
  
  --Real-Time Monitoring report for the profiler run.
  dbms_output.put_line('<!--sqlmonitor_report-->' || l_sqlmonitor_repot);
  
  --analyzed HTML report in location/filename.html
  dbms_hprof.analyze(location => l_plshprof_dir, filename => l_filename);
  
  --analyzed HTML report in report_clob.
  dbms_hprof.analyze(location => l_plshprof_dir, filename => l_filename, report_clob => l_report_clob);
  dbms_output.put_line('<!--hprof_report-->' || l_report_clob);
end;
/

Tuesday, July 3, 2018

12c Online Statistics Gathering for Direct Path Insert and 3 Side Effects

Oracle 12c introduced Online Statistics Gathering for direct path Bulk Loads (CTAS and IAS), documented in:
    Online Statistics Gathering for Bulk Loads 
    Online Statistics Gathering 
This Blog will discuss its side effects in 3 aspects:
    Read Committed (default transaction isolation level)
    Global Temporary Table (GTT)
    Deadlock with MMON Slave Process (Mnnn)
Note: All tests are done in Oracle 12.2.0.1.0


1. Online Statistics Gathering


xplan is adjusted with one additional Row Source line marked as "OPTIMIZER STATISTICS GATHERING". And it is exposed in DBA_TAB_COL_STATISTICS.NOTES column as "STATS_ON_LOAD ".

SQL(100) > drop table test_tab;

SQL(100) > create table test_tab(x number, y number);

SQL(100) > explain plan for insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 4321;

SQL(100) > select * from table(dbms_xplan.display);

    ---------------------------------------------------------------------------------------
    Plan hash value: 1541388231
    
    -------------------------------------------------------------------------------------
    | Id  | Operation                        | Name     | Rows  | Cost (%CPU)| Time     |
    -------------------------------------------------------------------------------------
    |   0 | INSERT STATEMENT                 |          |     1 |     2   (0)| 00:00:01 |
    |   1 |  LOAD AS SELECT                  | TEST_TAB |       |            |          |
    |   2 |   OPTIMIZER STATISTICS GATHERING |          |     1 |     2   (0)| 00:00:01 |
    |*  3 |    CONNECT BY WITHOUT FILTERING  |          |       |            |          |
    |   4 |     FAST DUAL                    |          |     1 |     2   (0)| 00:00:01 |
    -------------------------------------------------------------------------------------

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 4321;

SQL(100) > select owner, table_name, column_name, num_distinct, last_analyzed, '"'||notes||'"'
           from dba_tab_col_statistics 
           where table_name in ('TEST_TAB') and notes like '%STATS_ON_LOAD%';

    OWNER  TABLE_NAME  COLUMN_NAME  NUM_DISTINCT  LAST_ANALYZED         NOTES
    ------ ----------- ------------ ------------- --------------------- ----------------
    K      TEST_TAB    X            4321          2018-JUL-03 08:08:09  "STATS_ON_LOAD "
    K      TEST_TAB    Y            4             2018-JUL-03 08:08:09  "STATS_ON_LOAD "

SQL(100) > commit;
Same as other new features, Oracle provided 3 ways to disable it:
    Statement level hints: 
        no_gather_optimizer_statistics
      or 
        OPT_PARAM('_optimizer_gather_stats_on_load' 'false') 
    Session level: 
        alter session set "_optimizer_gather_stats_on_load"=false;
    System level:
        alter system set "_optimizer_gather_stats_on_load"=false;


2. Read Committed Violation


At first, look the new behaviour of Read Committed as Oracle default transaction isolation level:

---========= (1-1): Session_1@T1 =========---
SQL(100) > drop table test_tab;

SQL(100) > create table test_tab(x number, y number);

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 4321;
    4321 rows created.

---========= (1-2): Session_2@T2 =========---
         
SQL(200) > select table_name, num_rows, last_analyzed from dba_tables where table_name in ('TEST_TAB');
    TABLE_NAME     NUM_ROWS LAST_ANALYZED
    ------------ ---------- --------------------
    TEST_TAB           4321 2018*JUN*29 10:52:41

SQL(200) > explain plan for select * from test_tab; 

SQL(200) > select * from table(dbms_xplan.display);

    ------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |  4321 | 30247 |    30   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS FULL| TEST_TAB |  4321 | 30247 |    30   (0)| 00:00:01 |
    ------------------------------------------------------------------------------      
       
---========= (1-3): Session_1@T3 =========---         
SQL(100) > rollback;

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 1234;
    1234 rows created.
             
---========= (1-4): Session_2@T4 =========---
SQL(200) > select table_name, num_rows, last_analyzed from dba_tables where table_name in ('TEST_TAB');
    TABLE_NAME     NUM_ROWS LAST_ANALYZED
    ------------ ---------- -------------
    TEST_TAB

SQL(200) > explain plan for select * from test_tab; 

SQL(200) > select * from table(dbms_xplan.display);

    ------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |    82 |   574 |     2   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS FULL| TEST_TAB |    82 |   574 |     2   (0)| 00:00:01 |
    ------------------------------------------------------------------------------
Above tests showed that the second session can see the exact number (4321) of inserted rows from first session before committed, hence "Read Committed" broken.

If rollback IAS and insert again, there is no more Online Statistics Gathering. So this feature is only waked up on the first IAS.

As a consequence, Xplan is created based on un-committed data, potentially volatile xplan and unstable performance.


3. Global Temporary Table


Repeat the same test for GTT with commit delete rows.

---========= (2-1): Session_1@T5 =========---         
SQL(100) > rollback;

SQL(100) > drop table test_tab;

SQL(100) > create global temporary table test_tab(x number, y number) on commit delete rows;  

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 4321;
    4321 rows created.


---========= (2-2): Session_2@T6 =========---
         
SQL(200) > select table_name, num_rows, last_analyzed from dba_tables where table_name in ('TEST_TAB');
    TABLE_NAME     NUM_ROWS LAST_ANALYZED
    ------------ ---------- --------------------
    TEST_TAB           4321 2018*JUN*29 11:19:36

SQL(200) > explain plan for select * from test_tab; 

SQL(200) > select * from table(dbms_xplan.display);

    ------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |  4321 | 30247 |    30   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS FULL| TEST_TAB |  4321 | 30247 |    30   (0)| 00:00:01 |
    ------------------------------------------------------------------------------      

---========= (2-3): Session_1@T3 =========---         
SQL(100) > rollback;

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 1234;
    1234 rows created.
             
---========= (2-4): Session_2@T4 =========---
SQL(200) > select table_name, num_rows, last_analyzed from dba_tables where table_name in ('TEST_TAB');
    TABLE_NAME     NUM_ROWS LAST_ANALYZED
    ------------ ---------- --------------------
    TEST_TAB           1234 2018*JUN*29 11:21:16

SQL(200) > explain plan for select * from test_tab; 

SQL(200) > select * from table(dbms_xplan.display);

    ------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |  1234 |  8638 |    30   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS FULL| TEST_TAB |  1234 |  8638 |    30   (0)| 00:00:01 |
    ------------------------------------------------------------------------------
For GTT, other session can also see the exact number (4321) of inserted rows, hence GTT is no more session private.

In contrary to normal table, if rollback IAS and insert again, Online Statistics is re-gathered.

If GTT is created with commit preserve rows, the behavior is similar to normal table.

However Oracle 12c Documentation said that bulk loads do not gather statistics automatically when target table is global temporary table defined as ON COMMIT DELETE ROWS (see Online Statistics Gathering for Bulk Loads ).

The default GTT behaviour ('SHARED') can be turned off by global or table prefs:

exec dbms_stats.set_global_prefs ('GLOBAL_TEMP_TABLE_STATS','SESSION');
exec dbms_stats.set_table_prefs(null, 'TEST_TAB', 'GLOBAL_TEMP_TABLE_STATS', 'SESSION');

select dbms_stats.get_prefs('GLOBAL_TEMP_TABLE_STATS') from dual;


4. Internals


Turn on SQL Trace (10046), perform 3 IAS operations and one CTAS, trace files show the call of dbms_stats.postprocess_stats, which is probably gathering Online Statistics.

IAS - insert
  BEGIN dbms_stats.postprocess_stats(:owner, :tabname, :partname, :subpartname, 2, :rawstats, :selmap, :clist); END; 

IAS - commit
  BEGIN dbms_stats.postprocess_stats(:owner, :tabname, :partname, :subpartname, 1, null, null, null); END; 

IAS - rollback
  BEGIN dbms_stats.postprocess_stats(:owner, :tabname, :partname, :subpartname, 8, null, null, null); END; 

CTAS
  create table test_tab as select level x, mod(level, 4) y from dual connect by level <= 4321;
  BEGIN dbms_stats.postprocess_stats(:owner, :tabname, :partname, :subpartname, 6, :rawstats, :selmap, :clist);  END;   
It looks like that Statistics gathering is controlled by different FLAG (2, 1, 8, 6), where CTAS 6 = 2 + 4.

With dbms_stats Tracing, we can also observe this call:

SQL(300) > execute dbms_stats.set_global_prefs('trace',to_char(1+4+16+2048+65536)); 

SQL(300) > select sname, sval2, spare4 from sys.optstat_hist_control$ where sname in ('TRACE');
    SNAME      SVAL2                          SPARE4
    ---------- ------------------------------ ------
    TRACE      2018-JUN-29 12:10:36 +02:00    67605

SQL(300) > drop table test_tab;
SQL(300) > create table test_tab as select level x, mod(level, 4) y from dual connect by level <= 4321;

  DBMS_STATS: postprocess_stats on KS.TEST_TAB.. tobjn: 2585597 fobjn:
  DBMS_STATS: postprocess online optimizer stats gathering for KS.TEST_TAB: save statistics


5. Deadlock


There exist one background MMON Slave Process (Mnnn, for instance, M002), which is periodically (each 15 minutes in default) spawned to update Online Statistics (Flush KSXM hash table action). If coincidentally one foreground User session performs an IAS or CTAS operation at the same time, it can cause some deadlock as follows (some text removed):

Deadlock graph:
                ---------Blocker(s)--------  ---------Waiter(s)---------
Resource Name   process session holds waits  process session holds waits
TX-001F0003     123     321     X            789    987      S
TX-004C0008     789     987     X            123    321      X

Rows waited on:
  Session 321: obj - rowid = 00000001 
  (dictionary objn - 1, file - 51, block - 2012345, slot - 0)
  Session 987: no row
 
----- Information for the OTHER waiting sessions -----
Session 987:
  sid: 987 ser: 9876 audsid: 0 user: 0/SYS
    image: oracle@testdb (M002)
  current SQL:
    merge /*+ dynamic_sampling(mm 4) dynamic_sampling_est_cdn(mm) dynamic_sampling(m 4) dynamic_sampling_est_cdn(m) */ into sys.mon_mods_all$ mm
 
Information for THIS session:
----- Current SQL Statement for this session (sql_id=cyz7q9n00p23a) -----
update optstat_hist_control$ set sval2 = systimestamp  where sname = 'MON_MODS_ALL_UPD_TIME'   
If we turn on following sql_trace:

alter system set events 'sql_trace [sql:5vf82wpjq5y0v] wait=true, bind=true,plan_stat=first_execution,level=12';

alter system set events 'sql_trace [sql:cyz7q9n00p23a] wait=true, bind=true,plan_stat=first_execution,level=12';

alter system set events 'sql_trace [sql:aahsjvcnr3swn] wait=true, bind=true,plan_stat=first_execution,level=12';
and look both trace files (see Appendix: sql_fulltext):

Unix process pid: 123, image: oracle@testdb (M002)
  *** ACTION NAME:(Flush KSXM hash table action) 2018-06-26 11:15:27.632
 
===================== sql_id=5vf82wpjq5y0v 
select null from optstat_hist_control$ 
where sname = 'MON_MODS_ALL_UPD_TIME' 
  and ((systimestamp - sval2) > INTERVAL '540' SECOND or sval2 is null)
for update

===================== sql_id=aahsjvcnr3swn
merge /*+ dynamic_sampling(mm 4) dynamic_sampling_est_cdn(mm) ynamic_sampling(m 4) dynamic_sampling_est_cdn(m) */                    
 into sys.mon_mods_all$ mm 
 
===================== sql_id=cyz7q9n00p23a 
update optstat_hist_control$ 
   set sval2 = systimestamp where sname = 'MON_MODS_ALL_UPD_TIME'

Unix process pid: 456, image: oracle@testdb

===================== sql_id=aahsjvcnr3swn
merge /*+ dynamic_sampling(mm 4) dynamic_sampling_est_cdn(mm) ynamic_sampling(m 4) dynamic_sampling_est_cdn(m) */                    
 into sys.mon_mods_all$ mm 
 
===================== sql_id=cyz7q9n00p23a 
update optstat_hist_control$ 
   set sval2 = systimestamp where sname = 'MON_MODS_ALL_UPD_TIME'
The above trace files showed that M002 performs:
  select from optstat_hist_control$ for update
  merge into sys.mon_mods_all$
  update optstat_hist_control$ 
whereas User session executes:
  merge into sys.mon_mods_all$
  update optstat_hist_control$ 
The interleaved DML calls on mon_mods_all$ and optstat_hist_control$ probably caused the deadlock.

For all ORA-00060, the trace file is printed with following notice:
  The following deadlock is not an ORACLE error. It is a
  deadlock due to user error in the design of an application
  or from issuing incorrect ad-hoc SQL. The following
  information may aid in determining the deadlock:
In this case, the standard message is probably not addressed to application users.


6. Appendix: sql_fulltext


Here the complete sqltext of above involved statements:

--sql_id=5vf82wpjq5y0v 
 select null
   from optstat_hist_control$
  where     sname = 'MON_MODS_ALL_UPD_TIME'
        and ( (systimestamp - sval2) > interval '540' second or sval2 is null)
 for update

--sql_id=cyz7q9n00p23a 
update sys.optstat_hist_control$ set sval2 = systimestamp  where sname = 'MON_MODS_ALL_UPD_TIME';

--sql_id=aahsjvcnr3swn  (M002)
merge /*+ dynamic_sampling(mm 4) dynamic_sampling_est_cdn(mm) dynamic_sampling(m 4) dynamic_sampling_est_cdn(m) */
     into  sys.mon_mods_all$ mm
     using (select m.obj#          obj#,
                   m.inserts       inserts,
                   m.updates       updates,
                   m.deletes       deletes,
                   m.flags         flags,
                   m.timestamp     timestamp,
                   m.drop_segments drop_segments
              from sys.mon_mods$ m, tab$ t
             where m.obj# = t.obj# and :objn = 0
            union all
            select m.obj#          obj#,
                   m.inserts       inserts,
                   m.updates       updates,
                   m.deletes       deletes,
                   m.flags         flags,
                   m.timestamp     timestamp,
                   m.drop_segments drop_segments
              from sys.mon_mods$ m, tab$ t
             where m.obj# = t.obj# and :objn > 0 and m.obj# = :objn) v
        on (mm.obj# = v.obj#)
when matched
then
  update set mm.inserts = mm.inserts + v.inserts,
             mm.updates = mm.updates + v.updates,
             mm.deletes = mm.deletes + v.deletes,
             mm.flags = mm.flags + v.flags - bitand (mm.flags, v.flags) /* bitor(mm.flags,v.flags) */,
             mm.timestamp = v.timestamp,
             mm.drop_segments = mm.drop_segments + v.drop_segments
when not matched
then
  insert     (obj#,
              inserts,
              updates,
              deletes,
              timestamp,
              flags,
              drop_segments)
      values (v.obj#,
              v.inserts,
              v.updates,
              v.deletes,
              sysdate,
              v.flags,
              v.drop_segments);      

Sunday, April 8, 2018

TM lock and no transaction commit

Oracle Document wrote:
COMMIT
  Use the COMMIT statement to end your current transaction and make permanent all changes performed in the transaction. 
  A transaction is a sequence of SQL statements that Oracle Database treats as a single unit. 
  This statement also erases all savepoints in the transaction and releases transaction locks.

ROLLBACK
  Use the ROLLBACK statement to undo work done in the current transaction or to manually undo the work done by an in-doubt distributed transaction.
It looks like that COMMIT / ROLLBACK are for transactions.

This Blog will show that COMMIT / ROLLBACK has to be executed even without any transactions.

The test code is also trying to reproduce and study MOS:
    Bug 26965236 : DELETE FROM TSDP_SENSITIVE_DATA$ CAUSING ENQ: TM - CONTENTION WAITS

Note: All tests are done in Oracle 12.1.0.2.

------------------ T0: Test SetUp ------------------ 
drop table tt1;

create table tt1 (x number, c1 number, c2 number);

------------------ T1: Session_1------------------ 
SQL(sid 190) > delete from sys.tsdp_sensitive_data$ where 1=2; 
  0 rows deleted.

------------------ T2: Session_2 ------------------ 
SQL(sid 290) > alter table tt1 drop column c2;

-- Session 290 hanging, blocked by 190.
-- same for   alter table k.tt1 set unused (c1);

------------------ T3: Monitor Session_3 ------------------ 
SQL(sid 390) > select o.object_name, k.* from v$lock k, dba_objects o where k.type in ('TM') and k.ID1 = o.object_id;
 
  OBJECT_NAME                    SID  TYPE  ID1      ID2  LMODE  REQUEST  CTIME  BLOCK
  -----------------------------  ---  ----  -------  ---  -----  -------  -----  -----
  TSDP_SENSITIVE_DATA$           190  TM    1576498  0    3      0        14     0    
  TSDP_SUBPOL$                   190  TM    1578689  0    3      0        14     0    
  TSDP_PROTECTION$               190  TM    1578695  0    3      0        14     1    
  TT1                            290  TM    2321087  0    6      0        9      0    
  WRI$_OPTSTAT_HISTHEAD_HISTORY  290  TM    601844   0    3      0        9      0    
  WRI$_OPTSTAT_HISTGRM_HISTORY   290  TM    601856   0    3      0        9      0    
  COM$                           290  TM    136      0    3      0        9      0    
  COL_USAGE$                     290  TM    456      0    3      0        9      0    
  OBJAUTH$                       290  TM    61       0    3      0        9      0    
  TSDP_SENSITIVE_DATA$           290  TM    1576498  0    3      0        9      0    
  TSDP_SUBPOL$                   290  TM    1578689  0    3      0        9      0    
  TSDP_PROTECTION$               290  TM    1578695  0    0      5        9      0    

--TSDP_PROTECTION$  REQUEST = 5
--Session_2 blocked by Session_1 in 'enq: TM - contention' Lock Mode 5 (SSX/SRX)

SQL(sid 390) > select * from v$transaction;
  0 rows selected.
  
  -- no TRX

SQL(sid 390) > select chain_signature, sid, blocker_sid, wait_event_text, p1, p1_text, p2, p2_text, p3, p3_text from v$wait_chains;

  CHAIN_SIGNATURE                                        SID  BLOCKER_SID  WAIT_EVENT_TEXT              P1          P1_TEXT    P2       P2_TEXT   P3  P3_TEXT
  -----------------------------------------------------  ---  -----------  ---------------------------  ----------  ---------  -------  --------  --  ---------------
  'SQL*Net message from client'<='enq: TM - contention'  290  190          enq: TM - contention         1414332421  name|mode  1578695  object #  0   table/partition
  'SQL*Net message from client'<='enq: TM - contention'  190               SQL*Net message from client  1413697536  driver id  1        #bytes    0


SQL(sid 390) > select * from dba_constraints where constraint_name = 'TSDP_PROTECTION$FKSD';

  OWNER  CONSTRAINT_NAME       CONSTRAINT_TYPE  TABLE_NAME        R_CONSTRAINT_NAME       DELETE_RULE  STATUS
  -----  --------------------  ---------------  ----------------  ----------------------  -----------  ------
  SYS    TSDP_PROTECTION$FKSD  R                TSDP_PROTECTION$  TSDP_SENSITIVE_DATA$PK  CASCADE      ENABLED


-- Suspending LGWR will not block commit in Session_1
--SQL> oradebug setorapid 13
--  Oracle pid: 13, Unix process pid: 18482, image: oracle@testdb (LGWR)
--SQL> oradebug suspend
--SQL> oradebug resume

------------------ T4: Session_1, Release TM Locks to deblock ------------------ 
SQL(sid 290) > commit;
One quick workaround is to disable the foreign key constraint if Transparent Sensitive Data Protection is not used.

  alter table sys.tsdp_protection$ disable constraint tsdp_protection$fksd;
If we suspend LGWR in Session_3 (see commented-out code), and repeat the whole test, the "commit" in Session_1 will not be blocked. It indicates no "commit record" written to redo log for this "commit" execution, in other words, not every "commit" generates a "commit record".

With event 10704, we can list all triggered TM Locks. (see Blog: Investigating Oracle lock issues with event 10704 )

SQL(sid 290) > alter session set events='10046 trace name context forever, level 1 : 10704 trace name context forever, level 3' tracefile_identifier='ksun_10704_1';

SQL(sid 290) > alter table tt1 drop column c1;

SQL(sid 290) > alter session set events='10046 trace name context off : 10704 trace name context off ';


ksqgtl *** TM-00236ABF-00000000-00000000-00000000 mode=6 flags=0x400 timeout=5 ***
...
ksqgtl *** TM-001816C7-00000000-00000000-00000000 mode=5 flags=0x400 timeout=21474836 ***
ksqcnv: TM-001816C7-00000000-00000000-00000000 mode=3 timeout=21474836
ksqcmi: TM-001816C7-00000000-00000000-00000000 mode=3 timeout=21474836
ksqrcl: TM-001816C7-00000000-00000000-00000000
...
ksqrcl: TM-00236ABF-00000000-00000000-00000000

  -- 00236ABF (2321087) = TT1
  -- 001816C7 (1578695) = SYS.TSDP_PROTECTION$
  
  -- ksqgtl: get lock 
  -- ksqcnv: convert lock
  -- ksqcmi: 
  -- ksqrcl: release lock
We can see that DDL_LOCK_TIMEOUT = 5 seconds has no effect in this case (line with "TM-00236ABF" for TT1). TM lock on SYS.TSDP_PROTECTION$ ("TM-001816C7") is first obtained in MODE 5 (SRX), then converted to 3 (RX).

Tuesday, March 6, 2018

'enq: RO - fast object reuse' and 'enq: KO - fast object checkpoint' Final Blocker

In Wait Event: 'enq: RO - fast object reuse' and 'enq: KO - fast object checkpoint', CKPT is shown as final_blocking_session when one DBWR is suspended.

V$ENQUEUE_STATISTICS gives detailed information (several rows for same enqueues with different reasons) and statistics.

select * from v$enqueue_statistics where eq_type in ('RO', 'KO');

EQ_NAME                    EQ REQ_REASON             TOTAL_REQ# TOTAL_WAIT# SUCC_REQ# FAILED_REQ# CUM_WAIT_TIME REQ_DESCRIPTION                         
-------------------------- -- ---------------------- ---------- ----------- --------- ----------- ------------- ----------------------------------------
Multiple Object Reuse      RO fast object reuse           1,039          82     1,038           0     1,040,219 Coordinates fast object reuse
Multiple Object Reuse      RO contention                      0           0         0           0             0 Coordinates flushing of multiple objects   
Multiple Object Checkpoint KO fast object checkpoint         60           6        60           0       870,104 Coordinates fast object checkpoint        
Reuse Block Range          CR block range reuse ckpt      1,848          15     1,848           0            20 Coordinates fast block range reuse ckpt
If (TOTAL_REQ# - SUCC_REQ# > 0 and FAILED_REQ# = 0), there exists on-going EQ requests.

Note: All tests are done in Oracle 12.1.0.2 on Solaris.


1. Test Setup



--Test DB is configured with:
--  db_writer_processes=2
   
drop table tab1;

create table tab1 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 


2. 'enq: KO - fast object checkpoint' Test


Suspend one of DB WRITERs, for example, DBW1:

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.
Run query:

SQL (543) > select /*+ parallel(t 4) */ count(*) from tab1 t where x < 100000;
Both blocker_sid and final_blocking_session are same, that is, CKPT (SID: 361):

SQL (123) > select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
            from v$wait_chains c, v$session s
            where c.sid = s.sid order by c.chain_id, s.program;

CHAIN_ID CHAIN_SIGNATURE                                         SID BSID FINAL_BSID PROGRAM     SQL_ID        EVENT
-------- ------------------------------------------------------- --- ---- ---------- ----------- ------------- -------------------------------
       1 'rdbms ipc message'<='enq: KO - fast object checkpoint' 361                 (CKPT)                    rdbms ipc message
       1 'rdbms ipc message'<='enq: KO - fast object checkpoint' 543 361         361 sqlplus.exe 4wwzmhypuvnc6 enq: KO - fast object checkpoint

SQL (123) > select sql_id, executions, substr(sql_text, 1, 60) sql_text from v$sql v where sql_id = '4wwzmhypuvnc6';

SQL_ID        EXECUTIONS SQL_TEXT
------------- ---------- ------------------------------------------------------------
4wwzmhypuvnc6          0 select /*+ parallel(t 4) */ count(*) from tab1 t where x < 1
After test, resume DBW1:

SQL> oradebug resume
By the way, to make above behavior repeatable, each time tab1 has to be dropped and recreated.


3. 'enq: RO - fast object reuse' Test


Again suspend DBW1:

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.
Run statement:

SQL (543) > truncate table tab1;
Both blocker_sid and final_blocking_session are same, that is, CKPT (SID: 361):

SQL (123) > select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
            from v$wait_chains c, v$session s
            where c.sid = s.sid order by c.chain_id, s.program;
            
CHAIN_ID CHAIN_SIGNATURE                                    SID BSID FINAL_BSID PROGRAM     SQL_ID        EVENT
-------- -------------------------------------------------- --- ---- ---------- ----------- ------------- ---------------------------
       1 'rdbms ipc message'<='enq: RO - fast object reuse' 361                 (CKPT)                    rdbms ipc message
       1 'rdbms ipc message'<='enq: RO - fast object reuse' 543  361        361 sqlplus.exe 83w7b0h5ug6ph enq: RO - fast object reuse  
       
SQL (123) > select sql_id, executions, substr(sql_text, 1, 60) sql_text from v$sql v where sql_id = '83w7b0h5ug6ph';         

SQL_ID        EXECUTIONS SQL_TEXT
------------- ---------- -------------------
83w7b0h5ug6ph          0 truncate table tab1     
After test, resume DBW1:

SQL> oradebug resume  
By the way, we observed: "enq: CR - block range reuse ckpt", also blocked by CKPT, when running PL/SQL bulk SQL "forall insert into values".


4. FINAL_BLOCKING_SESSION


In both above tests, CKPT is shown as final_blocking_session, but in reality, that is DBW1 suspended. The reason is probably because Foreground process only communicates with CKPT, and has no direct IPC call of DB WRITER processes.

Oracle MOS documented this behavior:
    MOS Resolving Issues Where 'enq: RO - fast object reuse' Contention Seen During Drop or Truncate Operations (Doc ID 1475659.1)
The RO enqueue known as "Multiple object reuse" enqueue, is used to synchronise operations between foreground process 
and a background process such as DBWR or CKPT. It is typically used when dropping objects or truncating tables.
Following is the sequence of events When a truncate/drop occurs:
  1.Foreground process acquires the "RO" enqueue in exclusive mode
  2.Cross instance calls (or one call if it is a single object) are issued ("CI" enqueue is acquired)
  3.CKPT Processes on each of instances requests the DBWR to write the dirty buffers to the disk and invalidate all the clean buffers.
  4.After DBWR completes writing all blocks, the foreground process releases the RO enqueue.


5. Discussions


KO enqueue is triggered by SELECT table FULL scan, which requires writing all dirty buffer blocks into disk datafiles and updating Extent Bitmap in Segment Header Extent.

RO enqueue is triggered by TRUNCATE table, which requires cleaning up (write) segment header (bitmap info), that is the 2nd Block (Extent Bitmap) in Segment Header Extent for small table.

When both enqueues appear in top Wait Events, following Events can be also observed:
  free buffer waits
  buffer busy waits
  local write wait
  write complete waits
For "free buffer waits", P3 (set-id#) reveals the responsible DBWR.

Blog: ASSM Truncate demonstrated RO enqueue when truncating table with big "INITIAL", and explained that the blocks written were the space management bitmap blocks for the extent(s) that remained after the truncate (storage_clause "INITIAL" specifies the size of the first extent of the object. Oracle allocates space for this extent when you create the schema object).


6. row cache lock


In 'enq: RO - fast object reuse' Test, if we open one more Sqlplus Session (SID=726) and perform the same tab1 truncate, we observe "row cache lock" with "cache id = 8" (dc_objects/dc_object_grants).

drop table tab1;
create table tab1 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.

SQL (543) > truncate table tab1;

SQL (726) > truncate table tab1;

select c.wait_event_text, c.sid, c.blocker_sid bsid, s.final_blocking_session final_bsid, 
       s.program, s.sql_id, s.p1text, s.p1, s.p2text, s.p2, s.p3text, s.p3
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

WAIT_EVENT_TEXT             SID BSID FINAL_BSID PROGRAM      SQL_ID        P1TEXT               P1  P2TEXT      P2  P3TEXT  P3
--------------------------- --- ---- ---------- ------------ ------------- --------- -------------  ------  ------  ------  --
rdbms ipc message           361                  (CKPT)                    timeout             300              0            0
row cache lock              726  543        361  sqlplus.exe 83w7b0h5ug6ph cache id              8  mode        0   request  3
enq: RO - fast object reuse 543  361        361  sqlplus.exe 83w7b0h5ug6ph name|mode 1,380,909,062  2       65,563  0        1
If we create one second table (tab2), and let new Sqlplus Session (SID=726) truncate tab2, both sessions are on "enq: RO - fast object reuse", no more "row cache lock" observed.

drop table tab1;
create table tab1 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 

drop table tab2;
create table tab2 as select level x, rpad('ABC', 100, 'X') y from dual connect by level < 1000000; 

SQL> oradebug setorapid 12
Oracle pid: 12, Unix process pid: 19980, image: oracle@s5d00003 (DBW1)
SQL> oradebug suspend
Statement processed.

SQL (543) > truncate table tab1;

SQL (726) > truncate table tab2;

select c.wait_event_text, c.sid, c.blocker_sid bsid, s.final_blocking_session final_bsid, 
       s.program, s.sql_id, s.p1text, s.p1, s.p2text, s.p2, s.p3text, s.p3
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

WAIT_EVENT_TEXT             SID BSID FINAL_BSID PROGRAM      SQL_ID        P1TEXT               P1  P2TEXT      P2  P3TEXT  P3
--------------------------- --- ---- ---------- ------------ ------------- --------- -------------  ------  ------  ------  --
rdbms ipc message           361                  (CKPT)                    timeout             300              0            0
enq: RO - fast object reuse 543  361        361  sqlplus.exe 83w7b0h5ug6ph name|mode 1,380,909,062  2       65,563  0        1
enq: RO - fast object reuse 726  361        361  sqlplus.exe 2wdshw3gfd81s name|mode 1,380,909,062  2       65,564  0        1

select sql_id, executions, substr(sql_text, 1, 60) sql_text 
from v$sql v where sql_id in ('83w7b0h5ug6ph', '2wdshw3gfd81s');

SQL_ID        EXECUTIONS SQL_TEXT
------------- ---------- -------------------
2wdshw3gfd81s          0 truncate table tab2
83w7b0h5ug6ph          0 truncate table tab1

Oracle 12.1 Wait Event: 'log file sync: SCN ordering' Demo

Oracle MOS Document:
         What is the Difference Between 'log File Sync: SCN Ordering' and 'log File Sync' (Doc ID 2363231.1)
    Log file sync: SCN ordering is a new wait event introduced in 12.1.
    
    This wait event is triggered when an operation such as a direct path load compares the current SCN against the last on-disk commit SCN.
      
    Before an SCN can be written to a datafile, a check is performed to ensure that an SCN larger than 
    the SCN needed to maintain "crash delta" has already been written to redo.
      
    If the check determines that the SCN to be written to the datafile is greater than that currently needed in the redo logs, 
    LGWR will be posted to force some redo to disk, independent of a commit.
      
    If no actual redo with an appropriate SCN is available in the log buffer, it is possible that an empty redo record may be written 
    to the redo logs to satisfy the need to have the higher SCN.
      
    Prior to 12.1, the time spent waiting for redo being written by LGWR for this purpose was included in the main "log file sync" wait.
    
    Starting in 12.1, it is now tracked separately as "log file sync: SCN ordering". It was separated out 
    because it is not related to transaction commit wait for log file write.
In short, 'log File Sync: SCN Ordering' is 'log File Sync' not triggered by transaction commit.
There exists one non-commit SCN to be written to a datafile, which is bigger than last LGWR SCN.
LGWR is in charge of sequentially ("ordering") writing all SCN between last LGWR SCN and non-commit SCN to Redo Log.

In this Blog, we will try to demonstrate Wait Event: 'log file sync: SCN ordering' without any COMMIT (ROLLBACK) statements.

Note: All tests are done in Oracle 12.1.0.2 on Solaris with 6 CPUs.


1. Test


Test DB is configured as:
   shared_pool_size=1408M
   log_buffer=128M       (note: real allocated is 140M)
   db_cache_size=2000M
   db_writer_processes=2
   cpu_count=6
Launch Test (see appended Test Code):

exec test_upd_no_commit_job(4);
exec test_load_as_select_job(2);
When all 6 Jobs are visible in dba_jobs_running, we can see 6 transactions, 2 of which are select statements with materialized subquery factoring clause (WITH clause).

SQL > select s.sid, s.program, s.sql_id, t.addr, t.status, t.start_time, t.start_scn 
      from v$transaction t, v$session s where t.addr = s.taddr order by s.program;

SID  PROGRAM               SQL_ID         ADDR              STATUS  START_TIME                   START_SCN
---  --------------------  -------------  ----------------  ------  -------------------  -----------------
 15  oracle@testdb (J000)  5h3nqwh6fdw66  0000000184EBA498  ACTIVE  2018-03-06 07:17:16  9,332,237,391,411
727  oracle@testdb (J001)  a3376g221j75v  0000000184FA3B38  ACTIVE  2018-03-06 07:31:22  9,332,237,491,530
370  oracle@testdb (J002)  5h3nqwh6fdw66  0000000184EBBBD8  ACTIVE  2018-03-06 07:17:16  9,332,237,391,419
549  oracle@testdb (J003)  5h3nqwh6fdw66  0000000186A2C818  ACTIVE  2018-03-06 07:17:16  9,332,237,391,757
192  oracle@testdb (J004)  a3376g221j75v  0000000184FA46D8  ACTIVE  2018-03-06 07:31:22  9,332,237,491,538
545  oracle@testdb (J005)  5h3nqwh6fdw66  0000000186BB3778  ACTIVE  2018-03-06 07:17:16  9,332,237,392,203
  
SQL > select sql_id, executions, substr(sql_text, 1, 50) sql_text 
      from v$sql where sql_id in ('a3376g221j75v', '5h3nqwh6fdw66');

SQL_ID        EXECUTIONS  SQL_TEXT
------------- ----------- --------------------------------------------------
a3376g221j75v      11,254 WITH SQ1 AS (SELECT /*+ materialize */ LEVEL X FRO
5h3nqwh6fdw66     392,362 UPDATE TEST_TAB SET VAL = 'Upd_'||:B2 WHERE ID = :  
Suspend LGWR:

SQL> oradebug setorapid 13
Oracle pid: 13, Unix process pid: 18482, image: oracle@testdb (LGWR)
SQL> oradebug suspend
after about 10 minutes, we can see blocking chains:

select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

CHAIN_ID CHAIN_SIGNATURE                                                         SID  BSID  FINAL_BSID PROGRAM SQL_ID        EVENT
-------- ----------------------------------------------------------------------- ---- ----- ---------- ------- ------------ ---------------------------
       1 'rdbms ipc message'<='log file sync'                                       8 181          181 (J010)               log file sync
       1 'rdbms ipc message'<='log file sync'                                     181                  (LGWR)               rdbms ipc message
       2 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'   15 545          181 (J000) 5h3nqwh6fdw66 buffer busy waits
       2 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'  545 181          181 (J005) 5h3nqwh6fdw66 log file sync: SCN ordering
       3 'rdbms ipc message'<='log file sync'                                     189 181          181 (J011)               log file sync
       4 'rdbms ipc message'<='log file sync: SCN ordering'                       192 181          181 (J004) a3376g221j75v log file sync: SCN ordering
       5 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'  370 545          181 (J002) 5h3nqwh6fdw66 buffer busy waits
       6 'rdbms ipc message'<='log file sync'                                     548 181          181 (J007)               log file sync
       7 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'  549 545          181 (J003) 5h3nqwh6fdw66 buffer busy waits
       8 'rdbms ipc message'<='log file sync: SCN ordering'<='buffer busy waits'  719 545          181 (SMON)               buffer busy waits
       9 'rdbms ipc message'<='log file sync'                                     726 181          181 (J008)               log file sync
      10 'rdbms ipc message'<='log file sync: SCN ordering'                       727 181          181 (J001) a3376g221j75v log file sync: SCN ordering
      11 'rdbms ipc message'<='log file sync'                                     899 181          181 (J006)               log file sync
      12 'rdbms ipc message'<='log file sync'                                     903 181          181 (J009)               log file sync
Above output shows that only two non-commit sessions (SID; 192, 727 with SQL_ID: a3376g221j75v) hit Wait Event "log file sync: SCN ordering".

Look 'sync scn':
                                                                                                           
select distinct * from (
  select event, min(p2) over (partition by event) min_scn, max(p2) over (partition by event) max_scn
  from v$session 
  where p2text = 'sync scn' and event in ('log file sync',  'log file sync: SCN ordering')
) order by min_scn;

EVENT                             MIN_SCN        MAX_SCN
--------------------------- -------------  -------------
log file sync               3,568,537,824  3,568,549,488
log file sync: SCN ordering 3,568,549,406  3,568,549,406
which shows that SCN of 'log file sync: SCN ordering' falls between min and max SCN of 'log file sync' (3,568,537,824 < 3,568,549,406 < 3,568,549,488), in other words, there exists one SCN of 'log file sync' which is smaller than that of 'log file sync: SCN ordering' and one SCN of 'log file sync' which is bigger than that of 'log file sync: SCN ordering'. Probably that is the reason and result of 'SCN ordering'.

After the test, resume LGWR and clean up all Jobs:

SQL> oradebug resume
SQL> exec clean_jobs;
Collect AWR and ASH reports for the test interval, we can see:

Top 10 Foreground Events by Total Wait Time

Event Waits Total Wait Time (sec) Avg wait (ms) % DB time Wait Class
log file sync 14 7986.1 570437.20 29.5 Commit
buffer busy waits 23,544 4142.6 175.95 15.3 Concurrency
log file sync: SCN ordering 3 4139.8 1.4E+06 15.3 Concurrency
DB CPU 2184.4 8.1

Top SQL with Top Events

SQL ID %Activity Event %Event Top Row Source SQL Text
5h3nqwh6fdw66 32.83 buffer busy waits 19.35 UPDATE UPDATE TEST_TAB SET VAL = 'Upd..
CPU + Wait for CPU 7.03 TABLE ACCESS - FULL
log file sync: SCN ordering 6.45 UPDATE
a3376g221j75v 16.40 log file sync: SCN ordering 12.90 TEMP TABLE TRANSFORMATION WITH SQ1 AS (SELECT /*+ materi...
CPU + Wait for CPU 3.45 CONNECT BY - WITHOUT FILTERING

Occasionally we also observed statement:

  SQL ID:   g4gp07gt2z920 
  SQL Text: update sys.scheduler$_job set last_start_date = :1, running_instance = :2, running_slave = :3, job_status = :4 where obj# = :5
is blocked by 'log file sync: SCN ordering'.

In the above test, log_buffer is purposely set as a large value (128M). If we reduce it to a small value, for example, 2M (note: real allocated is 12M)

SQL> alter system set log_buffer=2M scope=spfile; 
SQL> startup force;
Repeat the same test by suspending LGWR. The blocking chains will be:

select c.chain_id, c.chain_signature, c.sid, c.blocker_sid bsid, final_blocking_session final_bsid, s.program, s.sql_id, s.event
from v$wait_chains c, v$session s
where c.sid = s.sid order by c.chain_id, s.program;

CHAIN_ID CHAIN_SIGNATURE                                              SID  BSID FINAL_BSID PROGRAM SQL_ID        EVENT
-------- ------------------------------------------------------------ ---- ---- ---------- ------- ------------- -----------------
       1 'rdbms ipc message'<='log buffer space'                      186  181         181 (J001)  a3376g221j75v log buffer space 
       1 'rdbms ipc message'<='log buffer space'                      181                  (LGWR)                rdbms ipc message
       2 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 367  547         181 (J002)  5h3nqwh6fdw66 buffer busy waits
       2 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 547  181         181 (J003)  5h3nqwh6fdw66 log buffer space 
       3 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 724  181         181 (J004)  a3376g221j75v log buffer space 
       3 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 542  724         181 (MMON)                buffer busy waits
       4 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 545  547         181 (J000)  5h3nqwh6fdw66 buffer busy waits
       5 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 719  724         181 (SMON)                buffer busy waits
       6 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 902    8         181 (CJQ0)  c96x1j3nt4suf buffer busy waits
       6 'rdbms ipc message'<='log buffer space'<='buffer busy waits'   8  181         181 (J006)  g4gp07gt2z920 log buffer space 
       7 'rdbms ipc message'<='log buffer space'<='buffer busy waits' 905  547         181 (J005)  5h3nqwh6fdw66 buffer busy waits
No 'log file sync: SCN ordering' is visible because sessions are blocked by 'log buffer space' at first, and no more 'log file sync: SCN ordering' occurs.

From above blocking chains, we can see SMON, MMON and CJQ0 are also blocked by Job sessions, but all final_blocking_session are LGWR.

As a tradition, in Oracle, all popular terms are named twice, log_buffer is not an exception:
  V$SGAINFO.name='Redo Buffers'
  V$SGASTAT.name='log_buffer'


2. MMON ORA_12751_DUMP


During test, we also observed MMON ORA-12751 errors dump:

Unix process pid: 19998, image: oracle@testdb (MMON)
----- START DDE Action: 'ORA_12751_DUMP' (Sync) -----
Runtime exceeded 300 seconds
Time limit violation detected at:
ksedsts()+439<-kspol_12751_dump()+81<-dbgdaExecuteAction()+384<-dbgerRunAction()+105<-dbgerRunActions()+2117<-dbgexProcessError()+2271
<-dbgePostErrorKGE()+2169<-dbkePostKGE_kgsf()+58<-kgeade()+369<-kgeselv()+94<-ksesecl0()+181<-kcbzwb()+8821<-kcbgtcr()+84390
<-ktucloUsMinScn()+527<-ktucloUsegScan()+1017<-ksb_run_managed_action()+456<-ksbcti()+2029<-ksbabs()+2231<-ksbrdp()+1734<-opirip()+844
<-opidrv()+651<-sou2o()+122<-opimai_real()+317<-ssthrdmain()+558<-main()+164<-_start()+123Current Wait Stack:
 0: waiting for 'buffer busy waits'
    file#=0x3, block#=0x23c0, class#=0x11
    wait_id=1873 seq_num=1874 snap_id=1
    wait times: snap=5 min 6 sec, exc=5 min 6 sec, total=5 min 6 sec
    wait times: max=infinite, heur=5 min 6 sec
    wait counts: calls=306 os=306
    in_wait=1 iflags=0x15a2
There is at least one session blocking this session.
  Dumping 1 direct blocker(s):
    inst: 1, sid: 724, ser: 1289
  Dumping final blocker:
    inst: 1, sid: 181, ser: 52654
...
sample interval: 1 sec, max history 120 sec
---------------------------------------------------
  [121 samples,                                            09:07:49 - 09:09:49]
    waited for 'buffer busy waits', seq_num: 1874
      p1: 'file#'=0x3
      p2: 'block#'=0x23c0
      p3: 'class#'=0x11
      time_waited: >= 120 sec (still in wait)
---------------------------------------------------
Sampled Session History Summary:
  longest_non_idle_wait: 'buffer busy waits'
  [121 samples, 09:07:49 - 09:09:49]
      time_waited: >= 120 sec (still in wait)
---------------------------------------------------
----- END DDE Action: 'ORA_12751_DUMP' (SUCCESS, 3 csec) -----
----- END DDE Actions Dump (total 3 csec) -----
KEBM: MMON action policy violation. 'Block Cleanout Optim, Undo Segment Scan' viol=1; err=12751                                                                  
where 'class#'=0x11 (Decimal 17) indicates that MMON is 'buffer busy waits' on 'undo header'.

'ORA_12751_DUMP' is mentioned in MOS Docu:
    AWR Snapshots Fail to Generate With Associated "Suspending MMON action '%s' for 82800 seconds" alert log messages and Underlying ORA-12751 Errors (Doc ID 2043531.1)

As we know MMON (MMNL) is responsible to flush 1 out of 10 V$ACTIVE_SESSION_HISTORY (memory Circular Buffer in SGA) into disk DBA_HIST_ACTIVE_SESS_HISTORY each Snapshot interval or out-of-space by a direct path load (insert), which matches precisely what Doc ID 2363231.1 mentioned.


3. Test Code



drop table test_tab;
              
create table test_tab 
   INITRANS   26           -- prevent Segments ITL Waits and Deadlocks. 
as select level id, rpad('ABC', 100, 'X') val from dual connect by level <= 100;

create or replace procedure test_upd_no_commit(p_id number) is
begin
 for i in 1..1000000 loop
   update test_tab set val = 'Upd_'||i where id = p_id;
 end loop;
end;
/

create or replace procedure test_upd_no_commit_job(p_job_cnt number) as
  l_job_id pls_integer;
begin
  for i in 1..p_job_cnt loop
    dbms_job.submit(l_job_id, 'begin while true loop test_upd_no_commit('||i||'); end loop; end;');
  end loop;
  commit;
end;    
/

create or replace procedure test_load_as_select is
  type  num_tab is table of number;
 l_tab num_tab;
begin
  for i in 1..1000000 loop
   with sq1 as (select /*+ materialize */ level x from dual connect by level <= 1000000)
       ,sq2 as (select /*+ materialize */ x from sq1 where x <= 999999)
       ,sq3 as (select /*+ materialize */ x from sq1 where x <= 888888)
   select x bulk collect into l_tab from sq3
   where x <= 3; 
 end loop;
end;
/

create or replace procedure test_load_as_select_job(p_job_cnt number) as
  l_job_id pls_integer;
begin
  for i in 1..p_job_cnt loop
    dbms_job.submit(l_job_id, 'begin while true loop test_load_as_select; end loop; end;');
  end loop;
  commit;
end;    
/

create or replace procedure clean_jobs as
begin
  for c in (select job from dba_jobs) loop
    begin
       dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;

  for c in (select d.job, d.sid, (select serial# from v$session where sid = d.sid) ser 
              from dba_jobs_running d) loop
    begin
      execute immediate
             'alter system kill session '''|| c.sid|| ',' || c.ser|| ''' immediate';
      dbms_job.remove (c.job);
    exception when others then null;
    end;
    commit;
  end loop;
  
  -- select * from dba_jobs;
  -- select * from dba_jobs_running;
end;
/