Blogroll

What is ‘rdbms ipc message’ wait event?

There was a question about the wait event ‘rdbms ipc message’ in Oracle-l list. Short answer is that ‘rdbms ipc message’ event means that a process is waiting for an IPC message to arrive. Usually, this wait event can be ignored, but there are few rare scenarios this wait event can’t be completely ignored.

What is ‘rdbms ipc message’ wait means?

It is typical of Oracle Database background processes to wait for more work. For example, LGWR will wait for more work until another (foreground or background ) process request LGWR to do a log flush. In UNIX platforms, wait mechanism is implemented as a sleep on a specific semaphore associated with that process. This wait time is accounted towards database wait events ‘rdbms ipc message’.

Also note that, semaphore based waits are used in other wait scenarios too, not just ‘rdbms ipc message’ waits.

Time to Trace

We will use UNIX utility TRUSS to trace system calls from LGWR; We will enable sql trace on LGWR process. Using the output of these two methods, we will explore this wait event.

Note, Enabling sql trace on LGWR is not a grand idea in a production environment, actually, even in environments where the performance is vital, so, try this test case only at home. Next section below prints few lines from the trace file of that LGWR process.

I tagged the lines with comment to improve readability and refer to those line numbers while reading this paragraph. There are few important points to understand:

As you may know, these trace lines are printed after the completion of waits. In Line #1, LGWR process completed a wait of 3 seconds and woken up at 2012-02-10 13:42:34.333 time. Essentially, LGWR was sleeping for 3 seconds between 13:42:31.333 and 13:42:34.333.

At Line #2 and Line #3, LGWR was sleeping for full three seconds.

But, in Line #4, elapsed time of ‘rdbms ipc message’ is 0.8 seconds, meaning, LGWR slept for 0.8 seconds only (not full three seconds). Line #5 shows that LGWR wrote a log block to the log file.

In a nutshell, LGWR is sleeping on ‘rdbms ipc message’ for full 3 seconds if there is no work to be done. Another process can wakeup LGWR process and trigger a log write as indicated in line #4 and line #5. I will disable SQL trace on LGWR at this point and then truss LGWR process.

LGWR truss

Let’s truss the LGWR process and match the pattern with the trace file. Truss command I am printing here will work in Solaris/hp platform. In Linux, you would use strace -ttT command to trace the UNIX process.

From the output of truss command above, we can understand LGWR behavior better. Second column prints the time offset from the base timestamp.

At time offset 12.2573, LGWR went in to sleep calling the semtimedop call. I will explain about semtimedop system call shortly.

At time offset 15.2576, LGWR was woken up from the sleep (meaning, that semtimedop call returned after three seconds of timer expiry).

LGWR went to sleep again for three seconds immediately after( possibly because no work to be done) and woken up at 18.2582 time offset. Similar 3 seconds timer expiry occured at 21.2589 time offset also.

It gets interesting at 23.8895 time offset. LGWR was (rudely!) woken up at 23.8895 time offset without allowing the LGWR to sleep for full three seconds ( 2.6 seconds). You can see few kaio calls (kaio kernalized async i/o calls) later and LGWR was submitting asynchronous I/O calls to the redo log file.

semtimedop

UNIX system call semtimedop is used by Oracle processes to sleep with a timer. In this example, LGWR called semtimedop system call with a 3 second timeout. Calling semtimedop system call with 3 seconds timer will suspend the process. Kernel will schedule the UNIX process in CPU (LGWR in this example) if one of these two conditions occur (a) Timer expired as requested by the process or (b) another process modifies this specific semaphore.

In our example, if there is no work, then, the LGWR process will sleep for full 3 seconds until the expiry of semaphore timer; If there is work to be done prior to that 3 seconds timer expiry, then another process will modify the semaphore associated with LGWR and so, Kernel will wakeup LGWR and schedule the LGWR in the CPU. LGWR will perform a log flush sync subsequently.

Advantage with this approach of sleep using semaphore with a timer expiry is that process will not consume any CPU while suspended.

This semaphore based sleep is analogous to a parent sleeping on a Saturday morning. Parent will wakeup if the timer goes off at 7:30 AM or if the kids wakeup prior to that alarm :)

Evidently, you can see that when the LGWR process is sleeping on semaphore, then the time is accounted towards the wait event ‘rdbms ipc message’. You should also remember that semaphores are created as semaphore sets and semctl system call allows the code to modify a specific semaphore in a semaphore set.

semtimedop is used in numerous places

Wait event ‘rdbms ipc message’ is not the only wait event associated with semtimedop system call. There are numerous places semtimedop call is used. Let’s examine a row level locking contention with two processes.

-- In session #1, we update a row.
SYS@solrac1:1>@mypid
SPID
------------------------
3100
SYS@solrac1:1>update rs.t_one set v1=v1 where n1=100;
1 row updated.
----------------
-- In session #2, we will find our PID and then, and then try updating the same row leading to locking contention.
----------------
SYS@solrac1:1>@mypid
SPID
------------------------
3048
SYS@solrac1:1>update rs.t_one set v1=v1 where n1=100;

At this time, PID 3048 is waiting for a lock. We will TRUSS PID 3048, to explore this concept further.

Under the cover, PID 3048 is waiting on a semaphore (its own semaphore) in a tight loop with a 0.5 seconds timer expiry. So, essentially, process is sleeping on the semaphore with a 0.5 seconds timer, wakesup after 0.5 seconds of timer expiry, and sleeps again in a loop. At this time, From session #1, I rolled back the changes with a rollback command (commit also will behave exactly the same). Process associated with session #1, identified next waiter in the waiting queue, woke up the waiting process by modifying the semaphore of the waiting process, at 17.2466 time offset. You can see that sleep time for the last semtimedop call is just 0.24 seconds and the semtimedop call returned with a return code of zero. If the timer expired, then EAGAIN is returned as a return code, if not, then 0 is returned. Remember that EAGAIN is not an error and just a timer expiry.

But, in the case of enqueue contention, even though semaphore based sleeps were used, time is accounted towards the wait event ‘enq: TX – row lock contention’. As you see, semaphore based sleeps can be used for waits for many wait evens.

select spid from v$process where
addr = (select paddr from v$session where sid=(select sid from v$mystat where rownum =1))
;

Summary

In Summary, this wait event can be ignored. In rare cases, this used to be a platform bug in 7.0 database version, semtimedop will not return even if another process modifies the semaphore. So, generally, this event is an idle event and as such, should be ignored.

8 Responses to “What is ‘rdbms ipc message’ wait event?”

Great post, as always .
Could You elaborate about ‘reliable message’ which looks similiar but there are a lot of bugs related to this wait .
Most annoying I’ve found was ‘DBMS_SERVER_ALERT.SET_THRESHOLD HANGS FOREVER AT RELIABLE MESSAGE [ID 794589.1]’.
Proces waiting on such wait even after being killed with -9 signal is still present in Oracle, and PMON is unable to deal with that .
I had to restart whole rac to make it stable .
Looks like PMON is unable to clear such hanging processes .
Regards
GregG