This discussion is archived
11 Replies Latest reply: Mar 6, 2013 3:59 AM by user2522172 RSS

Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!

user2522172 Newbie
Currently Being Moderated
Hi,

We have a Oracle 11.2.0.2.0 64 bit database on a SuSe 10 server (with NFS mounts) and in some trace file I did found the following message:

Log read is SYNCHRONOUS though disk_asynch_io is enabled!

I'm puzzled because Async Io is enabled:

filesystemio_options is set to SETALL and disk_async_io is set to TRUE. When I query:select file_no,filetype_name,asynch_io from v$iostat_file;
I get the following:

FILE_NO FILETYPE_NAME ASYNCH_IO
---------- ---------------------------- ---------
0 Other ASYNC_OFF
0 Control File ASYNC_OFF
0 Log File ASYNC_OFF
0 Archive Log ASYNC_OFF
0 Data File Backup ASYNC_OFF
0 Data File Incremental Backup ASYNC_OFF
0 Archive Log Backup ASYNC_OFF
0 Data File Copy ASYNC_OFF
0 Flashback Log ASYNC_OFF
0 Data Pump Dump File ASYNC_OFF
all datafiles: async_on!

The NFS mount options for all filesystems are correct: rw,v3,rsize=32768,wsize=32768,hard,nolock,timeo=600,proto=tcp,sec=sys

Is IO for log file allways synchrounous? The reason for my question is that we see from time to time the following Awr information:

Top 5 Timed Foreground Events

Event Waits     Time(s)     Avg wait (ms)     % DB time     Wait Class
log file sync     62,576     32,908     526     67.98     Commit
db file sequential read     539,144     11,033     20     22.79     User I/O
DB CPU          3,800          7.85     
enq: TX - row lock contention     375     693     1848     1.43     Application
Log archive I/O     667     59     89     0.12     System I/O


During this high log file sync users complain about bad performance.

Any ideas?


regards,

Ivan
  • 1. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    TSharma-Oracle Guru
    Currently Being Moderated
    Check might help.

    http://www.colestock.com/tech/How_To_Enable_Asynchronous_IO_Oracle.pdf
  • 2. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    Mark Malakanov (user11181920) Expert
    Currently Being Moderated
    As far as I remember there also should be aio libs installed in OS.
    also, are you shure that NFS is supported for AIO. For 10g it was not.

    Edited by: Mark Malakanov (user11181920) on Mar 4, 2013 12:08 PM
  • 3. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    user2522172 Newbie
    Currently Being Moderated
    Mark,

    Oracle uses async io for the database file (see output select from v$*** view in my previous post). Maybe Oracle use only sync io for the log-files?

    regards,

    Ivan
  • 4. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    Rob_J Journeyer
    Currently Being Moderated
    Hi,

    The log file sync wait event shows as an average wait time of 526 ms which is very high. Ideally you want to try and get that as low as possible, sub 5 ms perhaps. But it depends on what's happening in your DB:

    Lots of commits every second?
    Huge REDO generation?
    Are the REDO log sharing disks with datafiles?
    What type of disk are the REDO logs on?

    What does the load profile say for that time period? How much REDO is there? (please use the code tag to format the output properly, read the [url https://wikis.oracle.com/display/Forums/Forums+FAQ]FAQ on how to do that)

    I'm not surprised the users complain as it takes on average 0.5 of a second to commit a transaction. That's without the I/O, CPU, parsing, etc for the statement.

    Rob
  • 5. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    JohnWatson Guru
    Currently Being Moderated
    user2522172 wrote:
    Mark,

    Oracle uses async io for the database file (see output select from v$*** view in my previous post). Maybe Oracle use only sync io for the log-files?

    regards,

    Ivan
    I think this is correct. The concept behind commit processing, where your session must hang following commit until the logfile write is complete, would seem to require synchronous writes. If the write were asynchronous, in effect Oracle could return a "commit complete" message before the redo was written to disc, so it would then be theoretically possible to lose a committed transaction.

    Edited by: JohnWatson on Mar 5, 2013 11:26 AM
    I should have mentioned, I get the same results as you for the query: I've tested against local file system storage, and ASM using directly attached SCSI discs, and ASM using NFS files.
  • 6. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    user2522172 Newbie
    Currently Being Moderated
    Joahn,

    Thanks for the clarification.

    regards,

    Ivan
  • 7. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    user2522172 Newbie
    Currently Being Moderated
    Rob,

    OS/Network admin's found out there is a misconfiguration with the IO settings. What exactly I don't know yet but I'll let you know as soon as I have the information.

    regards,

    Ivan
  • 8. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    user2522172 Newbie
    Currently Being Moderated
    TSharma,

    Thanks for the link.

    regards,

    Ivan
  • 9. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    Girish Sharma Guru
    Currently Being Moderated
    Oracle uses async io for the database file (see output select from v$*** view in my previous post). Maybe Oracle use only sync io for the log-files?
    Yes, LGWR uses synchronous IO for redo logs. Below text confirm it : (I don't know how to check it though)
    The LGWR process synchronously writes to the local online redo log files
    http://docs.oracle.com/cd/B19306_01/server.102/b14239/log_transport.htm

    Regards
    Girish Sharma
  • 10. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    Mark Malakanov (user11181920) Expert
    Currently Being Moderated
    >
    I think this is correct. The concept behind commit processing, where your session must hang following commit until the logfile write is complete, would seem to require synchronous writes. If the write were asynchronous, in effect Oracle could return a "commit complete" message before the redo was written to disc, so it would then be theoretically possible to lose a committed transaction.
    >

    Not necessarily. Though commit's logical write must be "synchronous" or "assured", it is not necessarily that it must use synchronous i/o calls for it.
    For example Log Writer can issue 3 asynchronous writes to 3 logfiles simultaneously and then wait (or do other stuff like next buffer population) until all 3 finish, then if all 3 done successfully return control to user process.
    From a user process perspective the commit still look solid and "synchronous". But here Log Writer benefits from simultaneous parallel write to 3 disks. Plus Log Writer meantime can do some other activity with buffers or whatever. Other words it is 3 times faster versus it do that in 3 sequential synchronous i/o calls.

    to prove my point I run strace on lgwr process and run some quite big transactions.
    [root@oracledev ~]# ps -ef|grep lgwr
    # root       525 32728  0 13:41 pts/2    00:00:00 grep lgwr
    oraerd    7436     1  0 Jan27 ?        00:08:26 ora_lgwr_ERD
    
    # strace -p 7436
    io_submit(20971520, 2, {{...}, {...}})  = 2
    io_getevents(20971520, 2, 1024, {{...}, {...}}, {...}) = 2
    times(NULL)                             = 749695972
    times(NULL)                             = 749695972
    times(NULL)                             = 749695972
    semctl(294917, 96, SETVAL, 0xfff0a600)  = 0
    times(NULL)                             = 749695972
    times(NULL)                             = 749695972
    times(NULL)                             = 749695972
    io_submit(20971520, 2, {{...}, {...}})  = 2
    io_getevents(20971520, 2, 1024, {{...}, {...}}, {...}) = 2
    times(NULL)                             = 749695973
    times(NULL)                             = 749695973
    times(NULL)                             = 749695973
    semctl(294917, 88, SETVAL, 0xfff0a600)  = 0
    times(NULL)                             = 749695973
    times(NULL)                             = 749695973
    semtimedop(294917, 0xfff0c8e0, 1, {...}) = 0
    ...
    Note io_submit() and io_getevents() calls - it is Async I/O.
    I did not see other I/O like write().

    Oracle 10.2.0.5 on Linux on IBM POWER
    uanme -a
    Linux oracledev 2.6.18-308.1.1.el5 #1 SMP Fri Feb 17 16:51:00 EST 2012 ppc64 ppc64 ppc64 GNU/Linux

    Edited by: Mark Malakanov (user11181920) on Mar 5, 2013 1:41 PM
  • 11. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    user2522172 Newbie
    Currently Being Moderated
    All,

    The problem has been solved. There were two issues:

    1) a snapshot backup of the database (Netapp's are used) was made every wednesday and the snapshot was then copied to a remote place over the network;
    2) an 1 Gbit interface was used instead of a 10 Gbit interface.

    Thanks all for the input and help.

    regards,

    Ivan

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points