In earlier posts we looked at v$reqdist and v$queue, which report time spent running tasks, and time spent waiting in the COMMON and DISPATCHER queues.
I mentioned in the previous article that if we see too much time spent in the COMMON queue(s) then perhaps we needed more shared servers. Moving to the other end of the dialogue, one of the reasons why we might spend too much time waiting in a DISPATCHER queue for the result to go back to the user is that we don’t have enough dispatchers – and we can get a clue about this from the view v$dispatcher:
column messages format 999,999,999,999 column bytes format 999,999,999,999 column idle format 999,999,999,999 column busy format 999,999,999,999 column total_time format 999,999,999,999 column busy_percent format 999.99 select name, /* network, */ messages, bytes, idle, busy, idle + busy total_time, 100 * round(busy/nullif(idle+busy,0),4) busy_percent from v$dispatcher / NAME MESSAGES BYTES IDLE BUSY TOTAL_TIME BUSY_PERCENT ---- ---------------- ---------------- ---------------- ---------------- ---------------- ------------ D000 341,902,864 -1,875,035,869 498,676,896 897,199,945 1,395,876,841 64.28 D001 351,090,918 -860,132,585 1,672,899,708 216,085,537 1,888,985,245 11.44 D002 3,543,576 1,820,366,239 6,602,929 82,744 6,685,673 1.24 D003 5,994,180 -1,007,460,261 6,539,742 145,927 6,685,669 2.18
Unfortunately, it looks as if the critical columns in this view are recorded as 32-bit signed, which means they wrap from positive to negative at about 2,000,000,000 – and this means the figures for D000 and D001 are complete garbage. In my last note I pointed out that I had started up two extra dispatchers on a system that had been running for quite a long time – which is why dispatchers D002 and D003 have such small number compared to the others – they’ve only been running about 18 hours (66,857 seconds).
Clearly, to get some sensible figures, you really need to play around with snapshots and deltas and worry about all the usual problems of collecting information for the right interval. Even so, these figures do show you that D002 and D003 have been idle for most of the time they’ve been up – but you’ll have to take it from me that the 827 seconds and 1,459 seconds they’ve recorded as busy time was a small fraction of a soak test that we were running. It’s not obvious from the absolute figures, but with the background information I have I can say that there was a small benefit from having four dispatchers, but nothing significant.
Note: if we were able to trust the 64.28% figure for dispatcher D000 we could be reasonably confident that we needed at least the second dispatcher simply on the basis of the work being done by D000; but we might also worry about it for another reason – if the dispatcher is very busy, it’s possible that this is just a symptom of the whole machine being busy, in which case it’s possible that the dispatcher isn’t able to get CPU time to do its work.
The previous post in this series showed you how v$reqdist summarised the time taken by tasks running through shared servers – but there are several other ways we need to look at what’s going on with shared servers. One of the more important ones is to find out how much time a task is queueing before it gets to a shared server to start running – and Oracle gives us v$queue as the place to find this information:
set linesize 120 set trimspool on set pagesize 40 column program format a24 column totalq format 9,999,999,999 column wait format 9,999,999,999 select prc.program, que.type, que.totalq, que.wait, round(que.wait/nullif(que.totalq,0),2) avg_wait from v$queue que, v$process prc where prc.addr(+) = que.paddr / PROGRAM TYPE TOTALQ WAIT AVG_WAIT ------------------------ ---------- -------------- ------------- ---------- oracle@xxxxxxxx (D000) DISPATCHER 199,171,228 4,405,840 .02 oracle@xxxxxxxx (D001) DISPATCHER 204,687,986 1,435,915,630 7.02 oracle@xxxxxxxx (D002) DISPATCHER 2,068,714 29,477 .01 oracle@xxxxxxxx (D003) DISPATCHER 3,541,736 61,355 .02 COMMON 286,032,262 1,105,120,053 3.86
The view gives statistics since instance startup, usually, but can produce very strange results because it is possible to stop and start dispatchers dynamically. In this example the system had been running for quite a long time with just two dispatchers and I had increased it to four dispatchers in the previous 24 hours – hence the two dispatchers with a relatively tiny number of waits in the queue. (I stopped and restarted the dispatchers for subsequent test runs so that I didn’t have to keep working out the deltas.)
The COMMON queue is where incoming requests are queued waiting for a shared server to servive them, the DISPATCHER queues are where a shared server places its result set when it has processed the message. (A session is permanently “connected” to a dispatcher – but the association between a session and a shared server is transient, and each session request could end up being serviced by a different shared server).
If there are too many concurrent messages for the number of shared servers (or, almost equivalently) too many long-running tasks, then we would expect to see the time spent in the COMMON queue climbing as sessions wait for a shared served to become free. In principle I wouldn’t really expect to see much time spent in the DISPATCHER queues.
Before you ask, I can’t explain how the waits on D001 got to be so long when the similar number of waits on D000 were so short – all the explanations I hypothesised end up with a logical (usually statistical) flaw . Suggestions will be welcomed.
Footnote: Most of the notes I’ve seen about v$queue on the Internet say that there is only every one COMMON queue, so the number of rows in v$queue will always be one more than the number of rows in v$dispatcher – but my copy of 22.214.171.124 seems to start up with two COMMON queues (dictated by hidden parameter _shared_server_num_queues) – which are always fairly evenly loaded.
Although they are becoming increasingly rare (thanks, largely, to Web-based applications taking over the world) a few of the systems I get called in to review are still using Shared Server technology (formerly known as Mutli-threaded Server / MTS); and I have to say that there are a couple of nice “overview” features supporting this technology that I would like to see in the AWR or Statspack reports. These are the views which allow you to see how the workload is being shared out and what the time distribution looks like, and I’ll be taking a look at these views over the course of three or four blog notes.
The first view is v$reqdist – a view for which there is no match in dedicated server technology. This view gives you a simple histogram of how the shared servers have spent their time in the database. Here’s a simple query of the view, with the results from a system I was looking at a little while ago:
column bucket format 999,999,999,999 select * from v$reqdist order by bucket ; BUCKET COUNT ---------- ---------------- 0 284,997,511 1 0 2 482,285 3 348,456 4 160,150 5 37,206 6 3,891 7 313 8 29 9 33 10 12 11 28
According to the view definition, bucket N records the number of operations (for example a single “fetch” call) that took less than 4 * (2^N) hundredths of a second to complete. So this output shows 285 million operations took less than 4/100 seconds to complete, 482 thousand operations took less than 16/100 second to complete, and 28 operations took up to 81.92 seconds to complete. (In fact, anything taking longer than 81.92 seconds also falls into the last bucket.)
There are a few drawbacks to using this view, of course. The first is that it accumulates data since instance startup – and neither Statspack nor the AWR use it in their snapshots – so you have to write your own code to do interval analysis.
Secondly the choice of buckets isn’t ideal: a “fastest bucket” of 4 centiseconds doesn’t really help very much when you’ve got a system where you think most tasks are going to be very quick, and a “slowest bucket” of only 82 seconds doesn’t really highlight the massively slow jobs that you might want to know about. Perhaps this second loss of detail is deliberate – after all, everything you do through shared servers is supposed to be very quick, so perhaps all you really need to know is that some of your tasks are taking more than a few seconds - after which is doesn’t really matter how long they are taking.
The final problem with this view is that it loses data. Notice the zero that appears as the count in bucket 1 (the 4/100 to 8/100 second bucket) – that looks suspiciously out of place. Given the numbers in the buckets either side you can’t help feeling that there should have been some tasks falling into that bucket. And there is a bug (though not one I can find on MOS/Metalink): tasks taking 4/100 to 8/100 second fall into the 0 – 4/100 second bucket.
If you want to demonstrate this for yourself, and with your own platform and version of Oracle, it’s quite easy to do. From an SQL*plus session connected through a shared server simply query v$reqdist before and after running a script that looks like the following:
set serveroutput off execute dbms_lock.sleep(0.06) execute dbms_lock.sleep(0.06) execute dbms_lock.sleep(0.06) -- repeat for (say) 100 times execute dbms_lock.sleep(0.06) execute dbms_lock.sleep(0.06) execute dbms_lock.sleep(0.06)
Pick a few variations in the sleep time – and see which bucket your sleeps are recorded in. (The call to disable serveroutput is there so that you don’t see the effects of the dbms_output calls that SQL*Plus would otherwise issue after each call to the database – these would show up in the 0-4/100 bucket.)
There is actually another little problem with with view – it’s another of those little glitches that appear when you experiment with the SYS account – the view doesn’t seem to record the time spent in the virtual circuit when you were connected as SYS (although other views would show the traffic).
Update: Having created a simple piece of demonstration code to show that bug with the bucket usage, it occurred to me recently to use it for at stress test – and I found another bug with v$reqdist when running 126.96.36.199 on Windows XP. It looks as if, with sufficient concurrent sessions (leading to a backup in the COMMON queue) Oracle loses track of how to compute round-trip time. I haven’t pursued this very closely yet, but it looks almost as if Oracle starts to use the wrong start and end times to calculate the round-trip time, intially subtracting the start time of message N-1 from the end time of message N and gradually slipping further and further out of sync until it’s using times from widely separated messages.