Thursday, July 20, 2023

Simulate cursor:pin S enqueue and test the fix for it (MOS Note: 2369968.1)

Dear Readers,

I was stuck in a situation where in during the start of the business one of the oracle db running in 12.2 was hammered heavily and is saturating the CPU.  While I was diagnosing the issue, I found most of the sessions were stuck in cursor: pin S event.

I understood that it was caused by a connection pool repeatedly calling the same sql statement (with binds) recursively over 10M+ times in just over 6 mins time.

The load just grows for the first 3 mins and then settles down. So it is a bell curve. The issue repeats every working day.

After reviewing the oracle document about the cause for cursor: pin S. I was searching for a solution to see if there is a way we can mitigate this issue. I always know with latches, I will move the problem from one place to another by implementing a so called fix. But still wanted to give it a try.

Credit: I stumbled upon this url while searching for the solution and the same blog highlighted the MOS note also. Thanks to the blogger and blog.




 I didnt spent much time in test bed setup.

My goal in this blog: Reuse the codes used in the url with an objective of measuring the impact of the fix recommended in MOS note 2369968.1 on query run duration and cpu load reduction.

Final outcome: 

No improvement in this 4 cpu lab. I noticed the hot spot get offloaded from cursor: pin S to the next one which is library cache: mutex or mutex bucket etc...

Good thing in this test we observed is, with 1 cpu our test lasted for 7mins vs the 4 cpu it lasted for 3 to 4mins.

So the cpu addition is the real game changer on this situation.

Now let us get into the test:

create a test user:
SQL> create user cursortest identified by cursortest;

User created.

SQL> grant connect,resource to cursortest;

Grant succeeded.

SQL> alter user cursortest quota unlimited on users;

User altered.

SQL> grant create table to cursortest;

Grant succeeded.

SQL> grant SELECT_CATALOG_ROLE to cursortest;

Grant succeeded.

SQL> grant create procedure to cursortest;

Grant succeeded.

SQL>


create test table:
create table code_table (code_name char(1), low_value number, high_value number);

declare
  letters char(26) := 'ABCDEFGHIJKLMNOPQRSTUVWXYZ';
  v_num number := 1;
begin
  for i in 1..26 LOOP
    insert into code_table values (substr(letters,i,1), i*v_num, i*(v_num+1000));
    v_num := v_num + 1001;
  end loop;
  commit;
end; 
/

create or replace function fx_num (v_name varchar) return number is
  v_low number;
  v_high number;
begin
  select low_value, high_value into v_low, v_high from code_table where code_name=v_name;
  return(DBMS_RANDOM.value(low => v_low, high => v_high));
end;
/

Shell caller:

#launch_test.sh
#!/bin/bash
export ORACLE_SID=DBCASLNT
export ORAENV_ASK=NO;
. oraenv >/dev/null 2>&1;
for i in {1..50}
do
nohup sqlplus -s cursortest/cursortest @launch_sql1.sql >> launch_sql1.log 2>&1 &
nohup sqlplus -s cursortest/cursortest @launch_sql2.sql >> launch_sql2.log 2>&1 &
nohup sqlplus -s cursortest/cursortest @launch_sql3.sql >> launch_sql3.log 2>&1 &
nohup sqlplus -s cursortest/cursortest @launch_sql4.sql >> launch_sql4.log 2>&1 &
done
exit 0

-- sql 1: the sql which runs 1 routine of select and dies
-- launch_sql1.sql
set term off
select fx_num(substr(to_char(sysdate,'MON'),1,1)) from dual;
exit

-- sql 2: the sql which runs same number of times as number of objects in all_objects view - in my case 14000 
-- launch_sql2.sql
set term off
select object_name from all_objects where object_id < fx_num(substr(object_id,1,1));
exit

-- sql 3: the sql which runs same number of times as number of sources in all_source view - in my case 96000
-- launch_sql3.sql
set term off
select name, count(*) from all_source where line < fx_num(substr(name,1,1)) group by name;
exit

-- sql 4: the sql which runs same number of times as all_tab_partitions
-- launch_sql4.sql
set term off
select trunc(last_analyzed), sample_size, count(*) from all_tab_partitions where column_id < fx_num(substr(column_name,1,1)) group by trunc(last_analyzed), sample_size;
exit

DBA routine:

--- checkwaits.sql
set lines 200 pages 200
prompt - Waits on cursor pin S:
alter session set nls_date_format='DD/MON/YYYY HH24:MI:SS';
select sysdate,inst_id, substr(event,1,30) event, p1, sql_id, count(*)
from gv$session
where event = 'cursor: pin S'
group by inst_id, substr(event,1,30), p1, sql_id;
exit

Live sampler (screen 1):
while :
do
sqlplus -s '/as sysdba' @checkwaits.sql;
sleep 1;
done

Launch vmstat in another (screen 2):
vmstat 2 10000 -t

Launch the test: (screen 3)
sh launch_test.sh

1 CPU test routine:

Round 1: without hot object
Result:
[oracle@vcentos79-oracle-sby1 cursortestroutine]$ ps -ef|grep -i launch
oracle   11893     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11894     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11897     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11898     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11901     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11902     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11903     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11905     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11906     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11907     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11909     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11910     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11911     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11913     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11914     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11915     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11917     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11918     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11919     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11921     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11922     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11923     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11925     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11926     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11927     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11929     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11930     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11931     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11933     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11934     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11937     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11938     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11939     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11941     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11942     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11943     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11945     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11946     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11947     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11949     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11950     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11951     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11953     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11954     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11957     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11958     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11959     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11961     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11962     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11963     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11965     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11966     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11967     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11969     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11970     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11973     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11974     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11977     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11978     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11979     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11981     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11982     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11985     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11986     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11987     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11989     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11990     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11991     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11993     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11994     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11995     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   11997     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   11998     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   11999     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12001     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12002     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12003     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12005     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12006     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12007     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12009     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12010     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12011     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12013     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12014     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12015     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12017     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12018     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12019     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12021     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12022     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12023     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12025     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12026     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12027     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12029     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12030     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12031     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12033     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12034     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12035     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12037     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12038     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12039     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12041     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12042     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12043     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12045     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12046     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12047     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12049     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12050     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12051     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12053     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12054     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12055     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12057     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12058     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12059     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12061     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12062     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12063     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12065     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12066     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12067     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12069     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12070     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12071     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12073     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12074     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12075     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12077     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12078     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12079     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12081     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12082     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12083     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12085     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12086     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12087     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   12089     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
oracle   12090     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   12091     1  0 08:33 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
[oracle@vcentos79-oracle-sby1 cursortestroutine]$

Test run duration: 
 0  0      0 3124920   4180 4042188    0    0     0     8 2650 3703  1  1 98  0  0 2023-07-20 08:33:39
158  0      0 2510940   4180 4042468    0    0    18    12 1330 3400 47 49  4  0  0 2023-07-20 08:33:41
...
26  0      0 2730096   4180 4070260    0    0     2    20 1210 5330 94  6  0  0  0 2023-07-20 08:40:47
 0  0      0 3059524   4180 4068624    0    0     2    20 1920 5914 48  7 45  0  0 2023-07-20 08:40:49

Post Mortem:
1) Take a AWR snap:
exec dbms_workload_repository.create_snapshot;

SQL> exec dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.


2) Generate a AWR report:
                                           Total Wait       Avg   % DB Wait
Event                                Waits Time (sec)      Wait   time Class
------------------------------ ----------- ---------- --------- ------ --------
cursor: pin S                       40,322     3480.4   86.32ms   11.8 Concurre     <<< it was avergaed over 40mins vs our test lasted for only 7 mins.
cursor: pin S wait on X                146      930.8 6375.65ms    3.2 Concurre
library cache lock                   1,312      658.5  501.91ms    2.2 Concurre

Top SQLs by elapsed time:

        Elapsed                  Elapsed Time
        Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
        20,926.8             50        418.54   71.2    1.6     .0 1qkbdzb1953fs                <<< Parent sql which has 96000 sources within it
Module: SQL*Plus
select name, count(*) from all_source where line < fx_num(substr(name,1,1)) grou
p by name

        11,395.2     11,429,802          0.00   38.8    1.5     .0 7tr4jwnamtmsr                <<< the SQL of our interest
Module: SQL*Plus
SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1

         7,012.7             50        140.25   23.9     .9     .0 css31cyczctxm
Module: SQL*Plus
select object_name from all_objects where object_id < fx_num(substr(object_id,1,                <<< Parent sql which has 14000 sources within it
1))

           146.8              6         24.47     .5    4.7    1.8 fhf8upax5cxsz
BEGIN sys.dbms_auto_report_internal.i_save_report (:rep_ref, :snap_id, :pr_class
, :rep_id, :suc); END;

Executions: 1.1M
        11,395.2     11,429,802          0.00   38.8    1.5     .0 7tr4jwnamtmsr                <<< the SQL of our interest
Module: SQL*Plus
SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1

Our watcher:

SYSDATE                 INST_ID EVENT                                                                                     P1 SQL_ID           COUNT(*)
-------------------- ---------- ------------------------------------------------------------------------------------------------------------------------ ---------- ------------- ----------
20/JUL/2023 08:40:47          1 cursor: pin S                                                                              356306711 7tr4jwnamtmsr          16
20/JUL/2023 08:40:47          1 cursor: pin S                                                                              356306711                         1          <<< P1 value is same across.
20/JUL/2023 08:40:47          1 cursor: pin S                                                                              356306711 1qkbdzb1953fs          14

SQL Stats:
SQL_ID7tr4jwnamtmsr
SHARABLE_MEM27610
PERSISTENT_MEM7328
RUNTIME_MEM5696
SORTS0
LOADED_VERSIONS1
OPEN_VERSIONS0
USERS_OPENING0
FETCHES11429802
EXECUTIONS11429802
PX_SERVERS_EXECUTIONS0
END_OF_FETCH_COUNT11429802
USERS_EXECUTING0
LOADS1
FIRST_LOAD_TIME2023-07-20/08:10:19
INVALIDATIONS0
PARSE_CALLS152
DISK_READS2
DIRECT_WRITES0
DIRECT_READS0
BUFFER_GETS80008690
APPLICATION_WAIT_TIME0
CONCURRENCY_WAIT_TIME1616988115
CLUSTER_WAIT_TIME0
USER_IO_WAIT_TIME92
PLSQL_EXEC_TIME0
JAVA_EXEC_TIME0
ROWS_PROCESSED10267852
COMMAND_TYPE3
OPTIMIZER_ALL_ROWS
OPTIMIZER_COST3
OPTIMIZER_ENV
E289FB89D01122016A0210006EF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C65355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1
OPTIMIZER_ENV_HASH_VALUE2921190807
PARSING_USER_ID80
PARSING_SCHEMA_ID80
PARSING_SCHEMA_NAMECURSORTEST
KEPT_VERSIONS0
ADDRESS0000000061ACAA80
TYPE_CHK_HEAP0
HASH_VALUE356306711
OLD_HASH_VALUE3173993143
PLAN_HASH_VALUE2507369065
FULL_PLAN_HASH_VALUE985627438
CHILD_NUMBER0
SERVICESYS$USERS
SERVICE_HASH0
MODULESQL*Plus
MODULE_HASH-625018272
ACTION
ACTION_HASH0
SERIALIZABLE_ABORTS0
OUTLINE_CATEGORY
CPU_TIME167250167
ELAPSED_TIME1.14E+10
OUTLINE_SID
CHILD_ADDRESS0000000061B12AD8
SQLTYPE6
RN
OBJECT_STATUSVALID
LITERAL_HASH_VALUE0
LAST_LOAD_TIME2023-07-20/08:10:19
IN
IN
IN
IY
CHILD_LATCH0
SQL_PROFILE
SQL_PATCH
SQL_PLAN_BASELINE
PROGRAM_ID23829
PROGRAM_LINE#5
EXACT_MATCHING_SIGNATURE5.05E+18
FORCE_MATCHING_SIGNATURE5.05E+18
LAST_ACTI20-Jul-23
BIND_DATA
BEDA1300000064B8E359000101F001200369014A
TYPECHECK_MEM0
IO_CELL_OFFLOAD_ELIGIBLE_BYTES0
IO_INTERCONNECT_BYTES16384
PHYSICAL_READ_REQUESTS2
PHYSICAL_READ_BYTES16384
PHYSICAL_WRITE_REQUESTS0
PHYSICAL_WRITE_BYTES0
OPTIMIZED_PHY_READ_REQUESTS0
LOCKED_TOTAL152
PINNED_TOTAL11429803
IO_CELL_UNCOMPRESSED_BYTES0
IO_CELL_OFFLOAD_RETURNED_BYTES0
CON_ID0
IN
I
IM_SCANS0
IM_SCAN_BYTES_UNCOMPRESSED0
IM_SCAN_BYTES_INMEMORY0
DN
IN
IN
RN
SQL_QUARANTINE
AVOIDED_EXECUTIONS0


Round 2:
Mark the recursive sql as hot: 7tr4jwnamtmsr

col name for a40
col value for a10
select ksppinm name, ksppstvl value from x$ksppi a, x$ksppsv b, v$instance
where a.indx=b.indx AND substr(ksppinm,1,1) = '_' AND ksppinm = '_kgl_hot_object_copies';

SQL> select ksppinm name, ksppstvl value from x$ksppi a, x$ksppsv b, v$instance
where a.indx=b.indx AND substr(ksppinm,1,1) = '_' AND ksppinm = '_kgl_hot_object_copies';  2

NAME                                    ,VALUE
----------------------------------------,----------
_kgl_hot_object_copies                  ,0

SQL>

Though I have only 4 cpus in my laptop and I gave 1 to the vm, I will make this param as 8 for lab. Oracle recommends this to be 50% of the cpu.

alter system set "_kgl_hot_object_copies"=8 scope=spfile sid='*';

SQL> select ksppinm name, ksppstvl value from x$ksppi a, x$ksppsv b, v$instance
where a.indx=b.indx AND substr(ksppinm,1,1) = '_' AND ksppinm = '_kgl_hot_object_copies';  2

NAME                                    ,VALUE
----------------------------------------,----------
_kgl_hot_object_copies                  ,0

SQL>

select kglnahsh, kglnahsv from v$sql, x$kglob where kglhdadr=address and sql_id = '7tr4jwnamtmsr';

SQL> select kglnahsh, kglnahsv from v$sql, x$kglob where kglhdadr=address and sql_id = '7tr4jwnamtmsr';

  KGLNAHSH,KGLNAHSV
----------,--------------------------------
 356306711,eb4cdceda1c495cd7cdc91e5153ccf17

SQL>

To mark the sql 7tr4jwnamtmsr hot across the db bounce (which I am going to do now). I will set it in init param and bounce the db once for all. So both params comes into effect.

Option 2: Only instance effect:

begin
  dbms_shared_pool.markhot(hash => 'eb4cdceda1c495cd7cdc91e5153ccf17', namespace => 0, global => true);
end;
/

Query to verify hot object:
select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value = 356306711
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;

col name for a100
col namespace for a20
SQL> select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value = 356306711
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;  2    3

   INST_ID,HASH_VALUE,NAMESPACE           ,CHILD_LATCH,PROPERTY            ,STATUS              ,EXECUTIONS,NAME
----------,----------,--------------------,-----------,---------------------------,-------------------,----------,----------------------------------------------------------------------------------------------------
         1, 356306711,SQL AREA            ,          0,HOT                 ,VALID               ,  11429802,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1, 356306711,SQL AREA            ,      53015,HOT                 ,VALID               ,  11425849,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1

SQL>

So it is marked hot now. Let us bounce the db and check. Ensure to mark the object hot in all the instances if in case of RAC (to do this by connecting to individual instances not using sid='*' as per note 2369968.1).

After bounce:
SQL> col name for a100
col namespace for a20SQL>
SQL> select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value = 356306711
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;  2    3

no rows selected

SQL>

alter system set "_kgl_debug" = "hash='eb4cdceda1c495cd7cdc91e5153ccf17' namespace=0 debug=33554432";

SQL> select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value = 356306711
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;  2    3

no rows selected

SQL>

>>> this is the reason you need to have this object in memory; which is when the live execution is happening or just happened. Let me load this object into memory by manually invoking 1 sql.

Query ran:
[oracle@vcentos79-oracle-sby1 cursortestroutine]$ cat launch_sql1.sql
select fx_num(substr(to_char(sysdate,'MON'),1,1)) from dual;
exit
[oracle@vcentos79-oracle-sby1 cursortestroutine]$


SQL> @launch_sql1.sql

FX_NUM(SUBSTR(TO_CHAR(SYSDATE,'MON'),1,1))
------------------------------------------
                                97685.0719

SQL> select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value = 356306711
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;  2    3

   INST_ID,HASH_VALUE,NAMESPACE           ,CHILD_LATCH,PROPERTY                                                                 ,STATUS              ,EXECUTIONS,NAME
----------,----------,--------------------,-----------,--------------------------------------------------------------------------------,-------------------,----------,----------------------------------------------------------------------------------------------------
         1, 356306711,SQL AREA            ,      53015,HOT                                                                      ,UNKOWN              ,         0,SELECT LOW_VALUE, HI

SQL>

-- not vising in v$sql though. So it ideally came from the alter system command we ran. Try DB restart to see if the object is visible already on the db_object_cache view.

SQL> select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value = 356306711
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;  2    3

no rows selected

SQL>

>>> show it doesnt show up. But it shows up during execution hopefully.

12:04:53 SQL> exec dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.22
12:05:04 SQL>

Now a snap is taken. Vmstat command invoked.Launch the test...

SYSDATE                 INST_ID EVENT                                                                                     P1 SQL_ID           COUNT(*)
-------------------- ---------- ------------------------------------------------------------------------------------------------------------------------ ---------- ------------- ----------
20/JUL/2023 12:13:29          1 cursor: pin S                                                                              667730673 5bacfy8mwthrj           3
20/JUL/2023 12:13:29          1 cursor: pin S                                                                             3589634917                         1
20/JUL/2023 12:13:29          1 cursor: pin S                                                                              667730673                         3
20/JUL/2023 12:13:29          1 cursor: pin S                                                                             1835995903 ddttvdtqqy4rz           1
20/JUL/2023 12:13:29          1 cursor: pin S                                                                             3589634917 0u9hxt3azayv5           2
20/JUL/2023 12:13:29          1 cursor: pin S                                                                             3589634917 1qkbdzb1953fs           3
20/JUL/2023 12:13:29          1 cursor: pin S                                                                              667730673 1qkbdzb1953fs           2

7 rows selected.

[oracle@vcentos79-oracle-sby1 cursortestroutine]$ ps -ef|grep -i launch
oracle   24615     1  0 12:05 pts/1    00:00:00 sqlplus -s                       @launch_sql2.sql
..
oracle   24812     1  0 12:05 pts/1    00:00:00 sqlplus -s                       @launch_sql3.sql
oracle   24813     1  0 12:05 pts/1    00:00:00 sqlplus -s                       @launch_sql4.sql
oracle   25106 10105  0 12:05 pts/1    00:00:00 grep --color=auto -i launch
[oracle@vcentos79-oracle-sby1 cursortestroutine]$

Test window:
[oracle@vcentos79-oracle-sby1 ~]$ vmstat 2 10000 -t
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- -----timestamp-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st                 BST
 1  0      0 3055108   4180 4140776    0    0   101    30  420 1615  3  0 96  1  0 2023-07-20 12:05:08
 0  0      0 3051372   4180 4140776    0    0     0     8 2388 3415  1  1 99  0  0 2023-07-20 12:05:10
..
 0  0      0 2956464   4180 4147904    0    0     2    26 1549 2670 34  2 63  1  0 2023-07-20 12:13:51
 0  0      0 2956624   4180 4147908    0    0     2    16 1987 3045  2  1 97  0  0 2023-07-20 12:13:53
^C
[oracle@vcentos79-oracle-sby1 ~]$

AWR snap is also captured at the end. AWR report name: awrrpt_1_33_34.txt

Live watcher sample:
SYSDATE                 INST_ID EVENT                                                                                     P1 SQL_ID           COUNT(*)
-------------------- ---------- ------------------------------------------------------------------------------------------------------------------------ ---------- ------------- ----------
20/JUL/2023 12:13:29          1 cursor: pin S                                                                              667730673 5bacfy8mwthrj           3
20/JUL/2023 12:13:29          1 cursor: pin S                                                                             3589634917                         1
20/JUL/2023 12:13:29          1 cursor: pin S                                                                              667730673                         3
20/JUL/2023 12:13:29          1 cursor: pin S                                                                             1835995903 ddttvdtqqy4rz           1
20/JUL/2023 12:13:29          1 cursor: pin S                                                                             3589634917 0u9hxt3azayv5           2
20/JUL/2023 12:13:29          1 cursor: pin S                                                                             3589634917 1qkbdzb1953fs           3
20/JUL/2023 12:13:29          1 cursor: pin S                                                                              667730673 1qkbdzb1953fs           2

7 rows selected.

SQL> select count(1) from v$sql where sql_id='ddttvdtqqy4rz';

  COUNT(1)
----------
         1

SQL> select sql_text from v$sqltext where sql_id='ddttvdtqqy4rz' order by piece;

SQL_TEXT
----------------------------------------------------------------
SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1


SQL> select sql_id,hash_value from v$sql where force_matching_signature=(select force_matching_signature from v$sql where sql_id='ddttvdtqqy4rz');

SQL_ID       ,HASH_VALUE
-------------,----------
dg9n6z0w0cmnk, 939937426
61m38g7ygpfvz,4244290431
9pyrc45h3tgg9,1614593513
5bacfy8mwthrj, 667730673
ddttvdtqqy4rz,1835995903
arg5wx08suqm0, 294476384
1far8p5csfrmx,1502043773
0u9hxt3azayv5,3589634917

8 rows selected.

SQL>

So 8 db_cache_objects were created as expected. 

select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value in (select hash_value from v$sql where force_matching_signature=(select force_matching_signature from v$sql where sql_id='ddttvdtqqy4rz'))
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;

   INST_ID,HASH_VALUE,NAMESPACE      ,CHILD_LATCH,PROPERTY                                                                         ,STATUS             ,EXECUTIONS,NAME
----------,----------,--------------------------------------,-----------,--------------------------------------------------------------------------------,-------------------,----------,----------------------------------------------------------------------------------------------------
         1, 294476384,SQL AREA       ,   0,HOTCOPY4                                                                        ,VALID              ,    960918,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1, 294476384,SQL AREA       ,      88672,HOTCOPY4                                                                         ,VALID              ,    960712,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1, 667730673,SQL AREA       ,   0,HOTCOPY2                                                                        ,VALID              ,   1941201,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1, 667730673,SQL AREA       ,      49905,HOTCOPY2                                                                         ,VALID              ,   1941201,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1, 939937426,SQL AREA       ,   0,HOTCOPY8                                                                        ,VALID              ,   1348386,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1, 939937426,SQL AREA       ,      20114,HOTCOPY8                                                                         ,VALID              ,   1347865,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,1502043773,SQL AREA       ,   0,HOTCOPY5                                                                        ,VALID              ,    984165,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,1502043773,SQL AREA       ,      89725,HOTCOPY5                                                                         ,VALID              ,    983847,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,1614593513,SQL AREA       ,   0,HOTCOPY6                                                                        ,VALID              ,   1119780,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,1614593513,SQL AREA       ,      48617,HOTCOPY6                                                                         ,VALID              ,   1119372,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,1835995903,SQL AREA       ,   0,HOTCOPY3                                                                        ,VALID              ,   1805590,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,1835995903,SQL AREA       ,      70399,HOTCOPY3                                                                         ,VALID              ,   1805590,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,3589634917,SQL AREA       ,   0,HOTCOPY1                                                                        ,VALID              ,   1669975,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,3589634917,SQL AREA       ,      97125,HOTCOPY1                                                                         ,VALID              ,   1668163,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,4244290431,SQL AREA       ,   0,HOTCOPY7                                                                        ,VALID              ,   1600235,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,4244290431,SQL AREA       ,      47999,HOTCOPY7                                                                         ,VALID              ,   1600235,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1

16 rows selected.

Looks like 8 cursors in place of 1.Each was executed a million times or so.

   INST_ID,HASH_VALUE,NAMESPACE       ,CHILD_LATCH,PROPERTY                                                                         ,STATUS             ,EXECUTIONS,NAME
----------,----------,---------------------------------------,-----------,--------------------------------------------------------------------------------,-------------------,----------,----------------------------------------------------------------------------------------------------
         1, 356306711,SQL AREA        ,      53015,HOT                                                                              ,UNKOWN             ,  0,SELECT LOW_VALUE, HI

The old cursor isnt at all used.

Did it improve the performance and reduce overall job duration?

NO

AWR:

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:        33 20-Jul-23 12:05:03        51       1.1
  End Snap:        34 20-Jul-23 12:14:03        55       1.2
   Elapsed:                9.00 (mins)
   DB Time:              553.57 (mins)          <<< this is the amount of time job spent in 9 mins wall clock time.


                                           Total Wait       Avg   % DB Wait
Event                                Waits Time (sec)      Wait   time Class
------------------------------ ----------- ---------- --------- ------ --------
cursor: pin S wait on X                895     2948.7 3294.67ms    8.9 Concurre     << pin S wait on X increased 8 fold !!!! the issue if offloaded over to here
library cache: mutex X               7,949      812.7  102.25ms    2.4 Concurre
library cache: bucket mutex X        8,065      734.4   91.06ms    2.2 Concurre
DB CPU                                            448              1.3
library cache lock                   1,133      370.3  326.87ms    1.1 Concurre
cursor: pin S                        5,110      362.2   70.88ms    1.1 Concurre     << pin S waits have reduced by 8 fold :) as we set the param
library cache load lock                733      197.3  269.15ms     .6 Concurre
row cache mutex                      1,018      189.6  186.23ms     .6 Concurre
row cache lock                         195      138.2  708.81ms     .4 Concurre
latch free                             110       13.8  125.63ms     .0 Other

SQL elapsed report:

        Elapsed                  Elapsed Time
        Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
        22,772.7             50        455.45   68.6    1.6     .1 1qkbdzb1953fs            <<< Deteriorated by 2000 secs
Module: SQL*Plus
select name, count(*) from all_source where line < fx_num(substr(name,1,1)) grou
p by name

         7,268.1             50        145.36   21.9     .9     .0 css31cyczctxm            <<< Deteriorated by 2000 secs
Module: SQL*Plus
select object_name from all_objects where object_id < fx_num(substr(object_id,1,
1))

           529.1            189          2.80    1.6     .4     .0 599kk70c4bmmk
select option#,NVL(success,0),NVL(failure,0) from audit$ where user#=:client and
 proxy# is null

           417.8            200          2.09    1.3     .4     .0 g4y6nw3tts7cc
Module: sqlplus@vcentos79-oracle-sby1 (TNS V1-V3)
BEGIN DBMS_APPLICATION_INFO.SET_MODULE(:1,NULL); END;


The sqls arent visible in AWR as well!!!

Iteration 1 result (1 cpu round):
Looking at the v$sql stat, we could see the sql elapsed time total is 10000secs simillar to what we saw in the previous execution.

SQL_ID0u9hxt3azayv51far8p5csfrmx5bacfy8mwthrj61m38g7ygpfvz9pyrc45h3tgg9arg5wx08suqm0ddttvdtqqy4rzdg9n6z0w0cmnk
SHARABLE_MEM2761127611276112761127611276112761127611
PERSISTENT_MEM73287328732873287328732873287328
RUNTIME_MEM56965696569656965696569656965696
SORTS00000000
LOADED_VERSIONS11111111
OPEN_VERSIONS00000000
USERS_OPENING00000000
FETCHES166997598416519412011600235111978096091818055901348386
EXECUTIONS166997598416519412011600235111978096091818055901348386
PX_SERVERS_EXECUTIONS00000000
END_OF_FETCH_COUNT166997598416519412011600235111978096091818055901348386
USERS_EXECUTING00000000
LOADS11111111
FIRST_LOAD_TIME2023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:00
INVALIDATIONS00000000
PARSE_CALLS2016182117162121
DISK_READS00100050
DIRECT_WRITES00000000
DIRECT_READS00000000
BUFFER_GETS116898296889156135884311120164678384616726427126391519438710
APPLICATION_WAIT_TIME00000000
CONCURRENCY_WAIT_TIME4287498821789513333628893398592922352592217464393596372030538013
CLUSTER_WAIT_TIME00000000
USER_IO_WAIT_TIME0087000930
PLSQL_EXEC_TIME00000000
JAVA_EXEC_TIME00000000
ROWS_PROCESSED143749582142918482091437499102678882143016428541232146
COMMAND_TYPE33333333
OPTIMIZER_ALL_ROWSALL_ROWSALL_ROWSALL_ROWSALL_ROWSALL_ROWSALL_ROWSALL_ROWS
OPTIMIZER_COST33333333
OPTIMIZER_ENVE289FB89D01122016A0210006EF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C65355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1E289FB89D01122016A0210006EF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C65355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1E289FB89D01122016A0210006EF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C65355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1E289FB89D01122016A0210006EF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C65355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1E289FB89D01122016A0210006EF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C65355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1E289FB89D01122016A0210006EF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C65355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1E289FB89D01122016A0210006EF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C65355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1
E289FB89D01122016A0210006EF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C65355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1
OPTIMIZER_ENV_HASH_VALUE29211908072921190807292119080729211908072921190807292119080729211908072921190807
PARSING_USER_ID8080808080808080
PARSING_SCHEMA_ID8080808080808080
PARSING_SCHEMA_NAMECURSORTESTCURSORTESTCURSORTESTCURSORTESTCURSORTESTCURSORTESTCURSORTESTCURSORTEST
KEPT_VERSIONS00000000
ADDRESS0000000063BBFF200000000063BDAE980000000063BDAB680000000063BC80700000000063BC7D400000000063BCC1180000000063BD01C00000000063BD4268
TYPE_CHK_HEAP00000000
HASH_VALUE35896349171502043773667730673424429043116145935132944763841835995903939937426
OLD_HASH_VALUE31739931433173993143317399314331739931433173993143317399314331739931433173993143
PLAN_HASH_VALUE25073690652507369065250736906525073690652507369065250736906525073690652507369065
FULL_PLAN_HASH_VALUE985627438985627438985627438985627438985627438985627438985627438985627438
CHILD_NUMBER00000000
SERVICESYS$USERSSYS$USERSSYS$USERSSYS$USERSSYS$USERSSYS$USERSSYS$USERSSYS$USERS
SERVICE_HASH00000000
MODULESQL*PlusSQL*PlusSQL*PlusSQL*PlusSQL*PlusSQL*PlusSQL*PlusSQL*Plus
MODULE_HASH-625018272-625018272-625018272-625018272-625018272-625018272-625018272-625018272
ACTION
ACTION_HASH00000000
SERIALIZABLE_ABORTS00000000
OUTLINE_CATEGORY
CPU_TIME2460374814684995285324982359341116345084141686412643824419773328
ELAPSED_TIME1598063155100102848417394555361512044279104399533494337029716633064851256390795
OUTLINE_SID
CHILD_ADDRESS0000000063BBE7C80000000063BAF1500000000063BD94100000000063BC28700000000063BC65E80000000063BCA9C00000000063BCEA680000000063BD2B10
SQLTYPE66666666
RNNNNNNNN
OBJECT_STATUSVALIDVALIDVALIDVALIDVALIDVALIDVALIDVALID
LITERAL_HASH_VALUE00000000
LAST_LOAD_TIME2023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:002023-07-20/12:06:00
INNNNNNNN
INNNNNNNN
INNNNNNNN
IYYYYYYYY
CHILD_LATCH00000000
SQL_PROFILE
SQL_PATCH
SQL_PLAN_BASELINE
PROGRAM_ID2382923829238292382923829238292382923829
PROGRAM_LINE#55555555
EXACT_MATCHING_SIGNATURE5.05E+185.05E+185.05E+185.05E+185.05E+185.05E+185.05E+185.05E+18
FORCE_MATCHING_SIGNATURE5.05E+185.05E+185.05E+185.05E+185.05E+185.05E+185.05E+185.05E+18
LAST_ACTI20-Jul-2320-Jul-2320-Jul-2320-Jul-2320-Jul-2320-Jul-2320-Jul-2320-Jul-23
BIND_DATABEDA1300000064B91519000101F001200369014ABEDA1300000064B91519000101F001200369014ABEDA1300000064B91519000101F001200369014ABEDA1300000064B91519000101F001200369014ABEDA1300000064B91519000101F001200369014ABEDA1300000064B91519000101F001200369014ABEDA1300000064B91519000101F001200369014A
BEDA1300000064B91519000101F001200369014A
TYPECHECK_MEM00000000
IO_CELL_OFFLOAD_ELIGIBLE_BYTES00000000
IO_INTERCONNECT_BYTES008192000409600
PHYSICAL_READ_REQUESTS00100010
PHYSICAL_READ_BYTES008192000409600
PHYSICAL_WRITE_REQUESTS00000000
PHYSICAL_WRITE_BYTES00000000
OPTIMIZED_PHY_READ_REQUESTS00000000
LOCKED_TOTAL2016182117162121
PINNED_TOTAL166997698416619412021600236111978196091918055911348387
IO_CELL_UNCOMPRESSED_BYTES00000000
IO_CELL_OFFLOAD_RETURNED_BYTES00000000
CON_ID00000000
INNNNNNNN
I
IM_SCANS00000000
IM_SCAN_BYTES_UNCOMPRESSED00000000
IM_SCAN_BYTES_INMEMORY00000000
DNNNNNNNN
INNNNNNNN
INNNNNNNN
RNNNNNNNN
SQL_QUARANTINE
AVOIDED_EXECUTIONS00000000


4 CPU test routine:
I will try to upsize the cpu count to 4 and set the count to 2 and see how the situation is.

Cpu upsized to 4 (all of my lab machine cpu given to the vm).
Round 1 - without the hot object:

Repeat: [Ensure to disable resource_manager_plan, otherwise cpu quantum will disturb the test]
1. Snap captured
2. vmstat activated
3. Live monitoring activated
4. launch test ( noticed my lap host cpu is 100% full vs when only 1 cpu was allocated it was 30% full)
5. Test span: 3mins 17secs mins (vs 7 mins with 1 cpu)

AWR:

                                           Total Wait       Avg   % DB Wait
Event                                Waits Time (sec)      Wait   time Class
------------------------------ ----------- ---------- --------- ------ --------
cursor: pin S                       40,022     2217.8   55.41ms   17.3 Concurre [DB total time: 13K secs]
DB CPU                                            739              5.8
cursor: pin S wait on X                718      352.7  491.24ms    2.8 Concurre
library cache lock                   1,197      103.4   86.38ms     .8 Concurre
library cache: mutex X               1,455       60.2   41.40ms     .5 Concurre
library cache load lock              1,192       58.6   49.18ms     .5 Concurre
row cache lock                         321       38.1  118.77ms     .3 Concurre
row cache mutex                        785       28.1   35.84ms     .2 Concurre


                                                                % of  % of Total
Statistic Name                                       Time (s) DB Time   CPU Time
------------------------------------------ ------------------ ------- ----------
sql execute elapsed time                             12,064.1    94.1            [ this is more less is the db total time]
PL/SQL execution elapsed time                         1,949.0    15.2

Of 12K secs - 2K secs we spent on concurrency where did we spent rest on!!!
This is where the unaccounted latch comes. The cursor pin S ideally has some unreported time metrics.

        Elapsed                  Elapsed Time
        Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
         9,311.3             50        186.23   72.7    6.6     .0 1qkbdzb1953fs
Module: SQL*Plus
select name, count(*) from all_source where line < fx_num(substr(name,1,1)) grou
p by name

         4,925.0     11,380,426          0.00   38.4    5.8     .0 7tr4jwnamtmsr            <<< out candidate hot object
Module: SQL*Plus
SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1

         2,828.5             50         56.57   22.1    3.8     .0 css31cyczctxm
Module: SQL*Plus
select object_name from all_objects where object_id < fx_num(substr(object_id,1,
1))

SQL_ID7tr4jwnamtmsr
SHARABLE_MEM23554
PERSISTENT_MEM7328
RUNTIME_MEM5696
SORTS0
LOADED_VERSIONS1
OPEN_VERSIONS0
USERS_OPENING0
FETCHES11410663
EXECUTIONS11380426
PX_SERVERS_EXECUTIONS0
END_OF_FETCH_COUNT11415878
USERS_EXECUTING0
LOADS1
FIRST_LOAD_TIME2023-07-20/22:41:39
INVALIDATIONS0
PARSE_CALLS150
DISK_READS8
DIRECT_WRITES0
DIRECT_READS0
BUFFER_GETS66495314
APPLICATION_WAIT_TIME0
CONCURRENCY_WAIT_TIME1046857450
CLUSTER_WAIT_TIME0
USER_IO_WAIT_TIME8145
PLSQL_EXEC_TIME0
JAVA_EXEC_TIME0
ROWS_PROCESSED10238971
COMMAND_TYPE3
OPTIMIZER_ALL_ROWS
OPTIMIZER_COST3
OPTIMIZER_ENV
E289FB89D01122016A021000AEF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C6A355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1
OPTIMIZER_ENV_HASH_VALUE71584513
PARSING_USER_ID80
PARSING_SCHEMA_ID80
PARSING_SCHEMA_NAMECURSORTEST
KEPT_VERSIONS0
ADDRESS00000000635DDC48
TYPE_CHK_HEAP0
HASH_VALUE356306711
OLD_HASH_VALUE3173993143
PLAN_HASH_VALUE2507369065
FULL_PLAN_HASH_VALUE985627438
CHILD_NUMBER0
SERVICESYS$USERS
SERVICE_HASH0
MODULESQL*Plus
MODULE_HASH-625018272
ACTION
ACTION_HASH0
SERIALIZABLE_ABORTS0
OUTLINE_CATEGORY
CPU_TIME284413550
ELAPSED_TIME4925042008
OUTLINE_SID
CHILD_ADDRESS6.36E+173
SQLTYPE6
RN
OBJECT_STATUSVALID
LITERAL_HASH_VALUE0
LAST_LOAD_TIME2023-07-20/22:41:39
IN
IN
IN
IY
CHILD_LATCH0
SQL_PROFILE
SQL_PATCH
SQL_PLAN_BASELINE
PROGRAM_ID23829
PROGRAM_LINE#5
EXACT_MATCHING_SIGNATURE5.05E+18
FORCE_MATCHING_SIGNATURE5.05E+18
LAST_ACTI20-Jul-23
BIND_DATA
BEDA1300000064B9AA13000101F001200369014A
TYPECHECK_MEM0
IO_CELL_OFFLOAD_ELIGIBLE_BYTES0
IO_INTERCONNECT_BYTES65536
PHYSICAL_READ_REQUESTS4
PHYSICAL_READ_BYTES65536
PHYSICAL_WRITE_REQUESTS0
PHYSICAL_WRITE_BYTES0
OPTIMIZED_PHY_READ_REQUESTS0
LOCKED_TOTAL150
PINNED_TOTAL10589435
IO_CELL_UNCOMPRESSED_BYTES0
IO_CELL_OFFLOAD_RETURNED_BYTES0
CON_ID0
IN
I
IM_SCANS0
IM_SCAN_BYTES_UNCOMPRESSED0
IM_SCAN_BYTES_INMEMORY0
DN
IN
IN
RN
SQL_QUARANTINE
AVOIDED_EXECUTIONS0


Round 2: Reduced the hot objects from 8 to 2 

SQL> alter system set "_kgl_hot_object_copies"=2 scope=spfile sid='*';

System altered.

SQL> show parameter kgl

NAME                                ,TYPE       ,VALUE
------------------------------------,-----------,------------------------------
_kgl_hot_object_copies              ,integer    ,8
SQL>

Current hot object report:

SQL> select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value = 356306711
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;  2    3

   INST_ID,HASH_VALUE,NAMESPACE                                                                                                ,CHILD_LATCH,PROPERTY                                                                         ,STATUS             ,EXECUTIONS,NAME
----------,----------,--------------------------------------------------------------------------------------------------------------------------------,-----------,--------------------------------------------------------------------------------,-------------------,----------,----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
         1, 356306711,SQL AREA                                                                                                 ,      53015,                                                                                 ,VALID              ,  10764794,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1, 356306711,SQL AREA                                                                                                 ,   0,                                                                                ,VALID              ,  10485824,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1

SQL>


The object isnt marked hot yet though.

alter system set "_kgl_debug" = "hash='eb4cdceda1c495cd7cdc91e5153ccf17' namespace=0 debug=33554432";

Marked the object hot and bounced the db.
Post restart of the db:

SQL> sho parameter kgl

NAME                                ,TYPE       ,VALUE
------------------------------------,-----------,------------------------------
_kgl_debug                          ,string     ,hash='eb4cdceda1c495cd7cdc91e5
                                    ,           ,153ccf17' namespace=0 debug=33
                                    ,           ,554432
_kgl_hot_object_copies              ,integer    ,2
SQL>


SQL> select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value = 356306711
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;  2    3

no rows selected

SQL>

SQL> sho parameter resource

NAME                                ,TYPE       ,VALUE
------------------------------------,-----------,------------------------------
..
resource_manager_plan               ,string     ,SCHEDULER[0x4D50]:DEFAULT_MAIN
                                    ,           ,TENANCE_PLAN
SQL> alter system set resource_manager_plan='';

System altered.

SQL> sho parameter resource

NAME                                ,TYPE       ,VALUE
------------------------------------,-----------,------------------------------
..
resource_manager_plan               ,string     ,
SQL>

Disabled resource_manager_plan as well.

After loading query into memory with 1 iteration.

SQL> select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value = 356306711
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;  2    3

   INST_ID,HASH_VALUE,NAMESPACE   ,CHILD_LATCH,PROPERTY                                                                         ,STATUS             ,EXECUTIONS,NAME
----------,----------,-----------------------------------,-----------,--------------------------------------------------------------------------------,-------------------,----------,---------------------------------------------------------------------------
         1, 356306711,SQL AREA    ,      53015,HOT                                                                              ,UNKOWN             ,  0,SELECT LOW_VALUE, HI

SQL>


a. Snap captured
b. vmstat activated
c. Live monitoring activated
d. launch test ( noticed my lap host cpu is 100% full vs when only 1 cpu was allocated it was 30% full)
e. Test span: 3mins 34secs (more compared without hot copies)


                                           Total Wait       Avg   % DB Wait
Event                                Waits Time (sec)      Wait   time Class
------------------------------ ----------- ---------- --------- ------ --------
library cache: bucket mutex X       21,242     1221.8   57.52ms    8.6 Concurre
library cache: mutex X              19,058     1031.9   54.14ms    7.3 Concurre
DB CPU                                          828.5              5.9
cursor: pin S                       17,004      678.5   39.90ms    4.8 Concurre
library cache lock                   1,161      238.1  205.08ms    1.7 Concurre
cursor: pin S wait on X                257      176.2  685.71ms    1.2 Concurre
Disk file operations I/O               645        9.6   14.84ms     .1 User I/O

                                                          Avg             Avg
                                        Total Wait       Wait   % DB   Active
Wait Class                  Waits       Time (sec)       Time   time Sessions
---------------- ---------------- ---------------- ---------- ------ --------
Concurrency                58,976            3,364    57.04ms   23.8      9.7
DB CPU                                         828               5.9      2.4


                                                                % of  % of Total
Statistic Name                                       Time (s) DB Time   CPU Time
------------------------------------------ ------------------ ------- ----------
sql execute elapsed time                             13,478.1    95.4               <<<< from 12K secs it went up by 1000 more secs
PL/SQL execution elapsed time                         4,655.5    32.9               <<<< this event got 100% increase
DB CPU                                                  828.5     5.9       98.5
parse time elapsed                                      425.3     3.0

Hot copies:

SQL> select sql_id,hash_value from v$sql where force_matching_signature=(select force_matching_signature from v$sql where sql_id='5bacfy8mwthrj');

SQL_ID       ,HASH_VALUE
-------------,----------
5bacfy8mwthrj, 667730673
0u9hxt3azayv5,3589634917

SQL>

select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value in (select hash_value from v$sql where force_matching_signature=(select force_matching_signature from v$sql where sql_id='5bacfy8mwthrj'))
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;

SQL> select inst_id, hash_value, namespace, child_latch, property, status, sum(executions) executions, name
from gv$db_object_cache where hash_value in (select hash_value from v$sql where force_matching_signature=(select force_matching_signature from v$sql where sql_id='5bacfy8mwthrj'))
group by inst_id, hash_value, name, namespace, child_latch, property, status order by hash_value;  2    3

   INST_ID,HASH_VALUE,NAMESPACE                                                                                                ,CHILD_LATCH,PROPERTY                                                                         ,STATUS             ,EXECUTIONS,NAME
----------,----------,--------------------------------------------------------------------------------------------------------------------------------,-----------,--------------------------------------------------------------------------------,-------------------,----------,---------------------------------------------------------------------------
         1, 667730673,SQL AREA                                                                                                 ,   0,HOTCOPY2                                                                        ,VALID              ,   5315392,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1, 667730673,SQL AREA                                                                                                 ,      49905,HOTCOPY2                                                                         ,VALID              ,   5391154,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,3589634917,SQL AREA                                                                                                 ,   0,HOTCOPY1                                                                        ,VALID              ,   5712452,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1
         1,3589634917,SQL AREA                                                                                                 ,      97125,HOTCOPY1                                                                         ,VALID              ,   5797044,SELECT LOW_VALUE, HIGH_VALUE FROM CODE_TABLE WHERE CODE_NAME=:B1

SQL>

SQL_ID0u9hxt3azayv55bacfy8mwthrj
SHARABLE_MEM2355523555
PERSISTENT_MEM73287328
RUNTIME_MEM56965696
SORTS00
LOADED_VERSIONS11
OPEN_VERSIONS00
USERS_OPENING00
FETCHES59172655507031
EXECUTIONS59104975501652
PX_SERVERS_EXECUTIONS00
END_OF_FETCH_COUNT59180495507662
USERS_EXECUTING00
LOADS11
FIRST_LOAD_TIME2023-07-20/23:09:54
2023-07-20/23:12:56
INVALIDATIONS00
PARSE_CALLS7972
DISK_READS90
DIRECT_WRITES00
DIRECT_READS00
BUFFER_GETS3506189632685902
APPLICATION_WAIT_TIME00
CONCURRENCY_WAIT_TIME218226240145991239
CLUSTER_WAIT_TIME00
USER_IO_WAIT_TIME1840
PLSQL_EXEC_TIME00
JAVA_EXEC_TIME00
ROWS_PROCESSED53339924923975
COMMAND_TYPE33
OPTIMIZER_ALL_ROWSALL_ROWS
OPTIMIZER_COST33
OPTIMIZER_ENVE289FB89D01122016A021000AEF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C6A355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1
E289FB89D01122016A021000AEF5C3E2CFFA331056414555519521105545551545545558591555449665851D5511058555555155515122555415A0EA0C5551454265455454449081566E041696C6A355451501025415504416FD557151551555551001550A16214545D1C35444A1011015595510250153355555555551E91F1
OPTIMIZER_ENV_HASH_VALUE7158451371584513
PARSING_USER_ID8080
PARSING_SCHEMA_ID8080
PARSING_SCHEMA_NAMECURSORTESTCURSORTEST
KEPT_VERSIONS00
ADDRESS0000000067DA2AA8
0000000064B7FFF0
TYPE_CHK_HEAP00
HASH_VALUE3589634917667730673
OLD_HASH_VALUE31739931433173993143
PLAN_HASH_VALUE25073690652507369065
FULL_PLAN_HASH_VALUE985627438985627438
CHILD_NUMBER00
SERVICESYS$USERSSYS$USERS
SERVICE_HASH00
MODULESQL*PlusSQL*Plus
MODULE_HASH-625018272-625018272
ACTION
ACTION_HASH00
SERIALIZABLE_ABORTS00
OUTLINE_CATEGORY
CPU_TIME162150654150622302
ELAPSED_TIME22738029622104902607
OUTLINE_SID
CHILD_ADDRESS0000000067DA2350
0000000064B7E898
SQLTYPE66
RNN
OBJECT_STATUSVALIDVALID
LITERAL_HASH_VALUE00
LAST_LOAD_TIME2023-07-20/23:09:54
2023-07-20/23:12:56
INN
INN
INN
IYY
CHILD_LATCH00
SQL_PROFILE
SQL_PATCH
SQL_PLAN_BASELINE
PROGRAM_ID2382923829
PROGRAM_LINE#55
EXACT_MATCHING_SIGNATURE5.05E+185.05E+18
FORCE_MATCHING_SIGNATURE5.05E+185.05E+18
LAST_ACTI20-Jul-2320-Jul-23
BIND_DATABEDA1300000064B9B0B2000101F001200369014A
BEDA1300000064B9B167000101F001200369014A
TYPECHECK_MEM00
IO_CELL_OFFLOAD_ELIGIBLE_BYTES00
IO_INTERCONNECT_BYTES737280
PHYSICAL_READ_REQUESTS50
PHYSICAL_READ_BYTES737280
PHYSICAL_WRITE_REQUESTS00
PHYSICAL_WRITE_BYTES00
OPTIMIZED_PHY_READ_REQUESTS00
LOCKED_TOTAL7972
PINNED_TOTAL56791465329892
IO_CELL_UNCOMPRESSED_BYTES00
IO_CELL_OFFLOAD_RETURNED_BYTES00
CON_ID00
INN
I
IM_SCANS00
IM_SCAN_BYTES_UNCOMPRESSED00
IM_SCAN_BYTES_INMEMORY00
DNN
INN
INN
RNN
SQL_QUARANTINE
AVOIDED_EXECUTIONS00


Result:
No improvement in this 4 cpu lab. I noticed the hot spot get offloaded from cursor: pin S to the next one which is library cache: mutex or mutex bucket etc...
Good thing in this test we observed is, with 1 cpu our test lasted for 7mins vs the 4 cpu it lasted for 3 to 4mins.
So the cpu addition is the real game changer on this situation.


Thank you for visiting the blog.




at
Labels: , , , ,

No comments:

Post a Comment

Subscribe to: Post Comments (Atom)

Troubleshooting the “Cannot Generate SSPI Context” Error After SQL Server Migration

  Introduction After a recent  SQL Server migration from 2012 to 2022 , our team encountered a classic authentication issue: The target prin...