Oracle Temp Space Usage Monitoring and View v$tempseg_usage

v$tempseg_usage reports temp space usage per session. This Blog will first examine its coverage in two aspects: temp object creations and sql executions, then discuss Temp Space Usage Monitoring in queries, trace, and dump.

Note: Tested in Oracle 19c with following settings:

  locally managed uniform temporary tablespace (extent=256 8K blocks)
  db_block_size        = 8192
  pga_aggregate_target = 400M
  db_cache_size        = 2000M
  temp_undo_enabled    = TRUE
  nls_length_semantics = CHAR
  db_files             = 3072
  temp file maxsize    = 8000M

1. v$tempseg_usage and v$sort_usage

v$tempseg_usage (9i onwards) is v$sort_usage, which is retained for backward compatibility and removed from Oracle Docu.

gv$tempseg_usage is a synonym for sys.gv_$sort_usage and defined as follows:

CREATE OR REPLACE FORCE VIEW SYS.GV_$SORT_USAGE as
SELECT so.inst_id                                       INST_ID,       
       username                                         USERNAME,      
       username                                         "USER",        
       ktssoses                                         SESSION_ADDR,  
       ktssosno                                         SESSION_NUM,   
       prev_sql_addr                                    SQLADDR,       
       prev_hash_value                                  SQLHASH,       
       prev_sql_id                                      SQL_ID,        
       ts.name                                          TABLESPACE,    
       DECODE (ktssotbst, 1, 'TEMPORARY', 'PERMANENT')  CONTENTS,      
       DECODE (ktssosegt, 1, 'SORT',
                          2, 'HASH',
                          3, 'DATA',
                          4, 'INDEX',
                          5, 'LOB_DATA',
                          6, 'LOB_INDEX',
                          7, 'TEMP_UNDO',
                             'UNDEFINED')               SEGTYPE,        
       ktssofno                                         SEGFILE#,       
       ktssobno                                         SEGBLK#,        
       ktssoexts                                        EXTENTS,        
       ktssoblks                                        BLOCKS,         
       ktssorfno                                        SEGRFNO#,       
       ktssotsnum                                       TS#,            
       so.con_id                                        CON_ID,         
       ktssosqlid                                       SQL_ID_TEMPSEG  
  FROM x$ktsso so, v$session, v$tablespace ts
WHERE     so.ktssotsnum = ts.ts#
       AND so.con_id = ts.con_id
       AND ktssoses = v$session.saddr
       AND ktssosno = v$session.serial#

SEGTYPE indicates 7 different types of temp segments. In Oracle 19c Docu, it is noted as "Type of sort segment", and only first 6 types are listed. 'TEMP_UNDO' is not included, due to 12c new introduced "temp_undo_enabled"
(Note: Temp LOB_INDEX seems special, see later discussion).

2. Temp Object Creations

First we create a temp table including 5 different temp segment types: DATA, INDEX, LOB_INDEX, LOB_DATA, TEMP_UNDO. And fill it with 1000 rows.

truncate table temp_tab;
drop table temp_tab;
create global temporary table temp_tab(a number, b clob) on commit preserve rows;
create index temp_tab#i1 on temp_tab(a);
 
insert /*+ append */ into temp_tab select level, rpad('ABC', 7000, 'X') from dual connect by level <= 1e3;
commit;

Then we list all created temp segments (test session id = 123):

select s.sid, t.tablespace, t.segtype, t.blocks, t.sql_id_tempseg, substr(a.sql_text, 1, 110) sql_text --, t.*
  from v$tempseg_usage t, v$session s, v$sqlarea a
 where t.session_addr=s.saddr and t.sql_id_tempseg = a.sql_id and sid = 123
 order by t.segtype, t.blocks;
 
  SID TABL SEGTYPE    BLOCKS SQL_ID_TEMPSEG SQL_TEXT
  --- ---- ---------- ------ -------------- ---------------------------------------------------------------------------------------------------------
  123 TEMP DATA          256 d61k5majnv4mb  insert /*+ append */ into temp_tab select level, rpad('ABC', 7000, 'X') from dual connect by level <= 1e3
  123 TEMP INDEX         256 d61k5majnv4mb  insert /*+ append */ into temp_tab select level, rpad('ABC', 7000, 'X') from dual connect by level <= 1e3
  123 TEMP INDEX         256 d61k5majnv4mb  insert /*+ append */ into temp_tab select level, rpad('ABC', 7000, 'X') from dual connect by level <= 1e3
  123 TEMP LOB_DATA     1024 d61k5majnv4mb  insert /*+ append */ into temp_tab select level, rpad('ABC', 7000, 'X') from dual connect by level <= 1e3
  123 TEMP TEMP_UNDO     256 d61k5majnv4mb  insert /*+ append */ into temp_tab select level, rpad('ABC', 7000, 'X') from dual connect by level <= 1e3

We can aslo query underlined x$ktsso to reveal TEMP_OBJECT_ID and TEMP_DATA_OBJECT_ID (not exposed in v$tempseg_usage).
We can also see that names of LOB object and index are composed by table OBJECT_ID (4080456) with prefix "SYS_LOB"/"SYS_IL" and suffix "C00002$$".

-- sys.x_ktsso is x$ktsso
select s.sid, s.serial#, g.ktssoobjn temp_object_id, g.ktssoobjd temp_data_object_id, o.object_name, g.ktssosegt segtype, g.ktssoblks blocks,
       temporary, generated, g.ktssosqlid sql_id_tempseg --, a.sql_text, g.*
  from sys.x_ktsso g, v$session s, v$sqlarea a, dba_objects o
where g.ktssoses=s.saddr and g.ktssosqlid = a.sql_id and g.ktssoobjn=o.object_id(+) and s.sid=123
 order by g.ktssoobjn, g.ktssoblks;
 
  SID SERIAL# TEMP_OBJECT_ID TEMP_DATA_OBJECT_ID OBJECT_NAME               SEGTYPE     BLOCKS TEMPORARY GENERATED SQL_ID_TEMPSEG
  --- ------- -------------- ------------------- ------------------------- ------- ---------- --------- --------- ---------------
  123   10733              0             4311680                                 7        256                     d61k5majnv4mb
  123   10733        4080456             4349312 TEMP_TAB                        3        256 Y         N         d61k5majnv4mb
  123   10733        4080457             4376960 SYS_LOB0004080456C00002$$       5       1024 Y         Y         d61k5majnv4mb
  123   10733        4080458             4333440 SYS_IL0004080456C00002$$        4        256 Y         Y         d61k5majnv4mb
  123   10733        4080459             4327040 TEMP_TAB#I1                     4        256 Y         N         d61k5majnv4mb

In the above output, TEMP_DATA_OBJECT_ID=4311680 is with SEGTYPE=7, that is 'TEMP_UNDO' according to GV_$SORT_USAGE (there will be no 'TEMP_UNDO' if set "temp_undo_enabled = false").

Each temp segment is session specific, and is created as a distinct object in each session.
It has a unique DATA_OBJECT_ID, that means one different DATA_OBJECT_ID per session
(non-temp segment has the same DATA_OBJECT_ID in DB-wide for all the session). It is calculated as follows:

-- traditional (Smallfile) temp tablesapce
  DATA_OBJECT_ID = "relative file number" * power(2, 22) + "seg_header_block_number"

-- Bigfile temp tablesapce
  DATA_OBJECT_ID = "seg_header_block_number"

We can verify them as follows:

-- sys.x_ktsso is x$ktsso
select s.sid, s.serial#, g.ktssoobjn temp_object_id, 
       g.ktssoobjd temp_data_object_id, 
      (ktssorfno*power(2, 22) + ktssobno) temp_data_object_id_calc,
       ktssorfno rfile#, ktssobno seg_header_block,
       o.object_name, g.ktssosegt segtype, g.ktssoblks blocks, 
       temporary, generated
       --g.ktssosqlid sql_id_tempseg, a.sql_text, g.*
  from sys.x_ktsso g, v$session s, v$sqlarea a, dba_objects o
where g.ktssoses=s.saddr and g.ktssosqlid = a.sql_id and g.ktssoobjn=o.object_id(+) and s.sid=913 
 order by g.ktssoobjn, g.ktssoblks;

  SID SERIAL# TEMP_OBJECT_ID TEMP_DATA_OBJECT_ID  TEMP_DATA_OBJECT_ID_CALC     RFILE# SEG_HEADER_BLOCK  OBJECT_NAME               SEGTYPE     BLOCKS TEMPORARY GENERATED
  --- ------- -------------- -------------------  ------------------------ ---------- ----------------  ------------------------- ------- ---------- --------- ---------
  123   10733              0             4311680                   4311680          1           117376                                  7        256                    
  123   10733        4080456             4349312                   4349312          1           155008  TEMP_TAB                        3        256 Y         N        
  123   10733        4080457             4376960                   4376960          1           182656  SYS_LOB0004080456C00002$$       5       1024 Y         Y        
  123   10733        4080458             4333440                   4333440          1           139136  SYS_IL0004080456C00002$$        4        256 Y         Y        
  123   10733        4080459             4327040                   4327040          1           132736  TEMP_TAB#I1                     4        256 Y         N        

-- Note: v$bh.FILE# = x$bh.FILE# is absolute file number.
--       TEMP_DATA_OBJECT_ID_CALC is computed with relative file number, 
--       which can be caculated by v$bh.OBJD and v$bh.block# as follows.
--       relative file number is exposed in x$bh.DBARFIL, see next query

select file#, block#, class#, temp, objd 
      ,((OBJD - block#)/power(2, 22)) relative_file_number  --, b.*
  from v$bh b
 where (   OBJD = block#                             -- Bigfile   Tablespace
        or mod((OBJD - block#), power(2, 22)) = 0    -- Smallfile Tablespace
       )
 --and block# in (117376, 155008, 182656, 139136, 132736)
 --and OBJD in (4311680, 4349312, 4376960, 4333440, 4327040)
 and (class# = 4 or class# >= 17 and mod(class#,2)=1)   -- class# = 4: Segment Header, class# >= 17 odd number: Temp Undo Segment Header
 order by b.OBJD;
 
  FILE#  BLOCK#  class#  TEMP  OBJD     RELATIVE_FILE_NUMBER
  -----  ------  ------  ----  -------  --------------------
      1  117376      33     Y  4311680   1                     -- class# >= 17 odd number is Temp Undo Segment Header
      1  155008       4     Y  4349312   1                     -- class#  = 4 is normal Segment Header
      1  182656       4     Y  4376960   1                     
      1  139136       4     Y  4333440   1                     
      1  132736       4     Y  4327040   1  
  
-- The correct way is to use relative file number x$bh.DBARFIL instead of v$bh.FILE# = x$bh.FILE#, which is absolute file number

select * 
  from sys.x_bh 
 where dbarfil = 1    -- relative file number 
   --and dbablk in (117376, 155008, 182656, 139136, 132736)
   --and obj in (4311680, 4349312, 4376960, 4333440, 4327040)
   and (class = 4 or class >= 17 and mod(class,2)=1);   -- class = 4: Segment Header, class >= 17 odd number: Temp Undo Segment Header

-- Computation Verification. 
-- class is either  = 4 (Segment Header Block) 
--              or >= 17 odd number (Temp Undo Segment Header Block)
select OBJ, DBARFIL, DBABLK, class, b.* 
  from sys.x_bh b
 where OBJ = DBABLK                             -- Bigfile   Tablespace
    or OBJ = DBARFIL * power(2, 22) + dbablk    -- Smallfile Tablespace
;

TEMP_OBJECT_ID number (except 'TEMP_UNDO') also suggests the creating sequence of temp objects.

Following query displays the temp blocks kept in buffer cache.

select objd, count(*)
  from v$bh
where objd in (select ktssoobjd from sys.x_ktsso g, v$session s where g.ktssoses=s.saddr and s.sid=123)
 group by objd order by objd;
 
   OBJD COUNT(*)
------- --------
4311680       18
4327040        7
4333440        2
4349312        3
4376960        3

In the above output, "SYS_IL0004080456C00002$$" is marked as SEGTYPE=4, but according to definition of VIEW SYS.GV_$SORT_USAGE, SEGTYPE=4 is for normal 'INDEX', 'LOB_INDEX' should be ktssosegt (SEGTYPE) 6, specially for temp LOB_INDEX.

With following test code, we can see SEGTYPE: LOB_INDEX (ktssosegt: 6).

In one session (SID 123), we run following code to create a xmltype from bfile (sleeping for 60 seconds to observe):

declare
  l_xml    xmltype;
begin
  l_xml := xmltype(bfilename('TEST_DIR', 'TEST.XML'), nls_charset_id('utf8'));

  dbms_session.sleep(60);
end;
/

In another montoring session, we can see SEGTYPE: LOB_DATA (ktssosegt: 5) and LOB_INDEX (ktssosegt: 6):

select s.sid, tablespace, contents, segtype, segfile#, segblk#, blocks, segrfno#
 from v$tempseg_usage t, v$session s where t.session_addr=s.saddr;

   SID TABLESPACE CONTENTS  SEGTYPE   SEGFILE# SEGBLK# BLOCKS SEGRFNO#
  ---- ---------- --------- --------- -------- ------- ------ --------
   123 TEMP1      TEMPORARY LOB_DATA      3074  128384    768        1
   123 TEMP1      TEMPORARY LOB_INDEX     3074  126336    256        1
      
      
-- It creates 1 temp CACHE_LOBS, and 2 temp ABSTRACT_LOBS.
select * from v$temporary_lobs;

   SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS
  ---- ---------- ------------ -------------
   123          1            0             2

Following queries confirm that "SYS_IL0004080456C00002$$" is a 'LOB_INDEX'.

select table_name, column_name, segment_name, tablespace_name, index_name
  from dba_lobs where table_name='TEMP_TAB';
 
  TABLE_NAME COLUMN_NAM SEGMENT_NAME              TABLESPACE INDEX_NAME
  ---------- ---------- ------------------------- ---------- ------------------------
  TEMP_TAB   B          SYS_LOB0004080456C00002$$ TEMP       SYS_IL0004080456C00002$$
 
select index_name, index_type, table_name, uniqueness, temporary, generated, duration
  from dba_indexes where table_name='TEMP_TAB';
 
  INDEX_NAME               INDEX_TYPE TABLE_NAME UNIQUENES TEMPORARY GENERATED DURATION
  ------------------------ ---------- ---------- --------- --------- --------- ---------------
  SYS_IL0004080456C00002$$ LOB        TEMP_TAB   UNIQUE    Y         Y         SYS$TRANSACTION
  TEMP_TAB#I1              NORMAL     TEMP_TAB   NONUNIQUE Y         N         SYS$SESSION
 
select object_name, object_id, data_object_id, object_type, temporary, generated
  from dba_objects where object_name in (select index_name from dba_lobs where table_name='TEMP_TAB');
 
  OBJECT_NAME              OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE TEMPORARY GENERATED
  ------------------------ --------- -------------- ----------- --------- ---------
  SYS_IL0004080456C00002$$   4080458        4080458 INDEX       Y         Y

3. SQL Executions

Now we run a query and list different run-time temp segments during SQL execution.

At first create test objects:

truncate table temp_tab_3k;
drop table temp_tab_3k;
create global temporary table temp_tab_3k(a number) on commit preserve rows;
 
truncate table temp_tab_30k;
drop table temp_tab_30k;
create global temporary table temp_tab_30k(a number, b varchar2(1000)) on commit preserve rows;
 
truncate table temp_tab_4k;
drop table temp_tab_4k;
create global temporary table temp_tab_4k(a number) on commit preserve rows;
 
truncate table temp_tab_40k;
drop table temp_tab_40k;
create global temporary table temp_tab_40k(a number, b varchar2(1000)) on commit preserve rows;

Then run a Plsql code consisting of two queries, one is in main block, another is in autonomous_transaction block. Both are active during the Plsql code execution (so more than one Sql statements can be active at the same time in one single session).

(Note: we set "_optimizer_gather_stats_on_load"=true to enable Online Statistics Gathering.
See Blog: 12c Online Statistics Gathering for Direct Path Insert and 3 Side Effects)

alter session set max_dump_file_size = unlimited;
alter system set events '1652 trace name errorstack level 3';
  -- ORA-01652 trace file is appended at the end of the Blog
 
alter session set "_optimizer_gather_stats_on_load"=true;
 
declare
  l_cnt_temp_tab_4k  number;
  procedure sort is
    pragma autonomous_transaction;
    l_cnt_temp_tab_3k  number;
  begin
    begin
      select count(*) into l_cnt_temp_tab_3k from temp_tab_3k;
      dbms_output.put_line('temp_tab_3k rows='||l_cnt_temp_tab_3k);
     
      insert /*+ append */ into temp_tab_4k select level from dual connect by level <= 4e3;
      insert /*+ append */ into temp_tab_40k select level, rpad('ABC', 1000, 'X') from dual connect by level <= 4e4;
      commit;
      for c in (select /*+ GATHER_PLAN_STATISTICS MONITOR sort_2 */ t22.a from temp_tab_4k t21, temp_tab_40k t22 order by t22.a)
      loop
        if mod(c.a, 1e3)=0 then
          dbms_session.sleep(0.01);
        end if;     
      end loop;     
      commit;
    end;
  end sort;
begin
  insert /*+ append */ into temp_tab_3k select level from dual connect by level <= 3e3;
  insert /*+ append */ into temp_tab_30k select level, rpad('ABC', 1000, 'X') from dual connect by level <= 3e4;
  commit;
  for c in (select /*+ GATHER_PLAN_STATISTICS MONITOR sort_1 */ t12.a from temp_tab_3k t11, temp_tab_30k t12 order by t12.a)
  loop
    sort;
    select count(*) into l_cnt_temp_tab_4k from temp_tab_4k;
    dbms_output.put_line('temp_tab_4k rows='||l_cnt_temp_tab_4k);
    if mod(c.a, 1e3)=0 then
      dbms_session.sleep(0.01);
    end if;     
  end loop;
end;
/

Now we can list all created temp segments (test session id = 789):

select s.sid, t.tablespace, t.segtype, t.blocks, t.sql_id_tempseg, substr(a.sql_text, 1, 110) sql_text --, t.*
  from v$tempseg_usage t, v$session s, v$sqlarea a
 where t.session_addr=s.saddr and t.sql_id_tempseg = a.sql_id and sid = 789
 order by t.segtype desc, t.blocks;
 
  SID TABL SEGTYPE   BLOCKS SQL_ID_TEMPSEG SQL_TEXT
  --- ---- --------- ------ -------------- --------------------------------------------------------------------------------------------------------------
  789 TEMP TEMP_UNDO    256 c06dqvb5b20x0  declare   procedure sort is     pragma autonomous_transaction;   begin     begin       insert /*+ append */ in
  789 TEMP SORT      132608 6tuxpu523m1hf  SELECT /*+ GATHER_PLAN_STATISTICS MONITOR sort_1 */ T12.A FROM TEMP_TAB_3K T11, TEMP_TAB_30K T12 ORDER BY T12.
  789 TEMP SORT      235776 dmuyj6fvhjqp6  SELECT /*+ GATHER_PLAN_STATISTICS MONITOR sort_2 */ T22.A FROM TEMP_TAB_4K T21, TEMP_TAB_40K T22 ORDER BY T22.
  789 TEMP DATA         256 824w6gbdj9mr2  INSERT /*+ append */ INTO TEMP_TAB_3K SELECT LEVEL FROM DUAL CONNECT BY LEVEL <= 3E3
  789 TEMP DATA         256 fxqyxs94y5vk3  INSERT /*+ append */ INTO TEMP_TAB_4K SELECT LEVEL FROM DUAL CONNECT BY LEVEL <= 4E3
  789 TEMP DATA        4352 fatjqb5a1czd7  INSERT /*+ append */ INTO TEMP_TAB_30K SELECT LEVEL, RPAD('ABC', 1000, 'X') FROM DUAL CONNECT BY LEVEL <= 3E4
  789 TEMP DATA        5888 3m9nu19xxyr2d  INSERT /*+ append */ INTO TEMP_TAB_40K SELECT LEVEL, RPAD('ABC', 1000, 'X') FROM DUAL CONNECT BY LEVEL <= 4E4

We can also query underlined x$ktsso to reveal TEMP_OBJECT_ID and TEMP_DATA_OBJECT_ID.

select s.sid, s.serial#, g.ktssoobjn temp_object_id, g.ktssoobjd temp_data_object_id, o.object_name, g.ktssosegt segtype, g.ktssoblks blocks,
       temporary, generated, g.ktssosqlid sql_id_tempseg --, a.sql_text, g.*
  from sys.x_ktsso g, v$session s, v$sqlarea a, dba_objects o
where g.ktssoses=s.saddr and g.ktssosqlid = a.sql_id and g.ktssoobjn=o.object_id(+) and s.sid=789
 order by g.ktssoobjn, g.ktssoblks;
 
  SID SERIAL# TEMP_OBJECT_ID TEMP_DATA_OBJECT_ID OBJECT_NAME  SEGTYPE BLOCKS TEMPORARY GENERATED SQL_ID_TEMPSEG
  --- ------- -------------- ------------------- ------------ ------- ------ --------- --------- --------------
  789   40183              0             4287616                    7    256                     c06dqvb5b20x0
  789   40183              0             4285824                    1 132608                     6tuxpu523m1hf
  789   40183              0             4296832                    1 235776                     dmuyj6fvhjqp6
  789   40183        4080448             4218240 TEMP_TAB_3K        3    256 Y         N         824w6gbdj9mr2
  789   40183        4080449             4196992 TEMP_TAB_30K       3   4352 Y         N         fatjqb5a1czd7
  789   40183        4080450             4306304 TEMP_TAB_4K        3    256 Y         N         fxqyxs94y5vk3
  789   40183        4080451             4306048 TEMP_TAB_40K       3   5888 Y         N         3m9nu19xxyr2d

Query v$sql_workarea_active to show work areas currently allocated for the session:

select sid, sql_id, operation_type, expected_size, actual_mem_used, tempseg_size, tablespace, active_time --, v.*
  from v$sql_workarea_active v
 where sid = 789
 order by v.sql_id, v.operation_type;
 
  SID SQL_ID        OPERATION_TYPE EXPECTED_SIZE ACTUAL_MEM_USED TEMPSEG_SIZE TABL ACTIVE_TIME
  --- ------------- -------------- ------------- --------------- ------------ ---- -----------
  789 6tuxpu523m1hf BUFFER                 75776           75776                    1165320603
  789 6tuxpu523m1hf SORT (v2)            1245184          508928   1086324736 TEMP  1165320158
  789 dmuyj6fvhjqp6 BUFFER                104448          104448                    1150366036
  789 dmuyj6fvhjqp6 SORT (v2)            1245184          508928   1931476992 TEMP  1150365532

SQL_ID: 6tuxpu523m1hf is the query in main block, dmuyj6fvhjqp6 is that in autonomous_transaction block. Above output consists of two "BUFFER" areas and two "SORT (v2)" respectively for two queries. "BUFFER" is used for "BUFFER SORT" in xplan. "SORT (v2)" is used for "SORT ORDER BY" in xplan (see later "SQL Monitoring Report").

According to v$sql_workarea_active Oracle Docu, if a work area spills to disk, then this view contains information for the temporary segment created on behalf of this work area.

Due to the size of sorting, 1GB (1086324736) temp space is allocated for main block query; 2GB (1931476992) temp space is allocated for autonomous_transaction block query. (see later two SQL Monitoring Reports).

By looking v$sqlarea output, direct_writes indicates that TEMP is used due to "SORT (v2)". rows_processed shows number of rows fetched (PLSQL arraysize=100).

 
select sql_id, last_active_time, executions, disk_reads, direct_writes, buffer_gets, rows_processed, substr(sql_text, 1, 78) sql_text --, v.*
  from v$sqlarea v
  where sql_text like 'SELECT%MONITOR sort%' and sql_id in ('6tuxpu523m1hf','dmuyj6fvhjqp6')
  order by last_active_time;
 
  SQL_ID        LAST_ACTIVE_TIME     EXECUTIONS DISK_READS DIRECT_WRITES BUFFER_GETS ROWS_PROCESSED SQL_TEXT
  ------------- -------------------- ---------- ---------- ------------- ----------- -------------- ------------------------------------------------------------------------------
  6tuxpu523m1hf 2021-OCT-19 06:32:01          1       4353        132447        4304            100 SELECT /*+ GATHER_PLAN_STATISTICS MONITOR sort_1 */ T12.A FROM TEMP_TAB_3K T11
  dmuyj6fvhjqp6 2021-OCT-19 06:36:04          1      40918        235592        5736       23996500 SELECT /*+ GATHER_PLAN_STATISTICS MONITOR sort_2 */ T22.A FROM TEMP_TAB_4K T21

v$bh shows that TEMP_TAB_30K (OBJD 4196992) has 4287 blocks in buffer cache, and TEMP_TAB_40K (OBJD 4306048) has 5716 blocks in buffer cache. Both are close to their number of blocks in v$tempseg_usage.

select objd, count(*)
  from v$bh
where objd in (select ktssoobjd from sys.x_ktsso g, v$session s where g.ktssoses=s.saddr and s.sid=789)
 group by objd order by objd;
 
     OBJD COUNT(*)
  ------- --------
  4196992     4287
  4218240       15
  4285824        1
  4287616        2
  4296832        1
  4306048     5716
  4306304        8

After half hour, the session throws ORA-01652 (256 is number of DB blocks, i.e. one TEMP extent in the test. extent is TEMP minimum unit):

  temp_tab_3k rows=3000
  temp_tab_4k rows=4000
  temp_tab_3k rows=3000
  declare
  *
  ERROR at line 1:
  ORA-01652: unable to extend temp segment by 256 in tablespace TEMP
  ORA-06512: at line 14
  ORA-06512: at line 14
  ORA-06512: at line 29
  ORA-06512: at line 29
 
  Elapsed: 00:30:38.31

By the way, output line "temp_tab_3k rows=3000" is used to show that all committed rows (temp table is created as "commit preserve rows") in main block is visible inside autonomous_transaction block (no committed rows still not visible). "temp_tab_4k rows=4000" shows that of autonomous_transaction block is visible inside main block. So temp table is session private, not transaction private.

The first output line "temp_tab_3k rows=3000" indicates that the first execution of autonomous_transaction block is successful since it requires only 2GB Temp space (see next section "SQL Monitoring Report").

The second output line "temp_tab_3k rows=3000" ended with ORA-01652 because temp_tab_4k and temp_tab_40k (defined as "commit preserve rows") are filled again with 4k and 40k rows (the size doubled to 8K and 80K rows respectively), and it demands 7GB Temp space (see next section "SQL Monitoring Report"). Together with 1GB already allocated for the main block query, whole 8GB are used up, and it results in ORA-01652.

4. SQL Monitoring Report

Now we can look SQL Monitoring Report for two above queries.

4.1 Query_1: 6tuxpu523m1hf (in main block)

We can see "BUFFER SORT" uses 75776 bytes memory, "SORT ORDER BY" needs 497KB bytes memory and additionally demands 1GB Temp space to meet sorting request. (BTW, "BUFFER SORT" is a BUFFER area, not used for "SORT").

Refer to above v$sql_workarea_active query for SQL_ID: 6tuxpu523m1hf, it shows that "BUFFER" uses ACTUAL_MEM_USED=75776; "SORT ORDER BY" takes ACTUAL_MEM_USED=508928 (508928/1024=497KB) plus additionally TEMPSEG_SIZE=1086324736 (1GB).

Both pair of (Read Reqs=136, Read Bytes=34MB) and (Write Reqs=4502, Write Bytes=1GB) stats indicate that each IO Read / Write is about 32 8K blocks.

Almost similar Elapsed Time(s) and Cpu Time(s) values suggest that the Sql executions is CPU intensive (sorting).

Before the test, we set "_optimizer_gather_stats_on_load"=true, so Rows (Estim) is exactly Rows (Actual).

select sys.dbms_sqltune.report_sql_monitor('6tuxpu523m1hf', report_level=>'all' , type=>'TEXT') from dual;
 
SQL Text
------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS MONITOR sort_1 */ T12.A FROM TEMP_TAB_3K T11, TEMP_TAB_30K T12 ORDER BY T12.A
 
Global Information
------------------------------
Status              :  EXECUTING          
 SQL ID              :  6tuxpu523m1hf      
 SQL Execution ID    :  16777216           
 Execution Started   :  10/19/2021 06:31:46
 First Refresh Time  :  10/19/2021 06:31:46
 Last Refresh Time   :  10/19/2021 06:32:01
 Duration            :  455s               
 Fetch Calls         :  1                  
 
Global Stats
================================================================================
| Elapsed |   Cpu   |    IO    | Fetch | Buffer | Read | Read  | Write | Write |
| Time(s) | Time(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes | Reqs  | Bytes |
================================================================================
|      15 |      15 |     0.10 |     1 |   4304 |  136 |  34MB |  4502 |   1GB |
================================================================================
 
SQL Plan Monitoring Details (Plan Hash Value=2630616599)
======================================================================================================================================================================================
| Id   |        Operation        |     Name     |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read | Read  | Write | Write |  Mem  | Temp | Activity | Activity Detail |
|      |                         |              | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs | Bytes | Reqs  | Bytes |       |      |   (%)    |   (# samples)   |
======================================================================================================================================================================================
| -> 0 | SELECT STATEMENT        |              |         |       |        14 |     +2 |     1 |      100 |      |       |       |       |     . |    . |          |                 |
| -> 1 |   SORT ORDER BY         |              |     90M |  316K |        15 |     +1 |     1 |      100 |    1 | 248KB |  4502 |   1GB | 497KB |  1GB |    13.64 | Cpu (9)         |
| -> 2 |    MERGE JOIN CARTESIAN |              |     90M | 44087 |        14 |     +2 |     1 |      90M |      |       |       |       |     . |    . |     6.06 | Cpu (4)         |
| -> 3 |     TABLE ACCESS FULL   | TEMP_TAB_30K |   30000 |  1226 |        14 |     +2 |     1 |    30000 |  134 |  33MB |       |       |     . |    . |     1.52 | Cpu (1)         |
| -> 4 |     BUFFER SORT         |              |    3000 |  315K |        14 |     +2 | 30000 |      90M |      |       |       |       | 75776 |    . |     1.52 | Cpu (1)         |
|    5 |      TABLE ACCESS FULL  | TEMP_TAB_3K  |    3000 |     1 |         1 |     +2 |     1 |     3000 |    1 | 40960 |       |       |     . |    . |          |                 |
======================================================================================================================================================================================

4.2 Query_2: dmuyj6fvhjqp6 (in autonomous_transaction block)

We can see "BUFFER SORT" uses 102KB bytes memory, "SORT ORDER BY" needs 497KB bytes memory and additionally demands 2GB Temp space to meet sorting request ("BUFFER SORT" is a BUFFER area, not used for "SORT").

Refer to above v$sql_workarea_active query for SQL_ID: dmuyj6fvhjqp6, it shows that "BUFFER" uses ACTUAL_MEM_USED=104448 (104448/1024=102KB); "SORT ORDER BY" takes ACTUAL_MEM_USED=508928 (508928/1024=497KB) plus additionally TEMPSEG_SIZE=1931476992 (2GB).

Last column "Progress = 27%" can be used to estimate the remaining time.

select sys.dbms_sqltune.report_sql_monitor('dmuyj6fvhjqp6', report_level=>'all' , type=>'TEXT') from dual;
 
SQL Text
------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS MONITOR sort_2 */ T22.A FROM TEMP_TAB_4K T21, TEMP_TAB_40K T22 ORDER BY T22.A
 
Global Information
------------------------------
Status              :  EXECUTING          
 SQL ID              :  dmuyj6fvhjqp6      
 SQL Execution ID    :  16777216           
 Execution Started   :  10/19/2021 06:32:01
 First Refresh Time  :  10/19/2021 06:32:01
 Last Refresh Time   :  10/19/2021 06:39:54
 Duration            :  474s               
 Fetch Calls         :  439981              
 
Global Stats
================================================================================
| Elapsed |   Cpu   |    IO    | Fetch | Buffer | Read | Read  | Write | Write |
| Time(s) | Time(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes | Reqs  | Bytes |
================================================================================
|      42 |      37 |     4.93 |  440K |   5736 | 2448 | 549MB |  8113 |   2GB |
================================================================================
 
SQL Plan Monitoring Details (Plan Hash Value=1990735535)
===========================================================================================================================================================================================================
| Id   |        Operation        |     Name     |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read | Read  | Write | Write |  Mem  | Temp | Activity |      Activity Detail      | Progress |
|      |                         |              | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs | Bytes | Reqs  | Bytes |       |      |   (%)    |        (# samples)        |          |
===========================================================================================================================================================================================================
| -> 0 | SELECT STATEMENT        |              |         |       |       473 |     +1 |     1 |      44M |      |       |       |       |     . |    . |     7.55 | Cpu (4)                   |          |
| -> 1 |   SORT ORDER BY         |              |    160M |  565K |       473 |     +1 |     1 |      44M | 2268 | 504MB |  8113 |   2GB | 497KB |  2GB |    47.17 | Cpu (22)                  |      27% |
|      |                         |              |         |       |           |        |       |          |      |       |       |       |       |      |          | direct path read temp (3) |          |
|    2 |    MERGE JOIN CARTESIAN |              |    160M | 81639 |        27 |     +1 |     1 |     160M |      |       |       |       |     . |    . |     3.77 | Cpu (2)                   |          |
|    3 |     TABLE ACCESS FULL   | TEMP_TAB_40K |   40000 |  1635 |        27 |     +1 |     1 |    40000 |  179 |  45MB |       |       |     . |    . |          |                           |          |
|    4 |     BUFFER SORT         |              |    4000 |  563K |        27 |     +1 | 40000 |     160M |      |       |       |       | 102KB |    . |    13.21 | Cpu (7)                   |          |
|    5 |      TABLE ACCESS FULL  | TEMP_TAB_4K  |    4000 |     2 |         1 |     +1 |     1 |     4000 |    1 | 57344 |       |       |     . |    . |          |                           |          |
===========================================================================================================================================================================================================

During the first run of both queries, they together consume about 3GB Temp space (37% of 8GB).

06:56:32 SQL > select t.*, round(100*(tablespace_size - free_space)/tablespace_size) percent_used from dba_temp_free_space t;
 
  TABLESPACE_NAME TABLESPACE_SIZE ALLOCATED_SPACE FREE_SPACE SHARED INST_ID PERCENT_USED
  --------------- --------------- --------------- ---------- ------ ------- ------------
  TEMP                 8388608000      8388608000 5268045824 SHARED                   37

In the second run, immediately before:

  ORA-01652: unable to extend temp segment by 256 in tablespace TEMP
 
    (Note: 256 is number of DB blocks, i.e, one TEMP extent in the test. extent is TEMP minimum unit).

Whole 8GB is consumed.

07:02:24 SQL > select t.*, round(100*(tablespace_size - free_space)/tablespace_size) percent_used from dba_temp_free_space t;
 
  TABLESPACE_NAME TABLESPACE_SIZE ALLOCATED_SPACE FREE_SPACE SHARED INST_ID PERCENT_USED
  --------------- --------------- --------------- ---------- ------ ------- ------------
  TEMP                 8388608000      8388608000          0 SHARED                  100

SQL Monitoring Report shows that the second run of this query consumes Mem(Max) is 80MB. And Temp(Max) reaches 7GB, which means that total 8GB are all used, hence ORA-01652.
(Note: the first and second run of SQL_ID: dmuyj6fvhjqp6 are designated by different SQL Execution ID: 16777216 and 16777217)

Global Information
------------------------------
Status              :  DONE (ERROR)       
 SQL ID              :  dmuyj6fvhjqp6      
 SQL Execution ID    :  16777217            
 Execution Started   :  10/19/2021 07:00:44
 First Refresh Time  :  10/19/2021 07:00:44
 Last Refresh Time   :  10/19/2021 07:02:36
 Duration            :  112s               
 Fetch Calls         :  1                  
 
Global Stats
===========================================================================================
| Elapsed |   Cpu   |    IO    |  Other   | Fetch | Buffer | Read | Read  | Write | Write |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes | Reqs  | Bytes |
===========================================================================================
|     113 |     105 |     2.97 |     5.05 |     1 |  10691 | 3311 |   3GB | 29367 |   7GB |
===========================================================================================
 
SQL Plan Monitoring Details (Plan Hash Value=1990735535)
==================================================================================================================================================================================================
| Id |        Operation        |     Name     |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read | Read  | Write | Write |  Mem  | Temp  | Activity |       Activity Detail        |
|    |                         |              | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs | Bytes | Reqs  | Bytes | (Max) | (Max) |   (%)    |         (# samples)          |
==================================================================================================================================================================================================
|  0 | SELECT STATEMENT        |              |         |       |       113 |     +1 |     1 |        0 |      |       |       |       |     . |     . |    11.50 | Cpu (5)                      |
|    |                         |              |         |       |           |        |       |          |      |       |       |       |       |       |          | log file sequential read (8) |
|  1 |   SORT ORDER BY         |              |    160M |  565K |       101 |     +1 |     1 |        0 |      |       | 29370 |   7GB |  80MB |   7GB |    61.06 | Cpu (68)                     |
|    |                         |              |         |       |           |        |       |          |      |       |       |       |       |       |          | direct path write temp (1)   |
|  2 |    MERGE JOIN CARTESIAN |              |    160M | 81639 |       101 |     +1 |     1 |     597M |      |       |       |       |     . |     . |     9.73 | Cpu (11)                     |
|  3 |     TABLE ACCESS FULL   | TEMP_TAB_40K |   40000 |  1635 |       112 |     +1 |     1 |    74581 |  156 |  39MB |       |       |     . |     . |          |                              |
|  4 |     BUFFER SORT         |              |    4000 |  563K |       101 |     +1 | 74581 |     597M |      |       |       |       | 190KB |     . |    17.70 | Cpu (20)                     |
|  5 |      TABLE ACCESS FULL  | TEMP_TAB_4K  |    4000 |     2 |         1 |     +1 |     1 |     8000 |    1 | 57344 |       |       |     . |     . |          |                              |
==================================================================================================================================================================================================

After ORA-01652, Plsql block execution is terminated, and Temp space is released:

       
07:04:28 SQL > select t.*, round(100*(tablespace_size - free_space)/tablespace_size) percent_used from dba_temp_free_space t;
 
  TABLESPACE_NAME TABLESPACE_SIZE ALLOCATED_SPACE FREE_SPACE SHARED INST_ID PERCENT_USED
  --------------- --------------- --------------- ---------- ------ ------- ------------
  TEMP                 8388608000      8388608000 8241807360 SHARED                    2

By the way, with following query, we can observe both "SORT (v2)" and "HASH-JOIN" (SEGTYPE: 1 and 2) using Temp Space.

   
alter session set "_optimizer_gather_stats_on_load"=true;
insert /*+ append */ into temp_tab_40k select level, rpad('ABC', 1000, 'X') from dual connect by level <= 4e5;
commit;
 
select /*+ use_hash GATHER_PLAN_STATISTICS MONITOR sort_2 */ t1.a from temp_tab_40k t1, temp_tab_40k t2
 where t1.b = t2.b order by t1.a;
 
select sid, sql_id, operation_type, expected_size, actual_mem_used, tempseg_size, tablespace, active_time --, v.*
  from v$sql_workarea_active v
where sid = 195
order by v.sql_id, v.operation_type;

  SID SQL_ID        OPERATION_ EXPECTED_SIZE ACTUAL_MEM_USED  TEMPSEG_SIZE TABLESPACE ACTIVE_TIME
  --- ------------- ---------- ------------- --------------- ------------- ---------- -----------
  195 aj3f52afjwua7 HASH-JOIN     83,886,080      89,966,592   840,957,952 TEMP       136,327,805
  195 aj3f52afjwua7 SORT (v2)     64,120,832      34,364,416 6,035,603,456 TEMP       134,897,069

5. Shrinking Temporary Tablespaces

Oracle TEMP space can be allocated, but not de-allocated as explained in MOS "Queries To Monitor Temporary Tablespace Usage (Doc ID 289894.1)":

  Multiple transactions which need a sort on disk, can share the same sort segment, however, they cannot share the same extent.
  The sort segment expands by allocating new extents. The sort extents are not de-allocated while the instance is running,
  but are marked as free and can be re-used as required. Therefore, the sort segment grows to a certain steady state.

During the first run of both queries, although we are using less than 3GB Temp space, we get ORA-03297 when shrinking it down to 6G after 9 minutes.

ORA-03297 said "file contains used data beyond requested RESIZE value", which probably means that there exist temp extents distributed beyond 6G boundary inside 8G temp file (we will see it later in Tempfile Dump).

06:42:32 SQL > ALTER TABLESPACE temp SHRINK SPACE KEEP 6G;
 
  ERROR at line 1:
  ORA-03297: file contains used data beyond requested RESIZE value
  Elapsed: 00:09:41.83

DB alert.log shows only 1032K (8192000 - 8190968) are reduced.

  2021-10-19T06:42:32.351933+02:00
  ALTER TABLESPACE temp SHRINK SPACE KEEP 6G
  2021-10-19T06:42:32.381387+02:00
  Resize operation completed for file# 3073, old size 8192000K, new size 8190968K
  2021-10-19T06:52:14.174181+02:00
  ORA-3297 signalled during: ALTER TABLESPACE temp SHRINK SPACE KEEP 6G...

Unix also shows this only 1032k change (8388616192-8387559424=1056768=1032K):

  $ > ls -ltr temp01.dbf
    -rw-r----- 1 oracle dba 8388616192 Oct 19 06:40 temp01.dbf
 
  $ > ls -ltr temp01.dbf
    -rw-r----- 1 oracle dba 8387559424 Oct 19 06:53 temp01.dbf

11.2.0.4 introduced ORA-03297 is documented as:
(see MOS "Resize Of Temporary Tablespace with KEEP keyword not working (Doc ID 1663229.1)")

  03297, 00000, "file contains used data beyond requested RESIZE value"
  // *Cause:  Some portion of the file in the region to be trimmed is
  //          currently in use by a database object
  // *Action: Drop or move segments containing extents in this region prior to
  //          resizing the file, or choose a resize value such that only free
  //          space is in the trimmed.

After Plsql block running terminated (with ORA-01652), Temp space is released, only 2% of 8GB is used.

           
07:04:28 SQL > select t.*, round(100*(tablespace_size - free_space)/tablespace_size) percent_used from dba_temp_free_space t;
 
  TABLESPACE_NAME TABLESPACE_SIZE ALLOCATED_SPACE FREE_SPACE SHARED INST_ID PERCENT_USED
  --------------- --------------- --------------- ---------- ------ ------- ------------
  TEMP                 8388608000      8388608000 8241807360 SHARED                    2

Shrinking it again, Temp space is quickly resized down to 6GB.

07:05:04 SQL > ALTER TABLESPACE temp SHRINK SPACE KEEP 6G;
 
  Tablespace altered.
  Elapsed: 00:00:00.15

DB alert.log shows that Resize operation completed with new size 6409208K (about 6GB):

  2021-10-19T07:05:04.268529+02:00
  ALTER TABLESPACE temp SHRINK SPACE KEEP 6G
  2021-10-19T07:05:04.418246+02:00
  Resize operation completed for file# 3073, old size 8190968K, new size 6291456K
  Completed: ALTER TABLESPACE temp SHRINK SPACE KEEP 6G

Unix shows:

  $ > ls -ltr temp01.dbf
    -rw-r----- 1 oracle dba 6442459136 Oct 19 07:05 temp01.dbf

To efficiently shrink TABLESPACE temp, it is advisable to set database in restricted mode, then run above shrink command.

6. Monitoring Queries

Database Journal: "Monitoring Oracle's Temp Usage" gives some queries to monitor temp usage.

Oracle MOS:

   "Queries To Monitor Temporary Tablespace Usage (Doc ID 289894.1)",
   "How Can Temporary Segment Usage Be Monitored Over Time? (Doc ID 364417.1)"
   "Primary Note: Overview of Oracle Temporary Tablespaces (Doc ID 1498442.1)"

have descriptions about temporary (sort) segment and monitoring.

In this section, we collect a few often used Temp monitoring queries and classify them by their behaviours.

In order to correlate different stats in the queries, we first shrink Temp tablespace to 5000M (temp file maxsize 8000M).
Then fill a temp table with 1622M (see temp_tab in Section 2).

ALTER TABLESPACE temp SHRINK SPACE KEEP 5000M;
 
insert /*+ append */ into temp_tab select level, rpad('ABC', 7000, 'X') from dual connect by level <= 2e5;
commit;

--==== 1. List TEMP Settings ====--
 
$ > ls -ltr temp*
  -rw-r----- 1 oracle dba 5242888192 Oct 19 17:50 temp01.dbf
 
select * from dba_temp_files;
 
  FILE_NAME  FILE_ID TABLESPACE      BYTES BLOCKS STATUS RELATIVE_FNO AUTOE   MAXBYTES  MAXBLOCKS INCREMENT_BY USER_BYTES USER_BLOCKS SHARED
  ---------- ------- ---------- ---------- ------ ------ ------------ ----- ---------- ---------- ------------ ---------- ----------- ------
  temp01.dbf       1 TEMP       5242880000 640000 ONLINE            1 YES   8388608000    1024000        12800 5240782848      639744 SHARED

--==== 2. Monitor TEMP Allocations ====--
-- list current used space per session within allocated space (total USED_EXTENTS=811)
select session_addr, sum(blocks) used_blocks, (sum(blocks)*8192/1024/1024) used_mb, sum(blocks)*8192 used_bytes, sum(blocks)/256 used_extents
  from v$tempseg_usage
 group by rollup(session_addr);
 
  SESSION_ADDR     USED_BLOCKS USED_MB USED_BYTES USED_EXTENTS
  ---------------- ----------- ------- ---------- ------------
  00000000B70D97B8         256       2    2097152            1
  00000000B72A7418      206336    1612 1690304512          806     -- session which filled temp_tab
  00000000B8B6FF78         256       2    2097152            1
  00000000B8B92E28         256       2    2097152            1
  00000000B8D18540         256       2    2097152            1
  00000000B8D42BA8         256       2    2097152            1
                        207616    1622 1700790272          811     -- total used
 
-- list total, allocated, and free space
select t.*, (tablespace_size/8192) tablespace_blocks, (tablespace_size/8192/256) tablespace_extents,
      (allocated_space/8192) allocated_blocks, (allocated_space/8192/256) allocated_extents
  from dba_temp_free_space t;
 
  TABLESPACE TABLESPACE_SIZE ALLOCATED_SPACE FREE_SPACE SHARED TABLESPACE_BLOCKS TABLESPACE_EXTENTS ALLOCATED_BLOCKS ALLOCATED_EXTENTS
  ---------- --------------- --------------- ---------- ------ ----------------- ------------------ ---------------- -----------------
  TEMP            5242880000      1707081728 3539992576 SHARED            640000               2500           208384               814
 
-- list total TEMP used and free
select * from v$temp_space_header;
 
  TABLESPACE FILE_ID BYTES_USED BLOCKS_USED BYTES_FREE BLOCKS_FREE RELATIVE_FNO
  ---------- ------- ---------- ----------- ---------- ----------- ------------
  TEMP             1 1707081728      208384 3535798272      431616            1
 
-- list used and total
select s.tot_used_blocks, f.total_blocks, (s.tot_used_blocks/f.total_blocks)*100 as "percent used"
from (select sum(used_blocks) tot_used_blocks from v$sort_segment where tablespace_name='TEMP') s,
      (select sum(blocks)      total_blocks    from dba_temp_files where tablespace_name='TEMP') f;
 
  TOT_USED_BLOCKS TOTAL_BLOCKS percent used
  --------------- ------------ ------------
           207616       640000        32.44
 
-- list Allocated and Un-Allocated TEMP         
--   owner=0 are free extents (un-allocated), owner!=0 are allocated extents.
--   For details, see later section: Tempfile Dump
select owner, count(*), sum(bytes), sum(blocks) from v$temp_extent_map group by owner;
 
  OWNER COUNT(*) SUM(BYTES) SUM(BLOCKS)
  ----- -------- ---------- -----------
      1      813 1704984576      208128     -- Allocated (CACHED) TEMP
      0     1686 3535798272      431616     -- Un-Allocated       TEMP

--==== 3. Monitor Allocated TEMP Utilization (Efficiency: Used against Allocated, or Used against Cached) ====--
-- list cached stats and utilization (cache efficiency)    
--   cached temporary space usage (not clear if they are blocks of v$bh.temp='Y'. See following query Note of v$sort_segment)
select t.*, 100*blocks_used/blocks_cached block_percent_used from v$temp_extent_pool t;
 
  TABLESPACE FILE_ID EXTENTS_CACHED EXTENTS_USED BLOCKS_CACHED BLOCKS_USED BYTES_CACHED BYTES_USED RELATIVE_FNO BLOCK_PERCENT_USED
  ---------- ------- -------------- ------------ ------------- ----------- ------------ ---------- ------------ ------------------
  TEMP             1            813          811        208128      207616   1704984576 1700790272            1         99.7539975
 
-- list sort_segment stats and utilization of allocated blocks (TOTAL_BLOCKS). TOTAL_BLOCKS is allocated blocks in v$temp_extent_map
--   (EXTENT_HITS: Number of times an unused extent was found in the pool. 
--                 Probably accumulated (EXTENTS_ALLOCATED - EXTENTS_USED) in v$temp_extent_pool)
select current_users, total_blocks, used_blocks, free_blocks, max_blocks, max_used_blocks, max_sort_blocks
     ,extent_hits, freed_extents, free_requests
     ,(select sum(blocks) from v$tempseg_usage) tempseg_blocks
     ,100*used_blocks/total_blocks block_percent_used --, t.*
  from v$sort_segment t;
 
  CURRENT_USERS TOTAL_BLOCKS USED_BLOCKS FREE_BLOCKS MAX_BLOCKS MAX_USED_BLOCKS MAX_SORT_BLOCKS EXTENT_HITS FREED_EXTENTS FREE_REQUESTS TEMPSEG_BLOCKS BLOCK_PERCENT_USED
  ------------- ------------ ----------- ----------- ---------- --------------- --------------- ----------- ------------- ------------- -------------- ------------------
             10       208128      207616         512    1023744         1023744          951040      104014         15045            61         207616         99.7539975

                   
--==== 4. Monitor Workarea ====--
--Connect v$sql_workarea_active with v$sql_workarea
select *
  from v$sql_workarea_active a, v$sql_workarea w
 where a.workarea_address = w.workarea_address and a.sid = 789;
 
-- Connect v$sql_workarea_active with v$sql_workarea and v$tempseg_usage
select * from v$sql_workarea_active a, v$sql_workarea w, v$tempseg_usage t
 where a.workarea_address = w.workarea_address
   and a.tablespace = t.tablespace(+) and a.segrfno# = t.segrfno#(+) and a.segblk# = t.segblk#(+) and a.sid = 789;

--==== 5. Monitor executions. direct_writes indicates TEMP used; rows_processed indicates number of fetches (PLSQL arraysize=100) ====--
select sql_id, first_load_time, last_active_time, executions, disk_reads, direct_writes, buffer_gets, rows_processed, v.*
  from v$sqlarea v
  where sql_text like 'SELECT%MONITOR sort%' or sql_id in ('6tuxpu523m1hf','dmuyj6fvhjqp6');

--==== 6. Monitor PGA and TEMP allocation ====--
select pga_allocated, temp_space_allocated, v.*
  from v$active_session_history v where session_id = 789
  order by sample_time desc;

--==== 7. Monitor UNDO ====--
-- show tempundo stats, for example, 
--   SSOLDERRCNT   for count of ORA-01555 snapshot too old, 
--   NOSPACEERRCNT for count of ORA-1652: unable to extend temp segment

select * from v$tempundostat; --where ssolderrcnt > 0;


-- normal permanent undo segment (not including temp undo segment), which are displayed in AWR 
--(hence AWR does not contain temp undo segment stats, 
-- for example: ORA-01555 count (SSOLDERRCNT) for tempundo is not showed in AWR)

select * from v$undostat;
select * from dba_hist_undostat;

-- contain SYSTEM undo segment and normal permanent undo segment (not including temp undo segment) 

select * from dba_rollback_segs;

7. ORA-01652 Trace File

In section "SQL Executions", if we turn on ORA-01652 trace:

  alter system set events '1652 trace name errorstack level 3';

Here some excerpted sections:

ORA-01652: unable to extend temp segment by 256 in tablespace TEMP
 
----- Current SQL Statement for this session (sql_id=dmuyj6fvhjqp6) -----
SELECT /*+ GATHER_PLAN_STATISTICS MONITOR sort_2 */ T22.A FROM TEMP_TAB_4K T21, TEMP_TAB_40K T22 ORDER BY T22.A
 
----- Call Stack Trace -----
  FRAME [16] (ksesec2()+205 -> kgeselv())
  FRAME [17] (ktsxterr()+592 -> ksesec2())
  FRAME [18] (ktfttgex()+953 -> ktsxterr())
  FRAME [19] (ktstallocext()+396 -> ktfttgex())
  FRAME [20] (ktstgrowseg()+857 -> ktstallocext())
  FRAME [21] (ktstadr_addextent()+757 -> ktstgrowseg())
  FRAME [22] (ktrsexecExecuteInExcepHdlr()+327 -> ktstadr_addextent())
  FRAME [23] (ktrsexec()+193 -> ktrsexecExecuteInExcepHdlr())
  FRAME [24] (ktataddextent()+122 -> ktrsexec())
  FRAME [25] (stsGetExtent()+76 -> ktataddextent())
  FRAME [26] (ssmalc()+1232 -> stsGetExtent())
  FRAME [27] (sdbinb()+259 -> ssmalc())
  FRAME [28] (sdbputqb()+931 -> sdbinb())
  FRAME [29] (smboWrt2()+202 -> sdbputqb())
  FRAME [30] (smboFinishSpill()+194 -> smboWrt2())
  FRAME [31] (smboSort()+377 -> smboFinishSpill())
  FRAME [32] (smboWrt()+540 -> smboSort())
  FRAME [33] (smboPut()+1273 -> smboWrt())
  FRAME [34] (qersoSORowP()+242 -> smboPut())
  FRAME [35] (qerstRowP()+737 -> qersoSORowP())
  FRAME [36] (qerstRowP()+737 -> qerstRowP())
  FRAME [37] (qersoFetchSimple()+428 -> qerstRowP())
  FRAME [38] (qersoFetch()+210 -> qersoFetchSimple())
  FRAME [39] (qerstFetch()+449 -> qersoFetch())
  FRAME [40] (qerjoCartesianFetch()+3305 -> qerstFetch())
  FRAME [41] (qerstFetch()+449 -> qerjoCartesianFetch())
 
----- Session Wait History: ----- 
        elapsed time of 0.729063 sec since last wait
     0: waited for 'direct path write temp'
        file number=0xc01, first dba=0xf9e79, block cnt=0x1f
        wait_id=165501 seq_num=34439 snap_id=1
        wait times: snap=0.006435 sec, exc=0.006435 sec, total=0.006435 sec
        wait times: max=infinite
        wait counts: calls=0 os=0
        occurred after 0.003242 sec of elapsed time
     1: waited for 'local write wait'
        file#=0xc01, block#=0x2, =0x0
        wait_id=165500 seq_num=34438 snap_id=1
        wait times: snap=0.000235 sec, exc=0.000235 sec, total=0.000235 sec
        wait times: max=infinite
        wait counts: calls=1 os=1
        occurred after 0.000002 sec of elapsed time
    ...
     9: waited for 'local write wait'
        file#=0xc01, block#=0x4, =0x0
        wait_id=165492 seq_num=34430 snap_id=1
        wait times: snap=0.000118 sec, exc=0.000118 sec, total=0.000118 sec
        wait times: max=infinite
        wait counts: calls=1 os=1
        occurred after 0.000012 sec of elapsed time
       
    sample interval: 1 sec, max history 120 sec
    ---------------------------------------------------
      [43 samples,                                         07:02:03 - 07:02:25]
        not in wait at each sample
      [1 sample,                                                      07:02:02]
        waited for 'direct path write temp', seq_num: 31433
         p1: 'file number'=0xc01
          p2: 'first dba'=0x4051b
          p3: 'block cnt'=0x1f
          time_waited: 0.035970 sec (sample interval: 0 sec)
   
----- data_block_dump ----- 
BH (0x15cf77238) file#: 3073 rdba: 0x00488e20 (1/560672) class: 1 ba: 0x15c3aa000
  set: 13 pool: 3 bsz: 8192 bsi: 0 sflg: 0 pwc: 0,25
  dbwrid: 0 obj: 4306048 objn: 4080451 tsn: [0/3] afn: 3073 hint: f
 
BH (0x145fc3b10) file#: 3073 rdba: 0x00400002 (1/2) class: 13 ba: 0x145a78000
  set: 15 pool: 3 bsz: 8192 bsi: 0 sflg: 0 pwc: 0,25
  dbwrid: 0 obj: -1 objn: 972 tsn: [0/3] afn: 3073 hint: f
 
BH (0x13ef72378) file#: 3073 rdba: 0x00400004 (1/4) class: 12 ba: 0x13e33a000
  set: 13 pool: 3 bsz: 8192 bsi: 0 sflg: 0 pwc: 0,25
  dbwrid: 0 obj: -1 objn: 0 tsn: [0/3] afn: 3073 hint: f
 
  File Space Bitmap Block:
  BitMap Control:
  RelFno: 1, BeginBlock: 1015936, Flag: 1, First: 31, Free: 3937
  Bit number 0 - owned by instance 1
  Bit number 1 - owned by instance 1
  ...
  Bit number 30 - owned by instance 1
  Bit number 31 is free
  ...
  Bit number 3967 is free
 
BH (0xfff87228) file#: 3073 rdba: 0x00400003 (1/3) class: 12 ba: 0xff516000
  set: 16 pool: 3 bsz: 8192 bsi: 0 sflg: 0 pwc: 0,25
  dbwrid: 0 obj: -1 objn: 0 tsn: [0/3] afn: 3073 hint: f
 
  File Space Bitmap Block:
  BitMap Control:
  RelFno: 1, BeginBlock: 128, Flag: 1, First: 3968, Free: 0
  Bit number 0 - owned by instance 1
  Bit number 1 - owned by instance 1
  ...
  Bit number 3966 - owned by instance 1

8. Tempfile Dump

To further understand Temp Space allocation, we can dump temp File Space blocks (1-6).

alter system dump tempfile 1 BLOCK MIN 1 BLOCK MAX 6;

Here some parts excerpted from dump file:

BH (0x145fc3b10) file#: 3073 rdba: 0x00400002 (1/2) class: 13 ba: 0x145a78000
  frmt: 0x02 chkval: 0x0000 type: 0x1d=KTFB Bitmapped File Space Header
  File Space Header Block:
  Header Control:
  RelFno: 1, Unit: 256, Size: 640000, Flag: 9(0x9)
  AutoExtend: YES, Increment: 12800, MaxSize: 1024000
  Initial Area: 126, Tail: 639871, First: 811, Free: 1686
           
BH (0xfff87228) file#: 3073 rdba: 0x00400003 (1/3) class: 12 ba: 0xff516000
  frmt: 0x02 chkval: 0x0000 type: 0x1e=KTFB Bitmapped File Space Bitmap
  File Space Bitmap Block:
  BitMap Control:
  RelFno: 1, BeginBlock: 128, Flag: 1, First: 811, Free: 3155
    Bit number 0 - owned by instance 1
    Bit number 1 - owned by instance 1
    ...
    Bit number 810 - owned by instance 1
    Bit number 811 is free
    ...
    Bit number 1450 - owned by instance 1
    ...
    Bit number 1532 - owned by instance 1
    ...
    Bit number 3967 is free
 
BH (0x13ef72378) file#: 3073 rdba: 0x00400004 (1/4) class: 12 ba: 0x13e33a000
  frmt: 0x02 chkval: 0x0000 type: 0x1e=KTFB Bitmapped File Space Bitmap
  File Space Bitmap Block:
  BitMap Control:
  RelFno: 1, BeginBlock: 1015936, Flag: 1, First: 0, Free: 3968
    Bit number 0 is free
    ...
    Bit number 3967 is free
 
buffer tsn: 3 rdba: 0x00400005 (1/5)
  frmt: 0x02 chkval: 0xbf44 type: 0x1e=KTFB Bitmapped File Space Bitmap
  File Space Bitmap Block:
  BitMap Control:
  RelFno: 1, BeginBlock: 2031744, Flag: 1, First: 0, Free: 3968
    Bit number 0 is free
    ...
    Bit number 3967 is free
 
buffer tsn: 3 rdba: 0x00400006 (1/6)
  frmt: 0x02 chkval: 0x3f76 type: 0x1e=KTFB Bitmapped File Space Bitmap
  File Space Bitmap Block:
  BitMap Control:
  RelFno: 1, BeginBlock: 3047552, Flag: 1, First: 0, Free: 3968
    Bit number 0 is free
    ...
    Bit number 3967 is free

Block 2 is File Space Header (rdba: 0x00400002 (1/2) class: 13), which stores temp file settings (exposed in dba_temp_files), for example, file size is 640000 blocks, first free extent is 811, free extents is 1686 (exposed in v$temp_extent_map).

Blocks 3 to 6 are File Space Bitmap (class: 12), which stores extent Bitmap. For example, in Block 3 (rdba: 0x00400003 (1/3) class: 12), Allocated extents are marked as "owned by instance 1" (that probably points to "owner" column of v$temp_extent_map). UN-Allocated extents are marked as "free". Allocated Bits spread over three ranges: from 0 to 810 (811 Bits), and Bit 1450, 1532. 3155 Bits are free (3967-810-2, 2 are Bit number 1450 and 1532). Each Bitmap block can have 3968 rows.

File Space Bitmap is exposed in v$temp_extent_map, we can run a query to list all allocated extents:

select * from (
select rownum-1 rn, t.* from v$temp_extent_map t
) where owner=1;
 
  Bit number TABLESPACE FILE_ID BLOCK_ID   BYTES BLOCKS OWNER RELATIVE_FNO
  ---------- ---------- ------- -------- ------- ------ ----- ------------
           0 TEMP             1      128 2097152    256     1            1
           1 TEMP             1      384 2097152    256     1            1
           2 TEMP             1      640 2097152    256     1            1
        ....  
         810 TEMP             1   207488 2097152    256     1            1
        1450 TEMP             1   371328 2097152    256     1            1
        1532 TEMP             1   392320 2097152    256     1            1
 
  813 rows selected.

From Block dump and above query output, we can see that extents are not contiguously allocated, there exist 720 (1533-813) free extents under last allocated Bit number 1532. That is probably why we cannot shrink down to only allocated extents, and even get ORA-3297 when shrinking TABLESPACE temp.

Oracle sessiontimezone Format Changed After Calling dbms_scheduler/dbms_job Subprograms

dbms_scheduler/dbms_job subprograms implicitly change sessiontimezone from Named TZ (TZR) to Offset TZ (TZH:TZM) format.
As a side-effect, sessiontimezone is no more DST (Daylight saving time) aware.
(see Blog: Oracle Datetime (1) - Concepts)

This Blog will provide standalone tests and workaround.

Note 1: Tested in Oracle 19c (19.11).
Note 2: The behaviour has long been observed by other people in Oracle dbms_scheduler/dbms_job applications.

1. dbms_scheduler.enable

-----=========== dbms_scheduler.enable change time_zone ===========----- 
 
declare
  l_job_name         varchar2(100) := 'TEST_JOB_1';   
  l_time_zone_orig   varchar2(40);
  l_time_zone        varchar2(40);
begin
  execute immediate q'[alter session set time_zone = 'Europe/Paris']';
  l_time_zone_orig := sessiontimezone;
  dbms_output.put_line('----- 1 sessiontimezone = '|| sessiontimezone);
  dbms_scheduler.create_job(
    job_name   => l_job_name
   ,job_type   => 'PLSQL_BLOCK'
   ,job_action =>
     'begin
        dbms_session.sleep(300);
      end;'
   ,start_date      => systimestamp
   ,repeat_interval => 'systimestamp'   -- without repeat_interval, not reproducible
   ,enabled         => false
   ,auto_drop       => false);
  
  dbms_output.put_line('----- 2 sessiontimezone = '|| sessiontimezone);
  dbms_scheduler.enable(name  => l_job_name);
 
  l_time_zone := sessiontimezone;
  -- Workaround
  if (l_time_zone != l_time_zone_orig) then
    dbms_output.put_line('----- 3 sessiontimezone = '|| sessiontimezone); 
    dbms_output.put_line('--******* Changed after dbms_scheduler.enable. Restore to Original: '|| l_time_zone_orig); 
    execute immediate 'alter session set time_zone = ''' || l_time_zone_orig || '''';
  end if;
  dbms_output.put_line('----- 4 sessiontimezone = '|| sessiontimezone);
 
  dbms_scheduler.stop_job (l_job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
  dbms_scheduler.disable(name  => l_job_name);
  dbms_scheduler.drop_job(l_job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
  dbms_output.put_line('----- 5 sessiontimezone = '|| sessiontimezone);
end;
/
 
-----=========== Test Output ===========----- 
 
----- 1 sessiontimezone = Europe/Paris
----- 2 sessiontimezone = Europe/Paris
----- 3 sessiontimezone = +02:00
--******* Changed after dbms_scheduler.enable. Restore to Original: Europe/Paris
----- 4 sessiontimezone = Europe/Paris
----- 5 sessiontimezone = Europe/Paris

2. dbms_scheduler.set_attribute

-----=========== dbms_scheduler.set_attribute change time_zone ===========----- 
 
declare
  l_job_name         varchar2(100) := 'TEST_JOB_2'; 
begin
  execute immediate q'[alter session set time_zone = 'Europe/Paris']';
  dbms_output.put_line('----- 1 sessiontimezone = '|| sessiontimezone);
  dbms_scheduler.create_job(
    job_name   => l_job_name
   ,job_type   => 'PLSQL_BLOCK'
   ,job_action => 'BEGIN dbms_session.sleep(30); END;'
   ,start_date      => systimestamp
   ,repeat_interval => 'systimestamp'   -- without repeat_interval, not reproducible
   ,enabled         => true
   ,auto_drop       => false);
  
  dbms_output.put_line('----- 2 sessiontimezone = '|| sessiontimezone);
end;
/
 
declare
  l_job_name         varchar2(100) := 'TEST_JOB_2';    --'AVQ$AAA_BGP_911_1';
  l_time_zone_orig   varchar2(40);
  l_time_zone        varchar2(40);
BEGIN
  dbms_session.sleep(5);
  l_time_zone_orig := sessiontimezone;
  dbms_scheduler.stop_job (l_job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
 
  dbms_output.put_line('----- 3 sessiontimezone = '|| sessiontimezone);
  dbms_scheduler.set_attribute(
    name      => l_job_name
   ,attribute => 'job_action'
   ,value     => 'BEGIN dbms_session.sleep(60); END;'
  );
 
  l_time_zone := sessiontimezone;
  -- Workaround
  if (l_time_zone != l_time_zone_orig) then
    dbms_output.put_line('----- 4 sessiontimezone = '|| sessiontimezone); 
    dbms_output.put_line('--******* Changed after dbms_scheduler.set_attribute. Restore to Original: '|| l_time_zone_orig); 
    execute immediate 'alter session set time_zone = ''' || l_time_zone_orig || '''';
  end if;
 
  dbms_output.put_line('----- 5 sessiontimezone = '|| sessiontimezone);
  dbms_scheduler.stop_job (l_job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
  dbms_scheduler.disable(name  => l_job_name);
  dbms_scheduler.drop_job(l_job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
  dbms_output.put_line('----- 6 sessiontimezone = '|| sessiontimezone); 
end;
/
 
-----=========== Test Output ===========----- 
 
----- 1 sessiontimezone = Europe/Paris
----- 2 sessiontimezone = Europe/Paris
----- 3 sessiontimezone = Europe/Paris
----- 4 sessiontimezone = +02:00
--******* Changed after dbms_scheduler.set_attribute. Restore to Original: Europe/Paris
----- 5 sessiontimezone = Europe/Paris
----- 6 sessiontimezone = Europe/Paris

3. dbms_job.change

-----=========== dbms_job.change change time_zone ===========----- 
 
declare
  l_job_id pls_integer;
  l_time_zone_orig   varchar2(40);
  l_time_zone        varchar2(40);
begin
  execute immediate q'[alter session set time_zone = 'Europe/Paris']';
  l_time_zone_orig := sessiontimezone;
  dbms_output.put_line('----- 1 sessiontimezone = '|| sessiontimezone);
  dbms_job.submit(
    job       => l_job_id,
    what      => 'BEGIN dbms_session.sleep(30); END;',
    next_date => sysdate,
    interval  => 'sysdate+1/1440'  
   );
  commit;
  dbms_output.put_line('--******* l_job_id=' || l_job_id);
 
  --exception when others then dbms_output.put_line('error l_job_id =' || l_job_id); raise;
 
  dbms_output.put_line('----- 2 sessiontimezone = '|| sessiontimezone);
  dbms_job.change (
   job       =>  l_job_id,
   what      =>  'BEGIN dbms_session.sleep(60); END;',
   next_date => sysdate,
   interval  => 'sysdate+1/1440');
  commit;
 
  l_time_zone := sessiontimezone;
  -- Workaround
  if (l_time_zone != l_time_zone_orig) then
    dbms_output.put_line('----- 3 sessiontimezone = '|| sessiontimezone); 
    dbms_output.put_line('--******* Changed after dbms_job.change. Restore to Original: '|| l_time_zone_orig); 
    execute immediate 'alter session set time_zone = ''' || l_time_zone_orig || '''';
  end if;
 
  dbms_output.put_line('----- 4 sessiontimezone = '|| sessiontimezone);
 
  dbms_job.remove(l_job_id);
  commit;
  dbms_output.put_line('----- 5 sessiontimezone = '|| sessiontimezone);
end;      
/
 
-----=========== Test Output ===========----- 
 
----- 1 sessiontimezone = Europe/Paris
--******* l_job_id=86009
----- 2 sessiontimezone = Europe/Paris
----- 3 sessiontimezone = +02:00
--******* Changed after dbms_job.change. Restore to Original: Europe/Paris
----- 4 sessiontimezone = Europe/Paris
----- 5 sessiontimezone = Europe/Paris

4. Discussions

In all above three tests, we give a workaround to restore the original sessiontimezone.

We also tried to toggle dbms_scheduler attribute: 'default_timezone', there is no effect.

begin
  dbms_scheduler.set_scheduler_attribute(
    attribute => 'default_timezone',
    value     => 'Europe/Paris');
end;
/
 
select dbms_scheduler.stime from dual;
 
--   06-OCT-21 11.34.36.520960000 AM EUROPE/PARIS
 
begin
  dbms_scheduler.set_scheduler_attribute(
    attribute => 'default_timezone',
    value     => '02:00');
end;
/
 
select dbms_scheduler.stime from dual;
 
--   06-OCT-21 11.40.06.230467000 AM +02:00

It looks like that sessiontimezone is gotten by Oracle subroutine "pesstz", and dbtimezone by "pesdbtz".

It seems that session parameter modifications, for example:

  alter session set time_zone = 'CET';
  
  alter session set sql_trace=true;
  alter session set sql_trace=false;

are related to "kzctxhset".

MOS Note "DBMS_SCHEDULER or DBMS_JOB And DST / Timezones Explained (Doc ID 467722.1)" has a detail description of Job starting time in connection with Timezone setting in format of Named TZ (TZR) and Offset TZ (TZH:TZM).

Oracle Program and Table dc_objects "row cache lock"

In previous Blog: One "row cache lock" Test Case, we discussed dc_users "row cache lock".

In this Blog, we will look two types of dc_objects "row cache lock", one is Plsql program, another is table/partitions.

Note: Tested in Oracle 19c.

1. Test Setup

At first, we create two list partitioned tables, and Plsql procedures to add and drop partitions.

drop table test_tab_1 purge;
drop table test_tab_2 purge;

create table test_tab_1 (part_id number, val number) partition by list (part_id) (partition p_0 values (0));

create table test_tab_2 (part_id number, val number) partition by list (part_id) (partition p_0 values (0));

create or replace procedure add_part (p_tab_name varchar2, p_part_id number) as
  l_part_name  varchar2(10);
begin
  select decode(sign(p_part_id) , 1, 'P_', 'N_')||abs(p_part_id) into l_part_name from dual;
  execute immediate 'alter table '||p_tab_name||' add partition '||l_part_name||' values('||p_part_id||')';
  execute immediate 'insert into '||p_tab_name||' values ('||p_part_id||','||p_part_id||')';
  commit;
end;
/

create or replace procedure drop_part(p_tab_name varchar2, p_part_id number) as
  l_part_name  varchar2(10);
begin
  select decode(sign(p_part_id) , 1, 'P_', 'N_')||abs(p_part_id) into l_part_name from dual;
	execute immediate 'alter table '||p_tab_name||' drop partition '||l_part_name;
end;
/

-- exec add_part('TEST_TAB_1', 1);
-- exec drop_part('TEST_TAB_1', 1);

And one procedure to loop add and drop partitions:

create or replace procedure add_drop_part_loop(p_tab_name varchar2, p_cnt number, p_dur number, p_sign number := 1) as
	l_start   number := dbms_utility.get_time;
	l_run_cnt number := 0;
begin
  -- cleanup
	for c in (select * from dba_tab_partitions 
	           where table_name = p_tab_name and partition_name != 'P_0' and partition_name like (decode(p_sign, 1, 'P', 'N')||'_%')) 
	loop
	  drop_part(c.table_name, p_sign*substr(c.partition_name, 3));
	end loop;
	
  l_start  := dbms_utility.get_time;
  while (dbms_utility.get_time - l_start) < p_dur*100 loop
	  for i in 1..p_cnt loop
	    add_part(p_tab_name, p_sign*i);
	  end loop;
	  
	  for i in 1..p_cnt loop
	    drop_part(p_tab_name, p_sign*i);
	  end loop;
	  
	  l_run_cnt := l_run_cnt + 1;
	end loop;
	dbms_output.put_line('Table='||p_tab_name||', run_cnt='||l_run_cnt||', elapsed='||round((dbms_utility.get_time-l_start)/100));
end;
/

2. Program dc_objects "row cache lock"

We create a small Plsql program that depends on both above created tables.

create or replace procedure test_tab_bind as
  l_cnt number;
begin
  select count(*) into l_cnt from TEST_TAB_1, TEST_TAB_2; 
end;
/

Open two Sqlplus sessions (SID-1: 186, SID-2: 550), and run following test code for a duration of 300 seconds.
     In SID-1, we add_drop 'TEST_TAB_1';
     in SID-2, we add_drop 'TEST_TAB_2'.

-- SID-1: 186, add_drop 'TEST_TAB_1'
select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event 
where event = 'row cache lock' and sid = (select sid from v$mystat where rownum=1);

exec add_drop_part_loop('TEST_TAB_1', 100, 300);

select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event 
where event = 'row cache lock' and sid = (select sid from v$mystat where rownum=1);


--SID-2: 550, add_drop 'TEST_TAB_2'
select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event 
where event = 'row cache lock' and sid = (select sid from v$mystat where rownum=1);

exec add_drop_part_loop('TEST_TAB_2', 100, 300);

select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event 
where event = 'row cache lock' and sid = (select sid from v$mystat where rownum=1);

Here the test output:

-- SID-1: 186
select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event ...

  no rows selected

exec add_drop_part_loop('TEST_TAB_1', 100, 300);

  Table=TEST_TAB_1, run_cnt=79, elapsed=300

select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event ...   

  SID EVENT          TOTAL_WAITS TIME_WAITED AVERAGE_WAIT   MAX_WAIT
  --- -------------- ----------- ----------- ------------ ----------
  186 row cache lock        4143        3509          .85          3


--SID-2: 550
select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event ...

  no rows selected

exec add_drop_part_loop('TEST_TAB_2', 100, 300);

  Table=TEST_TAB_2, run_cnt=76, elapsed=300

select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event ...

  SID EVENT          TOTAL_WAITS TIME_WAITED AVERAGE_WAIT   MAX_WAIT
  --- -------------- ----------- ----------- ------------ ----------
  550 row cache lock        4142        3805          .92          3

We can see that there are about 4000 'row cache lock' concurrency waits in each session.

During the test, we can run query below to show the contention on 'dc_objects'
(cache_id: P1=8, Mode held: P2=0 (null), Mode request : P3=5 (exclusive))
(see MOS Docu: WAITEVENT: "row cache lock" Reference Note (Doc ID 34609.1)):

select chain_signature, sid, pid, osid, blocker_sid, blocker_is_valid, p1, p2, p3 from v$wait_chains;

  CHAIN_SIGNATURE    SID  PID OSID   BLOCKER_SID BLOCK   P1   P2   P3
  ---------------- ----- ---- ------ ----------- ----- ---- ---- ----
  'row cache lock'   186   49 11421          550 TRUE     8    0    5
  <not in a wait>    550   57 11575              FALSE

If we check DIAG dia0 or mmnl trace files, we can see the blocked session, blocker session, and the requested row cache parent address (po 0x9c79f958) in mode X. (we will give a further look in Section 4: dc_objects Internals).

--testdb_dia0_10885_base_1.trc
--testdb_mmnl_10915.trc

*** 2021-06-25T11:37:49.281348+02:00
kqrhngc ph1: po 0x9c79f958 req X from session 0xb8d1d508 lock 0x9cbfb5e8
kqrhngc ph1: blocker #1 owner  mode X session 0xb8990bb8 lock 0x9d32f7e0

With following query, we can find the contention dc_object: TEST_TAB_BIND (see Blog: Oracle ROWCACHE Views and Contents ):

select to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX') user_id,
       (select username from dba_users where user_id = 
          to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX')) user_name,
       dump_hex2str(rtrim(substr(key, 13), '0')) dc_object_name, 
       to_number(trim(both '0' from substr(key, 11, 2)||substr(key, 9, 2)), 'XXXX') key_len,
       indx, hash, address, cache#, cache_name, existent, lock_mode, lock_request, txn, saddr --,v.* 
from v$rowcache_parent v
where cache_name in ('dc_objects') and address like upper('%9c79f958');

  USER_ID USER_NAME  DC_OBJECT_NAME  KEY_LEN  INDX  HASH ADDRESS  CACHE# CACHE_NAME E LOCK_MODE LOCK_REQUEST TXN      SADDR
  ------- ---------- --------------- ------- ----- ----- -------- ------ ---------- - --------- ------------ -------- --------
       49 K          TEST_TAB_BIND        13  7196  5950 9C79F958      8 dc_objects Y         0            5 AE97BC88 B8D1D508
       49 K          TEST_TAB_BIND        13  7197  5950 9C79F958      8 dc_objects Y         5            0 AE97BC88 B8990BB8
       49 K          TEST_TAB_BIND        13 11549 27359 9C79F958      8 dc_objects Y         5            0 AE92EF30 B8D1D508

We can also list the involved sessions and (recursive) transactions:
(Note:
   gv$transaction is defined on x$ktcxb with filter: bitand (ksspaflg, 1) != 0 and bitand (ktcxbflg, 2) != 0.
   We use x$ktcxb since they are recursive transactions, which are filtered out in gv$transaction)

select sid, dc_object_name, r.indx, hash, address, cache#, cache_name, existent, lock_mode, lock_request, 
       txn, r.saddr, s.blocking_session --, s.*, t.* 
from (
  select to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX') user_id,
         (select username from dba_users where user_id = 
            to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX')) user_name,
         dump_hex2str(rtrim(substr(key, 13), '0')) dc_object_name, 
         to_number(trim(both '0' from substr(key, 11, 2)||substr(key, 9, 2)), 'XXXX') key_len, v.* 
  from v$rowcache_parent v
  where cache_name in ('dc_objects') and address like upper('%9c79f958')
  order by key) r, gv$session s, x$ktcxb t
where r.saddr = s.saddr(+) and r.txn = t.ktcxbxba(+);

  SID DC_OBJECT_NAME INDX  HASH  ADDRESS  CACHE# CACHE_NAME E LOCK_MODE LOCK_REQUEST TXN      SADDR    BLOCKING_SESSION
  ---- ------------- ----- ----- -------- ------ ---------- - --------- ------------ -------- -------- ----------------
   186 TEST_TAB_BIND  7291  5950 9C79F958      8 dc_objects Y         0            5 AEAB4380 B8990BB8              550
   186 TEST_TAB_BIND 11641 27359 9C79F958      8 dc_objects Y         5            0 AE7F2248 B8990BB8              550
   550 TEST_TAB_BIND  7292  5950 9C79F958      8 dc_objects Y         5            0 AEAB4380 B8D1D508

We can see that the contention of dc_objects 'row cache lock' is on 'TEST_TAB_BIND' because it binds TEST_TAB_1 and TEST_TAB_2 together.

If we invalidate 'TEST_TAB_BIND' by "dbms_utility.invalidate" and repeat above test, no more 'row cache lock' contention can be observed (Probably this can be used as a quick workaround to fix such contention).

select object_name, object_id, status from dba_objects where object_name = 'TEST_TAB_BIND';

  OBJECT_NAME    OBJECT_ID  STATUS
  ------------- ---------- -------
  TEST_TAB_BIND    4509953  VALID

exec sys.dbms_utility.invalidate(p_object_id =>4509953);  

--to validate:
--alter procedure TEST_TAB_BIND compile;

select object_name, object_id, status from dba_objects where object_name = 'TEST_TAB_BIND';

  OBJECT_NAME    OBJECT_ID  STATUS
  ------------- ---------- --------
  TEST_TAB_BIND    4509953  INVALID

In contrast to "dbms_utility.invalidate", if we created an INVALID Plsql program as follows and repeat above test, there still exists the same 'row cache lock' contention.

create or replace procedure test_tab_bind as
  l_cnt number;
begin
  -- xxxx_cnt is wrong name
  select count(*) into xxxx_cnt from TEST_TAB_1, TEST_TAB_2;  
end;
/

  Warning: Procedure created with compilation errors.
  
  5/24     PLS-00201: identifier 'XXXX_CNT' must be declared
  5/33     PL/SQL: ORA-00904: : invalid identifier

select object_name, object_id, status from dba_objects where object_name = 'TEST_TAB_BIND';

  OBJECT_NAME    OBJECT_ID  STATUS
  ------------- ---------- --------
  TEST_TAB_BIND    4509953  INVALID

After test, we re-create our VALID Plsql program:

create or replace procedure test_tab_bind as
  l_cnt number;
begin
  select count(*) into l_cnt from TEST_TAB_1, TEST_TAB_2; 
end;
/

select object_name, object_id, status from dba_objects where object_name = 'TEST_TAB_BIND';

  OBJECT_NAME    OBJECT_ID  STATUS
  ------------- ---------- -------
  TEST_TAB_BIND    4509953  VALID

3. Table and Partition dc_objects "row cache lock"

In last section, we demonstrated dc_objects "row cache lock" on Plsql program.
In this section, we will look dc_objects "row cache lock" on table/partition.

In two above Sqlplus sessions (SID-1: 186, SID-2: 550), run following test code for a duration of 300 seconds.
     In SID-1, we add_drop 'TEST_TAB_1' partitions prefixed by 'P_';
     in SID-2, we add_drop 'TEST_TAB_1' partitions prefixed by 'N_'.

-- SID-1: 186, add_drop 'TEST_TAB_1' partitions prefixed by 'P_'
select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event 
where event = 'row cache lock' and sid = (select sid from v$mystat where rownum=1);

-- Create/Drop partitions with name prefixed 'P_'
exec add_drop_part_loop('TEST_TAB_1', 100, 300, p_sign=>1);

select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event 
where event = 'row cache lock' and sid = (select sid from v$mystat where rownum=1);
       

-- SID-2: 550, add_drop 'TEST_TAB_1' partitions prefixed by 'N_'.    
select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event 
where event = 'row cache lock' and sid = (select sid from v$mystat where rownum=1);

-- Create/Drop partitions with name prefixed 'N_'
exec add_drop_part_loop('TEST_TAB_1', 100, 300, p_sign=>-1);

select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event 
where event = 'row cache lock' and sid = (select sid from v$mystat where rownum=1);

Here the test output. It shows that each session has about 500 'row cache lock' concurrency waits (5780-5217=563, 5751-5218=533).

-- SID-1: 186
select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event ...

  SID EVENT          TOTAL_WAITS TIME_WAITED AVERAGE_WAIT   MAX_WAIT
  --- -------------- ----------- ----------- ------------ ----------
  186 row cache lock        5217        5563         1.07          4

exec add_drop_part_loop('TEST_TAB_1', 100, 300, p_sign=>1);

  Table=TEST_TAB_1, run_cnt=23, elapsed=300

select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event ...

  SID EVENT          TOTAL_WAITS TIME_WAITED AVERAGE_WAIT   MAX_WAIT
  --- -------------- ----------- ----------- ------------ ----------
  186 row cache lock        5780        7246         1.25          7
       
   
-- SID-2: 500           
select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event ...

  SID EVENT          TOTAL_WAITS TIME_WAITED AVERAGE_WAIT   MAX_WAIT
  --- -------------- ----------- ----------- ------------ ----------
  550 row cache lock        5218        5804         1.11          4

exec add_drop_part_loop('TEST_TAB_1', 100, 300, p_sign=>-1);

  Table=TEST_TAB_1, run_cnt=22, elapsed=304
   
select sid, event, total_waits, time_waited, average_wait, max_wait from v$session_event ...

  SID EVENT          TOTAL_WAITS TIME_WAITED AVERAGE_WAIT   MAX_WAIT
  --- -------------- ----------- ----------- ------------ ----------
  550 row cache lock        5751        7334         1.28          6

During the test, we run query below to show the contention on 'dc_objects'
(cache_id: P1=8, Mode held: P2=0 (null), Mode request : P3=3 (share mode)).

Comparing to above P3=5 (exclusive) in case of dc_object Plsql program, dc_object table/partition request is blocked with P3=3 (share mode). (we will give a further look in Section 4: dc_objects Internals).

select chain_signature, sid, pid, osid, blocker_sid, blocker_is_valid, p1, p2, p3 from v$wait_chains;

  CHAIN_SIGNATURE                   SID PID OSID   BLOCKER_SID BLOCK  P1  P2  P3
  --------------------------------- --- --- ------ ----------- ----- --- --- ---
  <not in a wait><='row cache lock' 550  57 11575          186 TRUE    8   0   3
  <not in a wait><='row cache lock' 186  49 11421              FALSE

If we check DIAG dia0 or mmnl trace files, we can see the blocked session, blocker session. The blocked session requested row cache parent address (po 0x9c971fa8) in mode S, and blocked by mode X, held by blocker session.

      
--testdb_dia0_10885_base_1.trc
--testdb_mmnl_10915.trc

*** 2021-06-25T12:07:10.296235+02:00
kqrhngc ph1: po 0x9c971fa8 req S from session 0xb8990bb8 lock 0x9cfb6d50
kqrhngc ph1: blocker #1 owner  mode X session 0xb8d1d508 lock 0x9cbfd7b8

Similar to above Plsql program, we can also list the sessions and (recursive) transactions with po 0x9c971fa8:

select sid, dc_object_name, r.indx, hash, address, cache#, cache_name, existent, lock_mode, lock_request, 
       txn, r.saddr, s.blocking_session --, s.*, t.* 
from (
  select to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX') user_id,
         (select username from dba_users where user_id = 
            to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX')) user_name,
         dump_hex2str(rtrim(substr(key, 13), '0')) dc_object_name, 
         to_number(trim(both '0' from substr(key, 11, 2)||substr(key, 9, 2)), 'XXXX') key_len, v.* 
  from v$rowcache_parent v
  where cache_name in ('dc_objects') and address like upper('%9c971fa8')
  order by key) r, gv$session s, x$ktcxb t
where r.saddr = s.saddr(+) and r.txn = t.ktcxbxba(+);

  SID DC_OBJECT_NAME  INDX  HASH ADDRESS  CACHE# CACHE_NAME E LOCK_MODE LOCK_REQUEST TXN      SADDR    BLOCKING_SESSION
  --- --------------- ---- ----- -------- ------ ---------- - --------- ------------ -------- -------- ----------------
  186 TEST_TAB_1      5267 19145 9C971FA8      8 dc_objects Y         0            3 AEB04B20 B8990BB8              550
  550 TEST_TAB_1      8110 22657 9C971FA8      8 dc_objects Y         5            0 AEB04B20 B8D1D508
  186 TEST_TAB_1      8109 22657 9C971FA8      8 dc_objects Y         0            3 AEB04B20 B8990BB8              550
  550 TEST_TAB_1      5268 19145 9C971FA8      8 dc_objects Y         5            0 AEB04B20 B8D1D508

4. dc_objects Internals

To further understand 'row cache lock' contentions, we will make a blocking test with breakpoint, trace session activities, and dump Row Cache Data.

4.1 Blocking Test

At first, add one partition into 'TEST_TAB_1', and one into 'TEST_TAB_2':

exec add_part('TEST_TAB_1', 1);
exec add_part('TEST_TAB_2', 1);

Continue with two above Sqlplus sessions (SID-1: 186, SID-2: 550).

In SID-1 (ospid: 11421), set a breakpoint at retq of kqrpre1 with condition of above Plsql program dc_object (TEST_TAB_BIND: po 0x9c79f958):

gdb -p 11421

# break *kqrpre1 if $rdi==0x8 && $rcx==0x5
# <+3564>:	retq  
break *kqrpre1+3564 if $rdx==0x9c79f958

In SID-1, drop one partition of 'TEST_TAB_1':

-- SID-1
exec drop_part('TEST_TAB_1', 1);

It stopped with following frame info:

(gdb) c
Continuing.

Breakpoint 1, 0x00000000037ac6bc in kqrpre1 ()

(gdb) display /x $rdx
1: /x $rdx = 0x9c79f958

(gdb) bt 6
#0  0x00000000037ac6bc in kqrpre1 ()
#1  0x00000000032e95d6 in kqlidp0_int ()
#2  0x00000000032e7c19 in kqlidp0 ()
#3  0x0000000002631424 in atbFMdrop ()
#4  0x000000000261976a in atbdrv ()
#5  0x00000000127b19b0 in opiexe ()
(More stack frames follow...)

In SID-2, drop one partition of 'TEST_TAB_2':

-- SID-2
exec drop_part('TEST_TAB_2', 1);

Here the output of v$wait_chains (Mode request: P3=5 (exclusive)):

select chain_signature, sid, pid, osid, blocker_sid, blocker_is_valid, p1, p2, p3 from v$wait_chains;

  CHAIN_SIGNATURE                   SID PID OSID  BLOCKER_SID BLOCK  P1  P2  P3
  --------------------------------- --- --- ----- ----------- ----- --- --- ---
  <not in a wait><='row cache lock' 550  57 11575         186 TRUE    8   0   5
  <not in a wait><='row cache lock' 186  49 11421             FALSE

Some new lines appear in dia0 and mmnl trace files:

--testdb_dia0_10885_base_1.trc
--testdb_mmnl_10915.trc

*** 2021-06-25T11:37:49.281348+02:00
kqrhngc ph1: po 0x9c79f958 req X from session 0xb8d1d508 lock 0x9cbfb5e8
kqrhngc ph1: blocker #1 owner  mode X session 0xb8990bb8 lock 0x9d32f7e0

We can also list the contention details with the sessions and (recursive) transactions on po 0x9c79f958:

select sid, dc_object_name, r.indx, hash, address, cache#, cache_name, existent, lock_mode, lock_request, 
       txn, r.saddr, s.blocking_session --, s.*, t.* 
from (
  select to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX') user_id,
         (select username from dba_users where user_id = 
            to_number(ltrim((substr(key, 7, 2)||substr(key, 5, 2)||substr(key, 3, 2)||substr(key, 1, 2)), '0'), 'XXXX')) user_name,
         dump_hex2str(rtrim(substr(key, 13), '0')) dc_object_name, 
         to_number(trim(both '0' from substr(key, 11, 2)||substr(key, 9, 2)), 'XXXX') key_len, v.* 
  from v$rowcache_parent v
  where cache_name in ('dc_objects') and address like upper('%9c79f958')
  order by key) r, gv$session s, x$ktcxb t
where r.saddr = s.saddr(+) and r.txn = t.ktcxbxba(+);

  SID DC_OBJECT_NAME  INDX  HASH ADDRESS  CACHE# CACHE_NAME E LOCK_MODE LOCK_REQUEST TXN      SADDR    BLOCKING_SESSION
  --- -------------- ----- ----- -------- ------ ---------- - --------- ------------ -------- -------- ----------------
  550 TEST_TAB_BIND   6779  5950 9C79F958      8 dc_objects Y         0            5 AE92C090 B8D1D508              186
  186 TEST_TAB_BIND  28027 27359 9C79F958      8 dc_objects Y         5            0 AE92C090 B8990BB8
  550 TEST_TAB_BIND  28026 27359 9C79F958      8 dc_objects Y         0            5 AE92C090 B8D1D508              186
  186 TEST_TAB_BIND   6780  5950 9C79F958      8 dc_objects Y         5            0 AE92C090 B8990BB8

dia0 also shows blocking chain and call stack:

--testdb_dia0_10885_base_1.trc

*** 2021-06-25T16:19:35.806182+02:00
HM: Session with ID 550 serial # 22155 (FG) on single instance 1 is hung
    and is waiting on 'row cache lock' for 334 seconds.
    Final Blocker is Session ID 186 serial# 60254 on instance 1
     which is 'not in a wait' for 586 seconds
     
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
              session id: 550
    }
    is waiting for 'row cache lock' with wait info:
    {
                      p1: 'cache id'=0x8
                      p2: 'mode'=0x0
                      p3: 'request'=0x5
            time in wait: 1.370457 sec (last interval)
            time in wait: 5 min 34 sec (total)  
    }
    and is blocked by
 => Oracle session identified by:
    {
              session id: 186
    }
              
HM: Short Stack of immediate waiter session ID 550 serial# 22155, OSPID 11575 (FG)
Short stack dump: 
ksedsts()+426<-ksdxfstk()+58<-ksdxcb()+872<-sspuser()+200<-__sighandler()<-semtimedop()+10<-skgpwwait()+192<-ksliwat()+2192<-kslwaitctx()+200
<-kqrget()+1397<-kqrLockPo()+1644<-kqrpre1()+2373<-kqlidp0_int()+5990<-kqlidp0()+521<-atbFMdrop()+692<-atbdrv()+7722<-opiexe()+30672
 
HM: current SQL: alter table TEST_TAB_2 drop partition P_1

After the test, quit debugger to complete both partition dropping.

4.2 Trace Files

We will add one partition into 'TEST_TAB_1', and then trace the activities of partition drop: (see Blog: Oracle row cache objects Event: 10222, Dtrace Scripts (I) )

Add one partition:

exec add_part('TEST_TAB_1', 1);

Then drop it with tracing:

alter session set max_dump_file_size = UNLIMITED;
alter session set events='10046 trace name context forever, level 12 : 
                          10704 trace name context forever, level 3 : 
                          10222 trace name context forever, level 4294967295' 
                  tracefile_identifier='rcl_1';

exec drop_part('TEST_TAB_1', 1);

alter session set events='10046 trace name context off : 10704 trace name context off : 10222 trace name context off'; 

In the first part of trace file, we can see that "name=TEST_TAB_1" (po 0x9c971fa8) is gotten in "mode=S". That is probably why P3=3 (share mode) in case of table/partition 'row cache lock' contention. The flag: "transaction=(nil)" also shows that there is no transaction in this part:

KQR: cid  8 bucket  19145 marked HOT
kqrpre: start hash=7c144ac9 mode=S keyIndex=0 dur=CALL opt=FALSE hot=TRUE
kqrScan: hot hash chain: processing po 0x9c971fa8
kqrpre: found cached object po=0x9c971fa8 flg=2
kqrmpin : kqrpre: found po Pin po 0x9c971fa8 cid=8 flg=2 hash=7c144ac9
time=2774049915
kqrpre: pinned po=0x9c971fa8 flg=2 pso=0xa0294020
pinned stack po=0x9c971fa8 cid=8: 
----- Abridged Call Stack Trace -----
ksedsts()+426<-kqrpre()+1985<-kkdlgonm()+229<-ktfa_check_ddl_fda_tables()+729<-opiSem()+23554<-opiprs()+321<-kksParseChildCursor()+527
<-rpiswu2()+2004<-kksLoadChild()+5283<-kxsGetRuntimeLock()+1983<-kksfbc()+18656<-kkspsc0()+1566<-kksParseCursor()+114<-opiosq0()+2310
----- End of Abridged Call Stack Trace -----
Partial short call stack signature: 0x4d19b7541a515b26
kqrAllocateEnqueue: bis: po=0x9c971fa8 flag=00010000 before=00000002 after=00010002
kqrget bic: po=0x9c971fa8 flag=00010000 before=00010002 after=00000002
kqrpre: done po=0x9c971fa8 cid=8 flg=2 eq=0x9cfbbb88 pso=0xa0294020 dur=CALL
kqrpre: keyIndex=0 hash=7c144ac9 99535881 0
kqrpre: obobn=4547616 obname=TEST_TAB_1 obtyp=2 obsta=1 obflg=0
kqrpre: SQL=alter table TEST_TAB_1 drop partition P_1 kqrpre: time=2774053161
kqrpre: po=0x9c971fa8 cid=8 stack: 
----- Abridged Call Stack Trace -----
ksedsts()+426<-kqrpreDoneTrace()+613<-kqrpre()+2954<-kkdlgonm()+229<-ktfa_check_ddl_fda_tables()+729<-opiSem()+23554<-opiprs()+321<-
----- End of Abridged Call Stack Trace -----
kqrpre: returnVal: TRUE
kqrprl: eq=0x9cfbbb88 fpInUse=FALSE

kqreqd: eq=0x9cfbbb88 res=0x9c972078
----------------------------------------
row cache enqueue: count=0 session=0xb8990bb8 object=0x9c971fa8, mode=S
flag=00 -/-/-/-/-/-/-/- savepoint=0x91da37
row cache parent object: addr=0x9c971fa8 cid=8(dc_objects)
hash=7c144ac9 typ=1 transaction=(nil) flags=00000002
objectno=4547616 ownerid=49 nsp=1
name=TEST_TAB_1
own=0x9c972078[0x9cfbbc08,0x9cfbbc08] wat=0x9c972088[0x9c972088,0x9c972088] mode=S req=N
status=VALID/-/-/-/-/-/-/-/-/-/-/-  KGH pinned  
            [........]        
kqreqd: processing po=0x9c971fa8 flag=2 mode=S
kqrmupin : kqrReleaseLock Unpin po 0x9c971fa8 cid=8 flg=2 hash=7c144ac9 time=2774055412
kqreqd freed enqeue: eq: 0x9cfbbb88
time=2774055435
            [........] 

In the second part of trace file, we can see all three involved objects (partition, program, table):

  name=TEST_TAB_1subname=P_1
  name=TEST_TAB_BIND
  name=TEST_TAB_1

which are all gotten in "mode=X".

For table "name=TEST_TAB_1", in the first part, it is gotten in "mode=S", in the second part, it is gotten in "mode=X".

For Plsql program "name=TEST_TAB_BIND", it is only gotten once in this second part, that is "mode=X" . That is probably why (P3=5 (exclusive)) in case of Plsql program 'row cache lock' contention. The flag: "transaction=0xae92d7e0" shows that they are all involved in one (recursive) transaction.

Here some extract lines from trace file of 'dc_objects' and transaction call stacks (xctCommitTxn).

           
kqreqd: eq=0x9a64a500 res=0x9c8f2d40
----------------------------------------
SO: 0x9caf9990, type: row cache enqueues (111), map: 0x9a64a500
SOC: 0x9a64a500, type: row cache enqueues (111), map: 0x9caf9990
row cache enqueue: count=2 session=0xb8990bb8 object=0x9c8f2c70, mode=X
flag=00 -/-/-/-/-/-/-/- savepoint=0x91dd75
row cache parent object: addr=0x9c8f2c70 cid=8(dc_objects)
hash=28cd6d03 typ=1 transaction=0xae92d7e0 flags=00002001
objectno=4605248 ownerid=49 nsp=1
name=TEST_TAB_1subname=P_1
own=0x9c8f2d40[0x9a64a580,0x9a64a580] wat=0x9c8f2d50[0x9c8f2d50,0x9c8f2d50] mode=X req=N
status=EMPTY/-/-/-/-/-/-/-/NEEDS INV/-/-/-  KGH pinned  
            [........]        
kqreqd: processing po=0x9c8f2c70 flag=2001 mode=X
kqrInvalidateObject clear: ob=0x9c8f2c70 before=00002001 after=00000000
kqrmupin : kqrReleaseLock Unpin po 0x9c8f2c70 cid=8 flg=0 hash=28cd6d03 time=2779225491
kqreqd freed enqeue: eq: 0x9a64a500
time=2779225499


kqreqd: eq=0x9d32f938 res=0x9c79fa28
----------------------------------------
SO: 0xa6e6c660, type: row cache enqueues (111), map: 0x9d32f938
SOC: 0x9d32f938, type: row cache enqueues (111), map: 0xa6e6c660
row cache enqueue: count=1 session=0xb8990bb8 object=0x9c79f958, mode=X
flag=40 -/-/-/-/-/-/XLG/- savepoint=0x91da6e
row cache parent object: addr=0x9c79f958 cid=8(dc_objects)
hash=2526973e typ=1 transaction=0xae92d7e0 flags=00000002
objectno=4509953 ownerid=49 nsp=1
name=TEST_TAB_BIND
own=0x9c79fa28[0x9d32f9b8,0x9d32f9b8] wat=0x9c79fa38[0x9c79fa38,0x9c79fa38] mode=X req=N
status=VALID/-/-/-/-/-/-/-/-/-/-/-  KGH pinned  
            [........]        
kqreqd: processing po=0x9c79f958 flag=2 mode=X
kqrmupin : kqrReleaseLock Unpin po 0x9c79f958 cid=8 flg=2 hash=2526973e time=2779225965
kqreqd freed enqeue: eq: 0x9d32f938
time=2779225973


kqreqd: eq=0x9cfb2428 res=0x9c972078
----------------------------------------
SO: 0xa6e79900, type: row cache enqueues (111), map: 0x9cfb2428
SOC: 0x9cfb2428, type: row cache enqueues (111), map: 0xa6e79900
row cache enqueue: count=6 session=0xb8990bb8 object=0x9c971fa8, mode=X
flag=00 -/-/-/-/-/-/-/- savepoint=0x91da49
row cache parent object: addr=0x9c971fa8 cid=8(dc_objects)
hash=7c144ac9 typ=1 transaction=0xae92d7e0 flags=00000002
objectno=4547616 ownerid=49 nsp=1
name=TEST_TAB_1
own=0x9c972078[0x9cfb24a8,0x9cfb24a8] wat=0x9c972088[0x9c972088,0x9c972088] mode=X req=N
status=VALID/-/-/-/-/-/-/-/-/-/-/-  KGH pinned  
            [........]        
kqreqd: processing po=0x9c971fa8 flag=2 mode=X
kqrmupin : kqrReleaseLock Unpin po 0x9c971fa8 cid=8 flg=2 hash=7c144ac9 time=2779226293
kqreqd freed enqeue: eq: 0x9cfb2428
time=2779226300


Abridged Call Stack Trace -----
ksedsts()+426<-kqrpre()+1985<-ktssexist_segment()+159<-ktssdro_segment()+317<-ktadrpc()+103
<-ktcccDeleteCommitCallbacks()+439<-ktcccdel()+46<-ktccpcmt()+310<-ktcCommitTxn_new()+1779
<-ktcCommitTxn()+94<-ktdcmt()+120<-k2lcom()+165<-k2send()+1220<-xctctl()+94
<-xctCommitTxn()+669<-opiexe()+19234
----- End of Abridged Call Stack Trace -----

In above trace, we can also see some lines like:

  kqrpre: optimistic lookup: hash=2546ac00
  kqrpre: optimistic lookup: searching cache 0 po 0xa22b6ac8 hash      226 ver 1
  kqrpre: optimistic lookup: searching cache 1 po 0xa22b6ac8 hash      226 ver 1
  ...
  kqrpre: optimistic lookup: searching cache 6 empty
  ...
  kqrpre: optimistic lookup: searching cache 9 po 0xa22b6ac8 hash      226 ver 1
  kqrpre: optimistic lookup: reading hash mtx addr=0xa85e7570 version=78
  kqrpre: optimistic lookup: processing po 0xa3def4a0 mtx addr=0xa3def640 version=82
  kqrpre: optimistic lookup: lock mode 0 flag 00000002
  kqrpre: optimistic lookup: fail

It can be toggled by a hidden parameter (18c changed default from FALSE to TRUE):

   _kqr_optimistic_reads	   optimistic reading of row cache objects	    TRUE

4.3. Row Cache Data Dump

With following command, we can dump 'dc_objects'.
(See MOS Bug 19354335 - Diagnostic enhancement for rowcache data dumps (Doc ID 19354335.8)
and Blog: Row Cache Object and Row Cache Mutex Case Study )

    
alter session set max_dump_file_size = UNLIMITED;
alter session set tracefile_identifier = 'dc_objects_dump';
-- dump level 0x82b: f is cache id 8 ('dc_objects'), 2 is single cacheiddump, b is level of 11
alter session set events 'immediate trace name row_cache level 0x82b';
alter session set events 'immediate trace name row_cache off';

The dump file consists of two parts, the first is ROW CACHE STATISTICS; and the second is 'dc_objects' data sorted by BUCKET:

ROW CACHE STATISTICS:
cache                          size     gets  misses  hit ratio  
--------------------------  -------  -------  ------  ---------  
dc_objects                     1056  3224531   49309      0.985  
  dc_object_grants               96     1673     308      0.845

dc_users                       2072  2877996     102      1.000  
  dc_users                      392        0       0      0.000
  dc_user_grants                376   353752      26      1.000
  dc_app_role                   320        0       0      0.000
  user's audit policies          64        0       0      0.000
  user's audit contexts         320        0       0      0.000
  CONTAINER_DATA_Attributes     584        0       0      0.000

WARNING: Restricting rowcache dump to just cacheid 8
ROW CACHE HASH TABLE: cid=8 ht=0xa8760de0 size=32768
Buckets with more than 20 objects:
NONE
Hash Chain Size     Number of Buckets
---------------     -----------------
              0                     0
              1                 11697
              2                  4810
              3                  1239
              4                   272
              5                    48
  ...
            >20                     0

BUCKET 5951:
  row cache parent object: addr=0x9c79f958 cid=8(dc_objects)
  hash=2526973e typ=1 transaction=(nil) flags=00000002
  objectno=4509953 ownerid=49 nsp=1
  name=TEST_TAB_BIND
  data=
  00000031 4554000d 545f5453 425f4241 00444e49 00000000 00000000 00000000 ...
  BUCKET 5951 total object count=1
             
BUCKET 19146:
  row cache parent object: addr=0x9c971fa8 cid=8(dc_objects)
  hash=7c144ac9 typ=1 transaction=(nil) flags=00000002
  objectno=4547616 ownerid=49 nsp=1
  name=TEST_TAB_1
  data=
  00000031 4554000a 545f5453 315f4241 00000000 00000000 00000000 00000000 ...
  BUCKET 19146 total object count=1
  
BUCKET 27908:
  row cache parent object: addr=0x9c8f2c70 cid=8(dc_objects)
  hash=28cd6d03 typ=1 transaction=(nil) flags=00000000
  objectno=4605248 ownerid=49 nsp=1
  name=TEST_TAB_1  subname=P_1
  data=
  00000031 4554000a 545f5453 315f4241 00000000 00000000 00000000 00000000 ...
  BUCKET 27908 total object count=1

In DB alert.log, we can see some buckets marked HOT:

2021-06-25T17:43:19.272935+02:00
KQR: cid 10 bucket  20941 marked HOT
KQR: cid  8 bucket  22482 marked HOT
KQR: cid  2 bucket  11264 marked HOT

which are probably checked by:

     kqrScan: reached _kqr_max_hot_copies limit %d

but "_kqr_max_hot_copies" is not (yet) exposed (maybe it will be similar to "_kgl_hot_object_copies").

Update 2023-Aug-23: "_kqr_max_hot_copies" is now exposed in Oracle 21c

   _kqr_max_hot_copies: upper limit of object hot copies allowed (default 16)

In DB alert.log, we can see:

2023-08-18T05:14:13.661259+02:00
  KQR row cache hit _kqr_max_hot_copies limit 16 cid 10 bucket 17930
2023-08-18T06:21:09.844089+02:00
  KQR row cache hit _kqr_max_hot_copies limit 16 cid 10 bucket 31900

2023-08-18T11:21:01.397443+02:00
  KQR row cache contention check: gets 1000000 sleeps 5577 limit 5000
  KQR row cache hash chain marked hot: cid 0 hash f27284a6
  KQR: cid  0 bucket      6 marked HOT (kqrpre: mutex sleeps exceed limit)

MOS "Bug 31135517 - High row cache mutex waits on hot objects - superseded (Doc ID 31135517.8)" describes that the fix implements 'hot object cloning' to alleviate row cache mutex contention.

In Trace Files, we can also see the 19.9 new introduced subroutine "kqrScan" (called by kqrpre or kqrpre2).