The aim of this blog post is to warn about a potential performance issue in Oracle 12.2 related to PL\/SQL exceptions.<\/p>\n
The test case is rather simple. First, I’ll create an empty table.<\/p>\n
create table t (a number) ;<\/code><\/pre>\nSecondly, I’ll run the following anonymous block which executes a simple query on an empty table in a loop.<\/p>\n
declare\n l_c number ;\n i number ;\nbegin\n for i in 1..10000\n loop\n begin\n select a into l_c from t ;\n exception when no_data_found then\n null ;<\/span>\n end ;\n end loop ;\nend ; \n\/<\/code><\/pre>\nThe key point here is that the no_data_found exception handler will run with each loop iteration. Of course, null is a lousy exception handler, but I’m using it here just for demonstration purposes.<\/p>\n
In my case, the PL\/SQL block completed instantly on a 12.1 database, whereas on 12.2 the execution took 12.49 seconds. That’s way too long.<\/p>\n
Interestingly, the executed Oracle code is not instrumented. What I mean by that is, the CPU and the total wait time don’t account for the elapsed time.<\/p>\n
\ncall count cpu elapsed disk query current rows\n------- ------ -------- ---------- ---------- ---------- ---------- ----------\nParse 1 0.00 0.00 0 0 0 0\nExecute 1 2.25<\/span> 12.49<\/span> 0 0 0 1\nFetch 0 0.00 0.00 0 0 0 0\n------- ------ -------- ---------- ---------- ---------- ---------- ----------\ntotal 2 2.25 12.49 0 0 0 1\n\n...\n\nElapsed times include waiting on following events:\n Event waited on Times Max. Wait Total Waited\n ---------------------------------------- Waited ---------- ------------\n Disk file operations I\/O 1 0.00 0.00<\/span>\n SQL*Net message to client 1 0.00 0.00\n SQL*Net message from client 1 0.00 0.00\n<\/code><\/pre>\nTherefore, we need to use some OS diagnostics for further analysis. First of all, I executed pstack on the long running process on an Oracle 12.2 instance to get a rough idea which Oracle functions were being executed. This is what I got:<\/p>\n
ffff80ffbcf9298a __read () + a\n 000000000a1f32b3 slmsrd () + 83\n 0000000017ec5f6b lmsaprb () + 5b\n 0000000009cc7c8e lmsagb1 () + 11e\n 0000000009cc7b1e lmsagbf () + 4e\n 0000000009cc7240 kgebse () + 180\n 0000000009cc704c kgebem () + 4c\n 0000000009cc6f19 ksemgm () + 69\n 0000000009714f85 opiodr () + 455\n...<\/code><\/pre>\nAccording to Frits Hoogland’s sf.sh<\/a> , kge functions are some kernel generic error functions. In fact, it is easy to verify that those functions are called when the PL\/SQL exception handling code is being executed. In addition, we can inspect the arguments of the functions above with the following DTrace script:<\/p>\npid$target::kge*:entry,\npid$target::lms*:entry\n{\n printf(\"%x %x %x %x %x %x %x %x \\n\",arg0,arg1,arg2,arg3,arg4,arg5,arg6,arg7);\n}\n\n...\nlmsapsc ffff80ffbd5b02c8 57b<\/span> ffff80ffbfff62db 1f5 2 203a 0 3aad71e4 \nlmsapbn ffff80ffbd5b02c8 2 57b<\/span> ffff80ffbfff62db 1f5 0 0 0 \n...<\/code><\/pre>\nAs you can see, 0x57b<\/span> is being passed as an argument to some of the functions. 0x57b is 1403 in decimal notation which, in turn, is nothing else but the error code for the “no data found” condition.<\/p>\nAs for the next step, I’m going to compare the number of function calls in both Oracle versions.<\/p>\n
12.2:<\/p>\n
kgecss 2\n kge_is_oserr 20000\n kge_is_resig_mandatory 20000\n kgeade 20000\n kgebem 20000\n kgebse 20000\n kgefrp 20000\n kgekeep 20000\n kgepop 20000\n kgeselv 20000\n kgespf 20000\n kgespo 20000\n kgetop 20000\n lmsagb1 20000\n lmsagbf 20000\n lmsapbn 20000\n lmsaprb 20000\n lmsapsb 20000\n lmsapsc 20000\n lmsapts 20000\n slmsrd<\/span> 20000\n kge_is_resig_mandatory_errframe 40000\n kgeresl 40000\n kgegec 80000<\/code><\/pre>\n12.1:<\/p>\n
kgecss 1\n kge_is_oserr 10000\n kge_is_resig_mandatory 10000\n kgeade 10000\n kgebem 10000\n kgebse 10000\n kgefrp 10000\n kgegbc 10000\n kgekeep 10000\n kgepop 10000\n kgeselv 10000\n kgespf 10000\n kgespo 10000\n lmsagb1 10000\n lmsagbf 10000\n lmsapsb 10000\n lmsapsc 10000\n kge_is_resig_mandatory_errframe 20000\n kgeresl 20000\n kgetop 20000\n kgegec 50000<\/code><\/pre>\nAlthough the most obvious difference is twice as much calls for almost every function in 12.2 compared to 12.1, this is not the main reason for the severe performance decrease. As a matter of fact, an attentive reader might notice that the slmsrd calls are entirely missing in the 12.1 output.<\/p>\n
Again, I’ll use Frits’ sf.sh<\/a> to figure out the purpose of the Oracle kernel function slmsrd:<\/p>\n.\/sf.sh slmsrd\nslmsrd -- system specific call<\/code><\/pre>\nslms stands for “system specific call”. And if “rd” stands for read, the question is, what is being read during exception handling? Knowing that every read operation results in a system call, we can truss the Oracle dedicated process to answer this question:<\/p>\n
truss -f -tread -p 5522\n...\n5222: read(9, \"\\f\\0 x05\\0\\0 P\\0 y05\\0\\0\".., 512) = 512\n5522: read(9, \"\\f\\0 x05\\0\\0 P\\0 y05\\0\\0\".., 512) = 512\n5522: read(9, \"\\f\\0 x05\\0\\0 P\\0 y05\\0\\0\".., 512) = 512\n5522: read(9, \"\\f\\0 x05\\0\\0 P\\0 y05\\0\\0\".., 512) = 512\n5522: read(9, \"\\f\\0 x05\\0\\0 P\\0 y05\\0\\0\".., 512) = 512\n5522: read(9, \"\\f\\0 x05\\0\\0 P\\0 y05\\0\\0\".., 512) = 512\n5522: read(9, \"\\f\\0 x05\\0\\0 P\\0 y05\\0\\0\".., 512) = 512\n5522: read(9, \"\\f\\0 x05\\0\\0 P\\0 y05\\0\\0\".., 512) = 512\n5522: read(9, \"\\f\\0 x05\\0\\0 P\\0 y05\\0\\0\".., 512) = 512\n...<\/code><\/pre>\nAs you can see, not only are there thousands of reads on the file behind the descriptor 9, but also the same piece of information is read 20000 times for 10000 raised exceptions.<\/p>\n
Next, with pfiles we can find out which file is being read:<\/p>\n
pfiles 5522\n5522: oracleAVAR19 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))\n...\n 9: S_IFREG mode:0755 dev:286,65600 ino:4840002 uid:1000 gid:1000 size:1344512\n O_RDONLY|O_LARGEFILE FD_CLOEXEC\n ...\/rdbms\/mesg\/oraus.msb<\/span>\n...<\/code><\/pre>\nFinally, the culprit is revealed. It’s oraus.msb<\/span> that contains all of the error messages. Not only is the error message text completely unnecessary in this case, but also Oracle database doesn’t bother with caching it.<\/p>\nJust imagine a mess which might arise on a highly consolidated platform with applications frequently executing exception handling code and by doing so, heavily reading from oraus.msb at the same time. In addition, a session trace wouldn’t provide any clue that the the application is waiting on a completely irrelevant piece of information to be read from the filesystem.<\/p>\n
Workarounds<\/h1>\n
Unfortunately, I couldn’t find any documents on Metalink about the problem. However, I’d like to suggest some possible mitigation countermeasures. Before doing that, it’s worth noting that the Oracle home in this case was placed on a separate ZFS file system which was not configured for caching data, i.e. primarycache was set to metadata (only). The reason for doing this is to avoid cache thrashing by loading Oracle homes into the cache during OS backups. Frankly, it’s the first time I’ve ever seen that the query elapsed time is depending on the Oracle home file access latency. Anyway, after setting primarycache to all, the code started to run fast in 12.2 as well.<\/p>\n
In case you don’t have a possibility of either caching Oracle home or putting it on an SSD drive, there are also couple of things you could do on the application side to reduce the number of message file reads.<\/p>\n
First of all, check if you can create conditions in the environment which would lead to less exceptions in total. For instance, if you insert a row into the table above, no_data_found won’t fire any more and the code will execute fast.<\/p>\n
Secondly, you could increase the exception handler’s scope if feasible. For example, you can take it out of the loop:<\/p>\n
declare\n l_c number ;\n i number ;\nbegin\n for i in 1..10000\n loop\n select a into l_c from t ;\n end loop ;\nexception when no_data_found then\n null ;\nend ; \n\/<\/code><\/pre>\nLastly, you could replace the entire exception handler with an explicit cursor like this:<\/p>\n
declare\n l_c number ;\n i number ;\n cursor c is select a from t ;\nbegin\n open c ;\n for i in 1..10000\n loop\n fetch c into l_c ;\n if c%notfound then <\/span>\n\t null;\n\tend if ;\n end loop ;\nend ; \n\/<\/code><\/pre>\nSummary<\/h1>\n
In conclusion, a performance issue has been introduced in Oracle 12.2. The message file is repeatedly being read by dedicated processes, even in cases when no error has to be thrown. In particular, applications which frequently raise PL\/SQL exceptions could be affected. To make the problem worse, the trace file doesn’t provide any clues to the root-cause. Currently, there doesn’t seem to be any information on Metalink about it. Nevertheless, I highlighted different possibilities of mitigating the issue.<\/p>\n
Update February 17, 2022<\/h1>\n
The problem is fixed in recent Oracle releases. I tested it on 19.14 and 21.4 PDB. There’s only one read per execution:<\/p>\n
sudo \/bin\/strace -p 3924265 -c\n\n% time seconds usecs\/call calls errors syscall\n------ ----------- ----------- --------- --------- ----------------\n 83.81 0.000088 0 284 getrusage\n 14.29 0.000015 15 1 read\n 1.90 0.000002 2 1 write\n------ ----------- ----------- --------- --------- ----------------\n100.00 0.000105 0 286 total<\/code><\/pre>\n","protected":false},"excerpt":{"rendered":"Potentially a huge performance issue with PL\/SQL exception handling in 12.2 Continue Reading