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.

CPU ..intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  0    554  237  651  219   87  491    0  4349    9  91   0   0
  1    911    0 2412  591  353  630    0 15210   30  63   0   7
  2    313    0  613  106  190  105    0  3562    8  90   0   2
  3    255    0  492   92  161  530    0  2914    6  92   0   2
  4     86    1    2    3    1   63    0     8    0 100   0   0
  5    662    0 1269  153  326  211    0  6753   13  77   0  10
  6    349    0  589   54  170 1534    0  3002    7  88   0   5
  7    317   81  411  105   51   61    0  2484    4  93   0   3
  8   6423 6321  697   36  148  546    0  3663    6  86   0   9
  9    363    0  639   41  154 1893    0  3214    9  85   0   6
 10    456    0  964  194  193   77    0  5797   10  81   0   8
 11    104    0   42    3    9  183    0   207    0  95   0   5
 12    195    0  279  110   31   80    0  1590    3  97   0   0
 13    449    0  844  117  158  127    0  4486    7  85   0   8

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.

In db1:

create user test1 identified by test1;
grant connect, resource to test1;
conn test1/test1
create dtabase ink proddb
connect to test1 identified by test1
using 'proddb';

select * from dual@proddb;

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.

select sid, serial#, LOGON_TIME,LAST_CALL_ET from v$session where
  logon_time > sysdate-(1/24)*(1/60) and machine='machine_name_here'
/
       SID    SERIAL# LOGON_TIME           LAST_CALL_ET
---------- ---------- -------------------- ------------
      4306      51273 12-SEP-2008 20:47:29            1

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.

18.4630 close(10)                                       = 0
18.4807 shmdt(0x380000000)                              = 0
18.5053 shmdt(0x440000000)                              = 0
18.5295 shmdt(0x640000000)                              = 0
18.5541 shmdt(0x840000000)                              = 0
18.5784 shmdt(0xA40000000)                              = 0
18.6026 shmdt(0xC40000000)                              = 0
18.6273 shmdt(0xE40000000)                              = 0
18.6512 shmdt(0x1040000000)                             = 0
18.6752 shmdt(0x1240000000)                             = 0
18.6753 shmdt(0x1440000000)                             = 0

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.

That’s interesting! TRUSSing instance startup to understand why multiple shared memory segments are created.

Few lines from truss output shows calls to system calls _lgrpsys and pset_bind.

4.5957 munmap(0xFFFFFD7FFDAE0000, 32768)               = 0
4.5958 lgrp_version(1, )                               = 1
4.5958 _lgrpsys(1, 0, )                                = 42
4.5958 _lgrpsys(3, 0x00000000, 0x00000000)             = 19108
4.5959 _lgrpsys(3, 0x00004AA4, 0x06399D60)             = 19108
4.5959 _lgrpsys(1, 0, )                                = 42
4.5960 pset_bind(PS_QUERY, P_LWPID, 4294967295, 0xFFFFFD7FFFDFB11C) = 0
4.5960 pset_info(PS_MYID, 0x00000000, 0xFFFFFD7FFFDFB0D4, 0x00000000) = 0
4.5961 pset_info(PS_MYID, 0x00000000, 0xFFFFFD7FFFDFB0D4, 0x061AA2B0) = 0

_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 .

Output of lgrpinfo shows locality groups defined in that server.

#/usr/local/bin/lgrpinfo
lgroup 0 (root):
     Children: 10 12 14 15 17 19 21 23
     CPUs: 0-15
     Memory: installed 65024 Mb, allocated 2548 Mb, free 62476 Mb
     Lgroup resources: 1-8 (CPU); 1-8 (memory)?
     Latency: 146
lgroup 1 (leaf):
     Children: none, Parent: 9 <-- leaf node
     CPUs: 0 1
     Memory: installed 7680 Mb, allocated 1964 Mb, free 5716 Mb
     Lgroup resources: 1 (CPU); 1 (memory)?
     Load: 0.105
     Latency: 51
...
lgroup 9 (intermediate):
     Children: 1, Parent: 10
     CPUs: 0-5
     Memory: installed 24064 Mb, allocated 2187 Mb, free 21877 Mb
     Lgroup resources: 1-3 (CPU); 1-3 (memory)
     Latency: 81
...
lgroup 10 (intermediate):
     Children: 9, Parent: 0  <-- intermediate group
     CPUs: 0-13
     Memory: installed 56832 Mb, allocated 2491 Mb, free 54341 Mb
     Lgroup resources: 1-7 (CPU); 1-7 (memory)
     Latency: 113
...

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.

For e.g., for lgroup 1, hierarchy is : 1 -> 9 -> 10 -> 0. 0 is the root group here.

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.

--------------------------------------------------------------------------------------------------------
   |   0   1   2   3   4   5   6   7   8   9  10  11  12  13  14  15  16  17  18  19  20  21  22  23  24
--------------------------------------------------------------------------------------------------------
0  | 146 146 113 113 113 113 113 113 146 146 146 146 146 146 146 146 113 146 113 146 146 146 146 146 146
1  | 146  51  81  81 113 113 113 113 146  81 113 113 146 113 146 146 113 146 113 146 146 146 146 146 146
2  | 113  81  51 113  81 113 113  81 113 113 113  81 113 113 113 113 113 113 113 113 113 113 113 113 113
3  | 113  81 113  51 113  81  81 113 113 113 113 113 113  81 113 113 113 113 113 113 113 113 113 113 113
4  | 113 113  81 113  51  81  81 113 113 113 113 113 113 113 113 113  81 113 113 113 113 113 113 113 113
5  | 113 113 113  81  81  51 113  81 113 113 113 113 113 113 113 113 113 113  81 113 113 113 113 113 113
6  | 113 113 113  81  81 113  51 113  81 113 113 113 113 113 113 113 113 113 113 113  81 113 113 113 113
7  | 113 113  81 113 113  81 113  51  81 113 113 113 113 113 113 113 113 113 113 113 113 113  81 113 113
8  | 146 146 113 113 113 113  81  81  51 146 146 146 146 146 146 146 113 146 113 146 113 146 113 113  81
9  | 146  81 113 113 113 113 113 113 146  81 113 113 146 113 146 146 113 146 113 146 146 146 146 146 146
10 | 146 113 113 113 113 113 113 113 146 113 113 113 146 113 146 146 113 146 113 146 146 146 146 146 146
11 | 146 113  81 113 113 113 113 113 146 113 113  81 146 113 146 146 113 146 113 146 146 146 146 146 146
12 | 146 146 113 113 113 113 113 113 146 146 146 146 113 146 146 146 113 146 113 146 146 146 146 146 146
13 | 146 113 113  81 113 113 113 113 146 113 113 113 146  81 146 146 113 146 113 146 146 146 146 146 146
14 | 146 146 113 113 113 113 113 113 146 146 146 146 146 146 113 146 113 146 113 146 146 146 146 146 146
15 | 146 146 113 113 113 113 113 113 146 146 146 146 146 146 146 113 113 146 113 146 146 146 146 146 146
16 | 113 113 113 113  81 113 113 113 113 113 113 113 113 113 113 113  81 113 113 113 113 113 113 113 113
17 | 146 146 113 113 113 113 113 113 146 146 146 146 146 146 146 146 113 113 113 146 146 146 146 146 146
18 | 113 113 113 113 113  81 113 113 113 113 113 113 113 113 113 113 113 113  81 113 113 113 113 113 113
19 | 146 146 113 113 113 113 113 113 146 146 146 146 146 146 146 146 113 146 113 113 146 146 146 146 146
..

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:

1. We can disable NUMA completely setting Parameter _enable_numa_optimization to false.
2. Reduce NUMA nodes using _db_block_numa (Interestingly, this throws ORA-600 error during startup)
3. Or completely eliminate db link based architecture with streams or materialized views.

In case you were wondering, I presented part of this in SIOUG. This blog can be found in a presentation format here. High CPU usage SYS mode .