Results 1 to 6 of 6
  1. #1
    Join Date
    Sep 2003
    Location
    Delhi, India
    Posts
    2

    Red face Unanswered: sql query timing inconsistancy

    hi folks,

    i have been trying to time various queries being used on our web-appilcation as lately we have noticed some general slowdown throughout the site. The method that i am using is as follows

    1. creating a sql file "a.sql" in following format
    -----------------------------------
    -- query timing
    set termout off
    spool /tmp/queryTiming.lst
    --querying a big table with 12,500+ records and 25 columns
    timing start
    select count(*) from estimate;
    timing stop
    spool off
    set termout on
    -----------------------------------

    2. logging on to sqlplus (did this from various machines on same network and ... oracle itself)
    3. doing @a.sql on sql prompt multiple times.

    ************************************************
    -- Output from my sqlplus
    SQL> timing start
    SQL> select count(*) from estimate;

    COUNT(*)
    ----------
    12586

    SQL> timing stop
    Elapsed: 00:00:00.11
    SQL> timing start
    SQL> select count(*) from estimate;

    COUNT(*)
    ----------
    12586

    SQL> timing stop
    Elapsed: 00:00:00.00
    SQL> timing start
    SQL> select count(*) from estimate;

    COUNT(*)
    ----------
    12586

    SQL> timing stop
    Elapsed: 00:00:00.10
    SQL> timing start
    SQL> select count(*) from estimate;

    COUNT(*)
    ----------
    12586

    SQL> timing stop
    Elapsed: 00:00:00.20
    SQL> timing start
    SQL> select count(*) from estimate;

    COUNT(*)
    ----------
    12586

    SQL> timing stop
    Elapsed: 00:00:00.11
    SQL> timing start
    SQL> select count(*) from estimate;

    COUNT(*)
    ----------
    12586

    SQL> timing stop
    Elapsed: 00:00:00.70
    SQL> timing start
    SQL> select count(*) from estimate;

    COUNT(*)
    ----------
    12586

    SQL> timing stop
    Elapsed: 00:00:00.41
    ************************************************

    Now i see HUGE fluctuations in elapsed times from min of 00:00:00.00(no time at all) to max of 00:00:00.80(approx 800 milli secs), on machines on the network whereas this fluctuation in elapsed timing ranges from min of 00:00:00.00(no time at all) to max of 00:00:01.80(approx 1.800 milli secs) on the oracle box.
    I am not able to understand why first of all i see such variation in timings at all, i used to belive that the first time i execute the query it should have taken max time and then the query time should have decreased, but this does not happen in most cases, i observed random fluctuations.

    Please suggest what may be causing this fluctuation, and why the magnitude of query execution time is more on oracle box itself compared to sqlplus client m/c on network.

    thanks in anticipation... :-)

    Regards

    Abhishek

  2. #2
    Join Date
    Sep 2003
    Location
    The Netherlands
    Posts
    311
    Hi,

    Your ideas about the timing are not correct. You've expected that the first time would be longest and after that uoy don't have to wait no more, since that data resides in the SGA, so it would be available.

    Since you do a count(*) from estimate, Oracle has to do two things:
    retrieve all data from estimate and count all records.
    For retrieving all records Oracle does a full table scan, and full table scan and the datablock retrieved for it are not part of the LRU list, so they will not be 'found' ( it's not totally true, but for now enough)
    Second, Oracle has to do a sort order, which might take some time for allocating memory and stuff like that.
    So after all the differences are not that strange and I think not that long. Better look at SQL statement that are really slow and test with them.

    Good luck.
    Edwin van Hattem
    OCP DBA / System analyst

  3. #3
    Join Date
    Mar 2002
    Location
    Ireland
    Posts
    181
    Hi Abhishek,

    The timing utility on SQLPLUS is not accurate for what you are looking for.

    It is a client tool to measure round trips from client through to server and back again. So although you would expect the client on the box to get the best times it does not always work out that way - it depends on what the server is doing at the time the SQL is ran + etc

    I think I'm right in saying that if you trace the session running the query with timed statistics = true you should be able to get the numbers you are looking for.

    Could someone confirm this? I ain't sure.

    Rgs,
    Breen.

  4. #4
    Join Date
    Sep 2003
    Location
    The Netherlands
    Posts
    311
    For confirmation of the info from breen, this is what oracle says about timed_statistics:

    'If set to TRUE Oracle tries to keep timing information against
    various system statistics. TRUE enables the recording of ELAPSED times
    and CPU times (Some platforms such as Desktop platforms record
    ELAPSED times only)'

    I think that means yes, breen is right.
    Edwin van Hattem
    OCP DBA / System analyst

  5. #5
    Join Date
    Sep 2003
    Location
    Delhi, India
    Posts
    2
    select count(*) from estimate

    is just a example that i have taken to specially to raise the question on the list, while have been firing various live queries in batches and one by one to notice more or less the same time fluctuations. These queries are lot more complicated with nested queries, serveral decodes, order by clauses, etc etc.

    I was testing this whole day on the production server (its night there) with oracle box exclusively being used by me. I am not able to understand why will oracle show me 1.50 sec execution time for a query and in subsequent execution will it show me 2 and sometimes even 3+ sec of execution time. As the web application is doing something similar executing similar queries 300-400 times in a loop to paint a page, the variation in painting this page is 10 secs on a local site (database on low end m/c) while takes 150 secs on production site (database on very high end m/c). was thinking firewall, network to be issue at first but could not corroborate it with the data gathered and now oracle seems to be the curprit.
    Will surely attempt tracing the queries now with timed_statistics=true.

  6. #6
    Join Date
    Nov 2003
    Posts
    1

    got any answers ?

    Abhishek,

    I am seeing similar behaviour in our app. Have you solved this mystery ?

    thx,
    LK.

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •