Oracle performance tool: WW (wait watcher)
Date: Fri, 14 Oct 1994 19:09:06 -0800
Message-ID: <jkennedy-1410941909060001_at_jkennedy-lap.us.oracle.com>
I had requests to post the Wait Watcher (WW) tool, so here it is. This message starts with an explanation of WW, the underlying V$ tables that support WW, some caveats, and finally the source code.
What is WW?
It is a tool (read: hack) to help you determine what Oracle sessions are waiting, what event they're waiting for, and how long they typically spend waiting for the each event.
Where does WW get its information?
WW simply displays information from the V$SESSION_WAIT, V$SESSION_EVENT, and V$SYSTEM_EVENT internal tables in Oracle. These tables contain information describing why the Oracle wait routine was called. These tables have been in the Oracle kernel since 7.0.12.
Note that time in the V$ tables mentioned above is returned as 100ths of seconds, while the time returned in WW is normalized to seconds.
What does each V$ table return?
V$SESSION_WAIT - latest or current reason a session is waiting V$SESSION_EVENT - for each session, a list of wait events and assoc'd info V$SYSTEM_EVENT - for the instance, a list of wait events and assoc'd info
What's a session? And an event? Any other definitions?
A session is a connect to Oracle. A single process can possibly have multiple connections (concurrent logons) to Oracle; each connection is a session. Each session has a unique session id or Sid.
There is a routine in Oracle used to perform a wait. When the wait routine is called by another part of Oracle code, a reason that the wait is being called is supplied to the routine for reporting in the V$ tables listed above. It doesn't affect the wait itself, but the information is interesting. This wait reason is also known as the event.
Additional information that has to do with the event is provided in WW's "Additional Information" column. Stuff you might see in here: if a foreground is waiting for a disk read to complete, the additional information provided will include the database file number and block number being read. That sort of stuff.
Every time the wait routine is called, the wait sequence number associated with the session is bumped. Why is this useful? You may find a session spending all of its time in the "client message" wait event (waiting for something to do from the user or client side) even though you know the client has done stuff (successfully, too). The problem isn't that V$SESSION_WAIT isn't seeing the other wait states, it's just that you can't query V$SESSION_WAIT fast enough to see any other state. You can tell this by watching the sequence number advance with every WW screen refresh.
Lastly, "Wait Time" is the amount of time spent doing the wait. This is pretty straightforward in the V$SESSION_EVENT and V$SYSTEM_EVENT views.
In the V$SESSION_WAIT view (the view that shows what's currently happening), "Wait Time" is a bit different. If the wait is currently happening, you'll see 0's or -1's for the wait time. If the time is some other number, then the session is not currently waiting, and the event and wait time listed reflect the statistics from the last time the wait routine was called. Wait happen so frequently that you may never see anything but active waits (0's or -1's in the wait time column).
OK...So show me some output from WW
When you run WW, you tell it which information you want to see: V$SESSION_WAIT, V$SESSION_EVENT or V$SYSTEM_EVENT. You specify which information and the screen update frequency on the command line.
By the way, while in the V$SESSION_WAIT view, WW will bold lines for sessions that have been active (left their previous wait state). Kind of cooling for seeing who's hot and who's not. The following listings don't show that bolding, but...
Here's some screen shots from each view followed by some comments to help you figure this stuff out:
V$SESSION_WAIT at 13:23:20.87 (time interval 1.00 seconds)
Sid Sequence Event Wait Time Additional Information
--- -------- ----------------- ----------- ---------------------- 1 112 pmon timer 0.00 ( 0, 0, 0) 2 206 rdbms ipc message 0.00 (timeout 300, 0, 0) 3 306 rdbms ipc message 0.00 (timeout 300, 0, 0) 4 112 rdbms ipc message 0.00 (timeout 300, 0, 0) 5 28 smon timer 0.00 (sleep time 300, failed 0, 0) 7 13 client message -1.00 (two-task? 0, driver id 19645580, 0) 9 20 client message -1.00 (two-task? 0, driver id 18683020, 0)
This view is best for seeing what's currently happening on your system. If you have a stuck Oracle process, you probably want to use this display to figure out why it's stuck. It may help if you determine the session id of the stuck process (with the other V$ tables) before you look at this view so you know which "Sid" to look for.
V$SESSION_EVENT at 13:25:35.45 (time interval 1.00 seconds)
Sid Event Total Waits Total Time Ave Wait --- ------------------------------ ----------- ----------- --------- 1 pmon timer 155 463.02 2.9872 2 db file sequential read 18 0.01 0.0006 2 control file sequential read 68 0.11 0.0016 2 db file parallel write 3 0.24 0.0800 2 rdbms ipc message 161 467.62 2.9045 3 log file sequential read 5 0.02 0.0040 3 db file sequential read 9 0.03 0.0033 3 control file sequential read 30 0.06 0.0020 3 latch free 1 0.08 0.0800 3 log file single write 5 0.12 0.0240 3 db file single write 9 0.20 0.0222 3 control file parallel write 24 0.50 0.0208 3 log file parallel write 59 0.76 0.0129 3 rdbms ipc message 208 466.26 2.2416 4 rdbms ipc message 155 465.12 3.0008 5 latch free 6 0.03 0.0050 5 db file scattered read 9 0.50 0.0556 5 db file sequential read 9 0.68 0.0756 5 smon timer 4 329.33 82.3325 7 client message 13 0.00 0.0000 9 client message 22 0.03 0.0014
The V$SESSION_EVENT view almost has too much information to be of use. If you have a particular session whose wait states you're interested in, it may be better just to run a SQL query in SQL*DBA against the V$SESSION_EVENT table using a "where" clause to find just that sessions wait states.
V$SYSTEM_EVENT at 13:26:42.95 (time interval 1.00 seconds)
Event Total Waits Total Time Ave Wait ------------------------------ ----------- ----------- --------- log file sync 1 0.04 0.0400 log file single write 6 0.14 0.0233 latch free 12 0.15 0.0125 log file sequential read 9 0.20 0.0222 db file parallel write 3 0.24 0.0800 control file sequential read 121 0.27 0.0022 db file scattered read 10 0.53 0.0530 db file single write 27 0.64 0.0237 log file parallel write 59 0.76 0.0129 control file parallel write 41 0.90 0.0220 client message 741 1.85 0.0025 db file sequential read 196 2.50 0.0128 rdbms ipc reply 7 2.79 0.3986 process startup 5 5.00 1.0000 smon timer 4 329.33 82.3325 pmon timer 179 532.75 2.9763 rdbms ipc message 592 1603.03 2.7078
The V$SYSTEM_EVENT is a great view for showing you how much time you spend doing particular things. For example, the above shows that we spend about 13 ms doing a log file write...not bad.
Caveats
First and most importantly...this is unsupported software. And it's not terribly robust either; for example, there's no built-in way to exit the program once you've started it. But WW gets the job done. So don't call me or anyone else at Oracle about WW. Of course, I'm interested in what you do with this and any suggestions (and code!) you have for improvements.
Next, it was written for Digital's VMS operating system. If you need it on some other O/S, you'll have to port it. But, there are only two VMS-specific calls...one to get the current time and another to wait (hibernate, sleep) for a specified amount of time. Porting isn't a big deal.
WW works by executing a SQL query against the appropriate V$ table, and sprintf's the output to a huge array, complete with ANSI escape sequences to control cursor positioning, erasing, and bolding of lines. Once the query results have all been returned, the array is printf'd to the screen. Why do this? Because it makes for fast, clean response time...much better than printf'ing a line at a time. Problem with this is that the V$SESSION_EVENT can return more info than will fit into the screen array, causing you to potentially overwrite other storage. That view has never been all that useful to me (recall my earlier comments about it), so I've never worried about it.
WW works best when running against a wide and tall screen...this keeps it from wrapping and scrolling.
The username/password to access the database is hard-coded into the program. While this isn't a problem for us that do benchmarking at Oracle, it is probably a problem for you. Best to externalize this to the command line.
The include files referenced in the source are standard VMS include files or standard Oracle include files. You should already have your own version of the Oracle files. You're on your own for the O/S-specific files.
Conclusion
Well, that's about it. Just so you know, this was compiled, linked, and verified to run before this was posted, so this stuff really, really does work. Flame the coding all you want, but realize this is something akin to my_first_C_program.C, and was written a while ago.
Good luck with this! I hope it proves useful to someone (otherwise I wouldn't have spent a Friday evening typing this in). I'd like to hear feedback!
Thanks.
Jef (jkennedy_at_oracle.com)
- 8<--------------------------------------------------------------------
#include <stdlib.h> /* makes atof() work correctly */ #include <stdio.h> #include <time.h> #include <timeb.h> #include <ssdef.h> /* VMS return statuses */ #include <descrip.h> /* makes $DESCRIPTOR work */ #include "ocidfn" /* gives us the struct for ORACLE things */ #include "oratypes" /* used by ocidfn */
/* ORACLE data structures & stuff */
typedef struct cda_def ldadef;
ldadef tpclda;
typedef struct cda_def csrdef;
csrdef *sqlcsr; char sqlbuf[1024];
#define V$SESSION_WAIT \
"select sid, seq#, nvl(event,' '), nvl(p1text,' '), p1, nvl(p2text,' '), \
p2, nvl(p3text,' '), p3, wait_time from v$session_wait order by sid"
#define V$SESSION_EVENT \
"select sid, nvl(event,' '), total_waits, time_waited, average_wait from\ v$session_event order by sid, time_waited"
#define V$SYSTEM_EVENT \
"select event, total_waits, time_waited, average_wait from v$system_event\ order by time_waited"
#define ROWS 200
int sid[ROWS]; /* columns for v$session_wait */ unsigned long seq[ROWS];
char event[ROWS][80]; char p1text[ROWS][80]; long p1[ROWS]; char p2text[ROWS][80]; long p2[ROWS]; char p3text[ROWS][80]; long p3[ROWS]; float wait_time[ROWS];
unsigned long total_waits[ROWS]; /* add'l columns for v$session_event */ unsigned long time_waited[ROWS]; /* ...and v$system_event */ float average_wait[ROWS];
char uid[80] = "sys/change_on_install"; ub4 err = 0; long status; /* return status from lib$ and sys$calls */
int x; float sleeptime = 1; /* sleep time */ int which = 1; /* default to session_wait */ char which_s[20];
$DESCRIPTOR(which_d,which_s);
typedef int quadword[2]; /* VMS time needs a quadword to store */ quadword time_bin; /* time of current sample, binary */ char time_asc[12]; /* ascii version of time to display */ $DESCRIPTOR(time_desc,time_asc); /* Descriptor for time_asc */ #define PVMAX 500 long prev_val[PVMAX]; char line_buffer[1000]; char screen_buffer[10000]; void usage(); void banner(); void errrpt();
/* Main Program */
main(argc, argv)
int argc;
char *argv[];
{
/* Handle the command line parameters */
if (argc >= 2)
{
strcpy(which_s,argv[1]);
if (!(status = str$upcase(&which_d,&which_d))) exit(status);
if (strcmp(which_s,"SESSION_WAIT") == 0) which = 1;
else if (strcmp(which_s,"SESSION_EVENT") == 0) which = 2;
else if (strcmp(which_s,"SYSTEM_EVENT") == 0) which = 3;
else {
printf("Can't determine the wait_type\n\n");
usage();
}
}
if (argc >= 3) sleeptime = (float) atoi(argv[2]) / 100;
if (argc >= 4) strcpy(uid,argv[3]);
/* Log on to ORACLE and open a cursor */ printf("Logging on to ORACLE...\n"); if (olon(&tpclda, uid, -1, (char *) -1, -1, 0)) errrpt(&tpclda);
printf("Opening cursor\n");
sqlcsr = (csrdef *)malloc(sizeof(csrdef));
if (oopen(sqlcsr,&tpclda, (text *)0, 0, -1, uid, -1)) errrpt(sqlcsr);
/* Do the right query */
switch (which) {
case 1:
strcpy(sqlbuf,V$SESSION_WAIT);
if (oparse(sqlcsr, sqlbuf, -1, 0, 2)) errrpt(sqlcsr);
if (odefin(sqlcsr, 1, sid, sizeof(sid[0]), SQLT_INT,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 2, seq, sizeof(seq[0]), SQLT_INT,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 3, event, 80, SQLT_STR,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 4, p1text, 80, SQLT_STR,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 5, p1, sizeof(p1[0]), SQLT_INT,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 6, p2text, 80, SQLT_STR,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 7, p2, sizeof(p2[0]), SQLT_INT,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 8, p3text, 80, SQLT_STR,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 9, p3, sizeof(p3[0]), SQLT_INT,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 10, wait_time, sizeof(wait_time[0]), SQLT_FLT,
0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
strcpy(which_s,"V$SESSION_WAIT");
printf("\033[H\033[J");
while (1) {
if (err = oexfet(sqlcsr,ROWS,0,0)) errrpt(sqlcsr);
banner();
strcat(screen_buffer,"Sid Sequence Event
Wait Time Additional Information\033[0K\n");
strcat(screen_buffer,"--- --------
------------------------------ ----------- ----------------------\033[0K\n");
for (x = 0; x < sqlcsr->rpc; ++x)
{
if (wait_time[x] == (float) 4.2949673E+09)
wait_time[x] = -100;
if (prev_val[sid[x]] != seq[x])
{
prev_val[sid[x]] = seq[x];
strcat(screen_buffer,"\033[1m");
} else {
strcat(screen_buffer,"\033[0m");
}
sprintf(line_buffer,"%3d %8d %-30s %11.2f (%s %d, %s %d,
%s %d)\033[0K\n",
sid[x], seq[x], event[x], (float) wait_time[x]/100,
p1text[x], p1[x], p2text[x], p2[x], p3text[x], p3[x]);
strcat(screen_buffer,line_buffer);
}
strcat(screen_buffer,"\033[0m\033[0J");
printf(screen_buffer);
if ( status = lib$wait(&sleeptime) != SS$_NORMAL )
lib$stop(status);
}
case 2:
strcpy(sqlbuf,V$SESSION_EVENT);
if (oparse(sqlcsr, sqlbuf, -1, 0, 2)) errrpt(sqlcsr);
if (odefin(sqlcsr, 1, sid, sizeof(sid[0]),
SQLT_INT, 0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0))
errrpt(sqlcsr);
if (odefin(sqlcsr, 2, event, 80, SQLT_STR, 0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 3, total_waits, sizeof(total_waits[0]), SQLT_INT, 0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 4, time_waited, sizeof(time_waited[0]), SQLT_INT, 0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 5, average_wait, sizeof(average_wait[0]),SQLT_FLT, 0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
strcpy(which_s,"V$SESSION_EVENT");
printf("\033[H\033[J");
while (1) {
if (err = oexfet(sqlcsr,ROWS,0,0)) errrpt(sqlcsr);
banner();
strcat(screen_buffer,"Sid Event Total
Waits Total Time Ave Wait\033[0K\n");
strcat(screen_buffer,"--- ------------------------------
----------- ----------- ---------\033[0K\n");
for (x = 0; x < sqlcsr->rpc; ++x)
{
sprintf(line_buffer,"%3d %-30s %11d %11.2f %9.4f\033[0K\n",
sid[x], event[x], total_waits[x],
(float) time_waited[x]/100,
(float) average_wait[x]/100);
strcat(screen_buffer,line_buffer);
}
strcat(screen_buffer,"\033[0J");
printf(screen_buffer);
if ( status = lib$wait(&sleeptime) != SS$_NORMAL )
lib$stop(status);
}
case 3:
strcpy(sqlbuf,V$SYSTEM_EVENT);
if (oparse(sqlcsr, sqlbuf, -1, 0, 2)) errrpt(sqlcsr);
if (odefin(sqlcsr, 1, event, 80,
SQLT_STR, 0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0))
errrpt(sqlcsr);
if (odefin(sqlcsr, 2, total_waits, sizeof(total_waits[0]), SQLT_INT, 0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 3, time_waited, sizeof(time_waited[0]), SQLT_INT, 0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
if (odefin(sqlcsr, 4, average_wait, sizeof(average_wait[0]),SQLT_FLT, 0, (short *) 0, (char *) 0, 0, 0, (short *) 0, (short *) 0)) errrpt(sqlcsr);
strcpy(which_s,"V$SYSTEM_EVENT");
printf("\033[H\033[J");
while (1) {
if (err = oexfet(sqlcsr,ROWS,0,0)) errrpt(sqlcsr);
banner();
strcat(screen_buffer,"Event Total
Waits Total Time Ave Wait\033[0K\n");
strcat(screen_buffer,"------------------------------
----------- ----------- ---------\033[0K\n");
for (x = 0; x < sqlcsr->rpc; ++x)
{
sprintf(line_buffer,"%-30s %11d %11.2f %9.4f\033[0K\n",
event[x], total_waits[x], (float) time_waited[x]/100,
(float) average_wait[x]/100);
strcat(screen_buffer,line_buffer);
}
strcat(screen_buffer,"\033[0m\033[0J");
printf(screen_buffer);
if ( status = lib$wait(&sleeptime) != SS$_NORMAL )
lib$stop(status);
}
/* end switch */
}
}
void errrpt(cur)
csrdef *cur;
{
text msg[2048];
if (cur->rc == 1403) return;
if (cur->rc) {
(void) ocierr(cur, cur->rc, msg, 2048);
(void) printf("%s\n", msg);
}
exit(0);
}
void usage()
{
printf("Usage:\n");
printf(" $ WW [wait_type [interval [username/password]]]\n");
printf("\n");
printf(" wait_type = SESSION_WAIT (default) | SESSION_EVENT |
SYSTEM_EVENT\n");
printf(" interval = 100's of seconds; defaults to 1 second
(interval=100)\n");
printf(" username/password defaults to SYS/CHANGE_ON_INSTALL\n");
exit(0);
}
void banner()
{
/* Get the current time and convert it to ascii */ if (status = sys$gettim(&time_bin) != SS$_NORMAL) lib$stop(status); if (status = sys$asctim(0,&time_desc,&time_bin,1) != SS$_NORMAL) lib$stop(status);
sprintf(line_buffer,"\033[H%s at %s (time interval %6.2f seconds)\033[0K\n\033[0K\n",
which_s,time_asc,sleeptime);
screen_buffer[0]= '\0';
strcpy(screen_buffer,line_buffer);
}
/* end of file */
-- Jef "...I wouldn't normally do this kind of thing." -- Pet Shop BoysReceived on Sat Oct 15 1994 - 04:09:06 CET