Archive

Archive for the ‘DB Tuning’ Category

High log file sync

August 19, 2010 Leave a comment

Symptoms

– Top 5 Timed Foreground Events

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Avg

wait   % DB

Event                                 Waits     Time(s)   (ms)   time Wait Class

—————————— ———— ———– —— —— ———-

log file sync                           393         924   2352   37.2 Commit

DB CPU                                              631          25.4

SQL*Net more data from client         5,390         316     59   12.7 Network

ksfd: async disk IO                  67,412         275      4   11.1 System I/O

log buffer space                        193         136    704    5.5 Configurat

  • -Every process costs average 2.4 second to commit and wait for the event ‘log file sync’. The possible causes

– Trace log for LGWR process

*** 2010-08-18 09:55:13.666

WAIT #0: nam=’rdbms ipc message’ ela= 2939210 timeout=300 p2=0 p3=0 obj#=-1 tim=1690309619279

WAIT #0: nam=’ksfd: async disk IO’ ela= 292 count=1 intr=56 timeout=2147483647 obj#=-1 tim=1690309619880

WAIT #0: nam=’ksfd: async disk IO’ ela= 151 count=4294967295 intr=16 timeout=2147483647 obj#=-1 tim=1690309620020

WAIT #0: nam=’log file parallel write’ ela= 24 files=1 blocks=4 requests=1 obj#=-1 tim=1690309620042

*** 2010-08-18 09:55:16.732

WAIT #0: nam=’rdbms ipc message’ ela= 2993543 timeout=300 p2=0 p3=0 obj#=-1 tim=1690312613664

WAIT #0: nam=’ksfd: async disk IO’ ela= 362 count=1 intr=56 timeout=2147483647 obj#=-1 tim=1690312614613

WAIT #0: nam=’ksfd: async disk IO’ ela= 62 count=4294967295 intr=16 timeout=2147483647 obj#=-1 tim=1690312614662

WAIT #0: nam=’log file parallel write’ ela= 20 files=1 blocks=3 requests=1 obj#=-1 tim=1690312614680

*** 2010-08-18 09:55:19.736

WAIT #0: nam=’rdbms ipc message’ ela= 2932603 timeout=300 p2=0 p3=0 obj#=-1 tim=1690315547345

*** 2010-08-18 09:55:22.746

WAIT #0: nam=’rdbms ipc message’ ela= 2939079 timeout=300 p2=0 p3=0 obj#=-1 tim=1690318486609

*** 2010-08-18 09:55:25.756

WAIT #0: nam=’rdbms ipc message’ ela= 2939069 timeout=300 p2=0 p3=0 obj#=-1 tim=1690321426022

WAIT #0: nam=’ksfd: async disk IO’ ela= 324 count=1 intr=56 timeout=2147483647 obj#=-1 tim=1690321426663

WAIT #0: nam=’ksfd: async disk IO’ ela= 45 count=4294967295 intr=16 timeout=2147483647 obj#=-1 tim=1690321426697

WAIT #0: nam=’log file parallel write’ ela= 19 files=1 blocks=21 requests=1 obj#=-1 tim=1690321426714

*** 2010-08-18 09:55:28.766

WAIT #0: nam=’rdbms ipc message’ ela= 2938588 timeout=300 p2=0 p3=0 obj#=-1 tim=1690324365361

** 2010-08-18 09:55:31.776

WAIT #0: nam=’rdbms ipc message’ ela= 2939377 timeout=300 p2=0 p3=0 obj#=-1 tim=1690327304920

** 2010-08-18 09:55:34.786

WAIT #0: nam=’rdbms ipc message’ ela= 2939142 timeout=300 p2=0 p3=0 obj#=-1 tim=1690330244264

*** 2010-08-18 09:55:37.796

WAIT #0: nam=’rdbms ipc message’ ela= 2939526 timeout=300 p2=0 p3=0 obj#=-1 tim=1690333184006

*** 2010-08-18 09:55:40.806

WAIT #0: nam=’rdbms ipc message’ ela= 2939051 timeout=300 p2=0 p3=0 obj#=-1 tim=1690336123251

  • It shows the LGWR process going to sleeping (waiting for ‘rdbms ipc message’) and wake up when the sleeping timeout(ela= 2938608 timeout=300).
  • Processes commit transaction and post the sleeping LGWR, this will cause long ‘log file sync’ event

Fixed

Set the hidden parameter _log_io_size to 256k, to make LGWR running more frequency and keep it running.

The log file sync event goes away by looking at awrrpt.

wait   % DB

Event                                 Waits     Time(s)   (ms)   time Wait Class

—————————— ———— ———– —— —— ———-

DB CPU                                              516          32.5

SQL*Net message from dblink             580         345    595   21.7 Network

SQL*Net more data from client         5,315         330     62   20.8 Network

ksfd: async disk IO                  96,249         298      3   18.7 System I/O

db file sequential read               8,719          48      6    3.0 User I/O

Categories: DB Tuning