blob: d0c37478a811ed2b05f867213a2b3abf2299aece [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
Willy Tarreau3e109ee2021-08-28 12:04:25 +020042#ifdef USE_MEMORY_PROFILING
Willy Tarreaudb87fc72021-05-05 16:50:40 +020043/* determine the number of buckets to store stats */
44#define MEMPROF_HASH_BITS 10
45#define MEMPROF_HASH_BUCKETS (1U << MEMPROF_HASH_BITS)
46
Willy Tarreau616491b2021-05-11 09:26:23 +020047enum memprof_method {
48 MEMPROF_METH_UNKNOWN = 0,
49 MEMPROF_METH_MALLOC,
50 MEMPROF_METH_CALLOC,
51 MEMPROF_METH_REALLOC,
52 MEMPROF_METH_FREE,
53 MEMPROF_METH_METHODS /* count, must be last */
54};
55
56static const char *const memprof_methods[MEMPROF_METH_METHODS] = {
57 "unknown", "malloc", "calloc", "realloc", "free",
58};
59
Willy Tarreaudb87fc72021-05-05 16:50:40 +020060/* stats:
61 * - malloc increases alloc
62 * - free increases free (if non null)
63 * - realloc increases either depending on the size change.
64 * when the real size is known (malloc_usable_size()), it's used in free_tot
65 * and alloc_tot, otherwise the requested size is reported in alloc_tot and
66 * zero in free_tot.
67 */
68struct memprof_stats {
69 const void *caller;
Willy Tarreau616491b2021-05-11 09:26:23 +020070 enum memprof_method method;
71 /* 4-7 bytes hole here */
Willy Tarreaudb87fc72021-05-05 16:50:40 +020072 unsigned long long alloc_calls;
73 unsigned long long free_calls;
74 unsigned long long alloc_tot;
75 unsigned long long free_tot;
76};
77
78/* last one is for hash collisions ("others") and has no caller address */
79struct memprof_stats memprof_stats[MEMPROF_HASH_BUCKETS + 1] = { };
80
Willy Tarreauf93c7be2021-05-05 17:07:09 +020081/* used to detect recursive calls */
82static THREAD_LOCAL int in_memprof = 0;
83
84/* perform a pointer hash by scrambling its bits and retrieving the most
85 * mixed ones (topmost ones in 32-bit, middle ones in 64-bit).
86 */
87static unsigned int memprof_hash_ptr(const void *p)
88{
89 unsigned long long x = (unsigned long)p;
90
91 x = 0xcbda9653U * x;
92 if (sizeof(long) == 4)
93 x >>= 32;
94 else
95 x >>= 33 - MEMPROF_HASH_BITS / 2;
96 return x & (MEMPROF_HASH_BUCKETS - 1);
97}
98
99/* These ones are used by glibc and will be called early. They are in charge of
100 * initializing the handlers with the original functions.
101 */
102static void *memprof_malloc_initial_handler(size_t size);
103static void *memprof_calloc_initial_handler(size_t nmemb, size_t size);
104static void *memprof_realloc_initial_handler(void *ptr, size_t size);
105static void memprof_free_initial_handler(void *ptr);
106
107/* Fallback handlers for the main alloc/free functions. They are preset to
108 * the initializer in order to save a test in the functions's critical path.
109 */
110static void *(*memprof_malloc_handler)(size_t size) = memprof_malloc_initial_handler;
111static void *(*memprof_calloc_handler)(size_t nmemb, size_t size) = memprof_calloc_initial_handler;
112static void *(*memprof_realloc_handler)(void *ptr, size_t size) = memprof_realloc_initial_handler;
113static void (*memprof_free_handler)(void *ptr) = memprof_free_initial_handler;
114
115/* Used to force to die if it's not possible to retrieve the allocation
116 * functions. We cannot even use stdio in this case.
117 */
118static __attribute__((noreturn)) void memprof_die(const char *msg)
119{
120 DISGUISE(write(2, msg, strlen(msg)));
121 exit(1);
122}
123
124/* Resolve original allocation functions and initialize all handlers.
125 * This must be called very early at boot, before the very first malloc()
126 * call, and is not thread-safe! It's not even possible to use stdio there.
127 * Worse, we have to account for the risk of reentrance from dlsym() when
128 * it tries to prepare its error messages. Here its ahndled by in_memprof
129 * that makes allocators return NULL. dlsym() handles it gracefully. An
Ilya Shipitsin3df59892021-05-10 12:50:00 +0500130 * alternate approach consists in calling aligned_alloc() from these places
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200131 * but that would mean not being able to intercept it later if considered
132 * useful to do so.
133 */
134static void memprof_init()
135{
136 in_memprof++;
137 memprof_malloc_handler = get_sym_next_addr("malloc");
138 if (!memprof_malloc_handler)
139 memprof_die("FATAL: malloc() function not found.\n");
140
141 memprof_calloc_handler = get_sym_next_addr("calloc");
142 if (!memprof_calloc_handler)
143 memprof_die("FATAL: calloc() function not found.\n");
144
145 memprof_realloc_handler = get_sym_next_addr("realloc");
146 if (!memprof_realloc_handler)
147 memprof_die("FATAL: realloc() function not found.\n");
148
149 memprof_free_handler = get_sym_next_addr("free");
150 if (!memprof_free_handler)
151 memprof_die("FATAL: free() function not found.\n");
152 in_memprof--;
153}
154
155/* the initial handlers will initialize all regular handlers and will call the
156 * one they correspond to. A single one of these functions will typically be
157 * called, though it's unknown which one (as any might be called before main).
158 */
159static void *memprof_malloc_initial_handler(size_t size)
160{
161 if (in_memprof) {
162 /* it's likely that dlsym() needs malloc(), let's fail */
163 return NULL;
164 }
165
166 memprof_init();
167 return memprof_malloc_handler(size);
168}
169
170static void *memprof_calloc_initial_handler(size_t nmemb, size_t size)
171{
172 if (in_memprof) {
173 /* it's likely that dlsym() needs calloc(), let's fail */
174 return NULL;
175 }
176 memprof_init();
177 return memprof_calloc_handler(nmemb, size);
178}
179
180static void *memprof_realloc_initial_handler(void *ptr, size_t size)
181{
182 if (in_memprof) {
183 /* it's likely that dlsym() needs realloc(), let's fail */
184 return NULL;
185 }
186
187 memprof_init();
188 return memprof_realloc_handler(ptr, size);
189}
190
191static void memprof_free_initial_handler(void *ptr)
192{
193 memprof_init();
194 memprof_free_handler(ptr);
195}
196
197/* Assign a bin for the memprof_stats to the return address. May perform a few
198 * attempts before finding the right one, but always succeeds (in the worst
199 * case, returns a default bin). The caller address is atomically set except
200 * for the default one which is never set.
201 */
Willy Tarreau616491b2021-05-11 09:26:23 +0200202static struct memprof_stats *memprof_get_bin(const void *ra, enum memprof_method meth)
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200203{
204 int retries = 16; // up to 16 consecutive entries may be tested.
Willy Tarreau4a753282021-05-09 23:18:50 +0200205 const void *old;
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200206 unsigned int bin;
207
208 bin = memprof_hash_ptr(ra);
209 for (; memprof_stats[bin].caller != ra; bin = (bin + 1) & (MEMPROF_HASH_BUCKETS - 1)) {
210 if (!--retries) {
211 bin = MEMPROF_HASH_BUCKETS;
212 break;
213 }
214
215 old = NULL;
216 if (!memprof_stats[bin].caller &&
Willy Tarreau616491b2021-05-11 09:26:23 +0200217 HA_ATOMIC_CAS(&memprof_stats[bin].caller, &old, ra)) {
218 memprof_stats[bin].method = meth;
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200219 break;
Willy Tarreau616491b2021-05-11 09:26:23 +0200220 }
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200221 }
222 return &memprof_stats[bin];
223}
224
225/* This is the new global malloc() function. It must optimize for the normal
226 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
227 * It must remain simple to guarantee the lack of reentrance. stdio is not
228 * possible there even for debugging. The reported size is the really allocated
229 * one as returned by malloc_usable_size(), because this will allow it to be
230 * compared to the one before realloc() or free(). This is a GNU and jemalloc
231 * extension but other systems may also store this size in ptr[-1].
232 */
233void *malloc(size_t size)
234{
235 struct memprof_stats *bin;
236 void *ret;
237
238 if (likely(!(profiling & HA_PROF_MEMORY)))
239 return memprof_malloc_handler(size);
240
241 ret = memprof_malloc_handler(size);
Willy Tarreaud858cbf2021-10-22 16:33:53 +0200242 size = malloc_usable_size(ret) + sizeof(void *);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200243
Willy Tarreau616491b2021-05-11 09:26:23 +0200244 bin = memprof_get_bin(__builtin_return_address(0), MEMPROF_METH_MALLOC);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200245 _HA_ATOMIC_ADD(&bin->alloc_calls, 1);
246 _HA_ATOMIC_ADD(&bin->alloc_tot, size);
247 return ret;
248}
249
250/* This is the new global calloc() function. It must optimize for the normal
251 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
252 * It must remain simple to guarantee the lack of reentrance. stdio is not
253 * possible there even for debugging. The reported size is the really allocated
254 * one as returned by malloc_usable_size(), because this will allow it to be
255 * compared to the one before realloc() or free(). This is a GNU and jemalloc
256 * extension but other systems may also store this size in ptr[-1].
257 */
258void *calloc(size_t nmemb, size_t size)
259{
260 struct memprof_stats *bin;
261 void *ret;
262
263 if (likely(!(profiling & HA_PROF_MEMORY)))
264 return memprof_calloc_handler(nmemb, size);
265
266 ret = memprof_calloc_handler(nmemb, size);
Willy Tarreaud858cbf2021-10-22 16:33:53 +0200267 size = malloc_usable_size(ret) + sizeof(void *);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200268
Willy Tarreau616491b2021-05-11 09:26:23 +0200269 bin = memprof_get_bin(__builtin_return_address(0), MEMPROF_METH_CALLOC);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200270 _HA_ATOMIC_ADD(&bin->alloc_calls, 1);
271 _HA_ATOMIC_ADD(&bin->alloc_tot, size);
272 return ret;
273}
274
275/* This is the new global realloc() function. It must optimize for the normal
276 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
277 * It must remain simple to guarantee the lack of reentrance. stdio is not
278 * possible there even for debugging. The reported size is the really allocated
279 * one as returned by malloc_usable_size(), because this will allow it to be
280 * compared to the one before realloc() or free(). This is a GNU and jemalloc
281 * extension but other systems may also store this size in ptr[-1].
282 * Depending on the old vs new size, it's considered as an allocation or a free
283 * (or neither if the size remains the same).
284 */
285void *realloc(void *ptr, size_t size)
286{
287 struct memprof_stats *bin;
288 size_t size_before;
289 void *ret;
290
291 if (likely(!(profiling & HA_PROF_MEMORY)))
292 return memprof_realloc_handler(ptr, size);
293
294 size_before = malloc_usable_size(ptr);
295 ret = memprof_realloc_handler(ptr, size);
Willy Tarreau2639e2e2021-05-07 08:01:35 +0200296 size = malloc_usable_size(ret);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200297
Willy Tarreaud858cbf2021-10-22 16:33:53 +0200298 /* only count the extra link for new allocations */
299 if (!ptr)
300 size += sizeof(void *);
301
Willy Tarreau616491b2021-05-11 09:26:23 +0200302 bin = memprof_get_bin(__builtin_return_address(0), MEMPROF_METH_REALLOC);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200303 if (size > size_before) {
304 _HA_ATOMIC_ADD(&bin->alloc_calls, 1);
Willy Tarreau79acefa2021-05-11 09:12:56 +0200305 _HA_ATOMIC_ADD(&bin->alloc_tot, size - size_before);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200306 } else if (size < size_before) {
307 _HA_ATOMIC_ADD(&bin->free_calls, 1);
Willy Tarreau79acefa2021-05-11 09:12:56 +0200308 _HA_ATOMIC_ADD(&bin->free_tot, size_before - size);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200309 }
310 return ret;
311}
312
313/* This is the new global free() function. It must optimize for the normal
314 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
315 * It must remain simple to guarantee the lack of reentrance. stdio is not
316 * possible there even for debugging. The reported size is the really allocated
317 * one as returned by malloc_usable_size(), because this will allow it to be
318 * compared to the one before realloc() or free(). This is a GNU and jemalloc
319 * extension but other systems may also store this size in ptr[-1]. Since
320 * free() is often called on NULL pointers to collect garbage at the end of
321 * many functions or during config parsing, as a special case free(NULL)
322 * doesn't update any stats.
323 */
324void free(void *ptr)
325{
326 struct memprof_stats *bin;
327 size_t size_before;
328
329 if (likely(!(profiling & HA_PROF_MEMORY) || !ptr)) {
330 memprof_free_handler(ptr);
331 return;
332 }
333
Willy Tarreaud858cbf2021-10-22 16:33:53 +0200334 size_before = malloc_usable_size(ptr) + sizeof(void *);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200335 memprof_free_handler(ptr);
336
Willy Tarreau616491b2021-05-11 09:26:23 +0200337 bin = memprof_get_bin(__builtin_return_address(0), MEMPROF_METH_FREE);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200338 _HA_ATOMIC_ADD(&bin->free_calls, 1);
339 _HA_ATOMIC_ADD(&bin->free_tot, size_before);
340}
341
Willy Tarreaudb87fc72021-05-05 16:50:40 +0200342#endif // USE_MEMORY_PROFILING
343
Willy Tarreau609aad92018-11-22 08:31:09 +0100344/* Updates the current thread's statistics about stolen CPU time. The unit for
345 * <stolen> is half-milliseconds.
346 */
347void report_stolen_time(uint64_t stolen)
348{
349 activity[tid].cpust_total += stolen;
350 update_freq_ctr(&activity[tid].cpust_1s, stolen);
351 update_freq_ctr_period(&activity[tid].cpust_15s, 15000, stolen);
352}
Willy Tarreau75c62c22018-11-22 11:02:09 +0100353
Willy Tarreauca3afc22021-05-05 18:33:19 +0200354#ifdef USE_MEMORY_PROFILING
355/* config parser for global "profiling.memory", accepts "on" or "off" */
356static int cfg_parse_prof_memory(char **args, int section_type, struct proxy *curpx,
357 const struct proxy *defpx, const char *file, int line,
358 char **err)
359{
360 if (too_many_args(1, args, err, NULL))
361 return -1;
362
363 if (strcmp(args[1], "on") == 0)
364 profiling |= HA_PROF_MEMORY;
365 else if (strcmp(args[1], "off") == 0)
366 profiling &= ~HA_PROF_MEMORY;
367 else {
368 memprintf(err, "'%s' expects either 'on' or 'off' but got '%s'.", args[0], args[1]);
369 return -1;
370 }
371 return 0;
372}
373#endif // USE_MEMORY_PROFILING
374
Willy Tarreau75c62c22018-11-22 11:02:09 +0100375/* config parser for global "profiling.tasks", accepts "on" or "off" */
376static int cfg_parse_prof_tasks(char **args, int section_type, struct proxy *curpx,
Willy Tarreau01825162021-03-09 09:53:46 +0100377 const struct proxy *defpx, const char *file, int line,
Willy Tarreau75c62c22018-11-22 11:02:09 +0100378 char **err)
379{
380 if (too_many_args(1, args, err, NULL))
381 return -1;
382
383 if (strcmp(args[1], "on") == 0)
Willy Tarreaud2d33482019-04-25 17:09:07 +0200384 profiling = (profiling & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_ON;
385 else if (strcmp(args[1], "auto") == 0)
Willy Tarreauaa622b82021-01-28 21:44:22 +0100386 profiling = (profiling & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_AOFF;
Willy Tarreau75c62c22018-11-22 11:02:09 +0100387 else if (strcmp(args[1], "off") == 0)
Willy Tarreaud2d33482019-04-25 17:09:07 +0200388 profiling = (profiling & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_OFF;
Willy Tarreau75c62c22018-11-22 11:02:09 +0100389 else {
Willy Tarreaud2d33482019-04-25 17:09:07 +0200390 memprintf(err, "'%s' expects either 'on', 'auto', or 'off' but got '%s'.", args[0], args[1]);
Willy Tarreau75c62c22018-11-22 11:02:09 +0100391 return -1;
392 }
393 return 0;
394}
395
396/* parse a "set profiling" command. It always returns 1. */
397static int cli_parse_set_profiling(char **args, char *payload, struct appctx *appctx, void *private)
398{
Willy Tarreau75c62c22018-11-22 11:02:09 +0100399 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
400 return 1;
401
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200402 if (strcmp(args[2], "memory") == 0) {
Willy Tarreaudb87fc72021-05-05 16:50:40 +0200403#ifdef USE_MEMORY_PROFILING
404 if (strcmp(args[3], "on") == 0) {
405 unsigned int old = profiling;
406 int i;
407
408 while (!_HA_ATOMIC_CAS(&profiling, &old, old | HA_PROF_MEMORY))
409 ;
410
411 /* also flush current profiling stats */
412 for (i = 0; i < sizeof(memprof_stats) / sizeof(memprof_stats[0]); i++) {
413 HA_ATOMIC_STORE(&memprof_stats[i].alloc_calls, 0);
414 HA_ATOMIC_STORE(&memprof_stats[i].free_calls, 0);
415 HA_ATOMIC_STORE(&memprof_stats[i].alloc_tot, 0);
416 HA_ATOMIC_STORE(&memprof_stats[i].free_tot, 0);
417 HA_ATOMIC_STORE(&memprof_stats[i].caller, NULL);
418 }
419 }
420 else if (strcmp(args[3], "off") == 0) {
421 unsigned int old = profiling;
422
423 while (!_HA_ATOMIC_CAS(&profiling, &old, old & ~HA_PROF_MEMORY))
424 ;
425 }
426 else
427 return cli_err(appctx, "Expects either 'on' or 'off'.\n");
428 return 1;
429#else
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200430 return cli_err(appctx, "Memory profiling not compiled in.\n");
Willy Tarreaudb87fc72021-05-05 16:50:40 +0200431#endif
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200432 }
433
Willy Tarreau9d008692019-08-09 11:21:01 +0200434 if (strcmp(args[2], "tasks") != 0)
Ilya Shipitsin3df59892021-05-10 12:50:00 +0500435 return cli_err(appctx, "Expects either 'tasks' or 'memory'.\n");
Willy Tarreau75c62c22018-11-22 11:02:09 +0100436
Willy Tarreaud2d33482019-04-25 17:09:07 +0200437 if (strcmp(args[3], "on") == 0) {
438 unsigned int old = profiling;
Willy Tarreaucfa71012021-01-29 11:56:21 +0100439 int i;
440
Willy Tarreaud2d33482019-04-25 17:09:07 +0200441 while (!_HA_ATOMIC_CAS(&profiling, &old, (old & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_ON))
442 ;
Willy Tarreaucfa71012021-01-29 11:56:21 +0100443 /* also flush current profiling stats */
444 for (i = 0; i < 256; i++) {
445 HA_ATOMIC_STORE(&sched_activity[i].calls, 0);
446 HA_ATOMIC_STORE(&sched_activity[i].cpu_time, 0);
447 HA_ATOMIC_STORE(&sched_activity[i].lat_time, 0);
448 HA_ATOMIC_STORE(&sched_activity[i].func, NULL);
449 }
Willy Tarreaud2d33482019-04-25 17:09:07 +0200450 }
451 else if (strcmp(args[3], "auto") == 0) {
452 unsigned int old = profiling;
Willy Tarreauaa622b82021-01-28 21:44:22 +0100453 unsigned int new;
454
455 do {
456 if ((old & HA_PROF_TASKS_MASK) >= HA_PROF_TASKS_AON)
457 new = (old & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_AON;
458 else
459 new = (old & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_AOFF;
460 } while (!_HA_ATOMIC_CAS(&profiling, &old, new));
Willy Tarreaud2d33482019-04-25 17:09:07 +0200461 }
462 else if (strcmp(args[3], "off") == 0) {
463 unsigned int old = profiling;
464 while (!_HA_ATOMIC_CAS(&profiling, &old, (old & ~HA_PROF_TASKS_MASK) | HA_PROF_TASKS_OFF))
465 ;
466 }
Willy Tarreau9d008692019-08-09 11:21:01 +0200467 else
468 return cli_err(appctx, "Expects 'on', 'auto', or 'off'.\n");
469
Willy Tarreau75c62c22018-11-22 11:02:09 +0100470 return 1;
471}
472
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200473static int cmp_sched_activity_calls(const void *a, const void *b)
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100474{
475 const struct sched_activity *l = (const struct sched_activity *)a;
476 const struct sched_activity *r = (const struct sched_activity *)b;
477
478 if (l->calls > r->calls)
479 return -1;
480 else if (l->calls < r->calls)
481 return 1;
482 else
483 return 0;
484}
485
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200486static int cmp_sched_activity_addr(const void *a, const void *b)
487{
488 const struct sched_activity *l = (const struct sched_activity *)a;
489 const struct sched_activity *r = (const struct sched_activity *)b;
490
491 if (l->func > r->func)
492 return -1;
493 else if (l->func < r->func)
494 return 1;
495 else
496 return 0;
497}
498
Willy Tarreau3e109ee2021-08-28 12:04:25 +0200499#ifdef USE_MEMORY_PROFILING
Willy Tarreau993d44d2021-05-05 18:07:02 +0200500/* used by qsort below */
501static int cmp_memprof_stats(const void *a, const void *b)
502{
503 const struct memprof_stats *l = (const struct memprof_stats *)a;
504 const struct memprof_stats *r = (const struct memprof_stats *)b;
505
506 if (l->alloc_tot + l->free_tot > r->alloc_tot + r->free_tot)
507 return -1;
508 else if (l->alloc_tot + l->free_tot < r->alloc_tot + r->free_tot)
509 return 1;
510 else
511 return 0;
512}
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200513
514static int cmp_memprof_addr(const void *a, const void *b)
515{
516 const struct memprof_stats *l = (const struct memprof_stats *)a;
517 const struct memprof_stats *r = (const struct memprof_stats *)b;
518
519 if (l->caller > r->caller)
520 return -1;
521 else if (l->caller < r->caller)
522 return 1;
523 else
524 return 0;
525}
Willy Tarreau993d44d2021-05-05 18:07:02 +0200526#endif // USE_MEMORY_PROFILING
527
Willy Tarreau75c62c22018-11-22 11:02:09 +0100528/* This function dumps all profiling settings. It returns 0 if the output
529 * buffer is full and it needs to be called again, otherwise non-zero.
Willy Tarreau637d85a2021-05-05 17:33:27 +0200530 * It dumps some parts depending on the following states:
531 * ctx.cli.i0:
532 * 0, 4: dump status, then jump to 1 if 0
533 * 1, 5: dump tasks, then jump to 2 if 1
534 * 2, 6: dump memory, then stop
535 * ctx.cli.i1:
536 * restart line for each step (starts at zero)
537 * ctx.cli.o0:
538 * may contain a configured max line count for each step (0=not set)
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200539 * ctx.cli.o1:
540 * 0: sort by usage
541 * 1: sort by address
Willy Tarreau75c62c22018-11-22 11:02:09 +0100542 */
543static int cli_io_handler_show_profiling(struct appctx *appctx)
544{
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100545 struct sched_activity tmp_activity[256] __attribute__((aligned(64)));
Willy Tarreau3e109ee2021-08-28 12:04:25 +0200546#ifdef USE_MEMORY_PROFILING
Willy Tarreau993d44d2021-05-05 18:07:02 +0200547 struct memprof_stats tmp_memstats[MEMPROF_HASH_BUCKETS + 1];
Willy Tarreauf5fb8582021-05-11 14:06:24 +0200548 unsigned long long tot_alloc_calls, tot_free_calls;
549 unsigned long long tot_alloc_bytes, tot_free_bytes;
Willy Tarreau993d44d2021-05-05 18:07:02 +0200550#endif
Willy Tarreau75c62c22018-11-22 11:02:09 +0100551 struct stream_interface *si = appctx->owner;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100552 struct buffer *name_buffer = get_trash_chunk();
Willy Tarreaud2d33482019-04-25 17:09:07 +0200553 const char *str;
Willy Tarreau637d85a2021-05-05 17:33:27 +0200554 int max_lines;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100555 int i, max;
Willy Tarreau75c62c22018-11-22 11:02:09 +0100556
557 if (unlikely(si_ic(si)->flags & (CF_WRITE_ERROR|CF_SHUTW)))
558 return 1;
559
560 chunk_reset(&trash);
561
Willy Tarreaud2d33482019-04-25 17:09:07 +0200562 switch (profiling & HA_PROF_TASKS_MASK) {
Willy Tarreauaa622b82021-01-28 21:44:22 +0100563 case HA_PROF_TASKS_AOFF: str="auto-off"; break;
564 case HA_PROF_TASKS_AON: str="auto-on"; break;
Willy Tarreaud2d33482019-04-25 17:09:07 +0200565 case HA_PROF_TASKS_ON: str="on"; break;
566 default: str="off"; break;
567 }
568
Willy Tarreau637d85a2021-05-05 17:33:27 +0200569 if ((appctx->ctx.cli.i0 & 3) != 0)
570 goto skip_status;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100571
Willy Tarreaud2d33482019-04-25 17:09:07 +0200572 chunk_printf(&trash,
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200573 "Per-task CPU profiling : %-8s # set profiling tasks {on|auto|off}\n"
574 "Memory usage profiling : %-8s # set profiling memory {on|off}\n",
575 str, (profiling & HA_PROF_MEMORY) ? "on" : "off");
Willy Tarreau75c62c22018-11-22 11:02:09 +0100576
Willy Tarreau637d85a2021-05-05 17:33:27 +0200577 if (ci_putchk(si_ic(si), &trash) == -1) {
578 /* failed, try again */
579 si_rx_room_blk(si);
580 return 0;
581 }
582
583 appctx->ctx.cli.i1 = 0; // reset first line to dump
584 if ((appctx->ctx.cli.i0 & 4) == 0)
585 appctx->ctx.cli.i0++; // next step
586
587 skip_status:
588 if ((appctx->ctx.cli.i0 & 3) != 1)
589 goto skip_tasks;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100590
Willy Tarreau637d85a2021-05-05 17:33:27 +0200591 memcpy(tmp_activity, sched_activity, sizeof(tmp_activity));
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200592 if (appctx->ctx.cli.o1)
593 qsort(tmp_activity, 256, sizeof(tmp_activity[0]), cmp_sched_activity_addr);
594 else
595 qsort(tmp_activity, 256, sizeof(tmp_activity[0]), cmp_sched_activity_calls);
Willy Tarreau637d85a2021-05-05 17:33:27 +0200596
597 if (!appctx->ctx.cli.i1)
598 chunk_appendf(&trash, "Tasks activity:\n"
599 " function calls cpu_tot cpu_avg lat_tot lat_avg\n");
600
601 max_lines = appctx->ctx.cli.o0;
602 if (!max_lines)
603 max_lines = 256;
604
605 for (i = appctx->ctx.cli.i1; i < max_lines && tmp_activity[i].calls; i++) {
606 appctx->ctx.cli.i1 = i;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100607 chunk_reset(name_buffer);
608
609 if (!tmp_activity[i].func)
610 chunk_printf(name_buffer, "other");
611 else
612 resolve_sym_name(name_buffer, "", tmp_activity[i].func);
613
614 /* reserve 35 chars for name+' '+#calls, knowing that longer names
615 * are often used for less often called functions.
616 */
617 max = 35 - name_buffer->data;
618 if (max < 1)
619 max = 1;
620 chunk_appendf(&trash, " %s%*llu", name_buffer->area, max, (unsigned long long)tmp_activity[i].calls);
621
622 print_time_short(&trash, " ", tmp_activity[i].cpu_time, "");
623 print_time_short(&trash, " ", tmp_activity[i].cpu_time / tmp_activity[i].calls, "");
624 print_time_short(&trash, " ", tmp_activity[i].lat_time, "");
625 print_time_short(&trash, " ", tmp_activity[i].lat_time / tmp_activity[i].calls, "\n");
Willy Tarreau637d85a2021-05-05 17:33:27 +0200626
627 if (ci_putchk(si_ic(si), &trash) == -1) {
628 /* failed, try again */
629 si_rx_room_blk(si);
630 return 0;
631 }
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100632 }
633
Willy Tarreau75c62c22018-11-22 11:02:09 +0100634 if (ci_putchk(si_ic(si), &trash) == -1) {
635 /* failed, try again */
636 si_rx_room_blk(si);
637 return 0;
638 }
Willy Tarreau637d85a2021-05-05 17:33:27 +0200639
640 appctx->ctx.cli.i1 = 0; // reset first line to dump
641 if ((appctx->ctx.cli.i0 & 4) == 0)
642 appctx->ctx.cli.i0++; // next step
643
644 skip_tasks:
645
Willy Tarreau3e109ee2021-08-28 12:04:25 +0200646#ifdef USE_MEMORY_PROFILING
Willy Tarreau993d44d2021-05-05 18:07:02 +0200647 if ((appctx->ctx.cli.i0 & 3) != 2)
648 goto skip_mem;
649
650 memcpy(tmp_memstats, memprof_stats, sizeof(tmp_memstats));
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200651 if (appctx->ctx.cli.o1)
652 qsort(tmp_memstats, MEMPROF_HASH_BUCKETS+1, sizeof(tmp_memstats[0]), cmp_memprof_addr);
653 else
654 qsort(tmp_memstats, MEMPROF_HASH_BUCKETS+1, sizeof(tmp_memstats[0]), cmp_memprof_stats);
Willy Tarreau993d44d2021-05-05 18:07:02 +0200655
656 if (!appctx->ctx.cli.i1)
657 chunk_appendf(&trash,
658 "Alloc/Free statistics by call place:\n"
Willy Tarreau616491b2021-05-11 09:26:23 +0200659 " Calls | Tot Bytes | Caller and method\n"
Willy Tarreau993d44d2021-05-05 18:07:02 +0200660 "<- alloc -> <- free ->|<-- alloc ---> <-- free ---->|\n");
661
662 max_lines = appctx->ctx.cli.o0;
663 if (!max_lines)
664 max_lines = MEMPROF_HASH_BUCKETS + 1;
665
666 for (i = appctx->ctx.cli.i1; i < max_lines; i++) {
667 struct memprof_stats *entry = &tmp_memstats[i];
668
669 appctx->ctx.cli.i1 = i;
670 if (!entry->alloc_calls && !entry->free_calls)
671 continue;
672 chunk_appendf(&trash, "%11llu %11llu %14llu %14llu| %16p ",
673 entry->alloc_calls, entry->free_calls,
674 entry->alloc_tot, entry->free_tot,
675 entry->caller);
676
677 if (entry->caller)
678 resolve_sym_name(&trash, NULL, entry->caller);
679 else
680 chunk_appendf(&trash, "[other]");
681
Willy Tarreau60786932021-10-22 16:26:12 +0200682 chunk_appendf(&trash," %s(%lld)", memprof_methods[entry->method],
Willy Tarreau616491b2021-05-11 09:26:23 +0200683 (long long)(entry->alloc_tot - entry->free_tot) / (long long)(entry->alloc_calls + entry->free_calls));
Willy Tarreau993d44d2021-05-05 18:07:02 +0200684
Willy Tarreau60786932021-10-22 16:26:12 +0200685 if (entry->alloc_tot && entry->free_tot) {
686 /* that's a realloc, show the total diff to help spot leaks */
687 chunk_appendf(&trash," [delta=%lld]", (long long)(entry->alloc_tot - entry->free_tot));
688 }
689
690 chunk_appendf(&trash, "\n");
691
Willy Tarreau993d44d2021-05-05 18:07:02 +0200692 if (ci_putchk(si_ic(si), &trash) == -1) {
693 si_rx_room_blk(si);
694 return 0;
695 }
696 }
697
698 if (ci_putchk(si_ic(si), &trash) == -1) {
699 si_rx_room_blk(si);
700 return 0;
701 }
702
Willy Tarreauf5fb8582021-05-11 14:06:24 +0200703 tot_alloc_calls = tot_free_calls = tot_alloc_bytes = tot_free_bytes = 0;
704 for (i = 0; i < max_lines; i++) {
705 tot_alloc_calls += tmp_memstats[i].alloc_calls;
706 tot_free_calls += tmp_memstats[i].free_calls;
707 tot_alloc_bytes += tmp_memstats[i].alloc_tot;
708 tot_free_bytes += tmp_memstats[i].free_tot;
709 }
710
711 chunk_appendf(&trash,
712 "-----------------------|-----------------------------|\n"
713 "%11llu %11llu %14llu %14llu| <- Total; Delta_calls=%lld; Delta_bytes=%lld\n",
714 tot_alloc_calls, tot_free_calls,
715 tot_alloc_bytes, tot_free_bytes,
716 tot_alloc_calls - tot_free_calls,
717 tot_alloc_bytes - tot_free_bytes);
718
719 if (ci_putchk(si_ic(si), &trash) == -1) {
720 si_rx_room_blk(si);
721 return 0;
722 }
723
Willy Tarreau993d44d2021-05-05 18:07:02 +0200724 appctx->ctx.cli.i1 = 0; // reset first line to dump
725 if ((appctx->ctx.cli.i0 & 4) == 0)
726 appctx->ctx.cli.i0++; // next step
727
728 skip_mem:
729#endif // USE_MEMORY_PROFILING
730
Willy Tarreau75c62c22018-11-22 11:02:09 +0100731 return 1;
732}
733
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200734/* parse a "show profiling" command. It returns 1 on failure, 0 if it starts to dump.
735 * - cli.i0 is set to the first state (0=all, 4=status, 5=tasks, 6=memory)
736 * - cli.o1 is set to 1 if the output must be sorted by addr instead of usage
737 * - cli.o0 is set to the number of lines of output
738 */
Willy Tarreau42712cb2021-05-05 17:48:13 +0200739static int cli_parse_show_profiling(char **args, char *payload, struct appctx *appctx, void *private)
740{
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200741 int arg;
742
Willy Tarreau42712cb2021-05-05 17:48:13 +0200743 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
744 return 1;
745
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200746 for (arg = 2; *args[arg]; arg++) {
747 if (strcmp(args[arg], "all") == 0) {
748 appctx->ctx.cli.i0 = 0; // will cycle through 0,1,2; default
749 }
750 else if (strcmp(args[arg], "status") == 0) {
751 appctx->ctx.cli.i0 = 4; // will visit status only
752 }
753 else if (strcmp(args[arg], "tasks") == 0) {
754 appctx->ctx.cli.i0 = 5; // will visit tasks only
755 }
756 else if (strcmp(args[arg], "memory") == 0) {
757 appctx->ctx.cli.i0 = 6; // will visit memory only
758 }
759 else if (strcmp(args[arg], "byaddr") == 0) {
760 appctx->ctx.cli.o1 = 1; // sort output by address instead of usage
761 }
762 else if (isdigit((unsigned char)*args[arg])) {
763 appctx->ctx.cli.o0 = atoi(args[arg]); // number of entries to dump
764 }
765 else
766 return cli_err(appctx, "Expects either 'all', 'status', 'tasks', 'memory', 'byaddr' or a max number of output lines.\n");
Willy Tarreau42712cb2021-05-05 17:48:13 +0200767 }
768 return 0;
769}
770
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100771/* This function scans all threads' run queues and collects statistics about
772 * running tasks. It returns 0 if the output buffer is full and it needs to be
773 * called again, otherwise non-zero.
774 */
775static int cli_io_handler_show_tasks(struct appctx *appctx)
776{
777 struct sched_activity tmp_activity[256] __attribute__((aligned(64)));
778 struct stream_interface *si = appctx->owner;
779 struct buffer *name_buffer = get_trash_chunk();
780 struct sched_activity *entry;
781 const struct tasklet *tl;
782 const struct task *t;
783 uint64_t now_ns, lat;
784 struct eb32sc_node *rqnode;
785 uint64_t tot_calls;
786 int thr, queue;
787 int i, max;
788
789 if (unlikely(si_ic(si)->flags & (CF_WRITE_ERROR|CF_SHUTW)))
790 return 1;
791
792 /* It's not possible to scan queues in small chunks and yield in the
793 * middle of the dump and come back again. So what we're doing instead
794 * is to freeze all threads and inspect their queues at once as fast as
795 * possible, using a sched_activity array to collect metrics with
796 * limited collision, then we'll report statistics only. The tasks'
797 * #calls will reflect the number of occurrences, and the lat_time will
Willy Tarreau75f72332021-01-29 15:04:16 +0100798 * reflect the latency when set. We prefer to take the time before
799 * calling thread_isolate() so that the wait time doesn't impact the
800 * measurement accuracy. However this requires to take care of negative
801 * times since tasks might be queued after we retrieve it.
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100802 */
803
804 now_ns = now_mono_time();
805 memset(tmp_activity, 0, sizeof(tmp_activity));
806
807 thread_isolate();
808
809 /* 1. global run queue */
810
811#ifdef USE_THREAD
812 rqnode = eb32sc_first(&rqueue, ~0UL);
813 while (rqnode) {
814 t = eb32sc_entry(rqnode, struct task, rq);
815 entry = sched_activity_entry(tmp_activity, t->process);
816 if (t->call_date) {
817 lat = now_ns - t->call_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100818 if ((int64_t)lat > 0)
819 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100820 }
821 entry->calls++;
822 rqnode = eb32sc_next(rqnode, ~0UL);
823 }
824#endif
825 /* 2. all threads's local run queues */
826 for (thr = 0; thr < global.nbthread; thr++) {
827 /* task run queue */
828 rqnode = eb32sc_first(&task_per_thread[thr].rqueue, ~0UL);
829 while (rqnode) {
830 t = eb32sc_entry(rqnode, struct task, rq);
831 entry = sched_activity_entry(tmp_activity, t->process);
832 if (t->call_date) {
833 lat = now_ns - t->call_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100834 if ((int64_t)lat > 0)
835 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100836 }
837 entry->calls++;
838 rqnode = eb32sc_next(rqnode, ~0UL);
839 }
840
841 /* shared tasklet list */
842 list_for_each_entry(tl, mt_list_to_list(&task_per_thread[thr].shared_tasklet_list), list) {
843 t = (const struct task *)tl;
844 entry = sched_activity_entry(tmp_activity, t->process);
845 if (!TASK_IS_TASKLET(t) && t->call_date) {
846 lat = now_ns - t->call_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100847 if ((int64_t)lat > 0)
848 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100849 }
850 entry->calls++;
851 }
852
853 /* classful tasklets */
854 for (queue = 0; queue < TL_CLASSES; queue++) {
855 list_for_each_entry(tl, &task_per_thread[thr].tasklets[queue], list) {
856 t = (const struct task *)tl;
857 entry = sched_activity_entry(tmp_activity, t->process);
858 if (!TASK_IS_TASKLET(t) && t->call_date) {
859 lat = now_ns - t->call_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100860 if ((int64_t)lat > 0)
861 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100862 }
863 entry->calls++;
864 }
865 }
866 }
867
868 /* hopefully we're done */
869 thread_release();
870
871 chunk_reset(&trash);
872
873 tot_calls = 0;
874 for (i = 0; i < 256; i++)
875 tot_calls += tmp_activity[i].calls;
876
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200877 qsort(tmp_activity, 256, sizeof(tmp_activity[0]), cmp_sched_activity_calls);
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100878
879 chunk_appendf(&trash, "Running tasks: %d (%d threads)\n"
880 " function places %% lat_tot lat_avg\n",
881 (int)tot_calls, global.nbthread);
882
883 for (i = 0; i < 256 && tmp_activity[i].calls; i++) {
884 chunk_reset(name_buffer);
885
886 if (!tmp_activity[i].func)
887 chunk_printf(name_buffer, "other");
888 else
889 resolve_sym_name(name_buffer, "", tmp_activity[i].func);
890
891 /* reserve 35 chars for name+' '+#calls, knowing that longer names
892 * are often used for less often called functions.
893 */
894 max = 35 - name_buffer->data;
895 if (max < 1)
896 max = 1;
897 chunk_appendf(&trash, " %s%*llu %3d.%1d",
898 name_buffer->area, max, (unsigned long long)tmp_activity[i].calls,
899 (int)(100ULL * tmp_activity[i].calls / tot_calls),
900 (int)((1000ULL * tmp_activity[i].calls / tot_calls)%10));
901 print_time_short(&trash, " ", tmp_activity[i].lat_time, "");
902 print_time_short(&trash, " ", tmp_activity[i].lat_time / tmp_activity[i].calls, "\n");
903 }
904
905 if (ci_putchk(si_ic(si), &trash) == -1) {
906 /* failed, try again */
907 si_rx_room_blk(si);
908 return 0;
909 }
910 return 1;
911}
912
Willy Tarreau75c62c22018-11-22 11:02:09 +0100913/* config keyword parsers */
914static struct cfg_kw_list cfg_kws = {ILH, {
Willy Tarreauca3afc22021-05-05 18:33:19 +0200915#ifdef USE_MEMORY_PROFILING
916 { CFG_GLOBAL, "profiling.memory", cfg_parse_prof_memory },
917#endif
Willy Tarreau75c62c22018-11-22 11:02:09 +0100918 { CFG_GLOBAL, "profiling.tasks", cfg_parse_prof_tasks },
919 { 0, NULL, NULL }
920}};
921
Willy Tarreau0108d902018-11-25 19:14:37 +0100922INITCALL1(STG_REGISTER, cfg_register_keywords, &cfg_kws);
923
Willy Tarreau75c62c22018-11-22 11:02:09 +0100924/* register cli keywords */
925static struct cli_kw_list cli_kws = {{ },{
Daniel Corbett67b3cef2021-05-10 14:08:40 -0400926 { { "set", "profiling", NULL }, "set profiling <what> {auto|on|off} : enable/disable resource profiling (tasks,memory)", cli_parse_set_profiling, NULL },
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200927 { { "show", "profiling", NULL }, "show profiling [<what>|<#lines>|byaddr]*: show profiling state (all,status,tasks,memory)", cli_parse_show_profiling, cli_io_handler_show_profiling, NULL },
Willy Tarreaub205bfd2021-05-07 11:38:37 +0200928 { { "show", "tasks", NULL }, "show tasks : show running tasks", NULL, cli_io_handler_show_tasks, NULL },
Willy Tarreau75c62c22018-11-22 11:02:09 +0100929 {{},}
930}};
931
Willy Tarreau0108d902018-11-25 19:14:37 +0100932INITCALL1(STG_REGISTER, cli_register_kw, &cli_kws);