MINOR: debug: report the time since last wakeup and call

When task profiling is enabled, the current thread knows when the
currently running task was woken up and called, so we can calculate
how long ago it was woken up and called. This is convenient to figure
whether or not a warning or panic is caused by this task or by a
previous one, so let's report this info in thread outputs when known.

It would be useful to backport this to 3.2.

diff --git a/src/debug.c b/src/debug.c
index 19acb0ed1069e86ac71902d702bb6322a5896356..381831c9d68ec5935fc9ac47057e09ee5c154745 100644 (file)
--- a/src/debug.c
+++ b/src/debug.c
@@ -352,6 +352,18 @@ void ha_thread_dump_one(struct buffer *buf, int is_caller)
        chunk_appendf(buf, "\n");
        chunk_appendf(buf, "             cpu_ns: poll=%llu now=%llu diff=%llu\n", p, n, n-p);
 
+       /* also try to indicate for how long we've entered the current task.
+        * Note that the task's wake date only contains the 32 lower bits of
+        * the current time.
+        */
+       if (th_ctx->current && tick_isset(th_ctx->sched_wake_date)) {
+               unsigned long long now = now_mono_time();
+
+               chunk_appendf(buf, "             current call: wake=%u ns ago, call=%llu ns ago\n",
+                             (uint)(now - th_ctx->sched_wake_date),
+                             (now - th_ctx->sched_call_date));
+       }
+
        /* this is the end of what we can dump from outside the current thread */
 
        chunk_appendf(buf, "             curr_task=");

diff --git a/src/task.c b/src/task.c
index 11b5e635e3056ba5c11513a698e1a6604c2e2021..72be355f051fae67b3930a37d5d2df2790dc01c8 100644 (file)
--- a/src/task.c
+++ b/src/task.c
@@ -682,6 +682,7 @@ unsigned int run_tasks_from_lists(unsigned int budgets[])
                        HA_ATOMIC_ADD(&profile_entry->cpu_time, (uint32_t)(now_mono_time() - th_ctx->sched_call_date));
        }
        th_ctx->current_queue = -1;
+       th_ctx->sched_wake_date = TICK_ETERNITY;
 
        return done;
 }