Forum Stats

  • 3,769,600 Users
  • 2,252,990 Discussions
  • 7,875,117 Comments

Discussions

SQL details report Duration/DB time

Sekar_BLUE4EVER
Sekar_BLUE4EVER Member Posts: 324 Blue Ribbon
edited Feb 15, 2018 9:18AM in General Database Discussions

Hi , I am looking at a SQL details report for a query and it shows that DUration of query is 10 minutes and DB time is 6.2 seconds . How is this possible , the query is a serial query . Does duration include the inactive time from application as well (SQL*Net message from client)

Shouldnt the duration and DB time be same ? This is the screenshot from the report .Or is the stats not updated as the query is still executing ?

Capture.PNG

Thanks

Best Answer

  • AndrewSayer
    AndrewSayer Member Posts: 12,998 Gold Crown
    edited Feb 15, 2018 9:06AM Accepted Answer
    Sekar_BLUE4EVER wrote:Yes the application is doing single row fetches . So do you mean "Duration" in here actually includes the idle wait time ?

    Yes.

    sql>create table as_smallish_table as select * from all_objects where rownum <=10;

    Table created.

    sql>set timing on

    sql>declare

      2   cursor cMyRows is select /*+monitor*/* from as_smallish_table;

      3   rMyRows cMyRows%rowtype;

      4  begin

      5    open cMyRows;

      6    loop

      7      fetch cMyRows into rMyRows;

      8      exit when cMyRows%notfound;

      9      dbms_lock.sleep(6);

    10    end loop;

    11    close cMyRows;

    12  end;

    13  /

    PL/SQL procedure successfully completed.

    Elapsed: 00:01:02.21

    sql>select sql_id, sql_text from v$sql where sql_text not like '%v$sql%' and lower(sql_text) like '%monitor%smallish%';

    SQL_ID        SQL_TEXT

    _____________ ____________________________________________________________________________________________________

    gb1u7c36k83pu declare  cursor cMyRows is select /*+monitor*/* from as_smallish_table;  rMyRows cMyRows%rowtype; be

                  gin   open cMyRows;   loop     fetch cMyRows into rMyRows;     exit when cMyRows%notfound;     dbms_

                  lock.sleep(6);   end loop;   close cMyRows; end;

    4nk0g6fjuxx8y SELECT /*+monitor*/* FROM AS_SMALLISH_TABLE

    2 rows selected.

    Elapsed: 00:00:00.87

    sql>select dbms_sqltune.report_sql_monitor(sql_id=>'4nk0g6fjuxx8y',type=>'TEXT',report_level=>'all sql_text') from dual;

    DBMS_SQLTUNE.REPORT_SQL_MONITOR(SQL_ID=>'4NK0G6FJUXX8Y',TYPE=>'TEXT',REPORT_LEVEL=>'ALLSQL_TEXT')

    ____________________________________________________________________________________________________________________________________________________________________________

    SQL Monitoring Report

    SQL Text

    ------------------------------

    SELECT /*+monitor*/* FROM AS_SMALLISH_TABLE

    Global Information

    ------------------------------

    Status              :  DONE (ALL ROWS)

    Instance ID         :  1

    Session             :  ANDY (643:3343)

    SQL ID              :  4nk0g6fjuxx8y

    SQL Execution ID    :  16777216

    Execution Started   :  02/15/2018 14:03:00

    First Refresh Time  :  02/15/2018 14:03:00

    Last Refresh Time   :  02/15/2018 14:04:01

    Duration            :  61s

    Module/Action       :  SQL*Plus/-

    Service             :  service

    Program             :  sqlplus.exe

    Fetch Calls         :  11

    Global Stats

    =================================================================

    | Elapsed |    IO    |  Other   | Fetch | Buffer | Read | Read  |

    | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |

    =================================================================

    |    0.01 |     0.01 |     0.01 |    11 |     12 |    2 | 16384 |

    =================================================================

    SQL Plan Monitoring Details (Plan Hash Value=3254025205)

    =====================================================================================================================================================

    | Id |      Operation      |       Name        |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read | Read  | Activity | Activity Detail |

    |    |                     |                   | (Estim) |      | Active(s) | Active |       | (Actual) | Reqs | Bytes |   (%)    |   (# samples)   |

    =====================================================================================================================================================

    |  0 | SELECT STATEMENT    |                   |         |      |        56 |     +0 |     1 |       10 |      |       |          |                 |

    |  1 |   TABLE ACCESS FULL | AS_SMALLISH_TABLE |      10 |    3 |        56 |     +0 |     1 |       10 |    2 | 16384 |          |                 |

    =====================================================================================================================================================

    1 row selected.

Answers

  • BPeaslandDBA
    BPeaslandDBA Member Posts: 4,615 Blue Diamond
    edited Feb 15, 2018 12:13AM

    Check out this article: What is DB Time? Where has it gone? | Oracle FAQ

    Go towards the end...it says:

    DB Time includes IO time, which is not captured in v$sys_time_model and therefore not shown in your AWR or Statspack reports. That is usually the answer to the burning question "where has my DB time gone?"

    Does that help?

    Cheers,

    Brian

  • John Thorton
    John Thorton Member Posts: 14,493 Silver Crown
    edited Feb 15, 2018 12:18AM
    Sekar_BLUE4EVER wrote:Hi , I am looking at a SQL details report for a query and it shows that DUration of query is 10 minutes and DB time is 6.2 seconds . How is this possible , the query is a serial query . Does duration include the inactive time from application as well (SQL*Net message from client)Shouldnt the duration and DB time be same ? This is the screenshot from the report .Or is the stats not updated as the query is still executing ?
    Capture.PNG

    Thanks

    It appears that you suffer from Compulsive Tuning Disorder.

    Post SQL & results that show problem that needs to be solved.

  • Sekar_BLUE4EVER
    Sekar_BLUE4EVER Member Posts: 324 Blue Ribbon
    edited Feb 15, 2018 12:18AM

    But i have seen documentation saying DB time = CPU + IO + Non idle wait time

  • AndrewSayer
    AndrewSayer Member Posts: 12,998 Gold Crown
    edited Feb 15, 2018 2:16AM
    Sekar_BLUE4EVER wrote:Hi , I am looking at a SQL details report for a query and it shows that DUration of query is 10 minutes and DB time is 6.2 seconds . How is this possible , the query is a serial query . Does duration include the inactive time from application as well (SQL*Net message from client)Shouldnt the duration and DB time be same ? This is the screenshot from the report .Or is the stats not updated as the query is still executing ?
    Capture.PNG

    Thanks

    How many fetches has the client done? What is the session currently waiting on?

    I would be very tempted to suggest they fetched only some data from the cursor and left it open and the duration is simply time since the query started executed. That or it’s doing single row fetches and you have tons of rows to fetch (which begs the question why are they being fetched like this? No one is going to read that many rows)

  • Sekar_BLUE4EVER
    Sekar_BLUE4EVER Member Posts: 324 Blue Ribbon
    edited Feb 15, 2018 7:34AM

    Yes the application is doing single row fetches . So do you mean  "Duration" in here actually includes the idle wait time ?

  • AndrewSayer
    AndrewSayer Member Posts: 12,998 Gold Crown
    edited Feb 15, 2018 9:06AM Accepted Answer
    Sekar_BLUE4EVER wrote:Yes the application is doing single row fetches . So do you mean "Duration" in here actually includes the idle wait time ?

    Yes.

    sql>create table as_smallish_table as select * from all_objects where rownum <=10;

    Table created.

    sql>set timing on

    sql>declare

      2   cursor cMyRows is select /*+monitor*/* from as_smallish_table;

      3   rMyRows cMyRows%rowtype;

      4  begin

      5    open cMyRows;

      6    loop

      7      fetch cMyRows into rMyRows;

      8      exit when cMyRows%notfound;

      9      dbms_lock.sleep(6);

    10    end loop;

    11    close cMyRows;

    12  end;

    13  /

    PL/SQL procedure successfully completed.

    Elapsed: 00:01:02.21

    sql>select sql_id, sql_text from v$sql where sql_text not like '%v$sql%' and lower(sql_text) like '%monitor%smallish%';

    SQL_ID        SQL_TEXT

    _____________ ____________________________________________________________________________________________________

    gb1u7c36k83pu declare  cursor cMyRows is select /*+monitor*/* from as_smallish_table;  rMyRows cMyRows%rowtype; be

                  gin   open cMyRows;   loop     fetch cMyRows into rMyRows;     exit when cMyRows%notfound;     dbms_

                  lock.sleep(6);   end loop;   close cMyRows; end;

    4nk0g6fjuxx8y SELECT /*+monitor*/* FROM AS_SMALLISH_TABLE

    2 rows selected.

    Elapsed: 00:00:00.87

    sql>select dbms_sqltune.report_sql_monitor(sql_id=>'4nk0g6fjuxx8y',type=>'TEXT',report_level=>'all sql_text') from dual;

    DBMS_SQLTUNE.REPORT_SQL_MONITOR(SQL_ID=>'4NK0G6FJUXX8Y',TYPE=>'TEXT',REPORT_LEVEL=>'ALLSQL_TEXT')

    ____________________________________________________________________________________________________________________________________________________________________________

    SQL Monitoring Report

    SQL Text

    ------------------------------

    SELECT /*+monitor*/* FROM AS_SMALLISH_TABLE

    Global Information

    ------------------------------

    Status              :  DONE (ALL ROWS)

    Instance ID         :  1

    Session             :  ANDY (643:3343)

    SQL ID              :  4nk0g6fjuxx8y

    SQL Execution ID    :  16777216

    Execution Started   :  02/15/2018 14:03:00

    First Refresh Time  :  02/15/2018 14:03:00

    Last Refresh Time   :  02/15/2018 14:04:01

    Duration            :  61s

    Module/Action       :  SQL*Plus/-

    Service             :  service

    Program             :  sqlplus.exe

    Fetch Calls         :  11

    Global Stats

    =================================================================

    | Elapsed |    IO    |  Other   | Fetch | Buffer | Read | Read  |

    | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |

    =================================================================

    |    0.01 |     0.01 |     0.01 |    11 |     12 |    2 | 16384 |

    =================================================================

    SQL Plan Monitoring Details (Plan Hash Value=3254025205)

    =====================================================================================================================================================

    | Id |      Operation      |       Name        |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read | Read  | Activity | Activity Detail |

    |    |                     |                   | (Estim) |      | Active(s) | Active |       | (Actual) | Reqs | Bytes |   (%)    |   (# samples)   |

    =====================================================================================================================================================

    |  0 | SELECT STATEMENT    |                   |         |      |        56 |     +0 |     1 |       10 |      |       |          |                 |

    |  1 |   TABLE ACCESS FULL | AS_SMALLISH_TABLE |      10 |    3 |        56 |     +0 |     1 |       10 |    2 | 16384 |          |                 |

    =====================================================================================================================================================

    1 row selected.

  • Sekar_BLUE4EVER
    Sekar_BLUE4EVER Member Posts: 324 Blue Ribbon
    edited Feb 15, 2018 9:14AM

    Thank you exactly what I was looking for. So is it safe to assume  the SQL elapsed time in AWR report is "DB time "  for the particular SQL and does not include the user wait time?

  • AndrewSayer
    AndrewSayer Member Posts: 12,998 Gold Crown
    edited Feb 15, 2018 9:18AM
    Sekar_BLUE4EVER wrote:Thank you exactly what I was looking for. So is it safe to assume the SQL elapsed time in AWR report is "DB time " for the particular SQL and does not include the user wait time?

    AWR is unlikely to know the real wall clock time that the user was executing the SQL. I think live monitor is the one exception as it records the end fetch and the starting point (I at least assume that's how it works).

    If your live monitor is saying duration is high but DB time is low, look for sql*net style waits for the session, either lots of them or a few huge ones.

This discussion has been closed.