What is the Oracle ASH time waited column?

Posted on 27-Aug-2015 by Craig Shallahamer, craig@orapub.com

I'm all-in with Oracle's time model. An Oracle Time-Based Analysis is one of the most powerful Oracle Database analysis methodologies available. Strangely perhaps, I'm also all-in with Oracle's performance sampling methodology, known as Active Session History or simply, ASH.

What I'm NOT all-in with is combining the two... unless I for sure know exactly what the ASH time values mean. Why the paranoia? Because when an Oracle DBA doesn't know what a number truly represents, they tend to morph the numbers into their own convenient meaning. And, this is where Oracle Database tuning can quickly go down a career bending path.

So, I approached verifying the ASH time_waited column with both seriousness and suspicion. What I discovered, and will partially detail in this post, is this column is valuable, unusual and can be easily misinterpreted.

If you want to use ASH to its fullest, then you have got to understand the time_waited column... and that's what this post is all about.

The ASH Documentation

The Oracle documentation is a good place to start. If you look at the v$active_session_history Oracle Database documentation HERE , it says:

If SESSION_STATE = WAITING, then the time that the session actually spent waiting for that event (in hundredths of a second). This column is set for waits that were in progress at the time the sample was taken.

If a wait event lasted for more than a second and was caught waiting in more than one session sample row, then the actual time spent waiting for that wait event will be populated in the last of those session sample rows. At any given time, this information will not be available for the latest session sample.

Are you kidding me!? This reminds me of an advanced C Programmer's code. It's elegant, amazing and completely incomprehensible! I had to read this definition five times before I began understanding what it means!

However, having some timing information combined with the ASH data could be a powerful performance analysis tool. But if I don't understand what the values truly means, I could easily come to VERY wrong conclusions... not a good career move for anyone!

So, I embarked on a quest to truly understand what the time_waited values mean and also the resulting implications. Seems like a good time to do an experiment!

The Experiment: Setup

For this experiment to be repeatable and verifiable, I needed a non-idle wait event where I could control the duration. A table level lock seemed like a good choice! Don't try this on your production database. ;)

I created two sessions. The first session simply creates a table, locks it and never unlocks it. The second session attempts to acquire the lock for up to a specific set duration. If the lock is not acquired, the SQL statement essentially times out. This is awesome, because it allows me to look at the ASH time_waited value during the attempted lock acquisition!

Below is the SQL for the blocking session. I pasted this directly into SQL*Plus.

connect craig/craig
drop table bogusT;
create table bogusT as select * from dual;
select distinct sid from v$mystat;
lock table bogusT in exclusive mode;

It's pretty straightforward. Notice that I grabbed the session ID. This way I can verify the other session is being blocked by the above session.

Below is the result of pasting the above SQL directly into SQL*Plus.

SQL> connect craig/craig
Connected.

SQL> drop table bogusT;

Table dropped.

SQL> create table bogusT as select * from dual;

Table created.

SQL> select distinct sid from v$mystat;

       SID
----------
       326

SQL> lock table bogusT in exclusive mode;

Table(s) Locked.

SQL> 

So, the blocker is session 326 and is holding the lock indefinitely.

The second session's SQL, that I pasted directly into SQL*Plus, is shown below:

connect craig/craig
select distinct sid from v$mystat;
declare
  i_var number;
  s_var varchar2(100);
begin
  for i_var in 2..10
  loop
    s_var := 'lock table bogusT in exclusive mode wait '||i_var ;
    begin
      execute immediate s_var;  
    exception when others then null;
    end;
  end loop;
end;
/

Again it's pretty straightforward, but it is structured so I can easily get the details I need from ASH.

Noticed I grabbed the session ID. I did this, so I can follow this session's activity in v$active_session_history. Even more important, notice I control the lock acquisition attempt time, from two seconds up to ten seconds. I start with two seconds to ensure ASH's one second collection interval time will for sure sample this session. Also, once the lock attempt times out, the loop immediate starts another longer lock acquisition attempt.

Below is the result of pasting the above SQL directly into SQL*Plus.

SQL> connect craig/craig
select distinct sid from v$mystat;
Connected.
SQL> 

       SID
----------
       172

SQL> declare
  i_var number;
  s_var varchar2(100);
begin
  for i_var in 2..10
  loop
    s_var := 'lock table bogusT in exclusive mode wait '||i_var ;
    begin
      execute immediate s_var;  
    exception when others then null;
    end;
  end loop;
end;
/
  2    3    4    5    6    7    8    9   10   11   12   13   14  

PL/SQL procedure successfully completed.

SQL>

Now that the sessions did their part, let's look back in time using the v$active_session_history details... and especially the time_waited column!

The Experiment: The Raw Output

I used my BloodHound Toolkit to report on the ASH data. In BloodHound, the bhset.sql script is used to set the parameters for all the following script reporting. For this situation, I wanted to report on my local v$active_session_history data but only within the last two minutes. This keeps the report small and will only show the results from my previous experiment run.

The type of report I need is called a time-line report. I want to "watch" the locked 172 session as it progressed through its unsuccessful locking attempts. To do this I used my BloodHound "time line" script, bhBBtl.sql. I also wanted to see the time_waited and the blocking_session columns. Plus, I also displayed the wait_time column just in case I wanted the data for another purpose.

The below BloodHound script was run after session 172 attempted to lock the table multiple times and the script completed.

SQL> @bhBBtl 172 172 % % wait_time,time_waited,blocking_session

DB/Inst: prod40/prod40                                                                                                                                  12-Aug 12:16pm
Report:   bhBBtl.sql                                                                        BloodHound by OraPub, Inc.                                  Page         1

                                                                           Big Bang Session Timeline - ASH Sample Based Analysis Report

                                                                      Wait
 Sample ID Sample Time        SID User ID  Sess State SQL_ID          Type   Wait Event Name           Wait Event Parameters      WAIT_TIME TIME_WAITED BLOCKING_SESSION
---------- ------------ --------- -------- ---------- --------------- ------ ------------------------- ------------------------- ---------- ----------- ----------------
  21923239 12:15:58           172 116      WAITING    4t3fudfthqypy   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923240 12:15:59           172 116      WAITING    4t3fudfthqypy   other  enq: TM - contention      1414332422:125361:0                0     1999354              326
  21923241 12:16:00           172 116      WAITING    cdwfq8vd7k2d3   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923242 12:16:01           172 116      WAITING    cdwfq8vd7k2d3   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923243 12:16:02           172 116      WAITING    cdwfq8vd7k2d3   other  enq: TM - contention      1414332422:125361:0                0     2999616              326
  21923244 12:16:03           172 116      WAITING    8p766b1bsj9tt   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923245 12:16:04           172 116      WAITING    8p766b1bsj9tt   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923246 12:16:05           172 116      WAITING    8p766b1bsj9tt   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923247 12:16:06           172 116      WAITING    8p766b1bsj9tt   other  enq: TM - contention      1414332422:125361:0                0     4009354              326
  21923248 12:16:07           172 116      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923249 12:16:08           172 116      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923250 12:16:09           172 116      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923251 12:16:10           172 116      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923252 12:16:11           172 116      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:125361:0                0     5009568              326
  21923253 12:16:12           172 116      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923254 12:16:13           172 116      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923255 12:16:14           172 116      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923256 12:16:15           172 116      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923257 12:16:16           172 116      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923258 12:16:17           172 116      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:125361:0                0     5999553              326
  21923259 12:16:18           172 116      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923260 12:16:19           172 116      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923261 12:16:20           172 116      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923262 12:16:21           172 116      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923263 12:16:22           172 116      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923264 12:16:23           172 116      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923265 12:16:24           172 116      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:125361:0                0     7009401              326
  21923266 12:16:25           172 116      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923267 12:16:26           172 116      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923268 12:16:27           172 116      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923269 12:16:28           172 116      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923270 12:16:29           172 116      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923271 12:16:30           172 116      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923272 12:16:31           172 116      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923273 12:16:32           172 116      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:125361:0                0     8009453              326
  21923274 12:16:33           172 116      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923275 12:16:34           172 116      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923276 12:16:35           172 116      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923277 12:16:36           172 116      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923278 12:16:37           172 116      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923279 12:16:38           172 116      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923280 12:16:39           172 116      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923281 12:16:40           172 116      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923282 12:16:41           172 116      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:125361:0                0     8999528              326
  21923283 12:16:42           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923284 12:16:43           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923285 12:16:44           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923286 12:16:45           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923287 12:16:46           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923288 12:16:47           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923289 12:16:48           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923290 12:16:49           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923291 12:16:50           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0           0              326
  21923292 12:16:51           172 116      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:125361:0                0    10009392              326

54 rows selected.

The ASH data source is v$active_session_history from 2 minutes ago to 0 minutes ago

Clearly, we can see that session 172 is waiting to acquire a table level lock because it is being blocked by session 326. Take a look at the time_waited column. Interesting, eh? Read on!

The Experiment: What We See

There is so much to say, but I'll limit my comments and then drill into specifics in the below sections.

First, ASH is collecting and we reported on every second of session 172's activity. Perfect and just what I expected to see.

Second, session 172 is ALWAYS waiting when it was sampled by ASH,though is must consume a little CPU, and it was always waiting on a table level (TM) lock.

Third, the blocking session is 326, which is what I expected to see. This confirms session 172 is truly waiting on my lock table script's session 326.

Now it's time to delve into the strange time_waited world...

Time_Waited Column: Unit Of Time

To effectively use the ASH time_waited column, first I must know it's unit of time. Is it seconds, centi-seconds, milliseconds, microseconds or nanoseconds? Look closely at the above output and you can probably guess the time_waited column's unit of time is microseconds. How can we know this?

Look closely at the time_waited values. If you look at the time_waited column and divide by 1000000 the resulting time_waited values match the actual lock timeout values; 2s, 3s, 4s,... 10s. This is why it was so important for me to control the wait time duration. Because of this, I am able to match the numbers perfectly!

Documentation Doesn't Match Reality?

Hold on a second! The 11g documentation I showed at the top of this post, clearly states the time_waited column's unit of time is centi-seconds. Is this a contradiction?

Perhaps not because... my experiment above is running Oracle 12c. So I need to ensure I reference the documentation for Oracle Database 12c and not 11g. I went to the default Oracle 12c documentation page HERE and did a search for v$active_session_history which brought me THIS PAGE .

If you scroll down to the time_waited column, this is what you will see:

Looking at the time_waited column description, it says the unit of time is microseconds! OK, so that matches and clearly my 12c time_waited data for session 172 is in microseconds. So, we all good, right? Not yet...

But what about the Oracle 11g documentation and what about the Oracle Database 11g time_waited unit of time? Is there are contradiction?

Here is the Oracle 11g documentation picture of the of the time_waited column entry that I am referencing.

Running The Experiment In Oracle 11g

To verify the 11g time_waited unit of time, I need to run my experiment in an Oracle Database 11g environment. That's what I did. I ran the exact same experiment as above, but in an 11g environment and the results are shown below. You can see session 215 trying to acquire the TM lock held by session 173.


SQL> @bhBBtl 215 215 % % wait_time,time_waited,blocking_session

DB/Inst: prod30/prod30                                                                                                                                   14-Aug 10:34am
Report:   bhBBtl.sql                                                                        BloodHound by OraPub, Inc.                                   Page         1

                                                                           Big Bang Session Timeline - ASH Sample Based Analysis Report

                                                                      Wait
 Sample ID Sample Time        SID User ID  Sess State SQL_ID          Type   Wait Event Name           Wait Event Parameters      WAIT_TIME TIME_WAITED BLOCKING_SESSION
---------- ------------ --------- -------- ---------- --------------- ------ ------------------------- ------------------------- ---------- ----------- ----------------
  35970890 10:33:49           215 117      WAITING    4t3fudfthqypy   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970891 10:33:50           215 117      WAITING    4t3fudfthqypy   other  enq: TM - contention      1414332422:112719:0                0     1999733              173
  35970892 10:33:51           215 117      WAITING    cdwfq8vd7k2d3   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970893 10:33:52           215 117      WAITING    cdwfq8vd7k2d3   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970894 10:33:53           215 117      WAITING    cdwfq8vd7k2d3   other  enq: TM - contention      1414332422:112719:0                0     2999485              173
  35970895 10:33:54           215 117      WAITING    8p766b1bsj9tt   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970896 10:33:55           215 117      WAITING    8p766b1bsj9tt   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970897 10:33:56           215 117      WAITING    8p766b1bsj9tt   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970898 10:33:57           215 117      WAITING    8p766b1bsj9tt   other  enq: TM - contention      1414332422:112719:0                0     4009496              173
  35970899 10:33:58           215 117      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970900 10:33:59           215 117      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970901 10:34:00           215 117      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970902 10:34:01           215 117      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970903 10:34:02           215 117      WAITING    9fu0uqdxqnqkh   other  enq: TM - contention      1414332422:112719:0                0     5009624              173
  35970904 10:34:03           215 117      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970905 10:34:04           215 117      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970906 10:34:05           215 117      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970907 10:34:06           215 117      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970908 10:34:07           215 117      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970909 10:34:08           215 117      WAITING    f2zwc3w04yxyq   other  enq: TM - contention      1414332422:112719:0                0     6009427              173
  35970910 10:34:09           215 117      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970911 10:34:10           215 117      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970912 10:34:11           215 117      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970913 10:34:12           215 117      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970914 10:34:13           215 117      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970915 10:34:14           215 117      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970916 10:34:15           215 117      WAITING    9uh6dgy7hj6fw   other  enq: TM - contention      1414332422:112719:0                0     7009482              173
  35970917 10:34:16           215 117      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970918 10:34:17           215 117      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970919 10:34:18           215 117      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970920 10:34:19           215 117      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970921 10:34:20           215 117      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970922 10:34:21           215 117      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970923 10:34:22           215 117      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970924 10:34:23           215 117      WAITING    193dd3vxz35pr   other  enq: TM - contention      1414332422:112719:0                0     8009545              173
  35970925 10:34:24           215 117      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970926 10:34:25           215 117      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970927 10:34:26           215 117      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970928 10:34:27           215 117      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970929 10:34:28           215 117      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970930 10:34:29           215 117      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970931 10:34:30           215 117      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970932 10:34:31           215 117      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970933 10:34:32           215 117      WAITING    gsqnx5zdts7ks   other  enq: TM - contention      1414332422:112719:0                0     9009502              173
  35970934 10:34:33           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970935 10:34:34           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970936 10:34:35           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970937 10:34:36           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970938 10:34:37           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970939 10:34:38           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970940 10:34:39           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970941 10:34:40           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970942 10:34:41           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0           0              173
  35970943 10:34:42           215 117      WAITING    9t4uuwcmy8w0k   other  enq: TM - contention      1414332422:112719:0                0    10009525              173

54 rows selected.


The ASH data source is v$active_session_history from 2 minutes ago to 0 minutes ago

Are you kidding me?! So the Oracle 11 documentation is wrong! Flat out, 100% wrong! According to the documentation, session 215 above waited 100,095 seconds! No wonder a DBA would freak out when they saw this! Unless the DBA did a controlled experiment like I did, any reference to the time_waited column could make the situation appear much worse than it actually is.

Documentation Gone Wild

But this situation gets even stranger! I decided to do some more super-fun documentation checking. I discovered in another 11.2 reference documentation HERE the time_waited column is supposed to be in microseconds. So the 11g documentation contradicts itself!

I better check the Oracle 10.2 documentation and the Oracle 11.1 documentation. They both take the silent approach and do not state the unit of time... how convenient. Wow... what a stink'n mess!

Time_Waited Column: All Those Zeroes

Because my experiment was controlled AND the waits were longer than one second, the documentation is making a little more sense. (Not the unit of time aspect!) Let me explain.

If the wait is longer than one second but not finished, then the time_waited value is set to zero. However, when the wait finishes, the time_waited value is set to the actual the wait time, in microseconds.

This seems to match my experimental data... perfectly.

For example, in the ASH output in the previous section, look at the last set of time_waited zeros. How many are there? Each zero represents one second of wait time. Since there are nine zeros, this represents nine seconds. But what about the number after the nine zeros? Read on!

What About The Number After The Zeros?

Now look at the number following the set of nine zeros. The number is 10009525. This is in micro-seconds, so we're looking at a total of about 10 seconds.

Is this making sense? The nine zeros represent the session in a continual 9 second wait and the final 10009525 entry represents the final 1 second for a total of 10 seconds! This is exactly how long I set session 215 to wait before it timed out! The numbers make perfect sense!

You can do this for all sets of zero time_waited values! The first zero set has only 1 zero plus the final wait, for a total of 2 seconds... which was the first wait time in my loop. The third wait has 2 zeros occurrences plus the final wait, for a total of 3 seconds! ...repeat. So, everything seems to match up nicely!

Closer Look At The SQL Statements

In the output above, find the SQL_ID ending in fw. Count the number of zero time_waited entries above it and add one. That should be seven. Below is the SQL text for fw SQL statement.


SQL> @sqlgettext sql_id 9uh6dgy7hj6fw

DB/Inst: prod40/prod40                                                                                  12-Aug 12:22pm
Report:   sqlgettext.sql                          OSM by OraPub, Inc.                                   Page         1
                                       SQL Statement Text (sql_id=9uh6dgy7hj6fw)


HASH_VALUE ADDRESS            Line SQL Statement Text
---------- ---------------- ------ -----------------------------------------------------------------
2399705564 000000006158DE40      0 lock table bogusT in exclusive mode wait 7

1 row selected.

We should not be surprised that the wait timeout in the above SQL is 7 seconds! This equals the six zeros plus the final one second wait for a total of 7009482 microseconds, which is about 7 seconds! Nice.

ASH Time_Waited Column: Summary

Based on my experiment, this is what I found:

But there is more to this story! If you have looked at your real production data, you will notice there are many time_waited values that are less than one second, that is less than 1000000. What does that mean? How can we use this data? And what are the risks and limitations?

The short answer is I will reveal the details in my next post!

Until then...

All the best to you in your work,

Craig.

If you have any questions or comments, feel free to email me directly at craig at orapub.com.

Top 7 Reasons Why Oracle Database Conferences Are A Waste Of Time Integrating Stori Into Your Oracle Database Performance Management System Understanding Oracle Database User Calls