From 1bd67e9b0363a040f2b6e53c2715a28e47b18eca Mon Sep 17 00:00:00 2001 From: Willy Tarreau Date: Fri, 29 Jan 2021 00:07:40 +0100 Subject: [PATCH] MINOR: activity: also report collected tasks stats in "show profiling" "show profiling" will now dump the stats collected by the scheduler if profiling was previously enabled. This will immediately make it obvious what functions are responsible for others' high latencies or which ones are suffering from others, and should help spot issues like undesired wakeups. Example: 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 5569479 23.37s 4.196us - - h1_io_cb 5558654 13.60s 2.446us - - process_stream 250841 1.476s 5.882us 3.499s 13.95us main+0x9e670 198 - - 5.526ms 27.91us task_run_applet 17 1.509ms 88.77us 205.8us 12.11us srv_cleanup_idle_connections 12 44.51us 3.708us 25.71us 2.142us main+0x158c80 9 48.72us 5.413us - - srv_cleanup_toremove_connections 5 165.1us 33.02us 123.6us 24.72us --- doc/management.txt | 4 +++- src/activity.c | 44 ++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 47 insertions(+), 1 deletion(-) diff --git a/doc/management.txt b/doc/management.txt index d221e18f2..99b3e5936 100644 --- a/doc/management.txt +++ b/doc/management.txt @@ -2310,7 +2310,9 @@ show pools show profiling Dumps the current profiling settings, one per line, as well as the command - needed to change them. + needed to change them. When tasks profiling is enabled, some per-function + statistics collected by the scheduler will also be emitted, with a summary + covering the number of calls, total/avg CPU time and total/avg latency. show resolvers [] Dump statistics for the given resolvers section, or all resolvers sections diff --git a/src/activity.c b/src/activity.c index 0d64a3659..e0e6693b7 100644 --- a/src/activity.c +++ b/src/activity.c @@ -97,13 +97,29 @@ static int cli_parse_set_profiling(char **args, char *payload, struct appctx *ap return 1; } +static int cmp_sched_activity(const void *a, const void *b) +{ + const struct sched_activity *l = (const struct sched_activity *)a; + const struct sched_activity *r = (const struct sched_activity *)b; + + if (l->calls > r->calls) + return -1; + else if (l->calls < r->calls) + return 1; + else + return 0; +} + /* This function dumps all profiling settings. It returns 0 if the output * buffer is full and it needs to be called again, otherwise non-zero. */ static int cli_io_handler_show_profiling(struct appctx *appctx) { + struct sched_activity tmp_activity[256] __attribute__((aligned(64))); struct stream_interface *si = appctx->owner; + struct buffer *name_buffer = get_trash_chunk(); const char *str; + int i, max; if (unlikely(si_ic(si)->flags & (CF_WRITE_ERROR|CF_SHUTW))) return 1; @@ -117,10 +133,38 @@ static int cli_io_handler_show_profiling(struct appctx *appctx) default: str="off"; break; } + memcpy(tmp_activity, sched_activity, sizeof(tmp_activity)); + qsort(tmp_activity, 256, sizeof(tmp_activity[0]), cmp_sched_activity); + chunk_printf(&trash, "Per-task CPU profiling : %s # set profiling tasks {on|auto|off}\n", str); + chunk_appendf(&trash, "Tasks activity:\n" + " function calls cpu_tot cpu_avg lat_tot lat_avg\n"); + + for (i = 0; i < 256 && tmp_activity[i].calls; i++) { + chunk_reset(name_buffer); + + if (!tmp_activity[i].func) + chunk_printf(name_buffer, "other"); + else + resolve_sym_name(name_buffer, "", tmp_activity[i].func); + + /* reserve 35 chars for name+' '+#calls, knowing that longer names + * are often used for less often called functions. + */ + max = 35 - name_buffer->data; + if (max < 1) + max = 1; + chunk_appendf(&trash, " %s%*llu", name_buffer->area, max, (unsigned long long)tmp_activity[i].calls); + + print_time_short(&trash, " ", tmp_activity[i].cpu_time, ""); + print_time_short(&trash, " ", tmp_activity[i].cpu_time / tmp_activity[i].calls, ""); + print_time_short(&trash, " ", tmp_activity[i].lat_time, ""); + print_time_short(&trash, " ", tmp_activity[i].lat_time / tmp_activity[i].calls, "\n"); + } + if (ci_putchk(si_ic(si), &trash) == -1) { /* failed, try again */ si_rx_room_blk(si);