Blog List

• 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

Oracle Self-tune checkpointing lag of log switch

Often DB alert.log shows a lag of 5 minutes from log switch to Completed checkpoint as follows:
(from 11:03:36 to 11:08:39)

2024-11-04T11:03:36.681460+01:00
Beginning log switch checkpoint up to RBA [0x8b.2.10], SCN: 13022649669494
2024-11-04T11:03:36.681565+01:00
Thread 1 advanced to log sequence 139 (LGWR switch),  current SCN: 13022649669494
  Current log# 3 seq# 139 mem# 0: /oratestdb/oradata/testdb/redo03.dbf
2024-11-04T11:08:39.613734+01:00
Completed checkpoint up to RBA [0x8b.2.10], SCN: 13022649669494

is this a LGWR performance problem ?

In this Blog, we will demonstrate those LGWR and CKPT asynchronous write and 3 hidden parameters with Linux bpftrace by following the advanced guidance Let's trace it! A peek into the inner workings of Oracle with bpftrace von Christoph Lutz.

  _selftune_checkpointing_lag		Self-tune checkpointing lag the tail of the redo log   300
  _disable_selftune_checkpointing	Disable self-tune checkpointing                        FALSE
  _selftune_checkpoint_write_pct	Percentage of total physical i/os for self-tune ckpt   3    

Note: Tested in Oracle 19.24.

In Linux window, start bpftrace script below:

BPFTRACE_STRLEN=200 bpftrace -e '
 tracepoint:syscalls:sys_enter_openat /(strncmp("ora_lgwr", comm, 7) == 0 || strncmp("ora_ckpt", comm, 7) == 0) && strncmp("/oradir", str(args->filename), 7) == 0/ 
   {time("====== %H:%M:%S ------ ");
    printf("comm=%s, pid=%d, filename ------\n%8s%s\n", comm, pid, "", str(args->filename));}
 tracepoint:syscalls:sys_enter_write /(strncmp("ora_lgwr", comm, 7) == 0 || strncmp("ora_ckpt", comm, 7) == 0) && strncmp("<",str(args->buf), 1) == 1/ 
   {time("====== %H:%M:%S ------ ");
    printf("comm=%s, pid=%d, fd=%d, BUF ------\n%s\n", comm, pid, args->fd, str(args->buf));}'

In Sqlplus window, run following SQL:

--create table test_tab as select 1 x from dual; 

update tt1 set x = x + 1;
commit;
alter system switch logfile;

Back to Linux Window, we can see following output during around 5 minutes:

Attaching 2 probes...

====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/alert/log.xml
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/alert_testdb.log
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, fd=8, BUF ------
2024-11-04T11:03:36.681460+01:00
Beginning log switch checkpoint up to RBA [0x8b.2.10], SCN: 13022649669494

====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/alert/log.xml
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/alert_testdb.log
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, fd=8, BUF ------
2024-11-04T11:03:36.681565+01:00
Thread 1 advanced to log sequence 139 (LGWR switch),  current SCN: 13022649669494

====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/alert/log.xml
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/alert_testdb.log
====== 11:03:36 ------ comm=ora_lgwr_testdb, pid=1926182, fd=8, BUF ------
  Current log# 3 seq# 139 mem# 0: /oratestdb/oradata/testdb/redo03.dbf

====== 11:08:39 ------ comm=ora_ckpt_testdb, pid=1926186, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/alert/log.xml
====== 11:08:39 ------ comm=ora_ckpt_testdb, pid=1926186, filename ------
        /oradir/app/oracle/admin/testdb/diag/rdbms/testdb/testdb/trace/alert_testdb.log
====== 11:08:39 ------ comm=ora_ckpt_testdb, pid=1926186, fd=10, BUF ------
2024-11-04T11:08:39.613734+01:00
Completed checkpoint up to RBA [0x8b.2.10], SCN: 13022649669494

Both LGWR and CKPT write to DIAG "log.xml" and alert.log (xml content in "log.xml" are filtered out).
LGWR records redo log activities at beginning (11:03:36), and only after about 5 minutes,
CKPT sends "Completed checkpoint" (11:08:39) with same "RBA [0x8b.2.10]".

If we look redo logs immediately after switch logfile, the current one is marked with log switch timestamp (11:03):

oracle@testdb:testdb > ls -ltr /oratestdb/oradata/testdb/redo*
-rw-r----- 1 oracle dba 1073742336 Nov  4 10:19 /oratestdb/oradata/testdb/redo04.dbf
-rw-r----- 1 oracle dba 1073742336 Nov  4 10:21 /oratestdb/oradata/testdb/redo01.dbf
-rw-r----- 1 oracle dba 1073742336 Nov  4 11:03 /oratestdb/oradata/testdb/redo03.dbf
-rw-r----- 1 oracle dba 1073742336 Nov  4 11:03 /oratestdb/oradata/testdb/redo02.dbf

As tested, the 5 minutes is an upper limit and controlled by the default 300 seconds of "_selftune_checkpointing_lag".

If we change it as (require DB restart):

alter system set "_selftune_checkpointing_lag"=60 scope=spfile;

The "Completed checkpoint" is written after 1 minutes.

If we disable the Self-tune by (require DB restart):

alter system set "_disable_selftune_checkpointing"=true scope=spfile;

CKPT will no more write "Completed checkpoint" in alert.log.

Of course, if we want to watch "Completed checkpoint", we can force a checkpoint by:

alter system checkpoint;