9.6. Using queue statistics
Functions with the qsq_ prefix query the statistics averaged since the first queue operation or when qsq_start was called. Since statistics are often fractional, a scale parameter multiplies the result to a more useful scale. For some fractions, a scale of 100 returns percentage numbers.
9.6.1. qsq_blocked
General syntax:
qsq_blocked:long (qname:string, scale:long)
This function returns the fraction of elapsed time during which one or more requests were on the wait queue.
9.6.2. qsq_print
General syntax:
qsq_print:unknown (qname:string)
This function prints a line containing the following statistics for the given queue:
- queue name
- average rate of requests per second
- average wait queue length
- average time on the wait queue
- average time to service a request
- percentage of time the wait queue was used
- percentage of time any request was being serviced
9.6.3. qsq_service_time
General syntax:
qsq_service_time:long (qname:string, scale:long)
This function returns the average time in microseconds required to service a request once it is removed from the wait queue.
9.6.4. qsq_start
General syntax:
qsq_start:unknown (qname:string)
This function resets the statistics counters for the given queue, and restarts tracking from the moment the function was called. This command is used to create a queue.
9.6.5. qsq_throughput
General syntax:
qsq_throughput:long (qname:string, scale:long)
This function returns the average number of requests served per microsecond.
9.6.6. qsq_utilization
General syntax:
qsq_utilization:long (qname:string, scale:long)
This function returns the average time in microseconds that at least one request was being serviced.
9.6.7. qsq_wait_queue_length
General syntax:
qsq_wait_queue_length:long (qname:string, scale:long)
This function returns the average length of the wait queue.
9.6.8. qsq_wait_time
General syntax:
qsq_wait_time:long (qname:string, scale:long)
This function returns the average time in microseconds that it took for a request to be serviced (qs_wait() to qs_done()).
9.6.9. A queue example
What follows is an example from src/testsuite/systemtap.samples/queue_demo.stp. It uses the randomize feature of the timer probe to simulate queuing activity.
probe begin {
qsq_start ("block-read")
qsq_start ("block-write")
}
probe timer.ms(3500), end {
qsq_print ("block-read")
qsq_start ("block-read")
qsq_print ("block-write")
qsq_start ("block-write")
}
probe timer.ms(10000) {
exit ()
}
# synthesize queue work/service using three randomized "threads" for each queue.
global tc
function qs_doit (thread, name) {
n = tc[thread] = (tc[thread]+1) % 3 # per-thread state counter
if (n==1) qs_wait (name)
else if (n==2) qs_run (name)
else if (n==0) qs_done (name)
}
probe timer.ms(100).randomize(100) { qs_doit (0, "block-read") }
probe timer.ms(100).randomize(100) { qs_doit (1, "block-read") }
probe timer.ms(100).randomize(100) { qs_doit (2, "block-read") }
probe timer.ms(100).randomize(100) { qs_doit (3, "block-write") }
probe timer.ms(100).randomize(100) { qs_doit (4, "block-write") }
probe timer.ms(100).randomize(100) { qs_doit (5, "block-write") }
This prints:
block-read: 9 ops/s, 1.090 qlen, 215749 await, 96382 svctm, 69% wait, 64% util block-write: 9 ops/s, 0.992 qlen, 208485 await, 103150 svctm, 69% wait, 61% util block-read: 9 ops/s, 0.968 qlen, 197411 await, 97762 svctm, 63% wait, 63% util block-write: 8 ops/s, 0.930 qlen, 202414 await, 93870 svctm, 60% wait, 56% util block-read: 8 ops/s, 0.774 qlen, 192957 await, 99995 svctm, 58% wait, 62% util block-write: 9 ops/s, 0.861 qlen, 193857 await, 101573 svctm, 56% wait, 64% util
