PR5689 part 2: separate skip counters for low-stack and reentrancy cases

5 files changed, 63 insertions, 19 deletions

diff --git a/ChangeLog b/ChangeLog
index 20f5706a..f4cdb54f 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,5 +1,14 @@
 2008-11-21  Frank Ch. Eigler  <fche@elastic.org>
 
+	PR 5689.
+	* tapsets.cxx (common_probe_entryfn_{pro,epi}logue):
+	Track separate skip counts for low-stack and reentrancy conditions.
+	* translate.cxx (emit_common_header): Declare counters.
+	(emit_module_exit): Print them.
+	(emit_unlocks): Don't bother redundantly testing skipped_count.
+
+2008-11-21  Frank Ch. Eigler  <fche@elastic.org>
+
 	* translate.cxx (emit_module_exit): Perform shutdown probe
 	synchronization after all unregistrations and end/error probe
 	runs.
diff --git a/tapsets.cxx b/tapsets.cxx
index 601668d0..4b55470e 100644
--- a/tapsets.cxx
+++ b/tapsets.cxx
@@ -190,10 +190,10 @@ common_probe_entryfn_prologue (translator_output* o, string statestr,
   o->newline(1) << "< (MINSTACKSPACE + sizeof (struct thread_info)))) {"; // needed space
   // XXX: may need porting to platforms where task_struct is not at bottom of kernel stack
   // NB: see also CONFIG_DEBUG_STACKOVERFLOW
-  o->newline() << "if (unlikely (atomic_inc_return (& skipped_count) > MAXSKIPPED)) {";
-  o->newline(1) << "atomic_set (& session_state, STAP_SESSION_ERROR);";
-  o->newline() << "_stp_exit ();";
-  o->newline(-1) << "}";
+  o->newline() << "atomic_inc (& skipped_count);";
+  o->newline() << "#ifdef STP_TIMING";
+  o->newline() << "atomic_inc (& skipped_count_lowstack);";
+  o->newline() << "#endif";
   o->newline() << "goto probe_epilogue;";
   o->newline(-1) << "}";
 
@@ -202,13 +202,11 @@ common_probe_entryfn_prologue (translator_output* o, string statestr,
   o->indent(-1);
 
   o->newline() << "c = per_cpu_ptr (contexts, smp_processor_id());";
-  o->newline() << "if (unlikely (atomic_inc_return (&c->busy) != 1)) {";
-  o->newline(1) << "if (atomic_inc_return (& skipped_count) > MAXSKIPPED) {";
-  o->newline(1) << "atomic_set (& session_state, STAP_SESSION_ERROR);";
-  // NB: We don't assume that we can safely call stp_error etc. in such
-  // a reentrant context.  But this is OK:
-  o->newline() << "_stp_exit ();";
-  o->newline(-1) << "}";
+  o->newline() << "if (atomic_inc_return (& c->busy) != 1) {";
+  o->newline(1) << "atomic_inc (& skipped_count);";
+  o->newline() << "#ifdef STP_TIMING";
+  o->newline() << "atomic_inc (& skipped_count_reentrant);";
+  o->newline() << "#endif";
   o->newline() << "atomic_dec (& c->busy);";
   o->newline() << "goto probe_epilogue;";
   o->newline(-1) << "}";
@@ -316,6 +314,12 @@ common_probe_entryfn_epilogue (translator_output* o,
   o->newline(-1) << "probe_epilogue:"; // context is free
   o->indent(1);
 
+  // Check for excessive skip counts.
+  o->newline() << "if (unlikely (atomic_read (& skipped_count) > MAXSKIPPED)) {";
+  o->newline(1) << "atomic_set (& session_state, STAP_SESSION_ERROR);";
+  o->newline() << "_stp_exit ();";
+  o->newline(-1) << "}";
+
   if (! interruptible)
     o->newline() << "local_irq_restore (flags);";
   else
diff --git a/testsuite/ChangeLog b/testsuite/ChangeLog
index 96095b26..24f0cbdd 100644
--- a/testsuite/ChangeLog
+++ b/testsuite/ChangeLog
@@ -1,3 +1,8 @@
+2008-11-21  Frank Ch. Eigler  <fche@elastic.org>
+
+	PR5689.
+	* systemtap.base/skipped.exp: New test.
+
 2008-11-19  Jim Keniston  <jkenisto@us.ibm.com>
 
 	* systemtap.context/num_args.stp: Added s390x case.
diff --git a/testsuite/systemtap.base/skipped.exp b/testsuite/systemtap.base/skipped.exp
new file mode 100644
index 00000000..8c491037
--- /dev/null
+++ b/testsuite/systemtap.base/skipped.exp
@@ -0,0 +1,21 @@
+set test "skip tracking"
+
+if {! [installtest_p]} { untested $test; return }
+
+set cpus [exec sh -c "grep ^processor /proc/cpuinfo | wc -l"]
+if {$cpus < 2} { unsupported $test; return }
+
+set ok 0
+spawn stap -e "probe timer.s(5) {exit()} probe timer.profile,syscall.* {f++} global f" -DMAXTRYLOCK=0 -tu
+expect {
+    -timeout 30
+    -re {^WARNING: Number of errors: 0, skipped probes: [0-9]+\r\n} { incr ok; exp_continue }
+    -re {^WARNING: Skipped due to global .f. lock timeout: [0-9]+\r\n} { incr ok; exp_continue }
+    -re {^probe timer.profile[^\r\n]+, hits: [0-9]+[^\r\n]+\r\n} { incr ok; exp_continue }
+    eof { }
+    timeout { fail "$test (timeout)" }
+}
+catch {close}
+catch {wait}
+
+if {$ok >= 3} { pass "$test ($cpus $ok)" } else { fail "$test ($cpus $ok)" }
diff --git a/translate.cxx b/translate.cxx
index 8bae5275..74fa609f 100644
--- a/translate.cxx
+++ b/translate.cxx
@@ -863,6 +863,10 @@ c_unparser::emit_common_header ()
   o->newline() << "atomic_t session_state = ATOMIC_INIT (STAP_SESSION_STARTING);";
   o->newline() << "atomic_t error_count = ATOMIC_INIT (0);";
   o->newline() << "atomic_t skipped_count = ATOMIC_INIT (0);";
+  o->newline() << "#ifdef STP_TIMING";
+  o->newline() << "atomic_t skipped_count_lowstack = ATOMIC_INIT (0);";
+  o->newline() << "atomic_t skipped_count_reentrant = ATOMIC_INIT (0);";
+  o->newline() << "#endif";
   o->newline();
   o->newline() << "struct context {";
   o->newline(1) << "atomic_t busy;";
@@ -1349,9 +1353,13 @@ c_unparser::emit_module_exit ()
     {
       string vn = c_varname (session->globals[i]->name);
       o->newline() << "ctr = atomic_read (& global.s_" << vn << "_lock_skip_count);";
-      o->newline() << "if (ctr) _stp_warn (\"Variable `%s' lock timeouts: %d\\n\", "
+      o->newline() << "if (ctr) _stp_warn (\"Skipped due to global '%s' lock timeout: %d\\n\", "
                    << lex_cast_qstring(vn) << ", ctr);";
     }
+  o->newline() << "ctr = atomic_read (& skipped_count_lowstack);";
+  o->newline() << "if (ctr) _stp_warn (\"Skipped due to low stack: %d\\n\", ctr);";
+  o->newline() << "ctr = atomic_read (& skipped_count_reentrant);";
+  o->newline() << "if (ctr) _stp_warn (\"Skipped due to reentrancy: %d\\n\", ctr);";
   o->newline(-1) << "}";
   o->newline () << "#endif";
   o->newline() << "_stp_print_flush();";
@@ -1717,12 +1725,9 @@ c_unparser::emit_unlocks(const varuse_collecting_visitor& vut)
 
   if (numvars) // is there a chance that any lock attempt failed?
     {
-      o->newline() << "if (atomic_read (& skipped_count) > MAXSKIPPED) {";
-      // XXX: In this known non-reentrant context, we could print a more
-      // informative error.
-      o->newline(1) << "atomic_set (& session_state, STAP_SESSION_ERROR);";
-      o->newline() << "_stp_exit();";
-      o->newline(-1) << "}";
+      // Formerly, we checked skipped_count > MAXSKIPPED here, and set
+      // SYSTEMTAP_SESSION_ERROR if so.  But now, this check is shared
+      // via common_probe_entryfn_epilogue().
 
       if (session->verbose>1)
         clog << endl;
@@ -4770,7 +4775,7 @@ emit_symbol_data (systemtap_session& s)
        it != ctx.undone_unwindsym_modules.end();
        it ++)
     {
-      s.print_warning ("missing unwind/symbol data for module `" + (*it) + "'");
+      s.print_warning ("missing unwind/symbol data for module '" + (*it) + "'");
     }
 }