blob: 2080fd6dd64b8cb078a2d7b4eee826f9e12cc22e [file] [log] [blame]
Willy Tarreau609aad92018-11-22 08:31:09 +01001/*
2 * activity measurement functions.
3 *
4 * Copyright 2000-2018 Willy Tarreau <w@1wt.eu>
5 *
6 * This program is free software; you can redistribute it and/or
7 * modify it under the terms of the GNU General Public License
8 * as published by the Free Software Foundation; either version
9 * 2 of the License, or (at your option) any later version.
10 *
11 */
12
Willy Tarreaub2551052020-06-09 09:07:15 +020013#include <haproxy/activity-t.h>
Willy Tarreau4c7e4b72020-05-27 12:58:42 +020014#include <haproxy/api.h>
Willy Tarreau6be78492020-06-05 00:00:29 +020015#include <haproxy/cfgparse.h>
Willy Tarreauf1d32c42020-06-04 21:07:02 +020016#include <haproxy/channel.h>
Willy Tarreau83487a82020-06-04 20:19:54 +020017#include <haproxy/cli.h>
Willy Tarreaub2551052020-06-09 09:07:15 +020018#include <haproxy/freq_ctr.h>
Willy Tarreau5e539c92020-06-04 20:45:39 +020019#include <haproxy/stream_interface.h>
Willy Tarreau48fbcae2020-06-03 18:09:46 +020020#include <haproxy/tools.h>
Willy Tarreau75c62c22018-11-22 11:02:09 +010021
Willy Tarreauf93c7be2021-05-05 17:07:09 +020022#if defined(DEBUG_MEM_STATS)
23/* these ones are macros in bug.h when DEBUG_MEM_STATS is set, and will
24 * prevent the new ones from being redefined.
25 */
26#undef calloc
27#undef malloc
28#undef realloc
29#endif
Willy Tarreau75c62c22018-11-22 11:02:09 +010030
31/* bit field of profiling options. Beware, may be modified at runtime! */
Willy Tarreauef7380f2021-05-05 16:28:31 +020032unsigned int profiling __read_mostly = HA_PROF_TASKS_AOFF;
33unsigned long task_profiling_mask __read_mostly = 0;
Willy Tarreau609aad92018-11-22 08:31:09 +010034
35/* One struct per thread containing all collected measurements */
36struct activity activity[MAX_THREADS] __attribute__((aligned(64))) = { };
37
Willy Tarreau3fb6a7b2021-01-28 19:19:26 +010038/* One struct per function pointer hash entry (256 values, 0=collision) */
39struct sched_activity sched_activity[256] __attribute__((aligned(64))) = { };
Willy Tarreau609aad92018-11-22 08:31:09 +010040
Willy Tarreaudb87fc72021-05-05 16:50:40 +020041
42#if USE_MEMORY_PROFILING
43/* determine the number of buckets to store stats */
44#define MEMPROF_HASH_BITS 10
45#define MEMPROF_HASH_BUCKETS (1U << MEMPROF_HASH_BITS)
46
47/* stats:
48 * - malloc increases alloc
49 * - free increases free (if non null)
50 * - realloc increases either depending on the size change.
51 * when the real size is known (malloc_usable_size()), it's used in free_tot
52 * and alloc_tot, otherwise the requested size is reported in alloc_tot and
53 * zero in free_tot.
54 */
55struct memprof_stats {
56 const void *caller;
57 unsigned long long alloc_calls;
58 unsigned long long free_calls;
59 unsigned long long alloc_tot;
60 unsigned long long free_tot;
61};
62
63/* last one is for hash collisions ("others") and has no caller address */
64struct memprof_stats memprof_stats[MEMPROF_HASH_BUCKETS + 1] = { };
65
Willy Tarreauf93c7be2021-05-05 17:07:09 +020066/* used to detect recursive calls */
67static THREAD_LOCAL int in_memprof = 0;
68
69/* perform a pointer hash by scrambling its bits and retrieving the most
70 * mixed ones (topmost ones in 32-bit, middle ones in 64-bit).
71 */
72static unsigned int memprof_hash_ptr(const void *p)
73{
74 unsigned long long x = (unsigned long)p;
75
76 x = 0xcbda9653U * x;
77 if (sizeof(long) == 4)
78 x >>= 32;
79 else
80 x >>= 33 - MEMPROF_HASH_BITS / 2;
81 return x & (MEMPROF_HASH_BUCKETS - 1);
82}
83
84/* These ones are used by glibc and will be called early. They are in charge of
85 * initializing the handlers with the original functions.
86 */
87static void *memprof_malloc_initial_handler(size_t size);
88static void *memprof_calloc_initial_handler(size_t nmemb, size_t size);
89static void *memprof_realloc_initial_handler(void *ptr, size_t size);
90static void memprof_free_initial_handler(void *ptr);
91
92/* Fallback handlers for the main alloc/free functions. They are preset to
93 * the initializer in order to save a test in the functions's critical path.
94 */
95static void *(*memprof_malloc_handler)(size_t size) = memprof_malloc_initial_handler;
96static void *(*memprof_calloc_handler)(size_t nmemb, size_t size) = memprof_calloc_initial_handler;
97static void *(*memprof_realloc_handler)(void *ptr, size_t size) = memprof_realloc_initial_handler;
98static void (*memprof_free_handler)(void *ptr) = memprof_free_initial_handler;
99
100/* Used to force to die if it's not possible to retrieve the allocation
101 * functions. We cannot even use stdio in this case.
102 */
103static __attribute__((noreturn)) void memprof_die(const char *msg)
104{
105 DISGUISE(write(2, msg, strlen(msg)));
106 exit(1);
107}
108
109/* Resolve original allocation functions and initialize all handlers.
110 * This must be called very early at boot, before the very first malloc()
111 * call, and is not thread-safe! It's not even possible to use stdio there.
112 * Worse, we have to account for the risk of reentrance from dlsym() when
113 * it tries to prepare its error messages. Here its ahndled by in_memprof
114 * that makes allocators return NULL. dlsym() handles it gracefully. An
115 * alternate approch consists in calling aligned_alloc() from these places
116 * but that would mean not being able to intercept it later if considered
117 * useful to do so.
118 */
119static void memprof_init()
120{
121 in_memprof++;
122 memprof_malloc_handler = get_sym_next_addr("malloc");
123 if (!memprof_malloc_handler)
124 memprof_die("FATAL: malloc() function not found.\n");
125
126 memprof_calloc_handler = get_sym_next_addr("calloc");
127 if (!memprof_calloc_handler)
128 memprof_die("FATAL: calloc() function not found.\n");
129
130 memprof_realloc_handler = get_sym_next_addr("realloc");
131 if (!memprof_realloc_handler)
132 memprof_die("FATAL: realloc() function not found.\n");
133
134 memprof_free_handler = get_sym_next_addr("free");
135 if (!memprof_free_handler)
136 memprof_die("FATAL: free() function not found.\n");
137 in_memprof--;
138}
139
140/* the initial handlers will initialize all regular handlers and will call the
141 * one they correspond to. A single one of these functions will typically be
142 * called, though it's unknown which one (as any might be called before main).
143 */
144static void *memprof_malloc_initial_handler(size_t size)
145{
146 if (in_memprof) {
147 /* it's likely that dlsym() needs malloc(), let's fail */
148 return NULL;
149 }
150
151 memprof_init();
152 return memprof_malloc_handler(size);
153}
154
155static void *memprof_calloc_initial_handler(size_t nmemb, size_t size)
156{
157 if (in_memprof) {
158 /* it's likely that dlsym() needs calloc(), let's fail */
159 return NULL;
160 }
161 memprof_init();
162 return memprof_calloc_handler(nmemb, size);
163}
164
165static void *memprof_realloc_initial_handler(void *ptr, size_t size)
166{
167 if (in_memprof) {
168 /* it's likely that dlsym() needs realloc(), let's fail */
169 return NULL;
170 }
171
172 memprof_init();
173 return memprof_realloc_handler(ptr, size);
174}
175
176static void memprof_free_initial_handler(void *ptr)
177{
178 memprof_init();
179 memprof_free_handler(ptr);
180}
181
182/* Assign a bin for the memprof_stats to the return address. May perform a few
183 * attempts before finding the right one, but always succeeds (in the worst
184 * case, returns a default bin). The caller address is atomically set except
185 * for the default one which is never set.
186 */
187static struct memprof_stats *memprof_get_bin(const void *ra)
188{
189 int retries = 16; // up to 16 consecutive entries may be tested.
190 void *old;
191 unsigned int bin;
192
193 bin = memprof_hash_ptr(ra);
194 for (; memprof_stats[bin].caller != ra; bin = (bin + 1) & (MEMPROF_HASH_BUCKETS - 1)) {
195 if (!--retries) {
196 bin = MEMPROF_HASH_BUCKETS;
197 break;
198 }
199
200 old = NULL;
201 if (!memprof_stats[bin].caller &&
202 HA_ATOMIC_CAS(&memprof_stats[bin].caller, &old, ra))
203 break;
204 }
205 return &memprof_stats[bin];
206}
207
208/* This is the new global malloc() function. It must optimize for the normal
209 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
210 * It must remain simple to guarantee the lack of reentrance. stdio is not
211 * possible there even for debugging. The reported size is the really allocated
212 * one as returned by malloc_usable_size(), because this will allow it to be
213 * compared to the one before realloc() or free(). This is a GNU and jemalloc
214 * extension but other systems may also store this size in ptr[-1].
215 */
216void *malloc(size_t size)
217{
218 struct memprof_stats *bin;
219 void *ret;
220
221 if (likely(!(profiling & HA_PROF_MEMORY)))
222 return memprof_malloc_handler(size);
223
224 ret = memprof_malloc_handler(size);
225 size = malloc_usable_size(ret);
226
227 bin = memprof_get_bin(__builtin_return_address(0));
228 _HA_ATOMIC_ADD(&bin->alloc_calls, 1);
229 _HA_ATOMIC_ADD(&bin->alloc_tot, size);
230 return ret;
231}
232
233/* This is the new global calloc() function. It must optimize for the normal
234 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
235 * It must remain simple to guarantee the lack of reentrance. stdio is not
236 * possible there even for debugging. The reported size is the really allocated
237 * one as returned by malloc_usable_size(), because this will allow it to be
238 * compared to the one before realloc() or free(). This is a GNU and jemalloc
239 * extension but other systems may also store this size in ptr[-1].
240 */
241void *calloc(size_t nmemb, size_t size)
242{
243 struct memprof_stats *bin;
244 void *ret;
245
246 if (likely(!(profiling & HA_PROF_MEMORY)))
247 return memprof_calloc_handler(nmemb, size);
248
249 ret = memprof_calloc_handler(nmemb, size);
250 size = malloc_usable_size(ret);
251
252 bin = memprof_get_bin(__builtin_return_address(0));
253 _HA_ATOMIC_ADD(&bin->alloc_calls, 1);
254 _HA_ATOMIC_ADD(&bin->alloc_tot, size);
255 return ret;
256}
257
258/* This is the new global realloc() function. It must optimize for the normal
259 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
260 * It must remain simple to guarantee the lack of reentrance. stdio is not
261 * possible there even for debugging. The reported size is the really allocated
262 * one as returned by malloc_usable_size(), because this will allow it to be
263 * compared to the one before realloc() or free(). This is a GNU and jemalloc
264 * extension but other systems may also store this size in ptr[-1].
265 * Depending on the old vs new size, it's considered as an allocation or a free
266 * (or neither if the size remains the same).
267 */
268void *realloc(void *ptr, size_t size)
269{
270 struct memprof_stats *bin;
271 size_t size_before;
272 void *ret;
273
274 if (likely(!(profiling & HA_PROF_MEMORY)))
275 return memprof_realloc_handler(ptr, size);
276
277 size_before = malloc_usable_size(ptr);
278 ret = memprof_realloc_handler(ptr, size);
Willy Tarreau2639e2e2021-05-07 08:01:35 +0200279 size = malloc_usable_size(ret);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200280
281 bin = memprof_get_bin(__builtin_return_address(0));
282 if (size > size_before) {
283 _HA_ATOMIC_ADD(&bin->alloc_calls, 1);
284 _HA_ATOMIC_ADD(&bin->alloc_tot, size);
285 } else if (size < size_before) {
286 _HA_ATOMIC_ADD(&bin->free_calls, 1);
287 _HA_ATOMIC_ADD(&bin->free_tot, size_before);
288 }
289 return ret;
290}
291
292/* This is the new global free() function. It must optimize for the normal
293 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
294 * It must remain simple to guarantee the lack of reentrance. stdio is not
295 * possible there even for debugging. The reported size is the really allocated
296 * one as returned by malloc_usable_size(), because this will allow it to be
297 * compared to the one before realloc() or free(). This is a GNU and jemalloc
298 * extension but other systems may also store this size in ptr[-1]. Since
299 * free() is often called on NULL pointers to collect garbage at the end of
300 * many functions or during config parsing, as a special case free(NULL)
301 * doesn't update any stats.
302 */
303void free(void *ptr)
304{
305 struct memprof_stats *bin;
306 size_t size_before;
307
308 if (likely(!(profiling & HA_PROF_MEMORY) || !ptr)) {
309 memprof_free_handler(ptr);
310 return;
311 }
312
313 size_before = malloc_usable_size(ptr);
314 memprof_free_handler(ptr);
315
316 bin = memprof_get_bin(__builtin_return_address(0));
317 _HA_ATOMIC_ADD(&bin->free_calls, 1);
318 _HA_ATOMIC_ADD(&bin->free_tot, size_before);
319}
320
Willy Tarreaudb87fc72021-05-05 16:50:40 +0200321#endif // USE_MEMORY_PROFILING
322
Willy Tarreau609aad92018-11-22 08:31:09 +0100323/* Updates the current thread's statistics about stolen CPU time. The unit for
324 * <stolen> is half-milliseconds.
325 */
326void report_stolen_time(uint64_t stolen)
327{
328 activity[tid].cpust_total += stolen;
329 update_freq_ctr(&activity[tid].cpust_1s, stolen);
330 update_freq_ctr_period(&activity[tid].cpust_15s, 15000, stolen);
331}
Willy Tarreau75c62c22018-11-22 11:02:09 +0100332
Willy Tarreauca3afc22021-05-05 18:33:19 +0200333#ifdef USE_MEMORY_PROFILING
334/* config parser for global "profiling.memory", accepts "on" or "off" */
335static int cfg_parse_prof_memory(char **args, int section_type, struct proxy *curpx,
336 const struct proxy *defpx, const char *file, int line,
337 char **err)
338{
339 if (too_many_args(1, args, err, NULL))
340 return -1;
341
342 if (strcmp(args[1], "on") == 0)
343 profiling |= HA_PROF_MEMORY;
344 else if (strcmp(args[1], "off") == 0)
345 profiling &= ~HA_PROF_MEMORY;
346 else {
347 memprintf(err, "'%s' expects either 'on' or 'off' but got '%s'.", args[0], args[1]);
348 return -1;
349 }
350 return 0;
351}
352#endif // USE_MEMORY_PROFILING
353
Willy Tarreau75c62c22018-11-22 11:02:09 +0100354/* config parser for global "profiling.tasks", accepts "on" or "off" */
355static int cfg_parse_prof_tasks(char **args, int section_type, struct proxy *curpx,
Willy Tarreau01825162021-03-09 09:53:46 +0100356 const struct proxy *defpx, const char *file, int line,
Willy Tarreau75c62c22018-11-22 11:02:09 +0100357 char **err)
358{
359 if (too_many_args(1, args, err, NULL))
360 return -1;
361
362 if (strcmp(args[1], "on") == 0)
Willy Tarreaud2d33482019-04-25 17:09:07 +0200363 profiling = (profiling & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_ON;
364 else if (strcmp(args[1], "auto") == 0)
Willy Tarreauaa622b82021-01-28 21:44:22 +0100365 profiling = (profiling & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_AOFF;
Willy Tarreau75c62c22018-11-22 11:02:09 +0100366 else if (strcmp(args[1], "off") == 0)
Willy Tarreaud2d33482019-04-25 17:09:07 +0200367 profiling = (profiling & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_OFF;
Willy Tarreau75c62c22018-11-22 11:02:09 +0100368 else {
Willy Tarreaud2d33482019-04-25 17:09:07 +0200369 memprintf(err, "'%s' expects either 'on', 'auto', or 'off' but got '%s'.", args[0], args[1]);
Willy Tarreau75c62c22018-11-22 11:02:09 +0100370 return -1;
371 }
372 return 0;
373}
374
375/* parse a "set profiling" command. It always returns 1. */
376static int cli_parse_set_profiling(char **args, char *payload, struct appctx *appctx, void *private)
377{
Willy Tarreau75c62c22018-11-22 11:02:09 +0100378 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
379 return 1;
380
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200381 if (strcmp(args[2], "memory") == 0) {
Willy Tarreaudb87fc72021-05-05 16:50:40 +0200382#ifdef USE_MEMORY_PROFILING
383 if (strcmp(args[3], "on") == 0) {
384 unsigned int old = profiling;
385 int i;
386
387 while (!_HA_ATOMIC_CAS(&profiling, &old, old | HA_PROF_MEMORY))
388 ;
389
390 /* also flush current profiling stats */
391 for (i = 0; i < sizeof(memprof_stats) / sizeof(memprof_stats[0]); i++) {
392 HA_ATOMIC_STORE(&memprof_stats[i].alloc_calls, 0);
393 HA_ATOMIC_STORE(&memprof_stats[i].free_calls, 0);
394 HA_ATOMIC_STORE(&memprof_stats[i].alloc_tot, 0);
395 HA_ATOMIC_STORE(&memprof_stats[i].free_tot, 0);
396 HA_ATOMIC_STORE(&memprof_stats[i].caller, NULL);
397 }
398 }
399 else if (strcmp(args[3], "off") == 0) {
400 unsigned int old = profiling;
401
402 while (!_HA_ATOMIC_CAS(&profiling, &old, old & ~HA_PROF_MEMORY))
403 ;
404 }
405 else
406 return cli_err(appctx, "Expects either 'on' or 'off'.\n");
407 return 1;
408#else
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200409 return cli_err(appctx, "Memory profiling not compiled in.\n");
Willy Tarreaudb87fc72021-05-05 16:50:40 +0200410#endif
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200411 }
412
Willy Tarreau9d008692019-08-09 11:21:01 +0200413 if (strcmp(args[2], "tasks") != 0)
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200414 return cli_err(appctx, "Expects etiher 'tasks' or 'memory'.\n");
Willy Tarreau75c62c22018-11-22 11:02:09 +0100415
Willy Tarreaud2d33482019-04-25 17:09:07 +0200416 if (strcmp(args[3], "on") == 0) {
417 unsigned int old = profiling;
Willy Tarreaucfa71012021-01-29 11:56:21 +0100418 int i;
419
Willy Tarreaud2d33482019-04-25 17:09:07 +0200420 while (!_HA_ATOMIC_CAS(&profiling, &old, (old & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_ON))
421 ;
Willy Tarreaucfa71012021-01-29 11:56:21 +0100422 /* also flush current profiling stats */
423 for (i = 0; i < 256; i++) {
424 HA_ATOMIC_STORE(&sched_activity[i].calls, 0);
425 HA_ATOMIC_STORE(&sched_activity[i].cpu_time, 0);
426 HA_ATOMIC_STORE(&sched_activity[i].lat_time, 0);
427 HA_ATOMIC_STORE(&sched_activity[i].func, NULL);
428 }
Willy Tarreaud2d33482019-04-25 17:09:07 +0200429 }
430 else if (strcmp(args[3], "auto") == 0) {
431 unsigned int old = profiling;
Willy Tarreauaa622b82021-01-28 21:44:22 +0100432 unsigned int new;
433
434 do {
435 if ((old & HA_PROF_TASKS_MASK) >= HA_PROF_TASKS_AON)
436 new = (old & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_AON;
437 else
438 new = (old & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_AOFF;
439 } while (!_HA_ATOMIC_CAS(&profiling, &old, new));
Willy Tarreaud2d33482019-04-25 17:09:07 +0200440 }
441 else if (strcmp(args[3], "off") == 0) {
442 unsigned int old = profiling;
443 while (!_HA_ATOMIC_CAS(&profiling, &old, (old & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_OFF))
444 ;
445 }
Willy Tarreau9d008692019-08-09 11:21:01 +0200446 else
447 return cli_err(appctx, "Expects 'on', 'auto', or 'off'.\n");
448
Willy Tarreau75c62c22018-11-22 11:02:09 +0100449 return 1;
450}
451
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100452static int cmp_sched_activity(const void *a, const void *b)
453{
454 const struct sched_activity *l = (const struct sched_activity *)a;
455 const struct sched_activity *r = (const struct sched_activity *)b;
456
457 if (l->calls > r->calls)
458 return -1;
459 else if (l->calls < r->calls)
460 return 1;
461 else
462 return 0;
463}
464
Willy Tarreau993d44d2021-05-05 18:07:02 +0200465#if USE_MEMORY_PROFILING
466/* used by qsort below */
467static int cmp_memprof_stats(const void *a, const void *b)
468{
469 const struct memprof_stats *l = (const struct memprof_stats *)a;
470 const struct memprof_stats *r = (const struct memprof_stats *)b;
471
472 if (l->alloc_tot + l->free_tot > r->alloc_tot + r->free_tot)
473 return -1;
474 else if (l->alloc_tot + l->free_tot < r->alloc_tot + r->free_tot)
475 return 1;
476 else
477 return 0;
478}
479#endif // USE_MEMORY_PROFILING
480
Willy Tarreau75c62c22018-11-22 11:02:09 +0100481/* This function dumps all profiling settings. It returns 0 if the output
482 * buffer is full and it needs to be called again, otherwise non-zero.
Willy Tarreau637d85a2021-05-05 17:33:27 +0200483 * It dumps some parts depending on the following states:
484 * ctx.cli.i0:
485 * 0, 4: dump status, then jump to 1 if 0
486 * 1, 5: dump tasks, then jump to 2 if 1
487 * 2, 6: dump memory, then stop
488 * ctx.cli.i1:
489 * restart line for each step (starts at zero)
490 * ctx.cli.o0:
491 * may contain a configured max line count for each step (0=not set)
Willy Tarreau75c62c22018-11-22 11:02:09 +0100492 */
493static int cli_io_handler_show_profiling(struct appctx *appctx)
494{
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100495 struct sched_activity tmp_activity[256] __attribute__((aligned(64)));
Willy Tarreau993d44d2021-05-05 18:07:02 +0200496#if USE_MEMORY_PROFILING
497 struct memprof_stats tmp_memstats[MEMPROF_HASH_BUCKETS + 1];
498#endif
Willy Tarreau75c62c22018-11-22 11:02:09 +0100499 struct stream_interface *si = appctx->owner;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100500 struct buffer *name_buffer = get_trash_chunk();
Willy Tarreaud2d33482019-04-25 17:09:07 +0200501 const char *str;
Willy Tarreau637d85a2021-05-05 17:33:27 +0200502 int max_lines;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100503 int i, max;
Willy Tarreau75c62c22018-11-22 11:02:09 +0100504
505 if (unlikely(si_ic(si)->flags & (CF_WRITE_ERROR|CF_SHUTW)))
506 return 1;
507
508 chunk_reset(&trash);
509
Willy Tarreaud2d33482019-04-25 17:09:07 +0200510 switch (profiling & HA_PROF_TASKS_MASK) {
Willy Tarreauaa622b82021-01-28 21:44:22 +0100511 case HA_PROF_TASKS_AOFF: str="auto-off"; break;
512 case HA_PROF_TASKS_AON: str="auto-on"; break;
Willy Tarreaud2d33482019-04-25 17:09:07 +0200513 case HA_PROF_TASKS_ON: str="on"; break;
514 default: str="off"; break;
515 }
516
Willy Tarreau637d85a2021-05-05 17:33:27 +0200517 if ((appctx->ctx.cli.i0 & 3) != 0)
518 goto skip_status;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100519
Willy Tarreaud2d33482019-04-25 17:09:07 +0200520 chunk_printf(&trash,
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200521 "Per-task CPU profiling : %-8s # set profiling tasks {on|auto|off}\n"
522 "Memory usage profiling : %-8s # set profiling memory {on|off}\n",
523 str, (profiling & HA_PROF_MEMORY) ? "on" : "off");
Willy Tarreau75c62c22018-11-22 11:02:09 +0100524
Willy Tarreau637d85a2021-05-05 17:33:27 +0200525 if (ci_putchk(si_ic(si), &trash) == -1) {
526 /* failed, try again */
527 si_rx_room_blk(si);
528 return 0;
529 }
530
531 appctx->ctx.cli.i1 = 0; // reset first line to dump
532 if ((appctx->ctx.cli.i0 & 4) == 0)
533 appctx->ctx.cli.i0++; // next step
534
535 skip_status:
536 if ((appctx->ctx.cli.i0 & 3) != 1)
537 goto skip_tasks;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100538
Willy Tarreau637d85a2021-05-05 17:33:27 +0200539 memcpy(tmp_activity, sched_activity, sizeof(tmp_activity));
540 qsort(tmp_activity, 256, sizeof(tmp_activity[0]), cmp_sched_activity);
541
542 if (!appctx->ctx.cli.i1)
543 chunk_appendf(&trash, "Tasks activity:\n"
544 " function calls cpu_tot cpu_avg lat_tot lat_avg\n");
545
546 max_lines = appctx->ctx.cli.o0;
547 if (!max_lines)
548 max_lines = 256;
549
550 for (i = appctx->ctx.cli.i1; i < max_lines && tmp_activity[i].calls; i++) {
551 appctx->ctx.cli.i1 = i;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100552 chunk_reset(name_buffer);
553
554 if (!tmp_activity[i].func)
555 chunk_printf(name_buffer, "other");
556 else
557 resolve_sym_name(name_buffer, "", tmp_activity[i].func);
558
559 /* reserve 35 chars for name+' '+#calls, knowing that longer names
560 * are often used for less often called functions.
561 */
562 max = 35 - name_buffer->data;
563 if (max < 1)
564 max = 1;
565 chunk_appendf(&trash, " %s%*llu", name_buffer->area, max, (unsigned long long)tmp_activity[i].calls);
566
567 print_time_short(&trash, " ", tmp_activity[i].cpu_time, "");
568 print_time_short(&trash, " ", tmp_activity[i].cpu_time / tmp_activity[i].calls, "");
569 print_time_short(&trash, " ", tmp_activity[i].lat_time, "");
570 print_time_short(&trash, " ", tmp_activity[i].lat_time / tmp_activity[i].calls, "\n");
Willy Tarreau637d85a2021-05-05 17:33:27 +0200571
572 if (ci_putchk(si_ic(si), &trash) == -1) {
573 /* failed, try again */
574 si_rx_room_blk(si);
575 return 0;
576 }
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100577 }
578
Willy Tarreau75c62c22018-11-22 11:02:09 +0100579 if (ci_putchk(si_ic(si), &trash) == -1) {
580 /* failed, try again */
581 si_rx_room_blk(si);
582 return 0;
583 }
Willy Tarreau637d85a2021-05-05 17:33:27 +0200584
585 appctx->ctx.cli.i1 = 0; // reset first line to dump
586 if ((appctx->ctx.cli.i0 & 4) == 0)
587 appctx->ctx.cli.i0++; // next step
588
589 skip_tasks:
590
Willy Tarreau993d44d2021-05-05 18:07:02 +0200591#if USE_MEMORY_PROFILING
592 if ((appctx->ctx.cli.i0 & 3) != 2)
593 goto skip_mem;
594
595 memcpy(tmp_memstats, memprof_stats, sizeof(tmp_memstats));
596 qsort(tmp_memstats, MEMPROF_HASH_BUCKETS+1, sizeof(tmp_memstats[0]), cmp_memprof_stats);
597
598 if (!appctx->ctx.cli.i1)
599 chunk_appendf(&trash,
600 "Alloc/Free statistics by call place:\n"
601 " Calls | Tot Bytes | Caller\n"
602 "<- alloc -> <- free ->|<-- alloc ---> <-- free ---->|\n");
603
604 max_lines = appctx->ctx.cli.o0;
605 if (!max_lines)
606 max_lines = MEMPROF_HASH_BUCKETS + 1;
607
608 for (i = appctx->ctx.cli.i1; i < max_lines; i++) {
609 struct memprof_stats *entry = &tmp_memstats[i];
610
611 appctx->ctx.cli.i1 = i;
612 if (!entry->alloc_calls && !entry->free_calls)
613 continue;
614 chunk_appendf(&trash, "%11llu %11llu %14llu %14llu| %16p ",
615 entry->alloc_calls, entry->free_calls,
616 entry->alloc_tot, entry->free_tot,
617 entry->caller);
618
619 if (entry->caller)
620 resolve_sym_name(&trash, NULL, entry->caller);
621 else
622 chunk_appendf(&trash, "[other]");
623
624 chunk_appendf(&trash,"\n");
625
626 if (ci_putchk(si_ic(si), &trash) == -1) {
627 si_rx_room_blk(si);
628 return 0;
629 }
630 }
631
632 if (ci_putchk(si_ic(si), &trash) == -1) {
633 si_rx_room_blk(si);
634 return 0;
635 }
636
637 appctx->ctx.cli.i1 = 0; // reset first line to dump
638 if ((appctx->ctx.cli.i0 & 4) == 0)
639 appctx->ctx.cli.i0++; // next step
640
641 skip_mem:
642#endif // USE_MEMORY_PROFILING
643
Willy Tarreau75c62c22018-11-22 11:02:09 +0100644 return 1;
645}
646
Willy Tarreau42712cb2021-05-05 17:48:13 +0200647/* parse a "show profiling" command. It returns 1 on failure, 0 if it starts to dump. */
648static int cli_parse_show_profiling(char **args, char *payload, struct appctx *appctx, void *private)
649{
650 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
651 return 1;
652
653 if (strcmp(args[2], "all") == 0) {
654 appctx->ctx.cli.i0 = 0; // will cycle through 0,1,2; default
655 args++;
656 }
657 else if (strcmp(args[2], "status") == 0) {
658 appctx->ctx.cli.i0 = 4; // will visit status only
659 args++;
660 }
661 else if (strcmp(args[2], "tasks") == 0) {
662 appctx->ctx.cli.i0 = 5; // will visit tasks only
663 args++;
664 }
665 else if (strcmp(args[2], "memory") == 0) {
666 appctx->ctx.cli.i0 = 6; // will visit memory only
667 args++;
668 }
669 else if (*args[2] && !isdigit((unsigned char)*args[2]))
670 return cli_err(appctx, "Expects either 'all', 'status', 'tasks' or 'memory'.\n");
671
672 if (*args[2]) {
673 /* Second arg may set a limit to number of entries to dump; default is
674 * not set and means no limit.
675 */
676 appctx->ctx.cli.o0 = atoi(args[2]);
677 }
678 return 0;
679}
680
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100681/* This function scans all threads' run queues and collects statistics about
682 * running tasks. It returns 0 if the output buffer is full and it needs to be
683 * called again, otherwise non-zero.
684 */
685static int cli_io_handler_show_tasks(struct appctx *appctx)
686{
687 struct sched_activity tmp_activity[256] __attribute__((aligned(64)));
688 struct stream_interface *si = appctx->owner;
689 struct buffer *name_buffer = get_trash_chunk();
690 struct sched_activity *entry;
691 const struct tasklet *tl;
692 const struct task *t;
693 uint64_t now_ns, lat;
694 struct eb32sc_node *rqnode;
695 uint64_t tot_calls;
696 int thr, queue;
697 int i, max;
698
699 if (unlikely(si_ic(si)->flags & (CF_WRITE_ERROR|CF_SHUTW)))
700 return 1;
701
702 /* It's not possible to scan queues in small chunks and yield in the
703 * middle of the dump and come back again. So what we're doing instead
704 * is to freeze all threads and inspect their queues at once as fast as
705 * possible, using a sched_activity array to collect metrics with
706 * limited collision, then we'll report statistics only. The tasks'
707 * #calls will reflect the number of occurrences, and the lat_time will
Willy Tarreau75f72332021-01-29 15:04:16 +0100708 * reflect the latency when set. We prefer to take the time before
709 * calling thread_isolate() so that the wait time doesn't impact the
710 * measurement accuracy. However this requires to take care of negative
711 * times since tasks might be queued after we retrieve it.
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100712 */
713
714 now_ns = now_mono_time();
715 memset(tmp_activity, 0, sizeof(tmp_activity));
716
717 thread_isolate();
718
719 /* 1. global run queue */
720
721#ifdef USE_THREAD
722 rqnode = eb32sc_first(&rqueue, ~0UL);
723 while (rqnode) {
724 t = eb32sc_entry(rqnode, struct task, rq);
725 entry = sched_activity_entry(tmp_activity, t->process);
726 if (t->call_date) {
727 lat = now_ns - t->call_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100728 if ((int64_t)lat > 0)
729 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100730 }
731 entry->calls++;
732 rqnode = eb32sc_next(rqnode, ~0UL);
733 }
734#endif
735 /* 2. all threads's local run queues */
736 for (thr = 0; thr < global.nbthread; thr++) {
737 /* task run queue */
738 rqnode = eb32sc_first(&task_per_thread[thr].rqueue, ~0UL);
739 while (rqnode) {
740 t = eb32sc_entry(rqnode, struct task, rq);
741 entry = sched_activity_entry(tmp_activity, t->process);
742 if (t->call_date) {
743 lat = now_ns - t->call_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100744 if ((int64_t)lat > 0)
745 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100746 }
747 entry->calls++;
748 rqnode = eb32sc_next(rqnode, ~0UL);
749 }
750
751 /* shared tasklet list */
752 list_for_each_entry(tl, mt_list_to_list(&task_per_thread[thr].shared_tasklet_list), list) {
753 t = (const struct task *)tl;
754 entry = sched_activity_entry(tmp_activity, t->process);
755 if (!TASK_IS_TASKLET(t) && t->call_date) {
756 lat = now_ns - t->call_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100757 if ((int64_t)lat > 0)
758 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100759 }
760 entry->calls++;
761 }
762
763 /* classful tasklets */
764 for (queue = 0; queue < TL_CLASSES; queue++) {
765 list_for_each_entry(tl, &task_per_thread[thr].tasklets[queue], list) {
766 t = (const struct task *)tl;
767 entry = sched_activity_entry(tmp_activity, t->process);
768 if (!TASK_IS_TASKLET(t) && t->call_date) {
769 lat = now_ns - t->call_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100770 if ((int64_t)lat > 0)
771 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100772 }
773 entry->calls++;
774 }
775 }
776 }
777
778 /* hopefully we're done */
779 thread_release();
780
781 chunk_reset(&trash);
782
783 tot_calls = 0;
784 for (i = 0; i < 256; i++)
785 tot_calls += tmp_activity[i].calls;
786
787 qsort(tmp_activity, 256, sizeof(tmp_activity[0]), cmp_sched_activity);
788
789 chunk_appendf(&trash, "Running tasks: %d (%d threads)\n"
790 " function places %% lat_tot lat_avg\n",
791 (int)tot_calls, global.nbthread);
792
793 for (i = 0; i < 256 && tmp_activity[i].calls; i++) {
794 chunk_reset(name_buffer);
795
796 if (!tmp_activity[i].func)
797 chunk_printf(name_buffer, "other");
798 else
799 resolve_sym_name(name_buffer, "", tmp_activity[i].func);
800
801 /* reserve 35 chars for name+' '+#calls, knowing that longer names
802 * are often used for less often called functions.
803 */
804 max = 35 - name_buffer->data;
805 if (max < 1)
806 max = 1;
807 chunk_appendf(&trash, " %s%*llu %3d.%1d",
808 name_buffer->area, max, (unsigned long long)tmp_activity[i].calls,
809 (int)(100ULL * tmp_activity[i].calls / tot_calls),
810 (int)((1000ULL * tmp_activity[i].calls / tot_calls)%10));
811 print_time_short(&trash, " ", tmp_activity[i].lat_time, "");
812 print_time_short(&trash, " ", tmp_activity[i].lat_time / tmp_activity[i].calls, "\n");
813 }
814
815 if (ci_putchk(si_ic(si), &trash) == -1) {
816 /* failed, try again */
817 si_rx_room_blk(si);
818 return 0;
819 }
820 return 1;
821}
822
Willy Tarreau75c62c22018-11-22 11:02:09 +0100823/* config keyword parsers */
824static struct cfg_kw_list cfg_kws = {ILH, {
Willy Tarreauca3afc22021-05-05 18:33:19 +0200825#ifdef USE_MEMORY_PROFILING
826 { CFG_GLOBAL, "profiling.memory", cfg_parse_prof_memory },
827#endif
Willy Tarreau75c62c22018-11-22 11:02:09 +0100828 { CFG_GLOBAL, "profiling.tasks", cfg_parse_prof_tasks },
829 { 0, NULL, NULL }
830}};
831
Willy Tarreau0108d902018-11-25 19:14:37 +0100832INITCALL1(STG_REGISTER, cfg_register_keywords, &cfg_kws);
833
Willy Tarreau75c62c22018-11-22 11:02:09 +0100834/* register cli keywords */
835static struct cli_kw_list cli_kws = {{ },{
Willy Tarreaub205bfd2021-05-07 11:38:37 +0200836 { { "set", "profiling", NULL }, "set profiling <what> {auto|on|off} : enable/disable resource profiling (tasks,memory)", cli_parse_set_profiling, NULL },
837 { { "show", "profiling", NULL }, "show profiling [<what>] [<max_lines>] : show profiling state (all,status,tasks,memory)", cli_parse_show_profiling, cli_io_handler_show_profiling, NULL },
838 { { "show", "tasks", NULL }, "show tasks : show running tasks", NULL, cli_io_handler_show_tasks, NULL },
Willy Tarreau75c62c22018-11-22 11:02:09 +0100839 {{},}
840}};
841
Willy Tarreau0108d902018-11-25 19:14:37 +0100842INITCALL1(STG_REGISTER, cli_register_kw, &cli_kws);