We recently completed a few e eBS R12.2 database upgrade installations and noticed an issue with a particular SQL running as part of the AutoConfig.
The query sql_id is 5da8tjzfafw6j and it looks like this (formatted):
select uo.object_name, aa.object_name procedure_name, aa.ARGUMENT_NAME from user_objects uo, user_arguments aa where uo.object_name = 'FND_GSM_UTIL' and aa.object_id = uo.object_id and aa.object_name = 'UPLOAD_CONTEXT_FILE' and object_type = 'PACKAGE' order by 1,2,3
The query returns arguments for the FND_GSM_UTIL.UPLOAD_CONTEXT_FILE procedure.
It’s obviously a suboptimal code: the AutoConfig should just run the procedure it needs to run and handle exceptions in case of missing procedure.
Query execution time is up to 20 minutes, which is considerably higher than the normal AutoConfig runs prior to DB upgrade.
Here’s what the SQL Monitor report looks like:
Global Stats ================================================================= | Elapsed | Cpu | IO | Fetch | Buffer | Read | Read | | Time(s) | Time(s) | Waits(s) | Calls | Gets | Reqs | Bytes | ================================================================= | 999 | 24 | 976 | 1 | 402K | 95653 | 1GB | ================================================================= Parallel Execution Details (DOP=2 , Servers Allocated=4) ============================================================================================================================ | Name | Type | Server# | Elapsed | Cpu | IO | Buffer | Read | Read | Wait Events | | | | | Time(s) | Time(s) | Waits(s) | Gets | Reqs | Bytes | (sample #) | ============================================================================================================================ | PX Coordinator | QC | | 0.15 | 0.06 | 0.09 | 24 | 8 | 65536 | | | p000 | Set 1 | 1 | 0.06 | 0.06 | | | | . | | | p001 | Set 1 | 2 | 0.06 | 0.06 | | | | . | | | p002 | Set 2 | 1 | 0.06 | 0.06 | | | | . | | | p003 | Set 2 | 2 | 999 | 23 | 976 | 402K | 95645 | 1GB | log buffer space (1) | | | | | | | | | | | db file parallel read (534) | | | | | | | | | | | db file scattered read (2) | | | | | | | | | | | db file sequential read (408) | ============================================================================================================================ ============================================================================================================================================================================ | Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Mem | Activity | | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | (Max) | (%) ============================================================================================================================================================================ | 0 | SELECT STATEMENT | | | | 1 | +993 | 5 | 5 | | | . | | 1 | PX COORDINATOR | | | | 1 | +993 | 5 | 5 | | | . | | 2 | PX SEND QC (ORDER) | :TQ10003 | 2 | 22 | 1 | +993 | 2 | 5 | | | . | | 3 | SORT ORDER BY | | 2 | 22 | 1 | +993 | 2 | 5 | | | 4096 | | 4 | PX RECEIVE | | 2 | 21 | 1 | +993 | 2 | 5 | | | . | | 5 | PX SEND RANGE | :TQ10002 | 2 | 21 | 1 | +993 | 2 | 5 | | | . | | 6 | HASH JOIN BUFFERED | | 2 | 21 | 992 | +2 | 2 | 5 | | | 2MB | | 7 | BUFFER SORT | | | | 992 | +2 | 2 | 2 | | | 4096 | | 8 | PX RECEIVE | | 2 | 18 | 992 | +2 | 2 | 2 | | | . | | 9 | PX SEND HYBRID HASH | :TQ10000 | 2 | 18 | 1 | +993 | 1 | 2 | | | . | | 10 | STATISTICS COLLECTOR | | | | 1 | +993 | 1 | 1 | | | . | | 11 | VIEW | USER_OBJECTS | 2 | 18 | 1 | +993 | 1 | 1 | | | . | ... | 44 | PX RECEIVE | | 2 | 3 | | | 2 | | | | . | | 45 | PX SEND HYBRID HASH | :TQ10001 | 2 | 3 | 1 | +993 | 2 | 0 | | | . | | 46 | PX PARTITION LIST ALL | | 2 | 3 | 1 | +993 | 2 | 5 | | | . | | 47 | EXTENDED DATA LINK FULL | INT$DBA_ARGUMENTS | 2 | 3 | 992 | +2 | 2 | 5 | | | . | ===========================================================================================================================================================================
I’ve intentionally removed a few lines from the plan for better readability.
We can see that the query is running in parallel with degree of parallelism equal to 2. The query allocates four slaves to complete a hash join between user_objects and user_arguments, and most time is spent accessing INT$DBA_ARGUMENTS.
This INT$ extended data link view is something I haven’t seen before. As I understand, this view acts like a GV$ view, except it runs something against all containers.
Checking SQL that the PX slaves are running:
SQL> select p.spid, p.pname, sql_id from v$session s, v$process p where s.status='ACTIVE' and s.username='APPS' and s.paddr=p.addr; SPID PNAME SQL_ID ------------------------ ----- ------------- 47661 P000 5da8tjzfafw6j 47663 P001 5da8tjzfafw6j 47673 P002 5da8tjzfafw6j 47678 P003 5da8tjzfafw6j 56976 5da8tjzfafw6j
But if we go and check the running SQL of the P003 via oradebug, it looks different:
SQL> oradebug setospid 47678 Oracle pid: 81, Unix process pid: 47678, image: [email protected] (P003) SQL> oradebug dump errorstack 3 Statement processed. SQL> oradebug tracefile_name /u01/app/oracle/diag/rdbms/cdb/CDB/trace/CDB_p003_47678.trc
This is the query sql_id=ctvujtx8491t7 run by P003 (formatted):
SELECT /*+ NO_STATEMENT_QUEUING RESULT_CACHE (SYSOBJ=TRUE) OPT_PARAM('_ENABLE_VIEW_PDB', 'FALSE') */
"OWNER",
"OBJECT_NAME",
"OBJECT_ID",
"ARGUMENT_NAME"
FROM
NO_CROSS_CONTAINER("SYS"."INT$DBA_ARGUMENTS") "INT$DBA_ARGUMENTS"
WHERE
"INT$DBA_ARGUMENTS"."OBJECT_NAME"='UPLOAD_CONTEXT_FILE' AND
"INT$DBA_ARGUMENTS"."OWNER"=q'"APPS"'
The query is produced by the extended data link view, and runs in a PDB.
In fact, this query runs long and is the cause of the slow INT$DBA_ARGUMENTS view access.
Here’s the plan for sql_id=ctvujtx8491t7 when I run it manually with runtime statistics gathering enabled:
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 5 |00:19:52.76 | 392K| 33448 | | | |
| 1 | RESULT CACHE | 6z4f6jmj63bxh4w12xbkc9yzyb | 1 | | 5 |00:19:52.76 | 392K| 33448 | 65536 | 1024 | |
|* 2 | FILTER | | 1 | | 5 |00:19:52.76 | 392K| 33448 | | | |
| 3 | NESTED LOOPS | | 1 | 285 | 5 |00:19:52.76 | 392K| 33448 | | | |
| 4 | NESTED LOOPS | | 1 | 28518 | 6488K|00:06:57.84 | 170K| 11027 | | | |
|* 5 | HASH JOIN | | 1 | 194 | 85018 |00:00:00.91 | 3284 | 0 | 9307K| 2811K| 9598K (0)|
| 6 | NESTED LOOPS | | 1 | 194 | 85018 |00:00:00.45 | 3279 | 0 | | | |
| 7 | TABLE ACCESS BY INDEX ROWID | USER$ | 1 | 1 | 1 |00:00:00.01 | 3 | 0 | | | |
|* 8 | INDEX UNIQUE SCAN | I_USER1 | 1 | 1 | 1 |00:00:00.01 | 2 | 0 | | | |
| 9 | TABLE ACCESS BY INDEX ROWID BATCHED| OBJ$ | 1 | 194 | 85018 |00:00:00.30 | 3276 | 0 | | | |
|* 10 | INDEX RANGE SCAN | I_OBJ5 | 1 | 194 | 85018 |00:00:00.12 | 1016 | 0 | | | |
| 11 | INDEX FULL SCAN | I_USER2 | 1 | 577 | 577 |00:00:00.01 | 5 | 0 | | | |
|* 12 | INDEX RANGE SCAN | I_ARGUMENT2 | 85018 | 147 | 6488K|00:06:43.03 | 167K| 11027 | | | |
|* 13 | TABLE ACCESS BY INDEX ROWID | ARGUMENT$ | 6488K| 1 | 5 |00:12:34.33 | 222K| 22421 | | | |
|* 14 | TABLE ACCESS BY INDEX ROWID BATCHED | USER_EDITIONING$ | 1 | 1 | 1 |00:00:00.01 | 4 | 0 | | | |
|* 15 | INDEX RANGE SCAN | I_USER_EDITIONING | 1 | 12 | 7 |00:00:00.01 | 2 | 0 | | | |
|* 16 | TABLE ACCESS BY INDEX ROWID BATCHED | USER_EDITIONING$ | 1 | 1 | 1 |00:00:00.01 | 4 | 0 | | | |
|* 17 | INDEX RANGE SCAN | I_USER_EDITIONING | 1 | 12 | 7 |00:00:00.01 | 2 | 0 | | | |
| 18 | NESTED LOOPS SEMI | | 0 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 19 | INDEX RANGE SCAN | I_OBJ4 | 0 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 20 | INDEX RANGE SCAN | I_USER2 | 0 | 192 | 0 |00:00:00.01 | 0 | 0 | | | |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter((BITAND("O"."FLAGS",1048576)=1048576 OR BITAND("U"."SPARE1",16)=0 OR ("O"."TYPE#"<>88 AND IS NULL) OR ( IS NOT NULL AND (("U"."TYPE#"=2 AND
"U"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id'))) OR ("U"."TYPE#"<>2 AND SYS_CONTEXT('userenv','current_edition_name')='ORA$BASE') OR IS
NOT NULL))))
5 - access("O"."OWNER#"="U"."USER#")
8 - access("U"."NAME"='APPS')
10 - access("O"."SPARE3"="U"."USER#")
filter((INTERNAL_FUNCTION("O"."TYPE#") OR ("O"."TYPE#"=13 AND "O"."SUBNAME" IS NULL)))
12 - access("O"."OBJ#"="A"."OBJ#")
13 - filter(NVL("A"."PROCEDURE$","O"."NAME")='UPLOAD_CONTEXT_FILE')
14 - filter("TYPE#"=:B1)
15 - access("UE"."USER#"=:B1)
16 - filter("UE"."TYPE#"=:B1)
17 - access("UE"."USER#"=:B1)
19 - access("O2"."DATAOBJ#"=:B1 AND "O2"."TYPE#"=88)
20 - access("O2"."OWNER#"="U2"."USER#" AND "U2"."TYPE#"=2 AND "U2"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id')))
filter("U2"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id')))
Result Cache Information (identified by operation id):
------------------------------------------------------
1 -
Note
-----
- this is an adaptive plan
Most of the time is spent accessing ARGUMENT$ by the I_ARGUMENT2 index. It runs slowly because the index access returns 6.5M rows, most of which are thrown away after table access. Meaning, all the procedure arguments for APPS users are checked one by one and only rows for UPLOAD_CONTEXT_FILE are sent further up the execution stack after filtering.
SQL like this can’t run fast if the ARGUMENT$ data/index is not cached, which leads to reading of up to ~392K blocks. After data is cached, the query runs in seconds – minimum 3s in my tests.
By the way, the issue like this happens all the time: some suboptimal query runtime depends heavily on how much data is cached, and can run “occasionally” in seconds or minutes.
Is there a way to fix sql_id=5da8tjzfafw6j? Yes there is. Starting with Oracle 19.10 there’s a new parameter CONTAINER_DATA which can be set to CURRENT_DICTIONARY. Such a change makes the original query run instantly, with just 47 gets with the same results:
select /*+ opt_param('CONTAINER_DATA' 'CURRENT_DICTIONARY') */
uo.object_name,
aa.object_name procedure_name,
aa.ARGUMENT_NAME
from
user_objects uo,
user_arguments aa
where
uo.object_name = 'FND_GSM_UTIL' and
aa.object_id = uo.object_id
and aa.object_name = 'UPLOAD_CONTEXT_FILE' and
object_type = 'PACKAGE'
order by 1,2,3
Plan hash value: 1041619941
---------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 5 |00:00:00.01 | 47 | | | |
| 1 | SORT ORDER BY | | 1 | 1 | 5 |00:00:00.01 | 47 | 2048 | 2048 | 2048 (0)|
|* 2 | FILTER | | 1 | | 5 |00:00:00.01 | 47 | | | |
...
I wanted to add this hint as an SQL Patch to fix just this SQL and avoid potential impact for other queries. However, SQL Patch doesn’t work: the plan says that the hint is applied, but the plan shape doesn’t change and it continues to use an extended data link view. This makes me think that CONTAINER_DATA can only be changed on the session/instance level. Since I’m not sure whether it’s supported by eBS or not, it is a bit dangerous to set the parameter instance wide. I have an SR open with Oracle support regarding use of CONTAINER_DATA with eBS – no feedback yet.
Summary
- If you’ve upgraded eBS DB to 19c, you might notice hangs in the AutoConfig pre-steps due to suboptimal SQL.
- You might not notice any issue if your hardware is sufficiently fast to do 100K random IOs in a matter of a few seconds.
- You might also not notice the SQL if most of the data is cached already.
- There is a parameter CONTAINER_DATA that probably can be changed for eBS 19.10+ DB instances to completely avoid running into this issue, but this is not officially supported by Oracle (yet, maybe).
Feel free to share your questions in the comments and subscribe so you don’t miss the next post.
10 Comments. Leave new
Update: I managed to fix the query using fake baselines approach. Not sure what is wrong with SQL Patch; I guess it’s an internal restriction.
Its not working for me. I tried with fake base line. Can you please share your script with example.
Thanks
Hi,
show us what you’ve tried and what didn’t work please?
Following is my hinted sql:
SELECT /*+ OPT_PARAM(‘container_data’ ‘CURRENT_DICTIONARY’) hinted_query */
*
FROM
(
SELECT DISTINCT
aa.package_name,
aa.object_name,
aa.overload,
aa.object_id,
aa.owner
FROM
all_arguments aa
WHERE
aa.object_id IN (
SELECT
object_id
FROM
(
SELECT
*
FROM
all_objects
WHERE
object_type IN ( ‘PACKAGE’, ‘PROCEDURE’ )
AND upper(owner) = ‘APPS’
ORDER BY
object_name
) ao
WHERE
ROWNUM < 102
)
ORDER BY
aa.package_name,
aa.object_name
)
WHERE
ROWNUM ‘8upucxvav4mp2’,
plan_hash_value => 1896454774,
sql_text => m_clob,
fixed => ‘NO’,
enabled => ‘YES’
)
);
end;
/
declare
m_clob clob;
begin
select
sql_fulltext
into
m_clob
from
v$sql
where
sql_id = ‘g7hpw3cqa6ftk’ –original sql id
and child_number = 0
;
dbms_output.put_line(m_clob);
dbms_output.put_line(
dbms_spm.load_plans_from_cursor_cache(
sql_id => ‘8upucxvav4mp2’, –hinted sql id
plan_hash_value => 1896454774, –hinted PLH
sql_text => m_clob,
fixed => ‘NO’,
enabled => ‘YES’
)
);
end;
/
And what was the output from the load_plans_from_cursor_cache call? What didn’t work?
declare
m_clob clob;
begin
select
sql_fulltext
into
m_clob
from
v$sql
where
sql_id = ‘g7hpw3cqa6ftk’–original sql
and child_number = 0
;
dbms_output.put_line(m_clob);
dbms_output.put_line(
dbms_spm.load_plans_from_cursor_cache(
sql_id => ‘8upucxvav4mp2’,–container_data hinted sql
plan_hash_value => 1896454774, –hinted PLH
sql_text => m_clob,
fixed => ‘NO’,
enabled => ‘YES’
)
);
end;
/
The sql is still accessing int$dba_argument and is slow
Slow Dictionary Query on ALL_ARGUMENTS (Doc ID 2707499.1)
based on your SR, Timur, I suppose
Hi Igor,
Thanks, but no, this just explains that there is an issue with ALL_ARGUMENTS and there is a parameter CONTAINER_DATA introduced in 19.10 (with one-offs for previous versions) to workaround the issue.
The parameter helps when added as an OPT_PARTAM hint directly into SQL, or baselined. But not via SQL Patch.