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