link state changes take a "long" time to execute

[Robert Watson]

On Wed, 8 Jun 2005, Sam Leffler wrote:

> I don't think I ever committed the diagnostic code that checks for 
> long-running tasks so this must be something in your private tree.

Yes, I'm running with the attached patch which is more about measuring 
deadlines on tasks than run times on tasks.  I used to have similar 
diagnostics for run times but appear not to have it anymore.

Robert N M Watson

Index: sys/_task.h
===================================================================
RCS file: /home/ncvs/src/sys/sys/_task.h,v
retrieving revision 1.4
diff -u -r1.4 _task.h
--- sys/_task.h	24 Apr 2005 16:52:45 -0000	1.4
+++ sys/_task.h	1 Jun 2005 10:33:19 -0000
@@ -45,6 +45,7 @@
  	u_short	ta_priority;		/* Priority */
  	task_fn_t *ta_func;		/* task handler */
  	void	*ta_context;		/* argument for handler */
+	struct timespec ta_queuetime;	/* time enqueued */
  };

  #endif /* !_SYS__TASK_H_ */
Index: kern/subr_taskqueue.c
===================================================================
RCS file: /home/ncvs/src/sys/kern/subr_taskqueue.c,v
retrieving revision 1.27
diff -u -r1.27 subr_taskqueue.c
--- kern/subr_taskqueue.c	1 May 2005 00:38:11 -0000	1.27
+++ kern/subr_taskqueue.c	1 Jun 2005 10:40:08 -0000
@@ -36,10 +36,17 @@
  #include <sys/lock.h>
  #include <sys/malloc.h>
  #include <sys/mutex.h>
+#include <sys/sysctl.h>
  #include <sys/proc.h>
  #include <sys/taskqueue.h>
+#include <sys/time.h>
  #include <sys/unistd.h>

+int tq_in;
+SYSCTL_INT(_kern, OID_AUTO, tq_in, CTLFLAG_RD, &tq_in, 0, "");
+int tq_out;
+SYSCTL_INT(_kern, OID_AUTO, tq_out, CTLFLAG_RD, &tq_out, 0, "");
+
  static MALLOC_DEFINE(M_TASKQUEUE, "taskqueue", "Task Queues");
  static void	*taskqueue_giant_ih;
  static void	*taskqueue_ih;
@@ -166,6 +173,9 @@
  		return 0;
  	}

+	getnanotime(&task->ta_queuetime);
+	tq_in++;
+
  	/*
  	 * Optimise the case when all tasks have the same priority.
  	 */
@@ -197,6 +207,7 @@
  taskqueue_run(struct taskqueue *queue)
  {
  	struct task *task;
+	struct timespec tv;
  	int owned, pending;

  	owned = mtx_owned(&queue->tq_mutex);
@@ -211,9 +222,17 @@
  		STAILQ_REMOVE_HEAD(&queue->tq_queue, ta_link);
  		pending = task->ta_pending;
  		task->ta_pending = 0;
+		tq_out++;
  		queue->tq_running = task;
  		mtx_unlock(&queue->tq_mutex);

+		getnanotime(&tv);
+		timespecsub(&tv, &task->ta_queuetime);
+		if (tv.tv_nsec >= 50000000) {
+			printf("taskqueue_run: warning, queue time of %d.%09ld "
+			    "for context %p\n", tv.tv_sec, tv.tv_nsec,
+			    task->ta_func);
+		}
  		task->ta_func(task->ta_context, pending);

  		mtx_lock(&queue->tq_mutex);