NOW they’re fixed…
A few of our test EBS instances had developed a well-deserved reputation of taking a long time to start up. Here’s what we saw:
- Database ground to a near-halt shortly after running adstrtal.sh
- Most concurrent manager processes were being marked as “dead” in the internal manager log not long after startup, and the internal manager attempted to restart them.
- Consequence of #2: Three to four times as many FNDLIBR processes running on the app tier server as expected.
- Consequence of #2 and #3: The “Active sessions” graph in Grid Control resembled Mt. Kilimanjaro, and all three database server load average numbers (1, 5, and 15-minute) on were over 100.
Needless to say, neither users (who could not connect to the test instance), developers (who could not connect to the Apps database), nor DBAs (who had to answer endless “when will the instance be up?” emails) were very happy.
The culprit? This little query, executed for each FNDLIBR process as it started up, generating a ridiculous number of “control file sequential read” waits along the way:
SELECT count(*) FROM v$thread;
When I took a closer look at the query, this is what I found:
SQL> select /*+ gather_plan_statistics */ count(*)
2 from v$thread;
COUNT(*)
----------
2
Elapsed: 00:00:11.17
SQL> select *
2 from table(DBMS_XPLAN.DISPLAY_CURSOR(NULL, NULL, 'ALLSTATS LAST'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
SQL_ID 057v054v2svhp, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from v$thread
Plan hash value: 3150894624
------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | OMem | 1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:11.16 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:11.16 | | | |
| 2 | NESTED LOOPS | | 1 | 1 | 2 |00:00:00.37 | | | |
| 3 | MERGE JOIN CARTESIAN | | 1 | 1 | 3969 |00:00:00.17 | | | |
|* 4 | FIXED TABLE FULL | X$KCCTIR | 1 | 1 | 63 |00:00:00.09 | | | |
| 5 | BUFFER SORT | | 63 | 1 | 3969 |00:00:00.08 | 73728 | 73728 | |
| 6 | FIXED TABLE FULL | X$KCCCP | 1 | 1 | 63 |00:00:00.05 | | | |
|* 7 | FIXED TABLE FIXED INDEX| X$KCCRT (ind:1) | 3969 | 1 | 2 |00:00:11.00 | | | |
------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
4 - filter("TR"."INST_ID"=USERENV('INSTANCE'))
7 - filter(("RT"."INST_ID"=USERENV('INSTANCE') AND "RTNLF"<>0 AND "TIRNUM"="RTNUM" AND "CPTNO"="RTNUM"))
That’s a lot of work to do for 2 rows. Clearly the internal manager was expecting a faster start time from its children, which explains why it kept attempting to start new ones. Repeatedly. Until we had over 200 FNDLIBR processes running instead of our expected 80-ish.
After gathering fixed object statistics, the query behaved a bit better, and we therefore expect that our “slow to awaken” instance should be a bit more speedy:
SQL> exec dbms_stats.gather_fixed_objects_stats
PL/SQL procedure successfully completed.
Elapsed: 00:03:11.45
SQL> select /*+ gather_plan_statistics */ count(*) from v$thread
2 ;
COUNT(*)
----------
2
Elapsed: 00:00:00.03
SQL> select *
2 from table(DBMS_XPLAN.DISPLAY_CURSOR(NULL, NULL, 'ALLSTATS LAST'));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
SQL_ID f1pmbmcstp1rj, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from v$thread
Plan hash value: 93051267
-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time |
-----------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.02 |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.02 |
| 2 | NESTED LOOPS | | 1 | 2 | 2 |00:00:00.02 |
| 3 | NESTED LOOPS | | 1 | 2 | 2 |00:00:00.01 |
| 4 | FIXED TABLE FULL | X$KCCRT | 1 | 2 | 2 |00:00:00.01 |
| 5 | FIXED TABLE FIXED INDEX| X$KCCCP (ind:1) | 2 | 1 | 2 |00:00:00.01 |
| 6 | FIXED TABLE FIXED INDEX | X$KCCTIR (ind:1) | 2 | 1 | 2 |00:00:00.02 |
-----------------------------------------------------------------------------------------------
Here are some one-liners from my notebook (anything that looks like an opinion is my commentary/interpretation, not Caleb's):
