Slow Query in eBS AutoConfig with DB 19c
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: oracle@dbhost (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.
