Blog List

• January 2026 (1)
  
  1. "Disk file operations I/O" with (FileOperation: 8, fileno: 0, filetype: 8) Test
• December 2025 (1)
  
  1. Three Oracle cursor error Tests
• September 2025 (3)
  
  1. ORA-06502: NULL index table key value and plsql_optimize_level
  2. "ORA-00001: unique constraint violated" Debugging
  3. Oracle Database Stuck on DB Writer Wait Event: "oradebug request completion"
• August 2025 (1)
  
  1. Reading CLOB Line by Line with SQL and Plsql: ChatGPT and Gemini Implementations
• July 2025 (3)
  
  1. Reading CLOB Line by Line with SQL and Plsql
  2. "library cache: bucket mutex X" on V$ Fixed Views: Case Test
  3. Oracle dbms_hprof: Uncatchable Time in PL/SQL Nested Program Units
• June 2025 (1)
  
  1. ORA-01002: fetch out of sequence: One Case Test
• May 2025 (1)
  
  1. Oracle ORA-00600 [pfrsfm: stack mismatch] and [pfrsfm: stack mismatch] Reproducing
• February 2025 (1)
  
  1. One Oracle CLOB Space Usage Test
• November 2024 (1)
  
  1. Oracle Self-tune checkpointing lag of log switch
• October 2024 (1)
  
  1. Find the skipped rows in select for update skip locked
• September 2024 (1)
  
  1. One OracleJVM TIME_MODEL Test
• April 2024 (3)
  
  1. Oracle AQ Dequeue 'KTC latch subh' Memory Leak and Dequeue Long Running Test
  2. One Test of Oracle Object Collection MEMBER OF Function
  3. In Memoriam of Prof. Niklaus Wirth: One Email on Program Debugging
• January 2024 (1)
  
  1. One Test on the Different Errors of Oracle Global Temporary Tables vs. Private Temporary Tables
• October 2023 (1)
  
  1. ORA-28268: Exceeded the maximum allowed size for Context information in a session
• September 2023 (3)
  
  1. Oracle Index Root Modification CBC Latch Contention: Workaround Studies
  2. Oracle 19.18 Wait Event 'latch: cache buffers chains' P3: block number
  3. Oracle Index Range Scan with LIKE Condition on Wildcard '_'
• August 2023 (1)
  
  1. Oracle SYS_GUID Composition
• June 2023 (1)
  
  1. One Deadlock of 'row cache lock' and 'library cache lock'
• April 2023 (3)
  
  1. Oracle Multi-Consumer AQ dequeue with dbms_aq.listen Wait Events (I)
  2. Oracle Multi-Consumer AQ dequeue with dbms_aq.listen Performance Model (II)
  3. Oracle Multi-Consumer AQ dequeue with dbms_aq.listen Performance Analysis and Workaround (III)
• March 2023 (2)
  
  1. One Test of Oracle JSON Plsql PGA Memory Leak
  2. One Test of ORA-00600: [KGL-heap-size-exceeded] With AQ Subscriber
• February 2023 (1)
  
  1. Oracle Scalar Subquery Caching and Non-deterministic Functions
• January 2023 (1)
  
  1. Oracle dbms_crypto.randombytes and Enhancement Suggestion
• December 2022 (2)
  
  1. OracleJVM JAVA_JIT_ENABLED Linux /dev/shm mount noexec EPERM and Performance
  2. One Test of Oracle too many parse errors with ORA-12850 and ORA-12872
• October 2022 (2)
  
  1. How many times SYSDATE is called in SQL and Plsql ?
  2. Oracle WITH subquery_factoring_clause TEMP TABLE TRANSFORMATION and log file sync
• September 2022 (2)
  
  1. Update Restart and Undo Extends
  2. Proposal for ORA-04030 incident/trace files Enhancement to list Plsql package Memory Usage
• August 2022 (2)
  
  1. Oracle Global Temporary Table ORA-01555 and Undo Retention
  2. Oracle Global Temporary Table ORA-01555 and XML Data Size
• July 2022 (1)
  
  1. Plsql ORA-00600 by JDBC Call Exception Catch
• June 2022 (1)
  
  1. Tests of Oracle ORA-01866: the datetime class is invalid
• May 2022 (2)
  
  1. How volatile is ORA-00600 [qernsRowP] ?
  2. One Case of ORA-00036: Maximum Number Of Recursive SQL Levels (50) Exceeded
• April 2022 (2)
  
  1. Oracle Write Consistency and ORA-30926: "unable to get a stable set of rows in the source tables"
  2. Oracle Write Consistency and ORA-00600: [13030], [20]
• March 2022 (1)
  
  1. Index Skip Scan With First Column of Composite Index Specified
• February 2022 (2)
  
  1. Oracle Kill Session Crashes DB Instance
  2. How to determine session's CURRVAL of an oracle sequence without error and without modify ?
• January 2022 (1)
  
  1. Oracle SQL Monitoring Shared Pool "keomg: entry list " Memory Leak
• December 2021 (1)
  
  1. How to count the inserts and updates from merge ?
• November 2021 (1)
  
  1. Oracle dbms_aq.dequeue_array Shared Pool "KTC Latch Subh" Memory Leak
• October 2021 (2)
  
  1. Oracle Temp Space Usage Monitoring and View v$tempseg_usage
  2. Oracle sessiontimezone Format Changed After Calling dbms_scheduler/dbms_job Subprograms
• July 2021 (1)
  
  1. Oracle Program and Table dc_objects "row cache lock"
• June 2021 (1)
  
  1. Oracle dbms_alert and its Wait Events
• May 2021 (1)
  
  1. Oracle 19c new shared pool "SO private sga" and "SO private so latch" Performance Impacts
• April 2021 (3)
  
  1. Oracle PLITBLM "library cache: mutex X"
  2. The Third Test of ORA-04025: maximum allowed library object lock
  3. Oracle forall DML save exceptions and ORA-04030: out of process memory (callheap,psdalf:RPI allocations)
• March 2021 (2)
  
  1. Oracle Temp File Read Time Stats Problem
  2. Oracle deallocate_unused_clause and its effect
• January 2021 (1)
  
  1. DBMS_SCHEDULER Job Not Running and Used Slaves
• November 2020 (3)
  
  1. OracleJVM integer Array Size Limit and Out of Memory Error
  2. Oracle LOB Chunksize and Buffersize
  3. One case of dbms_alert.signal deadlock
• September 2020 (1)
  
  1. The Second Test of ORA-600 [4156] Rolling Back To Savepoint
• August 2020 (1)
  
  1. Row Cache Object and Row Cache Mutex Case Study
• May 2020 (3)
  
  1. 12cR2 Index Usage Tracking Manual Flushing
  2. One "row cache lock" Test Case
  3. ORA-600 [504] LATCH HIERARCHY ERROR Deadlock
• April 2020 (3)
  
  1. Index Service ITL and Recursive Transaction
  2. Index Block Split Point Distribution
  3. Cache Buffer Chains Latch Contention Case Study-3: index root block Modification Blocking
• February 2020 (2)
  
  1. Cache Buffer Chains Latch Contention Case Study-2: Reverse Primary Key Index
  2. Cache Buffer Chains Latch Contention Case Study-1: Reverse Key Index
• January 2020 (1)
  
  1. Oracle Unique Index Non-Consistency Read with RowCR
• December 2019 (2)
  
  1. Oracle Database and Java Datetime Conversion Differences across Daylight Saving Time (DST)
  2. Oracle 19.4 OracleJVM JAVA_JIT_ENABLED Not Working on AIX
• August 2019 (2)
  
  1. Oracle 18 New Wait Event: 'index (re)build lock or pin object'
  2. PDML Disabled on Nonpartitioned IOT
• April 2019 (1)
  
  1. LOB ORA-22924: snapshot too old and Fix
• November 2018 (5)
  
  1. Oracle row cache objects Event: 10222, Dtrace Script (I)
  2. Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)
  3. Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-2) (III)
  4. Row Cache and Sql Executions (IV)
  5. Latch: row cache objects Contentions and Scalability (V)
• October 2018 (2)
  
  1. Oracle ROWCACHE Views and Contents
  2. Result Cache: RC Enqueue and Contention (V)
• July 2018 (3)
  
  1. row cache mutex in Oracle 12.2.0.1.0
  2. plshprof command-line utility in Oracle 12.2.0.1.0
  3. 12c Online Statistics Gathering for Direct Path Insert and 3 Side Effects
• April 2018 (1)
  
  1. TM Lock and No Transaction Commit, TX & TM Locks and No Transaction Visible
• March 2018 (2)
  
  1. 'enq: RO - fast object reuse' and 'enq: KO - fast object checkpoint' Final Blocker
  2. Oracle 12.1 Wait Event: 'log file sync: SCN ordering' Demo
• February 2018 (1)
  
  1. SYS.LOADER_DIR_OBJS Query: Privileges and Performance
• January 2018 (4)
  
  1. Oracle Logical Read: Current Gets Access Path and Cost
  2. Oracle Logical Read: Consistent Gets Access Path and Cost
  3. Oracle Physical Read Access Path and Cost
  4. Oracle Latch Misses, Spin_gets, Sleeps and Recurrent_Misses
• October 2017 (2)
  
  1. ORA-04025 library object lock on DATABASE Truncate Triggers
  2. Result Cache: 0 rows updated Invalidations (IV)
• September 2017 (2)
  
  1. Result Cache: RC Latch Contention and PL/SQL Exception Handler (III)
  2. Result Cache: RC Latch Contention and RESULT_CACHE_MAX_SIZE(II)
• July 2017 (3)
  
  1. nls_database_parameters, dc_props, latch: row cache objects
  2. v$database select and control file sequential read
  3. Getting Oracle Transaction Commit SCN
• May 2017 (8)
  
  1. JDBC, Oracle object/collection, dbms_pickler, NOPARALLEL sys.type$ query
  2. PLSQL Context Switch Functions and Cost
  
  
  3. Oracle Datetime (1) - Concepts
  4. Oracle Datetime (2) - Examples
  5. Oracle Datetime (3) - Assignments
  6. Oracle Datetime (4) - Comparisons
  7. Oracle Datetime (5) - SQL Arithmetic
  8. Oracle Datetime (6) - PLSQL Arithmetic
• March 2017 (3)
  
  1. Oracle 12c PL/SQL Function in the WITH Clause: wrong result
  2. Oracle abstract_lob Memory Leak
  3. PL/SQL Function Result Cache Invalidation (I)
• February 2017 (1)
  
  1. Oracle JVM Java OutOfMemoryError and lazy GC
• January 2017 (1)
  
  1. ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling
• November 2016 (1)
  
  1. "library cache: mutex X" and Application Context
• September 2016 (2)
  
  1. PL/SQL Multidimensional Collection Memory Usage and Performance
  1. dbms_session.get_package_memory_utilization and limitations
• August 2016 (1)
  
  1. ORA-04025 library object lock on AQ queue and SQL cursor
• June 2016 (1)
  
  1. SQL Parsing in serializable transaction throws ORA-08177: can't serialize access for this transaction
• May 2016 (1)
  
  1. Oracle Fixed Table Practice
• April 2016 (1)
  
  1. sql_id and idn to shared pool subpool
• February 2016 (1)
  
  1. Native Code Files: Ora-7445 [Ioc_pin_shared_executable_object()] Reproducing
• January 2016 (3)
  
  1. Performance of Oracle Object Collection Comparisons - Part2
  2. Performance of Oracle Object Collection Comparisons - Part1
  3. Foreign Keys and Library Cache Locks: Analysis
• December 2015 (1)
  
  1. Oracle bigfile tablespace pre-allocation and session blocking
• November 2015 (1)
  
  1. Oracle 12c single session "library cache lock (cycle)" deadlock
• September 2015 (2)
  
  1. SQL DML Exceptions, Rollbacks and PL/SQL Exception Handlers
  2. Limit PGA Memory Usage
• August 2015 (1)
  
  1. Latch _SPIN_COUNT: adaptive
• July 2015 (2)
  
  1. Redo Practice
  2. UNDO Practice
• June 2015 (1)
  
  1. Temporary LOB Memory Allocation and Freeing in JAVA
• April 2015 (2)
  
  1. IBM AIX POWER7 CPU Usage and Throughput
  2. Oracle 11.2.0.4.0 AWR "Tablespace IO Stats" Column Names Shifted
• January 2015 (1)
  
  1. open_cursors, session_cached_cursors: cursordump
• December 2014 (1)
  
  1. Local prefixed vs. nonprefixed indexes: Column Null Values
• November 2014 (2)
  
  1. reverse key index: the remedy is worse than the symptoms
  2. Low High Water Mark, High High Water Mark, and Parallel Query
• May 2014 (3)
  
  1. Oracle 11g AUTO_SAMPLE_SIZE performance on Small Tables
  2. java stored procedure calls and latch: row cache objects, and performance
  3. java stored procedure calls and latch: row cache objects
• March 2014 (2)
  
  1. dbms_aq.dequeue - latch: row cache objects on AIX
  2. Hot Block Identification and latch: cache buffers chains
• November 2013 (3)
  
  1. Remove Stale Native Code Files on AIX
  2. PGA, SGA memory usage watching from UNIX
  3. ORA-04030 incident file and alert.log
• September 2013 (1)
  
  1. Execution Switching between "direct path read" and "db file scattered read"
• June 2013 (2)
  
  1. Oracle PL/SQL Collection Memory Reclaim 
  2. dbms_alert lock hash collision
• April 2013 (2)
  
  1. cursor: pin S wait on X
  2. Shared Pool - Free Memory, Fragmentation ?
• March 2013 (3)
  
  1. Shared Pool - SQLA and KGLH0
  2. Shared Pool - Memory Allocation - unbalanced
  3. Shared Pool - KKSSP
• December 2012 (1)
  
  1. Delete Restart and new Active Undo Extent
• November 2012 (2)
  
  1. One Oracle AQ Deadlock
  2. Oracle Java OutOfMemoryError
• July 2012 (1)
  
  1. One Mutex Collision Test
• May 2012 (1)
  
  1. Why shared pool is doubled ?
• April 2012 (1)
  
  1. High system time utilization on fast machine
• February 2012 (1)
  
  1. Is latch misses statistic gathered or deduced ?
• November 2011 (2)
  
  1. One Oracle 12g Pre-announce of bug fix in dbms_debug_jdwp
  2. Oracle 11gR2 single session "library cache pin"
• July 2011 (1)
  
  1. Redo/Undo explosion from thick declared table insert
• May 2011 (3)
  
  1. ORA-04027: self-deadlock during automatic validation
  2. Foreign Key on Nested Table
  3. Update Restart and new Active Undo Extent
• April 2011 (1)
  
  1. dbms_session package_memory_utilization

"Disk file operations I/O" with (FileOperation: 8, fileno: 0, filetype: 8) Test

In this blog, we will make a test to demonstrate Oracle Wait Event "Disk file operations I/O" with
(P1/FileOperation: 8, P2/fileno: 0, P3/filetype: 8).

Note: Tested in Oracle 19.27

1. Test Setup

The database auditing is configured as follows:

NAME                      TYPE        VALUE
------------------------- ----------- --------------------------------
audit_file_dest           string      /home/oracle/suk/slow_dir3/adump
audit_sys_operations      boolean     TRUE
audit_trail               string      OS

audit_file_dest is mounted on a slow file system with 5000 ms read/write delay.
(See Blog: Oracle Database Stuck on DB Writer Wait Event: "oradebug request completion" ).

2. Wait Event Tracing

2.1 10046 Trace

We start system-wide 10046 trace by:

alter system set events '10046 trace name context forever, level 12';  

2.2 strace

Find TNS listener process and strace it:

oracle@db3audit:db3audit > ps -efl |grep tns
  0 S oracle    728055       1  0  80   0 - 40462 do_epo Sep27 ?        00:00:15 /orabin/app/oracle/product/19.27.0.0./bin/tnslsnr LISTENER_oradb3audit             

oracle@db3audit:db3audit >  strace -ttTfy -p 728055 -o strace_output_2.txt

2.3 Sqlplus Session

Now we open a Sqlplus session by

SQL > sqlplus k/k@db3audit

2.4 10046 Trace Output

Trace file /orabin/app/oracle/admin/db3audit/diag/rdbms/db3audit/db3audit/trace/db3audit_ora_1072963.trc
Build label:    RDBMS_19.27.0.0.0DBRU_LINUX.X64_250331
Oracle process number: 57
Unix process pid: 1072963, image: oracle@db3audit
*** MODULE NAME:(sqlplus.exe) 2025-12-23T10:11:56.689481+01:00

*** 2025-12-23T10:12:01.847101+01:00
WAIT #0: nam='Disk file operations I/O' ela= 5100597 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=18667193313139

It shows "ela= 5100597" microseconds with "FileOperation=8 fileno=0 filetype=8".
So we can say that in this case, "FileOperation=8" is file open, and "filetype=8" is OS Audit file.

After test, stop 10046 trace by (otherwise too many trace files):

  alter system set events '10046 trace name context off';

2.5 strace Output

We can see that Sqlplus Process 1072963 was spawned by TNS Process 728055:

oracle@db3audit:db3audit > strace -ttTfy -p 728055 -o strace_output_3.txt
./strace: Process 728055 attached
./strace: Process 1072962 attached
./strace: Process 1072963 attached

Open strace_output_2.txt, it shows:

1072963 10:11:56.746551 openat(AT_FDCWD, "/home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud", O_RDWR|O_CREAT|O_EXCL, 0640) = 10
                                 <5.098572>
1072963 10:12:01.845204 write(10, "Audit file ", 11) = 11 <0.000058>
1072963 10:12:01.845315 write(10, "/home/oracle/suk/slow_dir3/adump"..., 84) = 84 <0.000023>
1072963 10:12:01.845372 write(10, "\n", 1) = 1 <0.000022>
1072963 10:12:01.845433 write(10, "Oracle Database 19c Enterprise E"..., 90) = 90 <0.000021>
1072963 10:12:01.845482 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.845533 write(10, "Build label:    RDBMS_19.27.0.0."..., 54) = 54 <0.000020>
1072963 10:12:01.845582 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.845639 write(10, "ORACLE_HOME:    /orabin/app/orac"..., 64) = 64 <0.000020>
1072963 10:12:01.845689 write(10, "System name:\tLinux\n", 19) = 19 <0.000020>
1072963 10:12:01.845738 write(10, "Node name:\tdb3audit\n", 20) = 20 <0.000021>
1072963 10:12:01.845796 write(10, "Release:\t4.18.0-372.9.1.el8.x86_"..., 35) = 35 <0.000020>
1072963 10:12:01.845845 write(10, "Version:\t#1 SMP Fri Apr 15 22:12"..., 45) = 45 <0.000021>
1072963 10:12:01.845895 write(10, "Machine:\tx86_64\n", 16) = 16 <0.000021>
1072963 10:12:01.845953 write(10, "CLID:\tP\n", 8) = 8 <0.000021>
1072963 10:12:01.846010 write(10, "Instance name: db3audit\n", 24) = 24 <0.000062>
1072963 10:12:01.846105 write(10, "Instance number: 1\n", 19) = 19 <0.000020>
1072963 10:12:01.846161 write(10, "Database name: db3audit ", 24) = 24 <0.000023>
1072963 10:12:01.846215 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846264 write(10, "Database unique name: db3audit ", 31) = 31 <0.000020>
1072963 10:12:01.846313 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846388 write(10, "Database id: 1059538969\n", 24) = 24 <0.000021>
1072963 10:12:01.846442 write(10, "Database role: PRIMARY\n", 23) = 23 <0.000020>
1072963 10:12:01.846491 write(10, "Redo thread mounted by this inst"..., 40) = 40 <0.000020>
1072963 10:12:01.846541 write(10, "Oracle process number: 57\n", 26) = 26 <0.000021>
1072963 10:12:01.846592 write(10, "Unix process pid: 1072963, image"..., 49) = 49 <0.000019>
1072963 10:12:01.846640 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846689 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846762 write(10, "Tue Dec 23 10:12:01 2025 +01:00\n", 32) = 32 <0.000021>
1072963 10:12:01.846812 write(10, "LENGTH: \"408\"", 13) = 13 <0.000021>
1072963 10:12:01.846860 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.846909 write(10, "SESSIONID:[9] \"102147891\" ENTRYI"..., 406) = 406 <0.000030>
1072963 10:12:01.846973 write(10, "\n", 1) = 1 <0.000020>
1072963 10:12:01.847023 write(10, "\n", 1) = 1 <0.000021>

The above output shows that openat "/home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud" returns FD = 10,
and it takes 5.098572 seconds from 10:11:56 to 10:12:01.

Look OS audit file, its name is composed by DB SID: db3audit, Unix process pid: 1072963, and creating timestamp: 20251223101156, which is 2025-12-23 10:11:56.
In the OS audit file, the first timestamp "10:12:01" is recorded for session LOGON, which has about 5 seconds delay (from 10:11:56 to 10:12:01),
and the second timestamp "10:28:44" is for session LOGOFF. Here the full audit file:

oracle@db3audit:db3audit > cat /home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud
Audit file /home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.27.0.0.0
Build label:    RDBMS_19.27.0.0.0DBRU_LINUX.X64_250331
ORACLE_HOME:    /orabin/app/oracle/product/19.27.0.0.
System name:	Linux
Node name:	db3audit
Release:	4.18.0-372.9.1.el8.x86_64
Version:	#1 SMP Fri Apr 15 22:12:19 EDT 2022
Machine:	x86_64
CLID:	P
Instance name: db3audit
Instance number: 1
Database name: db3audit 
Database unique name: db3audit 
Database id: 1059538969
Database role: PRIMARY
Redo thread mounted by this instance: 1
Oracle process number: 57
Unix process pid: 1072963, image: oracle@db3audit

Tue Dec 23 10:12:01 2025 +01:00
LENGTH: "408"
SESSIONID:[9] "102147891" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[1] "K" USERHOST:[16] "SYS\MACHINE12345" TERMINAL:[12] "MACHINE12345" ACTION:[3] "100" RETURNCODE:[1] "0" COMMENT$TEXT:[126] "Authenticated by: DATABASE;AUTHENTICATED IDENTITY: K; Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=10.44.105.100)(PORT=50160))" OS$USERID:[7] "KS00383" DBID:[10] "1059538969" PRIV$USED:[1] "5" CURRENT_USER:[1] "K"

Thu Dec 23 10:28:44 2025 +01:00
LENGTH: "231"
SESSIONID:[9] "102147891" ENTRYID:[1] "1" USERID:[1] "K" ACTION:[3] "101" RETURNCODE:[1] "0" LOGOFF$PREAD:[5] "35037" LOGOFF$LREAD:[6] "166495" LOGOFF$LWRITE:[1] "4" LOGOFF$DEAD:[1] "0" DBID:[10] "1059538969" SESSIONCPU:[3] "258"

Here the process lsof output showing FD 10u for audit file:

oracle@db3audit:db3audit > lsof -p 1072963 |grep aud
  COMMAND       PID   USER   FD      TYPE             DEVICE    SIZE/OFF       NODE NAME
  oracle_10 1072963 oracle   10u      REG             253,2         1167         77 /home/oracle/suk/slow_dir3/adump/db3audit_ora_1072963_20251223101156746537740094.aud

2.6 v$active_session_history and Oracle Performance Views

select sample_time, program, event, p1, p2, p3, p1text, p2text, p3text
  from v$active_session_history t 
 where event = 'Disk file operations I/O' and p1=8 and p2=0 and p3=8 
   and sample_time >= timestamp '2025-12-28 10:31:22.549'
 order by t.sample_time;
 
 
  SAMPLE_TIME         PROGRAM      EVENT                     P1  P2  P3  P1TEXT         P2TEXT  P3TEXT
  ------------------- ------------ ------------------------ --- --- --- --------------- ------- --------
  2025-12-22 10:11:57 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype
  2025-12-22 10:11:58 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype
  2025-12-22 10:11:59 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype
  2025-12-22 10:12:00 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype
  2025-12-22 10:12:01 sqlplus.exe  Disk file operations I/O   8   0   8  FileOperation  fileno  filetype


select filetype_id, filetype_name, function_id, function_name, sum(small_read_reqs), sum(small_write_reqs), sum(number_of_waits), sum(wait_time) 
from  v$iostat_function_detail 
where filetype_id = 8
group by filetype_id, filetype_name, function_id, function_name
order by filetype_id, function_id;

  FILETYPE_ID FILETYPE FUNCTION_ID FUNCTION_NAME        SUM(SMALL_READ_REQS) SUM(SMALL_WRITE_REQS) SUM(NUMBER_OF_WAITS) SUM(WAIT_TIME)
  ----------- -------- ----------- -------------------- -------------------- --------------------- -------------------- --------------
            8 Other              2 LGWR                                    0                     0               136398          50459
            8 Other              7 Recovery                                0                     0                    1              0
            8 Other              8 Buffer Cache Reads                      0                     0                  245            283
            8 Other             13 Others                                  0                     0               273272         120046


-- also in v$session_event, dba_hist_system_event
select event, total_waits, time_waited, time_waited_micro, event_id, wait_class_id, wait_class#, wait_class from v$system_event 
 where event = 'Disk file operations I/O';

  EVENT                     TOTAL_WAITS TIME_WAITED TIME_WAITED_MICRO   EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
  ------------------------- ----------- ----------- ----------------- ---------- ------------- ----------- ----------
  Disk file operations I/O        67226       28853         288534923  166678035    1740759767           8 User I/O

-- no rows in v$iostat_file
select * from v$iostat_file where filetype_id = 8;
	no rows selected

2.7 AWR and ASH

TOP Wait Event "Disk file operations I/O" in AWR and ASH looks like:

Top 10 Foreground Events by Total Wait Time

Event	Waits	Total Wait Time (sec)	Avg Wait	% DB time	Wait Class
Disk file operations I/O	2,706	11.4	4.20ms	35.4	User I/O

Top Event P1/P2/P3 Values

Event	% Event	P1, P2, P3 Values	% Activity	Parameter 1	Parameter 2	Parameter 3
Disk file operations I/O	45.45	"8","0","8"	45.45	FileOperation	fileno	filetype

3. bpftrace

Start following bpftrace script and then open a Sqlplus session.

The script output shows file open (sys_enter_openat) "Duration (us): 5089844", and its Oracle CallStack.

BPFTRACE_STRLEN=128 bpftrace -e 'tracepoint:syscalls:sys_enter_openat /strncmp("oracle", comm, 6) == 0 && strncmp("/home/oracle/suk/slow_dir3", str(args->filename), 26) == 0 / {
               time("%H:%M:%S "); @start[tid] = nsecs;
               printf("comm: %s, pid: %d, tid: %d, __syscall_nr: %d, dfd: %d, flags: %d, mode: %d \n============== filename: %s =======\n", 
                       comm, pid, tid, args->__syscall_nr, args->dfd, args->flags, args->mode, str(args->filename)); }
             tracepoint:syscalls:sys_exit_openat  /strncmp("oracle", comm, 6) == 0 && @start[tid] / {
               time("%H:%M:%S "); @fd = (uint64)args->ret; $duration_us = ( nsecs - @start[tid] ) / 1000; 
               printf("===================== File Descriptor: %d, Duration (us): %d ===================== \n", @fd, $duration_us); 
               printf("CallStack: %s\n", ustack(30));
               delete(@start[tid]); }
             tracepoint:syscalls:sys_enter_write /strncmp("oracle", comm, 6) == 0 && @fd == args->fd / {
               time("%H:%M:%S "); $length = args->count; $line = str(args->buf);
               printf("[pid: %d, fd: %d, length: %3d] %s \n", pid, args->fd, $length, $line); }'

13:12:01 comm: oracle_1086521_, pid: 1086521, tid: 1086521, __syscall_nr: 257, dfd: -100, flags: 194, mode: 416
============== filename: /home/oracle/suk/slow_dir3/adump/db3audit_ora_1086521_20251228131201036719868850.aud =======
13:12:06 ===================== File Descriptor: 8, Duration (us): 5089844 =====================
CallStack:
        __open+79
        szaudinit+506
        szaud+1416
        szaud_mkrec+1774
        audios+2936
        audins+13805
        audlon0+1983
        audlon+526
        auddft_internal+2853
        audStatement+1168
        kpolnb+4729
        kpoauth+1917
        opiodr+1264
        ttcpip+1219
        opitsk+1925
        opiino+939
        opiodr+1264
        opidrv+1094
        sou2o+165
        opimai_real+422
        ssthrdmain+417
        main+256
        __libc_start_main+243
        0x5541f689495641d7
        
13:12:06 [pid: 1086521, fd: 8, length:  11] Audit file
13:12:06 [pid: 1086521, fd: 8, length:  84] /home/oracle/suk/slow_dir3/adump/db3audit_ora_1086521_20251228131201036719868850.aud
13:12:06 [pid: 1086521, fd: 8, length:  90] Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.27.0.0.0
......
13:12:06 [pid: 1086521, fd: 8, length: 406] SESSIONID:[9] "102148556" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[1] "K" USERHOST:[16] "SYS\MACHINE12345" TERMINAL:[12] "MACH

In above test, Audit Parameter: audit_syslog_level is not set, and audit files (and audit info) are created under directory audit_file_dest.
If we set "audit_syslog_level='LOCAL0.INFO'" and re-start DB, audit info is written into /var/log/messages (configured in /etc/rsyslog.conf).

alter system set audit_syslog_level='LOCAL0.INFO' scope=spfile;
--DB re-start

-- reset by alter system reset audit_syslog_level scope=spfile;

$ cat /etc/rsyslog.conf
 
  # Log anything (except mail) of level info or higher.
  # Don't log private authentication messages!
  *.info;mail.none;authpriv.none;cron.none                /var/log/messages

4. Related Work

Blog: Disk file operations I/O (July 17, 2024 Dinesh Bandelkar) shows one case of "Disk file operations I/O" with (FileOperation: 8, fileno: 0, filetype: 8) when Oracle Redaction is OS audited.

Blog: Disk file operations I/O (December 21, 2020) shows ASH snapper to monitor such wait event.

Three Oracle cursor error Tests

In this Blog, we will test 3 Oracle cursor errors:

  ORA-01001: invalid cursor
  ORA-06511: PL/SQL: cursor already open
  ORA-21780: Maximum number of object durations exceeded

Note: Tested in Oracle 19.28

1. Test Setup

drop table test_tab;

create table test_tab as select level id, 'Name_'||level name from dual connect by level <= 10;

create or replace package test_cursor_errors is
  cursor p_curs(p_id number) is select * from test_tab where id = p_id;
  p_ORA_21780_Maximum number := 0;
  procedure test_ORA_01001(p_id number, p_recur_depth number);
  procedure test_ORA_06511(p_id number);
  procedure test_ORA_21780(p_id number, p_recur_depth number);
end;
/

create or replace package body test_cursor_errors is
  procedure prt(p_recur_depth number, text varchar2) is
  begin
    dbms_output.put_line(rpad(chr(32), 4*p_recur_depth, chr(32))||text);
  end;
  
  --ORA-01001: invalid cursor
  procedure test_ORA_01001(p_id number, p_recur_depth number) is
    l_name varchar2(1000);
    l_chg  integer := 1;  
  begin
    prt(p_recur_depth, '1-1 Start --- p_id = '||p_id||', recur_depth = '||p_recur_depth||', curs%isopen = '||bool_to_char(p_curs%isopen));

    if p_curs%isopen then
      prt(p_recur_depth, '2-1 Close p_curs  --- p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
      close p_curs;   --Close previous Implicit Cursor
      prt(p_recur_depth, '2-2 p_curs Closed --- p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
    end if;
    
    for c in p_curs(p_id) loop
      l_name :=c.name;
      prt(p_recur_depth, '3-1 Recur Entry --- p_id = '||p_id||', Implicit Cursor Opened'||', curs%isopen = '||bool_to_char(p_curs%isopen));
      test_ORA_01001(p_id - l_chg, p_recur_depth + 1);
      prt(p_recur_depth, '3-2 Recur Exit  --- p_id = '||p_id||', Close  Implicit Cursor'||', curs%isopen = '||bool_to_char(p_curs%isopen));
    end loop;

    if p_curs%isopen then
      prt(p_recur_depth, '4-1 Close p_curs --- p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
      close p_curs;
      prt(p_recur_depth, '4-2 p_curs Closed  --- p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
    end if;
   
    prt(p_recur_depth, '1-2 End --- p_id = '||p_id||', recur_depth = '||p_recur_depth||', curs%isopen = '||bool_to_char(p_curs%isopen));
  end;

  --ORA-06511: PL/SQL: cursor already open
  procedure test_ORA_06511 (p_id number) is
    l_name varchar2(1000);
  begin
    for c in p_curs(p_id) loop
      dbms_output.put_line('1. Loop p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
      l_name :=c.name;
      for c in p_curs(p_id -1) loop
        dbms_output.put_line('2. Loop p_id = '||p_id||', curs%isopen = '||bool_to_char(p_curs%isopen));
        l_name :=c.name;
      end loop;
    end loop;
  end;
  
  --ORA-21780: Maximum number of object durations exceeded. ORA_21780_Maximum = 65325 (Oracle 19.28), ORA_21780_Maximum = 65318 (Oracle 19.10)
  procedure test_ORA_21780 (p_id number, p_recur_depth number) is
    l_name varchar2(1000);
    l_chg  integer := 0;  
  begin
    if p_curs%isopen then
      close p_curs;   --Close previous Implicit Cursor
    end if;
    
    for c in p_curs(p_id) loop
      begin
	      l_name := c.name;
	      p_ORA_21780_Maximum := greatest(p_ORA_21780_Maximum, p_recur_depth + 1);
	      test_ORA_21780(p_id - l_chg, p_recur_depth + 1);
	    end;
    end loop;

    if p_curs%isopen then
      close p_curs;
    end if;
  end;
end;
/

2. Test Run

exec test_cursor_errors.test_ORA_01001(2, 1);

exec test_cursor_errors.test_ORA_06511(2);

begin
  test_cursor_errors.p_ORA_21780_Maximum := 0;
  test_cursor_errors.test_ORA_21780(2, 1);
  exception when others then
    dbms_output.put_line('ORA_21780_Maximum = '||test_cursor_errors.p_ORA_21780_Maximum);
    raise;
end;
/

3. Test Outcome

3.1. ORA-01001: invalid cursor

Here the indentation print of recursive calls:

SQL > exec test_cursor_errors.test_ORA_01001(2, 1);

    1-1 Start --- p_id = 2, recur_depth = 1, curs%isopen = false
    3-1 Recur Entry --- p_id = 2, Implicit Cursor Opened, curs%isopen = true
        1-1 Start --- p_id = 1, recur_depth = 2, curs%isopen = true
        2-1 Close p_curs  --- p_id = 1, curs%isopen = true
        2-2 p_curs Closed --- p_id = 1, curs%isopen = false
        3-1 Recur Entry --- p_id = 1, Implicit Cursor Opened, curs%isopen = true
            1-1 Start --- p_id = 0, recur_depth = 3, curs%isopen = true
            2-1 Close p_curs  --- p_id = 0, curs%isopen = true
            2-2 p_curs Closed --- p_id = 0, curs%isopen = false
            1-2 End --- p_id = 0, recur_depth = 3, curs%isopen = false
        3-2 Recur Exit  --- p_id = 1, Close  Implicit Cursor, curs%isopen = false
BEGIN test_cursor_errors.test_ORA_01001(2, 1); END;

*
ERROR at line 1:
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 20
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 20
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 20
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 20
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 23
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 23
ORA-06512: at line 1
Elapsed: 00:00:00.00

In Oracle. cursor for loop starts with one implicit cursor open and finishes with one implicit cursor close.
In above test, we have closed cursor in Step 2, and in Step 3-2 of cursor for loop Exit,
Oracle wants to close the implicit cursor again, and throws "ORA-01001: invalid cursor".
("invalid cursor" signifies error when closing an already closed cursor).

Here 10046 trace file with "err=1001" and 'SQL*Net break/reset to client':

alter session set events '10046 trace name context forever, level 12';  
exec test_cursor_errors.test_ORA_01001(2, 1);
alter session set events '10046 trace name context off';


=====================
PARSING IN CURSOR #140151808236992 len=52 dep=0 uid=49 oct=47 lid=49 tim=6880035008376 hv=4277818309 ad='9d4835d0' sqlid='7g4pxwzzgnny5'
BEGIN test_cursor_errors.test_ORA_01001(2, 1); END;

END OF STMT
PARSE #140151808236992:c=15,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6880035008375
=====================
PARSING IN CURSOR #140151808572984 len=38 dep=1 uid=49 oct=3 lid=49 tim=6880035009339 hv=1133886660 ad='77b15960' sqlid='c8b161d1tbg64'
SELECT * FROM TEST_TAB WHERE ID = :B1 
END OF STMT
PARSE #140151808572984:c=558,e=848,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=6880035009339
BINDS #140151808572984:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7f77a2c284c0  bln=22  avl=02  flg=05
  value=2
EXEC #140151808572984:c=932,e=1170,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880035010574
FETCH #140151808572984:c=65,e=65,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=3962208483,tim=6880035010672
STAT #140151808572984 id=1 cnt=1 pid=0 pos=1 obj=5983275 op='TABLE ACCESS FULL TEST_TAB (cr=3 pr=0 pw=0 str=1 time=58 us cost=3 size=315 card=3)'
CLOSE #140151808572984:c=0,e=0,dep=1,type=3,tim=6880035010802
BINDS #140151808572984:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7f77a2c284c0  bln=22  avl=02  flg=05
  value=1
EXEC #140151808572984:c=55,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880035010880
FETCH #140151808572984:c=18,e=18,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=3962208483,tim=6880035010927
CLOSE #140151808572984:c=0,e=0,dep=1,type=3,tim=6880035010963
BINDS #140151808572984:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7f77a2d11a98  bln=22  avl=01  flg=05
  value=0
EXEC #140151808572984:c=62,e=62,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880035011043
FETCH #140151808572984:c=13,e=13,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880035011068
CLOSE #140151808572984:c=0,e=0,dep=1,type=3,tim=6880035011100
EXEC #140151808236992:c=2237,e=2765,p=0,cr=10,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6880035011182
ERROR #140151808236992:err=1001 tim=6880035011196
WAIT #140151808236992: nam='SQL*Net break/reset to client' ela= 3 driver id=1413697536 break?=1 p3=0 obj#=528 tim=6880035011230
WAIT #140151808236992: nam='SQL*Net break/reset to client' ela= 5553 driver id=1413697536 break?=0 p3=0 obj#=528 tim=6880035016797
WAIT #140151808236992: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=528 tim=6880035016842
WAIT #140151808236992: nam='SQL*Net message from client' ela= 711 driver id=1413697536 #bytes=1 p3=0 obj#=528 tim=6880035017582

3.2 ORA-06511: PL/SQL: cursor already open

In this test, the same cursor opened twice, hence "ORA-06511: PL/SQL: cursor already open".

SQL > exec test_cursor_errors.test_ORA_06511(2);

1. Loop p_id = 2, curs%isopen = true
BEGIN test_cursor_errors.test_ORA_06511(2); END;

*
ERROR at line 1:
ORA-06511: PL/SQL: cursor already open
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 2
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 43
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 43
ORA-06512: at line 1

Here 10046 trace file with "err=6511" and 'SQL*Net break/reset to client':

alter session set events '10046 trace name context forever, level 12';  
exec test_cursor_errors.test_ORA_06511(2);
alter session set events '10046 trace name context off';


=====================
PARSING IN CURSOR #140498746628816 len=49 dep=0 uid=49 oct=47 lid=49 tim=6880557312015 hv=243630832 ad='72f8ab68' sqlid='1cu3xcc78b0rh'
BEGIN test_cursor_errors.test_ORA_06511(2); END;

END OF STMT
PARSE #140498746628816:c=50,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6880557312014
=====================
PARSING IN CURSOR #140498750073448 len=38 dep=1 uid=49 oct=3 lid=49 tim=6880557312222 hv=1133886660 ad='77b15960' sqlid='c8b161d1tbg64'
SELECT * FROM TEST_TAB WHERE ID = :B1 
END OF STMT
PARSE #140498750073448:c=77,e=77,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880557312222
BINDS #140498750073448:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fc869ff9388  bln=22  avl=02  flg=05
  value=2
EXEC #140498750073448:c=52,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3962208483,tim=6880557312308
FETCH #140498750073448:c=62,e=62,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=3962208483,tim=6880557312393
STAT #140498750073448 id=1 cnt=1 pid=0 pos=1 obj=5983275 op='TABLE ACCESS FULL TEST_TAB (cr=3 pr=0 pw=0 str=1 time=58 us cost=3 size=315 card=3)'
CLOSE #140498750073448:c=0,e=1,dep=1,type=3,tim=6880557312532
EXEC #140498746628816:c=512,e=513,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6880557312562
ERROR #140498746628816:err=6511 tim=6880557312573
WAIT #140498746628816: nam='SQL*Net break/reset to client' ela= 2 driver id=1413697536 break?=1 p3=0 obj#=528 tim=6880557312605
WAIT #140498746628816: nam='SQL*Net break/reset to client' ela= 696 driver id=1413697536 break?=0 p3=0 obj#=528 tim=6880557313324
WAIT #140498746628816: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=528 tim=6880557313347
WAIT #140498746628816: nam='SQL*Net message from client' ela= 5220 driver id=1413697536 #bytes=1 p3=0 obj#=528 tim=6880557318586

3.3 ORA-21780: Maximum number of object durations exceeded

In this test, we make an infinitive recursive calls, in each call, open the same cursor,
then hit "ORA-21780: Maximum number of object durations exceeded".
(The only difference of this test to "ORA-01001" code is that "l_chg = 0" instead of "l_chg = 1").

The test shows that the maximum value is around 65339.

SQL > begin
        test_cursor_errors.p_ORA_21780_Maximum := 0;
        test_cursor_errors.test_ORA_21780(2, 1);
        exception when others then
          dbms_output.put_line('ORA_21780_Maximum = '||test_cursor_errors.p_ORA_21780_Maximum);
          raise;
      end;
      /
            
ORA_21780_Maximum = 65339
begin
*
ERROR at line 1:
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-01001: invalid cursor
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 59
ORA-21780: Maximum number of object durations exceeded.
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 51
ORA-06512: at "K.TEST_CURSOR_ERRORS", line 63

Elapsed: 00:00:03.00

4. Pass Cursor as Integer Input

In one application, client program wants to receive cursor input represented by an integer.
Here is one implementation:

create or replace package test_cursor_number as 
  --p_recordset     sys_refcursor;  -- PLS-00994: Cursor Variables cannot be declared as part of a package
  function get_id_cur (p_id in test_tab.id%type) return integer;
end;
/

create or replace package body test_cursor_number as 
  function get_id_cur (p_id in test_tab.id%type) return integer as
    l_cursor_number   integer;
  begin
    l_cursor_number := dbms_sql.open_cursor;
    dbms_sql.parse (l_cursor_number, 'SELECT id, name from test_tab where id <= '||p_id, dbms_sql.NATIVE);
    return l_cursor_number;
  end;
end;
/

declare
  l_cursor_number   integer;
  l_return          integer;
  l_cursor          sys_refcursor;
  l_id              test_tab.id%type;
  l_name            test_tab.name%type;
begin
  l_cursor_number := test_cursor_number.get_id_cur(p_id => 3);
  dbms_output.put_line('cursor_number = '||l_cursor_number);
  
  l_return := dbms_sql.execute (l_cursor_number);
  dbms_output.put_line('execute return = '||l_return);
  
  l_cursor := dbms_sql.to_refcursor (l_cursor_number);
  --dbms_output.put_line('l_cursor = '||l_cursor);      
  loop
    fetch l_cursor
    into l_id, l_name;

    exit when l_cursor%notfound;
    dbms_output.PUT_LINE (l_id || ' | ' || l_name);
  end loop;

  close l_cursor;
end;
/

-- Test Output
cursor_number = 357706397
execute return = 0
1 | Name_1
2 | Name_2
3 | Name_3

By the way, Oracle Magazine On Connection Pools, Cursor Differentiation, and Optimal Ordering (By Tom Kyte May/June 2012) discussed the regular cursor vs. ref cursor, and showed the performance difference.

ORA-06502: NULL index table key value and plsql_optimize_level

In this Blog, we will show that the logically equivalent Plsql code can have different behaviour when toggling plsql_optimize_level.

Note: Tested in Oracle 19.27

1. plsql_optimize_level: 0 or 1

If we run all 4 tests below in Plsql code blocks with 0 or 1, they all throw the same error: ORA-06502: NULL index table key value.

alter session set plsql_optimize_level = 1;

--------- Test-1 ---------
declare
  type t is table of number index by binary_integer;
  v_t  t;
  i    pls_integer := null;
begin
  v_t(1) := 1;
  v_t(null) := v_t(1);
  dbms_output.put_line(v_t(null));
end;
/

--------- Test-2: error: NULL index table key value ---------
declare
  type t is table of number index by binary_integer;
  v_t  t;
  i    pls_integer := null;
begin
  v_t(1) := 1;
  v_t(i) := v_t(1);
  dbms_output.put_line(v_t(i));
end;
/

--------- Test-3 ---------
declare
  type t is table of number index by binary_integer;
  v_t  t;
  i    pls_integer := null;
begin
  if true then
    dbms_output.put_line(1);
  end if;
  v_t(1) := 1;
  v_t(null) := v_t(1);
  dbms_output.put_line(v_t(null));
end;
/

--------- Test-4: error: NULL index table key value ---------
declare
  type t is table of number index by binary_integer;
  v_t  t;
  i    pls_integer := null;
begin
  if v_t.exists(1) or not v_t.exists(1) then
    dbms_output.put_line(1);
  end if;
  v_t(1) := 1;
  v_t(null) := v_t(1);
  dbms_output.put_line(v_t(null));
end;
/

2. plsql_optimize_level: 2 or 3

When we run above 4 Plsql code blocks with plsql_optimize_level: 2 (Default value) or 3:

  alter session set plsql_optimize_level = 2;

we can see that Test-1 and Test-3 are OK, but Test-2 and Test-4 hit:

   ORA-06502: PL/SQL: numeric or value error: NULL index table key value

although Test-1 and Test-2 are logically equivalent, as well as Test-3 and Test-4.

3. PLSQ/SQL MCODE and DIANA Nodes

We tried to use PL/SQL event 10928, 10938 and dumpdian.sql to dump runtime PLSQ/SQL MCODE and DIANA Nodes:

event 10928 PL/SQL Machine Code Trace 
event 10938 PL/SQL calls and exceptions
admin/dumpdian.sql

(see:
   PL/SQL Machine Code Trace - event 10928, 
   PL/SQL, AST, DIANA, Attributes and IDL
)

but it is still hard to observe any difference.

alter session set events '10928 trace name context forever, level 1';
--------- Test-1 ---------
declare
  type t is table of number index by binary_integer;
  v_t  t;
  i    pls_integer := null;
begin
  v_t(1) := 1;
  v_t(null) := v_t(1);
  dbms_output.put_line(v_t(null));
end;
/
alter session set events '10928 trace name context off';


--  Run under sys 
create or replace procedure test_1_proc as
  type t is table of number index by binary_integer;
  v_t  t;
  i    pls_integer := null;
begin
  v_t(1) := 1;
  v_t(null) := v_t(1);
  dbms_output.put_line(v_t(null));
end;
/

-- dump into session trc file --

exec sys.dumpdiana.dump(aname => 'TEST_1_PROC');
exec sys.dumpdiana.node_count(aname => 'TEST_1_PROC');

We have also tried to switch plsql_code_type from interpreted (Default ) to native, no effect is observed.

"ORA-00001: unique constraint violated" Debugging

In this Blog, we demonstrate two approaches to debug ORA_00001, one is using errorstack event; another is with DML before trigger.
Both are especially useful for closed system, in which application is hard to be modified to fully expose code path and error causes.

Note: Tested in Oracle 19c

1. Test Setup

We create a table with one unique constraint, then insert a few rows:

drop table ora1_test_tab;

create table ora1_test_tab(id number, text varchar2(10));

create unique index ora1_test_tab#u#idx on ora1_test_tab(id);

--truncate table ora1_test_tab;

insert into ora1_test_tab values(1, 'A1');
insert into ora1_test_tab values(2, 'A2');
insert into ora1_test_tab values(3, 'A3');
commit;

select * from ora1_test_tab;

   ID  TEXT
  ---  ----
    1  A1
    2  A2
    3  A3

2. ORA-00001 Errorstack Trace

Run following test, in which ORA-00001 is cut away (Plsql callstack printed out in exception handler):

create or replace procedure ORA_00001_cut(p_id number) as
begin
  insert into ora1_test_tab values(p_id, 'B3');
exception when others then 
  dbms_output.put_line('Error');
  dbms_output.put_line(substr(dbms_utility.format_call_stack,1,2000));
end;
/

alter system set events='10046 trace name context forever, level 12';
alter system set events '1 trace name errorstack level 3';

begin
  ORA_00001_cut(3); 
end;
/

alter system set events '1 trace name errorstack off'; 
alter system set events='10046 trace name context off';

Sqlplus output:

Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 3
Detector: Check-2: ID = 3 (in Session_ID: 17), Exists by Already Committed TRX
Error
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x8a5b1568         6  procedure K.ORA_00001_CUT
0x81dd4768         2  anonymous block

DB alert.log output:

Errors in file /orabin/app/oracle/admin/test_db3/diag/rdbms/test_db3/test_db3/trace/test_db3_ora_650408.trc:
ORA-00001: unique constraint (K.ORA1_TEST_TAB#U#IDX) violated

Open trc file: test_db3_ora_650408.trc listed in above alert.log, we can see Bind value=3, DML SQL statement (sqlid='74zg41sgbw33n'), PL/SQL Call Stack and DIAG Call Stack Trace as follows:

=====================
PARSING IN CURSOR #140050023218008 len=44 dep=1 uid=49 oct=2 lid=49 tim=9261352709305 hv=515771508 ad='8db01638' sqlid='74zg41sgbw33n'
INSERT INTO ORA1_TEST_TAB VALUES(:B1 , 'B3')
END OF STMT
PARSE #140050023218008:c=170,e=170,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=9261352709305
BINDS #140050023218008:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=8b3cb490  bln=22  avl=02  flg=09
  value=3
=====================

----- Error Stack Dump -----
ORA-00001: unique constraint (K.ORA1_TEST_TAB#U#IDX) violated
----- Current SQL Statement for this session (sql_id=74zg41sgbw33n) -----
INSERT INTO ORA1_TEST_TAB VALUES(:B1 , 'B3')

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x8a5b1568         3  procedure K.ORA_00001_CUT
0x81dd4768         2  anonymous block

----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
ksedst1()+95         call     kgdsdst()            7FFF914C8680 000000002
                                                   7FFF914C28D0 ? 7FFF914C29E8 ?
                                                   000000000 000000000
......
kauerr()+522         call     kxcser()             7FFF914CBB40 000000001
                                                   7FFF914CBAC0 000000013
                                                   000000001 000000000
qesltcLoadIndexList  call     kauerr()             0005AAA5D 000000001 ?
()+2215                                            7FFF914CBAC0 ? 000000013 ?
                                                   000000001 ? 000000000 ?
qerltcNoKdtBuffered  call     qesltcLoadIndexList  7F682EC89290 09FC19BA8
InsRowCBK()+370               ()                   000000000 000000000
                                                   000000001 ? 000000000 ?
qerltcSingleRowLoad  call     qerltcNoKdtBuffered  7F682EC89230 09FC1A220
()+293                        InsRowCBK()          09FC1A750 000000000 ?
                                                   7F6835BACC08 000000000
qerltcFetch()+391    call     qerltcSingleRowLoad  09FC1A750 7F682EC89230
                              ()                   09FC1A220 000000000 ?
                                                   7F6835BACC08 ? 000000000 ?
qerstFetch()+541     call     qerltcFetch()        09FC1A750 7F682EC89230
                                                   009748EB0 7FFF914CD140
                                                   000007FFF 09FC1BC28
insexe()+733         call     qerstFetch()         09FC1A6E8 7F682EC89568
                                                   00D0CBE20 07302917A 000007FFF
                                                   09FC1BC28 ?
opiexe()+7194        call     insexe()             09FC1A6E8 ? 7F682EC89568 ?
                                                   00D0CBE20 ? 07302917A ?
                                                   000007FFF ? 09FC1BC28 ?

3. ORA-00001 Before Trigger

Here our test procedures:

3.1 ORA-00001 Detector

create or replace procedure debug_output(p_text varchar2) as
begin
  dbms_output.put_line(p_text);
  sys.DBMS_System.ksdwrt(2, p_text);
end;
/

create or replace procedure ora_00001_detector(p_id number) as
  l_id        number := p_id;
  l_sid       number; 
  l_trx_date  date;
  l_trx_ts    varchar2(100);
  l_stmt      varchar2(1000);
  l_id_found  number;
  l_ret_str   varchar2(1000);
begin
  select sid into l_sid from v$mystat where rownum = 1;
  l_ret_str := 'ID = '||l_id||' (in Session_ID: '||l_sid||')';
  select max(id) into l_id_found from ora1_test_tab where id = l_id;
  if l_id_found is null then
    --Insert ID not yet exist
    l_ret_str := 'Check-1: '||l_ret_str||' Not Exist';
  else
    select max(start_date) into l_trx_date from v$session s, v$transaction t where s.taddr=t.addr and sid = l_sid;
    if l_trx_date is null then 
      --Insert ID exists by Already Committed TRX
      l_ret_str := 'Check-2: '|| l_ret_str||', Exists by Already Committed TRX';
    else
      l_trx_ts := to_char(l_trx_date, 'YYYY-MM-DD hh24:mi:ss');
      l_ret_str := l_ret_str||', My TRX start_date: '||l_trx_ts ||', flashback query timestamp: '||l_trx_ts;
      l_stmt := 'select max(id) from ora1_test_tab as of timestamp timestamp''' ||l_trx_ts||''' where id = '||l_id;
      l_ret_str := l_ret_str||chr(10)||'    Stmt:'||l_stmt||chr(10);
      execute immediate l_stmt into l_id_found;
      if l_id_found is null then 
        --Insert ID inserted twice in the same TRX: first insert not yet committed, and inserted again. flashback query not found it.
        l_ret_str := 'Check-3: '||l_ret_str||'    flashback query No Found, My SID Inserted, Not Yet Committed.';
      else
        --Insert ID inserted after TRX started by another DML, flashback query found it.
        l_ret_str := 'Check-4: '||l_ret_str||'    flashback query Found Committed ID : '||l_id_found;
      end if;
    end if;
  end if;
  debug_output('Detector: '||l_ret_str);
  
  -- @TODO Printout Plsql call_stack:
  --debug_output(substr(dbms_utility.format_call_stack,1,2000));
end;
/

3.2 Before Trigger

create or replace trigger ora_00001_test_tab_trig
  before insert or update on ora1_test_tab referencing new as new old as old for each row
declare
  --pragma autonomous_transaction;
  tab    varchar2(30) := 'ora1_test_tab: ';
  action varchar2(30);
begin
	case
	  when inserting then action := 'BEFORE INSERT';
	  when updating  then action := 'BEFORE UPDATE';
	end case;
	debug_output('Trigger: '||action||' on '|| tab ||' :Old Val: '||:old.id||' :New Val: '||:new.id);
	ora_00001_detector(:new.id);
	
	exception when others then 
	  debug_output('ora_00001_test_tab_trig: '||SQLERRM);    --catch ORA-04091
	--commit;
end;
/

3.3 Test Procedure

create or replace procedure test_ora_00001_detector(p_id number, p_mode varchar2 := 'Detect') as
  l_id_tab t_id_tab := t_id_tab(-3, 3, 13);
begin
  rollback;
  
  ------------- Case-1 No ORA-00001: Insert Not Exist: ID = -3 -------------
  debug_output(chr(10)||'------------- Case-1 No ORA-00001: Insert Not Exist: ID = -3 -------------');
  if p_mode = 'Detect' then 
    ora_00001_detector(-p_id);
  else
    insert into ora1_test_tab values(-p_id, 'C1');
  end if;
  debug_output('Case-1 No ORA-00001 Insert: ID = -3 Not Exist');
  rollback;
  
  ------------- Case-2 ORA-00001: Insert Already Committed ID = 3 -------------
  debug_output(chr(10)||'------------- Case-2 ORA-00001: Insert Already Committed ID = 3 -------------');
  begin
     if p_mode = 'Detect' then 
       ora_00001_detector(p_id);
     else
       insert into ora1_test_tab values(p_id, 'C2');
     end if;
  exception when others then 
    debug_output('Case-2 ORA-00001 Insert: '||SQLERRM);
  end;
  rollback;
  
  ------------- Case-3 ORA-00001: Insert Twice ID = 13 in the Same TRX -------------
  debug_output(chr(10)||'-------------Case-3 ORA-00001: Insert Twice ID = 13 in the Same TRX -------------');
  begin
    insert into ora1_test_tab values(10+p_id, 'C3_1');
     if p_mode = 'Detect' then 
       ora_00001_detector(10+p_id);
     else
       insert into ora1_test_tab values(10+p_id, 'C3_2');
      end if;
  exception when others then 
    debug_output('Case-3 ORA-00001 Insert: '||SQLERRM);
  end;
  rollback;
  
  ------------- Case-4 ORA-00001: Insert ID = 3 in one already started TRX, flashback query detect Committed ID = 3 -------------
  debug_output(chr(10)||'------------- Case-4 ORA-00001: Insert ID = 3 in one already started TRX, flashback query detect Committed ID = 3 -------------');
  begin
    insert into ora1_test_tab values(10+p_id, 'C4_1');
    if p_mode = 'Detect' then 
      ora_00001_detector(p_id);
    else
      insert into ora1_test_tab values(p_id,  'C4_2');
    end if;
  exception when others then 
    debug_output('Case-4 ORA-00001 Insert: '||SQLERRM);
  end;
  rollback;
  
  ------------- Case-5 ORA-00001 Update to ID = 3 from ID = 13, flashback query detect Committed ID = 3 -------------
  debug_output(chr(10)||'------------- Case-5 ORA-00001 Update to ID = 3 from ID = 13, flashback query detect Committed ID = 3 -------------');
  begin
    if p_mode = 'Detect' then 
      ora_00001_detector(p_id);
    else
      insert into ora1_test_tab values(10+p_id, 'A13');
      update ora1_test_tab set id = p_id where id = 10+p_id;
    end if;
  exception when others then 
    debug_output('Case-5 ORA-00001 Update: '||SQLERRM);
  end;
  rollback;
  
  ------------- Case-6 ORA-00001 merge when matched, update to an existing ID -------------
  debug_output(chr(10)||'------------- Case-6 ORA-00001 merge when matched, update to an existing ID -------------');
  begin
    if p_mode = 'Detect' then 
      ora_00001_detector(p_id);
    else
      merge into ora1_test_tab t
      using (select p_id id, 'A3' text from dual) s
      on (t.text = s.text)
      when matched     then update set t.id = s.id - 1 
      when not matched then insert values (s.id, s.text);
    end if;
  exception when others then 
    debug_output('Case-6 ORA-00001 Update: '||SQLERRM);
  end;
  rollback;

  ------------- Case-7 ORA-00001 merge when not matched, insert one existing ID -------------
  debug_output(chr(10)||'------------- Case-7 ORA-00001 merge when not matched, insert one existing ID -------------');
  begin
    if p_mode = 'Detect' then 
      ora_00001_detector(p_id);
    else
      merge into ora1_test_tab t
      using (select p_id + 10 id, 'B3' text from dual) s
      on (t.text = s.text)
      when matched     then update set t.id = s.id - 1 
      when not matched then insert values (s.id - 10, s.text);
    end if;
  exception when others then 
    debug_output('Case-7 ORA-00001 Update: '||SQLERRM);
  end;
  rollback;
    
end;
/

4. Test Run

Here our tests and output recorded in DB alert.log:

4.1 Smoking Test

begin
  insert into ora1_test_tab values(13, 'A13');
  ora_00001_detector(3);
end;
/
rollback;

DB alert.log output:

2025-09-01T10:13:41.357832+02:00
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 13
Detector: Check-1: ID = 13 (in Session_ID: 297) Not Exist
Detector: Check-4: ID = 3 (in Session_ID: 297), My TRX start_date: 2025-09-01 10:13:41, flashback query timestamp: 2025-09-01 10:13:41
    Stmt:select max(id) from ora1_test_tab as of timestamp timestamp'2025-09-01 10:13:41' where id = 3
    flashback query Found Committed ID : 3

4.2 Detect Test

exec test_ora_00001_detector(3, 'Detect');

DB alert.log output:

2025-09-01T10:15:48.582676+02:00

------------- Case-1 No ORA-00001: Insert Not Exist: ID = -3 -------------
Detector: Check-1: ID = -3 (in Session_ID: 297) Not Exist
Case-1 No ORA-00001 Insert: ID = -3 Not Exist

------------- Case-2 ORA-00001: Insert Already Committed ID = 3 -------------
Detector: Check-2: ID = 3 (in Session_ID: 297), Exists by Already Committed TRX

-------------Case-3 ORA-00001: Insert Twice ID = 13 in the Same TRX -------------
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 13
Detector: Check-1: ID = 13 (in Session_ID: 297) Not Exist
Detector: Check-3: ID = 13 (in Session_ID: 297), My TRX start_date: 2025-09-01 10:15:48, flashback query timestamp: 2025-09-01 10:15:48
    Stmt:select max(id) from ora1_test_tab as of timestamp timestamp'2025-09-01 10:15:48' where id = 13
    flashback query No Found, My SID Inserted, Not Yet Committed.

------------- Case-4 ORA-00001: Insert ID = 3 in one already started TRX, flashback query detect Committed ID = 3 -------------
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 13
Detector: Check-1: ID = 13 (in Session_ID: 297) Not Exist
Detector: Check-4: ID = 3 (in Session_ID: 297), My TRX start_date: 2025-09-01 10:15:48, flashback query timestamp: 2025-09-01 10:15:48
    Stmt:select max(id) from ora1_test_tab as of timestamp timestamp'2025-09-01 10:15:48' where id = 3
    flashback query Found Committed ID : 3

------------- Case-5 ORA-00001 Update to ID = 3 from ID = 13, flashback query detect Committed ID = 3 -------------
Detector: Check-2: ID = 3 (in Session_ID: 297), Exists by Already Committed TRX

------------- Case-6 ORA-00001 merge when matched, update to an existing ID -------------
Detector: Check-2: ID = 3 (in Session_ID: 297), Exists by Already Committed TRX

------------- Case-7 ORA-00001 merge when not matched, insert one existing ID -------------
Detector: Check-2: ID = 3 (in Session_ID: 297), Exists by Already Committed TRX

4.3. Execute Test

exec test_ora_00001_detector(3, 'Execute');

DB alert.log output:

2025-09-01T10:16:27.833564+02:00

------------- Case-1 No ORA-00001: Insert Not Exist: ID = -3 -------------
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: -3
Detector: Check-1: ID = -3 (in Session_ID: 297) Not Exist
Case-1 No ORA-00001 Insert: ID = -3 Not Exist

------------- Case-2 ORA-00001: Insert Already Committed ID = 3 -------------
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 3
Detector: Check-2: ID = 3 (in Session_ID: 297), Exists by Already Committed TRX
Case-2 ORA-00001 Insert: ORA-00001: unique constraint (K.ORA1_TEST_TAB#U#IDX) violated

-------------Case-3 ORA-00001: Insert Twice ID = 13 in the Same TRX -------------
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 13
Detector: Check-1: ID = 13 (in Session_ID: 297) Not Exist
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 13
Detector: Check-3: ID = 13 (in Session_ID: 297), My TRX start_date: 2025-09-01 10:16:27, flashback query timestamp: 2025-09-01 10:16:27
    Stmt:select max(id) from ora1_test_tab as of timestamp timestamp'2025-09-01 10:16:27' where id = 13
    flashback query No Found, My SID Inserted, Not Yet Committed.
Case-3 ORA-00001 Insert: ORA-00001: unique constraint (K.ORA1_TEST_TAB#U#IDX) violated

------------- Case-4 ORA-00001: Insert ID = 3 in one already started TRX, flashback query detect Committed ID = 3 -------------
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 13
Detector: Check-1: ID = 13 (in Session_ID: 297) Not Exist
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 3
Detector: Check-4: ID = 3 (in Session_ID: 297), My TRX start_date: 2025-09-01 10:16:27, flashback query timestamp: 2025-09-01 10:16:27
    Stmt:select max(id) from ora1_test_tab as of timestamp timestamp'2025-09-01 10:16:27' where id = 3
    flashback query Found Committed ID : 3
Case-4 ORA-00001 Insert: ORA-00001: unique constraint (K.ORA1_TEST_TAB#U#IDX) violated

------------- Case-5 ORA-00001 Update to ID = 3 from ID = 13, flashback query detect Committed ID = 3 -------------
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 13
Detector: Check-1: ID = 13 (in Session_ID: 297) Not Exist
Trigger: BEFORE UPDATE on ora1_test_tab:  :Old Val: 13 :New Val: 3
ora_00001_test_tab_trig: ORA-04091: table K.ORA1_TEST_TAB is mutating, trigger/function may not see it
Case-5 ORA-00001 Update: ORA-00001: unique constraint (K.ORA1_TEST_TAB#U#IDX) violated

------------- Case-6 ORA-00001 merge when matched, update to an existing ID -------------
Trigger: BEFORE UPDATE on ora1_test_tab:  :Old Val: 3 :New Val: 2
ora_00001_test_tab_trig: ORA-04091: table K.ORA1_TEST_TAB is mutating, trigger/function may not see it
Case-6 ORA-00001 Update: ORA-00001: unique constraint (K.ORA1_TEST_TAB#U#IDX) violated

------------- Case-7 ORA-00001 merge when not matched, insert one existing ID -------------
Trigger: BEFORE INSERT on ora1_test_tab:  :Old Val:  :New Val: 3
ora_00001_test_tab_trig: ORA-04091: table K.ORA1_TEST_TAB is mutating, trigger/function may not see it
Case-7 ORA-00001 Update: ORA-00001: unique constraint (K.ORA1_TEST_TAB#U#IDX) violated

We can see that with before trigger, different scenarios of ORA-00001 (insert / update / merge, TRX started by previous DML or own DML) can be detected, and bind values are exposed.