I encountered that issue originally when I migrated one of my databases to 12.2.0.1.190416.
I started my investigation when observed the following rows in V$ACTIVE_SESSION_HISTORY for one execution:
SQL> select to_char(sample_time, 'hh24:mi:ss') sample_time, sql_id, sql_opname, top_level_sql_id, session_state, event,
2 trim(case when IN_CONNECTION_MGMT='Y' then ' IN_CONNECTION_MGMT' end||
3 case when IN_PARSE='Y' then ' IN_PARSE' end||
4 case when IN_HARD_PARSE='Y' then ' IN_HARD_PARSE' end||
5 case when IN_SQL_EXECUTION='Y' then ' IN_SQL_EXECUTION' end||
6 case when IN_PLSQL_EXECUTION='Y' then ' IN_PLSQL_EXECUTION' end||
7 case when IN_PLSQL_RPC='Y' then ' IN_PLSQL_RPC' end||
8 case when IN_PLSQL_COMPILATION='Y' then ' IN_PLSQL_COMPILATION' end||
9 case when IN_JAVA_EXECUTION='Y' then ' IN_JAVA_EXECUTION' end||
10 case when IN_BIND='Y' then ' IN_BIND' end||
11 case when IN_CURSOR_CLOSE='Y' then ' IN_CURSOR_CLOSE' end||
12 case when IN_SEQUENCE_LOAD='Y' then ' IN_SEQUENCE_LOAD' end||
13 case when IN_INMEMORY_QUERY='Y' then ' IN_INMEMORY_QUERY' end||
14 case when IN_INMEMORY_POPULATE='Y' then ' IN_INMEMORY_POPULATE' end||
15 case when IN_INMEMORY_PREPOPULATE='Y' then ' IN_INMEMORY_PREPOPULATE' end||
16 case when IN_INMEMORY_REPOPULATE='Y' then ' IN_INMEMORY_REPOPULATE' end||
17 case when IN_INMEMORY_TREPOPULATE='Y' then ' IN_INMEMORY_TREPOPULATE' end||
18 case when IN_TABLESPACE_ENCRYPTION='Y' then ' IN_TABLESPACE_ENCRYPTION' end) activity
19 from v$active_session_history
20 where session_id = 58
21 and sample_time between timestamp'2019-07-30 20:47:41' and timestamp'2019-07-30 20:48:30'
22 order by sample_time;
SAMPLE_T SQL_ID SQL_OPNAME TOP_LEVEL_SQL SESSION EVENT ACTIVITY
-------- ------------- ---------- ------------- ------- ---------- ---------------------------------------------------
20:47:42 a6n6qc8g855q6 SELECT 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION
20:47:43 a6n6qc8g855q6 SELECT 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION
20:47:44 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:45 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:46 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:47 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:48 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:49 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:50 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:51 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:52 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:53 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:54 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:55 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:56 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:57 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:58 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:59 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:00 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:01 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:02 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:03 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:04 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:05 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:06 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:07 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:08 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:09 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:10 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:11 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:12 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:13 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:14 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:15 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:16 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:17 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:18 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:19 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:20 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:21 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:22 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:23 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:24 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:25 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:26 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:27 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:28 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:29 2puw0smn3qw99 ON CPU IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
That was quite unusual as there was no SQL_ID and IN_CURSOR_CLOSE was set to 'Y'.
Here's an over-simplified version of what the session was doing:
SQL> declare
2 cursor test_csr is
3 select t1.*, user_agg_function(to_char(l)) c1
4 from (select level l from dual connect by level<=30001) t1
5 group by t1.l;
6 type test_tbl_type is table of test_csr%rowtype;
7 v_test_tbl test_tbl_type;
8 begin
9 open test_csr;
10
11 dbms_output.put_line(systimestamp||' After open');
12
13 for i in 1..6
14 loop
15 fetch test_csr bulk collect into v_test_tbl limit 5000;
16 dbms_output.put_line(systimestamp||' After fetch');
17 end loop;
18
19 dbms_output.put_line(systimestamp||' After all fetches');
20
21 close test_csr;
22 dbms_output.put_line(systimestamp||' After close');
23 end;
24 /
30-JUL-19 08.47.41.576257000 PM +01:00 After open
30-JUL-19 08.47.41.866173000 PM +01:00 After fetch
30-JUL-19 08.47.42.153764000 PM +01:00 After fetch
30-JUL-19 08.47.42.455019000 PM +01:00 After fetch
30-JUL-19 08.47.42.775041000 PM +01:00 After fetch
30-JUL-19 08.47.43.137562000 PM +01:00 After fetch
30-JUL-19 08.47.43.688608000 PM +01:00 After fetch
30-JUL-19 08.47.43.688630000 PM +01:00 After all fetches
30-JUL-19 08.48.30.799487000 PM +01:00 After close
PL/SQL procedure successfully completed.
Elapsed: 00:00:49.80
So it performed 6 fetches in 2 seconds and then spent the remaining 47 seconds while closing the cursor, huh?
Flamegraphs are quite useful in diagnosing such issues:
All of those kksumc, kxsFreeExecutionHeap, kxsFreeWorkArea, kxsdmc and others are memory free/releasing cursor routines.
As you might guess, the nature of this issue is related to that user-defined type from the query.
Here's the code that I used for that demo:
CREATE OR REPLACE TYPE user_agg_t as object(
v_clob clob,
static function ODCIAggregateInitialize(sctx IN OUT NOCOPY user_agg_t)
return number,
member function ODCIAggregateIterate(self IN OUT NOCOPY user_agg_t,
value IN varchar2)
return number,
member function ODCIAggregateTerminate(self IN OUT NOCOPY user_agg_t,
returnValue OUT NOCOPY clob,
flags IN number)
return number,
member function ODCIAggregateMerge(self IN OUT NOCOPY user_agg_t,
ctx2 IN OUT NOCOPY user_agg_t)
return number
);
/
CREATE OR REPLACE TYPE BODY user_agg_t
is
static function ODCIAggregateInitialize(sctx IN OUT NOCOPY user_agg_t)
return number is
begin
sctx := user_agg_t(null);
return ODCIConst.Success;
end;
member function ODCIAggregateIterate(self IN OUT NOCOPY user_agg_t,
value IN varchar2)
return number
is
begin
return ODCIConst.Success;
end;
member function ODCIAggregateTerminate(self IN OUT NOCOPY user_agg_t,
returnValue OUT NOCOPY clob,
flags IN number)
return number is
begin
self.v_clob := 'finished';
returnValue := self.v_clob;
return ODCIConst.Success;
end;
member function ODCIAggregateMerge(self IN OUT NOCOPY user_agg_t,
ctx2 IN OUT NOCOPY user_agg_t)
return number is
begin
return ODCIConst.Success;
end;
end;
/
CREATE OR REPLACE FUNCTION user_agg_function (input varchar2) RETURN clob PARALLEL_ENABLE AGGREGATE USING user_agg_t;
/
There is an abstract LOB created in the highlighted line.
While the anonymous block is running, it creates a lot of those abstract LOBs, upto 30,000 which is the number of rows that I fetch from that cursor (I am checking it through V$TEMPORARY_LOBS).
When I call the close cursor line, the server process decides that it is time to free up all of those resources back and that is what is taking so much time; here is the relevant output:
Why did I put 30,001 in that cursor? If I had not done this, Oracle would have performed that deallocation stage at the time of the last fetch.
It closely emulates what my APEX application is doing by using row-limiting clause instead.
Initially, I was not able to reproduce my test case in the vanilla 12.2.0.1.190416 database that I used for that demo.
Here's how that anonymous block was executing there:
SQL> declare
2 cursor test_csr is
3 select t1.*, user_agg_function(to_char(l)) c1
4 from (select level l from dual connect by level<=30001) t1
5 group by t1.l;
6 type test_tbl_type is table of test_csr%rowtype;
7 v_test_tbl test_tbl_type;
8 begin
9 open test_csr;
10
11 dbms_output.put_line(systimestamp||' After open');
12
13 for i in 1..6
14 loop
15 fetch test_csr bulk collect into v_test_tbl limit 5000;
16 dbms_output.put_line(systimestamp||' After fetch');
17 end loop;
18
19 dbms_output.put_line(systimestamp||' After all fetches');
20
21 close test_csr;
22 dbms_output.put_line(systimestamp||' After close');
23 end;
24 /
30-JUL-19 08.38.01.599807000 PM +01:00 After open
30-JUL-19 08.38.01.709834000 PM +01:00 After fetch
30-JUL-19 08.38.01.831769000 PM +01:00 After fetch
30-JUL-19 08.38.01.974946000 PM +01:00 After fetch
30-JUL-19 08.38.02.137070000 PM +01:00 After fetch
30-JUL-19 08.38.02.321525000 PM +01:00 After fetch
30-JUL-19 08.38.02.540002000 PM +01:00 After fetch
30-JUL-19 08.38.02.540024000 PM +01:00 After all fetches
30-JUL-19 08.38.02.604546000 PM +01:00 After close
PL/SQL procedure successfully completed.
Elapsed: 00:00:01.02
SQL>
SQL> select p.pga_used_mem, p.pga_alloc_mem
2 from v$session s, v$process p
3 where s.sid = sys_context('userenv', 'sid')
4 and p.addr = s.paddr;
PGA_USED_MEM PGA_ALLOC_MEM
------------ -------------
446703652 450742580
It's blazingly fast, isn't it? However, notice that PGA is not freed back and my session consumes 450MB!
While wading through OS/Oracle traces, I finally came across the trace[LOB_REFCOUNT] event that gave some clues:
kolradc : 0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x63 : 2 (24)
PGA usage percent: 4829 percent, isMaxHeap reached?: 1, Mem check freq: 25
kolrarfc: 0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x64 : 1
kolrarfc: kolaCreateClob()+123<-kolaslCreateClob()+144<-kole_templob_init()+428<-kole_ba2l()+170<-pfrcvfc_format_conversion()+2369<-pevm_CNVMSC()+49<-pfrinstr_CNVMSC()+52<-pfrrun_no_tool()+60<-pfrrun()+917<-plsql_run()+756<-peidxr_run()+265<-peidxexe()+76<-kkxdexe()+625<-kkxmpexe()+288<-kgmexwi()+592
kolrarfc: number of lobs = 100
kolrDmpTables_uts: Called from : at every 100th lob added
kolrDmpDurs_uts: Called from : at every 100th lob added
----- kolr Durations Dump Begin ----
-------------------------------------
DUR LOB COUNT TOTAL RFC
-------------------------------------
24 99 100
28 1 1
29 99 99
------ kolr Durations Dump End -----
----------------- kolr Dur Hash Table Dump Begin: 24 --------------
Lob Locator count (dur in loc)
------------------------------------------------------------------------
0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x5f 1 (29)
0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x0b 1 (29)
0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x06 1 (29)
0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x5a 1 (29)
That was from a database that had a plenty of PGA available that was far more below PGA_AGGREGATE_TARGET (PAT). Yet, that database was suffering from that issue.
Then I was able to reproduce that slow close cursor step by occupying a lot of PGA first. I wrote a simple package to help me in this task:
create or replace package fill_memory
is
type t is table of varchar2(32767);
v t := t();
procedure extend(i_size pls_integer := 10000);
end;
/
create or replace package body fill_memory
is
procedure extend(i_size pls_integer := 10000)
is
v_current_size pls_integer;
begin
v_current_size := v.count();
v.extend(i_size);
for i in v_current_size + 1..v_current_size + i_size
loop
v(i) := lpad('x', 32767, 'x');
end loop;
end extend;
end;
/
I found that in the demo database with PAT set to 512M, it is enough to call fill_memory.extend(25000) to make all subsequent executions of the anonymous block in question slow (bigger values resulted in the acknowledge over PGA limit event, which I tried to avoid for this demo as I did not observe them in my database initially and those would be a clear indication of the problem area):
Although I was able to reproduce that issue in a clean database, I have been able to do that only if I consumed a lot of PGA first.
Still, I observe that issue now in one of my development database where there is a bunch of free PGA and I have raised an SR with Oracle support to further investigate it (I believe I have already done my homework, so that it shouldb't be so hard for them to tackle this problem now).
Another remarkable thing that I discovered while I was working on this issue, is that 19c consumes far more memory on the same test case and performance does not suffer (it's 450M in 12.2 versus 1450M in 19c - I would probably raise another SR when I start using 19c for that application):
SQL> declare
2 cursor test_csr is
3 select t1.*, user_agg_function(to_char(l)) c1
4 from (select level l from dual connect by level<=30001) t1
5 group by t1.l;
6 type test_tbl_type is table of test_csr%rowtype;
7 v_test_tbl test_tbl_type;
8 begin
9 open test_csr;
10
11 dbms_output.put_line(systimestamp||' After open');
12
13 for i in 1..6
14 loop
15 fetch test_csr bulk collect into v_test_tbl limit 5000;
16 dbms_output.put_line(systimestamp||' After fetch');
17 end loop;
18
19 dbms_output.put_line(systimestamp||' After all fetches');
20
21 close test_csr;
22 dbms_output.put_line(systimestamp||' After close');
23 end;
24 /
30-JUL-19 09.51.59.629103000 PM +01:00 After open
30-JUL-19 09.51.59.809768000 PM +01:00 After fetch
30-JUL-19 09.51.59.916143000 PM +01:00 After fetch
30-JUL-19 09.52.00.016790000 PM +01:00 After fetch
30-JUL-19 09.52.00.116655000 PM +01:00 After fetch
30-JUL-19 09.52.00.217287000 PM +01:00 After fetch
30-JUL-19 09.52.00.317115000 PM +01:00 After fetch
30-JUL-19 09.52.00.317137000 PM +01:00 After all fetches
30-JUL-19 09.52.00.324701000 PM +01:00 After close
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.70
There is difference how those memory allocations are made in 12.2 and 19c:
12.2 uses 64K allocations whereas 19c seems to be allocating 150 64K allocations, 100/128K, 100/256K, 100/512K, 100/1M, 100, 2M, 50/4M, 50/8M, X/16M.
There is an obvious pattern in those allocations in 19c - they are just doubling in size.
Still, even with those allocations I expected to see some slowdowns in 19c, however, I have not found any.
I guess that some memory management code has been redone in 19c because both 12.2 and 19c were provisioned in my home lab from the same Virtual Box machine image.
