I have recently optimized one of processes working with LOBs and decided to write a blog post about it.
There was an anonymous block like the following:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
declare
v_result clob;
begin
for test_rec in (
select substr(clob_col, 1, 32000) clob_part1,
substr(clob_col, 32001, 32000) clob_part2
from driving_table
where some_conditions
order by sort_column)
loop
v_result := v_result || test_rec.clob_part1 || ';' || test_rec.clob_part2;
end loop;
end;
/
In a nutshell, that block unloaded some LOB data to a CLOB. Developers identified that this block was working quite fine being run for a relatively small number of rows, but the performance was deteriorating drastically when the same block was running against a large number of rows.
To set the scene for further analysis, let's create a table with 100K rows that has a 100 byte CLOB column:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
SQL> create table t100(
2 n int generated as identity,
3 c clob);
Table created.
SQL>
SQL> insert /*+ append*/into t100(c)
2 select lpad('x', 100, 'x')
3 from xmltable('1 to 100000');
100000 rows created.
SQL>
SQL> commit;
Firstly, I show what happens when I try to emulate the original cursor:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
SQL> select pga_used_mem, pga_alloc_mem
2 from v$session s,
3 v$process p
4 where s.sid = sys_context('userenv', 'sid')
5 and p.addr = s.paddr;
PGA_USED_MEM PGA_ALLOC_MEM
2544108 4114740
SQL>
SQL> select pm.*
2 from v$session s,
3 v$process p,
4 v$process_memory pm
5 where s.sid = sys_context('userenv', 'sid')
6 and p.addr = s.paddr
7 and pm.pid = p.pid
8 order by pm.category;
PID SERIAL# CATEGORY ALLOCATED USED MAX_ALLOCATED CON_ID
77 157 Other 5667940 5667940 3
77 157 PL/SQL 30744 23680 31920 3
77 157 SQL 54456 43688 319280 3
SQL>
SQL> var rc refcursor
SQL>
SQL> begin
2 open :rc for
3 select n,
4 substr(c, 1, 40) c_part1,
5 substr(c, 41, 40) c_part2,
6 substr(c, 81, 40) c_part3
7 from t100
8 where n <= 50000
9 order by n;
10 end;
11 /
PL/SQL procedure successfully completed.
SQL> declare
2 n int;
3 c1 clob;
4 c2 c1%type;
5 c3 c1%type;
6 begin
7 fetch :rc
8 into n, c1, c2, c3;
9 end;
10 /
PL/SQL procedure successfully completed.
SQL>
SQL>
SQL> select pm.*
2 from v$session s,
3 v$process p,
4 v$process_memory pm
5 where s.sid = sys_context('userenv', 'sid')
6 and p.addr = s.paddr
7 and pm.pid = p.pid
8 order by pm.category;
PID SERIAL# CATEGORY ALLOCATED USED MAX_ALLOCATED CON_ID
77 157 Freeable 1048576 0 3
77 157 Other 1375048620 1375048620 3
77 157 PL/SQL 32856 23104 60960 3
77 157 SQL 14988592 11145152 17361192 3
Oops! The code allocated 1.3G PGA in the Other category. There are also 150K abstract LOBs created:
1
2
3
4
5
6
7
SQL> select *
2 from v$temporary_lobs
3 where sid = sys_context('userenv', 'sid');
SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS CON_ID
435 0 0 150000 3
Let us find out what we have in
V$PROCESS_MEMORY_DETAIL :
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
SQL> alter session set events 'immediate trace name pga_detail_get level 77';
Session altered.
SQL> select name, heap_name, bytes, allocation_count, bytes/150000
2 from v$process_memory_detail
3 where pid = 77
4 and category = 'Other'
5 and allocation_count >= 140000
6 order by allocation_count
7 /
NAME HEAP_NAME BYTES ALLOCATION_COUNT BYTES/150000
kghdsx kokltcr: creat 16800000 150000 112
free permanent memory kokltcr: creat 15600216 150000 104.00144
kolrarfc:lobloc_kolrhte kolr heap ds i 9610304 150000 64.0686933
kolraloc-1 kolr heap ds i 12289592 150002 81.9306133
kokltcr: create clob koh dur heap d 53599912 300000 357.332747
kghsseg: kolaslCreateCtx kokltcr: creat 1212000000 300000 8080
That is more than 8,192 bytes per abstract LOB even for these 40 byte LOBs!
These are in-memory LOBs, however, memory is a limited resource obviously and Oracle can create non-in-memory LOBs starting with a certain number of abstract LOBs (it is around 215K LOBs in my test database). Notice that I limited the number of rows to 100K to create 300K abstract LOBs:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
SQL> begin
2 open :rc for
3 select n,
4 substr(c, 1, 40) c_part1,
5 substr(c, 41, 40) c_part2,
6 substr(c, 81, 40) c_part3
7 from t100
8 where n <= 100000
9 order by n;
10 end;
11 /
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.20
SQL> declare
2 n int;
3 c1 clob;
4 c2 c1%type;
5 c3 c1%type;
6 begin
7 fetch :rc
8 into n, c1, c2, c3;
9 end;
10 /
PL/SQL procedure successfully completed.
Elapsed: 00:01:08.04
SQL> select *
2 from v$temporary_lobs
3 where sid = sys_context('userenv', 'sid');
SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS CON_ID
435 84626 0 300000 3
Here is the output from
V$TEMPSEG_USAGE :
1
2
3
4
5
6
7
8
SQL> select contents, segtype, blocks
2 from v$tempseg_usage
3 where session_num = 61759;
CONTENTS SEGTYPE BLOCKS
TEMPORARY SORT 1792
TEMPORARY LOB_DATA 84736
After enabling an event
trace[LOB_REFCOUNT] , the following can be seen in the tracefile:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
PGA usage percent: 74 percent, isMaxHeap reached?: 0, Mem check freq: 50
kolrarfc: 0x55 0xbc 0x0d 0x00 0x00 0x03 0x40 0x9e : 1
kolrarfc: kolaCreateClob()+123<-kolaslCreateClob()+144<-kole_templob_init()+431<-kole_substr()+728<-kokle_substr()+340<-evaopn2()+612<-qersoRowP()+2657<-qerstRowP()+802<-kdstf010000100000000kmP()+1377<-kdsttgr()+2149<-qertbFetch()+1409<-qerstFetch()+477<-qersoProcessULS()+300<-qersoFetchSimple()+1433<-qersoFetch()+210
kolradls: 0x55 0xbc 0x0d 0x00 0x00 0x03 0x40 0x9e : 1 (32)
kolrarfc: 0x55 0xbc 0x0d 0x00 0x00 0x03 0x40 0x9e : 2
kolrarfc: kokegOpnGarbagePromote()+103<-qersoRowP()+2069<-qerstRowP()+802<-kdstf010000100000000kmP()+1377<-kdsttgr()+2149<-qertbFetch()+1409<-qerstFetch()+477<-qersoProcessULS()+300<-qersoFetchSimple()+1433<-qersoFetch()+210<-qerstFetch()+477<-opifch2()+3267<-opifch()+62<-opipls()+7312<-opiodr()+1229
kolradc : 0x55 0xbc 0x0d 0x00 0x00 0x03 0x40 0x9e : 2 (32)
...skip...
PGA usage percent: 75 percent, isMaxHeap reached?: 1, Mem check freq: 25
kolrarfc: 0x55 0xbc 0x0d 0x00 0x00 0x03 0x42 0x2e : 1
kolrarfc: kolaCreateClob()+123<-kolaslCreateClob()+144<-kole_templob_init()+431<-kole_substr()+728<-kokle_substr()+340<-evaopn2()+612<-qersoRowP()+2657<-qerstRowP()+802<-kdstf010000100000000kmP()+1377<-kdsttgr()+2149<-qertbFetch()+1409<-qer
stFetch()+477<-qersoProcessULS()+300<-qersoFetchSimple()+1433<-qersoFetch()+210
kolradls: 0x55 0xbc 0x0d 0x00 0x00 0x03 0x42 0x2e : 1 (32)
kolrarfc: 0x55 0xbc 0x0d 0x00 0x00 0x03 0x42 0x2e : 2
kolrarfc: kokegOpnGarbagePromote()+103<-qersoRowP()+2069<-qerstRowP()+802<-kdstf010000100000000kmP()+1377<-kdsttgr()+2149<-qertbFetch()+1409<-qerstFetch()+477<-qersoProcessULS()+300<-qersoFetchSimple()+1433<-qersoFetch()+210<-qerstFetch()+4
77<-opifch2()+3267<-opifch()+62<-opipls()+7312<-opiodr()+1229
kolradc : 0x55 0xbc 0x0d 0x00 0x00 0x03 0x42 0x2e : 2 (32)
Max limit reached for in-mem heap allocation
kolrarfc: 0x55 0xbc 0x0d 0x00 0x00 0x03 0x42 0x2f : 1
kolrarfc: kolaCreateClob()+123<-kolaslCreateClob()+144<-kole_templob_init()+431<-kole_substr()+728<-kokle_substr()+340<-evaopn2()+612<-qersoRowP()+2657<-qerstRowP()+802<-kdstf010000100000000kmP()+1377<-kdsttgr()+2149<-qertbFetch()+1409<-qerstFetch()+477<-qersoProcessULS()+300<-qersoFetchSimple()+1433<-qersoFetch()+210
kolradls: 0x55 0xbc 0x0d 0x00 0x00 0x03 0x42 0x2f : 1 (32)
kolrarfc: 0x55 0xbc 0x0d 0x00 0x00 0x03 0x42 0x30 : 1
kolrarfc: kokltcc()+131<-koltitcr()+364<-kolttcr()+72<-kolaslWriteCreateTempLob()+607<-kolaslWrite()+656<-kolaWrite()+289<-kolaCopy()+726<-koklAbsCopy()+69<-kokasuc()+247<-koklcopy2()+4270<-koklc_copy()+78<-kole_append()+211<-kole_templob_init()+354<-kole_substr()+728<-kokle_substr()+340
Once the session reached the max heap, which seems to be
75% in my environment, it starts allocating non-in-memory temporary LOBs and there are functions such as
kolaslWrite and
kolaslWriteCreateTempLob on the callstack that implies that they might be writing something to the temporary tablespace.
Let us take a look now at the following PL/SQL block that emulates what the application code does:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
SQL> declare
2 v_reporting_freq constant pls_integer := 20000;
3 procedure log_info(i_msg varchar2)
4 is
5 begin
6 dbms_output.put_line(to_char(sysdate, 'hh24:mi:ss')||' '||i_msg);
7 end log_info;
8 begin
9 log_info('Starting execution');
10 for test_rec in (
11 select n,
12 substr(c, 1, 40) c_part1,
13 substr(c, 41, 40) c_part2,
14 substr(c, 81, 40) c_part3
15 from t100
16 where n <= 100000
17 order by n)
18 loop
19 if mod(test_rec.n, v_reporting_freq) = 0
20 then
21 log_info('Processed '||v_reporting_freq||' rows');
22 end if;
23 end loop;
24 log_info('Finishing execution');
25 end;
26 /
06:35:34 Starting execution
06:36:58 Processed 20000 rows
06:37:10 Processed 20000 rows
06:37:18 Processed 20000 rows
06:37:21 Processed 20000 rows
06:37:22 Processed 20000 rows
06:44:52 Finishing execution
PL/SQL procedure successfully completed.
Elapsed: 00:09:18.82
There are a few observations about this output:
The SELECT was running from 35:34 37:22 108
The block itself was running in 9 minutes 18 seconds or in 558 108(SELECT)+450(other)
What exactly happened between 06:37:22 06:44:52 450
Here is a tkprof processed tracefile:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
SQL ID: btysk50atwccn Plan Hash: 1939537825
SELECT N, SUBSTR(C, 1, 40) C_PART1, SUBSTR(C, 41, 40) C_PART2, SUBSTR(C, 81,
40) C_PART3
FROM
T100 WHERE N <= 100000 ORDER BY N
call count cpu elapsed disk query current rows
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1001 106.43 107.82 5029 3341 649751 100000
total 1003 106.43 107.82 5029 3341 649751 100000
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 107 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
100000 100000 100000 SORT ORDER BY (cr=3341 pr=5029 pw=1695 time=108105549 us starts=1 cost=2080 size=4600000 card=100000)
100000 100000 100000 TABLE ACCESS FULL T100 (cr=3341 pr=3334 pw=0 time=474939 us starts=1 cost=923 size=4600000 card=100000)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
PGA memory operation 37387 0.00 0.29
Disk file operations I/O 2 0.00 0.00
db file scattered read 67 0.00 0.09
CSS initialization 1 0.00 0.00
CSS operation: query 6 0.00 0.00
CSS operation: action 1 0.00 0.00
direct path write temp 26 0.00 0.02
direct path read temp 66 0.00 0.07
********************************************************************************
declare
v_reporting_freq constant pls_integer := 20000;
procedure log_info(i_msg varchar2)
is
begin
dbms_output.put_line(to_char(sysdate, 'hh24:mi:ss')||' '||i_msg);
end log_info;
begin
log_info('Starting execution');
for test_rec in (
select n,
substr(c, 1, 40) c_part1,
substr(c, 41, 40) c_part2,
substr(c, 81, 40) c_part3
from t100
where n <= 100000
order by n)
loop
if mod(test_rec.n, v_reporting_freq) = 0
then
log_info('Processed '||v_reporting_freq||' rows');
end if;
end loop;
log_info('Finishing execution');
end;
call count cpu elapsed disk query current rows
Parse 1 0.00 0.00 0 0 0 0
Execute 1 446.41 450.44 0 0 468361 1
Fetch 0 0.00 0.00 0 0 0 0
total 2 446.41 450.44 0 0 468361 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 107
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
PGA memory operation 419 0.11 0.13
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.10 0.10
There are no waits that can explain why the block took 450 seconds to execute.
Let us get to the raw tracefile then:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
PARSING IN CURSOR #140371888210368 len=617 dep=0 uid=107 oct=47 lid=107 tim=9831631653615 hv=2253167668 ad='c9f31410' sqlid='3sfmy3y34t71n'
declare
v_reporting_freq constant pls_integer := 20000;
procedure log_info(i_msg varchar2)
is
begin
dbms_output.put_line(to_char(sysdate, 'hh24:mi:ss')||' '||i_msg);
end log_info;
begin
log_info('Starting execution');
for test_rec in (
select n,
substr(c, 1, 40) c_part1,
substr(c, 41, 40) c_part2,
substr(c, 81, 40) c_part3
from t100
where n <= 100000
order by n)
loop
if mod(test_rec.n, v_reporting_freq) = 0
then
log_info('Processed '||v_reporting_freq||' rows');
end if;
end loop;
log_info('Finishing execution');
end;
END OF STMT
PARSE #140371888210368:c=96,e=95,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=9831631653614
=====================
PARSING IN CURSOR #140371888222536 len=127 dep=1 uid=107 oct=3 lid=107 tim=9831631654062 hv=362688916 ad='c91e39a0' sqlid='btysk50atwccn'
SELECT N, SUBSTR(C, 1, 40) C_PART1, SUBSTR(C, 41, 40) C_PART2, SUBSTR(C, 81, 40) C_PART3 FROM T100 WHERE N <= 100000 ORDER BY N
END OF STMT
PARSE #140371888222536:c=95,e=95,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1939537825,tim=9831631654062
EXEC #140371888222536:c=41,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1939537825,tim=9831631654152
..skip..
FETCH #140371888222536:c=946,e=539,p=0,cr=0,cu=0,mis=0,r=100,dep=1,og=1,plh=1939537825,tim=9831739623035
FETCH #140371888222536:c=59,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1939537825,tim=9831739623185
STAT #140371888222536 id=1 cnt=100000 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3341 pr=5029 pw=1695 str=1 time=108105549 us cost=2080 size=4600000 card=100000)'
STAT #140371888222536 id=2 cnt=100000 pid=1 pos=1 obj=158217 op='TABLE ACCESS FULL T100 (cr=3341 pr=3334 pw=0 str=1 time=474939 us cost=923 size=4600000 card=100000)'
*** 2019-10-23 06:44:52.738 (PDB(3))
CLOSE #140371888222536:c=1,e=1,dep=1,type=3,tim=9832189916721
EXEC #140371888210368:c=552847911,e=558267064,p=5029,cr=3341,cu=1118112,mis=0,r=1,dep=0,og=1,plh=0,tim=9832189920765
*** 2019-10-23 06:44:52.934 (PDB(3))
WAIT #140371888210368: nam='PGA memory operation' ela= 89 p1=0 p2=0 p3=0 obj#=158217 tim=9832190113279
WAIT #140371888210368: nam='PGA memory operation' ela= 61 p1=0 p2=0 p3=0 obj#=158217 tim=9832190113427
The tracefile does not show what was going on between the last fetch(tim=
9831739623185 ) and the time the cursor was closed(tim=
9832189916721 ).
Here is the
V$ACTIVE_SESSION_HISTORY (ASH) output for the problem block:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
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 pga_allocated,
20 temp_space_allocated
21 from v$active_session_history
22 where session_id = 52
23 and sample_time >= timestamp'2019-10-23 06:35:33'
24 order by sample_time;
SAMPLE_T SQL_ID SQL_OPNAME TOP_LEVEL_SQL SESSION_STATE EVENT ACTIVITY PGA_ALLOCATED TEMP_SPACE_ALLOCATED
06:35:35 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 316826624 0
06:35:36 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 526869504 0
06:35:37 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 667640832 0
06:35:38 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 775185408 0
06:35:39 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 870933504 5242880
06:35:40 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 946693120 5242880
06:35:41 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1025664000 5242880
06:35:42 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1087202304 5242880
06:35:43 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1153000448 6291456
06:35:44 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1216242688 6291456
06:35:45 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1276404736 6291456
06:35:46 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1321624576 6291456
06:35:47 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1372152832 7340032
06:35:48 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1424450560 7340032
06:35:49 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1474192384 7340032
06:35:50 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1520133120 7340032
06:35:51 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1563255808 7340032
06:35:52 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 1593336832 8388608
..skip..
SAMPLE_T SQL_ID SQL_OPNAME TOP_LEVEL_SQL SESSION_STATE EVENT ACTIVITY PGA_ALLOCATED TEMP_SPACE_ALLOCATED
06:37:19 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2461950976 715128832
06:37:20 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2461950976 715128832
06:37:21 btysk50atwccn SELECT 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2461950976 715128832
06:37:23 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2460902400 700448768
06:37:24 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2460902400 700448768
06:37:25 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2460902400 700448768
06:37:26 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2460902400 700448768
06:44:50 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2460902400 700448768
06:44:51 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2460902400 700448768
06:44:52 3sfmy3y34t71n ON CPU IN_SQL_EXECUTION 2460902400 700448768
I would rather expect to see some PGA and TEMP deallocations between
06:37:22 (the time when the SELECT completes) and
06:44:52 (the time when the block completes) but there are none.
While I was looking at
V$TEMPORARY_LOBS , I was observing that the session was constantly releasing LOBs during the period in question.
Remember there are
300K abstract LOBs created - they are being released in those
450 seconds.
However, it is not reflected in ASH as far as I am aware.
All PGA and TEMP deallocations happen at once and there is really no hint in ASH to figure out what is going on.
Let us take a look at the Flamegraph to see what Oracle functions contributed to most load:
Flame Graph
Reset Zoom
Search
kola_set_locator (5 samples, 0.01%)
kohalc (13 samples, 0.02%)
__dta_xfs_vn_update_time_3412 (10 samples, 0.02%)
schedule (22 samples, 0.04%)
__vfs_write (5 samples, 0.01%)
kgghstfel_wfp (5 samples, 0.01%)
tlb_flush_mmu (7 samples, 0.01%)
kokliihdl (12 samples, 0.02%)
kcbzgb (19 samples, 0.03%)
free_pages_and_swap_cache (7 samples, 0.01%)
kgghstfel_wfp (7 samples, 0.01%)
kgghstine_wfp (51 samples, 0.09%)
kohalc (8 samples, 0.01%)
__handle_mm_fault (25 samples, 0.04%)
ktbchgro (33 samples, 0.06%)
kolaslWriteCreateTempLob (89 samples, 0.16%)
kghalf (10 samples, 0.02%)
sou2o (55,631 samples, 99.90%) sou2o
kohfrem (9 samples, 0.02%)
kolredur (44,967 samples, 80.75%) kolredur
do_syscall_64 (5 samples, 0.01%)
opifch2 (55,602 samples, 99.85%) opifch2
dbgtRecVAWriteDisk (37 samples, 0.07%)
finish_task_switch (30 samples, 0.05%)
kgh_invoke_alloc_cb (66 samples, 0.12%)
kdlrdo (130 samples, 0.23%)
ktecgsc (9 samples, 0.02%)
async_page_fault (61 samples, 0.11%)
entry_SYSCALL_64_after_hwframe (5 samples, 0.01%)
do_async_page_fault (41 samples, 0.07%)
run_timer_softirq (9 samples, 0.02%)
do_syscall_64 (31 samples, 0.06%)
__handle_mm_fault (35 samples, 0.06%)
tlb_finish_mmu (8 samples, 0.01%)
apic_timer_interrupt (28 samples, 0.05%)
rpidrv (55,607 samples, 99.86%) rpidrv
koklSurrCheck (7 samples, 0.01%)
plsql_run (55,610 samples, 99.86%) plsql_run
koklreadSurrChk (44 samples, 0.08%)
do_async_page_fault (9 samples, 0.02%)
dbgtTrcVaList_int (21 samples, 0.04%)
kpoal8 (55,610 samples, 99.86%) kpoal8
kollfre (14 samples, 0.03%)
kghalp (160 samples, 0.29%)
kolrghte (10 samples, 0.02%)
kdlfill (20 samples, 0.04%)
ksmrf_init_alloc (51 samples, 0.09%)
qerstRowP (6,579 samples, 11.81%) qerstRowP
kdlw_locator_op (13 samples, 0.02%)
kolaFree_rfc (44,931 samples, 80.69%) kolaFree_rfc
schedule (35 samples, 0.06%)
psddr0 (55,607 samples, 99.86%) psddr0
_intel_fast_memcmp (2,594 samples, 4.66%) _inte..
kolrarfc (6 samples, 0.01%)
ssthrdmain (55,631 samples, 99.90%) ssthrdmain
kolaCreate_rfc (178 samples, 0.32%)
ksni_handle_net_intr_int (21 samples, 0.04%)
kgicls (5 samples, 0.01%)
kokltcc (77 samples, 0.14%)
opiodr (55,631 samples, 99.90%) opiodr
kghalp (87 samples, 0.16%)
release_pages (6 samples, 0.01%)
koklcprv (10 samples, 0.02%)
kdltfinddur (5 samples, 0.01%)
do_syscall_64 (5 samples, 0.01%)
opidrv (55,631 samples, 99.90%) opidrv
kokegOpnGC_Lob (5,458 samples, 9.80%) kokegOpnGC_Lob
ksmarfg (34 samples, 0.06%)
kdlw_locator_op (17 samples, 0.03%)
entry_SYSCALL_64_after_hwframe (17 samples, 0.03%)
rpiswu2 (55,607 samples, 99.86%) rpiswu2
koklCurrentDataInline (20 samples, 0.04%)
handle_mm_fault (25 samples, 0.04%)
unmap_region (11 samples, 0.02%)
prepare_exit_to_usermode (15 samples, 0.03%)
kolrghte (13 samples, 0.02%)
qersoProcessULS (6,607 samples, 11.86%) qersoProcessULS
kolaGetHeap (21 samples, 0.04%)
all (55,686 samples, 100%)
kgh_invoke_alloc_cb (35 samples, 0.06%)
kokegPinLob (3,828 samples, 6.87%) kokegPinLob
kcbchg1_main (138 samples, 0.25%)
qmuhshget_internal (1,408 samples, 2.53%) qm..
kokegPromoteLob (21 samples, 0.04%)
dbgtTrcVaList_int (5 samples, 0.01%)
kolrdrfc (20 samples, 0.04%)
kdl_write1 (254 samples, 0.46%)
ttcpip (55,631 samples, 99.90%) ttcpip
do_anonymous_page (25 samples, 0.04%)
kolaAssign_rfc (20 samples, 0.04%)
koltitfr (44,820 samples, 80.49%) koltitfr
kokltslfn (5 samples, 0.01%)
kohfrem (5 samples, 0.01%)
kgghash (7 samples, 0.01%)
sys_write (5 samples, 0.01%)
schedule (23 samples, 0.04%)
kdlw_xid_eq (14 samples, 0.03%)
ksm_pga_limit_interrupt (21 samples, 0.04%)
apic_timer_interrupt (43 samples, 0.08%)
kghfnd (69 samples, 0.12%)
run_timer_softirq (7 samples, 0.01%)
kolttfr (44,827 samples, 80.50%) kolttfr
swapgs_restore_regs_and_return_to_usermode (12 samples, 0.02%)
vm_mmap_pgoff (26 samples, 0.05%)
rworupo (3,862 samples, 6.94%) rworupo
koklRead (71 samples, 0.13%)
kdlrsp (136 samples, 0.24%)
async_page_fault (9 samples, 0.02%)
ktecgetsh (11 samples, 0.02%)
kolrghte (5 samples, 0.01%)
koklglfn (7 samples, 0.01%)
do_anonymous_page (5 samples, 0.01%)
kollfrfn (5 samples, 0.01%)
main (55,631 samples, 99.90%) main
kolrddc (9 samples, 0.02%)
irq_exit (10 samples, 0.02%)
finish_task_switch (18 samples, 0.03%)
handle_mm_fault (35 samples, 0.06%)
kokegOpnGarbagePromote (25 samples, 0.04%)
kolrarfc (106 samples, 0.19%)
kghalf (8 samples, 0.01%)
kgghstdle_wfp (20 samples, 0.04%)
_intel_fast_memcmp (11,139 samples, 20.00%) _intel_fast_memcmp
kokltfc (44,780 samples, 80.42%) kokltfc
kdl_destroy (22,554 samples, 40.50%) kdl_destroy
kpdbHashTable_Find (6 samples, 0.01%)
peicnt (55,610 samples, 99.86%) peicnt
irq_exit (5 samples, 0.01%)
_intel_fast_memcmp (591 samples, 1.06%)
kolrde_alloc (8 samples, 0.01%)
rcu_process_callbacks (6 samples, 0.01%)
koklInlineRead (50 samples, 0.09%)
irq_exit (43 samples, 0.08%)
apic_timer_interrupt (40 samples, 0.07%)
kokacau (8 samples, 0.01%)
kohfrw (5 samples, 0.01%)
kdlopen (11,508 samples, 20.67%) kdlopen
kgghstdle_wfp (6 samples, 0.01%)
pmuocpy (61 samples, 0.11%)
koklWrite (277 samples, 0.50%)
kolaCreateClob (178 samples, 0.32%)
kohfrr (5 samples, 0.01%)
kdlw_xid_eq (7 samples, 0.01%)
__dta_xfs_file_buffered_aio_write_3297 (5 samples, 0.01%)
kdlt_filltid (11,654 samples, 20.93%) kdlt_filltid
do_page_fault (41 samples, 0.07%)
kcbhfho (10 samples, 0.02%)
kghualloc (6 samples, 0.01%)
kcbzgs (13 samples, 0.02%)
smp_apic_timer_interrupt (43 samples, 0.08%)
exit_to_usermode_loop (14 samples, 0.03%)
swapgs_restore_regs_and_return_to_usermode (39 samples, 0.07%)
__schedule (35 samples, 0.06%)
koklAbsCopy (618 samples, 1.11%)
do_munmap (13 samples, 0.02%)
kolrgmd (6 samples, 0.01%)
opifcr (136 samples, 0.24%)
kolttcr (82 samples, 0.15%)
kcbhfix_tail (6 samples, 0.01%)
dbgtfdFileWrite (24 samples, 0.04%)
kdlclose (10,877 samples, 19.53%) kdlclose
smp_apic_timer_interrupt (5 samples, 0.01%)
sdbgrfwf_write_file (17 samples, 0.03%)
arch_local_irq_enable (6 samples, 0.01%)
__dta_xfs_file_buffered_aio_write_3297 (5 samples, 0.01%)
swapgs_restore_regs_and_return_to_usermode (45 samples, 0.08%)
kgghstmap (44,967 samples, 80.75%) kgghstmap
skgmstack (55,607 samples, 99.86%) skgmstack
ktsbbsrch (31 samples, 0.06%)
free_hot_cold_page_list (6 samples, 0.01%)
kollasg (51 samples, 0.09%)
smp_apic_timer_interrupt (7 samples, 0.01%)
opimai_real (55,631 samples, 99.90%) opimai_real
kdlwfb (237 samples, 0.43%)
irq_exit (40 samples, 0.07%)
opipls (55,605 samples, 99.85%) opipls
kolaFree (44 samples, 0.08%)
kxsFreeWorkArea (44,968 samples, 80.75%) kxsFreeWorkArea
koklReadCbk (70 samples, 0.13%)
kolrdladd (12 samples, 0.02%)
irq_exit (38 samples, 0.07%)
__do_page_fault (40 samples, 0.07%)
xfs_file_write_iter (17 samples, 0.03%)
qersoFetch (10,625 samples, 19.08%) qersoFetch
kghfrh_internal (8 samples, 0.01%)
kdlrci_get_inline_data (9 samples, 0.02%)
kohalc (7 samples, 0.01%)
schedule (6 samples, 0.01%)
kcoapl (134 samples, 0.24%)
kole_getFillChar (9 samples, 0.02%)
kohfrw (13 samples, 0.02%)
smp_apic_timer_interrupt (38 samples, 0.07%)
pmuocpy2_copy_recur (61 samples, 0.11%)
__do_softirq (7 samples, 0.01%)
kollasg (56 samples, 0.10%)
koklCurrentDataInline (17 samples, 0.03%)
irq_exit (7 samples, 0.01%)
kdstf010000100000000kmP (6,606 samples, 11.86%) kdstf010000100000..
kghufree (12 samples, 0.02%)
kdlt_freetemp (33,088 samples, 59.42%) kdlt_freetemp
kolaslFree (44,871 samples, 80.58%) kolaslFree
kgghstfel_wfp (17 samples, 0.03%)
kgghash (22 samples, 0.04%)
kghalf (15 samples, 0.03%)
__mmap64 (32 samples, 0.06%)
kgghash (15 samples, 0.03%)
koklc_copy (633 samples, 1.14%)
kolrgrfc (5 samples, 0.01%)
kghgex (36 samples, 0.06%)
_intel_fast_memcmp (15 samples, 0.03%)
koklClosePCursor (10 samples, 0.02%)
oracle_16067_sf (55,686 samples, 100.00%) oracle_16067_sf
rpidrus (55,607 samples, 99.86%) rpidrus
ktcsna (10 samples, 0.02%)
kolaFree_rfc (43 samples, 0.08%)
__handle_mm_fault (6 samples, 0.01%)
pevm_BFTCHC (55,607 samples, 99.86%) pevm_BFTCHC
koklpgsz (58 samples, 0.10%)
_raw_spin_lock (7 samples, 0.01%)
kokle_substr (1,066 samples, 1.91%) k..
smp_apic_timer_interrupt (9 samples, 0.02%)
koklSurrCheck (7 samples, 0.01%)
kohalmc (5 samples, 0.01%)
kdlt_add_tlob_ctl_link (5 samples, 0.01%)
kghsupmm (88 samples, 0.16%)
sys_write (5 samples, 0.01%)
opikndf2 (21 samples, 0.04%)
arch_local_irq_enable (15 samples, 0.03%)
_intel_fast_memcmp (6 samples, 0.01%)
kghgex (6 samples, 0.01%)
qerstFetch (10,625 samples, 19.08%) qerstFetch
mmap_region (21 samples, 0.04%)
kolrarfc (57 samples, 0.10%)
kslwtectx (47 samples, 0.08%)
smp_apic_timer_interrupt (5 samples, 0.01%)
kokegGarbageCollectRworo (3,861 samples, 6.93%) kokegGarb..
kghssagptr (90 samples, 0.16%)
kolrgrfc (17 samples, 0.03%)
kolttfr_ed (44,932 samples, 80.69%) kolttfr_ed
kghgex (145 samples, 0.26%)
__handle_mm_fault (5 samples, 0.01%)
kolaAssign (7 samples, 0.01%)
kollalop (5 samples, 0.01%)
kolrdrfc (8 samples, 0.01%)
kole_append (633 samples, 1.14%)
__write_nocancel (17 samples, 0.03%)
do_anonymous_page (30 samples, 0.05%)
kolaAssign (21 samples, 0.04%)
koklpgszCbk (17 samples, 0.03%)
kgghstfel_wfp (13 samples, 0.02%)
__schedule (6 samples, 0.01%)
dbgtRecVAWriteDisk (5 samples, 0.01%)
ktecgshx (38 samples, 0.07%)
kolaslWrite (467 samples, 0.84%)
kolttfr (44 samples, 0.08%)
_intel_fast_memcpy (40 samples, 0.07%)
koklc_write (279 samples, 0.50%)
entry_SYSCALL_64_after_hwframe (5 samples, 0.01%)
sdbgrfwf_write_file (5 samples, 0.01%)
koklCurrentDataInline (8 samples, 0.01%)
do_mmap (23 samples, 0.04%)
exit_to_usermode_loop (33 samples, 0.06%)
kolrddc (30 samples, 0.05%)
kgghstine_wfp (23 samples, 0.04%)
__do_page_fault (61 samples, 0.11%)
finish_task_switch (5 samples, 0.01%)
__do_softirq (39 samples, 0.07%)
__do_softirq (41 samples, 0.07%)
kghbshrt (45 samples, 0.08%)
kollulin (15 samples, 0.03%)
__schedule (17 samples, 0.03%)
__alloc_pages_nodemask (11 samples, 0.02%)
xfs_file_write_iter (5 samples, 0.01%)
__schedule (7 samples, 0.01%)
kolrghte (35 samples, 0.06%)
kole_t2u_int (8 samples, 0.01%)
kghfrempty_subheaps_all (21 samples, 0.04%)
alloc_pages_vma (11 samples, 0.02%)
kolradlst (63 samples, 0.11%)
kghalo (149 samples, 0.27%)
sys_mmap_pgoff (26 samples, 0.05%)
ktsbvini (12 samples, 0.02%)
kokegGarbageCollectOpn (5,463 samples, 9.81%) kokegGarbageCo..
sorgetqbf (11 samples, 0.02%)
ktecgetsh (37 samples, 0.07%)
sdbgrfwf_write_file (6 samples, 0.01%)
schedule (7 samples, 0.01%)
kohalmc (5 samples, 0.01%)
kghfnd (86 samples, 0.15%)
irq_exit (28 samples, 0.05%)
koltitcr (81 samples, 0.15%)
sys_mmap (26 samples, 0.05%)
arch_local_irq_enable (9 samples, 0.02%)
koklcprv (24 samples, 0.04%)
dbgtfWriteRec (18 samples, 0.03%)
kdsttgr (6,606 samples, 11.86%) kdsttgr
kdlgsp (59 samples, 0.11%)
kghfrmrg (7 samples, 0.01%)
exit_to_usermode_loop (38 samples, 0.07%)
arch_tlb_finish_mmu (7 samples, 0.01%)
xfs_trans_alloc (6 samples, 0.01%)
exit_to_usermode_loop (44 samples, 0.08%)
kokltfr_pdbcbk (44,771 samples, 80.40%) kokltfr_pdbcbk
kolrgrfc (8 samples, 0.01%)
kghfrf (15 samples, 0.03%)
kghalo (85 samples, 0.15%)
prepare_exit_to_usermode (14 samples, 0.03%)
kolaFree (17 samples, 0.03%)
finish_task_switch (20 samples, 0.04%)
qerstRowP (138 samples, 0.25%)
opiodr (55,610 samples, 99.86%) opiodr
koklNeedSurrChk (6 samples, 0.01%)
dbgtTrc_int (5 samples, 0.01%)
kghfnd (66 samples, 0.12%)
do_anonymous_page (5 samples, 0.01%)
vfs_write (5 samples, 0.01%)
kghprmalo (158 samples, 0.28%)
kghalp (7 samples, 0.01%)
_intel_fast_memcmp (10,047 samples, 18.04%) _intel_fast_memcmp
kcbgcur (13 samples, 0.02%)
kdltfindctl (477 samples, 0.86%)
kolrgrfc (10 samples, 0.02%)
opiino (55,631 samples, 99.90%) opiino
free_hot_cold_page (5 samples, 0.01%)
kprccu (66 samples, 0.12%)
kdlf_write (259 samples, 0.47%)
kghprmalo (87 samples, 0.16%)
dbgtfmWriteMetadata (9 samples, 0.02%)
kksumc (44,968 samples, 80.75%) kksumc
ktsbgsp1 (58 samples, 0.10%)
kohfrr (17 samples, 0.03%)
kolaAssign_rfc (7 samples, 0.01%)
kohalc (5 samples, 0.01%)
__do_softirq (10 samples, 0.02%)
kohalw (13 samples, 0.02%)
kgghstfel_wfp (8 samples, 0.01%)
dbgtfdFileWrite (7 samples, 0.01%)
kolaCopy (613 samples, 1.10%)
kokavpr (8 samples, 0.01%)
do_page_fault (9 samples, 0.02%)
kdlw_locator_op_read (10 samples, 0.02%)
kolrghte (22 samples, 0.04%)
kghbshrt (72 samples, 0.13%)
kgghash (11 samples, 0.02%)
kdlwdb (178 samples, 0.32%)
kcbgcur (26 samples, 0.05%)
apic_timer_interrupt (5 samples, 0.01%)
kghalf (21 samples, 0.04%)
kspgip (6 samples, 0.01%)
kolrghte (5 samples, 0.01%)
kokavpr (23 samples, 0.04%)
kxstTraceWait (22 samples, 0.04%)
kole_t2u (8 samples, 0.01%)
arch_local_irq_enable (14 samples, 0.03%)
kxsdmc (44,967 samples, 80.75%) kxsdmc
kghalf (41 samples, 0.07%)
kghalo (35 samples, 0.06%)
ktbchgro (138 samples, 0.25%)
schedule (17 samples, 0.03%)
prepare_exit_to_usermode (12 samples, 0.02%)
kgghstine_wfp (30 samples, 0.05%)
ktbchgro (12 samples, 0.02%)
pfrrun (55,610 samples, 99.86%) pfrrun
do_page_fault (6 samples, 0.01%)
prepare_exit_to_usermode (39 samples, 0.07%)
kokasuc (619 samples, 1.11%)
irq_exit (5 samples, 0.01%)
tlb_flush_mmu_free (7 samples, 0.01%)
get_page_from_freelist (7 samples, 0.01%)
kolrgrfc2 (23 samples, 0.04%)
do_page_fault (61 samples, 0.11%)
kghfnd (35 samples, 0.06%)
kcbgcur (8 samples, 0.01%)
prepare_exit_to_usermode (37 samples, 0.07%)
__dta_xfs_file_buffered_aio_write_3297 (17 samples, 0.03%)
_setjmp (5 samples, 0.01%)
skgmrf_alloc (50 samples, 0.09%)
dbgtRecVAWriteDisk (19 samples, 0.03%)
kokegPinLob (5,451 samples, 9.79%) kokegPinLob
__do_page_fault (9 samples, 0.02%)
kdlrsp (5 samples, 0.01%)
__schedule (21 samples, 0.04%)
_intel_fast_memcmp (10,942 samples, 19.65%) _intel_fast_memcmp
kgghstfel_wfp (13 samples, 0.02%)
kohalmc (6 samples, 0.01%)
kohfrr (13 samples, 0.02%)
kdltfindctl (499 samples, 0.90%)
kollalop (14 samples, 0.03%)
opiodr (55,607 samples, 99.86%) opiodr
kghalf (5 samples, 0.01%)
kohalw (8 samples, 0.01%)
kcbinvbrhb (6 samples, 0.01%)
__dta_xfs_file_aio_write_checks_3294 (13 samples, 0.02%)
kghalo (83 samples, 0.15%)
qmuhshput (1,036 samples, 1.86%) q..
swapgs_restore_regs_and_return_to_usermode (37 samples, 0.07%)
kghfnd_get_extent (156 samples, 0.28%)
kgghstfel_wfp (5 samples, 0.01%)
kdltfindctl (512 samples, 0.92%)
ktsbbset (13 samples, 0.02%)
finish_task_switch (15 samples, 0.03%)
koklc_length (37 samples, 0.07%)
__vfs_write (5 samples, 0.01%)
kcbchg1 (138 samples, 0.25%)
kghfnd (83 samples, 0.15%)
kokltcr (75 samples, 0.13%)
kghfrf (6 samples, 0.01%)
ktsbdba_vbn (26 samples, 0.05%)
alloc_pages_vma (12 samples, 0.02%)
kolrghte (6 samples, 0.01%)
kghgex (66 samples, 0.12%)
evaopn2 (6,532 samples, 11.73%) evaopn2
kaf_typed_stuff (8 samples, 0.01%)
irq_exit (9 samples, 0.02%)
koklSurrCheck (30 samples, 0.05%)
kolttfr (17 samples, 0.03%)
__do_softirq (38 samples, 0.07%)
ktsbbscn (18 samples, 0.03%)
kghfrf (6 samples, 0.01%)
apic_timer_interrupt (38 samples, 0.07%)
kpmdurend (44,967 samples, 80.75%) kpmdurend
kghfnd (36 samples, 0.06%)
do_syscall_64 (17 samples, 0.03%)
dbgtTrc_int (40 samples, 0.07%)
kolaFree_rfc (17 samples, 0.03%)
_intel_fast_memcmp (6 samples, 0.01%)
kcbchg1_main (27 samples, 0.05%)
_intel_fast_memcmp (2,998 samples, 5.38%) _intel..
kolrgrfc (9 samples, 0.02%)
kgghstfel_wfp (22 samples, 0.04%)
kohalw (5 samples, 0.01%)
kokacau (20 samples, 0.04%)
__do_softirq (7 samples, 0.01%)
opitsk (55,631 samples, 99.90%) opitsk
_dl_addr (7 samples, 0.01%)
kollas2 (60 samples, 0.11%)
pfrinstr_BFTCHC (55,607 samples, 99.86%) pfrinstr_BFTCHC
kolaFree (44,931 samples, 80.69%) kolaFree
vfs_write (17 samples, 0.03%)
_intel_fast_memcmp (8 samples, 0.01%)
arch_local_irq_enable (6 samples, 0.01%)
kghgex (86 samples, 0.15%)
kghssgmm (90 samples, 0.16%)
__write_nocancel (5 samples, 0.01%)
kolrgrfc (5 samples, 0.01%)
kcbchg1_main (12 samples, 0.02%)
kssadf_numa_intl (7 samples, 0.01%)
qmuhsh_get (4,406 samples, 7.91%) qmuhsh_get
run_timer_softirq (7 samples, 0.01%)
kdltfindctl (556 samples, 1.00%)
rpidru (55,607 samples, 99.86%) rpidru
kcbzfb (9 samples, 0.02%)
koklpgszCbk (52 samples, 0.09%)
__schedule (21 samples, 0.04%)
get_page_from_freelist (7 samples, 0.01%)
kghalo (66 samples, 0.12%)
vfs_write (5 samples, 0.01%)
file_update_time (13 samples, 0.02%)
opifch (55,602 samples, 99.85%) opifch
entry_SYSCALL_64_after_hwframe (31 samples, 0.06%)
smp_apic_timer_interrupt (28 samples, 0.05%)
koklpgsz (21 samples, 0.04%)
_IO_vsnprintf (9 samples, 0.02%)
kgghstfel_wfp (10 samples, 0.02%)
prepare_exit_to_usermode (45 samples, 0.08%)
kghgex (35 samples, 0.06%)
kpdbUidToId (7 samples, 0.01%)
koklc_pagesize (58 samples, 0.10%)
kdli_iread (8 samples, 0.01%)
psdnal (55,607 samples, 99.86%) psdnal
kghgex (83 samples, 0.15%)
arch_local_irq_enable (13 samples, 0.02%)
kghuwrlength (5 samples, 0.01%)
_intel_fast_memcmp (10,369 samples, 18.62%) _intel_fast_memcmp
swapgs_restore_regs_and_return_to_usermode (15 samples, 0.03%)
koklglen (37 samples, 0.07%)
qmuhshget_internal (1,233 samples, 2.21%) q..
opiexe (55,610 samples, 99.86%) opiexe
kgghstfel_wfp (9 samples, 0.02%)
do_async_page_fault (61 samples, 0.11%)
kprcdt (63 samples, 0.11%)
apic_timer_interrupt (9 samples, 0.02%)
clear_page_erms (5 samples, 0.01%)
exit_to_usermode_loop (15 samples, 0.03%)
do_async_page_fault (6 samples, 0.01%)
apic_timer_interrupt (10 samples, 0.02%)
smp_apic_timer_interrupt (10 samples, 0.02%)
__do_softirq (28 samples, 0.05%)
ktcsna (8 samples, 0.01%)
__do_softirq (5 samples, 0.01%)
koklc_sysparam (6 samples, 0.01%)
kghfrempty_sh_all_depth (19 samples, 0.03%)
kohedu (44,967 samples, 80.75%) kohedu
skgmrf_alloc (26 samples, 0.05%)
apic_timer_interrupt (5 samples, 0.01%)
kollfrfn (14 samples, 0.03%)
kolrde_free (17 samples, 0.03%)
kcoapl (14 samples, 0.03%)
__intel_new_memset (14 samples, 0.03%)
kgghstfel_wfp (35 samples, 0.06%)
ktecgshx (11 samples, 0.02%)
kohdee (44,967 samples, 80.75%) kohdee
kokegCollectGarbageFromScalar (3,859 samples, 6.93%) kokegColl..
ktsbfsp (121 samples, 0.22%)
dbgtfmWriteMetadata (9 samples, 0.02%)
handle_mm_fault (6 samples, 0.01%)
kco_issue_callback (6 samples, 0.01%)
xfs_file_write_iter (5 samples, 0.01%)
__alloc_pages_nodemask (12 samples, 0.02%)
ktsbvini (39 samples, 0.07%)
kafger (12 samples, 0.02%)
sys_write (17 samples, 0.03%)
__vfs_write (17 samples, 0.03%)
ktsbbfill (18 samples, 0.03%)
dbgtTrc_int (22 samples, 0.04%)
pfrrun_no_tool (55,610 samples, 99.86%) pfrrun_no_tool
kghaddex (5 samples, 0.01%)
kolrghte (17 samples, 0.03%)
kxstTraceWait (45 samples, 0.08%)
pfsadrc (66 samples, 0.12%)
_intel_fast_memcmp (6 samples, 0.01%)
kolrghte (9 samples, 0.02%)
kcbchg1 (12 samples, 0.02%)
kolrgrfc (30 samples, 0.05%)
kokasuc (21 samples, 0.04%)
exit_to_usermode_loop (11 samples, 0.02%)
kcbivbr (9 samples, 0.02%)
kghgex (68 samples, 0.12%)
kghfnd (147 samples, 0.26%)
dbgtTrcVaList_int (40 samples, 0.07%)
prepare_exit_to_usermode (41 samples, 0.07%)
__do_softirq (5 samples, 0.01%)
__do_page_fault (6 samples, 0.01%)
qmuhshget_internal (434 samples, 0.78%)
koklcopy2 (630 samples, 1.13%)
koklglenCbk (34 samples, 0.06%)
kghfrempty (18 samples, 0.03%)
kokacpc (7 samples, 0.01%)
kcbchg1 (31 samples, 0.06%)
koklc_read (72 samples, 0.13%)
kollfre (5 samples, 0.01%)
ktecgsc (30 samples, 0.05%)
koklread (71 samples, 0.13%)
kolredurHashMapCbk (44,957 samples, 80.73%) kolredurHashMapCbk
kolrgdc (13 samples, 0.02%)
kslwtectx (25 samples, 0.04%)
qerstFetch (6,606 samples, 11.86%) qerstFetch
kcbnew (40 samples, 0.07%)
qmuhsh_get (3,827 samples, 6.87%) qmuhsh_get
kole_templob_init (1,010 samples, 1.81%) k..
kolradc (12 samples, 0.02%)
kdlw_locator_op_read (15 samples, 0.03%)
kcblibr_int (9 samples, 0.02%)
kxstcol (5 samples, 0.01%)
__intel_new_memset (5 samples, 0.01%)
kole_substr (1,056 samples, 1.90%) k..
smp_apic_timer_interrupt (40 samples, 0.07%)
handle_mm_fault (5 samples, 0.01%)
kgghstfel_wfp (28 samples, 0.05%)
kco_issue_callback (132 samples, 0.24%)
async_page_fault (6 samples, 0.01%)
kolrghte (28 samples, 0.05%)
kghfre (8 samples, 0.01%)
ksmrf_init_alloc (27 samples, 0.05%)
dbgtfWriteRec (37 samples, 0.07%)
__libc_start_main (55,631 samples, 99.90%) __libc_start_main
kohfrem (17 samples, 0.03%)
kdlt_createtemp (7 samples, 0.01%)
qersoRowP (6,575 samples, 11.81%) qersoRowP
dbgtfdFileAccessCbk (7 samples, 0.01%)
rcu_report_qs_rnp (5 samples, 0.01%)
ksmarfg (66 samples, 0.12%)
kghssgai (164 samples, 0.29%)
kkxexe (55,610 samples, 99.86%) kkxexe
exit_to_usermode_loop (39 samples, 0.07%)
koklwrite (279 samples, 0.50%)
swapgs_restore_regs_and_return_to_usermode (14 samples, 0.03%)
dbgtfdFileAccessCbk (24 samples, 0.04%)
kghfrempty_ex (21 samples, 0.04%)
kolaslCreateCtx (174 samples, 0.31%)
kdlt_remove_tlob_ctl_link (10,528 samples, 18.91%) kdlt_remove_tlob_ctl_link
kokasuc (8 samples, 0.01%)
smbput (7 samples, 0.01%)
arch_local_irq_enable (8 samples, 0.01%)
koklNeedSurrChk (6 samples, 0.01%)
__write_nocancel (5 samples, 0.01%)
[unknown] (15 samples, 0.03%)
qersoFetchSimple (10,625 samples, 19.08%) qersoFetchSimple
ksuintract_handle_network_interrupt (21 samples, 0.04%)
__intel_ssse3_rep_memcpy (69 samples, 0.12%)
kghalo (144 samples, 0.26%)
kohalmc (9 samples, 0.02%)
apic_timer_interrupt (7 samples, 0.01%)
dbgtfdFileWrite (5 samples, 0.01%)
ksuintract_exec_pending (21 samples, 0.04%)
async_page_fault (41 samples, 0.07%)
dbgtfWriteRec (5 samples, 0.01%)
qertbFetch (6,606 samples, 11.86%) qertbFetch
dbgtfdFileAccessCbk (5 samples, 0.01%)
kolaWrite (471 samples, 0.85%)
kxsFreeExecutionHeap (44,968 samples, 80.75%) kxsFreeExecutionHeap
swapgs_restore_regs_and_return_to_usermode (41 samples, 0.07%)
kolasaWrite (94 samples, 0.17%)
kolaslCreateClob (375 samples, 0.67%)
It can be seen that there are functions such as
kokegGarbageCollectOpn and
kokegGarbageCollectRworo that were active when
qersoFetch was active (19% of the time).
Those seem to be related to garbage collection and the koke prefix is present in the oradebug doc component output:
1
2
3
4
OBJECTS OBJECTS ((null))
OBJECTS_DDL OBJECTS DDL (kokt)
OBJECTS_Types OBJECTS Types (kot, ko, ort)
OBJECTS_Images OBJECTS Images (koke, kot, kad)
Most of the time (80%), though, the functions such as:
kksumc ,
kxsFreeExecutionHeap were active - they are supposedly related to releasing memory.
Oracle code might not be updating PGA_ALLOCATED, TEMP_SPACE_ALLOCATED till the whole duration is freed as I do not see any changes in those columns of V$ACTIVE_SESSION_HISTORY.
When I found that SUBSTR on LOBs produces new abstract LOBs, I implemented the following workaround:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
SQL> declare
2 v_reporting_freq constant pls_integer := 20000;
3 v_result clob;
4 procedure log_info(i_msg varchar2)
5 is
6 begin
7 dbms_output.put_line(to_char(sysdate, 'hh24:mi:ss')||' '||i_msg);
8 end log_info;
9 begin
10 log_info('Starting execution');
11 dbms_lob.createtemporary(v_result, cache=> true, dur=> dbms_lob.call);
12 for test_rec in (
13 select n,
14 dbms_lob.substr(c, 40, 1) c_part1,
15 dbms_lob.substr(c, 40, 41) c_part2,
16 dbms_lob.substr(c, 40, 81) c_part3
17 from t100
18 where n <= 100000
19 order by n)
20 loop
21 dbms_lob.append(v_result, test_rec.c_part1);
22 dbms_lob.append(v_result, test_rec.c_part2);
23 dbms_lob.append(v_result, test_rec.c_part3);
24 if mod(test_rec.n, v_reporting_freq) = 0
25 then
26 log_info('Processed '||v_reporting_freq||' rows');
27 end if;
28 end loop;
29 dbms_output.put_line('Lob size: '||dbms_lob.getlength(v_result));
30 dbms_lob.freetemporary(v_result);
31 log_info('Finishing execution');
32 end;
33 /
08:15:04 Starting execution
08:15:08 Processed 20000 rows
08:15:09 Processed 20000 rows
08:15:10 Processed 20000 rows
08:15:12 Processed 20000 rows
08:15:13 Processed 20000 rows
Lob size: 10000000
08:15:13 Finishing execution
PL/SQL procedure successfully completed.
Elapsed: 00:00:08.95
In spite of the fact that this block even writes a whole new LOB (there are no such operations in the block that was working 9 minutes), it completes just in 9 seconds. It is quite a neat optimization, isn't it?
That behavior of producing abstract LOBs of SUBSTR is documented:
Database SecureFiles and Large Objects Developer's Guide: Temporary LOBs :
If you use the newly provided enhanced SQL semantics functionality in your applications, then
there are many more temporary LOBs created silently in SQL and PL/SQL than before . Ensure that temporary tablespace for storing these temporary LOBs is large enough for your applications. In particular, these temporary LOBs are silently created when you use the following:
SQL functions on LOBs PL/SQL built-in character functions on LOBs
Variable assignments from VARCHAR2/RAW to CLOBs/BLOBs, respectively.
Perform a LONG-to-LOB migration
If SQL operators are used on LOBs, the PGA memory and temporary tablespace must be large enough to accommodate the temporary LOBs generated by SQL operators.
Apart from that workaround, I can come up with a few others that also provide significant performance boost:
This query is almost a corner-case due to that sorting. If the ORDER BY is really needed, then an indexed access on the N column can be considered.
These SUBSTR calls can be moved within the LOOP part, so that only the C column is selected in the query. Although it would not be the most efficient way to process the cursor (abstract LOBs will still be allocated), those abstract LOBs will be released after each iteration. Therefore, the time-consuming garbage collection at the end will be avoided.
All tests were performed on 12.2.0.1.190716. 19c has some nice optimizations, such as one mentioned in
Session spending its time IN_CURSOR_CLOSE
I was trying to reproduce that issue on 19c but I was not able to get the same results after a few attempts.
Though abstract LOBs were still allocated, they were being released rather quickly.
tl;dr
Oracle can create temporary LOBs when SQL functions are used on LOBs as this blog post demonstrates.
For example, SUBSTR behaves like that. Those calls can be replaced with DBMS_LOB.SUBSTR that does not lead to the aforementioned deficiency.
