Страницы

среда, 31 июля 2019 г.

Session spending its time IN_CURSOR_CLOSE

I encountered that issue originally when I migrated one of my databases to 12.2.0.1.190416.
I started my investigation when observed the following rows in V$ACTIVE_SESSION_HISTORY for one execution:
SQL> select to_char(sample_time, 'hh24:mi:ss') sample_time, sql_id, sql_opname, top_level_sql_id, session_state, event,
  2         trim(case when IN_CONNECTION_MGMT='Y' then ' IN_CONNECTION_MGMT' end||
  3              case when IN_PARSE='Y' then ' IN_PARSE' end||
  4              case when IN_HARD_PARSE='Y' then ' IN_HARD_PARSE' end||
  5              case when IN_SQL_EXECUTION='Y' then ' IN_SQL_EXECUTION' end||
  6              case when IN_PLSQL_EXECUTION='Y' then ' IN_PLSQL_EXECUTION' end||
  7              case when IN_PLSQL_RPC='Y' then ' IN_PLSQL_RPC' end||
  8              case when IN_PLSQL_COMPILATION='Y' then ' IN_PLSQL_COMPILATION' end||
  9              case when IN_JAVA_EXECUTION='Y' then ' IN_JAVA_EXECUTION' end||
 10              case when IN_BIND='Y' then ' IN_BIND' end||
 11              case when IN_CURSOR_CLOSE='Y' then ' IN_CURSOR_CLOSE' end||
 12              case when IN_SEQUENCE_LOAD='Y' then ' IN_SEQUENCE_LOAD' end||
 13              case when IN_INMEMORY_QUERY='Y' then ' IN_INMEMORY_QUERY' end||
 14              case when IN_INMEMORY_POPULATE='Y' then ' IN_INMEMORY_POPULATE' end||
 15              case when IN_INMEMORY_PREPOPULATE='Y' then ' IN_INMEMORY_PREPOPULATE' end||
 16              case when IN_INMEMORY_REPOPULATE='Y' then ' IN_INMEMORY_REPOPULATE' end||
 17              case when IN_INMEMORY_TREPOPULATE='Y' then ' IN_INMEMORY_TREPOPULATE' end||
 18              case when IN_TABLESPACE_ENCRYPTION='Y' then ' IN_TABLESPACE_ENCRYPTION' end) activity
 19    from v$active_session_history
 20   where session_id = 58
 21     and sample_time between timestamp'2019-07-30 20:47:41' and timestamp'2019-07-30 20:48:30'
 22   order by sample_time;

SAMPLE_T SQL_ID        SQL_OPNAME TOP_LEVEL_SQL SESSION EVENT      ACTIVITY
-------- ------------- ---------- ------------- ------- ---------- ---------------------------------------------------
20:47:42 a6n6qc8g855q6 SELECT     2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION
20:47:43 a6n6qc8g855q6 SELECT     2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION
20:47:44                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:45                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:46                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:47                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:48                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:49                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:50                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:51                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:52                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:53                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:54                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:55                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:56                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:57                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:58                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:47:59                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:00                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:01                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:02                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:03                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:04                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:05                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:06                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:07                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:08                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:09                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:10                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:11                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:12                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:13                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:14                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:15                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:16                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:17                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:18                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:19                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:20                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:21                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:22                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:23                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:24                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:25                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:26                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:27                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:28                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
20:48:29                          2puw0smn3qw99 ON CPU             IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_CURSOR_CLOSE
That was quite unusual as there was no SQL_ID and IN_CURSOR_CLOSE was set to 'Y'.
Here's an over-simplified version of what the session was doing:
SQL> declare
  2    cursor test_csr is
  3      select t1.*, user_agg_function(to_char(l)) c1
  4        from (select level l from dual connect by level<=30001) t1
  5       group by t1.l;
  6    type test_tbl_type is table of test_csr%rowtype;
  7    v_test_tbl test_tbl_type;
  8  begin
  9    open test_csr;
 10
 11    dbms_output.put_line(systimestamp||' After open');
 12
 13    for i in 1..6
 14    loop
 15      fetch test_csr bulk collect into v_test_tbl limit 5000;
 16      dbms_output.put_line(systimestamp||' After fetch');
 17    end loop;
 18
 19    dbms_output.put_line(systimestamp||' After all fetches');
 20
 21    close test_csr;
 22    dbms_output.put_line(systimestamp||' After close');
 23  end;
 24  /
30-JUL-19 08.47.41.576257000 PM +01:00 After open
30-JUL-19 08.47.41.866173000 PM +01:00 After fetch
30-JUL-19 08.47.42.153764000 PM +01:00 After fetch
30-JUL-19 08.47.42.455019000 PM +01:00 After fetch
30-JUL-19 08.47.42.775041000 PM +01:00 After fetch
30-JUL-19 08.47.43.137562000 PM +01:00 After fetch
30-JUL-19 08.47.43.688608000 PM +01:00 After fetch
30-JUL-19 08.47.43.688630000 PM +01:00 After all fetches
30-JUL-19 08.48.30.799487000 PM +01:00 After close

PL/SQL procedure successfully completed.

Elapsed: 00:00:49.80
So it performed 6 fetches in 2 seconds and then spent the remaining 47 seconds while closing the cursor, huh? Flamegraphs are quite useful in diagnosing such issues: Flame Graph Reset Zoom Search kolrgrfc2 (3 samples, 0.07%) kgghstfel_wfp (1 samples, 0.02%) sou2o (4,061 samples, 99.83%) sou2o psdghp (1 samples, 0.02%) sys_mmap_pgoff (6 samples, 0.15%) kcbgcur (1 samples, 0.02%) pfrrun_no_tool (141 samples, 3.47%) pfr.. kkxexe (4,061 samples, 99.83%) kkxexe kolaFree_rfc (3,832 samples, 94.20%) kolaFree_rfc kdl_write1 (82 samples, 2.02%) k.. rcu_process_callbacks (1 samples, 0.02%) pfrinstr_CNVMSC (138 samples, 3.39%) pfr.. kghbshrt (3 samples, 0.07%) pevm_MOVADT (1 samples, 0.02%) kkxmpbms (1 samples, 0.02%) kolaAssign_rfc (1 samples, 0.02%) __intel_new_memset (1 samples, 0.02%) kcbivbr (5 samples, 0.12%) __do_softirq (1 samples, 0.02%) kgscReleaseACursor (3,838 samples, 94.35%) kgscReleaseACursor kdltfindctl (31 samples, 0.76%) kghualloc (8 samples, 0.20%) kghfre (1 samples, 0.02%) free_hot_cold_page_list (2 samples, 0.05%) kdlclose (1 samples, 0.02%) kgghstdle_wfp (1 samples, 0.02%) irq_exit (3 samples, 0.07%) koklwrite (88 samples, 2.16%) k.. entry_SYSCALL_64_after_hwframe (1 samples, 0.02%) kkxmpexe (142 samples, 3.49%) kkx.. opifcr (14 samples, 0.34%) rpidru (1 samples, 0.02%) ksl_get_shared_latch_int (2 samples, 0.05%) pdy1F80_Generate_Code (1 samples, 0.02%) kco_issue_callback (1 samples, 0.02%) kcbchg1_main (2 samples, 0.05%) anon_vma_interval_tree_remove (1 samples, 0.02%) kolrddc (1 samples, 0.02%) kghfrempty (2 samples, 0.05%) do_async_page_fault (1 samples, 0.02%) kocedd (33 samples, 0.81%) kdlt_createtemp (1 samples, 0.02%) __intel_new_memset (2 samples, 0.05%) koltitfr (31 samples, 0.76%) _raw_spin_lock_irq (1 samples, 0.02%) __handle_mm_fault (2 samples, 0.05%) kdlgsp (13 samples, 0.32%) ktsbbscn (6 samples, 0.15%) kfk_submit_lib_io (1 samples, 0.02%) ktsbbset (4 samples, 0.10%) kghalo (4 samples, 0.10%) kcbgcur (1 samples, 0.02%) kfioRequestPriv (1 samples, 0.02%) pdw0F82_Run_Code_Gen (1 samples, 0.02%) kcoapl (53 samples, 1.30%) sltrgatime64 (1 samples, 0.02%) apic_timer_interrupt (1 samples, 0.02%) ktsbbsrch (7 samples, 0.17%) tlb_flush_mmu (2 samples, 0.05%) ktsbvopn (1 samples, 0.02%) kghgex (4 samples, 0.10%) opipls (187 samples, 4.60%) opipls kole_t2u_int (1 samples, 0.02%) kolrdrfc (2 samples, 0.05%) koccngt (1 samples, 0.02%) kghalo (4 samples, 0.10%) kolrarfc (1 samples, 0.02%) sys_mmap (6 samples, 0.15%) pfrrun (141 samples, 3.47%) pfr.. do_async_page_fault (3 samples, 0.07%) _raw_spin_lock (2 samples, 0.05%) kolaAssign_rfc (2 samples, 0.05%) __alloc_pages_nodemask (1 samples, 0.02%) qctcopn_internal (1 samples, 0.02%) kole_t2u (1 samples, 0.02%) kolaslWrite (98 samples, 2.41%) ko.. free_pages_and_swap_cache (2 samples, 0.05%) kgghstfel_wfp (1 samples, 0.02%) kghgex (2 samples, 0.05%) opifch2 (187 samples, 4.60%) opifch2 pfrinstr_RET (33 samples, 0.81%) kolttfr (31 samples, 0.76%) kolrdladd (1 samples, 0.02%) __GI___libc_poll (1 samples, 0.02%) kfioRequest (1 samples, 0.02%) kohfrw (3 samples, 0.07%) do_vfs_ioctl (1 samples, 0.02%) kdltfinddur (3 samples, 0.07%) kkxpispbn (1 samples, 0.02%) __schedule (3 samples, 0.07%) afdc_execute_ioctl (1 samples, 0.02%) kcbchg1_main (54 samples, 1.33%) main (4,061 samples, 99.83%) main schedule (2 samples, 0.05%) kgmpia_process_in_args (1 samples, 0.02%) kohfrw (4 samples, 0.10%) kole_ba2l (127 samples, 3.12%) kol.. sltrgftime64 (1 samples, 0.02%) evapls (146 samples, 3.59%) eva.. _setjmp (1 samples, 0.02%) kcbrls (1 samples, 0.02%) smp_apic_timer_interrupt (2 samples, 0.05%) kolaAssign (1 samples, 0.02%) nsmore2recv (1 samples, 0.02%) __sigsetjmp (1 samples, 0.02%) _intel_fast_memcmp (923 samples, 22.69%) _intel_fast_memcmp qesaAddDistValue (1 samples, 0.02%) kolttfr (2 samples, 0.05%) ktsbbfill (6 samples, 0.15%) phpcmp (1 samples, 0.02%) pfrinstr_MOVLOB (3 samples, 0.07%) opiodr (3,838 samples, 94.35%) opiodr kcblibr_int (5 samples, 0.12%) __vma_adjust (1 samples, 0.02%) async_page_fault (4 samples, 0.10%) do_async_page_fault (4 samples, 0.10%) handle_mm_fault (1 samples, 0.02%) kokapvpr (1 samples, 0.02%) kdlrdo (53 samples, 1.30%) do_page_fault (4 samples, 0.10%) pfsadrc (12 samples, 0.29%) kolrcomp (1 samples, 0.02%) pfrinstr_EXECC (1 samples, 0.02%) kpdbHashTable_Find (1 samples, 0.02%) prepare_exit_to_usermode (1 samples, 0.02%) skgmstack (1 samples, 0.02%) kcbtse_get_tbskey_info1_pdb (1 samples, 0.02%) psddr0 (187 samples, 4.60%) psddr0 kollfre (3 samples, 0.07%) kgmgaocn (2 samples, 0.05%) kohfrr (1 samples, 0.02%) kglpin (1 samples, 0.02%) kkxmesu (1 samples, 0.02%) skgmstack (3,838 samples, 94.35%) skgmstack kksParseCursor (1 samples, 0.02%) ktecgshx (5 samples, 0.12%) kokacau (1 samples, 0.02%) qervwRowProcedure (1 samples, 0.02%) __schedule (1 samples, 0.02%) kghfrmrg (1 samples, 0.02%) qctopls (1 samples, 0.02%) kgghstine_wfp (4 samples, 0.10%) skgmstack (187 samples, 4.60%) skgms.. kolrghte (1 samples, 0.02%) kolredur (3,837 samples, 94.32%) kolredur kollfrfn (3 samples, 0.07%) kghfnd (1 samples, 0.02%) kolaWrite (98 samples, 2.41%) ko.. __dta_afdc_dispatch_ioctl_155 (1 samples, 0.02%) rb_next (1 samples, 0.02%) qesmmIPgaFreeCb (2 samples, 0.05%) prepare_exit_to_usermode (1 samples, 0.02%) kgghstfel_wfp (1 samples, 0.02%) kghfnd_get_extent (4 samples, 0.10%) rpiswu2 (1 samples, 0.02%) kolaCreateClob (18 samples, 0.44%) kss_get_pdbid (1 samples, 0.02%) kdlclose (895 samples, 22.00%) kdlclose exit_to_usermode_loop (2 samples, 0.05%) kokegGarbageCollectOpn (1 samples, 0.02%) __handle_mm_fault (3 samples, 0.07%) ztchn (1 samples, 0.02%) kss_get_pdbid (1 samples, 0.02%) qesaAggDistincts (2 samples, 0.05%) _intel_fast_memcmp (1 samples, 0.02%) finish_task_switch (1 samples, 0.02%) kghfrmrg (1 samples, 0.02%) kxsGetRuntimeLock (1 samples, 0.02%) pdy5F00_Generate (1 samples, 0.02%) kghprmalo (5 samples, 0.12%) kohalmc (1 samples, 0.02%) kollfrfn (5 samples, 0.12%) kolaFree_rfc (2 samples, 0.05%) kcbzar (1 samples, 0.02%) kcoapl (3 samples, 0.07%) do_syscall_64 (7 samples, 0.17%) kolrfree (1 samples, 0.02%) up_read (1 samples, 0.02%) kdlf_length (2 samples, 0.05%) kcbinvbrhb (4 samples, 0.10%) psiini0_internal (1 samples, 0.02%) __GI___ioctl (1 samples, 0.02%) prepare_exit_to_usermode (1 samples, 0.02%) kpmdurend (3,838 samples, 94.35%) kpmdurend kghgex (1 samples, 0.02%) kohfrem (2 samples, 0.05%) evapls (14 samples, 0.34%) kolrdrfc (1 samples, 0.02%) kcbhfix_tail (1 samples, 0.02%) afd_ioctl (1 samples, 0.02%) pfrrun (4,059 samples, 99.78%) pfrrun kolrghte (3 samples, 0.07%) kolrde_free (1 samples, 0.02%) kcbgcur (1 samples, 0.02%) kxsGetRuntimeLock (1 samples, 0.02%) pcicmp0 (1 samples, 0.02%) kgghstfel_wfp (6 samples, 0.15%) kghfnd (2 samples, 0.05%) kcbzar (1 samples, 0.02%) __clock_gettime (1 samples, 0.02%) kkdllpoOpt (1 samples, 0.02%) lxhcsn (1 samples, 0.02%) rpidrus (187 samples, 4.60%) rpidrus kolaslCreateCtx (6 samples, 0.15%) evaopn2 (1 samples, 0.02%) __do_softirq (3 samples, 0.07%) pevm_CLOSC (3,838 samples, 94.35%) pevm_CLOSC kolaslFree (32 samples, 0.79%) _intel_fast_memcpy (27 samples, 0.66%) finish_task_switch (2 samples, 0.05%) _intel_fast_memcpy (1 samples, 0.02%) alloc_pages_vma (1 samples, 0.02%) __clock_gettime (1 samples, 0.02%) kcbo_unlink_q1 (1 samples, 0.02%) kgghstfel_wfp (1 samples, 0.02%) kolrgpdbid (1 samples, 0.02%) kollfre (6 samples, 0.15%) kcbchg1_main (8 samples, 0.20%) sorgetqb (1 samples, 0.02%) kfk_submit_sync_lib_ioq (1 samples, 0.02%) ktecgsc (1 samples, 0.02%) async_page_fault (1 samples, 0.02%) kgmexwi (145 samples, 3.56%) kgm.. kollasg (12 samples, 0.29%) kpoal8 (4,061 samples, 99.83%) kpoal8 kokltfc (31 samples, 0.76%) evareo (1 samples, 0.02%) kolredurHashMapCbk (3,836 samples, 94.30%) kolredurHashMapCbk finish_task_switch (1 samples, 0.02%) kohfrem (1 samples, 0.02%) kolredur (33 samples, 0.81%) kgiinb (1 samples, 0.02%) kolredurHashMapCbk (33 samples, 0.81%) kolrgdc (1 samples, 0.02%) kfk_io1 (1 samples, 0.02%) kxsFreeExecutionHeap (3,838 samples, 94.35%) kxsFreeExecutionHeap kghfnd (4 samples, 0.10%) irq_exit (1 samples, 0.02%) kzcksgn (3 samples, 0.07%) lxhci2h (1 samples, 0.02%) do_munmap (4 samples, 0.10%) kglpnp (1 samples, 0.02%) kolrghte (1 samples, 0.02%) kghufreetop (4 samples, 0.10%) _intel_fast_memcmp (940 samples, 23.11%) _intel_fast_memcmp qesaAggDistincts_1 (2 samples, 0.05%) kghalf (2 samples, 0.05%) _intel_fast_memcmp (11 samples, 0.27%) kgghstfel_wfp (1 samples, 0.02%) pfrinstr_CLOSC (3,838 samples, 94.35%) pfrinstr_CLOSC kdlt_remove_tlob_ctl_link (935 samples, 22.98%) kdlt_remove_tlob_ctl_link ksu_dispatch_tac (2 samples, 0.05%) kolrghte (1 samples, 0.02%) kgghstdle_wfp (1 samples, 0.02%) async_page_fault (1 samples, 0.02%) kksfbc (1 samples, 0.02%) peidxr_run (1 samples, 0.02%) kgghstfel_wfp (3 samples, 0.07%) opitca (1 samples, 0.02%) _setjmp (1 samples, 0.02%) opiodr (4,061 samples, 99.83%) opiodr __do_softirq (1 samples, 0.02%) schedule (1 samples, 0.02%) kdlopen (1 samples, 0.02%) kollasg (3 samples, 0.07%) kolaAssign (2 samples, 0.05%) kdlt_filltid (12 samples, 0.29%) ktecgsc (2 samples, 0.05%) kghufreetop (1 samples, 0.02%) kokegOpnGC_Lob (1 samples, 0.02%) safd_bio_submit (1 samples, 0.02%) afdq_batch_submit (1 samples, 0.02%) _raw_spin_unlock_irqrestore (1 samples, 0.02%) skgmrf_alloc (1 samples, 0.02%) kohalmc (1 samples, 0.02%) kolaAssign (1 samples, 0.02%) kolrgrfc (1 samples, 0.02%) kghfrh_internal (1 samples, 0.02%) _intel_fast_memcmp (2 samples, 0.05%) qergsRowP (1 samples, 0.02%) kcfrbd1 (1 samples, 0.02%) kews_pls_jvm_event_begin_i (1 samples, 0.02%) kolaCreate_rfc (18 samples, 0.44%) psdcls (3,838 samples, 94.35%) psdcls kdl_destroy (1,902 samples, 46.76%) kdl_destroy kpdbUidToId (1 samples, 0.02%) psiini0_internal (1 samples, 0.02%) __schedule (1 samples, 0.02%) koklpost1 (1 samples, 0.02%) opitsk (4,061 samples, 99.83%) opitsk sorgetqb (1 samples, 0.02%) kpdbUidToId (1 samples, 0.02%) _intel_fast_memcmp (1 samples, 0.02%) rpidrus (1 samples, 0.02%) kdlsinode (1 samples, 0.02%) qmuhshput (1 samples, 0.02%) ktsbvopn (1 samples, 0.02%) koltitfr (3,818 samples, 93.85%) koltitfr kdlclose (5 samples, 0.12%) apic_timer_interrupt (1 samples, 0.02%) kcbrls (1 samples, 0.02%) kghfre (1 samples, 0.02%) kss_get_pdbid (1 samples, 0.02%) kkxmpexe (3 samples, 0.07%) kgh_invoke_alloc_cb (1 samples, 0.02%) kksCloseCursorCbk (3,838 samples, 94.35%) kksCloseCursorCbk lxgcnvb (2 samples, 0.05%) kdlrsp (23 samples, 0.57%) kkxpispbn (2 samples, 0.05%) kghfrempty_ex (2 samples, 0.05%) kokltcc (8 samples, 0.20%) kdl_inst (1 samples, 0.02%) kgghstfel_wfp (1 samples, 0.02%) __mmap64 (7 samples, 0.17%) kghgex (2 samples, 0.05%) kdltfindctl (41 samples, 1.01%) pevm_MOVLOB (3 samples, 0.07%) kcbzgb (4 samples, 0.10%) kollalop (1 samples, 0.02%) kghalo (4 samples, 0.10%) psdnal (1 samples, 0.02%) prepare_exit_to_usermode (4 samples, 0.10%) exit_to_usermode_loop (4 samples, 0.10%) run_timer_softirq (2 samples, 0.05%) kokaccx (1 samples, 0.02%) sltrgatime64 (2 samples, 0.05%) alloc_pages_vma (1 samples, 0.02%) exit_to_usermode_loop (1 samples, 0.02%) kews_pls_jvm_event_end_i (1 samples, 0.02%) rpidrv (1 samples, 0.02%) __intel_ssse3_rep_memcpy (1 samples, 0.02%) kksLoadChild (1 samples, 0.02%) kgghstfel_wfp (1 samples, 0.02%) kohedu (3,838 samples, 94.35%) kohedu kghgex (4 samples, 0.10%) kgghstfel_wfp (3 samples, 0.07%) swapgs_restore_regs_and_return_to_usermode (3 samples, 0.07%) evaopn2 (1 samples, 0.02%) kcbrls (1 samples, 0.02%) do_page_fault (1 samples, 0.02%) koltitcr (10 samples, 0.25%) sltrgatime64 (1 samples, 0.02%) snttmoredata (1 samples, 0.02%) ksfdread (1 samples, 0.02%) kcbchg1 (8 samples, 0.20%) kksumc (3,838 samples, 94.35%) kksumc ktecgetsh (1 samples, 0.02%) pevm_CNVMSC (138 samples, 3.39%) pev.. do_anonymous_page (1 samples, 0.02%) kolrgdc (6 samples, 0.15%) kolrarfc (4 samples, 0.10%) ktecgetsh (3 samples, 0.07%) kksCancelCursor (3,838 samples, 94.35%) kksCancelCursor kolaFree_rfc (10 samples, 0.25%) kolttfr_ed (3,832 samples, 94.20%) kolttfr_ed smp_apic_timer_interrupt (1 samples, 0.02%) opiexe (4,061 samples, 99.83%) opiexe apic_timer_interrupt (1 samples, 0.02%) kcbzib (1 samples, 0.02%) kohfrr (1 samples, 0.02%) kghfnd (1 samples, 0.02%) kdlt_freetemp (2,837 samples, 69.74%) kdlt_freetemp ktecgetsh (1 samples, 0.02%) pfrust (33 samples, 0.81%) do_syscall_64 (1 samples, 0.02%) schedule (3 samples, 0.07%) kgmexec (10 samples, 0.25%) kcbz_fr_buf (1 samples, 0.02%) kolaGetHeap (2 samples, 0.05%) ktbchgro (8 samples, 0.20%) kkdllpo (1 samples, 0.02%) prepare_exit_to_usermode (3 samples, 0.07%) __do_softirq (1 samples, 0.02%) kgghstmap (33 samples, 0.81%) kocobld (1 samples, 0.02%) kohalw (1 samples, 0.02%) ktecgshx (1 samples, 0.02%) kodclod (1 samples, 0.02%) opicca (3,838 samples, 94.35%) opicca kolaAssign_rfc (1 samples, 0.02%) __do_page_fault (1 samples, 0.02%) qesaEvalDistAggOpns (1 samples, 0.02%) ktbchgro (54 samples, 1.33%) kgghstmap (3,837 samples, 94.32%) kgghstmap pfrinstr_MOVADT (1 samples, 0.02%) kolaslWriteCreateTempLob (10 samples, 0.25%) do_mmap (6 samples, 0.15%) kdlrsp (2 samples, 0.05%) kohfrem (1 samples, 0.02%) prepare_exit_to_usermode (3 samples, 0.07%) tlb_finish_mmu (2 samples, 0.05%) evaopn2 (146 samples, 3.59%) eva.. ktsbgsp1 (13 samples, 0.32%) ktcsna (1 samples, 0.02%) kohalc (1 samples, 0.02%) apic_timer_interrupt (2 samples, 0.05%) rpiswu2 (1 samples, 0.02%) kdlfill (13 samples, 0.32%) ktsbvcls (1 samples, 0.02%) kdlt_freetemp (18 samples, 0.44%) kdltfindctl (39 samples, 0.96%) kolrgrfc (1 samples, 0.02%) kgmgaicn (1 samples, 0.02%) kolaFree (3,832 samples, 94.20%) kolaFree _intel_fast_memcmp (5 samples, 0.12%) kghuwrlength (1 samples, 0.02%) kpdbUidToIdHash (1 samples, 0.02%) kohfrw (1 samples, 0.02%) ztchmd5m (2 samples, 0.05%) kgmtconv (1 samples, 0.02%) kohalc (1 samples, 0.02%) _intel_fast_memcmp (2 samples, 0.05%) __clock_gettime (2 samples, 0.05%) pfrrun (1 samples, 0.02%) rpidrus (3,838 samples, 94.35%) rpidrus kghfrf (2 samples, 0.05%) release_pages (2 samples, 0.05%) pfrrun (3 samples, 0.07%) arch_local_irq_disable (2 samples, 0.05%) koklSurrCheck (2 samples, 0.05%) async_page_fault (3 samples, 0.07%) __do_softirq (2 samples, 0.05%) rpidrv (187 samples, 4.60%) rpidrv peidxr_run (141 samples, 3.47%) pei.. finish_task_switch (1 samples, 0.02%) ksfdafIO (1 samples, 0.02%) kolrgrfc (1 samples, 0.02%) kocgpn (1 samples, 0.02%) kgh_invoke_alloc_cb (1 samples, 0.02%) kcbz_mk_fr (3 samples, 0.07%) kcbz_fp_shr (1 samples, 0.02%) all (4,068 samples, 100%) kkspsc0 (1 samples, 0.02%) ztchmd5n (2 samples, 0.05%) sltrgatime64 (1 samples, 0.02%) do_page_fault (1 samples, 0.02%) kcmlf_read (1 samples, 0.02%) opiosq0 (1 samples, 0.02%) pfrinstr_BFTCHC (187 samples, 4.60%) pfrin.. psdnal (187 samples, 4.60%) psdnal _intel_fast_memcmp (1 samples, 0.02%) rpidrv (3,838 samples, 94.35%) rpidrv kolrcomp (1 samples, 0.02%) ktucloGetGlobalMinScn (1 samples, 0.02%) kolrghte (1 samples, 0.02%) kghalo (1 samples, 0.02%) peiinspbn (1 samples, 0.02%) vm_mmap_pgoff (6 samples, 0.15%) psddr0 (3,838 samples, 94.35%) psddr0 kolrghte (1 samples, 0.02%) opidrv (4,061 samples, 99.83%) opidrv opiclo (3,838 samples, 94.35%) opiclo handle_mm_fault (2 samples, 0.05%) ktsbvini (3 samples, 0.07%) kolaslFree (3,824 samples, 94.00%) kolaslFree kokltfc (3,810 samples, 93.66%) kokltfc ktsbdba_vbn (3 samples, 0.07%) tlb_flush_mmu_free (2 samples, 0.05%) ttcpip (4,061 samples, 99.83%) ttcpip ktbchgro (4 samples, 0.10%) kohfrr (4 samples, 0.10%) kghgex (1 samples, 0.02%) pfrinstr_ENTERZ (1 samples, 0.02%) peiinbd (1 samples, 0.02%) kokdlod (1 samples, 0.02%) kglsim_upd_newhp (1 samples, 0.02%) pmuocpy (12 samples, 0.29%) note_gp_changes (1 samples, 0.02%) koklc_write (101 samples, 2.48%) ko.. qervwFetch (3 samples, 0.07%) ksmrf_init_alloc (1 samples, 0.02%) smp_apic_timer_interrupt (3 samples, 0.07%) smp_apic_timer_interrupt (1 samples, 0.02%) kdlird (1 samples, 0.02%) _intel_fast_memcmp (2 samples, 0.05%) kolttfr_ed (33 samples, 0.81%) evastr (1 samples, 0.02%) kcbgcur (1 samples, 0.02%) smp_apic_timer_interrupt (1 samples, 0.02%) kcblibr_int (1 samples, 0.02%) kgghstdle_wfp (2 samples, 0.05%) kdlgdata (1 samples, 0.02%) kolrdrfc (1 samples, 0.02%) __intel_new_memset (1 samples, 0.02%) kghbshrt (2 samples, 0.05%) ztchmd5f (2 samples, 0.05%) kgghstfel_wfp (1 samples, 0.02%) kglpin (1 samples, 0.02%) kprcdt (2 samples, 0.05%) apic_timer_interrupt (3 samples, 0.07%) kokegUnpinLob (2 samples, 0.05%) handle_mm_fault (3 samples, 0.07%) swapgs_restore_regs_and_return_to_usermode (1 samples, 0.02%) unmap_single_vma (1 samples, 0.02%) kohfrem (3 samples, 0.07%) kcbinvbrhb (1 samples, 0.02%) kghfrf (1 samples, 0.02%) arch_local_irq_enable (1 samples, 0.02%) kolaFree (33 samples, 0.81%) irq_exit (1 samples, 0.02%) kcbgcur (1 samples, 0.02%) kkxdexe (142 samples, 3.49%) kkx.. kdlwfb (77 samples, 1.89%) k.. kdltfindctl (1 samples, 0.02%) kgghstfel_wfp (1 samples, 0.02%) arch_tlb_finish_mmu (2 samples, 0.05%) unmap_region (3 samples, 0.07%) do_async_page_fault (1 samples, 0.02%) kollfre (1 samples, 0.02%) kolrgrfc (1 samples, 0.02%) kole_src2dst (2 samples, 0.05%) kolrde_alloc (1 samples, 0.02%) kolrde_free (1 samples, 0.02%) kocpin (1 samples, 0.02%) exit_to_usermode_loop (1 samples, 0.02%) kglobpn (1 samples, 0.02%) kghualloc (1 samples, 0.02%) kgmtobim (1 samples, 0.02%) kolradc (1 samples, 0.02%) __dta_afdc_io_153 (1 samples, 0.02%) pevm_ENTER (1 samples, 0.02%) qxuag_val2workarea (1 samples, 0.02%) clear_page_erms (1 samples, 0.02%) sltrgftime64 (1 samples, 0.02%) opiodr (4,061 samples, 99.83%) opiodr kdlt_remove_tlob_ctl_link (7 samples, 0.17%) kdltfindctl (54 samples, 1.33%) kghalf (1 samples, 0.02%) ktecgshx (3 samples, 0.07%) ktecgshx (2 samples, 0.05%) kolaslCreateClob (26 samples, 0.64%) _intel_fast_memcmp (1 samples, 0.02%) kglobpn (1 samples, 0.02%) free_hot_cold_page (2 samples, 0.05%) ktsbvini (5 samples, 0.12%) swapgs_restore_regs_and_return_to_usermode (1 samples, 0.02%) kdlopen (3 samples, 0.07%) pfrrun_no_tool (4,059 samples, 99.78%) pfrrun_no_tool kolradc (1 samples, 0.02%) kxsdmc (3,838 samples, 94.35%) kxsdmc qximeop_fbk (147 samples, 3.61%) qxim.. unmap_page_range (1 samples, 0.02%) peicnt (4,059 samples, 99.78%) peicnt kghufree (1 samples, 0.02%) kohfrr (1 samples, 0.02%) plsql_run (141 samples, 3.47%) pls.. kokltfr_pdbcbk (30 samples, 0.74%) kolttfr (3,819 samples, 93.88%) kolttfr blk_mq_flush_plug_list (1 samples, 0.02%) kdlopen (981 samples, 24.12%) kdlopen kcbtse_is_ts_enc_pdb (1 samples, 0.02%) kolrddc (4 samples, 0.10%) opiodr (187 samples, 4.60%) opiodr kdlt_add_tlob_ctl_link (1 samples, 0.02%) ksmarfg (1 samples, 0.02%) kokavpr (1 samples, 0.02%) ksfdafRequest (1 samples, 0.02%) kdlrsp_init (2 samples, 0.05%) kghfrempty_subheaps_all (2 samples, 0.05%) kghalp (6 samples, 0.15%) kgmexec (146 samples, 3.59%) kgm.. blkdev_ioctl (1 samples, 0.02%) kdltfinddur (1 samples, 0.02%) kolradc (1 samples, 0.02%) kghfrf (1 samples, 0.02%) exit_to_usermode_loop (1 samples, 0.02%) kcbchg1 (3 samples, 0.07%) kcbz_mk_fr (1 samples, 0.02%) kglpim (1 samples, 0.02%) ktecgsc (2 samples, 0.05%) kfioSubmitIO (1 samples, 0.02%) koklc_write (88 samples, 2.16%) k.. ktsbdba_vbn (1 samples, 0.02%) kdlu_timers_on (1 samples, 0.02%) kco_issue_callback (53 samples, 1.30%) entry_SYSCALL_64_after_hwframe (7 samples, 0.17%) kcbchg1 (54 samples, 1.33%) __libc_start_main (4,061 samples, 99.83%) __libc_start_main kgmpoa_process_out_args (2 samples, 0.05%) peidxexe (1 samples, 0.02%) evaopn2 (14 samples, 0.34%) rpidru (3,838 samples, 94.35%) rpidru kohalw (10 samples, 0.25%) kolaFree_rfc (33 samples, 0.81%) qximeop_fbk (14 samples, 0.34%) qxuageag (166 samples, 4.08%) qxua.. kocgpn2 (1 samples, 0.02%) ksmarfg (1 samples, 0.02%) kole_templob_init (26 samples, 0.64%) __do_page_fault (1 samples, 0.02%) kcbivbr (1 samples, 0.02%) kotgHashCode (1 samples, 0.02%) tred2i (1 samples, 0.02%) schedule (1 samples, 0.02%) kkspbd0 (1 samples, 0.02%) kdltfinddur (2 samples, 0.05%) opimai_real (4,061 samples, 99.83%) opimai_real unmap_vmas (1 samples, 0.02%) ksl_get_shared_latch_int (3 samples, 0.07%) ktsbfsp (1 samples, 0.02%) ktecgetsh (5 samples, 0.12%) get_page_from_freelist (1 samples, 0.02%) kgmexwi (6 samples, 0.15%) plsql_run (4,059 samples, 99.78%) plsql_run __intel_new_memset (1 samples, 0.02%) pmuocpy2_copy_recur (12 samples, 0.29%) _raw_spin_lock (1 samples, 0.02%) _intel_fast_memcmp (5 samples, 0.12%) swapgs_restore_regs_and_return_to_usermode (4 samples, 0.10%) pfrdef1_get_tdo (1 samples, 0.02%) blk_flush_plug_list (1 samples, 0.02%) kglobld (1 samples, 0.02%) kcbgcur (1 samples, 0.02%) kcbzar (1 samples, 0.02%) kcbhfix_tail (1 samples, 0.02%) alloc_pages_vma (1 samples, 0.02%) run_timer_softirq (1 samples, 0.02%) _intel_fast_memcmp (860 samples, 21.14%) _intel_fast_memcmp lxdgetobj (1 samples, 0.02%) free_pgtables (1 samples, 0.02%) kole_getFillChar (3 samples, 0.07%) lxgcnv (2 samples, 0.05%) kdlt_filltid (967 samples, 23.77%) kdlt_filltid kgghash (1 samples, 0.02%) zap_pte_range (1 samples, 0.02%) irq_exit (1 samples, 0.02%) pevm_EXECC (1 samples, 0.02%) pfrrun_no_tool (3 samples, 0.07%) nioqts (1 samples, 0.02%) irq_exit (2 samples, 0.05%) _intel_fast_memcmp (6 samples, 0.15%) __handle_mm_fault (1 samples, 0.02%) pdw0F01_Code_Gen (1 samples, 0.02%) pfrinstr_INHFA1 (1 samples, 0.02%) kews_pls_jvm_event_begin_i (2 samples, 0.05%) ktsbfsp (18 samples, 0.44%) kohdee (33 samples, 0.81%) plcurClose (3,838 samples, 94.35%) plcurClose kolaAssign_rfc (1 samples, 0.02%) oracle_19722_sf (4,068 samples, 100.00%) oracle_19722_sf kgghstfel_wfp (1 samples, 0.02%) kcoapl_validate (1 samples, 0.02%) ktsbiredo (1 samples, 0.02%) kohfrr (3 samples, 0.07%) kcbzgs (1 samples, 0.02%) block_ioctl (1 samples, 0.02%) kgghash (1 samples, 0.02%) kgghstfel_wfp (1 samples, 0.02%) ztchf (2 samples, 0.05%) ktecgshx (1 samples, 0.02%) do_anonymous_page (3 samples, 0.07%) kdltfindctl (1 samples, 0.02%) kghssgai (6 samples, 0.15%) qergsFetch (187 samples, 4.60%) qergs.. kole_t2u (2 samples, 0.05%) expeal (1 samples, 0.02%) plsql_run (1 samples, 0.02%) kokegCopyGarbageFromOpn (2 samples, 0.05%) _intel_fast_memcmp (1 samples, 0.02%) opiodr (1 samples, 0.02%) kolrghte (1 samples, 0.02%) kdl_destroy (11 samples, 0.27%) pdy8M23_Fill_TDO_Hash (1 samples, 0.02%) do_page_fault (3 samples, 0.07%) rpidru (187 samples, 4.60%) rpidru kkxdexe (3 samples, 0.07%) kghgex (1 samples, 0.02%) ktcsna (2 samples, 0.05%) kfk_transitIO (1 samples, 0.02%) __alloc_pages_nodemask (1 samples, 0.02%) swapgs_restore_regs_and_return_to_usermode (1 samples, 0.02%) psddr0 (1 samples, 0.02%) kolrghte (1 samples, 0.02%) pfrrun_no_tool (1 samples, 0.02%) kprccu (2 samples, 0.05%) kpdbUidToId (1 samples, 0.02%) pevm_RET (33 samples, 0.81%) kghalf (2 samples, 0.05%) opiino (4,061 samples, 99.83%) opiino kohdee (3,838 samples, 94.35%) kohdee kghalo (2 samples, 0.05%) kdl_length (2 samples, 0.05%) _intel_fast_memcmp (879 samples, 21.61%) _intel_fast_memcmp qctcpqb (1 samples, 0.02%) swapgs_restore_regs_and_return_to_usermode (3 samples, 0.07%) kpdbHashTable_Find (1 samples, 0.02%) kcbnew (10 samples, 0.25%) kghalo (1 samples, 0.02%) vma_merge (1 samples, 0.02%) kollas2 (2 samples, 0.05%) kohfrem (1 samples, 0.02%) kgghstdle_wfp (1 samples, 0.02%) kokegPinLob (1 samples, 0.02%) pfrcvfc_format_conversion (138 samples, 3.39%) pfr.. kgghash (1 samples, 0.02%) qercbiFetch (3 samples, 0.07%) ksmarfg (1 samples, 0.02%) kkxswcm (1 samples, 0.02%) sys_ioctl (1 samples, 0.02%) blk_finish_plug (1 samples, 0.02%) kolrddc (2 samples, 0.05%) rpiswu2 (3,838 samples, 94.35%) rpiswu2 kokasuc (1 samples, 0.02%) exit_to_usermode_loop (1 samples, 0.02%) __do_page_fault (3 samples, 0.07%) lxhasc (1 samples, 0.02%) kkxcrc (1 samples, 0.02%) qxuag_initself (15 samples, 0.37%) kollalop (10 samples, 0.25%) kgmgaicn (1 samples, 0.02%) kghufree (1 samples, 0.02%) opipls (1 samples, 0.02%) exit_to_usermode_loop (1 samples, 0.02%) ktecgetsh (2 samples, 0.05%) koklwrite (99 samples, 2.43%) ko.. _intel_fast_memcpy (1 samples, 0.02%) schedule (1 samples, 0.02%) kolrghte (1 samples, 0.02%) koklWrite (99 samples, 2.43%) ko.. __do_page_fault (4 samples, 0.10%) opifch (187 samples, 4.60%) opifch mmap_region (6 samples, 0.15%) kdltfindctl (1 samples, 0.02%) qctcopn_internal (1 samples, 0.02%) swapgs_restore_regs_and_return_to_usermode (1 samples, 0.02%) qesaEvaAndPutDistAggOpns (1 samples, 0.02%) schedule (1 samples, 0.02%) kokltfr_pdbcbk (3,810 samples, 93.66%) kokltfr_pdbcbk finish_task_switch (3 samples, 0.07%) xtypls (1 samples, 0.02%) kgghstfel_wfp (1 samples, 0.02%) __schedule (2 samples, 0.05%) rpiswu2 (187 samples, 4.60%) rpiswu2 kcbo_unlink_q1 (3 samples, 0.07%) pdy8M06_Create_TDO_Lite (1 samples, 0.02%) kglpim (1 samples, 0.02%) pdy4M17_Create (1 samples, 0.02%) kokageti (1 samples, 0.02%) kdlwdb (64 samples, 1.57%) do_anonymous_page (1 samples, 0.02%) kollulin (1 samples, 0.02%) kohalmc (10 samples, 0.25%) __vdso_clock_gettime (1 samples, 0.02%) kolttfr (10 samples, 0.25%) kolrEnabled (1 samples, 0.02%) __schedule (1 samples, 0.02%) kole_t2u_int (2 samples, 0.05%) sorlookqb (1 samples, 0.02%) __vdso_clock_gettime (1 samples, 0.02%) schedule (1 samples, 0.02%) kpdbHashTable_Find (1 samples, 0.02%) kolrEnabled (1 samples, 0.02%) kolrghte (1 samples, 0.02%) qctcopn (1 samples, 0.02%) kksfbc (1 samples, 0.02%) kolaFree (10 samples, 0.25%) kolradlst (6 samples, 0.15%) __schedule (1 samples, 0.02%) kolrarfc (10 samples, 0.25%) kkxcms (1 samples, 0.02%) kgmpia_process_in_args (1 samples, 0.02%) kokltcr (8 samples, 0.20%) kxsFreeWorkArea (3,838 samples, 94.35%) kxsFreeWorkArea __intel_new_memset (1 samples, 0.02%) kollfrfn (1 samples, 0.02%) finish_task_switch (1 samples, 0.02%) pcicms (1 samples, 0.02%) __clock_gettime (1 samples, 0.02%) kcoapl (1 samples, 0.02%) pevm_BFTCHC (187 samples, 4.60%) pevm_.. kghufree (1 samples, 0.02%) peidxexe (141 samples, 3.47%) pei.. kolaFree (2 samples, 0.05%) koklWrite (88 samples, 2.16%) k.. kfk_submit_io (1 samples, 0.02%) kolttcr (10 samples, 0.25%) kohedu (33 samples, 0.81%) kolrihtab (1 samples, 0.02%) lxhasc (1 samples, 0.02%) kghfnd (2 samples, 0.05%) kolrddc (3 samples, 0.07%) qxuagtag (1 samples, 0.02%) __intel_ssse3_rep_memcpy (13 samples, 0.32%) rcu_process_callbacks (1 samples, 0.02%) pdy1F01_Driver (1 samples, 0.02%) blk_mq_sched_insert_requests (1 samples, 0.02%) kdlf_write (83 samples, 2.04%) k.. kohalc (10 samples, 0.25%) prepare_exit_to_usermode (1 samples, 0.02%) ksfd_io (1 samples, 0.02%) qctcopn (1 samples, 0.02%) qximcom (1 samples, 0.02%) kghalf (9 samples, 0.22%) pdy4M63_Layout_Record (1 samples, 0.02%) kgghstfel_wfp (1 samples, 0.02%) kksLoadChild (1 samples, 0.02%) kdlt_filltid (1 samples, 0.02%) ksmust (1 samples, 0.02%) kkxpinbd (2 samples, 0.05%) kghufrheap (1 samples, 0.02%) kghfre (1 samples, 0.02%) kollasg (2 samples, 0.05%) kdltfinddur (1 samples, 0.02%) kgmatim (2 samples, 0.05%) kcbzfb (2 samples, 0.05%) kghalf (4 samples, 0.10%) kcbhfho (2 samples, 0.05%) kokacmc (1 samples, 0.02%) kgghash (4 samples, 0.10%) get_page_from_freelist (1 samples, 0.02%) ssthrdmain (4,061 samples, 99.83%) ssthrdmain kglsim_pin_simhp (1 samples, 0.02%) kcbgcur (2 samples, 0.05%) kgghstfel_wfp (1 samples, 0.02%) koklNeedSurrChk (2 samples, 0.05%) __alloc_pages_nodemask (1 samples, 0.02%) All of those kksumc, kxsFreeExecutionHeap, kxsFreeWorkArea, kxsdmc and others are memory free/releasing cursor routines. As you might guess, the nature of this issue is related to that user-defined type from the query. Here's the code that I used for that demo:
CREATE OR REPLACE TYPE user_agg_t as object(
  v_clob       clob,

  static function ODCIAggregateInitialize(sctx IN OUT NOCOPY user_agg_t)
    return number,

  member function ODCIAggregateIterate(self IN OUT NOCOPY user_agg_t,
                                       value IN varchar2)
    return number,

  member function ODCIAggregateTerminate(self IN OUT NOCOPY user_agg_t,
                                         returnValue OUT NOCOPY clob,
                                         flags IN number)
    return number,

  member function ODCIAggregateMerge(self IN OUT NOCOPY user_agg_t,
                                     ctx2 IN OUT NOCOPY user_agg_t)
    return number
);
/

CREATE OR REPLACE TYPE BODY user_agg_t
is

  static function ODCIAggregateInitialize(sctx IN OUT NOCOPY user_agg_t)
    return number is
  begin
    sctx := user_agg_t(null);
    return ODCIConst.Success;
  end;

  member function ODCIAggregateIterate(self   IN OUT NOCOPY user_agg_t,
                                       value  IN varchar2)
    return number
  is
  begin
    return ODCIConst.Success;
  end;

  member function ODCIAggregateTerminate(self IN OUT NOCOPY user_agg_t,
                                         returnValue OUT NOCOPY clob,
                                         flags IN number)
    return number is
  begin
    self.v_clob := 'finished';
    returnValue := self.v_clob;
    return ODCIConst.Success;
  end;

  member function ODCIAggregateMerge(self IN OUT NOCOPY user_agg_t,
                                     ctx2 IN OUT NOCOPY user_agg_t)
    return number is
  begin
    return ODCIConst.Success;
  end;
end;
/

CREATE OR REPLACE FUNCTION user_agg_function (input varchar2) RETURN clob PARALLEL_ENABLE AGGREGATE USING user_agg_t;
/
There is an abstract LOB created in the highlighted line. While the anonymous block is running, it creates a lot of those abstract LOBs, upto 30,000 which is the number of rows that I fetch from that cursor (I am checking it through V$TEMPORARY_LOBS). When I call the close cursor line, the server process decides that it is time to free up all of those resources back and that is what is taking so much time; here is the relevant output:
SQL> select to_char(sysdate, 'hh24:mi:ss') current_time, l.* from v$temporary_lobs l;

-- The session is executing
CURRENT_        SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID
-------- ---------- ---------- ------------ ------------- ----------
21:32:23         47          0            0             0          3
21:32:23         58      23921            0         23922          3

SQL> /

-- It created upto 30K abstract LOBs
CURRENT_        SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID
-------- ---------- ---------- ------------ ------------- ----------
21:32:24         47          0            0             0          3
21:32:24         58      29737            0         29738          3

SQL> /

-- Now it is steadily deallocating them
CURRENT_        SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID
-------- ---------- ---------- ------------ ------------- ----------
21:32:25         47          0            0             0          3
21:32:25         58      29507            0         29508          3

SQL> /

CURRENT_        SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID
-------- ---------- ---------- ------------ ------------- ----------
21:32:26         47          0            0             0          3
21:32:26         58      29269            0         29269          3

SQL> /

CURRENT_        SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID
-------- ---------- ---------- ------------ ------------- ----------
21:32:28         47          0            0             0          3
21:32:28         58      28626            0         28626          3

SQL> /

CURRENT_        SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID
-------- ---------- ---------- ------------ ------------- ----------
21:32:30         47          0            0             0          3
21:32:30         58      28017            0         28018          3

SQL> /

CURRENT_        SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID
-------- ---------- ---------- ------------ ------------- ----------
21:32:31         47          0            0             0          3
21:32:31         58      27551            0         27552          3

SQL> /

CURRENT_        SID CACHE_LOBS NOCACHE_LOBS ABSTRACT_LOBS     CON_ID
-------- ---------- ---------- ------------ ------------- ----------
21:32:33         47          0            0             0          3
21:32:33         58      27093            0         27093          3

Why did I put 30,001 in that cursor? If I had not done this, Oracle would have performed that deallocation stage at the time of the last fetch. It closely emulates what my APEX application is doing by using row-limiting clause instead. Initially, I was not able to reproduce my test case in the vanilla 12.2.0.1.190416 database that I used for that demo. Here's how that anonymous block was executing there:
SQL> declare
  2    cursor test_csr is
  3      select t1.*, user_agg_function(to_char(l)) c1
  4        from (select level l from dual connect by level<=30001) t1
  5       group by t1.l;
  6    type test_tbl_type is table of test_csr%rowtype;
  7    v_test_tbl test_tbl_type;
  8  begin
  9    open test_csr;
 10
 11    dbms_output.put_line(systimestamp||' After open');
 12
 13    for i in 1..6
 14    loop
 15      fetch test_csr bulk collect into v_test_tbl limit 5000;
 16      dbms_output.put_line(systimestamp||' After fetch');
 17    end loop;
 18
 19    dbms_output.put_line(systimestamp||' After all fetches');
 20
 21    close test_csr;
 22    dbms_output.put_line(systimestamp||' After close');
 23  end;
 24  /
30-JUL-19 08.38.01.599807000 PM +01:00 After open
30-JUL-19 08.38.01.709834000 PM +01:00 After fetch
30-JUL-19 08.38.01.831769000 PM +01:00 After fetch
30-JUL-19 08.38.01.974946000 PM +01:00 After fetch
30-JUL-19 08.38.02.137070000 PM +01:00 After fetch
30-JUL-19 08.38.02.321525000 PM +01:00 After fetch
30-JUL-19 08.38.02.540002000 PM +01:00 After fetch
30-JUL-19 08.38.02.540024000 PM +01:00 After all fetches
30-JUL-19 08.38.02.604546000 PM +01:00 After close

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.02
SQL>
SQL> select p.pga_used_mem, p.pga_alloc_mem
  2    from v$session s, v$process p
  3   where s.sid = sys_context('userenv', 'sid')
  4     and p.addr = s.paddr;

PGA_USED_MEM PGA_ALLOC_MEM
------------ -------------
   446703652     450742580
It's blazingly fast, isn't it? However, notice that PGA is not freed back and my session consumes 450MB! While wading through OS/Oracle traces, I finally came across the trace[LOB_REFCOUNT] event that gave some clues:
kolradc :  0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x63  : 2 (24)
PGA usage percent: 4829 percent, isMaxHeap reached?: 1, Mem check freq: 25 
kolrarfc:  0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x64  : 1
kolrarfc: kolaCreateClob()+123<-kolaslCreateClob()+144<-kole_templob_init()+428<-kole_ba2l()+170<-pfrcvfc_format_conversion()+2369<-pevm_CNVMSC()+49<-pfrinstr_CNVMSC()+52<-pfrrun_no_tool()+60<-pfrrun()+917<-plsql_run()+756<-peidxr_run()+265<-peidxexe()+76<-kkxdexe()+625<-kkxmpexe()+288<-kgmexwi()+592
kolrarfc: number of lobs = 100
kolrDmpTables_uts: Called from :  at every 100th lob added 
kolrDmpDurs_uts: Called from :  at every 100th lob added 
-----  kolr Durations Dump Begin ----
-------------------------------------
DUR     LOB COUNT     TOTAL RFC
-------------------------------------
 24            99           100
 28             1             1
 29            99            99
------  kolr Durations Dump End -----
-----------------  kolr Dur Hash Table Dump Begin:  24 --------------
 Lob Locator                                          count  (dur in loc)
------------------------------------------------------------------------
 0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x5f        1    (29)
 0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x0b        1    (29)
 0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x06        1    (29)
 0xe7 0x69 0xb7 0x01 0x00 0x00 0x00 0x5a        1    (29)
That was from a database that had a plenty of PGA available that was far more below PGA_AGGREGATE_TARGET (PAT). Yet, that database was suffering from that issue. Then I was able to reproduce that slow close cursor step by occupying a lot of PGA first. I wrote a simple package to help me in this task:
create or replace package fill_memory
is
  type t is table of varchar2(32767);
  v t := t();
  procedure extend(i_size pls_integer := 10000);
end;
/
create or replace package body fill_memory
is
  procedure extend(i_size pls_integer := 10000)
  is
    v_current_size pls_integer;
  begin
    v_current_size := v.count();
    v.extend(i_size);
    for i in v_current_size + 1..v_current_size + i_size
    loop
      v(i) := lpad('x', 32767, 'x');
    end loop;
  end extend;
end;
/
I found that in the demo database with PAT set to 512M, it is enough to call fill_memory.extend(25000) to make all subsequent executions of the anonymous block in question slow (bigger values resulted in the acknowledge over PGA limit event, which I tried to avoid for this demo as I did not observe them in my database initially and those would be a clear indication of the problem area):
SQL> exec fill_memory.extend(25000)

PL/SQL procedure successfully completed.
Although I was able to reproduce that issue in a clean database, I have been able to do that only if I consumed a lot of PGA first. Still, I observe that issue now in one of my development database where there is a bunch of free PGA and I have raised an SR with Oracle support to further investigate it (I believe I have already done my homework, so that it shouldb't be so hard for them to tackle this problem now). Another remarkable thing that I discovered while I was working on this issue, is that 19c consumes far more memory on the same test case and performance does not suffer (it's 450M in 12.2 versus 1450M in 19c - I would probably raise another SR when I start using 19c for that application):
SQL> declare
  2    cursor test_csr is
  3      select t1.*, user_agg_function(to_char(l)) c1
  4        from (select level l from dual connect by level<=30001) t1
  5       group by t1.l;
  6    type test_tbl_type is table of test_csr%rowtype;
  7    v_test_tbl test_tbl_type;
  8  begin
  9    open test_csr;
 10
 11    dbms_output.put_line(systimestamp||' After open');
 12
 13    for i in 1..6
 14    loop
 15      fetch test_csr bulk collect into v_test_tbl limit 5000;
 16      dbms_output.put_line(systimestamp||' After fetch');
 17    end loop;
 18
 19    dbms_output.put_line(systimestamp||' After all fetches');
 20
 21    close test_csr;
 22    dbms_output.put_line(systimestamp||' After close');
 23  end;
 24  /
30-JUL-19 09.51.59.629103000 PM +01:00 After open
30-JUL-19 09.51.59.809768000 PM +01:00 After fetch
30-JUL-19 09.51.59.916143000 PM +01:00 After fetch
30-JUL-19 09.52.00.016790000 PM +01:00 After fetch
30-JUL-19 09.52.00.116655000 PM +01:00 After fetch
30-JUL-19 09.52.00.217287000 PM +01:00 After fetch
30-JUL-19 09.52.00.317115000 PM +01:00 After fetch
30-JUL-19 09.52.00.317137000 PM +01:00 After all fetches
30-JUL-19 09.52.00.324701000 PM +01:00 After close

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.70
There is difference how those memory allocations are made in 12.2 and 19c:
[oracle@db-122 trace]$ grep 'PGA memory operation' orcl_ora_3519.trc | grep -v p1=0 | awk '{print $8}' | sort | uniq -c
      4 p1=131072
   4910 p1=65536

[oracle@db-19-siha trace]$ grep 'PGA memory operation' orcl_ora_15055.trc | grep -v 'p1=0' | awk '{print $8}' | sort -t= -n -k2| uniq -c
    165 p1=65536
    108 p1=131072
    100 p1=262144
    100 p1=524288
    100 p1=1048576
    100 p1=2097152
     52 p1=4194304
     50 p1=8388608
     14 p1=16777216
12.2 uses 64K allocations whereas 19c seems to be allocating 150 64K allocations, 100/128K, 100/256K, 100/512K, 100/1M, 100, 2M, 50/4M, 50/8M, X/16M. There is an obvious pattern in those allocations in 19c - they are just doubling in size. Still, even with those allocations I expected to see some slowdowns in 19c, however, I have not found any. I guess that some memory management code has been redone in 19c because both 12.2 and 19c were provisioned in my home lab from the same Virtual Box machine image.

Update Apr 2020


A service request which I raised for that issue finally has led to an officially published bug:
Bug 30213404 : CLOSE OF CURSORS IS VERY SLOW WITH LARGE PGA ALLOCATIONS.
I got it in this morning's My Oracle Support Hot Topics E-Mail.

Комментариев нет:

Отправка комментария