Oracle online patching a may impact OS/DB Performance

This article discusses the issue we faced during and oracle online patching on IBM AIX servers.

What is the issue faced

It is very simple. SQL plus connection to oracle database take about 2-3 seconds. No matter if it is a bequeath connection or listener connection. This issue surfaced when we tested Oracle Fusion Middleware for performance testing and we traced the issue back to the shadow process initiation. Oracle Fusion Middleware stack uses burst of connection. If the application stack does not get connection immediate enough, it again request for more connection thinking that first request may ever get through. So this 2-3 seconds delay make the CPU to spin at 100% when the application keep requesting more and more connection.

How to reproduce

Reproducing the issue without Oracle Fusion Middleware stack was main turning point in isolating the Oracle Fusion Middleware from the culprit list. The initial analysis of listener log reveled that we are getting about 40 to 50 connection request per seconds. In my experience I have never faced an issue with listener unable to service 40 to 50 connection request per seconds. In fact I have seen listener servicing up to 200 connection requests per second.
So I just wrote a shell script to just connect to database from the database server with no listener (just a bequeath connection) in a loop of about 20. Each time just connect and exit from SQL prompt. Then wrote a wrapper script just calling the above script with nohup about 40 times. So I am trying to establish about 800 connections to database. To my surprise the CPU went up to 100% and it took about 15 to 20 minutes to complete the connection request.
I took the same scripts to another machine and tried the same thing. Oh the script completed in less than 10 seconds. 800 connections in 10 seconds.
Ok now we have the problem. How to find the root cause.

How to find the root cause

To our surprise we could not reproduce this on the same database server with different database. To make it clearer we created a new database from same oracle home and the problem was not there. Again this problem was happening on couple of other AIX server.
We worked with oracle support for about 4 to 5 months. Couple of oracle support persons came on site and we did an in depth analyze of the issue. There was no clue what is going on.
We did sqlplus connection trace and found the slowing was happening in a place where it look into ORACL_HOME patch location and loading the library from patch location

17883340: 21377267: 22.4911: statx(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/”, 0x0FFFFFFFFFFFEAB0, 176, 0) = 0
17883340: 21377267: 22.4913: kopen(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/orapatchpor49r1.cfg”, O_RDWR|O_CREAT|O_LARGEFILE, S_IRUSR|S_IWUSR) = 6

In the following code you can see that sqlplus is loading patch version of the library.

kread(7, “\0\0\00106 h |C0\0\0A5E0”.., 55328) = 55328
1.1354: kopen(“/opt/app/oracle/product/11.2.0/dbhome_2/bin/oracle”, O_RDONLY|O_LARGEFILE) = 9
1.1356: fstatx(9, 0x0FFFFFFFFFFFD390, 176, 0) = 0
1.1358: mmap(0x0000000000000000, 4096, PROT_READ, MAP_FILE|MAP_VARIABLE|MAP_PRIVATE, 9, 0) = 0x0700000110000000
1.1360: munmap(0x0700000110000000, 24) = 0
1.1362: mmap(0x0000000000000000, 4096, PROT_READ, MAP_FILE|MAP_VARIABLE|MAP_PRIVATE, 9, 0) = 0x0700000110000000
1.1366: mmap(0x0000000000000000, 26742784, PROT_READ, MAP_FILE|MAP_VARIABLE|MAP_PRIVATE, 9, 267935744) = 0x0700000110001000
1.5173: statx(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/bug10269193.so”, 0x0FFFFFFFFFFFE230,176, 0) = 0
1.5175: __libc_sbrk(0x0000000000090020) = 0x0000000110736220
1.5177: kopen(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/bug10269193.so”, O_RDONLY|O_LARGEFILE) = 10
kread(10, “01F7\005 M c8B13\0\0\0\0”.., 315231) = 315231
1.5187: close(10) = 0
1.5188: __libc_sbrk(0x0000000000090020) = 0x00000001107C6240
kread(7, “01F7\005 M c8B13\0\0\0\0”.., 315231) = 315231
1.5199: disclaim(“^E9^?±”, 524288, 1) = 0
1.5203: close(7) = 0
1.5249: kload(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/bug10269193.so”, 17367680, “/opt/app/oracle/product/11.2.0/dbhome_2/lib:/opt/app/grid_2/11.2.0/lib:/opt/ODBC/shadow/7_1_212_64/lib”) = 648518346072922152
1.5267: _getpid() = 4296820
1.5269: kopen(“/proc/4296820/status”, O_RDONLY|O_LARGEFILE) = 7
kread(7, “\0 01\004\001\0\0\005”.., 1520) = 1520
1.5272: close(7) = 0
1.5274: kopen(“/unix”, O_RDONLY|O_LARGEFILE) = 7
1.5275: kioctl(7, 22528, 0x0000000000000000, 0x0000000000000000) = -1
1.5277: kioctl(7, 22528, 0x0000000000000000, 0x0000000000000000) = -1

What is hpatch

Hpatch is there since we applied an online patch also known as Hot patching. A regular RDBMS patch is comprised of one or more object (.o) files and/or libraries (.a files). Installing a regular patch requires shutting down the RDBMS instance, re-linking the oracle binary, and restarting the instance; uninstalling a regular patch requires the same steps.

On the other hand, an online patch is a special kind of patch that can be applied to a live, running RDBMS instance. An online patch contains a single shared library; installing an online patch does not require shutting down the instance or relinking the oracle binary. An online patch can be installed/un-installed using Opatch (which uses oradebug commands to install/uninstall the patch).
For more details check out the metalink note 761111.1

SQL> oradebug patch list

Patch File Name State
================ =========
bug10269193.pch ENABLED

15937724: 21668027: 6.2829: statx(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/”, 0x0FFFFFFFFFFFEAC0, 176, 0) = 0
15937724: 21668027: 6.2830: kopen(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/orapatchpor49r1.cfg”, O_RDWR|O_CREAT|O_LARGEFILE, S_IRUSR|S_IWUSR) = 6
15937724: 21668027: 6.2840: statx(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/bug10269193.pch”, 0x0FFFFFFFFFFFE190, 176, 0) = 0
15937724: 21668027: 6.2842: kopen(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/bug10269193.pch”, O_RDONLY|O_LARGEFILE) = 7
15937724: 21668027: 6.5099: statx(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/bug10269193.so”, 0x0FFFFFFFFFFFE190, 176, 0) = 0
15937724: 21668027: 6.5145: kload(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/bug10269193.so”, 17367680,

17989800: 19447907: 1.9035: statx(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/”, 0x0FFFFFFFFFFFEB00, 176, 0) = 0
17989800: 19447907: 1.9037: kopen(“/opt/app/oracle/product/11.2.0/dbhome_2/hpatch/orapatchtest1.cfg”, O_RDWR|O_CREAT|O_LARGEFILE, S_IRUSR|S_IWUSR) = 6