9 Replies Latest reply: May 15, 2008 2:36 PM by Jonathan Lewis RSS

    log file sync" while performing COMMIT and ROLLBACK operations

    639316
      Hi ,

      In ADDM finding, I got following recommendation.

      Finding: Waits on event "log file sync" while performing COMMIT and ROLLBACK operations were consuming significant database time.

      Action: Investigate the possibility of improving the performance of I/O to the online redo log files.
      Rationale The average size of writes to the online redo log files was 16 K and the average time per write was 1 milliseconds.

      I want to know what will be the best size of redo logs for my database and also what other parameters I need to change.

      I have 3 redo log groups (each on different disk) and each has 1 member, the size of each member is 256 MB,

      I am also getting the following error in Alert log. How I can get rid of following alerts

      Wed May 14 14:31:00 2008
      Thread 1 cannot allocate new log, sequence 4233
      Private strand flush not complete
      Current log# 3 seq# 4232 mem# 0: /u04/oradata/abc/redo3.log
      Thread 1 advanced to log sequence 4233
      Current log# 2 seq# 4233 mem# 0: /u03/oradata/abc/redo2.log
      Wed May 14 14:31:28 2008
      Thread 1 cannot allocate new log, sequence 4234
      Checkpoint not complete
      Current log# 2 seq# 4233 mem# 0: /u03/oradata/abc/redo2.log
      Thread 1 cannot allocate new log, sequence 4234
      Private strand flush not complete
      Current log# 2 seq# 4233 mem# 0: /u03/oradata/abc/redo2.log
      Thread 1 advanced to log sequence 4234
      Current log# 1 seq# 4234 mem# 0: /u02/oradata/abc/redo1.log


      Here are the related following init parameters

      log_checkpoint_timeout= 262144
      log_checkpoint_interval=0

      Regards,
        • 1. Re: log file sync" while performing COMMIT and ROLLBACK operations
          428027
          Hi,
          The best size is one that log switch only arround 10 minutes.

          Regards
          Helio Dias
          http://heliodias.com
          • 2. Re: log file sync" while performing COMMIT and ROLLBACK operations
            561093
            Waits on event "log file sync" while performing COMMIT and ROLLBACK operations
            were consuming significant database time.
            What storage type is assigned to redo log groups?

            Do you have anything else shared on this disk?

            I want to know what will be the best size of redo logs for my database
            That purely depends on the amount of redo generated. 3-4 log switches per hour should be ok.
            Thread 1 cannot allocate new log, sequence 4234
            Increase the number of redo log groups.
            • 3. Re: log file sync" while performing COMMIT and ROLLBACK operations
              Aman....
              Hi,
              Before doing anything , I shall recommend reading this excellent page about Log buffer and its working,
              http://www.ixora.com.au/tips/tuning/log_buffer_size.htm
              In best practise advice, its recommended that a log switch should take a time lap of about 20 minutes. 10 minutes as suggested is probably a little small. Also you are using 10g I believe as you have mentioned ADDM.In EM of 10g,there is an option that you can get advice of the size which should be used by your redo log files. So you can use that.And why you are still using these deperecated parameters of log_chckpoint_timout and all that?Oracle has recommended to use FAST_START_MTTR_TARGET since 9i. I shall suggest that you should take care of this parameter. Also one more thing to conclude that look in your application that how the transactions are written.Too much commit rate can also cause Log File Sync wait event.Read teh page that I have given for the thorough discussion for it.
              Aman....
              • 4. Re: log file sync" while performing COMMIT and ROLLBACK operations
                639316
                Thanks all. I am checking all the suggestion but still some questions.
                Citrus, Many databases are sharing the same disks for redo log (because these disks are fast so I pointed all database's redo logs to these disks). I have only 3 fast disks and this database has 3 redo log groups (each has 1 member) and each redo log group assigned to disk1 , disk2 and disk3 respectively. Can I add the fourth redo log group to the 1st disk again ( even though 1st redo log group is on the same disk) ?

                Aman, I was also reading the link you have mentioned . In the link it is mentioned that "It is very rare to require a log buffer more than a few hundred kilobytes in size" but when I checked the size of log_buffer in my database, it is 4MB, is it okay ? also I tried to find the advise for redo log buffer in Grid , I checked Advisor Central but no information for the redo log. I got the information for redo log in ADDM but not giving any recommendation

                Regards,
                • 5. Re: log file sync" while performing COMMIT and ROLLBACK operations
                  561093
                  because these disks are fast so I pointed all database's redo logs to these disks
                  As these disks were fast, you added everything from everywhere to make them slow.

                  Why not spend some money and add few disks so that you may have separate disks for separate databases.
                  Can I add the fourth redo log group to the 1st disk again ( even though 1st redo log group
                  is on the same disk) ?
                  Yes, you may create 4th group on the 1st disk, 5th group on the 2nd disk, and 6th group on the 3rd disk.....

                  Message was edited by:
                  Citrus
                  • 6. Re: log file sync" while performing COMMIT and ROLLBACK operations
                    Jonathan Lewis
                    There are a couple of oddities in the information:

                    1 - the average time per write was 1 m/s: this is pretty quick (and has to be a write to a cache, not to disc) so basically you can't make it significantly faster, and it's slightly odd that ADDM reported it, except that ...

                    2 - The average write size is 16Kb, which is quite small, and you get two 'cannot allocate next log' messages in the space of 28 seconds when your log file size is 256Mb; which means you seem to be doing lots of very small transactions very quicky. (Possibly, this is peak processing on a highly concurrent system, or it's a batch job processing and committing one row at a time - the latter should be investigated for reducing rate of commits).

                    You may get some relief from increasing the size of number of redo logs. You also need to look at the reasons why you are generating so much log in case the underlying code is inefficient.

                    It would also be helpful to give us a clue about where in the recommendations this one appeared - was it the top one, or just an "also-ran" somewhere near the bottom suggesting a couple of percent benefit ? It would be nice to see the Top 5 Timed events from the AWR report for the same period. (Check the FAQ at top-right to see how to use the 'pre' tags to make this appear in a readable fixed-font)

                    In 10gR2, by the way, you basically don't need to mess with the log buffer size - and you should take any reference to it out of the spfile (init.ora). It's controlled by Oracle, and the default is usually good enough.

                    One last thought - if you've set processes, sessions, or transactions to an unnecessarily high value, this could contribute to the complaint about 'private strand flush not complete'.

                    Regards
                    Jonathan Lewis
                    http://jonathanlewis.wordpress.com
                    http://www.jlcomp.demon.co.uk
                    • 7. Re: log file sync" while performing COMMIT and ROLLBACK operations
                      639316
                      Thanks for your information.
                      The ADDM finding I found in Advisor Central then search for Advisory taks=ADDM. I have pasted the information below

                      Database Instance: ABC > Advisor Central > Automatic Database Diagnostic Monitor (ADDM) > Logged in As XYZ

                      Performance Finding Details
                      Database Time (minutes) 96.7
                      Period Start Time May 14, 2008 3:00:35 PM EDT
                      Period Duration (minutes) 60.2

                      Task Owner SYS
                      Task Name ADDM:3526010935_1_2887
                      Average Active Sessions 1.6

                      Finding Waits on event "log file sync" while performing COMMIT and ROLLBACK operations were consuming significant database time.
                      Impact (minutes) 2
                      Impact (%) 2

                      Action Investigate the possibility of improving the performance of I/O to the online redo log files.

                      Rationale The average size of writes to the online redo log files was 16 K and the average time per write was 1 milliseconds.

                      Regards,
                      • 8. Re: log file sync" while performing COMMIT and ROLLBACK operations
                        247514
                        A few more point,
                        Wed May 14 14:31:00 2008
                        Thread 1 cannot allocate new log, sequence 4233
                        Private strand flush not complete
                        Current log# 3 seq# 4232 mem# 0: /u04/oradata/abc/redo3.log
                        Thread 1 advanced to log sequence 4233
                        Current log# 2 seq# 4233 mem# 0: /u03/oradata/abc/redo2.log
                        Wed May 14 14:31:28 2008
                        Thread 1 cannot allocate new log, sequence 4234
                        The error basically means, you are switching logfile too fast, Oracle can't prep the previous logfile file group fast enough to be recycled. You might consider add few more redo logfile group. Or resize your redo logfile to bigger size, as you can see the log switch interval is merely 28 seconds.
                        Of course all these are related, if you increase redo logfile size Oracle will not switch log as often then it will have more time to flush the changes in older redo logfile groups.

                        As Jonathan has pointed out, the problem is most likely not because your redo files disk speed. More likely you had too many transactions at the same time, a code review should be considered. Check top SQL sections.
                        • 9. Re: log file sync" while performing COMMIT and ROLLBACK operations
                          Jonathan Lewis
                          The impact is 2% - so I wouldn't get too worried about this.

                          Your 'average active sessions' is only 1.6, though, which points in the direction of my comment of a batch-like process committing every row. I would check for some pl/sql (or other language) loop inserting and updating a lot of data in small steps.

                          If you can extract the AWR report for the interval (in text form) and past the Top 5 and Load Profile sections, that might show more clues. Note - you can use tags (see the FAQ near the top right of the screen) to make things like AWR reports show up in fixed width fonts, that make them readable.

                          Regards
                          Jonathan Lewis
                          http://jonathanlewis.wordpress.com
                          http://www.jlcomp.demon.co.uk