Blogroll

Performance issue: High Kernel mode CPU usage

Recently, we resolved a performance issue with one of our esteemed clients. Problem was interesting and worth blogging about it.

Problem
An application makes 300 static connections to database DB1 in database server, say CLNTDB server. Application relies on database link and over a period of time, each session executes SQL through a database link, creating a connection in central database PROD1. So, there are 300 connections in PROD1 database coming from DB1 database through database links. Performance is fine during normal operation.

Problem starts when the application is shutdown. Shutting down the application in DB1, creates massive CPU consumption in PROD1DB server. Unfortunately, this spike in CPU usage lasts for 5-10 seconds and causes ASM heartbeat to fail. Considering that PROD1 is a central database and this has a global effect on application(s) functionality. See presentation below for graphical representation of this problem.

Symptoms
Looking at symptoms in detail, it is visible that CPU usage in sys mode. It is not uncommon to see high CPU usage during a storm of disconnects. But, this specific CPU usage is much higher and uses all CPUs in kernel mode. If this is a problem due to process destruction, then this will show up in CLNTDB server too as there are 300 disconnects there too. But, this problem manifests only in PROD1DB server.

mpstat output from PROD1DB server shows that CPU usage in %sys mode. Notice the numbers below under sys column. almost all CPUs are used in sys mode. We need to drill down further to understand why this much CPUs are used in sys mode. It is also visible that no other columns have any abnormal higher values.

Test case
Let’s analyze this issue for a single connection to simplify the problem. Created a test user in DB1 database, created a private database link from DB1 to PROD1 and then executed a select statement over that database link.

At this point, a database link connection has been created in PROD1 database. Querying v$session in PROD1 database to find session created for database link. SID 4306 is the session created for our test connection from db1 database.

Associating this session to v$process, found UNIX process for this session. Now, we will start truss on this UNIX process( Solaris platform).

truss -p -d -o /tmp/truss.log

In DB1 executed: exit

This will disconnect session in PROD1 database.

Truss output
Truss output contains activity generated for disconnect in PROD1 server. Reading through truss output, we can see that system call (shmdt) consumed CPU time. Each shmdt call consumes approximately 24ms from output below (18.5053-18.4807=0.0242). We are using -d flag as above to print time spent in that call. Of course, this is a system call and so this CPU usage will be in kernel mode.

So, one disconnect executes 10 system calls and consumes approximately 0.24 CPU seconds in kernel mode. Shmdt calls are used to detach from shared memory segment. Since there are 10 shared memory segments ( as visible in ipcs -ma), 10 shmdt calls are executed per session disconnect.

Projecting this calculation for 300 connections, CPU consumption will be for approximately 72 seconds in total. With 16 CPUs, at least, 5-6 seconds will be used in kernel mode, assuming linear projections[ But, in practice, due to mutex calls and such this may not be linear and will be over 72 seconds]. This is matching with our observation: 5-10 seconds of CPU consumption in kernel mode. First thing, we need to do is reduce # of shmdt calls. One way is to reduce # of shared memory segments.

Shared memory segments
We thought that SHMMAX kernel parameter is limiting since SGA size was bigger than SHMMAX size. After changing SHMMAX parameter, restarting server and such, still many shared memory segments were created.

_lgrpsys calls indicates that there is some form of NUMA activity going on here. pset_bind is used to bind a thread or process to a specific processor set.

Enter NUMA.

NUMA or Locality groups

NUMA stands for Non Uniform Memory Access. In high end SMP systems backplane bus can become a bottleneck. In non-NUMA platforms all memory access must go through system bus and system bus can reduce scalability. NUMA technology (aka ccNUMA) was introduced to relieve symptoms of this bottleneck. Every processor has its own local memory and connected by some form of hardware interconnect. A differentiation is also made between local and remote memory in NUMA based servers. Access to local memory has less latency compared to access to remote memory from a processor set. There is enormous amount of literature available about NUMA. Refer Wiki entry for NUMA and Kevin Closson blog and also my presentation below.

In Solaris, NUMA is implemented as locality groups. In a oversimplified way, a process running in a locality group will have much less latency accessing memory local to that group. As the “remoteness” of memory increases, latency also increases. In future releases of Solaris, this locality might be applied to other resources such as I/O.

To optimally use NUMA technology, Oracle code is spreading SGA in to all locality groups. Then a DBWR is assigned to that locality group. pset_bind calls binds that DBWR to a specific locality group or processor set. [ I think, LGWR is also assigned and bound to a processor set, but I have no confirmation of that ].

Now, we understand that why there are 10 shared memory segments for this SGA.

I was curious, with 12 CPUs in the server, do we really have these many locality groups defined? or Is there some kind of bug that we are hitting ?

Locality group
To find locality group, lgrpinfo can be used to get locality group details. We found identical machine architecture, and installed observability tools from Observability tools for NUMA .

There are many locality groups defined in Solaris. Local groups are defined as an hierarchy and 7 of them are leaf node local groups. In the output above, lgroup 0 is the root group. Intermediate groups are 10,12,14,15,17,19,23.

locality group latencies can be easily seen lgrpinfo -l command. From output below, it is visible that access to local memory has lower latency (for example accessing memory area 1 from locality group 1 is 51), whereas access to remote memory is 146 for accessing locality group 24. These numbers are not actual latency, merely a relative representation of latency.

Recap
High kernel mode CPU usage is due to excessive # of calls to shmdt. There are 10 shmdt calls per disconnect since there are 10 shared memory segments. SGA is spread across NUMA nodes creating these many segments.

Summary

Indeed 10 shared memory segments were created to use NUMA technology. NUMA is an excellent technology and it is a pity that we are suffering from a side effect of NUMA. We need to resolve this issue and We have couple of options at this point:

13 Responses to “Performance issue: High Kernel mode CPU usage”

I wonder if this is why 10g2 has introduced a “_logout_storm_rate” parameter to limit the number of detaches per second ? I had assumed that it was related to process cleanup in the shared pool – but your problem is much more dramatic.

Do you know if the initial ‘shm attach’ call is equally expensive on CPU, or is it just detach that is expensive ?

Is it possible that the cost of detaching is related to the size of the memory map that has been constructe as the process used memory ? (In which case large pages or ISM might be helpful).

[…] Jonathan Lewis @ 6:40 pm UTC Nov 2,2008 Browsing through a few blogs over the weekend, I found this interesting item from Riyaj Shamsudeen about tracking down a lost ASM heartbeat and excessive CPU usage on […]

I wonder if you are running on a Solaris/AMD Opteron: Oracle on Solaris considers each Opteron processor as a unit on par with a SPARC domain. An eight 2-cores system with a 32GB RAM will hold eight Oracle ccNUMA nodes. Oracle’s SGA will be split in small 2-4 GB chunks depending on the SGA allocation. Small chunks relative to the allocated SGA lower the probability for a thread to access its “local” memory. This can make the whole scheme irrelevant and possibly creates overhead and bugs (such as bug 5173642 references in Metalink) for non-partitioned servers.

_enable_NUMA_optimization was available (default value: FALSE) until Oracle 10.1.0 and was made obsolete in 10.2.0.
_db_block_numa is since Oracle 10.2.0.2 the number of Numa “nodes”. The “node” is the ccNUMA awareness unit.

Hi Tanel
Thanks for the idea about LOGOFF trigger. That’s a cool idea to explore and use global context variables to keep track of rate of disconnects. Yes, -c flag might have been more accurate in that truss output.

Hi Christian
Let me check on hardware configuration. It’s a Solaris zone and I don’t have much access in client environment.

Hi Freek
Yes, that was a mistake..Should be 16 CPUs and will correct it. I think, they are dual core CPUs.

Ryan Matteson, An excellent solaris system administrator [ with our client] said: ” That would make sense, since each processor has a built-in memory controller that has direct access to one or more banks of memory. CPUs are: Dual-Core AMD Opteron(tm) Processor 8220 CPU ”

Thanks for reading my blog and for your kind words. Thank you for pointing out that bug. Our problem (Early September) actually predates that bug date ( 23-OCT-2008) and I didn’t see that bug report earlier either. I am printing a summary of the bug below.

Bug summary: In 10.2.0.4 NUMA features were enabled by default and this can cause issues in platforms/hardware without NUMA capability. Workaround is to disable NUMA.

In this specific case though, hardware had NUMA capability as shown in lgrpinfo output. Just that we were hitting a side effect of NUMA capability.

Hello Lscheng
Can you post URL or document id referring to those best practices here, please? I am trying to understand why such an important feature[ at least, in high-end servers] would need to be completely turned off..