The other day I tracked down a nasty problem one application was having. It was first noticed in the alert.log:<\/p>\n
\r\nORA-04036: PGA memory used by the instance exceeds PGA_AGGREGATE_LIMIT\r\n...\r\nPGA memory used by the instance exceeds PGA_AGGREGATE_LIMIT of 7000 MB\r\nImmediate Kill Session#: 686, Serial#: 26646\r\nImmediate Kill Session: sess: 0x19e7c2a78 OS pid: 35173\r\n<\/pre>\nChecking the PGA memory from gv$process revealed a shocking picture:<\/p>\n
\r\nSQL> select prc.inst_id, ses.sid, ses.serial#, prc.pid, prc.spid, round(prc.pga_used_mem\/1024\/1024) used_mb, round(prc.pga_alloc_mem\/1024\/1024) alloc_mb, round((prc.pga_alloc_mem - prc.pga_used_mem)\/1024\/1024, 0) unused_mb, round(prc.pga_freeable_mem\/1024\/1024) freeable_mb, round(prc.pga_max_mem\/1024\/1024) max_mb\r\nfrom gv$process prc\r\n left outer join gv$session ses on (ses.inst_id = prc.inst_id and ses.paddr = prc.addr and ses.type = 'USER')\r\norder by used_mb desc\r\nfetch first 10 rows only;\r\n\r\n INST_ID SID SERIAL# PID SPID USED_MB ALLOC_MB UNUSED_MB FREEABLE_MB MAX_MB\r\n---------- ---------- ---------- ---------- ------------------------ ---------- ---------- ---------- --------------------------------------- ----------\r\n 1 655 50496 89 338934 227 284 57 0 499\r\n 1 675 45630 137 338938 223 280 57 0 296\r\n 1 416 7124 285 315339 222 281 58 1 298\r\n 1 290 45321 296 81710 184 233 49 0 280\r\n 2 296 52565 98 223329 163 207 45 0 270\r\n 2 710 8463 293 386687 162 207 45 0 270\r\n 1 67 15923 54 98311 147 187 40 0 264\r\n 2 295 25163 242 316189 143 185 42 0 266\r\n 1 32 55120 270 358206 137 178 41 0 260\r\n 2 309 13006 230 167307 135 175 39 0 258\r\n\r\n 10 rows selected \r\n<\/pre>\nA lot of sessions used between 100MB and 230MB. Monitoring these sessions over some time showed that the memory was never released, something’s definitely wrong. PGA dumps of a couple of connections all showed the same pattern.<\/p>\n
\r\noradebug setmypid\r\noradebug dump pga_detail_get <pid>\r\n<\/pre>\n\r\nSQL> select category, name, heap_name, round(bytes\/1024\/1024, 0) size_mb, allocation_count\r\nfrom gv$process_memory_detail\r\nwhere pid = 89\r\norder by pid, bytes desc\r\nfetch first 10 rows only;\r\n\r\nCATEGORY NAME HEAP_NAME SIZE_MB ALLOCATION_COUNT\r\n--------------- -------------------------- --------------- ---------- ---------------------------------------\r\nOther permanent memory kolarsCreateCt 214 10541\r\nOther free memory top uga heap 57 1571\r\nOther free memory kolarsCreateCt 3 4907\r\nOther free memory session heap 2 1016\r\nOther kollalos2 koh-kghu sessi 1 86\r\nOther permanent memory pga heap 1 43\r\nOther kxsFrame4kPage session heap 0 123\r\nOther qmushtCreate qmtmInit 0 6\r\nPL\/SQL static frame of inst koh-kghu sessi 0 36\r\nOther inode->map_kdlimem buckets_kdliug 0 9\r\n<\/pre>\nThe closest I come to kolarsCreateCt in the oradebug doc is this:<\/p>\n
\r\noradebug doc component\r\n...\r\nComponents in library GENERIC:\r\n--------------------------\r\n...\r\n LOB LOB (koll, kola)\r\n...\r\n<\/pre>\nThis is the clue that there is apparently a LOB resource management problem. Luckily, the PL\/SQL code base was not too big and only a couple of places where LOB handling was done. But, all LOBs seemed to be handled correctly.
\nOne thing, though, I first didn’t pay much attention to was a few “XMLTYPE.getClobVal()” in SELECT statements. I’ve used that myself in the past a couple of times and knew this returned a persistent LOB handle and should not leak.
\nI took one of these SQL statements and ran them in my favorite tool, SQL Developer, and BOOOOOM! My session just consumed a couple of hundreds of megabytes of PGA memory and wouldn’t release it until I closed the connection.<\/p>\nSo I crafted a little test case to check what’s going on.<\/p>\n
\r\nSQL> create table xmltest(id number, data xmltype, primary key (id))\r\nSQL> xmltype column data store as binary xml;\r\nSQL> insert into xmltest (id, data) values (1, '<someelement><\/someelement>');\r\nSQL> commit;\r\nSQL> select t.id, dbms_lob.istemporary(t.data.getclobval()) is_temp from xmltest t;\r\n\r\n ID IS_TEMP\r\n---------- ----------\r\n 1 1\r\n<\/pre>\nI don’t think this is what I knew from past experience so I did a quick MOS search and found following bug report:
\nBug 23061709 : HIGH KOLARSCREATECT AND ORA-04036 WHEN XMLTYPE COLUMN IS STORED AS BINARY<\/p>\nOK, lets change the XMLType storage to CLOB and see what happens:<\/p>\n
\r\nSQL> create table xmltest(id number, data xmltype, primary key (id))\r\nSQL> xmltype column data store as securefile clob;\r\nSQL> insert into xmltest (id, data) values (1, '<someelement><\/someelement>');\r\nSQL> commit;\r\nSQL> select t.id, dbms_lob.istemporary(t.data.getclobval()) is_temp from xmltest t;\r\n\r\n ID IS_TEMP\r\n---------- ----------\r\n 1 0\r\n<\/pre>\nTo be fair, the documentation for 11.2, 12.1, and 12.2 all state the following:
\n“This member function returns a CLOB containing the serialized XML representation. If the CLOB returned is temporary, it must be freed after use.”<\/p>\nBecause I always run my tests in SQL*Plus additionally to SQL Developer I was puzzled to see that there’s no memory leak. Why does it not happen in SQL*Plus? I thought that maybe SQL*Plus is clever enough to always check for temporary LOBs and free them.<\/p>\n
Firing up gdb with this script proved me right.<\/p>\n
\r\nbreak OCILobFreeTemporary\r\n commands\r\n where\r\n continue\r\n end\r\n<\/pre>\nThis SQL fetches five rows with CLOB data.<\/p>\n
\r\nSQL> select t.id, t.data.getclobval() from xmltest t where rownum <= 5;\r\n<\/pre>\nOutput from gdb:<\/p>\n
\r\nBreakpoint 1, 0x00007f678cc3d250 in OCILobFreeTemporary () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libclntsh.so.12.1\r\n#0 0x00007f678cc3d250 in OCILobFreeTemporary () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libclntsh.so.12.1\r\n#1 0x00007f678eafb1ef in afioci () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#2 0x00007f678eaed912 in afifpilobfreetemp () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#3 0x00007f678eaed799 in afifpifretmp () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#4 0x00007f678eae8f20 in afidet () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#5 0x00007f678eb272f3 in safiqry () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#6 0x00007f678eb096e3 in afiqry () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#7 0x00007f678eb21bf2 in afixeqqry () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#8 0x00007f678eb21521 in afixeqsql () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#9 0x00007f678eb20ed5 in afixeqr () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#10 0x00007f678eabfd74 in aficfd () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#11 0x00007f678eabec49 in aficdr () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#12 0x00007f678eaeacf2 in afidrv () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libsqlplus.so\r\n#13 0x00000000004007a1 in main ()\r\n\r\nBreakpoint 1, 0x00007f678cc3d250 in OCILobFreeTemporary () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libclntsh.so.12.1\r\n...\r\n#13 0x00000000004007a1 in main ()\r\n\r\nBreakpoint 1, 0x00007f678cc3d250 in OCILobFreeTemporary () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libclntsh.so.12.1\r\n...\r\n#13 0x00000000004007a1 in main ()\r\n\r\nBreakpoint 1, 0x00007f678cc3d250 in OCILobFreeTemporary () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libclntsh.so.12.1\r\n...\r\n#13 0x00000000004007a1 in main ()\r\n\r\nBreakpoint 1, 0x00007f678cc3d250 in OCILobFreeTemporary () from \/u01\/app\/oracle\/product\/12.1.0.2.161018\/RAC\/lib\/libclntsh.so.12.1\r\n...\r\n#13 0x00000000004007a1 in main ()\r\n<\/pre>\nFive rows fetched and gdb shows five calls to OCILobFreeTemporary. The call to OCILobFreeTemporary originates from libsqlplus.so which tells me it’s not the OCI layer itself handling it, it’s the logic in SQL*Plus.<\/p>\n
Next, I wanted to see myself what happens in a Java\/JDBC application. Here’s the relevant snippet from my test case:<\/p>\n
\r\n String sql = "select t.id, t.data.getclobval() from xmltest t where rownum <= 5";\r\n stmt = conn.prepareStatement(sql);\r\n \r\n for (int i=0; i<3; i++) {\r\n stmt = conn.prepareStatement(sql);\r\n rset = stmt.executeQuery();\r\n\r\n while (rset.next ()) {\r\n System.out.println (rset.getInt(1));\r\n xmlclob = rset.getClob(2);\r\n xmlclob.free();\r\n }\r\n\r\n rset.close();\r\n\r\n c.format("\\nPress ENTER 1 to proceed.\\n");\r\n c.readLine();\r\n }\r\n<\/pre>\nLike SQL*Plus being an application handling the LOB resources, you have to do it programmatically in Java as well. Line 11 frees the temporary LOB.
\nWithout the free() call on the Clob you will see the memory leak when there XMLType storage clause is XML BINARY. It happens, even when do don’t reference the LOB column in Java:<\/p>\n\r\n while (rset.next ()) {\r\n System.out.println (rset.getInt(1));\r\n }\r\n<\/pre>\nLesson learnt:<\/strong> never trust what you think you know! Sometimes things change in subtle ways.<\/p>\n","protected":false},"excerpt":{"rendered":"
The other day I tracked down a nasty problem one application was having. It was first noticed in the alert.log: ORA-04036: PGA memory used by the instance exceeds PGA_AGGREGATE_LIMIT … PGA memory used by the instance exceeds PGA_AGGREGATE_LIMIT of 7000 MB Immediate Kill Session#: 686, Serial#: 26646 Immediate Kill Session: sess: 0x19e7c2a78 OS pid: 35173 […]<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[2,3,6,13],"tags":[],"class_list":["post-267","post","type-post","status-publish","format-standard","hentry","category-general","category-internals","category-sqldev","category-things-that-happen"],"_links":{"self":[{"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=\/wp\/v2\/posts\/267","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=267"}],"version-history":[{"count":5,"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=\/wp\/v2\/posts\/267\/revisions"}],"predecessor-version":[{"id":270,"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=\/wp\/v2\/posts\/267\/revisions\/270"}],"wp:attachment":[{"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=267"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=267"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.spotonoracle.com\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=267"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}