Страницы

среда, 23 октября 2019 г.

Temporary LOBs

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:
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:
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:
-- I am gathering some memory statistics to be used in further research
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:
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:
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:
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:
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:
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:
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:
  1. The SELECT was running from 35:34 to 37:22, it is 108 seconds.
  2. The block itself was running in 9 minutes 18 seconds or in 558 seconds, which is 108(SELECT)+450(other)
  3. What exactly happened between 06:37:22, when was the last fetch, and 06:44:52 - that is exactly 450 seconds, when the block finished?
Here is a tkprof processed tracefile:
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
  ----------------------------------------   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
  ----------------------------------------   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:
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:
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
-------- ------------- ------------- ------------- ------------- ---------- ---------------- ------------- --------------------
-- the execution starts and the session steadily allocates PGA and TEMP
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
-------- ------------- ------------- ------------- ------------- ---------- ---------------- ------------- --------------------
-- the SELECT completes
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

-- the session is burning up CPUs
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:
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:
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:
  1. 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.
  2. 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.