Home » RDBMS Server » Performance Tuning » Very Similar Queries, Very Different Elapsed Times
Very Similar Queries, Very Different Elapsed Times [message #143034] Tue, 18 October 2005 18:32 Go to next message
scottwmackey
Messages: 515
Registered: March 2005
Senior Member
This post is similar to the one I recently posted on elapsed time. It maybe should be in the same thread but I will start a new one anyway. I apologize in advance if I should not have done so.

I have included below three queries that are literally back to back to back in a .sql file that I ran with set termout off. I have posted them exactly as they appear in the TKPROF, including the order. I did not provide a sort parameter to TKPROF. My question has to do with elapsed time. The first and third queries take 3 and 1 seconds, respectively. The second, however, took 20 seconds, even though it returned the fewest number of rows. The queries are essentially identical. They both do a full table scan as expected. (That is not my problem, so please no suggestions about adding indexes.) Disk read differences are trivial. The functions in the select clauses do not hit the database. They are basically varchar to date and varchar to number conversions. Moreover, when I re-ran the second query, it finished in about 2.5 seconds. Nobody has access to my schema, so it's definitely not a locking issue. It makes perfect sense to me that the box on which I am working my have been hit hard by some other process (not on my schema or maybe not even in Oracle) which delayed its ability to process my query at that particular time. But my question is, Does the trace facility factor out generic box business when getting its statistics, or will identical boxes with identical schemas give very different elapsed times for identical queries depending on how busy the box is with completely unrelated activity? Or is there something else that I am not seeing that could account for the 20 second elapsed time?
********************************************************************************

  SELECT sub.*,
         CASE
           WHEN to_char(sub.bond_call_dt, 'YYYYMM') =
                to_char(nvl(sub.maturity_dt, sub.first_coupon_dt), 'YYYYMM') THEN
            1
           ELSE
            0
         END is_event_cpn_day
  FROM   (SELECT td.*,
                 fb_proc.get_date(td.next_par_call_dt) bond_call_dt,
                 fb_proc.get_price(td.expnd_frst_call_strk_pr, td.frst_call_strk_pr, 'ISC'/*p_src_format_cd*/, NULL) bond_call_price,
                 fb_proc.get_date(td.fi_cou_dt_pay_dt) first_coupon_dt
          FROM   tmp_fb_prs_desc td
          WHERE  td.instr_discrim_cd IN ('FI', 'AB')) sub
  WHERE  sub.bond_call_dt IS NOT NULL

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.05       0.04          0        260          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      547      2.99       2.90      11829      14376          0        8176
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      549      3.04       2.94      11829      14636          0        8176

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 103

Rows     Row Source Operation
-------  ---------------------------------------------------
   8176  TABLE ACCESS FULL TMP_FB_PRS_DESC


********************************************************************************

  SELECT sub.*,
         CASE
           WHEN to_char(sub.td_put_dt, 'YYYYMM') =
                to_char(nvl(sub.maturity_dt, fb_proc.get_date(sub.fi_cou_dt_pay_dt)), 'YYYYMM') THEN
            1
           ELSE
            0
         END is_event_cpn_day
  FROM   (SELECT td.*,
                 fb_proc.get_price(td.expnd_put_price, td.put_price, 'ISC'/*p_src_format_cd*/, td.instr_discrim_cd) td_put_price,
                 fb_proc.get_date(td.put_dt) td_put_dt
          FROM   tmp_fb_prs_desc td
          WHERE  td.instr_discrim_cd IN ('FI', 'AB')) sub
  WHERE  sub.td_put_dt IS NOT NULL

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.03       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       15      0.92      20.03      11828      13854          0         196
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       17      0.95      20.06      11828      13854          0         196

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 103

Rows     Row Source Operation
-------  ---------------------------------------------------
    196  TABLE ACCESS FULL TMP_FB_PRS_DESC


********************************************************************************

  SELECT sub.*,
         CASE
           WHEN to_char(sub.second_pre_call_dt, 'YYYYMM') =
                to_char(nvl(sub.maturity_dt, fb_proc.get_date(sub.fi_cou_dt_pay_dt)), 'YYYYMM') THEN
            1
           ELSE
            0
         END is_event_cpn_day
  FROM   (SELECT td.*,
                 fb_proc.get_price(td.expnd_scnd_pre_call_pr,
                                   td.scnd_pre_call_pr,
                                   'ISC'/*p_src_format_cd*/,
                                   td.instr_discrim_cd) second_pre_call_price,
                 fb_proc.get_date(td.scnd_pre_call_dt) second_pre_call_dt
          FROM   tmp_fb_prs_desc td
          WHERE  td.instr_discrim_cd IN ('FI', 'AB')) sub
  WHERE  sub.second_pre_call_dt IS NOT NULL

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.03       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       42      1.05       1.06       9133      13881          0         615
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       44      1.08       1.08       9133      13881          0         615

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 103

Rows     Row Source Operation
-------  ---------------------------------------------------
    615  TABLE ACCESS FULL TMP_FB_PRS_DESC

********************************************************************************

Re: Very Similar Queries, Very Different Elapsed Times [message #143043 is a reply to message #143034] Tue, 18 October 2005 21:24 Go to previous message
Art Metzer
Messages: 2480
Registered: December 2002
Senior Member
Scott,

Nothing jumps out at me. You need some insight into what it is that you're waiting for. I would highly recommend this free extended SQL trace resource profiler to find out which resource is your bottleneck for this particular query. Note, it requires running your raw extended SQL trace file through a Perl routine, but the output (sample) is well worth it, especially when you compare your laggard example to your performant queries.

This piece of code is similar to the extended SQL trace resource profiler espoused by Millsap and Holt in their book Optimizing Oracle Performance.

Hope this helps.
Previous Topic: bind variable peeking and collecting statistics
Next Topic: Interpreting TKPROF for Complex Inserts/Updates
Goto Forum:
  


Current Time: Wed Nov 27 09:58:59 CST 2024