Long running Customer Interface request in production

Posted byIndraneil SealPosted inMongoDB Performance related topics

Back in 2010 when I started my DBA journey, I worked as an offshore Oracle Apps DBA for a top credit-reporting company. We would frequently face performance issues for custom programs. On one such fateful day, a particular customer interface request was stuck . One of our Performance Tuning expert (who was a role model and whom I admire till date) provided the following fix:

Step 1. Enabled level 12 trace on the EBS concurrent request:

a. Identified the oracle_process_id from request_id

SQL> select oracle_process_id from fnd_concurrent_requests where request_id = &request_id;

b. Found the OS process

[oracle@proddb01 ~]$ ps -ef|grep 32705
oracle 6266 24196 0 11:32 pts/9 00:00:00 grep 32705
oracle 32705 1 99 08:56 ? 02:35:39 oracleM1PROD1 (LOCAL=NO)

c. Enable trace:

SQL> oradebug setospid 32705;
SQL> oradebug EVENT 10046 trace name context forever, level 12
SQL> oradebug unlimit
SQL> oradebug tracefile_name

d. Run tkprof

tkprof M1PROD1_ora_32705.trc M1PROD1_ora_32705.txt sort=fchela,exeela,prsela waits=yes sys=no explain=apps/****

e. Disable trace:

SQL> oradebug setospid 32705;
Oracle pid: 310, Unix process pid: 32705, image: oracle@proddb01
SQL> oradebug event 10046 trace name context off;
Statement processed.

Step 2. Reviewed the generated tkprof file & identified the culprit select statement

call count cpu elapsed disk query current rows
——- —— ——– ———- ———- ———- ———- ———-
Parse 1 0.00 0.00 0 0 0 0
Execute 1 8053.34 8622.83 155428 1810173374 9601 2136
Fetch 0 0.00 0.00 0 0 0 0
——- —— ——– ———- ———- ———- ———- ———-
total 2 8053.34 8622.83 155428 1810173374 9601 2136

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 173

Rows Row Source Operation
——- —————————————————
2136 SEQUENCE HZ_DQM_SYNC_INTERFACE_S (cr=1810173186 pr=154938 pw=0 time=29114812788 us)
2136 FILTER (cr=1810173182 pr=154932 pw=0 time=29114714504 us)
2136 TABLE ACCESS BY INDEX ROWID HZ_RELATIONSHIPS (cr=22331 pr=2194 pw=0 time=24830647 us)
6409 NESTED LOOPS (cr=18059 pr=2049 pw=0 time=30969994 us)
2136 NESTED LOOPS (cr=13751 pr=2015 pw=0 time=22119150 us)
2136 NESTED LOOPS SEMI (cr=7331 pr=1445 pw=0 time=18837595 us)
2136 NESTED LOOPS (cr=7330 pr=1445 pw=0 time=18829016 us)
2136 VIEW VW_SQ_1 (cr=5194 pr=0 pw=0 time=55933 us)
2136 SORT GROUP BY (cr=5194 pr=0 pw=0 time=51660 us)
5850 FILTER (cr=5194 pr=0 pw=0 time=27289 us)
5850 NESTED LOOPS SEMI (cr=5194 pr=0 pw=0 time=27284 us)
5850 TABLE ACCESS FULL RA_CONTACT_PHONES_INT_ALL (cr=5193 pr=0 pw=0 time=21343 us)
1 INDEX UNIQUE SCAN MO_GLOB_ORG_ACCESS_TMP_U1 (cr=1 pr=0 pw=0 time=32 us)(object id 244828)
2136 TABLE ACCESS BY USER ROWID RA_CONTACT_PHONES_INT_ALL (cr=2136 pr=1445 pw=0 time=13551448 us)
1 INDEX UNIQUE SCAN MO_GLOB_ORG_ACCESS_TMP_U1 (cr=1 pr=0 pw=0 time=28 us)(object id 244828)
2136 TABLE ACCESS BY INDEX ROWID HZ_CUST_ACCOUNT_ROLES (cr=6420 pr=570 pw=0 time=4660808 us)
2136 INDEX RANGE SCAN HZ_CUST_ACCOUNT_ROLES_N4 (cr=4284 pr=42 pw=0 time=620524 us)(object id 107549)
4272 INDEX RANGE SCAN HZ_RELATIONSHIPS_N3 (cr=4308 pr=34 pw=0 time=84107 us)(object id 239405)
0 NESTED LOOPS (cr=1810150851 pr=152738 pw=0 time=8595995978 us)
445815240 TABLE ACCESS BY INDEX ROWID HZ_DQM_SYNC_INTERFACE (cr=449743125 pr=21065 pw=0 time=2131368253 us)
1014854184 INDEX SKIP SCAN HZ_DQM_SYNC_INTERFACE_N100 (cr=10107098 pr=13291 pw=0 time=1015150096 us)(object id 1084727)
0 TABLE ACCESS BY INDEX ROWID HZ_PARTIES (cr=1360407726 pr=131673 pw=0 time=5689103643 us)
445815240 INDEX UNIQUE SCAN HZ_PARTIES_U1 (cr=891632622 pr=19180 pw=0 time=2694128754 us)(object id 172682)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
—————————————- Waited ———- ————
library cache lock 5 0.00 0.00
gc cr grant 2-way 108224 0.45 52.82

Step 4. Following action plan was tested in a lower environment which was a recent clone of production

a. Created Composite Indexes on HZ_PARTIES(orig_system_reference,party_type,party_id) and HZ_DQM_SYNC_INTERFACE(party_id,staged_flag,record_id).
b. Reorged table HZ_PARTIES (alter table HZ_PARTIES move), rebuilt corresponding indexes & gather statistics on both the tables.
c. DQM interface table were truncated

Step 5. Re-ran the customer Load Interface.

And Voila!! Issue resolved.

Published by Indraneil Seal

I originally hail from Kolkata, India, and I've dedicated a significant portion of my professional journey to both India and the United States before relocating to Canada during the pandemic. I’m a member of MongoDB's esteemed Technical Services team. Before joining this exceptional group, I held the role of Senior Apps DBA at the Government of Ontario. Prior to that, I spent many years honing my technical(DBA/Cloud) and soft skills with TCS, KBACE Technologies(which later got acquired by Cognizant Technology Solutions) and Oracle Corporation. Throughout my career, I was deeply immersed in day-to-day operations and spearheaded significant projects, including the modernization of platforms, Oracle application and database upgrades. In my last stint at the Government of Ontario, I was also responsible for overseeing various automation initiatives including out-of-place patching, automated EBS Application patching. Outside of my professional life, I have a strong passion for reading, blogging, spending quality time with my family, and my feline buddies, Smokey & Louis. I also relish solitary walks and jogging as personal interests. As a proponent of open source technologies, I'm looking forward to sharing my knowledge and expertise as well as contribute as much as possible to the success of the IT fraternity thereby perpetually expanding my skillset.

Leave a comment