timeout(9): new flag: TIMEOUT_SCHEDULED, new statistic: tos_scheduled

This flag is set whenever a timeout is put on the wheel and cleared upon
(a) running, (b) deletion, and (c) readdition.  It serves two purposes:

1. Facilitate distinguishing scheduled and rescheduled timeouts.  When a
   timeout is put on the wheel it is "scheduled" for a later softclock().
   If this happens two or more times it is also said to be "rescheduled".
   The tos_rescheduled value thus indicates how many distant timeouts
   have been cascaded into a lower wheel level.

2. Eliminate false late timeouts.  A timeout is not late if it is due
   before softclock() has had a chance to schedule it.  To track this we
   need additional state, hence a new flag.

rprocter@ raises some interesting questions.  Some answers:

 - This interface is not stable and name changes are possible at a
   later date.

 - Although rescheduling timeouts is a side effect of the underlying
   implementation, I don't forsee us using anything but a timeout wheel
   in the future.  Other data structures are too slow in practice, so
   I doubt that the concept of a rescheduled timeout will be irrelevant
   any time soon.

 - I think the development utility of gathering these sorts of statistics
   is high.  Watching the distribution of timeouts under a given workflow
   is informative.

ok visa@

3 files changed, 25 insertions, 19 deletions

diff --git a/sbin/sysctl/sysctl.c b/sbin/sysctl/sysctl.c
index 2611aab2a42..868d8ed77c4 100644
--- a/sbin/sysctl/sysctl.c
+++ b/sbin/sysctl/sysctl.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: sysctl.c,v 1.249 2019/11/28 16:27:25 guenther Exp $	*/
+/*	$OpenBSD: sysctl.c,v 1.250 2019/12/25 00:15:36 cheloha Exp $	*/
 /*	$NetBSD: sysctl.c,v 1.9 1995/09/30 07:12:50 thorpej Exp $	*/
 
 /*
@@ -1038,14 +1038,14 @@ parse(char *string, int flags)
 			printf("%s%s", string, equ);
 		printf("added = %llu, cancelled = %llu, deleted = %llu, "
 		    "late = %llu, pending = %llu, readded = %llu, "
-		    "rescheduled = %llu, run_softclock = %llu, "
-		    "run_thread = %llu, softclocks = %llu, "
-		    "thread_wakeups = %llu\n",
+		    "scheduled = %llu, rescheduled = %llu, "
+		    "run_softclock = %llu, run_thread = %llu, "
+		    "softclocks = %llu, thread_wakeups = %llu\n",
 		    tstat->tos_added, tstat->tos_cancelled, tstat->tos_deleted,
 		    tstat->tos_late, tstat->tos_pending, tstat->tos_readded,
-		    tstat->tos_rescheduled, tstat->tos_run_softclock,
-		    tstat->tos_run_thread, tstat->tos_softclocks,
-		    tstat->tos_thread_wakeups);
+		    tstat->tos_scheduled, tstat->tos_rescheduled,
+		    tstat->tos_run_softclock, tstat->tos_run_thread,
+		    tstat->tos_softclocks, tstat->tos_thread_wakeups);
 		return;
 	}
 	switch (type) {
diff --git a/sys/kern/kern_timeout.c b/sys/kern/kern_timeout.c
index 1ef591bbccb..27d667ed0e1 100644
--- a/sys/kern/kern_timeout.c
+++ b/sys/kern/kern_timeout.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: kern_timeout.c,v 1.66 2019/12/12 18:12:43 cheloha Exp $	*/
+/*	$OpenBSD: kern_timeout.c,v 1.67 2019/12/25 00:15:36 cheloha Exp $	*/
 /*
  * Copyright (c) 2001 Thomas Nordin <nordin@openbsd.org>
  * Copyright (c) 2000-2001 Artur Grabowski <art@openbsd.org>
@@ -250,7 +250,7 @@ timeout_add(struct timeout *new, int to_ticks)
 	/* Initialize the time here, it won't change. */
 	old_time = new->to_time;
 	new->to_time = to_ticks + ticks;
-	CLR(new->to_flags, TIMEOUT_TRIGGERED);
+	CLR(new->to_flags, TIMEOUT_TRIGGERED | TIMEOUT_SCHEDULED);
 
 	/*
 	 * If this timeout already is scheduled and now is moved
@@ -377,7 +377,7 @@ timeout_del(struct timeout *to)
 		tostat.tos_cancelled++;
 		ret = 1;
 	}
-	CLR(to->to_flags, TIMEOUT_TRIGGERED);
+	CLR(to->to_flags, TIMEOUT_TRIGGERED | TIMEOUT_SCHEDULED);
 	tostat.tos_deleted++;
 	mtx_leave(&timeout_mutex);
 
@@ -471,7 +471,7 @@ timeout_run(struct timeout *to)
 
 	MUTEX_ASSERT_LOCKED(&timeout_mutex);
 
-	CLR(to->to_flags, TIMEOUT_ONQUEUE);
+	CLR(to->to_flags, TIMEOUT_ONQUEUE | TIMEOUT_SCHEDULED);
 	SET(to->to_flags, TIMEOUT_TRIGGERED);
 
 	fn = to->to_func;
@@ -512,10 +512,14 @@ softclock(void *arg)
 		if (delta > 0) {
 			bucket = &BUCKET(delta, to->to_time);
 			CIRCQ_INSERT_TAIL(bucket, &to->to_list);
-			tostat.tos_rescheduled++;
+			if (ISSET(to->to_flags, TIMEOUT_SCHEDULED))
+				tostat.tos_rescheduled++;
+			else
+				SET(to->to_flags, TIMEOUT_SCHEDULED);
+			tostat.tos_scheduled++;
 			continue;
 		}
-		if (delta < 0)
+		if (ISSET(to->to_flags, TIMEOUT_SCHEDULED) && delta < 0)
 			tostat.tos_late++;
 		if (ISSET(to->to_flags, TIMEOUT_NEEDPROCCTX)) {
 			CIRCQ_INSERT_TAIL(&timeout_proc, &to->to_list);
diff --git a/sys/sys/timeout.h b/sys/sys/timeout.h
index 82e7caf7f04..c72016b9b29 100644
--- a/sys/sys/timeout.h
+++ b/sys/sys/timeout.h
@@ -1,4 +1,4 @@
-/*	$OpenBSD: timeout.h,v 1.32 2019/12/02 21:47:54 cheloha Exp $	*/
+/*	$OpenBSD: timeout.h,v 1.33 2019/12/25 00:15:36 cheloha Exp $	*/
 /*
  * Copyright (c) 2000-2001 Artur Grabowski <art@openbsd.org>
  * All rights reserved. 
@@ -67,10 +67,11 @@ struct timeout {
 /*
  * flags in the to_flags field.
  */
-#define TIMEOUT_NEEDPROCCTX	1	/* timeout needs a process context */
-#define TIMEOUT_ONQUEUE		2	/* timeout is on the todo queue */
-#define TIMEOUT_INITIALIZED	4	/* timeout is initialized */
-#define TIMEOUT_TRIGGERED	8	/* timeout is running or ran */
+#define TIMEOUT_NEEDPROCCTX	0x01	/* needs a process context */
+#define TIMEOUT_ONQUEUE		0x02	/* on any timeout queue */
+#define TIMEOUT_INITIALIZED	0x04	/* initialized */
+#define TIMEOUT_TRIGGERED	0x08	/* running or ran */
+#define TIMEOUT_SCHEDULED	0x10	/* put on wheel at least once */
 
 struct timeoutstat {
 	uint64_t tos_added;		/* timeout_add*(9) calls */
@@ -79,9 +80,10 @@ struct timeoutstat {
 	uint64_t tos_late;		/* run after deadline */
 	uint64_t tos_pending;		/* number currently ONQUEUE */
 	uint64_t tos_readded;		/* timeout_add*(9) + already ONQUEUE */
-	uint64_t tos_rescheduled;	/* requeued from softclock() */
+	uint64_t tos_rescheduled;	/* bucketed + already SCHEDULED */
 	uint64_t tos_run_softclock;	/* run from softclock() */
 	uint64_t tos_run_thread;	/* run from softclock_thread() */
+	uint64_t tos_scheduled;		/* bucketed during softclock() */
 	uint64_t tos_softclocks;	/* softclock() calls */
 	uint64_t tos_thread_wakeups;	/* wakeups in softclock_thread() */
 };