MINOR: tasks: also compute the tasklet latency when DEBUG_TASK is set

It is extremely useful to be able to observe the wakeup latency of some
important I/O operations, so let's accept to inflate the tasklet struct
by 8 extra bytes when DEBUG_TASK is set. With just this we have enough
to get live reports like this:

  $ socat - /tmp/sock1 <<< "show profiling"
  Per-task CPU profiling              : on      # set profiling tasks {on|auto|off}
  Tasks activity:
    function                      calls   cpu_tot   cpu_avg   lat_tot   lat_avg
    si_cs_io_cb                 8099492   4.833s    596.0ns   8.974m    66.48us
    h1_io_cb                    7460365   11.55s    1.548us   2.477m    19.92us
    process_stream              7383828   22.79s    3.086us   18.39m    149.5us
    h1_timeout_task                4157      -         -      348.4ms   83.81us
    srv_cleanup_toremove_connections751   39.70ms   52.86us   10.54ms   14.04us
    srv_cleanup_idle_connections     21   1.405ms   66.89us   30.82us   1.467us
    task_run_applet                  16   1.058ms   66.13us   446.2us   27.89us
    accept_queue_process              7   34.53us   4.933us   333.1us   47.58us

diff --git a/include/haproxy/task-t.h b/include/haproxy/task-t.h
index 3df4bf6892f3c13910e103fa162e83ea1fa0532b..34d9a4565db71baf13d15b8fb19477e7927ca3c5 100644 (file)
--- a/include/haproxy/task-t.h
+++ b/include/haproxy/task-t.h
@@ -127,6 +127,9 @@ struct task {
 struct tasklet {
        TASK_COMMON;                    /* must be at the beginning! */
        struct list list;
+#ifdef DEBUG_TASK
+       uint64_t call_date;             /* date of the last tasklet wakeup or call */
+#endif
        int tid;                        /* TID of the tasklet owner, <0 if local */
 };
 

diff --git a/include/haproxy/task.h b/include/haproxy/task.h
index ce6418260cdb0864f55cfe37675a8ecebec94ac1..c717420f7700657ac139a0c952ca4f0569792a9a 100644 (file)
--- a/include/haproxy/task.h
+++ b/include/haproxy/task.h
@@ -368,6 +368,8 @@ static inline void _tasklet_wakeup_on(struct tasklet *tl, int thr, const char *f
        tl->debug.caller_idx = !tl->debug.caller_idx;
        tl->debug.caller_file[tl->debug.caller_idx] = file;
        tl->debug.caller_line[tl->debug.caller_idx] = line;
+       if (task_profiling_mask & tid_bit)
+               tl->call_date = now_mono_time();
 #endif
        __tasklet_wakeup_on(tl, thr);
 }

diff --git a/src/task.c b/src/task.c
index 9249068eca56b1c06d99a38d0fba9a77b22bdbe9..e33120fcf00dc05ad7f38ea05c5e923c0706919c 100644 (file)
--- a/src/task.c
+++ b/src/task.c
@@ -505,6 +505,9 @@ unsigned int run_tasks_from_lists(unsigned int budgets[])
 
                                profile_entry = sched_activity_entry(sched_activity, t->process);
                                before = now_mono_time();
+#ifdef DEBUG_TASK
+                               HA_ATOMIC_ADD(&profile_entry->lat_time, before - ((struct tasklet *)t)->call_date);
+#endif
                                process(t, ctx, state);
                                HA_ATOMIC_ADD(&profile_entry->calls, 1);
                                HA_ATOMIC_ADD(&profile_entry->cpu_time, now_mono_time() - before);