From 2a99f48ff1f873f537784d6f70d7641ada1ed7bd Mon Sep 17 00:00:00 2001 From: fche Date: Tue, 14 Feb 2006 22:12:07 +0000 Subject: [PATCH] 2006-02-14 Frank Ch. Eigler * stapfuncs.5.in: Document new queue_stats tapset. * elaborate.cxx (*): Put "while:" clarification messages before a thrown semantic error. * staptree.cxx (print_format::string_to_components): Correct parse of "%%" formatting element. * queue_stats.stp: New tapset. * systemtap.samples/queue_demo.*: New test. --- ChangeLog | 8 +++ elaborate.cxx | 17 ++++-- stapfuncs.5.in | 52 ++++++++++++++++++ staptree.cxx | 2 +- tapset/ChangeLog | 4 ++ tapset/queue_stats.stp | 118 +++++++++++++++++++++++++++++++++++++++++ 6 files changed, 195 insertions(+), 6 deletions(-) create mode 100644 tapset/queue_stats.stp diff --git a/ChangeLog b/ChangeLog index 55f40b8c1..5e2c374c5 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,3 +1,11 @@ +2006-02-14 Frank Ch. Eigler + + * stapfuncs.5.in: Document new queue_stats tapset. + * elaborate.cxx (*): Put "while:" clarification messages before a + thrown semantic error. + * staptree.cxx (print_format::string_to_components): Correct + parse of "%%" formatting element. + 2006-02-07 Frank Ch. Eigler * src/testsuite/buildok/syscalls.stp: Build with "-u" to build-test diff --git a/elaborate.cxx b/elaborate.cxx index ce8844ceb..a906bb871 100644 --- a/elaborate.cxx +++ b/elaborate.cxx @@ -391,10 +391,10 @@ systemtap_session::register_library_aliases() } catch (const semantic_error& e) { - print_error (e); - cerr << " while: registering probe alias "; + cerr << "while: registering probe alias "; alias->printsig(cerr); cerr << endl; + print_error (e); } } } @@ -442,7 +442,7 @@ derive_probes (systemtap_session& s, { // XXX: prefer not to print_error at every nest/unroll level s.print_error (e); - cerr << " while: resolving probe point " << *loc << endl; + cerr << "while: resolving probe point " << *loc << endl; // if (! exc_outermost) // throw; } @@ -935,7 +935,11 @@ symresolution_info::visit_foreach_loop (foreach_loop* e) if (d) array->referent = d; else - throw semantic_error ("unresolved global array " + array->name, e->tok); + { + cerr << "while searching for arity " << e->indexes.size() + << " array:\n"; + throw semantic_error ("unresolved global array " + array->name, e->tok); + } } } else @@ -1071,7 +1075,10 @@ symresolution_info::visit_functioncall (functioncall* e) if (d) e->referent = d; else - throw semantic_error ("unresolved function call", e->tok); + { + cerr << "while searching for arity " << e->args.size() << " function:\n"; + throw semantic_error ("unresolved function call", e->tok); + } } diff --git a/stapfuncs.5.in b/stapfuncs.5.in index 3ad19642a..b6b663f38 100644 --- a/stapfuncs.5.in +++ b/stapfuncs.5.in @@ -164,6 +164,58 @@ errno_str:string (e:long) Return the symbolic string associated with the given error code, like "ENOENT" for the number 2, or "E#3333" for an out-of-range value like 3333. +.SS QUEUE_STATS +.PP +The queue_stats tapset provides functions that, given notifications of +elementary queuing events (wait, run, done), tracks averages such as +queue lenghth, service and wait times, utilization. The following +three functions should be called from appropriate probes, in sequence. +.TP +qs_wait:unknown (qname:string) +Record that a new request was enqueued for the given queue name. +.TP +qs_run:unknown (qname:string) +Record that a previously enqueued request was removed from the given +wait queue and is now being serviced. +.TP +qs_done:unknown (qname:string) +Record that a request originally from the given queue has completed +being serviced. +.\" XXX: qs_time +.PP +Functions with the prefix +.BR qsq_ +are for querying the statistics averaged since the first queue operation +(or when +.BR qsq_start +was called). Since statistics are often fractional, a scale parameter +is multiplies the result to a more useful scale. For some fractions, +a scale of 100 will usefully return percentage numbers. +.TP +qsq_start:unknown (qname:string) +Reset the statistics counters for the given queue, and start tracking +anew from this moment. +.TP +qsq_print:unknown (qname:string) +Print a line containing a selection of the given queue's statistics. +.TP +qsq_utilization:long (qname:string, scale:long) +Return the fraction of elapsed time when the resource was utilized. +.TP +qsq_blocked:long (qname:string, scale:long) +Return the fraction of elapsed time when the wait queue was used. +.TP +qsq_wait_queue_length:long (qname:string, scale:long) +Return the average length of the wait queue. +.TP +qsq_service_time:long (qname:string, scale:long) +Return the average time required to service a request. +.TP +qsq_wait_time:long (qname:string, scale:long) +Return the average time a request took from being enqueued to completed. +.TP +qsq_throughput:long (qname:string, scale:long) +Return the average rate of requests per scale units of time. .SH FILES .nh diff --git a/staptree.cxx b/staptree.cxx index b43983126..74aa3964b 100644 --- a/staptree.cxx +++ b/staptree.cxx @@ -448,7 +448,7 @@ print_format::string_to_components(string const & str) assert (curr.type == conv_unspecified || curr.type == conv_literal); curr.type = conv_literal; curr.literal_string += '%'; - ++i; + i += 2; continue; } else diff --git a/tapset/ChangeLog b/tapset/ChangeLog index 41f84b167..0b84dc139 100644 --- a/tapset/ChangeLog +++ b/tapset/ChangeLog @@ -1,3 +1,7 @@ +2006-02-14 Frank Ch. Eigler + + * queue_stats.stp: New tapset. + 2006-02-14 Mark McLoughlin * aux_syscalls.stp: (_sys_open_flag_str): s/O_NDCTTY/O_NOCTTY/ diff --git a/tapset/queue_stats.stp b/tapset/queue_stats.stp new file mode 100644 index 000000000..02b041c5f --- /dev/null +++ b/tapset/queue_stats.stp @@ -0,0 +1,118 @@ +# qstats.stp: Queue statistics gathering tapset + +# ------------------------------------------------------------------------ + +# The default timing function: microseconds. This function could +# go into a separate file (say, qstats_qs_time.stp), so that a user +# script can override it with another definition. + +function qs_time () { return gettimeofday_us () } + +# ------------------------------------------------------------------------ + +global qs_wtime, qs_wlentime, qs_wcount +global qs_rtime, qs_rlentime, qs_rcount +global qs_stime, qs_utime, qs_dcount + +# ------------------------------------------------------------------------ + +function _qs_update (qname) { + now = qs_time () + then = qs_utime[qname]; if (! then) { then = now } + delta = now-then + + qs_wtime[qname] += qs_wcount[qname] ? delta : 0 + qs_wlentime[qname] += qs_wcount[qname] * delta + qs_rtime[qname] += qs_rcount[qname] ? delta : 0 + qs_rlentime[qname] += qs_rcount[qname] * delta + qs_utime[qname] = now +} + +function qs_wait (qname) { # enqueueing request + _qs_update (qname) + qs_wcount[qname] ++ +} + +function qs_run (qname) { # starting to service request + _qs_update (qname) + if (qs_wcount[qname] > 0) { + qs_wcount[qname] -- + qs_rcount[qname] ++ + } +} + +function qs_done (qname) { # done servicing request + _qs_update (qname) + if (qs_rcount[qname] > 0) { + qs_rcount[qname] -- + qs_dcount[qname] ++ + } +} + +# ------------------------------------------------------------------------ + +function qsq_start (qname) { # reset statistics for new baseline + delete qs_rcount[qname] + delete qs_rtime[qname] + delete qs_rlentime[qname] + delete qs_wcount[qname] + delete qs_wtime[qname] + delete qs_wlentime[qname] + delete qs_dcount[qname] + qs_stime[qname] = qs_time () +} + +# ------------------------------------------------------------------------ +# Various query functions. Each returns the average, taken over the time +# interval from the last qsq_start(). Most deal with fractions, and so +# also take a scale parameter (use 100 for percent). + +# fraction of time that any request was being serviced +function qsq_utilization (qname, scale) { + elapsed = qs_time() - qs_stime[qname] + return (scale * qs_rtime[qname]) / elapsed +} + +# fraction of time that any request was blocked in the wait queue +function qsq_blocked (qname, scale) { + elapsed = qs_time() - qs_stime[qname] + return (scale * qs_wtime[qname]) / elapsed +} + +# length of wait queue +function qsq_wait_queue_length (qname, scale) { + elapsed = qs_time() - qs_stime[qname] + return (scale * qs_wlentime[qname]) / elapsed +} + +# service time (amount of time per request service) +function qsq_service_time (qname, scale) { + return (scale * qs_rlentime[qname]) / qs_dcount[qname] +} + +# wait time (amount of time in queue + service per request) +function qsq_wait_time (qname, scale) { + return (scale * (qs_rlentime[qname] + qs_wlentime[qname])) + / qs_dcount[qname] +} + +# service rate (number of requests served per unit time) +function qsq_throughput (qname, scale) { + elapsed = qs_time() - qs_stime[qname] + return (scale * qs_dcount[qname]) / elapsed +} + + +# ------------------------------------------------------------------------ + +function qsq_print (qname) { + qwl = qsq_wait_queue_length (qname, 1000) + printf("%s: %d ops/s, %d.%03d qlen, %d await, %d svctm, %d%% wait, %d%% util\n", + qname, + qsq_throughput (qname, 1000000), # number of qs_time() units per second + qwl/1000, qwl%1000, + qsq_wait_time (qname, 1), + qsq_service_time (qname, 1), + qsq_blocked (qname, 100), + qsq_utilization (qname, 100)) +} -- 2.43.5