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.
Комментариев нет:
Отправить комментарий
Примечание. Отправлять комментарии могут только участники этого блога.