]> sourceware.org Git - systemtap.git/commitdiff
2006-02-14 Frank Ch. Eigler <fche@elastic.org>
authorfche <fche>
Tue, 14 Feb 2006 22:12:07 +0000 (22:12 +0000)
committerfche <fche>
Tue, 14 Feb 2006 22:12:07 +0000 (22:12 +0000)
* 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
elaborate.cxx
stapfuncs.5.in
staptree.cxx
tapset/ChangeLog
tapset/queue_stats.stp [new file with mode: 0644]

index 55f40b8c161f1da07a2e1801a5f2110cc52597f4..5e2c374c5c41b42ebe4161afe39990f60276b251 100644 (file)
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,11 @@
+2006-02-14  Frank Ch. Eigler  <fche@elastic.org>
+
+       * 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  <fche@elastic.org>
 
        * src/testsuite/buildok/syscalls.stp: Build with "-u" to build-test
index ce8844cebdd109fad2c4d6b0f828cc0ecb428669..a906bb871f6f2cf2de67bb0d29e800a67eb76f4f 100644 (file)
@@ -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);
+    }
 }
 
 
index 3ad19642a43fe5511b860035c697b6e11baa67a9..b6b663f382fd4cb665428a6ea35215e422fc41e5 100644 (file)
@@ -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
index b43983126470f1a6f196fad5d1fafa3d23257989..74aa3964b5c3fdd7f9b541bf95e9652618bf9e36 100644 (file)
@@ -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 
index 41f84b16714f604eee579266c2452507f0cfb355..0b84dc13991c6509b17d1069d286952fb4d28ed6 100644 (file)
@@ -1,3 +1,7 @@
+2006-02-14  Frank Ch. Eigler  <fche@elastic.org>
+
+       * queue_stats.stp: New tapset.
+
 2006-02-14  Mark McLoughlin  <markmc@redhat.com>
 
        * 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 (file)
index 0000000..02b041c
--- /dev/null
@@ -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))
+}
This page took 0.046088 seconds and 5 git commands to generate.