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"

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 (see /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;

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.