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:
-
Whenever you see a value in the time_waited column that is 0 while the session is waiting, we know the session is in the middle of a multi-second wait.
-
Whenever you see a value in the time_waited column that is greater than 0 while the session is waiting, we know the session has just completed a multi-second wait and the value displayed is the final and total wait time... in microseconds for Oracle 11g and 12c. I did not perform my experiment on 10g.
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.
