Wait Events: Log File Sync and Log File Parallel Write.

In OLTP environments, one of the biggest performance problems is the excessive wait events for recordings Online Redo Log Files. Every time that Oracle Database waits for recordings in these files can observe events "Log File Sync 'and' Log File Parallel Write".

What is the expected event 'log file sync'?

When a session of a user or application executes a COMMIT, the information stored in memory Redo (LOG_BUFFER) are discharged in the Online Redo Log Files to make permanent changes made in the database. This process is executed by LOG WRITER (LGWR). When the LGWR process ends this recording, a warning is sent to the session stating that the COMMIT process is 100% complete.

The time between the user session / application LGWR request the recording of redos Memory (LOG_BUFFER) for Online Redo Log Files and LGWR inform the meeting that the process was completed is where the event occurs 'log file

sync'.

How to identify the event 'log file sync'?

To analyze and identify the event 'log file sync' can use the information to:

- Reports of a period AWR timely collection.

- Trace files of LGWR. These files can show many events waiting on 'log file parallel wait'

Events which occur Waiting 'log file sync'?

Events waiting to 'log file sync' can happen at any stage between the user session / application LGWR request the recording of redos Memory (LOG_BUFFER) for Online Redo Log Files and LGWR inform the session that the process was completed.

Performance of LGWR

The main question is "Is there any problem for Recording Performance in Online Redo Logs"?

The steps below can help you find performance problems in the Log Writer (LGWR).

1 - Comparing the average waiting time for 'log file sync' with the average waiting time for 'log file parallel write'

The event hopes to 'log file parallel write' occurs while LGWR is writing redo information on Online Redo Log Files. The Total time of this event is the total recording time in disk files.

Analyzing this event together with the event 'log file sync' can identify the total time consumption and I / O completion of a cycle COMMIT.

Analyzing the information in an AWR report:

In the above example, we can identify a very time-consuming and I / O (ms) for both events 'log file sync' and 'log file parallel write'.

The proportion of time between 'log file sync' and 'log file parallel write' suggests a problem of I / O (Waiting recording redo from memory to disk).

If the time spent in waiting event 'log file parallel write' exceeds 20ms, the likelihood of a problem of I / O is great.

Recommendations

- Check the filesystems where are the Redo Logs, and check possbilidade to optimize the performance of I / O through OS

- Do not use RAID 5 for filesystems / disks where are the Redo Logs.

- Ensure that there are other processes that can be recording information on the same disks where are the Redo Logs. Make sure that the disk has enough throughput for competition of these processes, or change the Redo Logs Filesystem.

- Check if the parameter is not too large LOG_BUFFER. The higher the LOG_BUFFER the longer it takes for the LGWR to write redo the changes to disk.

2 - Check the Traces of the Log Writer (LGWR)

Even if the average waiting time of the event 'log file parallel write' is normal, there may be peaks where the writing of the redo logs is high in influence and then the event 'log file sync'.

From version 10.2.0.4 are generated alert messages in the LGWR trace file when a process LGWR writing takes longer than 500ms. This is a high threshold, but it is a way of identifying problems I / O. Messages are other similar to:

Recommendations

- Check what else is running at the moment to identify gaps recording LGWR.

3 - Check if the size of Redo logs is Enough

An operation 'log file sync' is run every time there is a switch of logfiles to ensure that all information in redos were recorded before the next log starts. As a standard recommendation is that a log switch occurs every 15 or 20 minutes. If the log switches occur in a shorter time, more often, then more wait events 'log file sync' will occur, which means a longer waiting time between sessions.

- You can check the alert.log to check the switch logfile:

In the above switches can be checked every 2 to 4 minutes, which is 5x more frequently than desirable.

- Another option is to check the average Log Switchs through AWR report:

In the example above 29.98 log switches occur every hour, which means about 2 log switches per minute. This is a value much higher than recommended (15 to 20 switches per minute).

Recommendations

- Increasing the size of Redo Log files.

4 - Excessive number of commits by Application

In this case the question is what to do: "The application is performing many commits?"

If so, there may be performance issues, since the redo information are unloaded from memory (LOG_BUFFER) redo logs to disk.

A simple way to identify this scenario is when the average wait for the event 'log file sync' is much larger than average wait event "log file parallel write ', this shows that the longer the waiting is not for recording Disco redo logs. The high CPU time can also show restraint caused by excessive commits.

Another scenario is still where the average wait event "log file sync 'is low but the number of waits is high.

One can compare the average 'User commits' with 'User calls':

The above example could identify 5.76 'user calls' commit by what is considered 5x greater than recommended (1).

Recommendations:

- If multiple commits in the application in a short time interval, or small call commits, it is recommended to execute a block of larger changes before executing a commit. Ateração This should be done through the application.

- Enabling Asynchronous Commit.

Sources:

How to Minimise Waits for 'Log File Sync'? [MOS ID 857576.1]

Troubleshooting: log file sync 'Waits [MOS ID 1376916.1]

========================================================

Log file sync and log file parallel write

s ‘LOG FILE SYNC’ (LFS) relevant?

Arguably the single most misleading wait event in the Oracle database is ‘log file sync’ (LFS). Let me explain why. Suppose you have a single client process and it spends 1% of its time in LFS. Would you gain a lot by engaging in a tuning exercise that aimed exclusively at reducing this wait event? Well, obviously the upper limit on the gain you might make is 1% even if you eliminated these events in their entirety; the answer is, therefore, NO. You are unlikely to waste your time though because your Statspack or AWR report will probably not highlight the event in the first place.

On the other hand, suppose you have 10,000 sessions connecting to your database and 300 of these are active at any one time. Suppose that 1% of the active time of each session is spent in LFS would you gain much by tuning the event? The answer is the same as before: NO. However, you might be misled by Statspack or AWR because now the total wait time for the database for LFS will be 3 hours in any one hour! This is because at any one time we have 300 active sessions and on average three of them will be in LFS. That comes out to be 3 hours per hour waiting! So before you conclude that LFS is a major performance issue first check out what the average wait time per active session is. Of course, what you should really do is find out the percentage of wait time for your business critical processes but I digress again. Let us get back to the technicalities of LFS.

‘Log File Sync’ (LFS) versus ‘log file parallel write’ (LFPW)

When a transaction commits it will usually wait for its redo data to be recorded on disk before returning control to the application. That wait is LFS. There are three main exceptions to this:

• When the commit is issued within a PL/SQL block. In this case the wait will be deferred until the block returns. If the PL/SQL block contains multiple commit statements then only one wait will occur when the block returns.
• When the commit statement is actually COMMIT WORK NOWAIT. In this case, there is no LFS wait. See part 3 in this series for an explanation of why this is dangerous.
•  When the session parameter COMMIT_WAIT (COMMIT_WRITE in earlier releases) is set to NOWAIT. This parameter can be set at the instance level but this is dangerous practice and should be set at the session level only with care. See part 3 in this series for an explanation of why this is dangerous.

The waiting client process does not do the I/O itself. LGWR does. When LGWR does the I/O it waits on ‘log file parallel write’ (LFPW). So does this mean that the number of LFPW events should equal the number of LFS events? NO! This is because LGWR employs a tactic known as ‘group write’ and may write out the redo data for multiple transactions and multiple sessions in one go. Suppose you have 5 client processes each of which is waiting for its transaction to complete. These transactions will be waiting for LFS. LGWR will be waiting for LFPW. If the I/O takes 10ms then:

• The system will accumulate 50ms of time in LFS (10ms for each client process). 5 wait events will be recorded.
• LGWR will accumulate 10ms. One wait event will be recorded.

That is 6 wait events totalling 60ms clocked up for one 10ms I/O! You see the danger in oversimplifying?

In the simplified example above I have suggested that the average wait time for LFS should be about the same as the average wait time for LFPW as they are both associated with waiting for the redo data to be written to disk. In fact, this is itself a misleading simplification

====

n reality, Oracle now uses a combination of ‘private redo strands’ and ‘public redo strands’.

Private redo strands do not exist in instances within a RAC cluster.  In a non-RAC environment each transaction gets its own redo strand (subject to availability).  These strands are used in combination with in-memory undo (IMU) to reduce the amount of data that is logged but more importantly to reduce latching conflicts; data is normally copied from a private redo strand only at commit time.  Data will also be copied out if the private redo strand fills up before a commit is issued.  These private redo strands are allocated from shared pool.

RAC or no RAC there is also a minimum of two public redo strands as well.  In larger systems there may be more (number of CPUs divided by 16).  These public redo strands also contribute to latch reduction.  The number of these strands can be changed by use of the hidden parameter“_log_parallelism_max”.

In relatively quiet systems only one public redo strand may be in use but even with as few as two concurrent sessions busy generating redo you can see the second redo strand being used.  When that happens, LGWR writes out the data in the public redo strands sequentially!

How do I know this?

Well, I was performing a rather artificial insert-only performance test on one instance of an 11.2 RAC database on a 64-CPU system with a suspected faulty I/O subsystem (don’t ask).  LGWR was spending 90% of its time in ‘log file parallel write’ (LFPW) and about 10% of the time on the CPU.  I had taken the advice in Kevin’s article above and “reniced” LGWR so I was fairly sure that LGWR rescheduling was not a big issue: throughput was limited by the I/O subsystem.

Nevertheless, ‘log file sync’ (LFS) wait events averaged 4 or 5 times the LFPW times despite the average CPU utilisation only being about 25%.  Theoretically, one would expect that the average LFS time would be somewhat more than 50% higher than LFPW in a system that is limited by LGWR I/O:  if LGWR has just started an I/O at the time that you commit then you have to wait for that I/O to finish as well as your own that follows.  If you are luckier LGWR may just finish an I/O as you commit and now you just have to wait for your own I/O. This gives an average LFS/LFPW ratio of 1.5.  Given the fact that you are still in LFS when LGWR is on the CPU doing its post processing I thought that LFS should be a little higher than 50% above LFPW but certainly not 300% or 400% higher.

Explanations revolving around ‘CPU storms’ didn’t seem plausible so I had to dig deeper.  Well, by ‘digging deeper’ I mean a) posting a question on OTN and asking for help from ‘knowledgeable friends’.  When that failed b) guessing.  I eventually guessed correctly when I set “_log_parallelism_max” to 1 (it was previously 4 on my 64 CPU system).

The faulty I/O subsystem had (has) a characteristic that throughput is several times higher when the I/O size is larger.  The reason for this is not yet known.  However, when the initialisation parameter change was made:

• The average size of the I/O increased several times
• The (faulty) I/O subsystem throughput increased several fold
• The LFS time came back down to just over 50% of the LFPW time.
• LGWR started waiting on the idle event ‘rdbms ipc message’; the system was no longer limited by I/O.
• Latching increased thus proving that the long term solution was to fix the I/O subsystem not make unsupported changes to initialisation parameters!

I then set about trying to devise some kind of experiment that others can repeat to verify my conclusions.  The problem is that the only way to get more than one public redo strand in play is to have sufficient redo being generated that a redo allocation latch collision occurs.  You can easily generate this scenario.  You can also prove that the number of transactions being committed each write (redo size/commit size) is much less than the number of processes in LFS but I can’t think of a way to prove that this discrepancy is caused by I/O serialisation without a faulty I/O subsystem.  Sure you can run a trace and see that there are multiple LFPW events between idle ‘rdbms ipc message’ events but that is hardly conclusive.

====

when a COMMIT from a PL/SQL might impact ACID properties and to explain why 99% of the time it didn’t.  At the time I wrote this blog the assumption was that ACID properties could confidently be assigend to standard COMMIT statements executed from SQL (e.g. SQL*PLUS, JDBC, etc.).  As you will see in the comments to this blog this is far from the case.  I have annoted the false assumption in bold.

The first thing to get your head round is that PL/SQL language statements are different from SQL statements. When you issue a COMMIT statement from SQL*PLUS, from Java, C, or almost all other languages you need to refer to the “SQL Language Reference” manual for syntax and semantics. When you issue a COMMIT statement (or one of the other seven SQL statements with direct PL/SQL equivalents) from PL/SQL, however, you need to look in “PL/SQL Language Reference” manual for syntax and semantics. Sure, they do very similar things but there are subtle differences.

In the 11.2 SQL Language Reference manual, you will see this statement:

If you omit [the write clause], then the behavior of the commit operation is controlled by the COMMIT_LOGGING and COMMIT_WAIT initialization parameters, if they have been set.

The COMMIT_LOGGING and COMMIT_WAIT parameters replace the COMMIT_WRITE parameter used in previous releases. Unfortunately, the documentation for COMMIT_WRITE is at best incomplete and at worst wrong. To see what the default semantics are we need to look at the documentation for the deprecated COMMIT_WRITE parameter. Here we can see:

If this parameter is not explicitly specified, then database commit behaviour defaults to writing commit records to disk before control is returned to the client.

We also see this line:

Be aware that the NOWAIT option can cause a failure that occurs after the database receives the commit message, but before the redo log records are written. This can falsely indicate to a transaction that its changes are persistent. Also, it can violate the durability of ACID (Atomicity, Consistency, Isolation, Durability) transactions if the database shuts down unexpectedly.

This is poor English but obviously sounds scary. Most programmers would and should avoid using NOWAIT in their programs or overriding the default session or system initialisation settings. However, let us look at the documentation in the PL/SQL reference manual:

The default PL/SQL commit behaviour for nondistributed transactions is BATCH NOWAIT if the COMMIT_LOGGING and COMMIT_WAIT database initialization parameters have not been set.

Whoa! Suddenly the behaviour that you were warned might cause a violation of the durability of durability (that is what it says isn’t it?) is now the default behaviour! Why is something that is so dangerous from SQL suddenly safe from PL/SQL and why?

Well, as we shall see it isn’t always safe. But to understand what is safe and what is not safe let me try to expand on the scary documentation from the SQL language reference manual. Consider this piece of pseudo-code from some non-PL/SQL program:

   do some DML;
   commit;
   put_on_screen('Transaction complete') ;

Imagine that the commit returned immediately without waiting for the data to be recorded on disk. You might tell the user that the transaction committed and then the database might crash causing all the DML to be lost. You have misled the user. What if, however, the ‘user’ was another computer system or database?

    get a message from a remote system;
    do some DML;
    commit;
    send confirmation of receipt of message to remote system;

Well, a human might (or might not) realise that there was a crash around the time his message was displayed saying that his transaction completed but a remote computer system will not be so paranoid. It is highly unlikely that such a remote application would retransmit a message if it receives an explicit positive acknowledgement to the first transmission.

So this is why the default behaviour for SQL is to wait until the transaction details are recorded in the redo log on disk; it is to ensure that if the application relays the fact that the transaction is committed to a third party (human or computer) that the transaction isn’t later discovered to be ‘uncommitted’ so to speak. This is the “durability” part of ACID.

Now that we have that sorted out let us turn our attention to PL/SQL. First of all, the documentation here is “incomplete”. Let me try and expand:

• For all but the last commit statement executed before PL/SQL returns control to the caller the default PL/SQL commit behaviour for nondistributed transactions is BATCH NOWAIT if the COMMIT_LOGGING and COMMIT_WAIT database initialization parameters have not been set.
• The default behaviour for the last commit statement executed before PL/SQL returns control to the caller is to trigger a wait at the point control is returned to the caller.
• Sometimes you will experience a ‘log file sync’ wait event even if you explicitly or implicitly specify NOWAIT.

Ok, so the semantics are not only apparently dangerous but also complicated. Why?

Well let us take an example PL/SQL block and add some measurements of ‘log file sync’wait events.  Let us begin by creating a test table:

CREATE TABLE T1 (dummy varchar2(100)) ;

Now our test:

 SELECT total_waits
  FROM v$session_event
 WHERE sid = USERENV ('SID') AND event = 'log file sync';

BEGIN
   INSERT INTO t1 (dummy)
        VALUES ('Transaction 1');

   COMMIT;

   INSERT INTO t1 (dummy)
        VALUES ('Transaction 2');

   COMMIT;
END;

SELECT total_waits
  FROM v$session_event
 WHERE sid = USERENV ('SID') AND event = 'log file sync';

We see only one ‘log file sync’. This is the one triggered at the end of the block by the second commit. The first commit triggered no wait. However, no risk of a consistency problem arises. This is because:

• Locking will prevent either inserted row being visible to outside sessions until the redo is actually on disk and

The statement above is how databases in general are supposed to work.  Oracle does not work this way, however: commits from PL/SQL or SQL are visible to other sessions before they are actually on disk.  See the comments below for more discussion.

• The second transaction will have a higher SCN than the first and in the event of a crash Oracle will ensure that if the first transaction needs to be rolled back the second will be also.

This can be a bit tricky to get your head round but it is a legitimate optimisation that I believe (historians are welcome to correct me) was first introduced in IMS Fastpath many decades ago and has been copied by Oracle and other database systems subsequently.

When I have explained this to other DBAs and programmers over the years I have known when the point has been understood when I get the question:

“Yes, but what if I communicate the commit outside of the PL/SQL block by some means other than updating the database”?

This question indicates a grasp of the key concept. Unfortunately, I have always answered this question incorrectly! Let us get one easy case out of the way first:

BEGIN
   INSERT INTO t1 (dummy)
        VALUES ('Transaction 1');

   COMMIT;
   DBMS_OUTPUT.put_line ('Transaction committed');
END;

This is actually safe because the results of DBMS_OUTPUT.PUT_LINE are invisible until after the PL/SQL block returns. So if the supposedly committed transaction is subsequently rolled back nobody will ever have known that the commit statement returned to the PL/SQL block in the first place.

But what about this:

SELECT total_waits
  FROM v$session_event
 WHERE sid = USERENV ('SID') AND event = 'log file sync';

DECLARE
   filehandler   UTL_FILE.file_type;
BEGIN
   INSERT INTO t1 (dummy)
        VALUES ('Transaction 1');

   COMMIT;

   INSERT INTO t1@dblink (dummy)
        VALUES ('Transaction 2');

   COMMIT;
   filehandler :=
      UTL_FILE.fopen (
                      'DATA_PUMP_DIR',
                      'test_file.txt',
                      'W'
                     );
   UTL_FILE.putf (
                  filehandler,
                  'A transaction committed\n'
                 );
   UTL_FILE.fclose (filehandler);

   INSERT INTO t1 (dummy)
        VALUES ('Transaction 3');

   COMMIT;
END;

SELECT total_waits
  FROM v$session_event
 WHERE sid = USERENV ('SID') AND event = 'log file sync';

You might have to run this a couple of times as there is sometimes an ‘extra’ ‘log file sync’ wait event but most of the time there will only be one wait for the entire PL/SQL block. The use of a database link doesn’t mean there is a distributed transaction because there are no changes to the local database in the transaction. If the local database crashes neither the update to the text file nor the update to the remote database will be “rolled back” so an inconsistency can arise after all.

Until I started to prepare for writing this blog I had always assumed that whenever a remote database was updated or a package such as UTL_FILE or UTL_HTTP was called then a ‘log file sync’ would occur at that point. This is such a fundamental requirement of database consistency, it never occurred to me to check. Not only that, but the PL/SQL engine knows enough to do this easily. However, even in 11.2 this is not the case. You can protect against these inconsistencies by changing your PL/SQL COMMIT statements (the last being optional) to ‘COMMIT WORK WRITE WAIT’ statements.

So when is it safe to use COMMIT WORK WRITE NOWAIT (either explicitly or not)?

• If the only thing you do between ‘commit number one’ and ‘commit number two’ is issue queries and/or updates to the local database it is safe for ‘commit number one’ to use NOWAIT. This is true both for PL/SQL and SQL.
• If you commit a transaction and then your program terminates completely then it is safe to use NOWAIT. This is true for both SQL and PL/SQL.
• If you commit a transaction and then ‘communicate with the outside world’ then you should wait (explicitly in PL/SQL) if you care about consistency.

==========================================================