11 Replies Latest reply: Mar 6, 2013 5:59 AM by user2522172 RSS

    Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!

    user2522172
      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
          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)
            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
              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
                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
                  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
                    Joahn,

                    Thanks for the clarification.

                    regards,

                    Ivan
                    • 7. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
                      user2522172
                      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
                        TSharma,

                        Thanks for the link.

                        regards,

                        Ivan
                        • 9. Re: Oracle  gives Log read is SYNCHRONOUS though disk_asynch_io is enabled!
                          Girish Sharma
                          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)
                            >
                            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
                              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