Hi experts,
There is a DB link between 2 database e.g. DBS1 and DBS2. Databases are on different servers.
DBS1 is not in maintained by me. I am maintaining DBS2 Oracle 11g.
The team from DBS1 is complaining that some times their query move into wait stage. Due to this their procedure stuck into mid of execution. According to them there is a problem with my database i.e. DBS2 and listener. DBS1 team has shared me a TKPROF generated file. I am attaching it for reference
I checked all the logs on to my server but there is no such type of problem. I am unable to understand where is the problem. Help me to find out what is the exact problem and how can i solve the issue because DBS1 team is blaming that there is a problem with my database i.e. DBS2.
Sorry I did not find attachment option so i am pasting TKPROF content here
#####################################################################################
TKPROF: Release 11.2.0.3.0 - Development on Sat May 27 08:58:37 2017
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: PROD1_ora_5178072_MHMPRD_CR327011032.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
SQL ID: 2xvvm81avq7q1 Plan Hash: 0
alter session set events='10046 trace name context forever, level 8'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Parsing user id: 173 (APPS) (recursive depth: 1)
********************************************************************************
SQL ID: 2bg73wmjuzhgz Plan Hash: 0
begin fnd_conc_stat.store_initial; end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.05 0.24 40 345 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.05 0.24 40 345 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173 (APPS)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 0.00 0.00
********************************************************************************
SQL ID: 0wmwsjy9kd92f Plan Hash: 1374985481
SELECT PROFILE_OPTION_ID, APPLICATION_ID, SITE_ENABLED_FLAG ,
APP_ENABLED_FLAG , RESP_ENABLED_FLAG , USER_ENABLED_FLAG, ORG_ENABLED_FLAG ,
SERVER_ENABLED_FLAG, SERVERRESP_ENABLED_FLAG, HIERARCHY_TYPE,
USER_CHANGEABLE_FLAG
FROM
FND_PROFILE_OPTIONS WHERE PROFILE_OPTION_NAME = :B1 AND START_DATE_ACTIVE <=
SYSDATE AND NVL(END_DATE_ACTIVE, SYSDATE) >= SYSDATE
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 6 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 6 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173 (APPS) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'FND_PROFILE_OPTIONS' (TABLE)
0 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'FND_PROFILE_OPTIONS_U2' (INDEX (UNIQUE))
********************************************************************************
SQL ID: 7qs7fx89194u1 Plan Hash: 2802907561
SELECT PROFILE_OPTION_VALUE
FROM
FND_PROFILE_OPTION_VALUES WHERE PROFILE_OPTION_ID = :B4 AND APPLICATION_ID =
:B3 AND LEVEL_ID = :B2 AND LEVEL_VALUE = :B1 AND PROFILE_OPTION_VALUE IS
NOT NULL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 6 0.00 0.00 0 0 0 0
Fetch 6 0.00 0.00 0 12 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 0.00 0.00 0 12 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173 (APPS) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'FND_PROFILE_OPTION_VALUES' (TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF
'FND_PROFILE_OPTION_VALUES_U1' (INDEX (UNIQUE))
********************************************************************************
SQL ID: 55dc767ajydh3 Plan Hash: 2802907561
SELECT PROFILE_OPTION_VALUE
FROM
FND_PROFILE_OPTION_VALUES WHERE PROFILE_OPTION_ID = :B4 AND APPLICATION_ID =
:B3 AND LEVEL_ID = 10003 AND LEVEL_VALUE = :B2 AND
LEVEL_VALUE_APPLICATION_ID = :B1 AND PROFILE_OPTION_VALUE IS NOT NULL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 4 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173 (APPS) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'FND_PROFILE_OPTION_VALUES' (TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF
'FND_PROFILE_OPTION_VALUES_U1' (INDEX (UNIQUE))
********************************************************************************
SQL ID: 5ftc07zks7arg Plan Hash: 0
BEGIN apps.xxom_icm_sow_iface(:errbuf,:rc,:A0); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173 (APPS)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 0.02 0.02
********************************************************************************
SQL ID: 7ng34ruy5awxq Plan Hash: 3984801583
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,
i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,
i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,
nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),
i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),
nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,
null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,
ist.logicalread
from
ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,
min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4)))
valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where
i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 6 0.00 0.01 12 21 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.00 0.01 12 21 0 4
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
3 3 3 SORT ORDER BY (cr=9 pr=6 pw=0 time=5141 us cost=8 size=378 card=2)
3 3 3 HASH JOIN OUTER (cr=9 pr=6 pw=0 time=5006 us cost=7 size=378 card=2)
3 3 3 NESTED LOOPS OUTER (cr=6 pr=4 pw=0 time=3818 us cost=3 size=292 card=2)
3 3 3 TABLE ACCESS CLUSTER IND$ (cr=5 pr=4 pw=0 time=3792 us cost=3 size=188 card=2)
1 1 1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=1 pw=0 time=700 us cost=1 size=0 card=1)(object id 3)
0 0 0 TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=1 pr=0 pw=0 time=14 us cost=0 size=52 card=1)
0 0 0 INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=1 pr=0 pw=0 time=10 us cost=0 size=0 card=1)(object id 7095049)
0 0 0 VIEW (cr=3 pr=2 pw=0 time=1120 us cost=3 size=258 card=6)
0 0 0 SORT GROUP BY (cr=3 pr=2 pw=0 time=1118 us cost=3 size=96 card=6)
0 0 0 TABLE ACCESS CLUSTER CDEF$ (cr=3 pr=2 pw=0 time=1084 us cost=2 size=96 card=6)
1 1 1 INDEX UNIQUE SCAN I_COBJ# (cr=2 pr=1 pw=0 time=509 us cost=1 size=0 card=1)(object id 27)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
library cache lock 2 0.00 0.00
library cache pin 2 0.00 0.00
db file sequential read 12 0.00 0.00
gc cr grant 2-way 6 0.00 0.00
********************************************************************************
SQL ID: 5n1fs4m2n2y0r Plan Hash: 992489688
select pos#,intcol#,col#,spare1,bo#,spare2,spare3
from
icol$ where obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 9 0.00 0.00 1 18 0 5
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 0.00 0.00 1 18 0 5
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
2 2 2 TABLE ACCESS BY INDEX ROWID ICOL$ (cr=6 pr=1 pw=0 time=624 us cost=2 size=58 card=2)
2 2 2 INDEX RANGE SCAN I_ICOL1 (cr=4 pr=1 pw=0 time=624 us cost=1 size=0 card=2)(object id 37)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
********************************************************************************
SQL ID: 53saa2zkr6wc3 Plan Hash: 2631433895
select intcol#,nvl(pos#,0),col#,nvl(spare1,0)
from
ccol$ where con#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 15 0.00 0.00 0 0 0 0
Fetch 30 0.00 0.00 1 75 0 15
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 46 0.00 0.00 1 75 0 15
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS BY INDEX ROWID CCOL$ (cr=5 pr=1 pw=0 time=847 us cost=4 size=18 card=1)
1 1 1 INDEX RANGE SCAN I_CCOL1 (cr=4 pr=1 pw=0 time=795 us cost=3 size=0 card=1)(object id 51)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
********************************************************************************
SQL ID: fncu0crv33dk5 Plan Hash: 1111874337
SELECT TO_NUMBER(B.DESCRIPTION)
FROM
TMS_LOOKUP_TYPES A,TMS_LOOKUP_MASTER B WHERE A.LOOKUP_TYPE = 'MHM_SOW_ICM'
AND A.LOOKUP_TYPE = B.LOOKUP_TYPE AND ROWNUM=1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 3 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.02 3 4 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 173 (APPS) (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 COUNT STOPKEY (cr=4 pr=3 pw=0 time=3047 us)
1 1 1 NESTED LOOPS (cr=4 pr=3 pw=0 time=3035 us cost=2 size=106 card=2)
1 1 1 INDEX UNIQUE SCAN TMS_LOOKUP_TYPES_U1 (cr=1 pr=0 pw=0 time=11 us cost=0 size=16 card=1)(object id 208678)
1 1 1 TABLE ACCESS BY INDEX ROWID TMS_LOOKUP_MASTER (cr=3 pr=3 pw=0 time=3020 us cost=2 size=74 card=2)
1 1 1 INDEX RANGE SCAN TMS_LOOKUP_MASTER_N1 (cr=2 pr=2 pw=0 time=2456 us cost=1 size=0 card=2)(object id 208681)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
1 COUNT (STOPKEY)
1 NESTED LOOPS
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF
'TMS_LOOKUP_TYPES_U1' (INDEX (UNIQUE))
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'TMS_LOOKUP_MASTER' (TABLE)
1 INDEX MODE: ANALYZED (RANGE SCAN) OF
'TMS_LOOKUP_MASTER_N1' (INDEX)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
library cache lock 3 0.00 0.00
library cache pin 3 0.00 0.00
Disk file operations I/O 2 0.00 0.00
db file sequential read 3 0.00 0.00
gc cr grant 2-way 1 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.05 0.24 40 345 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.05 0.24 40 345 0 2
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 5 0.02 0.02
library cache lock 5 0.00 0.00
library cache pin 5 0.00 0.00
cursor: pin S 39 663.06 25781.54
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 5 0.00 0.02 0 0 0 0
Execute 33 0.00 0.00 0 0 0 0
Fetch 56 0.00 0.01 17 140 0 27
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 94 0.01 0.04 17 140 0 27
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 21 0.00 0.01
gc cr grant 2-way 8 0.00 0.00
Disk file operations I/O 2 0.00 0.00
7 user SQL statements in session.
3 internal SQL statements in session.
10 SQL statements in session.
4 statements EXPLAINed in this session.
********************************************************************************
Trace file: PROD1_ora_5178072_MHMPRD_CR327011032.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
7 user SQL statements in trace file.
3 internal SQL statements in trace file.
10 SQL statements in trace file.
10 unique SQL statements in trace file.
4 SQL statements EXPLAINed using schema:
APPS.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
436 lines in trace file.
0 elapsed seconds in trace file.
#####################################################################################
Thanks and regards,
Pardeep