1 files changed, 87 insertions, 0 deletions

diff --git a/lib/thread.c b/lib/thread.c
index 7b223ed6de..376f61c247 100644
--- a/lib/thread.c
+++ b/lib/thread.c
@@ -787,6 +787,7 @@ static struct thread *thread_get(struct thread_master *m, uint8_t type,
 	thread->arg = arg;
 	thread->yield = THREAD_YIELD_TIME_SLOT; /* default */
 	thread->ref = NULL;
+	thread->ignore_timer_late = false;
 
 	/*
 	 * So if the passed in funcname is not what we have
@@ -1651,12 +1652,31 @@ static void thread_process_io(struct thread_master *m, unsigned int num)
 static unsigned int thread_process_timers(struct thread_master *m,
 					  struct timeval *timenow)
 {
+	struct timeval prev = *timenow;
+	bool displayed = false;
 	struct thread *thread;
 	unsigned int ready = 0;
 
 	while ((thread = thread_timer_list_first(&m->timer))) {
 		if (timercmp(timenow, &thread->u.sands, <))
 			break;
+		prev = thread->u.sands;
+		prev.tv_sec += 4;
+		/*
+		 * If the timer would have popped 4 seconds in the
+		 * past then we are in a situation where we are
+		 * really getting behind on handling of events.
+		 * Let's log it and do the right thing with it.
+		 */
+		if (!displayed && !thread->ignore_timer_late &&
+		    timercmp(timenow, &prev, >)) {
+			flog_warn(
+				EC_LIB_STARVE_THREAD,
+				"Thread Starvation: %pTHD was scheduled to pop greater than 4s ago",
+				thread);
+			displayed = true;
+		}
+
 		thread_timer_list_pop(&m->timer);
 		thread->type = THREAD_READY;
 		thread_list_add_tail(&m->ready, thread);
@@ -2056,3 +2076,70 @@ bool thread_is_scheduled(struct thread *thread)
 
 	return true;
 }
+
+static ssize_t printfrr_thread_dbg(struct fbuf *buf, struct printfrr_eargs *ea,
+				   const struct thread *thread)
+{
+	static const char * const types[] = {
+		[THREAD_READ] = "read",
+		[THREAD_WRITE] = "write",
+		[THREAD_TIMER] = "timer",
+		[THREAD_EVENT] = "event",
+		[THREAD_READY] = "ready",
+		[THREAD_UNUSED] = "unused",
+		[THREAD_EXECUTE] = "exec",
+	};
+	ssize_t rv = 0;
+	char info[16] = "";
+
+	if (!thread)
+		return bputs(buf, "{(thread *)NULL}");
+
+	rv += bprintfrr(buf, "{(thread *)%p arg=%p", thread, thread->arg);
+
+	if (thread->type < array_size(types) && types[thread->type])
+		rv += bprintfrr(buf, " %-6s", types[thread->type]);
+	else
+		rv += bprintfrr(buf, " INVALID(%u)", thread->type);
+
+	switch (thread->type) {
+	case THREAD_READ:
+	case THREAD_WRITE:
+		snprintfrr(info, sizeof(info), "fd=%d", thread->u.fd);
+		break;
+
+	case THREAD_TIMER:
+		snprintfrr(info, sizeof(info), "r=%pTVMud", &thread->u.sands);
+		break;
+	}
+
+	rv += bprintfrr(buf, " %-12s %s() %s from %s:%d}", info,
+			thread->xref->funcname, thread->xref->dest,
+			thread->xref->xref.file, thread->xref->xref.line);
+	return rv;
+}
+
+printfrr_ext_autoreg_p("TH", printfrr_thread);
+static ssize_t printfrr_thread(struct fbuf *buf, struct printfrr_eargs *ea,
+			       const void *ptr)
+{
+	const struct thread *thread = ptr;
+	struct timespec remain = {};
+
+	if (ea->fmt[0] == 'D') {
+		ea->fmt++;
+		return printfrr_thread_dbg(buf, ea, thread);
+	}
+
+	if (!thread) {
+		/* need to jump over time formatting flag characters in the
+		 * input format string, i.e. adjust ea->fmt!
+		 */
+		printfrr_time(buf, ea, &remain,
+			      TIMEFMT_TIMER_DEADLINE | TIMEFMT_SKIP);
+		return bputch(buf, '-');
+	}
+
+	TIMEVAL_TO_TIMESPEC(&thread->u.sands, &remain);
+	return printfrr_time(buf, ea, &remain, TIMEFMT_TIMER_DEADLINE);
+}