From 9efd7456e038457257b0901ebd77c4a54da2f83d Mon Sep 17 00:00:00 2001 From: Willy Tarreau Date: Thu, 31 May 2018 14:48:54 +0200 Subject: [PATCH] MEDIUM: tasks: collect per-task CPU time and latency Right now we measure for each task the cumulated time spent waiting for the CPU and using it. The timestamp uses a 64-bit integer to report a nanosecond-level date. This is only enabled when "profiling.tasks" is enabled, and consumes less than 1% extra CPU on x86_64 when enabled. The cumulated processing time and wait time are reported in "show sess". The task's counters are also reset when an HTTP transaction is reset since the HTTP part pretends to restart on a fresh new stream. This will make sure we always report correct numbers for each request in the logs. --- include/proto/task.h | 3 +++ include/types/task.h | 3 +++ src/proto_http.c | 6 ++++++ src/stream.c | 15 +++++++++------ src/task.c | 16 ++++++++++++++++ 5 files changed, 37 insertions(+), 6 deletions(-) diff --git a/include/proto/task.h b/include/proto/task.h index cc18bab31b..264899e5d1 100644 --- a/include/proto/task.h +++ b/include/proto/task.h @@ -299,6 +299,9 @@ static inline struct task *task_init(struct task *t, unsigned long thread_mask) t->thread_mask = thread_mask; t->nice = 0; t->calls = 0; + t->call_date = 0; + t->cpu_time = 0; + t->lat_time = 0; t->expire = TICK_ETERNITY; return t; } diff --git a/include/types/task.h b/include/types/task.h index bc64f43f58..e8ade67d6e 100644 --- a/include/types/task.h +++ b/include/types/task.h @@ -64,6 +64,7 @@ struct notification { unsigned short state; /* task state : bitfield of TASK_ */ \ short nice; /* task prio from -1024 to +1024, or -32768 for tasklets */ \ unsigned int calls; /* number of times process was called */ \ + uint64_t cpu_time; /* total CPU time consumed */ \ struct task *(*process)(struct task *t, void *ctx, unsigned short state); /* the function which processes the task */ \ void *context; /* the task's context */ \ } @@ -75,6 +76,8 @@ struct task { struct eb32_node wq; /* ebtree node used to hold the task in the wait queue */ int expire; /* next expiration date for this task, in ticks */ unsigned long thread_mask; /* mask of thread IDs authorized to process the task */ + uint64_t call_date; /* date of the last task wakeup or call */ + uint64_t lat_time; /* total latency time experienced */ }; /* lightweight tasks, without priority, mainly used for I/Os */ diff --git a/src/proto_http.c b/src/proto_http.c index f7222cdd16..019556cc91 100644 --- a/src/proto_http.c +++ b/src/proto_http.c @@ -3809,6 +3809,12 @@ void http_end_txn_clean_session(struct stream *s) stream_stop_content_counters(s); stream_update_time_stats(s); + /* reset the profiling counter */ + s->task->calls = 0; + s->task->cpu_time = 0; + s->task->lat_time = 0; + s->task->call_date = (profiling & HA_PROF_TASKS) ? now_mono_time() : 0; + s->logs.accept_date = date; /* user-visible date for logging */ s->logs.tv_accept = now; /* corrected date for internal use */ s->logs.t_handshake = 0; /* There are no handshake in keep alive connection. */ diff --git a/src/stream.c b/src/stream.c index 3c84cbe6bf..96e7f88654 100644 --- a/src/stream.c +++ b/src/stream.c @@ -2984,14 +2984,15 @@ static int stats_dump_full_strm_to_buffer(struct stream_interface *si, struct st } else if ((tmpctx = objt_appctx(strm->si[0].end)) != NULL) { chunk_appendf(&trash, - " app0=%p st0=%d st1=%d st2=%d applet=%s tmask=0x%lx nice=%d calls=%u\n", + " app0=%p st0=%d st1=%d st2=%d applet=%s tmask=0x%lx nice=%d calls=%u cpu=%llu lat=%llu\n", tmpctx, tmpctx->st0, tmpctx->st1, tmpctx->st2, tmpctx->applet->name, tmpctx->thread_mask, - tmpctx->t->nice, tmpctx->t->calls); + tmpctx->t->nice, tmpctx->t->calls, + (unsigned long long)tmpctx->t->cpu_time, (unsigned long long)tmpctx->t->lat_time); } if ((cs = objt_cs(strm->si[1].end)) != NULL) { @@ -3018,14 +3019,15 @@ static int stats_dump_full_strm_to_buffer(struct stream_interface *si, struct st } else if ((tmpctx = objt_appctx(strm->si[1].end)) != NULL) { chunk_appendf(&trash, - " app1=%p st0=%d st1=%d st2=%d applet=%s tmask=0x%lx, nice=%d, calls=%u\n", + " app1=%p st0=%d st1=%d st2=%d applet=%s tmask=0x%lx, nice=%d, calls=%u, cpu=%llu, lat=%llu\n", tmpctx, tmpctx->st0, tmpctx->st1, tmpctx->st2, tmpctx->applet->name, tmpctx->thread_mask, - tmpctx->t->nice, tmpctx->t->calls); + tmpctx->t->nice, tmpctx->t->calls, + (unsigned long long)tmpctx->t->cpu_time, (unsigned long long)tmpctx->t->lat_time); } chunk_appendf(&trash, @@ -3225,10 +3227,11 @@ static int cli_io_handler_dump_sess(struct appctx *appctx) } chunk_appendf(&trash, - " ts=%02x age=%s calls=%d", + " ts=%02x age=%s calls=%d cpu=%llu lat=%llu", curr_strm->task->state, human_time(now.tv_sec - curr_strm->logs.tv_accept.tv_sec, 1), - curr_strm->task->calls); + curr_strm->task->calls, + (unsigned long long)curr_strm->task->cpu_time, (unsigned long long)curr_strm->task->lat_time); chunk_appendf(&trash, " rq[f=%06xh,i=%u,an=%02xh,rx=%s", diff --git a/src/task.c b/src/task.c index 779dbf5d88..5c5e104388 100644 --- a/src/task.c +++ b/src/task.c @@ -140,6 +140,9 @@ redo: t->rq.key += offset; } + if (profiling & HA_PROF_TASKS) + t->call_date = now_mono_time(); + eb32sc_insert(root, &t->rq, t->thread_mask); #ifdef USE_THREAD if (root == &rqueue) { @@ -416,6 +419,14 @@ void process_runnable_tasks() ctx = t->context; process = t->process; t->calls++; + + if (unlikely(!TASK_IS_TASKLET(t) && t->call_date)) { + uint64_t now_ns = now_mono_time(); + + t->lat_time += now_ns - t->call_date; + t->call_date = now_ns; + } + curr_task = (struct task *)t; if (likely(process == process_stream)) t = process_stream(t, ctx, state); @@ -432,6 +443,11 @@ void process_runnable_tasks() * immediately, else we defer it into wait queue */ if (t != NULL) { + if (unlikely(!TASK_IS_TASKLET(t) && t->call_date)) { + t->cpu_time += now_mono_time() - t->call_date; + t->call_date = 0; + } + state = HA_ATOMIC_AND(&t->state, ~TASK_RUNNING); if (state) #ifdef USE_THREAD -- 2.39.5