Mutex waits. Part II. “Cursor: Pin S” in Oracle 11.2 _mutex_wait_scheme=0. Steps out of shadow.

I would like to describe how Oracle versions 11.2.0.1-11.2.0.2.1 waited for mutexes. This algorithm also appears to be used in post-11.2.0.2.2 PSUs and new 11.2.0.3 patchset as _mutex_wait_scheme=0.

My previous post demonstrated that before version 11.2:

• “Cursor: pin S” was pure wait for CPU. Long “cursor: pin S” waits indicated CPU starvation.
• Mutex contention was almost invisible to Oracle Wait Interface
• Spin time to acquire mutex was accounted as CPU time. It was service time, not waiting time.

Things changed. Mutex waits in Oracle 11.2 significantly differ from previous versions. Contemporary mutex waits are not CPU aggressive anymore, completely visible to Oracle Wait Interface and highly tunable.

I. Oracle 11.2.0.1. Mutex spin visibility

In previous post, I introduced the testcase in which session waited for mutex during 49 sec. In Oracle 11.2.0.1 for Solaris SPARC on T2000 server, this testcase results in the following AWR report:

sqlplus /nolog @cursor_pin_s_waits.sql
...

Top 5 Timed Foreground Events

Event	Waits	Time(s)	Avg wait (ms)	% DB time	Wait Class
DB CPU		55		99.84
cursor: pin S	1	49	49261	89.05	Concurrency
db file scattered read	87	0	1	0.14	User I/O
db file sequential read	360	0	0	0.06	User I/O
control file sequential read	89	0	0	0.00	System I/O

Previously, in versions 10.2-11.1 Oracle Wait Interface registered millions “cursor: pin S” waits of microseconds duration. In 11.2.0.1 the testcase demonstrated single “wait” for 49 sec. However, truss reveals many yield() syscalls exactly like in previous versions:

truss -p 14287
...
/1:	yield()						= 0
/1:	yield()						= 0
/1:	yield()						= 0
/1:	yield()						= 0
...

Essentially, this is busy wait exactly as in 10.2. It is not surprising to find millions of “sleeps” in v$mutex_sleep_history section of AWR report:
…
Mutex Sleep Summary

Mutex Type	Location	Sleeps	Wait Time (ms)
Cursor Pin	kksfbc [KKSCHLCREA]	2,734,166	0

…
Like 10.2, the “wait time” appeared in this table supposedly is the summary time spent in CPU runqueue during yield() syscalls. It is zero in my testcase, I think due to a bug. Oracle 11.2.0.1 mutex is the same “classic” spinlock without sleeps as before.

On the other hand, Oracle 11.2 Wait Interface computes “wait time” as a duration between the first spin and successful mutex acquisition. As a result we observe only one wait in v$system_event.

Oracle 11.2 mutex wait includes both spinning and waiting. Therefore, it is “expected” to observe longer mutex waits after upgrade. You may see a lot of such bugs on MOS. Previously invisible, mutex contention steps out of the shadow in 11.2

Naturally, in 11.2 the significant part of “cursor: pin S” mutex wait time is pure spinning. This spinning also accounted as CPU time. However, the double accounting is not propagated into “DB time” statistics. As a result, in previous “Top 5 Events” table we observe two rows constituting 90% of “DB Time” each.

It is straightforward to compute an average time of “spin and yield” mutex cycle. We observed 2,734,166 cycles during 49.261 sec. One cycle took around 49/2,734,166 18 us. This is the large time. Another core of my 1.2GHz T2000 can execute 22 thousands instructions during this time and release the mutex.

In summary, the 11.2.0.1 the “Cursor: Pin S” waits became more visible, but still aggressive as were in previous versions. This also applies to “library cache: mutex X” events.

II. Oracle 11.2.0.2. No more excessive CPU consumption

The testcase in 11.2.0.2 on the same server demonstrated almost twice less CPU consumption and sleeps:

Top 5 Timed Foreground Events

Event	Waits	Time(s)	Avg wait (ms)	% DB time	Wait Class
cursor: pin S	1	49	49259	91.71	Concurrency
DB CPU		36		67.21
db file scattered read	1175	0	0	0.07	User I/O
db file sequential read	482	0	0	0.06	User I/O
control file sequential read	91	0	0	0.01	System I/O

…
Mutex Sleep Summary

Mutex Type	Location	Sleeps	Wait Time (ms)
Cursor Pin	kkslce [KKSCHLPIN2]	1,739,264	0

The mpstat utility confirms that the process waiting for “cursor: pin S” no more consumes the processor entirely. The truss output showed that in addition to yield() syscalls the waiting process sometimes issue pollsys() syscall with 1 ms timeout. This is sleeping system call.

DTrace script syscalls_in_mutex_wait.d traces system calls made by Oracle process inside the mutex wait. The script reveals interesting pattern. Process slept during 1 ms after 99 yields:

sql>@cursor_pin_s_waits.sql
...
kgxSharedExamine()
  yield() call repeated 99 times
  pollsys()   timeout=1 ms
  yield() call repeated 99 times
  pollsys()   timeout=1 ms
  yield() call repeated 99 times
  pollsys()   timeout=1 ms
...

It is these short waits that decrease CPU consumption. It is worth to note that for consistency with other platforms I configured millisecond timer resolution in my Solaris using hires_tick=1. See the discussion below.

Let us crosscheck the times. “Spin and yield” cycles consumed 1,739,26418us=31 sec. The remaining 49-31=18 seconds were spent in 1,739,264/100=17,392 sleeps. Average sleep duration was 18/17,3921.03ms as expected.

On Linux platform Oracle 11.2.0.2 uses sched_yield() and select() syscalls in mutex wait. Both calls counted as sleeps in v$mutex_sleep.

Therefore, the 11.2.0.2 the “cursor: pin S” wait event no more starve CPU. This reduces probability of CPU thrashing due to mutex waits.

III. Yield and sleep tuning parameters

It makes sense to dig deeper inside this waits pattern because it is used since 11.2.0.2.2 PSU as _mutex_wait_scheme=0. In fact, my further experiments used 11.2.0.2.2.

One millisecond sleep per hundred yields? These values should be tunable. Quick search found interesting family of parameters:

SELECT indx + 1 num,ksppinm NAME,ksppstvl VALUE,
       DECODE (BITAND (ksppiflg / 65536, 3),1, 'IMMEDIATE',2, 'DEFERRED',3, 'IMMEDIATE','FALSE') 
           ISSYS_MODIFIABLE,
       ksppdesc DESCRIPTION
  FROM x$ksppi x  join x$ksppcv using (indx ) 
 where ksppinm like '%yield%';

NUM	NAME	VALUE	ISSYS_MOD	DESCRIPTION
31	_wait_yield_mode	yield	IMMEDIATE	Wait Yield – Mode
32	_wait_yield_hp_mode	yield	IMMEDIATE	Wait Yield – High Priority Mode
33	_wait_yield_sleep_time_msecs	1	IMMEDIATE	Wait Yield – Sleep Time (in milliseconds)
34	_wait_yield_sleep_freq	100	IMMEDIATE	Wait Yield – Sleep Frequency
35	_wait_yield_yield_freq	20	IMMEDIATE	Wait Yield – Yield Frequency

All these “_wait_yield…” parameters were introduced in 11.2.0.2.

The default value of _wait_yield_mode is “yield”. In this mode Oracle process first yields the CPU during mutex waits. The _wait_yield_sleep_freq value (minus one) is the number of yield() syscalls attempted before sleep. The _wait_yield_sleep_time_msecs defines the sleep duration. Let me experiment with them:

SQL>alter system set "_mutex_wait_scheme"=0;
SQL>alter system set "_wait_yield_sleep_time_msecs"=2  "_wait_yield_sleep_freq"=3;
...
kgxSharedExamine()
  yield() call repeated 2 times
  pollsys(...,timeout=2 ms,...)
  yield() call repeated 2 times
  pollsys(...,timeout=2 ms,...)
...

After such change, the process sleeps for mutex during 2 milliseconds on each 3d yield.

The complementary wait mode for scheme 0 mutexes is ‘sleep’. In this mode Oracle process first sleeps then yields. Look at the trace:

sql>alter system set "_wait_yield_mode"='sleep';
sql>@cursor_pin_s_waits.sql
...
kgxSharedExamine()
  pollsys()   timeout=1 ms    call repeated 19 times
  yield()
  pollsys()   timeout=1 ms    call repeated 19 times
  yield()
  pollsys()   timeout=1 ms    call repeated 19 times
  yield()
...

The number of sleeps between yields is determined by the _wait_yield_yield_freq parameter, which defaults to 20. Again, I will demonstrate the effect of parameters change:

sql>alter system set "_wait_yield_mode"='sleep';
sql>alter system set "_wait_yield_sleep_time_msecs"=3 "_wait_yield_yield_freq"=3;
sql>@cursor_pin_s_waits.sql
...
kgxSharedExamine()
  pollsys()   timeout=3 ms    call repeated 2 times
  yield()
  pollsys()   timeout=3 ms    call repeated 2 times
  yield()
  pollsys()   timeout=3 ms    call repeated 2 times
  yield()
...

These parameters provide great flexibility to tune mutex sleeps and yields. I like this mutex wait scheme, because it is more tunable than others. For example, I can easily simulate 10g mutex wait behavior:

sql>alter system set "_wait_yield_mode"='yield' "_wait_yield_sleep_time_msecs"=0;
sql>@cursor_pin_s_waits.sql
...
kgxSharedExamine()
 yield() call repeated 1021648 times
...

In addition, I can simulate the Patch 6904068 with _first_spare_parameter=1 without installing the patch itself:

sql>alter system set "_wait_yield_sleep_time_msecs"=10 "_wait_yield_sleep_freq"=0;
sql>@cursor_pin_s_waits.sql
...
kgxSharedExamine()
  pollsys()   timeout=10 ms    call repeated 4356 times
...

I will discuss in separate posts when and how this scheme should be used to achieve performance gains. Anticipating schemes comparison, I would like to emphasize that this is the fastest and most CPU consuming scheme under moderate mutex contention.

IV. Mutex waits in high priority processes

The “yield” mutex wait mode may cause starvation when Oracle processes run at different priorities. Higher priority processes yielding the CPU are not preempted by lower priority processes. We know that since 10g some of Oracle processes have Real-Time priority. By default only LMS and VKTM processes scheduled in RT class. These processes do not use mutexes. However, we may need to schedule other processes as real-time.

The _wait_yield_hp_mode parameter controls how high priority Oracle processes wait for mutexes. It allows to specify different wait modes for standard and high priority processes. Look how it works:

SQL>alter system set "_high_priority_processes"='LMS*|VKTM|SMON' scope=spfile;
SQL>startup force;
SQL>alter system set "_mutex_wait_scheme"=0;
sql>alter system set "_wait_yield_mode" ='yield' "_wait_yield_hp_mode" ='sleep';

Now SMON process runs at real-time priority class (RT):

$ ps -afec
     UID   PID  PPID  CLS PRI    STIME TTY         TIME CMD
...
  oracle  24070     1   RT 101 05:50:05 ?           0:14 ora_smon_E112
...

It is easy to find using DTrace that SMON in my instance repeatedly acquires mutex at address 0x42CD4C328.

$/usr/sbin/dtrace -ZCs syscalls_in_mutex_wait.d -64 -p 24070
...
kgxSharedExamine(0x10C1E7BE0,mutex=0x42CD4C328,aol=0x43DF48798)
...

SQL protected by this mutex is: “lock table sys.mon_mods$ in exclusive mode nowait“. I will artificially block this mutex using mutex_e_mode.sql script and wait for the next SQL execution:

$sqlplus /nolog @mutex_e_mode 42CD4C328
...
kgxSharedExamine(0x10C1E7BE0,mutex=0x42CD4C328,aol=0x43DF48798)
  pollsys()   timeout=1 ms    call repeated 19 times
  yield()
  pollsys()   timeout=1 ms    call repeated 19 times
  yield()
...

This confirmed the ‘sleep‘ mode for mutex waits in high priority process. At the same time other processes use ‘yield‘ mode.

IV. Platform sleeps granularity

With default Solaris OS parameters the CPU consumption of my testcase drops to 7 seconds. This is due to default 100Hz Solaris timer granularity. It is easy to check using dtruss that “millisecond” sleep actually took 10ms elapsed time. It looks exactly like setting “_wait_yield_sleep_time_msecs”=10 parameter.

Therefore it is not enough to request the 1 millisecond timeout in pollsys() or select(). Operating system itself must support milliseconds sleep granularity.

Not long ago, most Unixes used coarse-grained sleeps with 1 cs precision. For example, even realtime pre-2.6 Linux kernels could not wait with milliseconds sleeps accuracy. Nowadays, the latest RedHat and Oracle Enterprise Linux versions certified for Oracle 11.2 support milliseconds resolution. The same is true for HP-UX.

Solaris had built-in high-resolution waits functionality for twenty years, but still use centisecond granularity by default. To turn on the high-resolution 1000Hz timer one need to add “set hires_tick = 1” into /etc/system and reboot. Most Oracle instances on Solaris operate at 100Hz timer frequency.

Whether this granularity choice makes sense? It depends upon load and degree of mutex contention. The 1 ms sleeps are 10 times shorter then waits used by Patch 6904068 and default mutex wait scheme 2. If you have enough CPU power, short waits may be more beneficial because 10ms is huge time in spinlock world. Session waiting for 1 cs will skip 20 million instructions executed on another 2GHz CPU. Latch waits, for comparison, normally have less then millisecond duration.

Look at the following graph. It compares time to complete my “library cache mutex X” testcase for Solaris T2000 with 100Hz and 1000Hz timers.

Predictably, when the number of threads is small, both graphs are identical. In region of moderate contention, the high-granularity configuration performs upto 10% percents better. However, in high contention region the 100Hz timer definitely wins.

Complementary to the completion time is throughput. For my testcase it is the number of calls to dbms_application_info.set_client_info() per second. The graph below compares the throughputs achieved for both wait resolutions:

We see almost linear increase of througput until all 8 cores of T2000 became busy. Then the Chip MultiТhreading changed the slope. The linearity continues upto 2 CMT threads per core. After this point thrashing diminishes the throughput. Again, the 1000Hz wait resolution is more effective at moderate-, and 100Hz is more robust at the high-contention regions

This section demonstrates that adjustment of timer granularity provides additional tuning possibility for _mutex_wait_scheme=0.

Summary

Here I discussed how “cursor: pin S” mutex wait works in Oracle 11g Release 2 _mutex_wait_scheme=0.
Contemporary mutex waits are not CPU aggressive anymore and became visible to Oracle Wait Interface. I described related Oracle parameters and influence of OS sleep granularity. The next post will explore other mutex wait schemes.