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.

diff --git a/include/proto/task.h b/include/proto/task.h
index cc18bab31bbb96cb7a4a84827ab88fd2862f4f1f..264899e5d13da4fc0345ce6c22899aa43836be3f 100644 (file)
--- 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 bc64f43f5820c82e9106926b8afa9cb9b751ae03..e8ade67d6ee9ebd585b1a47085504b10e4403a72 100644 (file)
--- 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 f7222cdd162a1a442b4e253edcea19e2ed00067f..019556cc912e5c10667cb7f36c7f34a39e275486 100644 (file)
--- 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 3c84cbe6bf6e92b09dead266763806a0354078a1..96e7f886541973d53945ef88cb8870d82b830047 100644 (file)
--- 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 779dbf5d8890006adc416c09670e1d668971eaff..5c5e1043884ccfb9645fb75e180765c36263aab9 100644 (file)
--- 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