Add STAP_USER_HOOKS for begin and end probes

Add source line to the _stp_runtime_entryfn_xx_context()

.gitignore

@@ -37,3 +37,4 @@ stamp-elfutils
 dtrace
 stappaths.7
 .zanata-cache
+/Debug/

runtime/common_probe_context.h

@@ -175,3 +175,8 @@ struct unwind_context uwcontext_kernel;
 #ifdef _HAVE_PERF_
 long *perf_read_values;
 #endif
+
+unsigned line_put;
+unsigned line_get;
+int busy_get;
+int busy_put;

runtime/linux/print.c

@@ -78,7 +78,9 @@ static void _stp_print_cleanup (void)
 
 static inline void _stp_print_flush(void)
 {
+#ifndef STP_PRINT_OFF
 	stp_print_flush(per_cpu_ptr(Stp_pbuf, smp_processor_id()));
+#endif
 }
 #ifndef STP_MAXBINARYARGS
 #define STP_MAXBINARYARGS 127

runtime/linux/runtime_context.h

@@ -76,13 +76,14 @@ static inline struct context * _stp_runtime_get_context(void)
 	return rcu_dereference_sched(contexts[smp_processor_id()]);
 }
 
-static struct context * _stp_runtime_entryfn_get_context(void)
+static struct context * _stp_runtime_entryfn_get_context(int line)
 {
 	struct context* __restrict__ c = NULL;
 	preempt_disable ();
 	c = _stp_runtime_get_context();
 	if (c != NULL) {
 		if (atomic_inc_return(&c->busy) == 1) {
+			c->line_get = line;
 			// NB: Notice we're not re-enabling preemption
 			// here. We exepect the calling code to call
 			// _stp_runtime_entryfn_get_context() and
@@ -91,19 +92,31 @@ static struct context * _stp_runtime_entryfn_get_context(void)
 			return c;
 		}
 		atomic_dec(&c->busy);
+		//printk(KERN_ALERT "secdo: %s: c->busy=%d last_stmt=%s\n", __func__, atomic_read(&c->busy), c->last_stmt);
+	}
+	else {
+		//printk(KERN_ALERT "secdo: %s: context is null\n", __func__);
 	}
 	preempt_enable_no_resched();
 	return NULL;
 }
 
-static inline void _stp_runtime_entryfn_put_context(struct context *c)
+static inline void _stp_runtime_entryfn_put_context(struct context *c, int line)
 {
 	if (c) {
-		if (c == _stp_runtime_get_context())
+		if (c == _stp_runtime_get_context()) {
 			atomic_dec(&c->busy);
-		/* else, warn about bad state? */
+			c->line_put = line;
+		}
+		else {
+			/* else, warn about bad state? */
+			//printk(KERN_ALERT "secdo: %s: wrong context c->busy=%d last_stmt=%s\n", __func__,  atomic_read(&c->busy), c->last_stmt);
+		}
 		preempt_enable_no_resched();
 	}
+	else {
+		//printk(KERN_ALERT "secdo: %s: context is null\n", __func__);
+	}
 	return;
 }
 
@@ -131,7 +144,8 @@ static void _stp_runtime_context_wait(void)
 				if (time_after(jiffies, hold_start + HZ)  // > 1 second
 				    && (i > hold_index)) { // not already printed
 					hold_index = i;
-					printk(KERN_ERR "%s context[%d] stuck: %s\n", THIS_MODULE->name, i, c->probe_point);
+					printk(KERN_ERR "%s context[%d] stuck: %s, line_get=%d, line_put=%d last_err=%s last_stmt=%s\n", THIS_MODULE->name, i,
+							c->probe_point, c->line_get, c->line_put, c->last_error, c->last_stmt);
 				}
 			}
 		}

runtime/print_flush.c

@@ -127,7 +127,7 @@ void stp_print_flush(_stp_pbuf *pb)
                  * concurrency-control-laden effort with a lockless
                  * algorithm.
 		 */
-		c = _stp_runtime_entryfn_get_context();
+		c = _stp_runtime_entryfn_get_context(__LINE__);
 
 		dbug_trans(1, "calling _stp_data_write...\n");
 		stp_spin_lock_irqsave(&_stp_print_lock, flags);
@@ -148,7 +148,7 @@ void stp_print_flush(_stp_pbuf *pb)
 			}
 		}
 		stp_spin_unlock_irqrestore(&_stp_print_lock, flags);
-		_stp_runtime_entryfn_put_context(c);
+		_stp_runtime_entryfn_put_context(c, __LINE__);
 	}
 #endif /* STP_TRANSPORT_VERSION != 1 */
 #endif /* !STP_BULKMODE */

runtime/runtime.h

@@ -15,8 +15,8 @@
 static int _stp_runtime_contexts_alloc(void);
 static void _stp_runtime_contexts_free(void);
 static int _stp_runtime_get_data_index(void);
-static struct context *_stp_runtime_entryfn_get_context(void);
-static void _stp_runtime_entryfn_put_context(struct context *);
+static struct context *_stp_runtime_entryfn_get_context(int);
+static void _stp_runtime_entryfn_put_context(struct context *, int);
 static struct context *_stp_runtime_get_context(void);
 
 #include "addr-map.h"

runtime/transport/control.c

@@ -560,15 +560,15 @@ static int _stp_ctl_send(int type, void *data, unsigned len)
 	   We ensure this by grabbing the context here and everywhere else that
 	   uses those locks, so such a probe will appear reentrant and be
 	   skipped rather than deadlock.  */
-	c = _stp_runtime_entryfn_get_context();
+	c = _stp_runtime_entryfn_get_context(__LINE__);
 
 	/* get a buffer from the free pool */
 	bptr = _stp_ctl_get_buffer(type, data, len);
 	if (unlikely(bptr == NULL)) {
 		/* Nothing else we can do... but let's not spam the kernel
                    with these reports. */
                 /* printk(KERN_ERR "ctl_write_msg type=%d len=%d ENOMEM\n", type, len); */
-		_stp_runtime_entryfn_put_context(c);
+		_stp_runtime_entryfn_put_context(c, __LINE__);
 		return -ENOMEM;
 	}
 
@@ -579,7 +579,7 @@ static int _stp_ctl_send(int type, void *data, unsigned len)
 	list_add_tail(&bptr->list, &_stp_ctl_ready_q);
 	spin_unlock_irqrestore(&_stp_ctl_ready_lock, flags);
 
-	_stp_runtime_entryfn_put_context(c);
+	_stp_runtime_entryfn_put_context(c, __LINE__);
 
 	/* It would be nice if we could speed up the notification
 	   timer at this point, but calling mod_timer() at this
@@ -618,18 +618,18 @@ static ssize_t _stp_ctl_read_cmd(struct file *file, char __user *buf,
 	unsigned long flags;
 
 	/* Prevent probe reentrancy while grabbing probe-used locks.  */
-	c = _stp_runtime_entryfn_get_context();
+	c = _stp_runtime_entryfn_get_context(__LINE__);
 
 	/* wait for nonempty ready queue */
 	spin_lock_irqsave(&_stp_ctl_ready_lock, flags);
 	while (list_empty(&_stp_ctl_ready_q)) {
 		spin_unlock_irqrestore(&_stp_ctl_ready_lock, flags);
-		_stp_runtime_entryfn_put_context(c);
+		_stp_runtime_entryfn_put_context(c, __LINE__);
 		if (file->f_flags & O_NONBLOCK)
 			return -EAGAIN;
 		if (wait_event_interruptible(_stp_ctl_wq, !list_empty(&_stp_ctl_ready_q)))
 			return -ERESTARTSYS;
-		c = _stp_runtime_entryfn_get_context();
+		c = _stp_runtime_entryfn_get_context(__LINE__);
 		spin_lock_irqsave(&_stp_ctl_ready_lock, flags);
 	}
 
@@ -639,7 +639,7 @@ static ssize_t _stp_ctl_read_cmd(struct file *file, char __user *buf,
 	spin_unlock_irqrestore(&_stp_ctl_ready_lock, flags);
 
 	/* NB: we can't hold the context across copy_to_user, as it might fault.  */
-	_stp_runtime_entryfn_put_context(c);
+	_stp_runtime_entryfn_put_context(c, __LINE__);
 
 	/* write it out */
 	len = bptr->len + 4;
@@ -655,9 +655,9 @@ static ssize_t _stp_ctl_read_cmd(struct file *file, char __user *buf,
 	}
 
 	/* put it on the pool of free buffers */
-	c = _stp_runtime_entryfn_get_context();
+	c = _stp_runtime_entryfn_get_context(__LINE__);
 	_stp_ctl_free_buffer(bptr);
-	_stp_runtime_entryfn_put_context(c);
+	_stp_runtime_entryfn_put_context(c, __LINE__);
 
 	return len;
 }

runtime/transport/transport.c

@@ -348,14 +348,14 @@ static void _stp_ctl_work_callback(unsigned long val)
 	struct context* __restrict__ c = NULL;
 
 	/* Prevent probe reentrancy while grabbing probe-used locks.  */
-	c = _stp_runtime_entryfn_get_context();
+	c = _stp_runtime_entryfn_get_context(__LINE__);
 
 	spin_lock_irqsave(&_stp_ctl_ready_lock, flags);
 	if (!list_empty(&_stp_ctl_ready_q))
 		do_io = 1;
 	spin_unlock_irqrestore(&_stp_ctl_ready_lock, flags);
 
-	_stp_runtime_entryfn_put_context(c);
+	_stp_runtime_entryfn_put_context(c, __LINE__);
 
 	if (do_io)
 		wake_up_interruptible(&_stp_ctl_wq);

tapsets.cxx

@@ -168,7 +168,7 @@ common_probe_entryfn_prologue (systemtap_session& s,
       pre_context_callback(s, callback_data);
       s.op->newline() << "#endif";
     }
-  s.op->newline() << "c = _stp_runtime_entryfn_get_context();";
+  s.op->newline() << "c = _stp_runtime_entryfn_get_context(__LINE__);";
   s.op->newline() << "if (!c) {";
   s.op->newline(1) << "#if !INTERRUPTIBLE";
   s.op->newline() << "atomic_inc (skipped_count());";
@@ -352,7 +352,7 @@ common_probe_entryfn_epilogue (systemtap_session& s,
 
   // We mustn't release the context until after all _stp_error(), so dyninst
   // mode can still access the log buffers stored therein.
-  s.op->newline() << "_stp_runtime_entryfn_put_context(c);";
+  s.op->newline() << "_stp_runtime_entryfn_put_context(c, __LINE__);";
 
   s.op->newline() << "#if !INTERRUPTIBLE";
   s.op->newline() << "local_irq_restore (flags);";

translate.cxx

@@ -1776,6 +1776,10 @@ c_unparser::emit_module_init ()
   o->newline() << "#include \"linux/stp_tracepoint.c\"";
   o->newline() << "#endif";
 
+  o->newline() << "#ifdef STAP_USER_HOOKS";
+  o->newline() << "static int stp_user_init(void);";
+  o->newline() << "#endif";
+
   o->newline();
   o->newline() << "static int systemtap_module_init (void) {";
   o->newline(1) << "int rc = 0;";
@@ -1924,6 +1928,15 @@ c_unparser::emit_module_init ()
   o->newline(1) << "goto out;";
   o->indent(-1);
 
+  // user init hook
+  o->newline() << "#ifdef STAP_USER_HOOKS";
+  o->newline() << "rc = stp_user_init();";
+  o->newline() << "if (rc) {";
+  o->newline(1) << "_stp_error (\"user init failed\");";
+  o->newline() << "goto out;";
+  o->newline(-1) << "}";
+  o->newline() << "#endif";
+
   for (unsigned i=0; i<session->globals.size(); i++)
     {
       vardecl* v = session->globals[i];
@@ -2169,6 +2182,10 @@ c_unparser::emit_module_refresh ()
 void
 c_unparser::emit_module_exit ()
 {
+  o->newline() << "#ifdef STAP_USER_HOOKS";
+  o->newline() << "static void stp_user_close(void);";
+  o->newline() << "#endif";
+
   o->newline() << "static void systemtap_module_exit (void) {";
   // rc?
   o->newline(1) << "int i=0, j=0;"; // for derived_probe_group use
@@ -2243,6 +2260,12 @@ c_unparser::emit_module_exit ()
 	o->newline() << getvar (v).fini();
     }
 
+  // user close hook
+  o->newline() << "#ifdef STAP_USER_HOOKS";
+  o->newline() << "stp_user_close();";
+  o->newline() << "#endif";
+
+
   // We're finished with the contexts if we're not in dyninst
   // mode. The dyninst mode needs the contexts, since print buffers
   // are stored there.
@@ -2253,7 +2276,7 @@ c_unparser::emit_module_exit ()
   else
     {
       o->newline() << "struct context* __restrict__ c;";
-      o->newline() << "c = _stp_runtime_entryfn_get_context();";
+      o->newline() << "c = _stp_runtime_entryfn_get_context(__LINE__);";
     }
 
   // teardown tracepoints (if needed)
@@ -2318,8 +2341,10 @@ c_unparser::emit_module_exit ()
       o->newline() << "#endif"; // STP_TIMING
     }
 
+  o->newline() << "#ifndef STP_PRINT_OFF";
   o->newline() << "_stp_print_flush();";
   o->newline() << "#endif";
+  o->newline() << "#endif";
 
   //print lock contentions if non-zero
   o->newline() << "#ifdef STP_TIMING";
@@ -2334,7 +2359,9 @@ c_unparser::emit_module_exit ()
 	           << lex_cast_qstring(orig_vn) << ", ctr);";
     }
   o->newline(-1) << "}";
+  o->newline() << "#ifndef STP_PRINT_OFF";
   o->newline() << "_stp_print_flush();";
+  o->newline() << "#endif";
   o->newline () << "#endif";
 
   // print final error/skipped counts if non-zero
@@ -2366,7 +2393,9 @@ c_unparser::emit_module_exit ()
   o->newline() << "if (ctr) _stp_warn (\"Skipped due to uprobe unregister failure: %d\\n\", ctr);";
   o->newline(-1) << "}";
   o->newline () << "#endif";
+  o->newline() << "#ifndef STP_PRINT_OFF";
   o->newline() << "_stp_print_flush();";
+  o->newline() << "#endif";
   o->newline(-1) << "}";
 
   // NB: PR13386 needs to restore preemption-blocking counts
@@ -2375,7 +2404,7 @@ c_unparser::emit_module_exit ()
   // In dyninst mode, now we're done with the contexts, transport, everything!
   if (session->runtime_usermode_p())
     {
-      o->newline() << "_stp_runtime_entryfn_put_context(c);";
+      o->newline() << "_stp_runtime_entryfn_put_context(c, __LINE__);";
       o->newline() << "_stp_dyninst_transport_shutdown();";
       o->newline() << "_stp_runtime_contexts_free();";
     }
@@ -2888,7 +2917,9 @@ c_unparser::emit_probe (derived_probe* v)
 
       // XXX: do this flush only if the body included a
       // print/printf/etc. routine!
+      o->newline() << "#ifndef STP_PRINT_OFF";
       o->newline() << "_stp_print_flush();";
+      o->newline() << "#endif";
       o->newline(-1) << "}\n";
     }