Thoughts on TM_DELTA_TIME

What are these columns in V$ACTIVE_SESSION_HISTORY – TM_DELTA_TIME, TM_DELTA_CPU_TIME and TM_DELTA_DB_TIME?

What does the doco say?

  • TM_DELTA_TIME – Time interval (in microseconds) over which TM_DELTA_CPU_TIME and TM_DELTA_DB_TIME are accumulated
  • TM_DELTA_CPU_TIME – Amount of time this session spent on CPU over the last TM_DELTA_TIME microseconds
  • TM_DELTA_DB_TIME – Amount of time spent by this session in database calls over the last TM_DELTA_TIME microseconds

Need a reminder on TIME MODEL STATISTICS?

The most important of the time model statistics is DB time.

This statistics represents the total time spent in database calls and is an indicator of the total instance workload.

It is calculated by aggregating the CPU and wait times of all sessions not waiting on idle wait events (non-idle user sessions).

i.e. DB TIME is time spent either actively working or actively waiting

What this effectively means is that TM_DELTA_CPU_TIME and TM_DELTA_DB_TIME have no context without TM_DELTA_TIME.

So when looking at TM_DELTA_CPU_TIME and TM_DELTA_DB_TIME, all other sample times/periods are pretty much irrelevant apart from TM_DELTA_TIME – the latter is the only value that gives context to the other two.

TM_DELTA_DB_TIME is time spent actively working or actively waiting, some of this might be time spent on CPU – TM_DELTA_CPU_TIME – the rest will be time spent actively waiting on some non-idle wait events plus some overheads no doubt.

And TM_DELTA_DB_TIME should never exceed TM_DELTA_TIME, right?

The difference between TM_DELTA_TIME and TM_DELTA_DB_TIME should be idle time.

Sounds like something that might be quite useful particularly to counterbalance some of the pitfalls of looking at sampled data?

How might we investigate this further?

Shall we start with a plsql loop that should do nothing but sit on CPU for a short while?

SQL> select * from v$version;

BANNER
-------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
PL/SQL Release 11.2.0.3.0 - Production
CORE    11.2.0.3.0      Production
TNS for Linux: Version 11.2.0.3.0 - Production
NLSRTL Version 11.2.0.3.0 - Production

SQL> select distinct sid from v$mystat;

       SID
----------
       642

SQL> alter session set plsql_optimize_level = 0;

Session altered.

SQL> set timing on
SQL> DECLARE
  2  BEGIN
  3   FOR i IN 1 .. 1000000000 LOOP
  4     NULL;
  5   END LOOP;
  6  END;
  7  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:16.46
SQL> 

What does ASH say?

SQL> select to_char(sample_time,'HH24:MI:SS')
  2  ,      is_awr_sample
  3  ,      event
  4  ,      session_state
  5  ,      to_char(tm_delta_time) tm_delta_time
  6  ,      to_char(tm_delta_cpu_time) tm_delta_cpu_time
  7  ,      to_char(tm_delta_db_time) tm_delta_db_time
  8  from   v$active_session_history
  9  where  session_id = 642
 10  and    sql_id     = '6b5drmtrvs6vv'
 11  order by sample_id desc;

TO_CHAR( I EVENT                     SESSION TM_DELTA_TIME   TM_DELTA_CPU_TIME TM_DELTA_DB_TIME
-------- - ------------------------- ------- --------------- ----------------- ----------------
14:45:25 N                           ON CPU
14:45:24 N                           ON CPU  2019831         2016694           2019831
14:45:23 N                           ON CPU
14:45:22 N                           ON CPU  2019978         2017693           2019978
14:45:21 N                           ON CPU
14:45:20 N                           ON CPU  2019848         2017694           2019848
14:45:19 N                           ON CPU
14:45:18 Y                           ON CPU
14:45:17 N                           ON CPU  2019934         2017693           2019934
14:45:16 N                           ON CPU
14:45:15 N                           ON CPU  2019803         2017693           2019803
14:45:14 N                           ON CPU
14:45:13 N                           ON CPU  2019925         2017693           2019925
14:45:12 N                           ON CPU
14:45:11 N                           ON CPU  4711327         1921708           1926278
14:45:10 N                           ON CPU  40504273        130979            134479

16 rows selected.

SQL> 

So, in this example, roughly every two seconds I get feedback of what my session was doing for that DELTA TIME period.

Unsurprisingly, given what we were doing, the session mainly spent 100% of it’s time in TM_DELTA_DB_TIME actively working, and TM_DELTA_CPU_TIME is the major component of that.

The difference between CPU_TIME – DB_TIME would be the time spent actively waiting plus some overhead.

If did more waiting on a non-idle wait event – IO for example – our DB_TIME would be similar but the element of CPU_TIME would be smaller, e.g.

SQL> DECLARE
  2  BEGIN
  3   FOR i IN (SELECT * FROM all_source) LOOP
  4     NULL;
  5   END LOOP;
  6  END;
  7  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:37.82

which gives

SQL> select to_char(sample_time,'HH24:MI:SS')
  2  ,      is_awr_sample
  3  ,      event
  4  ,      session_state
  5  ,      to_char(tm_delta_time) tm_delta_time
  6  ,      to_char(tm_delta_cpu_time) tm_delta_cpu_time
  7  ,      to_char(tm_delta_db_time) tm_delta_db_time
  8  from   v$active_session_history
  9  where  session_id = 642
 10  and    sql_id     IN ('2nj4dm3qwmkqh','34y8jhfh5w4q9')
 11  order by sample_id desc;

TO_CHAR( I EVENT                     SESSION TM_DELTA_TIME   TM_DELTA_CPU_TIME TM_DELTA_DB_TIME
-------- - ------------------------- ------- --------------- ----------------- ----------------
15:05:43 N                           ON CPU  2019899         1089835           2019899
15:05:42 Y db file scattered read    WAITING
15:05:41 N db file scattered read    WAITING 2020879         1359793           2020879
15:05:40 N                           ON CPU
15:05:39 N db file scattered read    WAITING 2022891         1487774           2022891
15:05:38 N db file scattered read    WAITING
15:05:37 N db file scattered read    WAITING 2021913         1123828           2021913
15:05:36 N                           ON CPU
15:05:35 N db file scattered read    WAITING 2036914         953856            2036914
15:05:34 N                           ON CPU
15:05:33 N db file scattered read    WAITING 1017936         686895            1017936
15:05:32 Y db file scattered read    WAITING 2039867         897864            2039867
15:05:31 N db file scattered read    WAITING
15:05:30 N db file scattered read    WAITING 1928599         1035843           1928599
15:05:29 N                           ON CPU
15:05:28 N                           ON CPU  2069218         1185819           2069218
15:05:27 N                           ON CPU
15:05:26 N                           ON CPU  2092901         840872            2092901
15:05:25 N                           ON CPU
15:05:24 N db file scattered read    WAITING 1998272         1044841           1998272
15:05:23 N db file scattered read    WAITING
15:05:22 Y db file scattered read    WAITING 2052570         1131828           2052570
15:05:21 N                           ON CPU
15:05:20 N db file scattered read    WAITING 2021863         1411786           2021863
15:05:19 N                           ON CPU
15:05:18 N db file scattered read    WAITING 1674137         797879            1674137
15:05:17 N db file scattered read    WAITING
15:05:16 N                           ON CPU  2350338         270958            2350338
15:05:15 N                           ON CPU
15:05:14 N db file scattered read    WAITING 1944057         165975            1944057
15:05:13 N db file scattered read    WAITING
15:05:12 Y db file scattered read    WAITING 2078929         1194819           2078929
15:05:11 N db file scattered read    WAITING
15:05:10 N                           ON CPU  2052015         1266807           2052015
15:05:09 N                           ON CPU
15:05:08 N db file scattered read    WAITING 985873021       915860            1846906
15:05:07 N                           ON CPU
15:05:06 N                           ON CPU  6746807         836873            843056

82 rows selected.

SQL> 

As expected, we see from TM_DELTA_DB_TIME that we are mainly spending 100% of our time actively working or actively waiting.

But, because we’ve had to do some IO, the proportion of that time which is CPU has reduced and the difference between TM_DELTA_DB_TIME and TM_DELTA_CPU_TIME should be roughly the time spent actively waiting during that TM_DELTA_TIME.

But in this output immediately above, do we start to see some of the limitations in this data?

What about this?

TO_CHAR( I EVENT                     SESSION TM_DELTA_TIME   TM_DELTA_CPU_TIME TM_DELTA_DB_TIME
-------- - ------------------------- ------- --------------- ----------------- ----------------
15:05:08 N db file scattered read    WAITING 985873021       915860            1846906

Why the big TM_DELTA_TIME all of a sudden? What’s that all about?

I’ve no idea and if anyone does then please comment.

I would presume that it’s a bug in the accounting.

And if it is a bug, it seriously limits the usefulness of this data for now and the ability to build diagnostic scripts on top of it.

So, moving quickly to how this data is stored down into the repository – DBA_HIST_ACTIVE_SESS_HISTORY.

You probably already know that every 10th second’s worth of the ASH buffer is marked for storage in the repository, as marked by V$ACTIVE_SESSION_HISTORY.IS_AWR_SAMPLE (included in the output above).

From the last buffer output above executing the loop of cpu+io workload, it should be these rows:

TO_CHAR( I EVENT                     SESSION TM_DELTA_TIME   TM_DELTA_CPU_TIME TM_DELTA_DB_TIME
-------- - ------------------------- ------- --------------- ----------------- ----------------
15:05:42 Y db file scattered read    WAITING
15:05:32 Y db file scattered read    WAITING 2039867         897864            2039867
15:05:22 Y db file scattered read    WAITING 2052570         1131828           2052570
15:05:12 Y db file scattered read    WAITING 2078929         1194819           2078929

My initial thoughts were to wonder whether these TM_DELTA figures are persisted “as is”.
In which case, their value would be seriously limited.

Don’t want to wait for the flushing of ASH buffer to the repository?
We can force the flush by creating an AWR snapshot.

SQL> exec dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

SQL> 

And wham, bam, we can check out what has actually been persisted to DBA_HIST_ACTIVE_SESSION_HISTORY:

SQL> select to_char(sample_time,'HH24:MI:SS')
  2  ,      event
  3  ,      session_state
  4  ,      to_char(tm_delta_time) tm_delta_time
  5  ,      to_char(tm_delta_cpu_time) tm_delta_cpu_time
  6  ,      to_char(tm_delta_db_time) tm_delta_db_time
  7  from   dba_hist_active_sess_history
  8  where  session_id = 642
  9  and    sql_id     IN ('2nj4dm3qwmkqh','34y8jhfh5w4q9')
 10  order by sample_id desc;

TO_CHAR( EVENT                     SESSION TM_DELTA_TIME   TM_DELTA_CPU_TIME TM_DELTA_DB_TIME
-------- ------------------------- ------- --------------- ----------------- ----------------
15:05:42 db file scattered read    WAITING 9120533         5612146           703679604684133
15:05:32 db file scattered read    WAITING 10128857        7202905           281471853489246
15:05:22 db file scattered read    WAITING 10042965        7493861           20148167
15:05:12 db file scattered read    WAITING 1194282071      20199931          31190611

9 rows selected.

SQL> 

So, the good news would be that the values from the buffer are not just copied down but seem to be an aggregation, presumably of the sampled rows. I’m not sure because some of the numbers add up, some don’t.

But the big, bad news is that there are similar accounting bugs – note the values in the first two rows for TM_DELTA_DB_TIME.

It should not be possible for TM_DELTA_DB_TIME to be greater than TM_DELTA_TIME.

As a result, this data seems occasionally unreliable and this unreliability undermines it’s usefulness.

Unless of course someone else has another explanation?

About these ads

5 Responses to Thoughts on TM_DELTA_TIME

  1. I have tried to use these three columns and find excessively large TM_DELTA_CPU_TIME appearing in both V$ACTIVE_SESSION_HISTORY and DBA_HIST_ACTIVE_SESS_HISTORY (naturally following from the source). This is in 11.2.0.2 A search on support.oracle.com doesn’t yield any useful notes.

  2. Hi Dominic,

    just to give some more thoughts on this: All these columns added in 11.2 are actually used by Real-Time SQL Monitoring to populate the “Metrics” tab in the “EM/Active” (flash-based) version of the report.

    There is an interesting query run by the DBMS_SQLTUNE.BUILD_STASH_XML function as part of generating the final XML embedded into the HTML document representing the document.

    This uses all these newly added fields to come up with some bucket-based aggregation of that data which in turn seems to be used by the function PL/SQL code to generate the corresponding XML data the “Metrics” tab content is based on.

    The query also seems to filter out those “outliers” that you’ve identified.

    Note that my XPLAN_ASH tool in “experimental” mode also tries to analyze that data (the I/O related part) but it looks like that at least the I/O figures are not really corresponding to the actual amount of I/O – quite often they seem to fall short of the actual amount.

    I haven’t investigated if a common cause for this can be found, but I have test cases where I can see that the I/O related graphs in the “Metrics” tab show the same inconsistency, so it doesn’t look a problem of my code handling the ASH data.

    Randolf

  3. Steve Howard says:

    If I am doing the math correctly, it looks like there 985 seconds in your first session record in ASH at 15:05. This is about 16 minutes. Your previous record was 2:45PM, or about 20 minutes prior. I am wondering if you didn’t do something else in your session at about 2:49PM, and then nothing for 16 minutes. Could there be a bug where the time is recorded since the previous measurement? I know that defeats the entire purpose of tracking “active” sessions, but the math at least makes me ask the question.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 69 other followers

%d bloggers like this: