From beee600491c15861a923113ee322c9f57aba07e5 Mon Sep 17 00:00:00 2001 From: Willy Tarreau Date: Wed, 7 Sep 2022 16:17:49 +0200 Subject: [PATCH] BUG/MINOR: stream/sched: take into account CPU profiling for the last call When task profiling is enabled, the reported CPU time for short requests and responses (e.g. redirect) is always zero in the logs, because process_stream() is only called once and the CPU time is measured after it returns. This is particuarly annoying when dealing with denies and in general anything that deals with parasitic traffic because it can be difficult to figure where the CPU is spent. The solution taken in this patch consists in having process_stream() update the cpu time itself before logging and quitting. It's very simple. It will not take into account the time taken to produce the log nor freeing the stream, but that's marginal compared to always logging zero. The task's wake_date is also reset so that the scheduler doesn't have to perform these operations again. This is dependent on the following patch: MINOR: sched: store the current profile entry in the thread context It should be backported to 2.6 as it does help for troubleshooting. --- src/stream.c | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) diff --git a/src/stream.c b/src/stream.c index e268d68c6..8d6275405 100644 --- a/src/stream.c +++ b/src/stream.c @@ -1556,6 +1556,27 @@ static void stream_update_both_sc(struct stream *s) } } +/* if the current task's wake_date was set, it's being profiled, thus we may + * report latencies and CPU usages in logs, so it's desirable to do that before + * logging in order to report accurate CPU usage. In this case we count that + * final part and reset the wake date so that the scheduler doesn't do it a + * second time, and by doing so we also avoid an extra call to clock_gettime(). + * The CPU usage will be off by the little time needed to run over stream_free() + * but that's only marginal. + */ +static void stream_cond_update_cpu_usage(struct stream *s) +{ + uint32_t cpu; + + /* stats are only registered for non-zero wake dates */ + if (likely(!th_ctx->sched_wake_date)) + return; + + cpu = (uint32_t)now_mono_time() - th_ctx->sched_call_date; + s->task->cpu_time += cpu; + HA_ATOMIC_ADD(&th_ctx->sched_profile_entry->cpu_time, cpu); + th_ctx->sched_wake_date = 0; +} /* This macro is very specific to the function below. See the comments in * process_stream() below to understand the logic and the tests. @@ -2562,6 +2583,8 @@ struct task *process_stream(struct task *t, void *context, unsigned int state) (!(sess->fe->options & PR_O_NULLNOLOG) || req->total)) { /* we may need to know the position in the queue */ pendconn_free(s); + + stream_cond_update_cpu_usage(s); s->do_log(s); }