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

diff --git a/doc/management.txt b/doc/management.txt
index d221e18f236a44c362dee4a718fa7ef7cd592d11..99b3e5936cef17977e087003dd4216bc5d1a48c1 100644 (file)
--- 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 [<resolvers section id>]
   Dump statistics for the given resolvers section, or all resolvers sections

diff --git a/src/activity.c b/src/activity.c
index 0d64a36591316a66fa57ea733a7bd63349ae4ab9..e0e6693b7bdfe1bcc1ae1fba9af5625972285d0b 100644 (file)
--- 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);