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
