DBMS_SCHEDULER Job Not Running and Used Slaves

Oracle parameter JOB_QUEUE_PROCESSES specifies the maximum number of job slaves per instance that can be created for the execution of DBMS_JOB jobs and Oracle Scheduler (DBMS_SCHEDULER) jobs. The number of free available slaves (#free_slaves) is JOB_QUEUE_PROCESSES minus the number of used slaves (#used_slaves). When #used_slaves >= JOB_QUEUE_PROCESSES, no more job slaves are able to run.

In this Blog, we will show that #used_slaves not only counts the currently running jobs, but also abnormal terminated jobs, which include incident jobs and killed jobs.

Note: 
        Tested and reproducible in Oracle 18.10, 19.6 and 19.7. 
        Partially reproducible in Oracle 12.1.
        Not reproducible in Oracle 19.8.
        
        *  Oracle 19.8 changed this Blog tested behaviour.

1. Test Setup

We will create two types of repeated DBMS_SCHEDULER jobs. The first one is the abnormal terminated jobs which crashes with ORA-600 [4156] (see Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling); The second is normal jobs with each running duration of 60 seconds.

drop table t purge;
create table t(id number, label varchar2(20));
insert into t(id, label) select level, 'label_'||level from dual connect by level <= 100;
commit;

create or replace procedure test_proc_crashed(p_i number) as
begin 
  savepoint sp;
  update t set label = label where id = p_i;
  execute immediate '
    begin
      raise_application_error(-20000, ''error-sp'');
    exception
      when others then
        rollback to savepoint sp;
        update t set label = label where id = '||p_i||';
        raise;
    end;';        
end;
/

create or replace procedure start_job_crashed(p_count number) as
begin
  for i in 1..p_count loop
    dbms_scheduler.create_job (
      job_name        => 'TEST_JOB_CRASHED_'||i,
      job_type        => 'PLSQL_BLOCK',
      job_action      => 'begin test_proc_crashed('||i||'); end;',    
      start_date      => systimestamp,
      repeat_interval => 'systimestamp',
      auto_drop       => true,
      enabled         => true);
  end loop;
end;
/

create or replace procedure start_job_normal(p_count number) as
  l_job_name varchar2(50);
begin
  for i in 1..p_count loop
    l_job_name := 'TEST_JOB_NORMAL_'||i;
    dbms_scheduler.create_job (
      job_name        => l_job_name,
      job_type        => 'PLSQL_BLOCK',
      job_action      => 
        'begin 
           dbms_lock.sleep(13); 
           dbms_scheduler.set_attribute(
              name      => '''||l_job_name||'''
             ,attribute => ''start_date''
             ,value     => systimestamp);
           dbms_lock.sleep(47);
        end;',    
      start_date      => systimestamp,
      repeat_interval => 'systimestamp',
      auto_drop       => true,
      enabled         => true);
  end loop;
end;
/

2. Test Start

At first, we set job_queue_processes to 13, and at the same time trace DBMS_SCHEDULER coordinator CJQ0 with event 27402 level 65535.

alter system set job_queue_processes=13 scope=memory;
alter system set max_dump_file_size = unlimited scope=memory;

-- DBMS_SCHEDULER coordinator CJQ0 (sid, s.serial#) = (7, 15601)
exec sys.dbms_system.set_ev(7, 15601, 27402, 65535, '');

then start two test_proc_crashed jobs and one normal job.

exec start_job_crashed(2);
exec start_job_normal(1);

During the test, we continously monitor running jobs in dba_scheduler_running_jobs, and job state ("RUNNING") in dba_scheduler_jobs:

select job_name,session_id, slave_process_id, slave_os_process_id, elapsed_time, log_id 
  from dba_scheduler_running_jobs;

  JOB_NAME            SESSION_ID SLAVE_PROCESS_ID SLAVE_OS_PRO ELAPSED_TIME      LOG_ID
  ------------------- ---------- ---------------- ------------ ------------------------
  TEST_JOB_CRASHED_2         375               62 25302        +000 00:00:06.93 8587896
  TEST_JOB_NORMAL_1          731               64 25130        +000 00:00:06.95 8587892
  TEST_JOB_CRASHED_1         910               65 25270        +000 00:00:06.95 8587894

select job_name, enabled, state, run_count, failure_count, retry_count, start_date, last_start_date, next_run_date
  from dba_scheduler_jobs v where job_name like '%TEST_JOB%';

  JOB_NAME            ENABL STATE   RUN_COUNT FAILURE_COUNT RETRY_COUNT START_DATE   LAST_START_DATE  NEXT_RUN_DATE
  ------------------- ----- ----------------- ------------- ----------- ------------ ---------------- -------------
  TEST_JOB_CRASHED_1  TRUE  RUNNING         2             0           0 10:37:05.497 10:38:12.072     10:37:45.054
  TEST_JOB_CRASHED_2  TRUE  RUNNING         2             0           0 10:37:06.370 10:38:12.090     10:37:45.071
  TEST_JOB_NORMAL_1   TRUE  RUNNING         1             0           0 10:37:24.732 10:38:12.071     10:37:24.769

After a few minutes, we can see that there are no more running jobs in dba_scheduler_running_jobs, and job state in dba_scheduler_jobs remains as "SCHEDULED":

select job_name,session_id, slave_process_id, slave_os_process_id, elapsed_time, log_id 
  from dba_scheduler_running_jobs;

  no rows selected

select job_name, enabled, state, run_count, failure_count, retry_count, start_date, last_start_date, next_run_date
  from dba_scheduler_jobs v where job_name like '%TEST_JOB%';

  JOB_NAME            ENABL STATE     RUN_COUNT FAILURE_COUNT RETRY_COUNT START_DATE    LAST_START_DATE  NEXT_RUN_DATE
  ------------------- ----- ------------------- ------------- ----------- ------------- ---------------- -------------
  TEST_JOB_CRASHED_1  TRUE  SCHEDULED         7             0           0 10:37:05.497  10:41:12.340     10:41:12.341
  TEST_JOB_CRASHED_2  TRUE  SCHEDULED         6             0           0 10:37:06.370  10:39:44.948     10:39:44.950
  TEST_JOB_NORMAL_1   TRUE  SCHEDULED         4             0           0 10:40:25.148  10:40:12.145     10:40:25.152

Now we can turn off CJQ0 tracing (otherwise CJQ0 trace file will get many MB):

exec sys.dbms_system.set_ev(7, 15601, 27402, 0, '');

Note that we use CJQ0 trace event 27402 level 65535 (0xffff) instead of level 65355 (0xff4b) as documented in MOS: Scheduler Stuck Executing Jobs And CJQ0 Locking SYS.LAST_OBSERVED_EVENT (Doc ID 2341386.1).

One can also start a DB wide 27402 trace by:

  alter system set events '27402 trace name context forever, level 65535';
  alter system set events '27402 trace name context off';

As a test, we can run the "SCHEDULED" job immediately in the current session (foreground session) in lieu of job slave session (background session) as follows:

exec dbms_scheduler.run_job(job_name  => 'TEST_JOB_NORMAL_1', use_current_session => true);
exec dbms_scheduler.run_job(job_name  => 'TEST_JOB_CRASHED_1', use_current_session => true);

3. Used Slaves by Job Incident

From above dba_scheduler_jobs query, we can see that TEST_JOB_CRASHED_1 run_count=7, TEST_JOB_CRASHED_2 run_count=6, the total run_count of two test_proc_crashed jobs is 13:

select sum(run_count) "#used_slaves" 
  from dba_scheduler_jobs 
 where job_name like 'TEST_JOB_CRASHED%';

  #used_slaves
  ------------
            13

The number of incident ORA-00600:[4156] in v$diag_alert_ext during the test inteval is 13:

    
select count(distinct process_id) "#used_slaves", min(originating_timestamp), max(originating_timestamp)
  from v$diag_alert_ext
 where (message_text like '%incident%ORA-00600%4156%' or problem_key like '%ORA 600 [4156]%')
   and originating_timestamp > timestamp'2021-01-18 10:30:00';
     
  #used_slaves MIN(ORIGINATING_TIMESTAMP)  MAX(ORIGINATING_TIMESTAMP)
  ------------ --------------------------- --------------------------
            13 10:37:06.572                10:41:21.195

Open DB alert.log, count the number of different OS process id in all ORA-00600:[4156] incident files (around text "ORA-00600: internal error code, arguments: [4156]"), it is exactly 13.

Go to diag incident directory, count the number of incident files with different OS process id, it is also 13.

Now open CJQ0 trace file, it shows that when condition "CDB slave limit" <= "CDB Used/Reserved slaves" is not true, subroutine jscr_can_pdb_run_job returns 1, more slaves can become "RUNNING". The text in the trace file looks like:

  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscrsq_select_queue):Considering job 3715269
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Enter
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):CDB slave limit=13, CDB Used/Reserved slaves=5, MSL=2
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):PDB 0 slaves: used=4, assigned=1, reserved=5, max=13
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Return 1
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_increase_pdb_assigned_slaves):Enter
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_increase_pdb_assigned_slaves):Return
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscrsq_select_queue):JOB FLOW TRACE: SELECT Q: ADD JOB TO TJL WORK Q: 3715269
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscrsq_select_queue):Considering job 3715270
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Enter
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):CDB slave limit=13, CDB Used/Reserved slaves=6, MSL=2
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):PDB 0 slaves: used=4, assigned=2, reserved=6, max=13
  SCHED 01-18 10:38:12.061 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Return 1
  ...
  SCHED 01-18 10:39:12.095 1 00 23038 CJQ0 0(jscrsq_select_queue):Considering job 3715271
  SCHED 01-18 10:39:12.095 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Enter
  SCHED 01-18 10:39:12.095 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):CDB slave limit=13, CDB Used/Reserved slaves=8, MSL=2
  SCHED 01-18 10:39:12.095 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):PDB 0 slaves: used=8, assigned=0, reserved=8, max=13
  SCHED 01-18 10:39:12.095 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Return 1

When "CDB slave limit" <= "CDB Used/Reserved slaves" is true, jscr_can_pdb_run_job returns 0, slaves remain in state "SCHEDULED", not able to move to state "RUNNING". The trace file is repeatedly filled with following text.

  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscrsq_select_queue):Considering job 3715270
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Enter
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):CDB slave limit=13, CDB Used/Reserved slaves=13, MSL=2
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):PDB 0 slaves: used=13, assigned=0, reserved=13, max=13
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Return 0
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscrsq_select_queue):Considering job 3715271
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Enter
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):CDB slave limit=13, CDB Used/Reserved slaves=13, MSL=2
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):PDB 0 slaves: used=13, assigned=0, reserved=13, max=13
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Return 0
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscrsq_select_queue):Considering job 3715269
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Enter
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):CDB slave limit=13, CDB Used/Reserved slaves=13, MSL=2
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):PDB 0 slaves: used=13, assigned=0, reserved=13, max=13
  SCHED 01-18 10:43:10.442 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Return 0  

From above test and CJQ0 trace file, we can see that #used_slaves is the number of incident, "CDB slave limit" is specified by JOB_QUEUE_PROCESSES. Once #used_slaves reached JOB_QUEUE_PROCESSES, no more JOB can be in state "RUNNING". dba_scheduler_jobs shows that job is enabled ("TRUE"), but state remains in "SCHEDULED". Restarting database will reset #used_slaves.

In the above trace, slave limit is prefixed with CDB as "CDB slave limit=13". Job slaves are spawned in the root container because they are a shared resource among PDBs as documented in MOS: Alter System Kill Session Failed With ORA-00026 When Kill a Job Session From PDB (Doc ID 2491701.1)). (This MOS Note seems not consistent with Oracle docu about JOB_QUEUE_PROCESSES, which said: it is maximum number of job slaves per instance, not root container).

"MSL=2" seems the number of maximum assigned jobs in each scheduling scan. jscr_can_pdb_run_job Call Stack looks like:

  #0  0x00000000041bfcbb in jscr_can_pdb_run_job ()
  #1  0x00000000041be8a8 in jscrsq_select_queue ()       
  #2  0x00000000041b3224 in jscrs_select0 ()
  #3  0x00000000041b00f2 in jscrs_select ()
  #4  0x00000000122ac797 in rpiswu2 ()
  #5  0x0000000003726293 in kkjcjexe ()
  #6  0x0000000003725d65 in kkjssrh ()
  #7  0x0000000012360495 in ksb_act_run_int ()
  #8  0x000000001235f162 in ksb_act_run ()
  #9  0x000000001235dec5 in ksbcti ()
  #10 0x0000000003d2a550 in ksbabs ()
  #11 0x0000000003d48611 in ksbrdp ()
  #12 0x0000000004168bf7 in opirip ()
  #13 0x00000000027b8138 in opidrv ()
  #14 0x00000000033be90f in sou2o ()
  #15 0x0000000000d81f9a in opimai_real ()
  #16 0x00000000033cb767 in ssthrdmain ()
  #17 0x0000000000d81ea3 in main ()

JOB_QUEUE_PROCESSES max value is fixed as:

      up to Oracle 12cR1: 1000
      from  Oracle 12cR2: 4000  

It seems that CJQ0 is periodically waking up each 200 ms to check enabled jobs. The related hidden parameters are:

  Name                                     Description                                               Default
  ---------------------------------------- --------------------------------------------------------  -------
  _sched_delay_sample_interval_ms          scheduling delay sampling interval in ms                  1000 
  _sched_delay_max_samples                 scheduling delay maximum number of samples                4    
  _sched_delay_sample_collection_thresh_ms scheduling delay sample collection duration threshold ms  200  
  _sched_delay_measurement_sleep_us        scheduling delay mesurement sleep us                      1000 
  _sched_delay_os_tick_granularity_us      os tick granularity used by scheduling delay calculations 16000

In the above trace file, job 3715269, 3715270 and 3715271 can be found by query:

select o.object_name, start_date, last_enabled_time, last_start_date, next_run_date, last_end_date
  from dba_objects o, sys.scheduler$_job j 
 where o.object_id = j.obj# and j.obj# in (3715269, 3715270, 3715271);
 
OBJECT_NAME         START_DATE    LAST_ENABLED_TIME  LAST_START_DATE  NEXT_RUN_DATE  LAST_END_DATE
------------------  ------------  -----------------  ---------------  -------------  -------------
TEST_JOB_CRASHED_1  10:37:05.497  10:37:06.351       10:41:12.340     10:41:12.341   10:41:24.322
TEST_JOB_CRASHED_2  10:37:06.370  10:37:06.373       10:39:44.948     10:39:44.950   10:40:12.115
TEST_JOB_NORMAL_1   10:40:25.148  10:40:25.152       10:40:12.145     10:40:25.152   10:41:12.153

class object 12166 is DEFAULT_JOB_CLASS:

select owner, object_name, object_type from dba_objects where object_id = 12166;

  OWNER  OBJECT_NAME        OBJECT_TYPE
  ------ ------------------ -----------
  SYS    DEFAULT_JOB_CLASS  JOB CLASS

In Oracle 12.1, the above behaviour can only be partially reproduced. Once #used_slaves reached JOB_QUEUE_PROCESSES, they can still periodically start and stop (job state changed from "RUNNING" to "SCHEDULED", then back to "RUNNING" after a while). Following CJQ0 trace shows that jleft (job left) is started with JOB_QUEUE_PROCESSES (13), once reached 0, it is reset back 0 after certain interval.

  SCHED 11:58:35.575 1 00 19988592 CJQ0 0(jscrs_select0):position 0, job 1287236, considered_count 0, prio 6 
  SCHED 11:58:35.575 1 00 19988592 CJQ0 0(jscrmrr_mark_run_resource_mgr):Entering jscrmrr_mark_run_resource_mgr
  SCHED 11:58:35.575 1 00 19988592 CJQ0 0(jscrmrr_mark_run_resource_mgr):jleft=13, sleft=1032, pleft=638
  SCHED 11:58:35.575 1 00 19988592 CJQ0 0(jscrrsa_rm_slave_allocation):all cg granted total of 1
  ...
  SCHED 11:59:36.145 1 00 19988592 CJQ0 0(jscrs_select0):position 0, job 1287236, considered_count 0, prio 6 
  SCHED 11:59:36.145 1 00 19988592 CJQ0 0(jscrmrr_mark_run_resource_mgr):Entering jscrmrr_mark_run_resource_mgr
  SCHED 11:59:36.145 1 00 19988592 CJQ0 0(jscrmrr_mark_run_resource_mgr):jleft=1, sleft=1029, pleft=636
  SCHED 11:59:36.145 1 00 19988592 CJQ0 0(jscrrsa_rm_slave_allocation):all cg granted total of 1
  ...
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrs_select0):position 0, job 1287237, considered_count 2, prio 6 
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrs_select0):position 1, job 1287236, considered_count 0, prio 6 
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrmrr_mark_run_resource_mgr):Entering jscrmrr_mark_run_resource_mgr
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrmrr_mark_run_resource_mgr):jleft=0, sleft=1032, pleft=637
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrmrr_mark_run_resource_mgr):Max number of jobs we can run is 0
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrs_select0):No jobs to run
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrcw_compute_wait):Entering jscrcw_compute_wait
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrcw_compute_wait):0  jscrcw_compute_wait returns value 400
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrs_select0):Running 0 jobs:
  SCHED 11:59:44.941 1 00 19988592 CJQ0 0(jscrs_select0):Waiting 4000 milliseconds:
  ...
  SCHED 12:01:19.509 1 00 19988592 CJQ0 0(jscrs_select0):position 0, job 1287236, considered_count 27, prio 5 
  SCHED 12:01:19.509 1 00 19988592 CJQ0 0(jscrs_select0):position 1, job 17408, considered_count 13, prio 6 
  SCHED 12:01:19.509 1 00 19988592 CJQ0 0(jscrs_select0):position 2, job 1287238, considered_count 12, prio 6 
  SCHED 12:01:19.509 1 00 19988592 CJQ0 0(jscrs_select0):position 3, job 1287237, considered_count 9, prio 6 
  SCHED 12:01:19.509 1 00 19988592 CJQ0 0(jscrmrr_mark_run_resource_mgr):Entering jscrmrr_mark_run_resource_mgr
  SCHED 12:01:19.509 1 00 19988592 CJQ0 0(jscrmrr_mark_run_resource_mgr):jleft=13, sleft=1033, pleft=661
  SCHED 12:01:19.509 1 00 19988592 CJQ0 0(jscrrsa_rm_slave_allocation):all cg granted total of 4

Probably this different behaviour shows that DBMS_SCHEDULER it still evolving after the releases.

4. Used Slaves by Job Kill

At first, we disable both incident jobs. Then look different job kill commands and its impact on #used_slaves.

  exec dbms_scheduler.disable ('TEST_JOB_CRASHED_1', force => true, commit_semantics =>'ABSORB_ERRORS');
  exec dbms_scheduler.disable ('TEST_JOB_CRASHED_2', force => true, commit_semantics =>'ABSORB_ERRORS');

4.1. OS Command Kill

Increase job_queue_processes from 13 to 14 to allow one job slave running:

  alter system set job_queue_processes=14 scope=memory;

Now we can see that TEST_JOB_NORMAL_1 is changed from "SCHEDULED" to "RUNNING" (incident jobs are all in state="DISABLED"):

select job_name, enabled, state, run_count, failure_count, retry_count, start_date, last_start_date, next_run_date
  from dba_scheduler_jobs v where job_name like '%TEST_JOB%';
  
  JOB_NAME           ENABL STATE    RUN_COUNT FAILURE_COUNT RETRY_COUNT START_DATE   LAST_START_DATE NEXT_RUN_DATE
  ------------------ ----- -------- --------- ------------- ----------- ------------ --------------- -------------
  TEST_JOB_CRASHED_1 FALSE DISABLED         7             0           0 10:37:05.497 10:41:12.340    10:41:12.341
  TEST_JOB_CRASHED_2 FALSE DISABLED         6             0           0 10:37:06.370 10:39:44.948    10:39:44.950
  TEST_JOB_NORMAL_1  TRUE  RUNNING          4             0           0 11:36:31.298 11:36:18.276    11:36:31.305

Find OS process id of TEST_JOB_NORMAL_1:

select s.program, s.module, s.action, s.sid, s.serial#, p.pid, p.spid, s.event
  from v$session s, v$process p 
 where s.paddr=p.addr and s.program like '%J0%';  
 
  PROGRAM              MODULE         ACTION            SID SERIAL# PID SPID  EVENT
  -------------------- -------------- ----------------- --- ------- --- ----- -----------------
  oracle@testdb (J000) DBMS_SCHEDULER TEST_JOB_NORMAL_1 373   27399  50 23709 PL/SQL lock timer

Then kill it by OS command:

  kill -9 23709

Now we can see that TEST_JOB_NORMAL_1 is in state "SCHEDULED", same as above incident case. So the job killed by OS command is also counted into #used_slaves (TEST_JOB_CRASHED_1 and TEST_JOB_CRASHED_2 rows are same, removed in the output).

select job_name, enabled, state, run_count, failure_count, retry_count, start_date, last_start_date, next_run_date
  from dba_scheduler_jobs v where job_name like '%TEST_JOB%';
  
  JOB_NAME          ENABL STATE     RUN_COUNT FAILURE_COUNT RETRY_COUNT START_DATE   LAST_START_DATE NEXT_RUN_DATE
  ----------------- ----- --------- --------- ------------- ----------- ------------ --------------- -------------
  TEST_JOB_NORMAL_1 TRUE  SCHEDULED        13             0           0 11:44:31.619 11:44:18.617    11:44:18.617

CJQ0 trace shows "CDB slave limit=14, CDB Used/Reserved slaves=14", no more job can be in state "RUNNING".

  SCHED 01-18 11:49:48.662 1 00 23038 CJQ0 0(jscrsq_select_queue):Considering job 3715271
  SCHED 01-18 11:49:48.662 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Enter
  SCHED 01-18 11:49:48.662 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):CDB slave limit=14, CDB Used/Reserved slaves=14, MSL=2
  SCHED 01-18 11:49:48.662 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):PDB 0 slaves: used=14, assigned=0, reserved=14, max=14
  SCHED 01-18 11:49:48.662 1 00 23038 CJQ0 0(jscr_can_pdb_run_job):Return 0

IN DB alert log, there is no info about this OS killed job, but pmon trace contains text below:

  *** 2021-01-18T11:45:36.206630+01:00
  Marked process 0xb75d64a0 pid=50 serial=18 ospid=23709 newly dead
  User session information :
    sid: 373 ser: 945
    client details:
      O/S info: user: oracle, term: UNKNOWN, ospid: 23709
      machine: testdb program: oracle@testdb (J000)
      application name: DBMS_SCHEDULER, hash value=2478762354
      action name: TEST_JOB_NORMAL_1, hash value=355935408

4.2. Oracle Kill Statement With "immediate" Option (KILL HARD)

We increase job_queue_processes from 14 to 15:

  alter system set job_queue_processes=15 scope=memory;

TEST_JOB_NORMAL_1 back to state "RUNNING" again:

select job_name, enabled, state, run_count, failure_count, retry_count, start_date, last_start_date, next_run_date
  from dba_scheduler_jobs v where job_name like '%TEST_JOB%';
  
  JOB_NAME          ENABL STATE   RUN_COUNT FAILURE_COUNT RETRY_COUNT START_DATE   LAST_START_DATE NEXT_RUN_DATE
  ----------------- ----- ------- --------- ------------- ----------- ------------ --------------- -------------
  TEST_JOB_NORMAL_1 TRUE  RUNNING        13             0           0 12:17:43.620 12:17:30.610    12:17:43.627 
    
select s.program, s.module, s.action, s.sid, s.serial#, p.pid, p.spid, s.event
  from v$session s, v$process p 
 where s.paddr=p.addr and s.program like '%J0%'; 
  
  PROGRAM              MODULE         ACTION            SID SERIAL# PID SPID EVENT
  -------------------- -------------- ----------------- --- ------- --- ---- -----------------
  oracle@testdb (J000) DBMS_SCHEDULER TEST_JOB_NORMAL_1 722   45490  58 5571 PL/SQL lock timer

Pick sid and serial#, kill TEST_JOB_NORMAL_1 by Oracle statement with "immediate" option:

  alter system kill session '722,45490,@1' immediate;

Now we can see that TEST_JOB_NORMAL_1 is in state "SCHEDULED", same as above incident case. So the job killed by Oracle statement with "immediate" option is counted into #used_slaves.

select job_name, enabled, state, run_count, failure_count, retry_count, start_date, last_start_date, next_run_date
  from dba_scheduler_jobs v where job_name like '%TEST_JOB%';
  
  JOB_NAME          ENABL STATE     RUN_COUNT FAILURE_COUNT RETRY_COUNT START_DATE   LAST_START_DATE NEXT_RUN_DATE
  ----------------- ----- --------- --------- ------------- ----------- ------------ --------------- -------------
  TEST_JOB_NORMAL_1 TRUE  SCHEDULED        20             0           0 12:23:43.714 12:23:30.712    12:23:30.712 

DB alert log shows Process termination by "KILL HARD SAFE":

  2021-01-18T12:23:54.011134+01:00
  Process termination requested for pid 5571 [source = rdbms], [info = 2] [request issued by pid: 5315, uid: 100]
  2021-01-18T12:23:54.060574+01:00
  KILL SESSION for sid=(722, 45490):
    Reason = alter system kill session
    Mode = KILL HARD SAFE -/-/-
    Requestor = USER (orapid = 50, ospid = 5315, inst = 1)
    Owner = Process: J000 (orapid = 58, ospid = 5571)
    Result = ORA-0

pmon trace text:

  *** 2021-01-18T12:23:54.061510+01:00
  Marked process 0xb75df060 pid=58 serial=17 ospid=5571 newly dead
  User session information :
    sid: 722 ser: 45490
    client details:
      O/S info: user: oracle, term: UNKNOWN, ospid: 5571
      machine: testdb program: oracle@testdb (J000)
      application name: DBMS_SCHEDULER, hash value=2478762354
      action name: TEST_JOB_NORMAL_1, hash value=355935408

The Kill Statement seems implemented by subroutine call: "kpoal8 () -> opiexe () -> kksExecuteCommand ()".

4.3. Oracle Kill Statement Without "immediate" Option (KILL SOFT)

We increase job_queue_processes from 15 to 16:

  alter system set job_queue_processes=16 scope=memory;

TEST_JOB_NORMAL_1 back to state "RUNNING" again:

select job_name, enabled, state, run_count, failure_count, retry_count, start_date, last_start_date, next_run_date
  from dba_scheduler_jobs v where job_name like '%TEST_JOB%';
  
  JOB_NAME           ENABL STATE    RUN_COUNT FAILURE_COUNT RETRY_COUNT START_DATE   LAST_START_DATE NEXT_RUN_DATE
  ------------------ ----- -------- --------- ------------- ----------- ------------ --------------- -------------
  TEST_JOB_NORMAL_1  TRUE  RUNNING         20             0           0 12:23:43.714 12:26:16.292    12:23:30.712
 
select s.program, s.module, s.action, s.sid, s.serial#, p.pid, p.spid, s.event
  from v$session s, v$process p 
 where s.paddr=p.addr and s.program like '%J0%'; 
 
  PROGRAM              MODULE         ACTION            SID SERIAL# PID SPID EVENT
  -------------------- -------------- ----------------- --- ------- --- ---- -----------------
  oracle@testdb (J000) DBMS_SCHEDULER TEST_JOB_NORMAL_1 722   58202  58 6652 PL/SQL lock timer

Pick sid and serial#, kill TEST_JOB_NORMAL_1 by Oracle statement without "immediate" option, and check its state:

alter system kill session '722,58202,@1';

select job_name, enabled, state, run_count, failure_count, retry_count, start_date, last_start_date, next_run_date
  from dba_scheduler_jobs v where job_name like '%TEST_JOB%';
  
  JOB_NAME          ENABL STATE    RUN_COUNT FAILURE_COUNT RETRY_COUNT START_DATE   LAST_START_DATE NEXT_RUN_DATE
  ----------------- ----- -------- --------- ------------- ----------- ------------ --------------- -------------
  TEST_JOB_NORMAL_1 TRUE  RUNNING         24             0           0 12:28:58.543 12:29:45.639    12:28:58.549

Now we can see that TEST_JOB_NORMAL_1 is able to be started in state "RUNNING". So the job killed by Oracle statement without "immediate" option is not counted into #used_slaves.

DB alert log shows aborting process by "KILL SOFT":

                                       
  2021-01-18T12:28:30.705849+01:00
  opidrv aborting process J000 ospid (6652) as a result of ORA-28
  2021-01-18T12:28:30.754338+01:00
  KILL SESSION for sid=(722, 58202):
    Reason = alter system kill session
    Mode = KILL SOFT -/-/-
    Requestor = USER (orapid = 50, ospid = 5315, inst = 1)
    Owner = Process: J000 (orapid = 58, ospid = 6652)
    Result = ORA-0

pmon trace:

  *** 2021-01-18T12:28:33.714660+01:00
  Marked process 0xb75df060 pid=58 serial=18 ospid=6652 newly dead

In Oracle 12.1, all above Job Kill behaviours are not observed.

4.4. Alter Session Kill Statement UNIX Signals, v$session and v$process Changes

Here some observations of Alter Session Kill Statement With vs. WithOut "immediate" in Oracle 18c and 19c.

(1). Signals Sending (tracing with strace/truss)
  -. alter system kill session 'sid,serial#' immediate;
     sends SIGTERM to the killed session (process). The killed process received:
       SIGTERM {si_signo=SIGTERM, si_code=SI_QUEUE, si_pid=24984, si_uid=100, si_value={int=2, ptr=0x100000002}}
       
  -. alter system kill session 'sid,serial#';
     sends SIGTSTP to the killed session (process). The killed process received:
       SIGTSTP {si_signo=SIGTSTP, si_code=SI_TKILL, si_pid=24984, si_uid=100}

  Both SIGTERM and SIGTSTP can be ignored or handled (caught) differently, depending on OS (platform) and Oracle versions.
  Whereas their sibling SIGKILL, SIGSTOP are unblockable, and cannot be caught or ignored.

(2). After Sending Kill Statement
  -. When the session killed With "immediate", the UNIX process is terminated.
     The session disappeared from v$session because flag KSSPAFLG in the underlined x$ksuse is changed from 1 to 6
     (filtered out by BITAND("S"."KSSPAFLG",1)<>0). Its info is still visible in x$ksuse (v$session .SID=x$ksuse).
     The process disappeared from v$process/x$ksupr.

  -. The session killed WithOut "immediate", the UNIX process is not terminated.
     It is still visible in v$session/x$ksuse and v$process/x$ksupr.

(3). After Kill Statement, using it again to execute a statement on the killed session:   
  -. The session killed With "immediate" throws ORA-03113.
     
     The UNIX process is already terminated. It is still kept in x$ksuse and x$ksupr.
     The flag KSSPAFLG in the underlined x$ksuse is further changed from 6 to 2 (filtered out by BITAND("S"."KSSPAFLG",1)<>0).
     
  -. The session killed WithOut "immediate" throws ORA-00028.
     
     The UNIX process is still alive (not terminated). It is no more visible in v$session 
     because the flag KSSPAFLG in the underlined x$ksuse is changed from 1 to 2 (filtered out by BITAND("S"."KSSPAFLG",1)<>0).
     It is still kept in v$process/x$ksupr, and x$ksuse with KSSPAFLG=2. 
     We can see that UNIX process actively reacts to any actions from the session.
     Each use of that killed session again, its process received:
        SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0}

There are also session cancel and disconnect statements. Here the observed behaviour:

alter system cancel sql 'sid,serial#';      
  sends SIGTSTP to the cancelled session (process). The cancelled process received:
    SIGTSTP {si_signo=SIGTSTP, si_code=SI_TKILL, si_pid=24984, si_uid=100} 
  The cancelled session is alive in v$session and v$process.
  It only cancels the current execution (even in the middle of processing or in a loop)
  If using that session again, it behaves as normal.

alter system disconnect session 'sid,serial#' immediate;   
  sends SIGTERM to the disconnected session (process). The disconnected process received:
    SIGTERM {si_signo=SIGTERM, si_code=SI_QUEUE, si_pid=24984, si_uid=100, si_value={int=2, ptr=0x100000002}} 
  The disconnected session in x$ksuse is with KSSPAFLG changed from 1 to 6.
  If using that session again, it throws ORA-03113: end-of-file on communication channel

alter system disconnect session 'sid,serial#';   
  sends SIGTSTP to the disconnected session (process). The disconnected process received:
    SIGTSTP {si_signo=SIGTSTP, si_code=SI_TKILL, si_pid=24984, si_uid=100} ---
  The disconnected session is kept in v$process/x$ksupr, and x$ksuse with KSSPAFLG=2.
  If using that session again, it throws ORA-00028: your session has been killed

For cancel statement, it is similar to kill WithOut "immediate". For disconnect statement, the two variants (With/WithOut) are similar to kill (With/WithOut).

We can see that the same signal SIGTSTP is handled differently. in case of:

  alter system kill session 'sid,serial#';

It makes the session unusable. If using that session again, it throws ORA-00028.

Whereas in case of:

  alter system cancel sql 'sid,serial#';

It only cancels the current execution. If using that session again, it behaves normal.

By the way, we can also toggle SIGSTOP and SIGCONT to suspend and resume session's current execution:

  kill -s SIGSTOP pid
  kill -s SIGCONT pid

Anyway, SIGKILL is used as a last resort to terminate processes immediately. It cannot be caught or ignored, and the receiving process cannot perform any clean-up upon receiving this signal.

4.5 v$resource_limit and x$ksupr/v$process, x$ksuse/v$session

When instance startup, Oracle allocates number of processes and sessions by their initial_allocation values specified in v$resource_limit.

  select * from v$resource_limit where resource_name in ('processes', 'sessions');

You can see the number of rows in x$ksupr, x$ksuse are the same as their initial_allocation values. But the visible processes and sessions in v$process and v$session are less since recursive sessions and un-used sessions are filtered out. (Note: both x$ksupr and x$ksuse contains one identical name column: "KSSPAFLG")

v$process rows are selected as:

  select ksspaflg, bitand (ksspaflg, 1), p.* from x$ksupr p 
   where BITAND("KSSPAFLG",1)<>0;

v$session rows are selected as:

  select ksuseflg, bitand(ksuseflg,1), ksspaflg, bitand(ksspaflg,1), s.* from x$ksuse s 
   where BITAND("S"."KSSPAFLG",1)<>0 AND BITAND("S"."KSUSEFLG",1)<>0;

current_utilization of sessions in v$resource_limit are those selected without BITAND("S"."KSUSEFLG",1)<>0 predicate.

  select ksuseflg, bitand(ksuseflg,1), ksspaflg, bitand(ksspaflg,1), s.* from x$ksuse s 
   where BITAND("S"."KSSPAFLG",1)<>0;

We can see that session type in v$session is mapped from x$ksuse.ksuseflg as:

	DECODE (BITAND (S.KSSPAFLG, 19),
	17, 'BACKGROUND',
	1, 'USER',
	2, 'RECURSIVE',
	'?'),

and 'RECURSIVE' sessions has BITAND (S.KSSPAFLG, 19)=2. All even number is filtered out by predicate BITAND("S"."KSUSEFLG",1)<>0.

When initialization values exceeded, Oracle throws the corresponding error:

  ORA-00018 maximum number of sessions exceeded 
  ORA-00020: maximum number of processes (1200) exceeded

The default values of parameter SESSIONS is computed by (1.5 * PROCESSES) + 24.

Following MOS Notes have certain related descriptions:

  -.KILLING INACTIVE SESSIONS DOES NOT REMOVE SESSION ROW FROM V$SESSION (Doc ID 1041427.6)
  -.Troubleshooting Guide - ORA-18: Maximum Number Of Sessions (%S) Exceeded (Doc ID 1307128.1)
  -.Troubleshooting Guide - ORA-18: Maximum Number Of Sessions (%S) Exceeded (Doc ID 1307128.1)

5. Job Datetime and Start Delay

For job TEST_JOB_NORMAL_1, its job_action contains a set_attribute of 'start_date':

  -- TEST_JOB_NORMAL_1 job_action
  begin
    dbms_lock.sleep(13);
    dbms_scheduler.set_attribute(
       name      => 'TEST_JOB_NORMAL_1'
      ,attribute => 'start_date'
      ,value     => systimestamp);
    dbms_lock.sleep(47);
  end;

Remove 'start_date' setting, create a similar job TEST_JOB_NORMAL_B:

  begin 
    dbms_scheduler.create_job (
      job_name        => 'TEST_JOB_NORMAL_B',
      job_type        => 'PLSQL_BLOCK',
      job_action      => 
        'begin 
           dbms_lock.sleep(13); 
           dbms_lock.sleep(47);
        end;',    
      start_date      => systimestamp,
      repeat_interval => 'systimestamp',
      auto_drop       => true,
      enabled         => true);
  end;
  /

We increase job_queue_processes from 16 to 17 to run TEST_JOB_NORMAL_B:

  alter system set job_queue_processes=17 scope=memory;

Both jobs are running, and now we look their datatime (we query sys.scheduler$_job instead of dba_scheduler_jobs for two addtional fileds: last_end_date, last_enabled_time):

select o.object_name, o.created, o.last_ddl_time, start_date, last_start_date, next_run_date, last_end_date, last_enabled_time
  from dba_objects o, sys.scheduler$_job j 
 where o.object_id = j.obj# and o.object_name like 'TEST_JOB_NORMAL_%';
 
  OBJECT_NAME       CREATED  LAST_DDL START_DATE   LAST_START_DATE NEXT_RUN_DATE LAST_END_DATE LAST_ENABLED_TIME
  ----------------- -------- -------- ------------ --------------- ------------- ------------- -----------------
  TEST_JOB_NORMAL_1 10:37:11 15:49:50 15:49:50.791 15:49:37.786    15:49:50.810  15:49:37.758  15:49:50.810
  TEST_JOB_NORMAL_B 14:14:55 15:49:34 14:14:55.515 15:49:34.731    15:48:34.726  15:49:34.728  15:43:34.625

In the simple case (TEST_JOB_NORMAL_B), job start_date is (almost) same as DBA_OBJECTS.created. both start_date and last_enabled_time are not changed once started. last_start_date and last_end_date are the timestamp of job action start and end (in fact, last_start_date is current start timestamp, last_end_date is previous end timestamp). next_run_date is an expected time for next run, calculated when current run starts (only a scheduled time, not a real performed time). DBA_OBJECTS.last_ddl is the last modification time of job object.

In the case of TEST_JOB_NORMAL_1, job_action modifies 'start_date' to 'systimestamp' after 13 seconds of job start, then continue another 47 seconds. Therefore start_date is 13 seconds after last_start_date. next_run_date and last_enabled_time are also modified close to start_date. DBA_OBJECTS.last_ddl records the timestamp of this modifcation.

Now we can also query dba_scheduler_job_run_details for historical job run timestamp:

select job_name, log_date, status, req_start_date, actual_start_date, session_id, slave_pid
      ,(actual_start_date - req_start_date) delay
  from dba_scheduler_job_run_details v 
 where job_name = 'TEST_JOB_NORMAL_1' 
 order by v.log_date

  JOB_NAME           LOG_DATE     STATUS    REQ_START_DATE ACTUAL_START_DA SESSION_ID SLAVE_ DELAY
  -----------------  ------------ --------- -------------- --------------- ---------- ------ -------------
      -- TEST_JOB_NORMAL_1 RUN_COUNT=4 till state=SCHEDULED
  TEST_JOB_NORMAL_1  10:38:11.853 SUCCEEDED 10:37:11.681   10:37:11.703    731,19298  25130  +00:00:00.022
  TEST_JOB_NORMAL_1  10:39:12.080 SUCCEEDED 10:37:24.769   10:38:12.071    731,52059  25130  +00:00:47.302
  TEST_JOB_NORMAL_1  10:40:12.112 SUCCEEDED 10:38:25.077   10:39:12.105    731,411    25130  +00:00:47.027
  TEST_JOB_NORMAL_1  10:41:12.153 SUCCEEDED 10:39:25.111   10:40:12.145    731,11120  25130  +00:00:47.034
  
      -- increase job_queue_processes to make state=RUNNING
  TEST_JOB_NORMAL_1  11:37:18.437 SUCCEEDED 10:40:25.152   11:36:18.276    373,30624  23709  +00:55:53.124
  TEST_JOB_NORMAL_1  11:38:18.554 SUCCEEDED 11:36:31.305   11:37:18.546    373,36987  23709  +00:00:47.240
  TEST_JOB_NORMAL_1  11:39:18.564 SUCCEEDED 11:37:31.552   11:38:18.556    373,44734  23709  +00:00:47.003
  TEST_JOB_NORMAL_1  11:40:18.574 SUCCEEDED 11:38:31.562   11:39:18.566    373,54579  23709  +00:00:47.004
  TEST_JOB_NORMAL_1  11:41:18.584 SUCCEEDED 11:39:31.573   11:40:18.576    373,4241   23709  +00:00:47.003
  TEST_JOB_NORMAL_1  11:42:18.594 SUCCEEDED 11:40:31.583   11:41:18.587    373,27399  23709  +00:00:47.003
  TEST_JOB_NORMAL_1  11:43:18.604 SUCCEEDED 11:41:31.593   11:42:18.597    373,41459  23709  +00:00:47.004
  TEST_JOB_NORMAL_1  11:44:18.614 SUCCEEDED 11:42:31.603   11:43:18.607    373,23208  23709  +00:00:47.003

      -- kill by OS command to stop it (state=SCHEDULED)
  TEST_JOB_NORMAL_1  11:45:45.239 STOPPED   11:44:31.623   11:44:18.617    373,945           -00:00:13.006
  
      -- increase job_queue_processes to make state=RUNNING
  TEST_JOB_NORMAL_1  12:18:30.629 SUCCEEDED 11:44:18.617   12:17:30.611    722,16157  5571   +00:33:11.993
  TEST_JOB_NORMAL_1  12:19:30.669 SUCCEEDED 12:17:43.627   12:18:30.660    722,53334  5571   +00:00:47.033

In the normal case of job running, from actual_start_date to log_date is from start to end of each run. req_start_date is 13 seconds after previous actual_start_date.

If we use (actual_start_date - req_start_date) to determine job start delay, we should take into account 'start_date' setting, state 'SCHEDULED', job killed. Even though there is no real delay, (actual_start_date - req_start_date) can show certain values, even some big or negative ones.

Run the same query for incident job TEST_JOB_CRASHED_1. The output lists all 7 runs (RUN_COUNT=7) with 4 computed fields (DELAY, DURATION, START_DIFF, LOG_DIFF). The DELAY and START_DIFF are (almost) same in the same row, but are varied in different rows. During incident, job slave process is still alive and the dump is performed by the job slave process itself, but SLAVE_PID is not filled.

select job_name, log_date, status, req_start_date, actual_start_date, session_id, slave_pid
      ,(actual_start_date - req_start_date)                                  delay
      ,(log_date - actual_start_date)                                        duration
      ,(actual_start_date - lag(actual_start_date) over(order by log_date))  start_diff
      ,(log_date - lag(log_date) over(order by log_date))                    log_diff
  from dba_scheduler_job_run_details v 
 where job_name = 'TEST_JOB_CRASHED_1'
 order by v.log_date;
 
  JOB_NAME           LOG_DATE     STATUS  REQ_START_DATE ACTUAL_START_DA SESSION_ID SLAVE_ DELAY         DURATION      START_DIFF    LOG_DIFF     
  ------------------ ------------ ------- -------------- --------------- ---------- ------ ------------- ------------- ------------- -------------
  TEST_JOB_CRASHED_1 10:37:44.948 STOPPED 10:37:06.351   10:37:06.416    375,57672         +00:00:00.064 +00:00:38.532                            
  TEST_JOB_CRASHED_1 10:38:12.048 STOPPED 10:37:06.439   10:37:45.052    375,51826         +00:00:38.613 +00:00:26.995 +00:00:38.636 +00:00:27.099
  TEST_JOB_CRASHED_1 10:38:44.843 STOPPED 10:37:45.054   10:38:12.072    910,52595         +00:00:27.017 +00:00:32.770 +00:00:27.020 +00:00:32.795
  TEST_JOB_CRASHED_1 10:39:12.082 STOPPED 10:38:12.075   10:38:44.883    375,55842         +00:00:32.808 +00:00:27.199 +00:00:32.810 +00:00:27.238
  TEST_JOB_CRASHED_1 10:39:44.892 STOPPED 10:38:44.886   10:39:12.106    910,46748         +00:00:27.220 +00:00:32.785 +00:00:27.223 +00:00:32.810
  TEST_JOB_CRASHED_1 10:40:12.114 STOPPED 10:39:12.109   10:39:44.932    375,49907         +00:00:32.822 +00:00:27.182 +00:00:32.825 +00:00:27.221
  TEST_JOB_CRASHED_1 10:41:24.323 STOPPED 10:39:44.934   10:41:12.340    731,55755         +00:01:27.405 +00:00:11.983 +00:01:27.408 +00:01:12.209

select job_name, log_date, operation, status,dbms_lob.substr(additional_info, 120,1) add_info
  from dba_scheduler_job_log  v 
 where job_name like 'TEST_JOB_CRASHED_1'
 order by v.log_date;
 
  JOB_NAME           LOG_DATE     OPERATION STATUS  ADD_INFO
  ------------------ ------------ --------- ------- -----------------------------------------
  TEST_JOB_CRASHED_1 10:37:44.790 RUN       STOPPED REASON="Job slave process was terminated"
  TEST_JOB_CRASHED_1 10:38:12.047 RUN       STOPPED REASON="Job slave process was terminated"
  TEST_JOB_CRASHED_1 10:38:44.843 RUN       STOPPED REASON="Job slave process was terminated"
  TEST_JOB_CRASHED_1 10:39:12.082 RUN       STOPPED REASON="Job slave process was terminated"
  TEST_JOB_CRASHED_1 10:39:44.892 RUN       STOPPED REASON="Job slave process was terminated"
  TEST_JOB_CRASHED_1 10:40:12.114 RUN       STOPPED REASON="Job slave process was terminated"
  TEST_JOB_CRASHED_1 10:41:24.323 RUN       STOPPED REASON="Job slave process was terminated"

Actually, as we observed, sys.scheduler$_job_run_details is filled by job session calling: "jslgLogJobRunInt() -> OCIStmtExecute()" with LOG_DATE = SYSTIMESTAMP, whereas sys.scheduler$_event_log is inserted by both job session and control session(enable/disable/stop/drop).

One similar query from OEM Grid Control looks like:

select j.job_name,
       j.owner,
       case
           when j.state = 'SCHEDULED'
           then to_char (j.next_run_date, 'DD-MON-YYYY HH24:MI:SS TZH:TZM')
           else null
       end    scheduled_date,
       case
           when j.state = 'RUNNING'
           then (  (sys_extract_utc (systimestamp) + 0) - (sys_extract_utc (j.last_start_date) + 0))* 24*60
           else null
       end    duration_mins,
       j.state
  from dba_scheduler_jobs j, dba_scheduler_running_jobs r
 where     (   (j.state = 'RUNNING' or j.state = 'CHAIN_STALLED')
            or (j.state = 'SCHEDULED'))
       and j.job_subname is null
       and r.job_subname is null
       and j.job_name = r.job_name(+)
       and j.owner = r.owner(+)
       and (   (    j.state = 'SCHEDULED'
                and   (  (sys_extract_utc (j.next_run_date) + 0) - (sys_extract_utc (systimestamp) + 0)) * 24*60 < 24*60)
            or (j.state = 'RUNNING' or j.state = 'CHAIN_STALLED'))
union
select sj.job_name,
       sj.owner,
       null                                             scheduled_date,
       extract (day from 24 * 60 * sj.run_duration)     duration_mins,
       sj.status
  from dba_scheduler_job_run_details sj
 where (   (    sj.status = 'STOPPED'
            and   (  (sys_extract_utc (systimestamp) + 0)
                   - (  (sys_extract_utc (sj.actual_start_date) + 0) + extract (day from sj.run_duration))) * 24*60 < 24*60)
        or (    sj.status = 'FAILED'
            and   (  (sys_extract_utc (systimestamp) + 0)
                   - (  (sys_extract_utc (sj.actual_start_date) + 0) + extract (day from sj.run_duration))) * 24*60 < 24*60)
);

6. Test Cleanup

After test, we can cleanup the test by following procedure:

create or replace procedure clearup_test as
begin
  for c in (select * from dba_scheduler_jobs where job_name like '%TEST_JOB%') loop
    begin
      --set DBA_SCHEDULER_JOBS.enabled=FALSE
	    dbms_scheduler.disable (c.job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
	    --set DBA_SCHEDULER_JOBS.enabled=TRUE, so that it can be scheduled to run (state='RUNNING')
	    --  dbms_scheduler.enable (c.job_name, commit_semantics =>'ABSORB_ERRORS');
	  exception when others then null;
	  end;
	end loop;
	
  for c in (select * from dba_scheduler_running_jobs where job_name like '%TEST_JOB%') loop
    begin
      --If force=FALSE, gracefully stop the job, slave process can update the status of the job in the job queue.
      --If force= TRUE, the Scheduler immediately terminates the job slave.
      --For repeating job with attribute "start_date => systimestamp" and enabled=TRUE, 
      --re-start immediate (state changed from 'SCHEDULED to 'RUNNING'), DBA_SCHEDULER_JOBS.run_count increases 1.
	    dbms_scheduler.stop_job (c.job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
	  exception when others then null;
	  end;
	end loop;
	
  for c in (select * from dba_scheduler_jobs where job_name like '%TEST_JOB%') loop
    begin
      --If force=TRUE, the Scheduler first attempts to stop the running job instances 
      --(by issuing the STOP_JOB call with the force flag set to false), and then drops the jobs.
	    dbms_scheduler.drop_job (c.job_name, force => true, commit_semantics =>'ABSORB_ERRORS');
	  exception when others then null;
	  end;
	end loop;
end;
/

exec clearup_test;

OracleJVM integer Array Size Limit and Out of Memory Error

Java provides 4 Primitive Data Types (byte, short, int, long) to represent integer numbers. In this Blog, we will look their array size limits in relation to two OracleJVM errors: ORA-29532 OutOfMemoryError and ORA-27102: out of memory.

Note: Tested in Oracle 19c on Linux.

1. ORA-29532 java.lang.OutOfMemoryError

Nenad's Blog: Troubleshooting java.lang.OutOfMemoryError in the Oracle Database made a deep investigation of ORA-29532 OutOfMemoryError, and found the internal hard-coded maximum total size in bytes: 536870895 It shows that for int[] array size of 134217723 (0x7FFFFFB, about 128MB Java int), there is no memory error. However, adding just one additional element will cause OutOfMemoryError (By default, Java int data type is a 32-bit signed).

We will explore further ORA-29532 OutOfMemoryError and list the 4 hard-coded integer array size limits on 4 respective Java integer Primitive Data Types.

At first, we copy Nenad's test code and add one method for byte[].

drop java source "Demo";

create or replace and compile java source named "Demo" as
public class Demo {
    public static void defineIntArray(int p_size) throws Exception {
      //Test of ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
      //copy from https://nenadnoveljic.com/blog/troubleshooting-java-lang-outofmemoryerror-in-the-oracle-database/
      int[] v = new int[p_size];
      System.out.println("OracleJvm int[].length: " + v.length);
    }

    public static void defineByteArray(int p_size) throws Exception {
      byte[] v = new byte[p_size];
      System.out.println("OracleJvm byte[].length: " + v.length);
    }
}     
/

create Or replace procedure p_define_int_array (p_size number)
as language java name 'Demo.defineIntArray(int)' ;
/

create Or replace procedure p_define_byte_array (p_size number)
as language java name 'Demo.defineByteArray(int)' ;
/

Run the same test to demonstrate OracleJVM java.lang.OutOfMemoryError exactly at 134217724:

SQL > exec p_define_int_array(134217723);

  OracleJvm int[].length: 134217723


SQL > exec p_define_int_array(134217724);

  Exception in thread "Root Thread" java.lang.OutOfMemoryError
          at Demo.defineIntArray(Demo:29)
  BEGIN p_define_int_array(134217724); END;
  
  *
  ERROR at line 1:
  ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
  ORA-06512: at "K.P_DEFINE_INT_ARRAY", line 1
  ORA-06512: at line 1

Following Blog's guidelines: switch off JIT compiler to obtain descriptive call stack, we disable OracleJVM Just-in-Time (JIT):

  alter system set java_jit_enabled=false;

and (gdb) disassemble joe_make_primitive_array:

# --------------------------- long, max: 0x3fffffd ---------------------------
  <+107>:   cmp    %r13d,%eax
  <+110>:   jl     0x583c639 <joe_make_primitive_array+121>
  <+112>:   cmp    $0x3fffffd,%rdx
  <+119>:   jbe    0x583c64b <joe_make_primitive_array+139>
  <+121>:   lea    0x11b9ed78(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>
  <+128>:   mov    %r15,%rdi
  <+131>:   mov    (%rax),%rsi
  <+134>:   callq  0x58459f0 <joe_blow>
  <+139>:   mov    0x1f1(%r15),%r9
# --------------------------- int, max: 0x7fffffb ---------------------------    
  <+299>:   cmp    %r13d,%eax
  <+302>:   jl     0x583c6f9 <joe_make_primitive_array+313>
  <+304>:   cmp    $0x7fffffb,%rdx
  <+311>:   jbe    0x583c70b <joe_make_primitive_array+331>
  <+313>:   lea    0x11b9ecb8(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>
  <+320>:   mov    %r15,%rdi
  <+323>:   mov    (%rax),%rsi
  <+326>:   callq  0x58459f0 <joe_blow>
  <+331>:   mov    0x1f1(%r15),%r9
# --------------------------- short, max: 0xffffff7 ---------------------------  
  <+491>:   cmp    %r13d,%eax
  <+494>:   jl     0x583c7b9 <joe_make_primitive_array+505>
  <+496>:   cmp    $0xffffff7,%rdx
  <+503>:   jbe    0x583c7cb <joe_make_primitive_array+523>
  <+505>:   lea    0x11b9ebf8(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>
  <+512>:   mov    %r15,%rdi
  <+515>:   mov    (%rax),%rsi
  <+518>:   callq  0x58459f0 <joe_blow>
  <+523>:   mov    0x1f1(%r15),%r9
# --------------------------- byte, max: 0x1fffffef ---------------------------  
  <+676>:   cmp    %r13d,%eax
  <+679>:   jl     0x583c872 <joe_make_primitive_array+690>
  <+681>:   cmp    $0x1fffffef,%rdx
  <+688>:   jbe    0x583c884 <joe_make_primitive_array+708>
  <+690>:   lea    0x11b9eb3f(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>
  <+697>:   mov    %r15,%rdi
  <+700>:   mov    (%rax),%rsi
  <+703>:   callq  0x58459f0 <joe_blow>
  <+708>:   mov    0x1f1(%r15),%r9

Copy 4 hex constants from above 4 cmp instructions and map to 4 integer Primitive Data Types:

  long  (8 bytes, 0x3fffffd =67108861 )
  int   (4 bytes, 0x7fffffb =134217723) 
  short (2 bytes, 0xffffff7 =268435447)
  byte  (1 byte,  0x1fffffef=536870895)

Above assemble code shows that each integer type is handled individually with different hard-coded limit, but total memory is capped below 512MB.

For example, for data type int, the input parameter array size (register rdx, passed as arg2 to joe_make_primitive_array) is checked against fixed constant 0x7fffffb (134217723, a hard-coded value). According to cmp status flags, create array if rdx below or equal to 0x7fffffb (%rdx - $0x7fffffb, CF=1 or ZF=1); otherwise continue to "ioa_ko_j_l_out_of_memory_error".

  <+304>:   cmp    $0x7fffffb,%rdx
  <+311>:   jbe    0x583c70b <joe_make_primitive_array+331>
  <+313>:   lea    0x11b9ecb8(%rip),%rax        # 0x173db3b8 <ioa_ko_j_l_out_of_memory_error>

We can also see that there is another memory pre-check before each integer type check. If the memory limit in eax is less than input parameter array size in r13d (%r13d > %eax), then jump to "ioa_ko_j_l_out_of_memory_error" (Note: maximum rax seems 0x20000000=536870912=512MB, probably default Heap Size since 11.2, see later appended MOS Doc ID 2526642.1).

  <+299>:   cmp    %r13d,%eax
  <+302>:   jl     0x583c6f9 <joe_make_primitive_array+313>

Now we can verify the limit of byte integer type exactly at 536870896:

SQL > exec p_define_byte_array(536870895);
  OracleJvm byte[].length: 536870895

SQL > exec p_define_byte_array(536870896);
  Exception in thread "Root Thread" java.lang.OutOfMemoryError
          at Demo.defineByteArray(Demo:31)
  BEGIN p_define_byte_array(536870896); END;
  
  *
  ERROR at line 1:
  ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
  ORA-06512: at "K.P_DEFINE_BYTE_ARRAY", line 1
  ORA-06512: at line 1

Oracle MOS: Java Stored Procedure suddenly fails with java.lang.OutOfMemoryError (Doc ID 2526642.1) wrote:

Symptoms
  A database routine implemented as a Java Stored procedure receives the following error.
  ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
  This routine may have worked previously or it may be brand new development.
  
Cause
  The DB JVM does not have enough session Heap Memory. This error occurs when a Java Stored Procedure 
  (ie. a PL/SQL routine where the body is implemented in Java ) does not have enough Heap space 
  to work with the amount of data being processed. If this were a client-side java program 
  using the Java Runtime Engine (JRE) (ie. java.exe), one would use the -Xmx parameter to configure the Heap Memory.  
  However, as the Oracle DB JVM is running in the process space of the Oracle executable, 
  there is no way to use the -Xmx switch.  The JVM has a default Heap Size (512MB since 11.2) 
  but it is also configurable using a method in the "Java Runtime" class called "oracle.aurora.vm.OracleRuntime".  
  Along with other "java runtime" related switches, this class contains a couple methods 
  that can be used to manage the Java Heap Size.  Therefore, if you encounter the OutOfMemoryError 
  and need to increase from either the default or a previous configured amount, 
  you can use oracle.aurora.vm.OracleRuntime.setMaxMemorySize to allocate more memory for the Java Heap.

The MOS Note described that "Oracle DB JVM is running in the process space of the Oracle executable" and had one hint about 512MB: "The JVM has a default Heap Size (512MB since 11.2)". As one Solution, MOS Note provided following workaround.

create or replace package Java_Runtime is
  function getHeapSize return number;
  function setHeapSize(num number) return number;
end Java_Runtime;
/

create or replace package body Java_Runtime is
  function getHeapSize return number is
    language java name 'oracle.aurora.vm.OracleRuntime.getMaxMemorySize() returns long';
  function setHeapSize(num number) return number is
    language java name 'oracle.aurora.vm.OracleRuntime.setMaxMemorySize(long) returns long';
end Java_Runtime;
/

declare
   heap_return_val NUMBER;
begin
   -- MOS code has a typo, setMaxMemorySize should be setHeapSize
   -- heap_return_val := Java_Runtime.setMaxMemorySize(1024*1024*1024);
   
   dbms_output.put_line('HeapSize Before Set: '||Java_Runtime.getHeapSize);
   heap_return_val := Java_Runtime.setHeapSize(1024*1024*1024);
   dbms_output.put_line('HeapSize After Set: '||Java_Runtime.getHeapSize);
   
   -- MOS code
   -- MY_JAVA_STORED_PROC(...);
   
   p_define_int_array(134217724);
end;
/

HeapSize Before Set: 536870912
HeapSize After Set: 1073741824
declare
*
ERROR at line 1:
ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
ORA-06512: at "K.P_DEFINE_INT_ARRAY", line 1
ORA-06512: at line 14

We made the test in Oracle 12c and 19c and still got ORA-29532 OutOfMemoryError (for the reason of the hard-coded limit discovered by Nenad's Blog).

2. ORA-27102: out of memory

Blog: Oracle JVM Java OutOfMemoryError and lazy GC was trying to bring up some discussions on OracleJVM OutOfMemoryError in connection with lazy GC.

The first test in the Blog is to allocate 511MB byte array:

SQL > exec createBuffer512(1024*1024*511);
  PL/SQL procedure successfully completed

succeeded without Error.

but the second test with 512MB:

SQL > exec createBuffer512(1024*1024*512);
  
  ERROR at line 1:
  ORA-29532: Java call terminated by uncaught Java exception: java.lang.OutOfMemoryError
  ORA-06512: at "K.CREATEBUFFER512", line 1
  ORA-06512: at line 1

hit the general Java error: ORA-29532 java.lang.OutOfMemoryError, which probably indicates that the JVM is limited by 512MB for one single object instance, in this test, it is "new byte[bufferSize]".

We can see that above hard-coded byte[] limit of 536870895 (0x1fffffef) is between 511MB and 512MB.

   1024*1024*512=536870912 > 536870895 > 535822336=1024*1024*511.

Run a third test case, which gradually allocates memory from 1MB to 511MB, each time increases 1MB per call.

SQL > exec createBuffer512_loop(511, 1, 1);

  Step -- 1 --, Buffer Size (MB) = 1
  Step -- 2 --, Buffer Size (MB) = 2
  Step -- 3 --, Buffer Size (MB) = 3
  ...
  Step -- 202 --, Buffer Size (MB) = 202
  Step -- 203 --, Buffer Size (MB) = 203

  ERROR at line 1:
  ORA-27102: out of memory
  Linux-x86_64 Error: 12: Cannot allocate memory
  Additional information: 12394
  Additional information: 218103808
  ORA-06512: at "K.CREATEBUFFER512", line 1
  ORA-06512: at "K.CREATEBUFFER512_LOOP", line 8
  ORA-06512: at line 1

It reveals that out of memory can be generated even under above discussed hard-coded limit (203MB < 512MB), but the error code is ORA-27102 (in 12c, we saw ORA-29532). The test shows that above 4 integer array size limits for respective 4 integer Primitive Data Types are sufficient, but not necessary conditions for out of memory.

Make a 27102 trace:

  alter session set max_dump_file_size = unlimited;
  alter session set tracefile_identifier='ORA27102_trc3'; 
  alter session set events '27102 trace name errorstack level 3'; 
  exec createBuffer512_loop(511, 1, 1);

Here the extracted error message, call stack, and session wait event from trace file:

----- Error Stack Dump -----
Linux-x86_64 Error: 12: Cannot allocate memory
Additional information: 12394
Additional information: 218103808

BEGIN createBuffer512_loop(511, 1, 1); END;
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x91948d30         1  procedure K.CREATEBUFFER512
0x8ef98db0         8  procedure K.CREATEBUFFER512_LOOP
0x8ca47e38         1  anonymous block

----- Call Stack Trace -----
FRAME [12] (dbgePostErrorKGE()+1066 -> dbkdChkEventRdbmsErr())
FRAME [13] (dbkePostKGE_kgsf()+71 -> dbgePostErrorKGE())
FRAME [14] (kgerscl()+546 -> dbkePostKGE_kgsf())
FRAME [15] (kgecss()+69 -> kgerscl())
FRAME [16] (ksmrf_init_alloc()+821 -> kgecss())
  CALL TYPE: call   ERROR SIGNALED: yes   COMPONENT: KSM
FRAME [17] (ksmapg()+521 -> ksmrf_init_alloc())
FRAME [18] (kgh_invoke_alloc_cb()+162 -> ksmapg())
  RDI 000000000D000000 RSI 00007F4D777511E0 RDX 000000000CE2D8B0 
FRAME [19] (kghgex()+2713 -> kgh_invoke_alloc_cb())
FRAME [20] (kghfnd()+376 -> kghgex())
FRAME [21] (kghalo()+4908 -> kghfnd())
FRAME [22] (kghgex()+593 -> kghalo())
FRAME [23] (kghfnd()+376 -> kghgex())
FRAME [24] (kghalo()+4908 -> kghfnd())
FRAME [25] (kghgex()+593 -> kghalo())
FRAME [26] (kghalf()+617 -> kghgex())
FRAME [27] (ioc_allocate0()+1094 -> kghalf())
FRAME [28] (iocbf_allocate0()+53 -> ioc_allocate0())
FRAME [29] (ioc_do_call()+1297 -> iocbf_allocate0())
FRAME [30] (joet_switched_env_callback()+376 -> ioc_do_call())
FRAME [31] (ioct_allocate0()+79 -> joet_switched_env_callback())
FRAME [32] (eoa_new_mman_segment()+368 -> ioct_allocate0())
FRAME [33] (eoa_new_mswmem_chunk()+66 -> eoa_new_mman_segment())
FRAME [34] (eomsw_allocate_block()+229 -> eoa_new_mswmem_chunk())
FRAME [35] (eoa_alloc_mswmem_object_no_gc()+2037 -> eomsw_allocate_block())
FRAME [36] (eoa_alloc_mswmem_object()+48 -> eoa_alloc_mswmem_object_no_gc())
FRAME [37] (eoa_new_ool_alloc()+508 -> eoa_alloc_mswmem_object())
FRAME [38] (joe_make_primitive_array()+828 -> eoa_new_ool_alloc())
FRAME [39] (joe_run_vm()+15736 -> joe_make_primitive_array())
FRAME [40] (joe_run()+608 -> joe_run_vm())
FRAME [41] (joe_invoke()+1156 -> joe_run())
FRAME [42] (joet_aux_thread_main()+1674 -> joe_invoke())
FRAME [43] (seoa_note_stack_outside()+34 -> joet_aux_thread_main())
FRAME [44] (joet_thread_main()+64 -> seoa_note_stack_outside())
FRAME [45] (sjontlo_initialize()+178 -> joet_thread_main())
FRAME [46] (joe_enter_vm()+1197 -> sjontlo_initialize())
FRAME [47] (ioei_call_java()+4716 -> joe_enter_vm())
FRAME [48] (ioesub_CALL_JAVA()+569 -> ioei_call_java())
FRAME [49] (seoa_note_stack_outside()+34 -> ioesub_CALL_JAVA())
FRAME [50] (ioe_call_java()+292 -> seoa_note_stack_outside())
FRAME [51] (jox_invoke_java_()+4133 -> ioe_call_java())
FRAME [52] (kkxmjexe()+1493 -> jox_invoke_java_())

    Session Wait History:
     0: waited for 'PGA memory operation'
        =0xd000000, =0x2, =0x0

"Error: 12" is ENOMEM defined in /usr/include/asm-generic/errno-base.h.
"Additional information: 12394" is not clear.
"Additional information: 218103808" points out P1 parameter in Event "PGA memory operation" (12.2 new introduced), which also appears in "RDI 000000000D000000" of kgh_invoke_alloc_cb call (0xd000000 = 218103808).

In the above call stack, there is a subroutine "FRAME [35] (eoa_alloc_mswmem_object_no_gc()", with suffix "no_gc".

"FRAME [38] (joe_make_primitive_array()+828 -> eoa_new_ool_alloc())" shows that "joe_make_primitive_array" already passed line <+708> of byte array size check (see above disassembled code), and is calling "eoa_new_ool_alloc".

Occasionally, session is terminated:

SQL > exec createBuffer512_loop(511, 1, 1);
  ERROR:
  ORA-03114: not connected to ORACLE
  ORA-03113: end-of-file on communication channel
  Process ID: 14461
  Session ID: 907 Serial number: 50430

and Linux dmesg shows:

  Out of memory: Kill process 14461 (oracle_14461_c0) score 781 or sacrifice child
  Killed process 14461 (oracle_14461_c0) total-vm:23745148kB, anon-rss:18595960kB, file-rss:132kB, shmem-rss:538232kB

3. Out of Memory Error Application Handling

If PL/SQL applications hit out of Memory Error even under the discussed hard-coded limit, one possible workaround is try to catch the error, invoke dbms_java.endsession to release memory, and then re-try the application as follows:

set serveroutput on size 50000;
exec dbms_java.set_output(50000);

declare
  java_oom_29532    exception;
  pragma            exception_init(java_oom_29532, -29532);
  l_es_ret          varchar2(100);
begin
  p_define_int_array(134217724);   -- only illustrative demo, real application should use size below the limit
  exception 
    when java_oom_29532 then
      dbms_output.put_line('------ int[134217724] hit ORA-29532: java.lang.OutOfMemoryError ------');
      l_es_ret  := dbms_java.endsession;
      p_define_int_array(134217723);
      dbms_output.put_line('------ int[134217723] Succeed ------');
    when others then
      raise;
end;
/

Exception in thread "Root Thread" java.lang.OutOfMemoryError
        at Demo.defineIntArray(Demo:5)
------ int[134217724] hit ORA-29532: java.lang.OutOfMemoryError ------
OracleJvm int[].length: 134217723
------ int[134217723] Succeed ------

set serveroutput on size 50000;
exec dbms_java.set_output(50000);

declare
  java_oom_27102    exception;
  pragma            exception_init(java_oom_27102, -27102);
  l_es_ret          varchar2(100);
begin
  createBuffer512_loop(511, 1, 1); 
  exception 
    when java_oom_27102 then
      dbms_output.put_line('------ createBuffer512_loop hit ORA-27102: out of memory ------');
      l_es_ret  := dbms_java.endsession;
      createBuffer512_loop(3, 1, 1);
      dbms_output.put_line('------ createBuffer512_loop(3, 1, 1) Succeed ------');
    when others then
      raise;
end;
/

Step -- 284 --, Buffer Size (MB) = 284
Step -- 285 --, Buffer Size (MB) = 285
------ createBuffer512_loop hit ORA-27102: out of memory ------
Step -- 1 --, Buffer Size (MB) = 1
Step -- 2 --, Buffer Size (MB) = 2
Step -- 3 --, Buffer Size (MB) = 3
------ createBuffer512_loop(3, 1, 1) Succeed ------   

Oracle LOB Chunksize and Buffersize

In this Blog, we first show Oracle LOB chunksize in SQL and Plsql, then look chunksize and buffersize of LOB objects in Java from database and OracleJvm.

Note: Tested in Oracle 12c, 19c on Linux, Solaris, AIX with DB_BLOCK_SIZE=8192 and tablespace BLOCK_SIZE=8192.

1. SQL LOB Chunksize

First we create a table containing CLOB and BLOB columns with different chunk values, and insert one row:

drop table tab_lob cascade constraints;

create table tab_lob(
  id           number,
  clob_8k       clob,
  blob_8k       blob,
  clob_16k      clob,
  blob_16k      blob,
  clob_32k      clob,
  blob_32k      blob
)
lob (clob_8k) store as basicfile (
  enable       storage in row
  chunk        8192)
lob (blob_8k) store as basicfile (
  enable       storage in row
  chunk        8192)
lob (clob_16k) store as basicfile (
  enable       storage in row
  chunk        16384)
lob (blob_16k) store as basicfile (
  enable       storage in row
  chunk        16384)
lob (clob_32k) store as basicfile (
  enable       storage in row
  chunk        32768)
lob (blob_32k) store as basicfile (
  enable       storage in row
  chunk        32768);
  
insert into tab_lob values (1, empty_clob(), empty_blob(), empty_clob(), empty_blob(), empty_clob(), empty_blob());

commit;

List all chunksize with query:

select id, 
      dbms_lob.getchunksize(clob_8k)  clob_8k, 
      dbms_lob.getchunksize(blob_8k)  blob_8k, 
      dbms_lob.getchunksize(clob_16k) clob_16k, 
      dbms_lob.getchunksize(blob_16k) blob_16k,
      dbms_lob.getchunksize(clob_32k) clob_32k, 
      dbms_lob.getchunksize(blob_32k) blob_32k
from tab_lob;               


   ID   CLOB_8K   BLOB_8K   CLOB_16K   BLOB_16K   CLOB_32K   BLOB_32K
  --- --------- --------- ---------- ---------- ---------- ----------
    1      8132      8132      16264      16264      32528      32528

We can see that for chunking factor: 8192, chunksize is 8132, an overhead of 60 (8192-8132) bytes, only 8132 is used to store LOB value. All chunksize are multiple of 8132 instead of 8192 (DB_BLOCK_SIZE).

Here Oracle Docu on DBMS_LOB.GETCHUNKSIZE (19c):

DBMS_LOB.GETCHUNKSIZE Functions 
  When creating the table, you can specify the chunking factor, a multiple of tablespace blocks in bytes. 
  This corresponds to the chunk size used by the LOB data layer when accessing or modifying the LOB value. 
  Part of the chunk is used to store system-related information, and the rest stores the LOB value. 
  This function returns the amount of space used in the LOB chunk to store the LOB value.

The maximum CHUNK value is 32768 (32K), which is the largest Oracle Database block size allowed as documented in 19c LOB Storage with Applications :

LOB Storage CHUNK 
  If the tablespace block size is the same as the database block size, 
  then CHUNK is also a multiple of the database block size. 
  The default CHUNK size is equal to the size of one tablespace block, and the maximum value is 32K. 

2. Plsql and Java LOB Chunksize and BufferSize

We will look two sources of Java LOB objects, one is created in DB and passed to OracleJVM, another is directly created in OracleJVM. Besides chunksize similar to above SQL, Java LOB object has a bufferSize.

Here the test code:

drop java source "LobChunkBufferSize";

create or replace and compile java source named "LobChunkBufferSize" as
import java.sql.Connection;
import java.io.IOException;
import java.sql.SQLException;
import oracle.jdbc.OracleDriver;
import oracle.sql.CLOB;
import oracle.sql.BLOB;

public class LobChunkBufferSize {
    public static void printSizeFromDB(CLOB clob, BLOB blob) throws Exception {
        System.out.println("Java  CLOB ChunkSize: " + clob.getChunkSize() + ", BufferSize: " + clob.getBufferSize());
        System.out.println("Java  BLOB ChunkSize: " + blob.getChunkSize() + ", BufferSize: " + blob.getBufferSize());
    }
    
    public static void printSizeFromOracleJvm() throws Exception {
      Connection conn = new OracleDriver().defaultConnection();
      CLOB clob = CLOB.createTemporary(conn, false, CLOB.DURATION_SESSION);
      System.out.println("OracleJvm CLOB ChunkSize: " + clob.getChunkSize() + ", BufferSize: " + clob.getBufferSize());
      
      BLOB blob = BLOB.createTemporary(conn, false, BLOB.DURATION_SESSION);
      System.out.println("OracleJvm BLOB ChunkSize: " + blob.getChunkSize() + ", BufferSize: " + blob.getBufferSize());
    }
}     
/

create Or replace procedure printSizeFromDB (p_clob clob, p_blob blob) 
as language java name 'LobChunkBufferSize.printSizeFromDB(oracle.sql.CLOB, oracle.sql.BLOB)';
/

create Or replace procedure printSizeFromOracleJvm
as language java name 'LobChunkBufferSize.printSizeFromOracleJvm()' ;
/

First we display Plsql Chunksize, then pass LOB to OracleJVM and display their Chunksize and Buffersize:

set serveroutput on size 50000;
exec dbms_java.set_output(50000);

declare
  l_clob  clob;
  l_blob  blob;
  procedure print (l_name varchar2, l_clob clob, l_blob blob) as
    begin
      dbms_output.put_line(l_name);
      dbms_output.put_line('Plsql CLOB ChunkSize: '||dbms_lob.getchunksize(l_clob));
      dbms_output.put_line('Plsql BLOB ChunkSize: '||dbms_lob.getchunksize(l_blob)); 
      printSizeFromDB(l_clob, l_blob);        
    end;
begin
    select clob_8k, blob_8k into l_clob, l_blob from tab_lob where id = 1;
    print('------- 1. DB Lob 8k -------', l_clob, l_blob);
    
    select clob_16k, blob_16k into l_clob, l_blob from tab_lob where id = 1;
    print('------- 2. DB Lob 16k -------', l_clob, l_blob);
    
    select clob_32k, blob_32k into l_clob, l_blob from tab_lob where id = 1;
    print('------- 3. DB Lob 32k -------', l_clob, l_blob);
    
    dbms_lob.createtemporary(l_clob, TRUE);
    dbms_lob.createtemporary(l_blob, TRUE);        
    print('------- 4. Temporary Lob empty -------', l_clob, l_blob);
    
    l_clob := 'ABCabc123';
    l_blob := utl_raw.cast_to_raw(l_clob);
    print('------- 5. Temporary Lob small -------', l_clob, l_blob);
    dbms_output.put_line('----------**** CLOB length: '||dbms_lob.getlength(l_clob));
    
    l_clob := lpad('ABCabc123', 32767, 'A');
    l_blob := utl_raw.cast_to_raw(l_clob);
    print('------- 6. Temporary Lob big -------', l_clob, l_blob);
    dbms_output.put_line('----------****  CLOB length: '||dbms_lob.getlength(l_clob));
end;
/

Here the result:

  ------- 1. DB Lob 8k -------
  Plsql CLOB ChunkSize: 8132
  Plsql BLOB ChunkSize: 8132
  Java  CLOB ChunkSize: 8132, BufferSize: 32528
  Java  BLOB ChunkSize: 8132, BufferSize: 32528
  ------- 2. DB Lob 16k -------
  Plsql CLOB ChunkSize: 16264
  Plsql BLOB ChunkSize: 16264
  Java  CLOB ChunkSize: 16264, BufferSize: 32528
  Java  BLOB ChunkSize: 16264, BufferSize: 32528
  ------- 3. DB Lob 32k -------
  Plsql CLOB ChunkSize: 32528
  Plsql BLOB ChunkSize: 32528
  Java  CLOB ChunkSize: 32528, BufferSize: 32528
  Java  BLOB ChunkSize: 32528, BufferSize: 32528
  ------- 4. Temporary Lob empty -------
  Plsql CLOB ChunkSize: 8132
  Plsql BLOB ChunkSize: 8132
  Java  CLOB ChunkSize: 8132, BufferSize: 32528
  Java  BLOB ChunkSize: 8132, BufferSize: 32528
  ------- 5. Temporary Lob small -------
  Plsql CLOB ChunkSize: 4000
  Plsql BLOB ChunkSize: 4000
  Java  CLOB ChunkSize: 4000, BufferSize: 32000
  Java  BLOB ChunkSize: 4000, BufferSize: 32000
  ----------**** CLOB length: 9
  ------- 6. Temporary Lob big -------
  Plsql CLOB ChunkSize: 4000
  Plsql BLOB ChunkSize: 4000
  Java  CLOB ChunkSize: 4000, BufferSize: 32000
  Java  BLOB ChunkSize: 4000, BufferSize: 32000
  ----------****  CLOB length: 32767

We can see that Plsql and Java ChunkSize are the same as SQL for 8k, 16k, and 32k, and their BufferSize are always 32528. But Temporary Lob is special. In case of empty, ChunkSize is 8132, when assigned a value, it is decreased to 4000, in which CHUNK seems no more a multiple of the database block size as described in above "LOB Storage CHUNK". Their BufferSize are respectively 32528, 32000.

Now we look ChunkSize and BufferSize for LOB created in OracleJVM:

SQL > exec printSizeFromOracleJvm;

  OracleJvm CLOB ChunkSize: 8132, BufferSize: 32528
  OracleJvm BLOB ChunkSize: 8132, BufferSize: 32528

They are the same as the above case of 8k.

If we open Java class BLOB, we can see that getBufferSize is computed based on getChunkSize (all calculations are Java integer arithmetic), for example, if ChunkSize is 8132, BufferSize is 32528 (4*8132). Its maximum value is hard-coded as 32768 (probably the same limit as largest allowed Oracle Database block size).

public class BLOB extends DatumWithConnection implements Blob {
    public int getBufferSize() throws SQLException {
        ...

        int size = getChunkSize();
        int ret = size;

        if ((size >= 32768) || (size <= 0)) {
            ret = 32768;
        } else {
            ret = 32768 / size * size;
        }
        ...
        
        return ret;
    }

SQL*Plus Release 12.2.0.1.0 New Feature:

SET LOBPREFETCH {0 | n} 

sets the amount of LOB data (in bytes) that SQL*Plus will prefetch from the database at one time (one "roundtrips to/from client"), which has a maximum value of 32767. Each LOB value fetch requires one roundtrip.

One case of dbms_alert.signal deadlock

In this Blog, we present one case of DBMS_ALERT_INFO update deadlock when two sessions calling dbms_alert.signal.

At first, setup test by:

begin
       dbms_alert.register('test_alert_1');
       dbms_alert.register('test_alert_2');
end;
/

Then open 2 Sqlplus Sessions: S1, and S2, run following steps one after another:

---======== S1@T1:  send 'test_alert_1' ========---
exec dbms_alert.signal('test_alert_1', 'alert_msg_1');

---======== S2@T2:  send 'test_alert_2' ========---
exec dbms_alert.signal('test_alert_2', 'alert_msg_2');

---======== S1@T3:  send 'test_alert_2' ========---
exec dbms_alert.signal('test_alert_2', 'alert_msg_2');

---======== S2@T4:  send 'test_alert_1' ========---
exec dbms_alert.signal('test_alert_1', 'alert_msg_1');

After about 3 seconds, S1 (first starting session) hit a deadlock.

  
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource
ORA-06512: at "SYS.DBMS_ALERT", line 431
ORA-06512: at line 1

The trace file contains the Deadlock graph and Error Stack. It looks like a conventional case of deadlock generated in application of dbms_alert.signal.

Deadlock graph:
                                          ------------Blocker(s)-----------  ------------Waiter(s)------------
Resource Name                             process session holds waits serial  process session holds waits serial
TX-000F0014-00030A6B-00000000-00000000          8     374     X        16904      47     914           X  60788
TX-00020013-00043AF0-00000000-00000000         47     914     X        60788       8     374           X  16904
 
----- Information for waiting sessions -----
Session 374:
  sid: 374 ser: 16904 audsid: 50061287 user: 0/SYS
    flags: (0x8100041) USR/- flags2: (0x40009) -/-/INC
    flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
  pid: 8 O/S info: user: oracle, term: UNKNOWN, ospid: 6207
    image: oracle@testdb
  client details:
    O/S info: user: ksun, term: TESTPC, ospid: 20744:22464
    machine: SYS\TESTPC program: sqlplus.exe
    application name: SQL*Plus, hash value=3669949024
  current SQL:
  UPDATE DBMS_ALERT_INFO SET CHANGED = 'Y', MESSAGE = :B2 WHERE NAME = UPPER(:B1 )
 
Session 914:
  sid: 914 ser: 60788 audsid: 50061288 user: 0/SYS
    flags: (0x8100041) USR/- flags2: (0x40009) -/-/INC
    flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
  pid: 47 O/S info: user: oracle, term: UNKNOWN, ospid: 6325
    image: oracle@testdb
  client details:
    O/S info: user: ksun, term: TESTPC, ospid: 21236:22040
    machine: SYS\TESTPC program: sqlplus.exe
    application name: SQL*Plus, hash value=3669949024
  current SQL:
  UPDATE DBMS_ALERT_INFO SET CHANGED = 'Y', MESSAGE = :B2 WHERE NAME = UPPER(:B1 )
 
----- End of information for waiting sessions -----
 
*** 2020-11-08T14:53:34.649821+01:00
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=1, mask=0x0)
----- Error Stack Dump -----
 at 0x7ffef6442228 placed updexe.c@2062
 at 0x7ffef6443050 placed updexe.c@4637
----- Current SQL Statement for this session (sql_id=6tmkh8j0d3w0p) -----
UPDATE DBMS_ALERT_INFO SET CHANGED = 'Y', MESSAGE = :B2 WHERE NAME = UPPER(:B1 )
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x9ce97888       431  package body SYS.DBMS_ALERT.SIGNAL
0x7294ec28         1  anonymous block

In AskTOM: dbms_alert_info - Ask TOM - Oracle, there is also one case of dbms_alert deadlock.

The Second Test of ORA-600 [4156] Rolling Back To Savepoint

In the previous Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling, we followed Oracle MOS Note:
     Bug 9471070 : ORA-600 [4156] GENERATED WITH EXECUTE IMMEDIATE AND SAVEPOINT
and presented 5 reproducible test codes (one original from MOS plus 4 variants).

In this Second Test, we extend the previous test by including Global Temporary Table (GTT), and run the test with trace and dumps to get further understanding of the error.

The original MOS Note: Bug 9471070 cannot be found any more. As a substitute, we found a new published MOS Note:
     ORA-00600: [4156] when Rolling Back to a Savepoint (Doc ID 2242249.1)
which provides a possible workaround:
     Set the TEMP_UNDO_ENABLED back to the default setting of FALSE.
We will repeat the same tests with this workaround and watch the outcome.

Note: Tested in Oracle 19.6

1. Test Setup

The test includes a normal table and a GTT table. GTT table is created analogue to SYS.ATEMPTAB$. We also list their object_id for later dump file reference.

drop table test_tab purge;
create table test_tab(id number);

drop table test_atemptab purge;
create global temporary table test_atemptab (id number) on commit delete rows nocache;
create index test_atempind on test_atemptab(id);

select object_name, object_id from dba_objects where object_name in ('TEST_TAB', 'TEST_ATEMPTAB', 'TEST_ATEMPIND');
  OBJECT_NAME    OBJECT_ID
  -------------  ---------
  TEST_TAB         3333415
  TEST_ATEMPTAB    3333416
  TEST_ATEMPIND    3333417     

By the way, SYS.ATEMPTAB$ (and its index SYS.ATEMPIND$) has the smallest object_id in dba_objects with TEMPORARY='Y', possibly the earliest Oracle temporary object. If ORA-00600: [4156] points to some SYS object like this one, it probably signifies an Oracle internal error since applications do not have privilege to directly perform DML on it.

2. ORA-600 [4156] Error Message

At first, we perform all the tests with TEMP_UNDO_ENABLED= TRUE. Later we will test the workaround of FALSE (default) provided by MOS (Doc ID 2242249.1).

Open a Sqplus window, run following code snippet (similar to VARIANT-3 in Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling).

savepoint sp_a;
insert into test_tab values(1);
insert into test_atemptab values(11);
savepoint sp_b; 
begin
  rollback to savepoint sp_a;
  insert into test_atemptab values(12);
  rollback to savepoint sp_b;
end;
/

The session is terminated with ORA-00600, and an incident file is generated:

ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [],
[], [], [], []
ORA-01086: savepoint 'SP_B' never established in this session or is invalid
ORA-06512: at line 4
Process ID: 25417
Session ID: 902 Serial number: 20826

Opening incident file, it shows:

kturRollbackToSavepoint temp undokturRollbackToSavepoint savepoint uba: 0x00406a82.0000.02 xid: 0x005f.016.00007623
kturRollbackToSavepoint current call savepoint: ksucaspt num: 342  uba: 0x00c060ad.15fe.11
uba: 0x00406a82.0000.02 xid: 0x005f.016.00007623
 xid: 0x0386.000.00000001           <<< 0x0386 is Session ID: 902 (0x0386)

The first line indicates that the session is trying to rollback to a target savepoint by using temp undo (uba: 0x00406a82.0000.02) in transaction (xid: 0x005f.016.00007623).

The second and third line contain the info at the moment of crash, probably caused the error, which are savepoint (num: 342), permanent undo (uba: 0x00c060ad.15fe.11), temporary undo (uba: 0x00406a82.0000.02), transaction (xid: 0x005f.016.00007623).

The fourth line (xid: 0x0386.000.00000001) is not clear. As all the tests suggested, the first hexadecimal number is Session ID, for example, above 0x0386 is Session ID: 902. The second and third hexadecimal numbers are always 000.00000001.

3. Test with Trace and Dumps

To further explore the error, we can add some trace code to the test.

First we create a helper Plsql procedure to write out transaction and permanent/temporary undo info.

create or replace procedure write_info (p_step varchar2, p_sleep number := 5) as
  l_dst       binary_integer := 1;
  l_sid       number;
  l_trx       varchar2(100);
  l_temp_undo varchar2(100);
begin
  select sid into l_sid from v$mystat where rownum=1;
  
  select 'SID:'||s.sid||', XID:('||xidusn||'.'||xidslot||'.'||xidsqn||', '||flag||
         '), UNDO:('||ubafil||', '||ubablk||', '||ubasqn||', '||ubarec||')'
  into l_trx
  from v$transaction t, v$session s 
  where t.addr(+) = s.taddr and s.sid = l_sid;
  
  select 'TEMP_UNDO_HEADER:('||segrfno#||', '||segblk#||', '||segfile#||')' 
  into l_temp_undo
  from v$tempseg_usage t, v$session s 
  where t.segtype(+) = 'TEMP_UNDO' and t.session_addr(+) = s.saddr and s.sid = l_sid;
  
  sys.dbms_system.ksdwrt(l_dst, p_step||l_trx||', '||l_temp_undo);
  dbms_session.sleep(p_sleep);
end;
/

Each output line is composed of three tuples (all numbers in decimal):

  Step sid, XID:(xidusn.xidslot.xidsqn, flag), 
            UNDO:(ubafil, ubablk, ubasqn, ubarec), 
            TEMP_UNDO_HEADER:(segrfno#, segblk#, segfile#)

In the above test code, we add write_info after each code line. Step1 to Step5 make a default pause of 5 seconds. At Step6, we sleep 300 seconds, so that we have time to make dumps.

Open a Sqlplus window, run code below:

alter session set max_dump_file_size = unlimited;

alter session set tracefile_identifier = "Test_f";  

savepoint sp_a;
  exec write_info('Step1_');   
insert into test_tab values(1);
  exec write_info('Step2_');
insert into test_atemptab values(11);
savepoint sp_b; 
  exec write_info('Step3_');
begin
       write_info('Step4_');
  rollback to savepoint sp_a;
       write_info('Step5_');
  insert into test_atemptab values(12);
       write_info('Step6_', 300);
  rollback to savepoint sp_b;
       write_info('Step7_');
end;
/

And monitor the trace file "Test_f", once it reaches Step6 as follows:

Oracle process number: 38
Unix process pid: 16147, image: oracle@testdb
*** SESSION ID:(370.53180) 2020-09-13T15:21:48.003188+02:00

*** 2020-09-13T15:21:53.118636+02:00
Step2_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(, , )

*** 2020-09-13T15:21:58.165769+02:00
Step3_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(1, 19328, 3073)

*** 2020-09-13T15:22:03.263868+02:00
Step4_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(1, 19328, 3073)

*** 2020-09-13T15:22:08.352391+02:00
Step5_SID:370, XID:(89.15.51190, 5635), UNDO:(0, 0, 0, 0), TEMP_UNDO_HEADER:(1, 19328, 3073)

*** 2020-09-13T15:22:13.553650+02:00
Step6_SID:370, XID:(89.15.51190, 5635), UNDO:(0, 0, 0, 0), TEMP_UNDO_HEADER:(1, 19328, 3073)

we pick the three tuples from Step4 line:

Step4_SID:370, XID:(89.15.51190, 7683), UNDO:(3, 2476, 6688, 3), TEMP_UNDO_HEADER:(1, 19328, 3073)

and make the both permanent and temporary undo dump (19328 is temp undo header block, we make 4 more blocks dump to include undo data block):

oradebug setmypid;
alter system flush buffer_cache;
alter system checkpoint;

oradebug settracefileid undo_f;
alter system dump datafile 3 block min 2476 block max 2476; 

oradebug settracefileid temp_undo_f;
alter system dump tempfile 1 block min 19328 block max 19332;	

and additionally make a processstate dump (38 is Oracle PID of test session):

oradebug setorapid 38;
oradebug settracefileid proc_f;
oradebug dump processstate 10;

After about 6 minutes, the session terminated with fatal error:

ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [], [], [], [], []
ORA-01086: savepoint 'SP_B' never established in this session or is invalid
ORA-06512: at line 7
Process ID: 16147
Session ID: 370 Serial number: 53180

and incident file looks like:

========= Dump for incident 73594 (ORA 600 [4156]) ========
*** SESSION ID:(370.53180) 2020-09-13T15:27:13.752430+02:00

kturRollbackToSavepoint temp undokturRollbackToSavepoint savepoint uba: 0x00404b82.0000.02 xid: 0x0059.00f.0000c7f6
kturRollbackToSavepoint current call savepoint: ksucaspt num: 394  uba: 0x00c009ac.1a20.03
uba: 0x00404b82.0000.02 xid: 0x0059.00f.0000c7f6
 xid: 0x0172.000.00000001         <<< 0x0172 is Session ID: 370 (0x0172)

Now we go through all three dumps (only related lines are extracted).

3.1. Permanent Undo

We inserted one row into test_tab. "Rec #0x3" is the only undo record (first and last), noted with "rdba: 0x00000000" and "rci 0x00". It is "uba: 0x00c009ac.1a20.03" (rdba: 3/2476, seq: 6688, rec: 3) in above incident file.

========= undo_f ========
Start dump data blocks tsn: 2 file#:3 minblk 2476 maxblk 2476
Block dump from cache:
Dump of buffer cache at level 3 for pdb=0 tsn=2 rdba=12585388
BH (0x140f569e8) file#: 3 rdba: 0x00c009ac (3/2476) class: 194 ba: 0x1400c6000
...
UNDO BLK:  
 xid: 0x0059.00f.0000c7f6  seq: 0x1a20 cnt: 0x3   irb: 0x3   icl: 0x0   flg: 0x0000
 
 Rec Offset      Rec Offset      Rec Offset      Rec Offset      Rec Offset
---------------------------------------------------------------------------
0x01 0x1f78     0x02 0x1ec4     0x03 0x1e3c     
...
*-----------------------------
* Rec #0x3  slt: 0x0f  objn: 3333415(0x0032dd27)  objd: 3333415  tblspc: 2300(0x000008fc)
*       Layer:  11 (Row)   opc: 1   rci 0x00   
Undo type:  Regular undo    Begin trans    Last buffer split:  No 
Temp Object:  No 
rdba: 0x00000000Ext idx: 0
flg2: 0
*-----------------------------
uba: 0x00c009ac.1a20.02 ctl max scn: 0x000008d5bc68c586 prv tx scn: 0x000008d5bc68c589
txn start scn: scn: 0x000008d5bc68ccc8 logon user: 49
 prev brb: 12585365 prev bcl: 0

3.2. Temp Undo

At first, we look temp undo header block (rdba: 0x00404b80 (1/19328) class: 33. File number: 3073, Relative file number: 1).

========= temp_undo_f (undo header block) ========
Dump of buffer cache at level 3 for pdb=0 tsn=3 rdba=4213632
BH (0x108fe8de8) file#: 3073 rdba: 0x00404b80 (1/19328) class: 33 ba: 0x108dc6000
...
  TRN CTL:: seq: 0x0000 chd: 0x0001 ctl: 0x0061 inc: 0x00000000 nfb: 0x0000
            mgc: 0x8002 xts: 0x0068 flg: 0x0001 opt: 2147483647 (0x7fffffff)
            uba: 0x00404b82.0000.01 scn: 0x0000000000000000 
  TRN TBL::
  index  state cflags  wrap#    uel         scn            dba            parent-xid    nub     stmt_num
  ------------------------------------------------------------------------------------------------
   0x00   10    0x80  0x0001  0x0000  0x000008d5bc68cd00  0x00404b82   0x0000.000.00000000  0x00000001   0x00000000   0
   0x01    9    0x00  0x0000  0x0002  0x0000000000000000  0x00000000   0x0000.000.00000000  0x00000000   0x00000000   0
...
   0x61    9    0x00  0x0000  0xffff  0x0000000000000000  0x00000000   0x0000.000.00000000  0x00000000   0x00000000   0

There is one active slot 0x00 flagged with state 10, which is our transaction with starting uba: 0x00404b82.0000.01, and current dba 0x00404b82.

Here we can also see that temp undo header (class: 33) TRN TBL has 98 entries (0x00 to 0x61), whereas normal permanent undo header has 34 entries (0x00 to 0x21).

Then look temp undo data block (rdba: 0x00404b82 (1/19330) class: 34).

========= temp_undo_f (undo data block) ========
Dump of buffer cache at level 3 for pdb=0 tsn=3 rdba=4213634
BH (0x109fe2308) file#: 3073 rdba: 0x00404b82 (1/19330) class: 34 ba: 0x109d2e000
...
UNDO BLK:  
 xid: 0x0059.00f.0000c7f6  seq: 0x0   cnt: 0x4   irb: 0x4   icl: 0x0   flg: 0x0000
 
 Rec Offset      Rec Offset      Rec Offset      Rec Offset      Rec Offset
---------------------------------------------------------------------------
0x01 0x1f6c     0x02 0x1efc     0x03 0x1eb0     0x04 0x1e40     
...
*-----------------------------
* Rec #0x1  slt: 0x00  objn: 3333416(0x0032dd28)  objd: 4222336  tblspc: 3(0x00000003)
*       Layer:  11 (Row)   opc: 1   rci 0x00   
Undo type:  Regular undo    Begin trans    Last buffer split:  No 
Temp Object:  Yes 
rdba: 0x00000000Ext idx: 4
*-----------------------------
uba: 0x00000000.0000.00 ctl max scn: 0x0000000000000000 prv tx scn: 0x0000000000000000
txn start scn: scn: 0x000008d5bc68cd00 logon user: 49
 prev brb: 0 prev bcl: 0
*-----------------------------
* Rec #0x2  slt: 0x00  objn: 3333417(0x0032dd29)  objd: 4221568  tblspc: 3(0x00000003)
*       Layer:  10 (Index)   opc: 22   rci 0x01   
rdba: 0x00000000Ext idx: 5
*-----------------------------
(kdxlpu): purge leaf row
key :(10):  02 c1 0c 06 00 40 6d 81 00 00
*-----------------------------
* Rec #0x3  slt: 0x00  objn: 3333416(0x0032dd28)  objd: 4221568  tblspc: 3(0x00000003)
*       Layer:  11 (Row)   opc: 1   rci 0x00   
rdba: 0x00000000Ext idx: 4
*-----------------------------
* Rec #0x4  slt: 0x00  objn: 3333417(0x0032dd29)  objd: 4222336  tblspc: 3(0x00000003)
*       Layer:  10 (Index)   opc: 22   rci 0x03   
rdba: 0x00000000Ext idx: 5
*-----------------------------
(kdxlpu): purge leaf row
key :(10):  02 c1 0d 06 00 40 6a 81 00 00

Here we can see two temp table inserted rows:

  02 c1 0c 06 00 40 6d 81 00 00    <<< "c1 0c": 02 bytes for number 11, followed by 06 bytes
  02 c1 0d 06 00 40 6a 81 00 00    <<< "c1 0d": 02 bytes for number 12, followed by 06 bytes

both are marked with "purge leaf row", that represents undo of insert (reverse of insert).

In the above dump, there are 4 undo records. The last one is "Rec #0x4", whose "rci 0x03" indicates that its previous undo record is "Rec #0x3" (all undo records in the test with "rdba: 0x00000000"). Whereas "Rec #0x3" has "rci 0x00", which means that it is a first undo record and does not have any previous undo record, since in our test, immediately after "Step4", we rollback to a savepoint by:

  rollback to savepoint sp_a;

The incident file shows that "uba: 0x00404b82.0000.02" (Rec #0x2) is the target savepoint uba (undokturRollbackToSavepoint), and it is also the current temp undo record at the moment of crash (instead of Rec #0x4).

Since there is no link from ("Rec #0x4" -> "Rec #0x3") to ("Rec #0x2" -> "Rec #0x1"), "rollback to savepoint sp_b" failed, and hence ORA-600 [4156] Rolling Back To Savepoint.

By the way, if we remove this rollback, "Rec #0x3" will point to previous undo record "rci 0x02" as follows:

* Rec #0x3  slt: 0x00  objn: 3333416(0x0032dd28)  objd: 4221568  tblspc: 3(0x00000003)
*       Layer:  11 (Row)   opc: 1   rci 0x02  

3.3. Processstate

We only list Savepoint related lines.

========= proc_f ========
Flags=[0000] SavepointNum=1a7 Time=09/13/2020 15:22:13 
  LibraryHandle:  Address=0x8b61ad18 Hash=4ac26de7 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=INSERT INTO TEST_ATEMPTAB VALUES(12) 
    
Flags=CNB/[0001] SavepointNum=18a Time=09/13/2020 15:22:03 
  LibraryHandle:  Address=0x8b5e1558 Hash=a2b60837 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=begin
                           write_info('Step4_');
                      rollback to savepoint sp_a;
                           write_info('Step5_');
                      insert into test_atemptab values(12);
                           write_info('Step6_', 300);
                      rollback to savepoint sp_b;
                           write_info('Step7_');
                    end;

Flags=CNB/[0001] SavepointNum=164 Time=09/13/2020 15:21:57 
  LibraryHandle:  Address=0xa39d5d68 Hash=65d67994 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=insert into test_atemptab values(11) 
    
Flags=CNB/[0001] SavepointNum=14f Time=09/13/2020 15:21:52 
  LibraryHandle:  Address=0x96c1c530 Hash=9abe37a2 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=insert into test_tab values(1) 

We can see the three executed DML insert statements, one Plsql anonymous block, and their corresponding Savepoint numbers, timestamp, ordered reversely by execution sequence:

  INSERT INTO TEST_ATEMPTAB VALUES(12)  >>> SavepointNum=1a7  Time=09/13/2020 15:22:13 
  begin ... end                         >>> SavepointNum=18a  Time=09/13/2020 15:22:03
  insert into test_atemptab values(11)  >>> SavepointNum=164  Time=09/13/2020 15:21:57 
  insert into test_tab values(1)        >>> SavepointNum=14f  Time=09/13/2020 15:21:52

SavepointNum=18a is placed directly before we submit Plsql anonymous block.

Searching "0x18a" in Processstate dump, we found:

svpt(xcb:0xad719320 sptn:0x18a uba: 0x00c009ac.1a20.03 uba: 0x00404b82.0000.02)
xctsp name:ˆb¬‹
      svpt(xcb:0x8bac6310 sptn:0x6013cfa0 uba: 0x00000000.0000.00 uba: 0x00000000.0000.00)
      status:INVALID next:(nil)

Referring back to above incident file, "current call savepoint: ksucaspt num: 394" is exactly "sptn:0x18a". Its cryptic name "ˆb¬‹" (extended ascii: 88 62 AC 8B) suggested that it is an implicit savepoint created by Oracle in order to maintain the atomicity (eventually rollback when error happens). The "status:INVALID" probably hints the cause of ORA-00600: [4156].
(Note: occasionally cryptic name is empty, or "status:VALID", but same ORA-00600: [4156]).

In above trace file "Test_f", Step5 and Step6 are marked with a valid XID, but UNDO tuple contains 4 zeros:

Step5_SID:370, XID:(89.15.51190, 5635), UNDO:(0, 0, 0, 0), TEMP_UNDO_HEADER:(1, 19328, 3073)

It means that there exists an active transaction having XID, but no undo record. If we dump permanent undo header block, it also shows dba as "0x00000000" for the active (state 10) TRN TBL slot. By the way, in Blog: TM lock and No Transaction Commit, TX & TM Locks and No Transaction Visible , we showed one case where there exist TX and TM Locks, but no Transaction Visible (TX & TM Locks and No Transaction Visible).

gv$transaction is defined as:

select 
    ...
    ktcxbflg                                             flag     ,                                            
    decode (bitand (ktcxbflg, 16), 0, 'NO', 'YES')       space    ,      
    decode (bitand (ktcxbflg, 32), 0, 'NO', 'YES')       recursive,      
    decode (bitand (ktcxbflg, 64), 0, 'NO', 'YES')       noundo   ,      
    decode (bitand (ktcxbflg, 8388608), 0, 'NO', 'YES')  ptx      , 
    ...
  from x$ktcxb 
 where bitand (ksspaflg, 1) != 0 and bitand (ktcxbflg, 2) != 0

It contains a column: NOUNDO, computed by bitand (ktcxbflg, 64), which is YES for no undo transaction. In above test, the exported flag is either 5635 (1 0110 0000 0011) or 7683 (1 1110 0000 0011). Both has bit-7 not set (0100 0000=64), i.e., NOUNDO = 'NO'.

In above Step5, we have UNDO:(0, 0, 0, 0), but NOUNDO = 'NO'. It is not clear how this flag is set up.

We also tried to put a DML insert before "savepoint sp_a" to keep UNDO filled with non zeors, but it generates the same error.

insert into test_tab values(0);
savepoint sp_a;
insert into test_tab values(1);
insert into test_atemptab values(11);
savepoint sp_b; 
begin
  rollback to savepoint sp_a;
  insert into test_atemptab values(12);
  rollback to savepoint sp_b;
end;
/

(Note: If TEMP_UNDO_ENABLED = FALSE, the above code snippet with this added first insert statement does not throw "ORA-00600: [4156]", the error is "ORA-01086: savepoint 'SP_B' never established in this session or is invalid")

In above investigation, we looked different traces and dumps to understand the error. In real operations, when such an error occurs, an incident file is generated. We can go through the incident file to find similar information (if dump file size is unlimited).

In the incident file, we can see the redo dump commands like:

Dump redo command(s):
 ALTER SYSTEM DUMP REDO DBA MIN 3073 19328 DBA MAX 3073 19328 TIME MIN 1050591433 TIME MAX 1050593293
 ALTER SYSTEM DUMP REDO DBA MIN 3073 19330 DBA MAX 3073 19330 TIME MIN 1050591451 TIME MAX 1050593311

which are brought out by call stack:

  kcra_dump_redo_tsn_rdba <- kturDiskRbkToSvpt <- kturRbkToSvpt <- ktcrsp1_new 
  <- ktcrsp1 <- ksudlc <- kss_del_cb <- kssdel <- ksupop

4. TEMP_UNDO_ENABLED = FALSE Workaround Test

Here the Oracle Workaround MOS Note (copy here to archive a persistent reference):

ORA-00600: [4156] when Rolling Back to a Savepoint (Doc ID 2242249.1)

Applies to:
    Oracle Database - Standard Edition - Version 12.1.0.2 and later
Symptoms
    You are running a procedure that utilizes savepoints, however, 
    when attempting to rollback to a savepoint, you experience the following error:
The stack trace will show similar stack:
    ksedst1 <- ksedst <- dbkedDefDump <- ksedmp <- ksfdmp <- dbgexPhaseII <- dbgexExplicitEndInc 
    <- dbgeEndDDEInvocatio <- nImpl <- dbgeEndDDEInvocatio <- kturDiskRbkToSvpt <- kturRbkToSvpt 
    <- ktcrsp1 <- xctrsp <- roldrv <- kksExecuteCommand
Cause
    This is due to a product defect. This is being investigated in unpublished
    Bug 25393735 - SR18.1TEMPUNDO - TRC - KTURDISKRBKTOSVPT - ORA-600 [4156]
    This issue occurs when we have temp undo and the logical standby performs eager apply.
Solution
    Possible workaround is:
      Set the TEMP_UNDO_ENABLED back to the default setting of FALSE.
    TEMP_UNDO_ENABLED determines whether transactions within a particular session can have a temporary undo log.
    The default choice for database transactions has been to have a single undo log per transaction. 
    This parameter, at the session level / system level scope, lets a transaction split its undo log into 
    temporary undo log (for changes on temporary objects) and permanent undo log (for changes on persistent objects).
    
    Modifiable: ALTER SESSION, ALTER SYSTEM

Now we try to test the Workaround with the same code:

ALTER SESSION set TEMP_UNDO_ENABLED=FALSE;
-- ALTER SYSTEM set TEMP_UNDO_ENABLED= FALSE; is also tested. Same outcome

savepoint sp_a;
insert into test_tab values(1);
insert into test_atemptab values(11);
savepoint sp_b; 
begin
  rollback to savepoint sp_a;
  insert into test_atemptab values(12);
  rollback to savepoint sp_b;
end;
/

ORA-00603: ORACLE server session terminated by fatal error
ORA-00600: internal error code, arguments: [4156], [], [], [], [], [], [], [],
[], [], [], []
ORA-01086: savepoint 'SP_B' never established in this session or is invalid
ORA-06512: at line 4
Process ID: 24328
Session ID: 370 Serial number: 32536

The session terminated by the same fatal error, and incident file shows:

kturRollbackToSavepoint perm undokturRollbackToSavepoint savepoint uba: 0x00c038d7.1a1c.0b xid: 0x0059.01f.0000c7f4
kturRollbackToSavepoint current call savepoint: ksucaspt num: 362  uba: 0x00c038d7.1a1c.0b
uba: 0x00000000.0000.00 xid: 0x0059.01f.0000c7f4
 xid: 0x0000.000.00000000

Compared to the case of TEMP_UNDO_ENABLED=TRUE, no more temp undo is recorded. If we also make a processstate dump, we can see the similar savepoint info.

In fact, we re-run all 5 test codes from previous Blog: ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling in the same DB (Oracle 19.6), once with default TEMP_UNDO_ENABLED=FALSE, and once with TEMP_UNDO_ENABLED=TRUE. They all generated ORA-600 [4156]. As above tests showed, it is not clear in which case the abvoe MOS Note Workaround can be applied.

Row Cache Object and Row Cache Mutex Case Study

12cR2 introduced "row cache mutex" to replace previous "latch: row cache objects". In this Blog, we will choose 'dc_props' and 'dc_cdbprops' to test "row cache mutex". Both have a fixed number of objects, a fixed pattern to use mutex for each object access, so that test can be repeated, and results are identical for each run.

First we run queries and make dumps to expose row cache data structure and content. Then we perform 10222 event trace and gdb script to understand row cache data access and row cache mutex usage. Finally we make a few discussions on the test result.

Note: Tested in Oracle 19c on Linux.

Acknowledgement: This work results from the help and discussions with a longtime Oracle specialist.

1. Row Cache: 'dc_props' and 'dc_cdbprops'

Following query shows that dc_props has 85 objects, and dc_cdbprops has 6.

select cache#, type, subordinate#, parameter, count, usage, fixed, gets, fastgets 
from v$rowcache where parameter in ('dc_props', 'dc_cdbprops');

  CACHE# TYPE   SUBORDINATE# PARAMETER   COUNT USAGE FIXED    GETS FASTGETS
  ------ ------ ------------ ----------- ----- ----- ----- ------- --------
      15 PARENT              dc_props       85    85     0 1162164        0
      60 PARENT              dc_cdbprops     6     6     0    1127        0

One query on nls_database_parameters requires 88 row cache Gets. (GETS_DELTA should be 85, the difference of 3 is due to v$rowcache query. dc_props is the backbone of nls_database_parameters. See Blog: nls_database_parameters, dc_props, latch: row cache objects )

column gets new_value gets_old;
column fastgets new_value gets_oldf;
select sum(gets) gets, sum(fastgets) fastgets from v$rowcache where parameter = 'dc_props';

select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';

select (sum(gets)-&gets_old) gets_delta, (sum(fastgets)-&gets_oldf) gets_deltaf, sum(gets) gets, sum(fastgets) fastgets from v$rowcache where parameter = 'dc_props';

  GETS_DELTA  GETS_DELTAF        GETS    FASTGETS
  ----------  -----------  ----------  ----------
          88            0      138749           0    

By the way, Oracle has a hidden parameter to turn on FASTGETS when TRUE, and 19c changed the default value from FALSE to TRUE.

    _kqr_optimistic_reads

Description: optimistic reading of row cache objects

Default: FALSE (Oracle 12.1); TRUE (Oracle 19.6)

Change: alter system set "_kqr_optimistic_reads"=false; (require DB restart)

One more query reveals that 85 'dc_props' objects are distributed into 5 hash buckets with size varied from 1 to 6 (no hash_bucket_size 5). Most of objects are hashed into bucket size of 1 or 2. Later we will see the same hash mapping in row_cache dump.

select Hash_Bucket_Size, count(*) Number_of_Buckets, (Hash_Bucket_Size * count(*)) Number_of_RowCache_Objects from 
  (select (hash+1) Hash_Bucket, count(*) Hash_Bucket_Size from v$rowcache_parent where cache_name = 'dc_props' group by hash)
group by Hash_Bucket_Size order by 2 desc;

  HASH_BUCKET_SIZE NUMBER_OF_BUCKETS NUMBER_OF_ROWCACHE_OBJECTS
  ---------------- ----------------- --------------------------
                 1                22                         22
                 2                13                         26
                 3                 5                         15
                 4                 4                         16
                 6                 1                          6

Here the similar query for 6 'dc_cdbprops' objects:

select Hash_Bucket_Size, count(*) Number_of_Buckets, (Hash_Bucket_Size * count(*)) Number_of_RowCache_Objects from 
  (select (hash+1) Hash_Bucket, count(*) Hash_Bucket_Size from v$rowcache_parent where cache_name = 'dc_cdbprops' group by hash)
group by Hash_Bucket_Size order by 2 desc;

  HASH_BUCKET_SIZE NUMBER_OF_BUCKETS NUMBER_OF_ROWCACHE_OBJECTS
  ---------------- ----------------- --------------------------
                 2                 2                          4
                 1                 2                          2      

With following helper function and query, we can reveal the exact name of each 'dc_props' row cache object (See Blog: Oracle ROWCACHE Views and Contents)

----helper function----
create or replace function dump_hex2str (dump_hex varchar2) return varchar2 is
  l_str varchar2(100);
begin
  with sq_pos as (select level pos from dual connect by level <= 1000)
      ,sq_chr as (select pos, chr(to_number(substr(dump_hex, (pos-1)*2+1, 2), 'XX')) ch
                  from sq_pos where pos <= length(dump_hex)/2)
  select listagg(ch, '') within group (order by pos) word
    into l_str
  from sq_chr;
  return l_str;
end;
/
     
select dump_hex2str(rtrim(key, '0')) dc_prop_name, v.* 
from v$rowcache_parent v 
where cache_name in ('dc_props') 
order by key; 

  DC_PROP_NAME         INDX HASH ADDRESS          CACHE# CACHE_NAME EXISTENT
  -------------------- ---- ---- ---------------- ------ ---------- --------
  COMMON_DATA_MA       8840    1 0000000094E51558     15 dc_props   N
  MAX_PDB_SNAPSHOTS    8838    0 0000000093638360     15 dc_props   Y
  NLS_SPECIAL_CHARS    8842    2 000000009F55FB18     15 dc_props   N
  NLS_TIMESTAMP_FORMAT 8841    2 000000008C2726C8     15 dc_props   Y
  PDB_AUTO_UPGRADE     8839    0 0000000095BCE218     15 dc_props   N
  ...
  85 rows selected.              

2. Row Cache Data Dump

With following command, we can dump 'dc_props'. (See MOS Bug 19354335 - Diagnostic enhancement for rowcache data dumps (Doc ID 19354335.8))

alter session set tracefile_identifier = 'dc_props_dump';
-- dump level 0xf2b: f is cache id 15 ('dc_props'), 2 is single cacheiddump, b is level of 11
alter session set events 'immediate trace name row_cache level 0xf2b';
alter session set events 'immediate trace name row_cache off';

The dump consists of 3 sections, the first is about all ROW CACHE STATISTICS, the second is ROW CACHE HASH TABLE for our specified 'dc_props' (same as above query output about HASH_BUCKET), the third is about each BUCKET and its grouped rows. For example, 4 rows are hashed to BUCKET 50. After BUCKET 50 is BUCKET 52, there is no BUCKET 51.

We will pick BUCKET 50 and its last row cache parent object "addr=0x8d7bc858" in our later discussion.

ROW CACHE STATISTICS:
cache                          size     gets  misses  hit ratio  
--------------------------  -------  -------  ------  ---------  
dc_tablespaces                  560    94329    3277      0.966  
dc_free_extents                 336        0       0      0.000  
dc_segments                     416     9751    3050      0.762  
dc_rollback_segments            496   769333     367      1.000  
...

ROW CACHE HASH TABLE: cid=15 ht=0xa709f910 size=64
  Hash Chain Size     Number of Buckets
  ---------------     -----------------
  0                    0
  1                   22
  2                   13
  3                    5
  4                    4
  5                    0    <<< HASH_BUCKET_SIZE 5 has 0 Buckets. Same as previous query
  6                    1               
           
BUCKET 50:
  row cache parent object: addr=0x8d776c38 cid=15(dc_props) conid=0 conuid=0
  hash=641d81f1 typ=21 transaction=(nil) flags=00000001 inc=1, pdbinc=1
  own=0x8d776d08[0x8d776d08,0x8d776d08] wat=0x8d776d18[0x8d776d18,0x8d776d18] mode=N req=N
  status=EMPTY/-/-/-/-/-/-/-/-  KGH unpinned
  data=
  
  row cache parent object: addr=0x8e8c5b10 cid=15(dc_props) conid=0 conuid=0
  hash=534cbb1 typ=21 transaction=(nil) flags=00000002 inc=1, pdbinc=1
  own=0x8e8c5be0[0x8e8c5be0,0x8e8c5be0] wat=0x8e8c5bf0[0x8e8c5bf0,0x8e8c5bf0] mode=N req=N
  status=VALID/-/-/-/-/-/-/-/-  KGH unpinned
  
  row cache parent object: addr=0x8e8e5be0 cid=15(dc_props) conid=0 conuid=0
  hash=3cf1dc71 typ=21 transaction=(nil) flags=00000002 inc=1, pdbinc=1
  own=0x8e8e5cb0[0x8e8e5cb0,0x8e8e5cb0] wat=0x8e8e5cc0[0x8e8e5cc0,0x8e8e5cc0] mode=N req=N
  status=VALID/-/-/-/-/-/-/-/-  KGH unpinned
  
  row cache parent object: addr=0x8d7bc858 cid=15(dc_props) conid=0 conuid=0
  hash=819e131 typ=21 transaction=(nil) flags=00000002 inc=1, pdbinc=1
  own=0x8d7bc928[0x8d7bc928,0x8d7bc928] wat=0x8d7bc938[0x8d7bc938,0x8d7bc938] mode=N req=N
  status=VALID/-/-/-/-/-/-/-/-  KGH unpinned
  data=
  
  BUCKET 50 total object count=4
BUCKET 52:
  row cache parent object: addr=0x8d76c148 cid=15(dc_props) conid=0 conuid=0

3. Processstate Dump

Additionally, we make a Processstate Dump, which contains "call: 0xb74520f0", and can be mapped to later 10222 trace "pso=0xb74520f0", and gdb "kqrpre1 pso (SOC): b74520f0".

alter session set tracefile_identifier = 'proc_state';
alter session set events 'immediate trace name PROCESSSTATE level 10'; 
alter session set events 'immediate trace name PROCESSSTATE off'; 

Each SO (State Object) seems having one SOC (State Object Call (or Copy) as current instance)

PROCESS STATE
-------------
Process global information:
     process: 0xb84202a0, call: 0xb74520f0, xact: (nil), curses: 0xb898ecc8, usrses: 0xb898ecc8
     in_exception_handler: no
  ----------------------------------------
  SO: 0xb8eeb9a8, type: process (2), map: 0xb84202a0
      state: LIVE (0x4532), flags: 0x1
      owner: (nil), proc: 0xb8eeb9a8
      link: 0xb8eeb9c8[0xb8eeb9c8, 0xb8eeb9c8]
      child list count: 6, link: 0xb8eeba18[0xb8f060c8, 0xa6fe8208]
      pg: 0
  SOC: 0xb84202a0, type: process (2), map: 0xb8eeb9a8
       state: LIVE (0x99fc), flags: INIT (0x1)
  (process) Oracle pid:55, ser:96, calls cur/top: 0xb74520f0/0xb74520f0
...
    ----------------------------------------
    SO: 0xb8f226a8, type: call (3), map: 0xb74520f0
        state: LIVE (0x4532), flags: 0x1
        owner: 0xb8eeb9a8, proc: 0xb8eeb9a8
        link: 0xb8f226c8[0xa6fe8208, 0xb4ed1eb0]
        child list count: 0, link: 0xb8f22718[0xb8f22718, 0xb8f22718]
        pg: 0
    SOC: 0xb74520f0, type: call (3), map: 0xb8f226a8
         state: LIVE (0x99fc), flags: INIT (0x1)
    (call) sess: cur b898ecc8, rec 0, usr b898ecc8; flg:20 fl2:1; depth:0
    svpt(xcb:(nil) sptn:0x13f uba: 0x00000000.0000.00 uba: 0x00000000.0000.00)

4. Row Cache Event 10222

Make one 10222 trace: (See Blog: Oracle row cache objects Event: 10222, Dtrace Scripts (I))

alter session set tracefile_identifier = 'dc_props_10222';
alter session set events '10222 trace name context forever, level 4294967295';  
select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
alter session set events '10222 trace name context off';

The trace file contains Function Calls and Call Stack, for example, Parent Object po=0x8d7bc858 has hash=819e131, pso=0xb74520f0. The same information can be found in the output of next gdb Script.

kqrpre: start hash=819e131 mode=S keyIndex=0 dur=CALL opt=FALSE
kqrpre: found cached object po=0x8d7bc858 flg=2
kqrmpin : kqrpre: found po Pin po 0x8d7bc858 cid=15 flg=2 hash=819e131
time=978904531
kqrpre: pinned po=0x8d7bc858 flg=2 pso=0xb74520f0
pinned stack po=0x8d7bc858 cid=15: ----- Abridged Call Stack Trace -----
ksedsts()+426<-kqrpre2 code="" kkdlpexecsql="" kkdlpexecsqlcbk="" kkdlpget="" kqrpre1="">

5. gdb Script

In Oracle session, we run again query on nls_database_parameters, and at the same time, trace the process with Blog appended Script: gdb_cmd_script2 in a UNIX window, write the trace output into file mutex-test2.log.

$ > gdb -x gdb_cmd_script2 -p 18158

SQL > select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';

Excerpted from mutex-test2.log, here the access pattern for row cache row with addr=0x8d7bc858.

Breakpoint 334, 0x00000000126e3930 in kqrpre1 ()
<<<==================== (1) kqrpre1 pso (SOC): b74520f0 ====================>>>
Breakpoint 124, 0x00000000126dd4e0 in kqrpre2 ()
Breakpoint 125, 0x00000000126df840 in kqrhsh ()
Breakpoint 335, 0x00000000126df8ad in kqrhsh ()
     (1) kqrhsh retq hash (rax): hash=819e131
Breakpoint 135, 0x00000000126e33f0 in kqrGetHashMutexInt ()
Breakpoint 336, 0x00000000129da970 in kgxExclusive ()
     (1-1) ---> kgxExclusive Mutex addr (rsi): a70a01a8
Breakpoint 146, 0x00000000126e5fd0 in kqrGetPOMutex ()
Breakpoint 336, 0x00000000129da970 in kgxExclusive ()
     (1-2) ---> kgxExclusive Mutex addr (rsi): 8d7bc960
Breakpoint 137, 0x00000000126e38c0 in kqrIncarnationMismatch ()
Breakpoint 132, 0x00000000126e2170 in kqrCacheHit ()
Breakpoint 338, 0x00000000126e2980 in kqrmpin ()
     (1) kqrmpin v$rowcache_parent.address (rdi): addr=8d7bc858 cid=15
Breakpoint 131, 0x00000000126e1fa0 in kqrFreeHashMutex ()
Breakpoint 337, 0x00000000129db980 in kgxRelease ()
     (1-1) <--- kgxRelease Mutex addr (*rsi): a70a01a8
Breakpoint 127, 0x00000000126dfd30 in kqrLockPo ()
Breakpoint 128, 0x00000000126e0180 in kqrAllocateEnqueue ()
Breakpoint 129, 0x00000000126e0790 in kqrget ()
Breakpoint 137, 0x00000000126e38c0 in kqrIncarnationMismatch ()
Breakpoint 137, 0x00000000126e38c0 in kqrIncarnationMismatch ()
Breakpoint 126, 0x00000000126dfc40 in kqrFreePOMutex ()
Breakpoint 337, 0x00000000129db980 in kgxRelease ()
     (1-2) <--- kgxRelease Mutex addr (*rsi): 8d7bc960
Breakpoint 139, 0x00000000126e3980 in kqrprl ()
Breakpoint 140, 0x00000000126e3ed0 in kqreqd ()
Breakpoint 146, 0x00000000126e5fd0 in kqrGetPOMutex ()
Breakpoint 336, 0x00000000129da970 in kgxExclusive ()
     (1-3) ---> kgxExclusive Mutex addr (rsi): 8d7bc960
Breakpoint 141, 0x00000000126e4d40 in kqrReleaseLock ()
Breakpoint 143, 0x00000000126e5910 in kqrmupin ()
Breakpoint 142, 0x00000000126e4ff0 in kqrpspr ()
Breakpoint 337, 0x00000000129db980 in kgxRelease ()
     (1-3) <--- kgxRelease Mutex addr (*rsi): 8d7bc960
Breakpoint 144, 0x00000000126e5e30 in kqrFreeEnqueue ()

6. Discussions

1. gdb output mutex-test2.log contains 95 kqrpre1 Calls, each for one 'dc_props' / 'dc_cdbprops' object
   (total 85+6=91, 4 are fetched twice).
   
   
2. For each row cache access, first compute a hash value (hash=819e131) and then access object (addr=8d7bc858).
   
   
3. Each RowCache Object Get triggers three kgxExclusive Mutex Gets,
   one from kqrGetHashMutexInt (Mutex addr (rsi): a70a01a8),
   two from kqrGetPOMutex (Mutex addr (rsi): 8d7bc960).
   
   
4. Mutex a70a01a8 is used in kqrGetHashMutexInt to protect hash BUCKET, hence BUCKET mutex.
   In above example, BUCKET 50 contains 4 row cache objects, so there are 4 occurrences in mutex-test2.log.
   
   Mutex 8d7bc960 is used in kqrGetPOMutex to protect individual row cache object, hence OBJECT mutex.
   So each row cache object has its own mutex.
   
   
5. kqrGetHashMutexInt Mutex is released after first kqrGetPOMutex Get (interleaved).
   So at certain instant, one session can hold two Mutexes at the same time (same as latch).
   
   For latch, there is MOS Note: ORA-600 [504] "Trying to obtain a latch which is already held" (Doc ID 28104.1), which said:
   "This ORA-600 triggers when a latch request violates the ordering rules for obtaining latches and granting the latch would potentially result in a deadlock." (See Blog: ORA-600 [504] LATCH HIERARCHY ERROR Deadlock)
   
   For Mutex, it is not clear if there could exist such similar deadlock.
   
   
6. The first Mutex Get is from kqrGetHashMutexInt, called by kqrpre, and released only after the second Mutex Get (the first of kqrGetPOMutex mutex Get). So kqrpre can hold two Mutexes and keep the first Mutex longer (till kqrFreeHashMutex).
   
   kqreqd makes one Mutex Get.
   
   In case of Latch (Oracle 12c), there are three Latch Gets with 3 different Locations:
   (see Blog: Oracle row cache objects Event: 10222, Dtrace Scripts (I) )

          Where=>4441(0x1159): kqrpre: find obj -> kslgetl()  -- latch Get at 1st Location
          Where=>4464(0x1170): kqreqd           -> kslgetl()  -- latch Get at 2nd Location
          Where=>4465(0x1171): kqreqd: reget    -> kslgetl()  -- latch Get at 3rd Location
   

   They are probably mapped to three kgxExclusive Mutex Gets as discussed in above Point (c).
   
   
7. If one session, which held a mutex, but abnormally terminated, CLMN wrote a log about its cleanup and recovery of the mutex (0xa70a01a8).

          KGX cleanup...
          KGX Atomic Operation Log 0x928ad480
           Mutex 0xa70a01a8(14, 0) idn f00003c oper EXCL(6)
           Row Cache uid 14 efd 6 whr 19 slp 0
           oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
           pt4=(nil) pt5=(nil) ub4=15 flg=0x8
          KQR UOL Recovery lc 928ad480 options = 1
   

7. kqrMutexLocations[] array

For all kqrMutexLocations in kqr.c, we can try to list them with following command. They often appear in AWR section "Mutex Sleep Summary" for Mutex Type: "Row Cache" (or V$MUTEX_SLEEP / V$MUTEX_SLEEP_HISTORY.location).

   
// uname -srm 
//      Linux 3.10.0-957.5.1.el7.x86_64 x86_64  cast (uint64_t *) optional
//      Linux 4.18.0-372.9.1.el8.x86_64 x86_64  requires cast (uint64_t *)
#Define Command to kqrMutexLocations      
define PrintkqrMutexLocations
  set $i = 0
  while $i < $arg0
    x /s *((uint64_t *)&kqrMutexLocations + $i)
    set $i = $i + 1
  end
end

(gdb) PrintkqrMutexLocations 51
0x14c21f40:     "[01] kqrHashTableInsert"
0x14c21f58:     "[02] kqrHashTableRemove"
0x14c21f70:     "[03] kqrUpdateHashTable"
0x14c21f88:     "[04] kqrshu"
0x14c21f94:     "[05] kqrWaitForObjectLoad"
0x14c21fb0:     "[06] kqrGetClusterLock"
0x14c21fc8:     "[07] kqrBackgroundInvalidate"
0x14c21fe8:     "[08] kqrget"
0x14c21ff4:     "[09] kqrReleaseLock"
0x14c22008:     "[10] kqreqd"
0x14c22014:     "[11] kqrfpo"
0x14c22020:     "[12] kqrpad"
0x14c2202c:     "[13] kqrsad"
0x14c22038:     "[14] kqrScan"
0x14c22048:     "[15] kqrCacheHit"
0x14c2205c:     "[16] kqrReadFromDB"
0x14c22070:     "[17] kqrCreateUsingSecondaryKey"
0x14c22090:     "[18] kqrCreateNewVersion"
0x14c220ac:     "[19] kqrpre"
0x14c220b8:     "[20] kqrpla"
0x14c220c4:     "[21] kqrpScanAndInvalidateLocal"
0x14c220e4:     "[22] kqrpScan"
0x14c220f4:     "[23] kqrpsiv"
0x14c22104:     "[24] kqrpsci"
0x14c22114:     "[25] kqrpup"
0x14c22120:     "[26] kqrpfu"
0x14c2212c:     "[27] kqrpdl"
0x14c22138:     "[28] kqrLocalInvalidateByHash"
0x14c22158:     "[29] kqrpiv"
0x14c22164:     "[30] kqrpsf"
0x14c22170:     "[31] kqrcmt"
0x14c2217c:     "[32] kqrsfd"
0x14c22188:     "[33] kqrsrd"
0x14c22194:     "[34] kqrssc"
0x14c221a0:     "[35] kqrisi"
0x14c221ac:     "[36] kqrsup"
0x14c221b8:     "[37] kqrsfu"
0x14c221c4:     "[38] kqrsdl"
0x14c221d0:     "[39] kqrsiv"
0x14c221dc:     "[40] kqrfrpo"
0x14c221ec:     "[41] kqrfrso"
0x14c221fc:     "[42] kqrdfc"
0x14c22208:     "[43] kqrlfc"
0x14c22214:     "[44] kqrdpc"
0x14c22220:     "[45] kqrdhst"
0x14c22230:     "[46] kqrMutexCleanup"
0x14c22248:     "[47] kqrftr"
0x14c22254:     "[48] kqrhngc"
0x14c22264:     "[49] kqrcic"
0x14c22270:     "[50] kqrpspr"
0x14c22280:     "[51] kqrglblkrs"

8. gdb script: gdb_cmd_script2

Before running the script, the breakpoint number and address have to be adjusted.

### ----================ gdb script: gdb -x gdb_cmd_script2 -p 18158 ================----
set pagination off
set logging file /temp/mutex-test2.log
set logging overwrite on
set logging on
set $k = 0
set $g = 0
set $r = 0
set $spacex = ' '

rbreak ^kqr.*
rbreak ^kgx.*

command 1-333                               
continue
end

#kqrmpin 
delete 133 
#kqrpre1   
delete 138 
#kgxExclusive   
delete 326 
#kgxRelease                               
delete 331   

#10222 trc pso, processstate dump SOC (State Object Call): $r8
break *kqrpre1
command 
printf "<<<==================== (%i) kqrpre1 pso (SOC): %x ====================>>>\n", ++$k, $r8
set $g = 0 
set $r = 0              
continue
end

#kqrhsh+109 retq, output hash value in "oradebug dump row_cache 0xf2b" (0xf2b is for "dc_props") 
break *0x00000000126df8ad     
command
printf "%5c(%i) kqrhsh retq hash (rax): hash=%x\n", $spacex, $k, $rax 
continue
end

break *kgxExclusive
command 
printf "%5c(%i-%i) ---> kgxExclusive Mutex addr (rsi): %x\n", $spacex, $k, ++$g, $rsi             
continue
end

break *kgxRelease
command
printf "%5c(%i-%i) <--- kgxRelease Mutex addr (*rsi): %x\n", $spacex, $k, ++$r, *((int *)$rsi)   
continue
end

#output v$rowcache_parent.address for row cache object
break *kqrmpin     
command
printf "%5c(%i) kqrmpin v$rowcache_parent.address (rdi): addr=%x cid=%i\n", $spacex, $k, $rdi, $r11
continue
end