Re: link state changes take a "long" time to execute

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
_at__at_ -45,6 +45,7 _at__at_
  	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
_at__at_ -36,10 +36,17 _at__at_
  #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;
_at__at_ -166,6 +173,9 _at__at_
  		return 0;
  	}

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

  	owned = mtx_owned(&queue->tq_mutex);
_at__at_ -211,9 +222,17 _at__at_
  		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);