What got triggered as a human mistake in a cloned instance at a customer environment, caused a new discovery by the onsite senior DBA, Brian Fane

Someone from the customer released a sysadmin custom job that caused the configurator servlet JVMs in Production to get bounced! This was an unexpected situation and while the users sat twiddling their thumbs while the configurator models were pre-loading, Brian started digging into the current executing sql of the DB sessions doing the preloading.

To give an idea of the patch levels, the CZ patchset installed was  11i.CZ.I(2690432) and the FND & ATG patchsets were 11i.FND.H(3262159) and 11i.ATG_PF.H.5(5473858) respectively.

He happened to note that the maximum time seemed to be taken by the following sql:

SELECT  cz_lce_load_specs.lce_header_id,
        cz_lce_texts.lce_text,
        cz_lce_headers.component_id
    FROM apps.cz_lce_load_specs,
         apps.cz_lce_headers,
         apps.cz_lce_texts
   WHERE cz_lce_load_specs.attachment_comp_id = :1
     AND cz_lce_load_specs.net_type = :2
     AND cz_lce_texts.lce_header_id = cz_lce_load_specs.lce_header_id
     AND cz_lce_texts.lce_header_id = cz_lce_headers.lce_header_id
     AND cz_lce_headers.deleted_flag = :3
     AND cz_lce_load_specs.deleted_flag = :4
ORDER BY cz_lce_texts.seq_nbr;

When he ran it a BCV copy of the PROD (which was a replica of PROD as of that morning - daily process), it did ~37,400 gets/execution, and almost all of them were physical reads. Most of this comes from a full table scan on CZ_LCE_LOAD_SPECS, which right around 37,150 blocks. Query time was between 1 and 2 seconds (TOAD doesn't get any more precise when dealing with values > 1 second).

His Solution...

So well, he thought, why not add an index to cz_lce_load_specs that may speed up the query:

CREATE INDEX cz.blf_test ON cz.cz_lce_load_specs
       (attachment_comp_id, net_type, deleted_flag)
       COMPUTE STATISTICS;

This reduced the gets from 37,400 to 20. Execution dropped to ~10 ms.

Some more data points...

Let's try some testing in DEV and see how this index performs in the wild :)

DECLARE
   CURSOR c_driver IS
      SELECT attachment_comp_id, net_type
        FROM apps.cz_lce_load_specs
       WHERE deleted_flag = '0'
         AND ROWNUM < 100;

   counter NUMBER := 0;
   v4 varchar2(10) := '0';
   v1 number;
   v2 varchar2(2000);
   v3 number;
BEGIN
   FOR r_driver IN c_driver LOOP
      BEGIN
          SELECT   cz_lce_load_specs.lce_header_id,
                   cz_lce_texts.lce_text,
                   cz_lce_headers.component_id
            INTO v1, v2, v3
            FROM apps.cz_lce_load_specs,
                 apps.cz_lce_headers,
                 apps.cz_lce_texts
           WHERE cz_lce_load_specs.attachment_comp_id = r_driver.attachment_comp_id
             AND cz_lce_load_specs.net_type = r_driver.net_type
             AND cz_lce_texts.lce_header_id = cz_lce_load_specs.lce_header_id
             AND cz_lce_texts.lce_header_id = cz_lce_headers.lce_header_id
             AND cz_lce_headers.deleted_flag = v4
             AND cz_lce_load_specs.deleted_flag = v4
           ORDER BY cz_lce_texts.seq_nbr;
           EXCEPTION
             WHEN others THEN NULL;
      END;
   END LOOP;
END;
/

Observation data for without the index creation on cz_lce_load_specs:

1) First passive configurator model loading (preloading):

Web response time	Buffer  gets	Disk reads	Executions	Sql time for execution	Buffer gets/ execution
2:14.6	2,403,145	35,551	68	110.45	35,340
2:02.0	2,367,735	0	67	94.66	35,340
2:03.3	2,367,735	0	68	94.7	35,340

2) The models are already preloaded now and they are being launched:

Web response time	Buffer  gets	Disk reads	Executions
0:05.6	0	0	0
0:06.4	0	0	0
0:05.5	0	0	0

3) Launch a configurator model, change an attribute of a selection for an item or sub-item and save the configuration (do not submit an order yet):

Web response time	Buffer  gets	Disk reads	Executions	Sql time for execution	Buffer gets/ execution
0:30.1	600,259	3	17	23.76	35,309
0:05.9	0	0	0
0:04.3	0	0	0

Observation data for WITH the index creation on cz_lce_load_specs:

1) First passive load of the configurator model (preloading):

Web response time	Buffer  gets	Disk reads	Executions	Sql time for execution	Buffer gets/ execution
0:22.7	3,240	3	67	0.03	48
0:23.1	3,141	0	67	0.04	47
0:26.1	3,141	0	67	0.02	47

2) First WebUI launch, after the preloading with the index:

Web response time	Buffer  gets	Disk reads	Executions
0.04.3	0	0	0
0.04.4	0	0	0
0.04.8	0	0	0

3) Launch a configurator model, change an attribute of a selection for an item or sub-item and save the configuration (do not submit an order yet):

Web response time	Buffer  gets	Disk reads	Executions	Sql time for execution	Buffer gets/ execution
0.05.1	209	0	17	0.01	12
0.04.8	0	0	0
0.04.0	0	0	0

Real time benefits..

To illustrate this point better after putting it in production, here is a quick comparision of the preload timings of a some configurator models that were grouped in 2 configurator servlets JVMs:

Before the index:

GROUP29	Max preloading time was 857 secs taken by M91R  Min preloading time was 852 secs taken by M91  Avg preloading time was 0:14:13 ( 853 seconds ) secs/model over a total of 6 models
GROUP30	Max preloading time was 1684 secs taken by TDXSR-CG Min preloading time was 1302 secs taken by TDXSCSEAT Avg preloading time was 0:25:56 ( 1556 seconds ) secs/model over a total of 13 models

After the index:

GROUP29	Max preloading time was 54 secs taken by M91R Min preloading time was 53 secs taken by M91-C Avg preloading time was 0:0:53 ( 53 seconds ) secs/model over a total of 6 models
GROUP30	Max preloading time was 96 secs taken by TDXSC2-CG Min preloading time was 82 secs taken by TDXSR-HD Avg preloading time was 0:1:30 ( 90 seconds ) secs/model over a total of 14 models

Conclusion

Although this index could have been provided by Oracle, it was a lucky discovery to speeden up the preloading time for configurator models. With the new index, it is now possible for the client to bounce anytime and have 10-20 most popular models preloaded in within 2-3 mins, as compared to 10-15 mins before, which is really something.

Interestingly, the same columns got indexes in the 11.5.10 release as seen from http://etrm.oracle.com:



Note: This article is being produced with the explicit permission of Brian Fane, and is aimed at sharing tips in the Oracle world for other people who might be in the same situation.