blob: 67c1017b721f51b0ee0b35ea4afae1c07c2912eb [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 Tarreaue8d006a2022-05-05 14:19:00 +020015#include <haproxy/applet.h>
Willy Tarreau6be78492020-06-05 00:00:29 +020016#include <haproxy/cfgparse.h>
Willy Tarreau55542642021-10-08 09:33:24 +020017#include <haproxy/clock.h>
Willy Tarreauf1d32c42020-06-04 21:07:02 +020018#include <haproxy/channel.h>
Willy Tarreau83487a82020-06-04 20:19:54 +020019#include <haproxy/cli.h>
Willy Tarreaub2551052020-06-09 09:07:15 +020020#include <haproxy/freq_ctr.h>
Willy Tarreau5edca2f2022-05-27 09:25:10 +020021#include <haproxy/sc_strm.h>
Willy Tarreaucb086c62022-05-27 09:47:12 +020022#include <haproxy/stconn.h>
Willy Tarreau48fbcae2020-06-03 18:09:46 +020023#include <haproxy/tools.h>
Willy Tarreaua26be372021-10-06 16:26:33 +020024#include <haproxy/xxhash.h>
Willy Tarreau75c62c22018-11-22 11:02:09 +010025
Willy Tarreaue8d006a2022-05-05 14:19:00 +020026/* CLI context for the "show profiling" command */
27struct show_prof_ctx {
28 int dump_step; /* 0,1,2,4,5,6; see cli_iohandler_show_profiling() */
29 int linenum; /* next line to be dumped (starts at 0) */
30 int maxcnt; /* max line count per step (0=not set) */
31 int by_addr; /* 0=sort by usage, 1=sort by address */
32};
33
Willy Tarreauf93c7be2021-05-05 17:07:09 +020034#if defined(DEBUG_MEM_STATS)
35/* these ones are macros in bug.h when DEBUG_MEM_STATS is set, and will
36 * prevent the new ones from being redefined.
37 */
38#undef calloc
39#undef malloc
40#undef realloc
41#endif
Willy Tarreau75c62c22018-11-22 11:02:09 +010042
43/* bit field of profiling options. Beware, may be modified at runtime! */
Willy Tarreauef7380f2021-05-05 16:28:31 +020044unsigned int profiling __read_mostly = HA_PROF_TASKS_AOFF;
Willy Tarreau609aad92018-11-22 08:31:09 +010045
46/* One struct per thread containing all collected measurements */
47struct activity activity[MAX_THREADS] __attribute__((aligned(64))) = { };
48
Willy Tarreau3fb6a7b2021-01-28 19:19:26 +010049/* One struct per function pointer hash entry (256 values, 0=collision) */
50struct sched_activity sched_activity[256] __attribute__((aligned(64))) = { };
Willy Tarreau609aad92018-11-22 08:31:09 +010051
Willy Tarreaudb87fc72021-05-05 16:50:40 +020052
Willy Tarreaue15615c2021-08-28 12:04:25 +020053#ifdef USE_MEMORY_PROFILING
Willy Tarreau616491b2021-05-11 09:26:23 +020054
55static const char *const memprof_methods[MEMPROF_METH_METHODS] = {
Willy Tarreaufacfad22022-08-17 09:12:53 +020056 "unknown", "malloc", "calloc", "realloc", "free", "p_alloc", "p_free",
Willy Tarreau616491b2021-05-11 09:26:23 +020057};
58
Willy Tarreaudb87fc72021-05-05 16:50:40 +020059/* last one is for hash collisions ("others") and has no caller address */
60struct memprof_stats memprof_stats[MEMPROF_HASH_BUCKETS + 1] = { };
61
Willy Tarreauf93c7be2021-05-05 17:07:09 +020062/* used to detect recursive calls */
63static THREAD_LOCAL int in_memprof = 0;
64
Willy Tarreauf93c7be2021-05-05 17:07:09 +020065/* These ones are used by glibc and will be called early. They are in charge of
66 * initializing the handlers with the original functions.
67 */
68static void *memprof_malloc_initial_handler(size_t size);
69static void *memprof_calloc_initial_handler(size_t nmemb, size_t size);
70static void *memprof_realloc_initial_handler(void *ptr, size_t size);
71static void memprof_free_initial_handler(void *ptr);
72
73/* Fallback handlers for the main alloc/free functions. They are preset to
74 * the initializer in order to save a test in the functions's critical path.
75 */
76static void *(*memprof_malloc_handler)(size_t size) = memprof_malloc_initial_handler;
77static void *(*memprof_calloc_handler)(size_t nmemb, size_t size) = memprof_calloc_initial_handler;
78static void *(*memprof_realloc_handler)(void *ptr, size_t size) = memprof_realloc_initial_handler;
79static void (*memprof_free_handler)(void *ptr) = memprof_free_initial_handler;
80
81/* Used to force to die if it's not possible to retrieve the allocation
82 * functions. We cannot even use stdio in this case.
83 */
84static __attribute__((noreturn)) void memprof_die(const char *msg)
85{
86 DISGUISE(write(2, msg, strlen(msg)));
87 exit(1);
88}
89
90/* Resolve original allocation functions and initialize all handlers.
91 * This must be called very early at boot, before the very first malloc()
92 * call, and is not thread-safe! It's not even possible to use stdio there.
93 * Worse, we have to account for the risk of reentrance from dlsym() when
94 * it tries to prepare its error messages. Here its ahndled by in_memprof
95 * that makes allocators return NULL. dlsym() handles it gracefully. An
Ilya Shipitsin3df59892021-05-10 12:50:00 +050096 * alternate approach consists in calling aligned_alloc() from these places
Willy Tarreauf93c7be2021-05-05 17:07:09 +020097 * but that would mean not being able to intercept it later if considered
98 * useful to do so.
99 */
100static void memprof_init()
101{
102 in_memprof++;
103 memprof_malloc_handler = get_sym_next_addr("malloc");
104 if (!memprof_malloc_handler)
105 memprof_die("FATAL: malloc() function not found.\n");
106
107 memprof_calloc_handler = get_sym_next_addr("calloc");
108 if (!memprof_calloc_handler)
109 memprof_die("FATAL: calloc() function not found.\n");
110
111 memprof_realloc_handler = get_sym_next_addr("realloc");
112 if (!memprof_realloc_handler)
113 memprof_die("FATAL: realloc() function not found.\n");
114
115 memprof_free_handler = get_sym_next_addr("free");
116 if (!memprof_free_handler)
117 memprof_die("FATAL: free() function not found.\n");
118 in_memprof--;
119}
120
121/* the initial handlers will initialize all regular handlers and will call the
122 * one they correspond to. A single one of these functions will typically be
123 * called, though it's unknown which one (as any might be called before main).
124 */
125static void *memprof_malloc_initial_handler(size_t size)
126{
127 if (in_memprof) {
128 /* it's likely that dlsym() needs malloc(), let's fail */
129 return NULL;
130 }
131
132 memprof_init();
133 return memprof_malloc_handler(size);
134}
135
136static void *memprof_calloc_initial_handler(size_t nmemb, size_t size)
137{
138 if (in_memprof) {
139 /* it's likely that dlsym() needs calloc(), let's fail */
140 return NULL;
141 }
142 memprof_init();
143 return memprof_calloc_handler(nmemb, size);
144}
145
146static void *memprof_realloc_initial_handler(void *ptr, size_t size)
147{
148 if (in_memprof) {
149 /* it's likely that dlsym() needs realloc(), let's fail */
150 return NULL;
151 }
152
153 memprof_init();
154 return memprof_realloc_handler(ptr, size);
155}
156
157static void memprof_free_initial_handler(void *ptr)
158{
159 memprof_init();
160 memprof_free_handler(ptr);
161}
162
163/* Assign a bin for the memprof_stats to the return address. May perform a few
164 * attempts before finding the right one, but always succeeds (in the worst
165 * case, returns a default bin). The caller address is atomically set except
166 * for the default one which is never set.
167 */
Willy Tarreau219afa22022-08-17 08:53:36 +0200168struct memprof_stats *memprof_get_bin(const void *ra, enum memprof_method meth)
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200169{
170 int retries = 16; // up to 16 consecutive entries may be tested.
Willy Tarreau4a753282021-05-09 23:18:50 +0200171 const void *old;
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200172 unsigned int bin;
173
Willy Tarreau245d32f2022-09-07 11:20:01 +0200174 bin = ptr_hash(ra, MEMPROF_HASH_BITS);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200175 for (; memprof_stats[bin].caller != ra; bin = (bin + 1) & (MEMPROF_HASH_BUCKETS - 1)) {
176 if (!--retries) {
177 bin = MEMPROF_HASH_BUCKETS;
178 break;
179 }
180
181 old = NULL;
182 if (!memprof_stats[bin].caller &&
Willy Tarreau616491b2021-05-11 09:26:23 +0200183 HA_ATOMIC_CAS(&memprof_stats[bin].caller, &old, ra)) {
184 memprof_stats[bin].method = meth;
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200185 break;
Willy Tarreau616491b2021-05-11 09:26:23 +0200186 }
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200187 }
188 return &memprof_stats[bin];
189}
190
191/* This is the new global malloc() function. It must optimize for the normal
192 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
193 * It must remain simple to guarantee the lack of reentrance. stdio is not
194 * possible there even for debugging. The reported size is the really allocated
195 * one as returned by malloc_usable_size(), because this will allow it to be
196 * compared to the one before realloc() or free(). This is a GNU and jemalloc
197 * extension but other systems may also store this size in ptr[-1].
198 */
199void *malloc(size_t size)
200{
201 struct memprof_stats *bin;
202 void *ret;
203
204 if (likely(!(profiling & HA_PROF_MEMORY)))
205 return memprof_malloc_handler(size);
206
207 ret = memprof_malloc_handler(size);
Willy Tarreau1de51eb2021-10-22 16:33:53 +0200208 size = malloc_usable_size(ret) + sizeof(void *);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200209
Willy Tarreau616491b2021-05-11 09:26:23 +0200210 bin = memprof_get_bin(__builtin_return_address(0), MEMPROF_METH_MALLOC);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200211 _HA_ATOMIC_ADD(&bin->alloc_calls, 1);
212 _HA_ATOMIC_ADD(&bin->alloc_tot, size);
213 return ret;
214}
215
216/* This is the new global calloc() function. It must optimize for the normal
217 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
218 * It must remain simple to guarantee the lack of reentrance. stdio is not
219 * possible there even for debugging. The reported size is the really allocated
220 * one as returned by malloc_usable_size(), because this will allow it to be
221 * compared to the one before realloc() or free(). This is a GNU and jemalloc
222 * extension but other systems may also store this size in ptr[-1].
223 */
224void *calloc(size_t nmemb, size_t size)
225{
226 struct memprof_stats *bin;
227 void *ret;
228
229 if (likely(!(profiling & HA_PROF_MEMORY)))
230 return memprof_calloc_handler(nmemb, size);
231
232 ret = memprof_calloc_handler(nmemb, size);
Willy Tarreau1de51eb2021-10-22 16:33:53 +0200233 size = malloc_usable_size(ret) + sizeof(void *);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200234
Willy Tarreau616491b2021-05-11 09:26:23 +0200235 bin = memprof_get_bin(__builtin_return_address(0), MEMPROF_METH_CALLOC);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200236 _HA_ATOMIC_ADD(&bin->alloc_calls, 1);
237 _HA_ATOMIC_ADD(&bin->alloc_tot, size);
238 return ret;
239}
240
241/* This is the new global realloc() function. It must optimize for the normal
242 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
243 * It must remain simple to guarantee the lack of reentrance. stdio is not
244 * possible there even for debugging. The reported size is the really allocated
245 * one as returned by malloc_usable_size(), because this will allow it to be
246 * compared to the one before realloc() or free(). This is a GNU and jemalloc
247 * extension but other systems may also store this size in ptr[-1].
248 * Depending on the old vs new size, it's considered as an allocation or a free
249 * (or neither if the size remains the same).
250 */
251void *realloc(void *ptr, size_t size)
252{
253 struct memprof_stats *bin;
254 size_t size_before;
255 void *ret;
256
257 if (likely(!(profiling & HA_PROF_MEMORY)))
258 return memprof_realloc_handler(ptr, size);
259
260 size_before = malloc_usable_size(ptr);
261 ret = memprof_realloc_handler(ptr, size);
Willy Tarreau2639e2e2021-05-07 08:01:35 +0200262 size = malloc_usable_size(ret);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200263
Willy Tarreau1de51eb2021-10-22 16:33:53 +0200264 /* only count the extra link for new allocations */
265 if (!ptr)
266 size += sizeof(void *);
267
Willy Tarreau616491b2021-05-11 09:26:23 +0200268 bin = memprof_get_bin(__builtin_return_address(0), MEMPROF_METH_REALLOC);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200269 if (size > size_before) {
270 _HA_ATOMIC_ADD(&bin->alloc_calls, 1);
Willy Tarreau79acefa2021-05-11 09:12:56 +0200271 _HA_ATOMIC_ADD(&bin->alloc_tot, size - size_before);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200272 } else if (size < size_before) {
273 _HA_ATOMIC_ADD(&bin->free_calls, 1);
Willy Tarreau79acefa2021-05-11 09:12:56 +0200274 _HA_ATOMIC_ADD(&bin->free_tot, size_before - size);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200275 }
276 return ret;
277}
278
279/* This is the new global free() function. It must optimize for the normal
280 * case (i.e. profiling disabled) hence the first test to permit a direct jump.
281 * It must remain simple to guarantee the lack of reentrance. stdio is not
282 * possible there even for debugging. The reported size is the really allocated
283 * one as returned by malloc_usable_size(), because this will allow it to be
284 * compared to the one before realloc() or free(). This is a GNU and jemalloc
285 * extension but other systems may also store this size in ptr[-1]. Since
286 * free() is often called on NULL pointers to collect garbage at the end of
287 * many functions or during config parsing, as a special case free(NULL)
288 * doesn't update any stats.
289 */
290void free(void *ptr)
291{
292 struct memprof_stats *bin;
293 size_t size_before;
294
295 if (likely(!(profiling & HA_PROF_MEMORY) || !ptr)) {
296 memprof_free_handler(ptr);
297 return;
298 }
299
Willy Tarreau1de51eb2021-10-22 16:33:53 +0200300 size_before = malloc_usable_size(ptr) + sizeof(void *);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200301 memprof_free_handler(ptr);
302
Willy Tarreau616491b2021-05-11 09:26:23 +0200303 bin = memprof_get_bin(__builtin_return_address(0), MEMPROF_METH_FREE);
Willy Tarreauf93c7be2021-05-05 17:07:09 +0200304 _HA_ATOMIC_ADD(&bin->free_calls, 1);
305 _HA_ATOMIC_ADD(&bin->free_tot, size_before);
306}
307
Willy Tarreaudb87fc72021-05-05 16:50:40 +0200308#endif // USE_MEMORY_PROFILING
309
Willy Tarreau609aad92018-11-22 08:31:09 +0100310/* Updates the current thread's statistics about stolen CPU time. The unit for
311 * <stolen> is half-milliseconds.
312 */
313void report_stolen_time(uint64_t stolen)
314{
315 activity[tid].cpust_total += stolen;
316 update_freq_ctr(&activity[tid].cpust_1s, stolen);
317 update_freq_ctr_period(&activity[tid].cpust_15s, 15000, stolen);
318}
Willy Tarreau75c62c22018-11-22 11:02:09 +0100319
Willy Tarreau20adfde2021-10-08 11:34:46 +0200320/* Update avg_loop value for the current thread and possibly decide to enable
321 * task-level profiling on the current thread based on its average run time.
322 * The <run_time> argument is the number of microseconds elapsed since the
323 * last time poll() returned.
Willy Tarreaue0650222021-10-06 16:22:09 +0200324 */
Willy Tarreau20adfde2021-10-08 11:34:46 +0200325void activity_count_runtime(uint32_t run_time)
Willy Tarreaue0650222021-10-06 16:22:09 +0200326{
Willy Tarreaue0650222021-10-06 16:22:09 +0200327 uint32_t up, down;
328
329 /* 1 millisecond per loop on average over last 1024 iterations is
330 * enough to turn on profiling.
331 */
332 up = 1000;
333 down = up * 99 / 100;
334
Willy Tarreaue0650222021-10-06 16:22:09 +0200335 run_time = swrate_add(&activity[tid].avg_loop_us, TIME_STATS_SAMPLES, run_time);
336
337 /* In automatic mode, reaching the "up" threshold on average switches
338 * profiling to "on" when automatic, and going back below the "down"
339 * threshold switches to off. The forced modes don't check the load.
340 */
Willy Tarreaubdcd3252022-06-22 09:19:46 +0200341 if (!(_HA_ATOMIC_LOAD(&th_ctx->flags) & TH_FL_TASK_PROFILING)) {
Willy Tarreaue0650222021-10-06 16:22:09 +0200342 if (unlikely((profiling & HA_PROF_TASKS_MASK) == HA_PROF_TASKS_ON ||
343 ((profiling & HA_PROF_TASKS_MASK) == HA_PROF_TASKS_AON &&
344 swrate_avg(run_time, TIME_STATS_SAMPLES) >= up)))
Willy Tarreau680ed5f2022-06-13 15:59:39 +0200345 _HA_ATOMIC_OR(&th_ctx->flags, TH_FL_TASK_PROFILING);
Willy Tarreaue0650222021-10-06 16:22:09 +0200346 } else {
347 if (unlikely((profiling & HA_PROF_TASKS_MASK) == HA_PROF_TASKS_OFF ||
348 ((profiling & HA_PROF_TASKS_MASK) == HA_PROF_TASKS_AOFF &&
349 swrate_avg(run_time, TIME_STATS_SAMPLES) <= down)))
Willy Tarreau680ed5f2022-06-13 15:59:39 +0200350 _HA_ATOMIC_AND(&th_ctx->flags, ~TH_FL_TASK_PROFILING);
Willy Tarreaue0650222021-10-06 16:22:09 +0200351 }
352}
353
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 Tarreaue15615c2021-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 Tarreaua26be372021-10-06 16:26:33 +0200528/* Computes the index of function pointer <func> for use with sched_activity[]
529 * or any other similar array passed in <array>, and returns a pointer to the
530 * entry after having atomically assigned it to this function pointer. Note
531 * that in case of collision, the first entry is returned instead ("other").
532 */
533struct sched_activity *sched_activity_entry(struct sched_activity *array, const void *func)
534{
535 uint64_t hash = XXH64_avalanche(XXH64_mergeRound((size_t)func, (size_t)func));
536 struct sched_activity *ret;
537 const void *old = NULL;
538
539 hash ^= (hash >> 32);
540 hash ^= (hash >> 16);
541 hash ^= (hash >> 8);
542 hash &= 0xff;
543 ret = &array[hash];
544
545 if (likely(ret->func == func))
546 return ret;
547
548 if (HA_ATOMIC_CAS(&ret->func, &old, func))
549 return ret;
550
551 return array;
552}
553
Willy Tarreau75c62c22018-11-22 11:02:09 +0100554/* This function dumps all profiling settings. It returns 0 if the output
555 * buffer is full and it needs to be called again, otherwise non-zero.
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200556 * It dumps some parts depending on the following states from show_prof_ctx:
557 * dump_step:
Willy Tarreau637d85a2021-05-05 17:33:27 +0200558 * 0, 4: dump status, then jump to 1 if 0
559 * 1, 5: dump tasks, then jump to 2 if 1
560 * 2, 6: dump memory, then stop
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200561 * linenum:
Willy Tarreau637d85a2021-05-05 17:33:27 +0200562 * restart line for each step (starts at zero)
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200563 * maxcnt:
Willy Tarreau637d85a2021-05-05 17:33:27 +0200564 * may contain a configured max line count for each step (0=not set)
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200565 * byaddr:
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200566 * 0: sort by usage
567 * 1: sort by address
Willy Tarreau75c62c22018-11-22 11:02:09 +0100568 */
569static int cli_io_handler_show_profiling(struct appctx *appctx)
570{
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200571 struct show_prof_ctx *ctx = appctx->svcctx;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100572 struct sched_activity tmp_activity[256] __attribute__((aligned(64)));
Willy Tarreaue15615c2021-08-28 12:04:25 +0200573#ifdef USE_MEMORY_PROFILING
Willy Tarreau993d44d2021-05-05 18:07:02 +0200574 struct memprof_stats tmp_memstats[MEMPROF_HASH_BUCKETS + 1];
Willy Tarreauf5fb8582021-05-11 14:06:24 +0200575 unsigned long long tot_alloc_calls, tot_free_calls;
576 unsigned long long tot_alloc_bytes, tot_free_bytes;
Willy Tarreau993d44d2021-05-05 18:07:02 +0200577#endif
Willy Tarreauc12b3212022-05-27 11:08:15 +0200578 struct stconn *sc = appctx_sc(appctx);
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100579 struct buffer *name_buffer = get_trash_chunk();
Willy Tarreaud2d33482019-04-25 17:09:07 +0200580 const char *str;
Willy Tarreau637d85a2021-05-05 17:33:27 +0200581 int max_lines;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100582 int i, max;
Willy Tarreau75c62c22018-11-22 11:02:09 +0100583
Willy Tarreau475e4632022-05-27 10:26:46 +0200584 if (unlikely(sc_ic(sc)->flags & (CF_WRITE_ERROR|CF_SHUTW)))
Willy Tarreau75c62c22018-11-22 11:02:09 +0100585 return 1;
586
587 chunk_reset(&trash);
588
Willy Tarreaud2d33482019-04-25 17:09:07 +0200589 switch (profiling & HA_PROF_TASKS_MASK) {
Willy Tarreauaa622b82021-01-28 21:44:22 +0100590 case HA_PROF_TASKS_AOFF: str="auto-off"; break;
591 case HA_PROF_TASKS_AON: str="auto-on"; break;
Willy Tarreaud2d33482019-04-25 17:09:07 +0200592 case HA_PROF_TASKS_ON: str="on"; break;
593 default: str="off"; break;
594 }
595
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200596 if ((ctx->dump_step & 3) != 0)
Willy Tarreau637d85a2021-05-05 17:33:27 +0200597 goto skip_status;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100598
Willy Tarreaud2d33482019-04-25 17:09:07 +0200599 chunk_printf(&trash,
Willy Tarreau00dd44f2021-05-05 16:44:23 +0200600 "Per-task CPU profiling : %-8s # set profiling tasks {on|auto|off}\n"
601 "Memory usage profiling : %-8s # set profiling memory {on|off}\n",
602 str, (profiling & HA_PROF_MEMORY) ? "on" : "off");
Willy Tarreau75c62c22018-11-22 11:02:09 +0100603
Willy Tarreaud0a06d52022-05-18 15:07:19 +0200604 if (applet_putchk(appctx, &trash) == -1) {
Willy Tarreau637d85a2021-05-05 17:33:27 +0200605 /* failed, try again */
Willy Tarreau637d85a2021-05-05 17:33:27 +0200606 return 0;
607 }
608
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200609 ctx->linenum = 0; // reset first line to dump
610 if ((ctx->dump_step & 4) == 0)
611 ctx->dump_step++; // next step
Willy Tarreau637d85a2021-05-05 17:33:27 +0200612
613 skip_status:
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200614 if ((ctx->dump_step & 3) != 1)
Willy Tarreau637d85a2021-05-05 17:33:27 +0200615 goto skip_tasks;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100616
Willy Tarreau637d85a2021-05-05 17:33:27 +0200617 memcpy(tmp_activity, sched_activity, sizeof(tmp_activity));
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200618 if (ctx->by_addr)
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200619 qsort(tmp_activity, 256, sizeof(tmp_activity[0]), cmp_sched_activity_addr);
620 else
621 qsort(tmp_activity, 256, sizeof(tmp_activity[0]), cmp_sched_activity_calls);
Willy Tarreau637d85a2021-05-05 17:33:27 +0200622
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200623 if (!ctx->linenum)
Willy Tarreau637d85a2021-05-05 17:33:27 +0200624 chunk_appendf(&trash, "Tasks activity:\n"
625 " function calls cpu_tot cpu_avg lat_tot lat_avg\n");
626
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200627 max_lines = ctx->maxcnt;
Willy Tarreau637d85a2021-05-05 17:33:27 +0200628 if (!max_lines)
629 max_lines = 256;
630
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200631 for (i = ctx->linenum; i < max_lines && tmp_activity[i].calls; i++) {
632 ctx->linenum = i;
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100633 chunk_reset(name_buffer);
634
635 if (!tmp_activity[i].func)
636 chunk_printf(name_buffer, "other");
637 else
638 resolve_sym_name(name_buffer, "", tmp_activity[i].func);
639
640 /* reserve 35 chars for name+' '+#calls, knowing that longer names
641 * are often used for less often called functions.
642 */
643 max = 35 - name_buffer->data;
644 if (max < 1)
645 max = 1;
646 chunk_appendf(&trash, " %s%*llu", name_buffer->area, max, (unsigned long long)tmp_activity[i].calls);
647
648 print_time_short(&trash, " ", tmp_activity[i].cpu_time, "");
649 print_time_short(&trash, " ", tmp_activity[i].cpu_time / tmp_activity[i].calls, "");
650 print_time_short(&trash, " ", tmp_activity[i].lat_time, "");
651 print_time_short(&trash, " ", tmp_activity[i].lat_time / tmp_activity[i].calls, "\n");
Willy Tarreau637d85a2021-05-05 17:33:27 +0200652
Willy Tarreaud0a06d52022-05-18 15:07:19 +0200653 if (applet_putchk(appctx, &trash) == -1) {
Willy Tarreau637d85a2021-05-05 17:33:27 +0200654 /* failed, try again */
Willy Tarreau637d85a2021-05-05 17:33:27 +0200655 return 0;
656 }
Willy Tarreau1bd67e92021-01-29 00:07:40 +0100657 }
658
Willy Tarreaud0a06d52022-05-18 15:07:19 +0200659 if (applet_putchk(appctx, &trash) == -1) {
Willy Tarreau75c62c22018-11-22 11:02:09 +0100660 /* failed, try again */
Willy Tarreau75c62c22018-11-22 11:02:09 +0100661 return 0;
662 }
Willy Tarreau637d85a2021-05-05 17:33:27 +0200663
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200664 ctx->linenum = 0; // reset first line to dump
665 if ((ctx->dump_step & 4) == 0)
666 ctx->dump_step++; // next step
Willy Tarreau637d85a2021-05-05 17:33:27 +0200667
668 skip_tasks:
669
Willy Tarreaue15615c2021-08-28 12:04:25 +0200670#ifdef USE_MEMORY_PROFILING
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200671 if ((ctx->dump_step & 3) != 2)
Willy Tarreau993d44d2021-05-05 18:07:02 +0200672 goto skip_mem;
673
674 memcpy(tmp_memstats, memprof_stats, sizeof(tmp_memstats));
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200675 if (ctx->by_addr)
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200676 qsort(tmp_memstats, MEMPROF_HASH_BUCKETS+1, sizeof(tmp_memstats[0]), cmp_memprof_addr);
677 else
678 qsort(tmp_memstats, MEMPROF_HASH_BUCKETS+1, sizeof(tmp_memstats[0]), cmp_memprof_stats);
Willy Tarreau993d44d2021-05-05 18:07:02 +0200679
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200680 if (!ctx->linenum)
Willy Tarreau993d44d2021-05-05 18:07:02 +0200681 chunk_appendf(&trash,
682 "Alloc/Free statistics by call place:\n"
Willy Tarreau616491b2021-05-11 09:26:23 +0200683 " Calls | Tot Bytes | Caller and method\n"
Willy Tarreau993d44d2021-05-05 18:07:02 +0200684 "<- alloc -> <- free ->|<-- alloc ---> <-- free ---->|\n");
685
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200686 max_lines = ctx->maxcnt;
Willy Tarreau993d44d2021-05-05 18:07:02 +0200687 if (!max_lines)
688 max_lines = MEMPROF_HASH_BUCKETS + 1;
689
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200690 for (i = ctx->linenum; i < max_lines; i++) {
Willy Tarreau993d44d2021-05-05 18:07:02 +0200691 struct memprof_stats *entry = &tmp_memstats[i];
692
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200693 ctx->linenum = i;
Willy Tarreau993d44d2021-05-05 18:07:02 +0200694 if (!entry->alloc_calls && !entry->free_calls)
695 continue;
696 chunk_appendf(&trash, "%11llu %11llu %14llu %14llu| %16p ",
697 entry->alloc_calls, entry->free_calls,
698 entry->alloc_tot, entry->free_tot,
699 entry->caller);
700
701 if (entry->caller)
702 resolve_sym_name(&trash, NULL, entry->caller);
703 else
704 chunk_appendf(&trash, "[other]");
705
Willy Tarreau8cce4d72021-10-22 16:26:12 +0200706 chunk_appendf(&trash," %s(%lld)", memprof_methods[entry->method],
Willy Tarreau616491b2021-05-11 09:26:23 +0200707 (long long)(entry->alloc_tot - entry->free_tot) / (long long)(entry->alloc_calls + entry->free_calls));
Willy Tarreau993d44d2021-05-05 18:07:02 +0200708
Willy Tarreau8cce4d72021-10-22 16:26:12 +0200709 if (entry->alloc_tot && entry->free_tot) {
710 /* that's a realloc, show the total diff to help spot leaks */
711 chunk_appendf(&trash," [delta=%lld]", (long long)(entry->alloc_tot - entry->free_tot));
712 }
713
Willy Tarreau42b180d2022-08-17 09:35:16 +0200714 if (entry->info) {
715 /* that's a pool name */
716 const struct pool_head *pool = entry->info;
717 chunk_appendf(&trash," [pool=%s]", pool->name);
718 }
719
Willy Tarreau8cce4d72021-10-22 16:26:12 +0200720 chunk_appendf(&trash, "\n");
721
Willy Tarreaud0a06d52022-05-18 15:07:19 +0200722 if (applet_putchk(appctx, &trash) == -1)
Willy Tarreau993d44d2021-05-05 18:07:02 +0200723 return 0;
Willy Tarreau993d44d2021-05-05 18:07:02 +0200724 }
725
Willy Tarreaud0a06d52022-05-18 15:07:19 +0200726 if (applet_putchk(appctx, &trash) == -1)
Willy Tarreau993d44d2021-05-05 18:07:02 +0200727 return 0;
Willy Tarreau993d44d2021-05-05 18:07:02 +0200728
Willy Tarreauf5fb8582021-05-11 14:06:24 +0200729 tot_alloc_calls = tot_free_calls = tot_alloc_bytes = tot_free_bytes = 0;
730 for (i = 0; i < max_lines; i++) {
731 tot_alloc_calls += tmp_memstats[i].alloc_calls;
732 tot_free_calls += tmp_memstats[i].free_calls;
733 tot_alloc_bytes += tmp_memstats[i].alloc_tot;
734 tot_free_bytes += tmp_memstats[i].free_tot;
735 }
736
737 chunk_appendf(&trash,
738 "-----------------------|-----------------------------|\n"
739 "%11llu %11llu %14llu %14llu| <- Total; Delta_calls=%lld; Delta_bytes=%lld\n",
740 tot_alloc_calls, tot_free_calls,
741 tot_alloc_bytes, tot_free_bytes,
742 tot_alloc_calls - tot_free_calls,
743 tot_alloc_bytes - tot_free_bytes);
744
Willy Tarreaud0a06d52022-05-18 15:07:19 +0200745 if (applet_putchk(appctx, &trash) == -1)
Willy Tarreauf5fb8582021-05-11 14:06:24 +0200746 return 0;
Willy Tarreauf5fb8582021-05-11 14:06:24 +0200747
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200748 ctx->linenum = 0; // reset first line to dump
749 if ((ctx->dump_step & 4) == 0)
750 ctx->dump_step++; // next step
Willy Tarreau993d44d2021-05-05 18:07:02 +0200751
752 skip_mem:
753#endif // USE_MEMORY_PROFILING
754
Willy Tarreau75c62c22018-11-22 11:02:09 +0100755 return 1;
756}
757
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200758/* parse a "show profiling" command. It returns 1 on failure, 0 if it starts to dump.
759 * - cli.i0 is set to the first state (0=all, 4=status, 5=tasks, 6=memory)
760 * - cli.o1 is set to 1 if the output must be sorted by addr instead of usage
761 * - cli.o0 is set to the number of lines of output
762 */
Willy Tarreau42712cb2021-05-05 17:48:13 +0200763static int cli_parse_show_profiling(char **args, char *payload, struct appctx *appctx, void *private)
764{
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200765 struct show_prof_ctx *ctx = applet_reserve_svcctx(appctx, sizeof(*ctx));
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200766 int arg;
767
Willy Tarreau42712cb2021-05-05 17:48:13 +0200768 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
769 return 1;
770
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200771 for (arg = 2; *args[arg]; arg++) {
772 if (strcmp(args[arg], "all") == 0) {
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200773 ctx->dump_step = 0; // will cycle through 0,1,2; default
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200774 }
775 else if (strcmp(args[arg], "status") == 0) {
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200776 ctx->dump_step = 4; // will visit status only
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200777 }
778 else if (strcmp(args[arg], "tasks") == 0) {
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200779 ctx->dump_step = 5; // will visit tasks only
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200780 }
781 else if (strcmp(args[arg], "memory") == 0) {
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200782 ctx->dump_step = 6; // will visit memory only
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200783 }
784 else if (strcmp(args[arg], "byaddr") == 0) {
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200785 ctx->by_addr = 1; // sort output by address instead of usage
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200786 }
787 else if (isdigit((unsigned char)*args[arg])) {
Willy Tarreaue8d006a2022-05-05 14:19:00 +0200788 ctx->maxcnt = atoi(args[arg]); // number of entries to dump
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200789 }
790 else
791 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 +0200792 }
793 return 0;
794}
795
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100796/* This function scans all threads' run queues and collects statistics about
797 * running tasks. It returns 0 if the output buffer is full and it needs to be
798 * called again, otherwise non-zero.
799 */
800static int cli_io_handler_show_tasks(struct appctx *appctx)
801{
802 struct sched_activity tmp_activity[256] __attribute__((aligned(64)));
Willy Tarreauc12b3212022-05-27 11:08:15 +0200803 struct stconn *sc = appctx_sc(appctx);
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100804 struct buffer *name_buffer = get_trash_chunk();
805 struct sched_activity *entry;
806 const struct tasklet *tl;
807 const struct task *t;
808 uint64_t now_ns, lat;
Willy Tarreau319d1362022-06-16 16:28:01 +0200809 struct eb32_node *rqnode;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100810 uint64_t tot_calls;
811 int thr, queue;
812 int i, max;
813
Willy Tarreau475e4632022-05-27 10:26:46 +0200814 if (unlikely(sc_ic(sc)->flags & (CF_WRITE_ERROR|CF_SHUTW)))
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100815 return 1;
816
817 /* It's not possible to scan queues in small chunks and yield in the
818 * middle of the dump and come back again. So what we're doing instead
819 * is to freeze all threads and inspect their queues at once as fast as
820 * possible, using a sched_activity array to collect metrics with
821 * limited collision, then we'll report statistics only. The tasks'
822 * #calls will reflect the number of occurrences, and the lat_time will
Willy Tarreau75f72332021-01-29 15:04:16 +0100823 * reflect the latency when set. We prefer to take the time before
824 * calling thread_isolate() so that the wait time doesn't impact the
825 * measurement accuracy. However this requires to take care of negative
826 * times since tasks might be queued after we retrieve it.
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100827 */
828
829 now_ns = now_mono_time();
830 memset(tmp_activity, 0, sizeof(tmp_activity));
831
832 thread_isolate();
833
834 /* 1. global run queue */
835
836#ifdef USE_THREAD
Willy Tarreau6f780382022-06-16 15:30:50 +0200837 for (thr = 0; thr < global.nbthread; thr++) {
838 /* task run queue */
Willy Tarreau319d1362022-06-16 16:28:01 +0200839 rqnode = eb32_first(&ha_thread_ctx[thr].rqueue_shared);
Willy Tarreau6f780382022-06-16 15:30:50 +0200840 while (rqnode) {
Willy Tarreau319d1362022-06-16 16:28:01 +0200841 t = eb32_entry(rqnode, struct task, rq);
Willy Tarreau6f780382022-06-16 15:30:50 +0200842 entry = sched_activity_entry(tmp_activity, t->process);
Willy Tarreau04e50b32022-09-07 14:49:50 +0200843 if (t->wake_date) {
844 lat = now_ns - t->wake_date;
Willy Tarreau6f780382022-06-16 15:30:50 +0200845 if ((int64_t)lat > 0)
846 entry->lat_time += lat;
847 }
848 entry->calls++;
Willy Tarreau319d1362022-06-16 16:28:01 +0200849 rqnode = eb32_next(rqnode);
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100850 }
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100851 }
852#endif
853 /* 2. all threads's local run queues */
854 for (thr = 0; thr < global.nbthread; thr++) {
855 /* task run queue */
Willy Tarreau319d1362022-06-16 16:28:01 +0200856 rqnode = eb32_first(&ha_thread_ctx[thr].rqueue);
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100857 while (rqnode) {
Willy Tarreau319d1362022-06-16 16:28:01 +0200858 t = eb32_entry(rqnode, struct task, rq);
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100859 entry = sched_activity_entry(tmp_activity, t->process);
Willy Tarreau04e50b32022-09-07 14:49:50 +0200860 if (t->wake_date) {
861 lat = now_ns - t->wake_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100862 if ((int64_t)lat > 0)
863 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100864 }
865 entry->calls++;
Willy Tarreau319d1362022-06-16 16:28:01 +0200866 rqnode = eb32_next(rqnode);
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100867 }
868
869 /* shared tasklet list */
Willy Tarreau1a9c9222021-10-01 11:30:33 +0200870 list_for_each_entry(tl, mt_list_to_list(&ha_thread_ctx[thr].shared_tasklet_list), list) {
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100871 t = (const struct task *)tl;
872 entry = sched_activity_entry(tmp_activity, t->process);
Willy Tarreau04e50b32022-09-07 14:49:50 +0200873 if (!TASK_IS_TASKLET(t) && t->wake_date) {
874 lat = now_ns - t->wake_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100875 if ((int64_t)lat > 0)
876 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100877 }
878 entry->calls++;
879 }
880
881 /* classful tasklets */
882 for (queue = 0; queue < TL_CLASSES; queue++) {
Willy Tarreau1a9c9222021-10-01 11:30:33 +0200883 list_for_each_entry(tl, &ha_thread_ctx[thr].tasklets[queue], list) {
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100884 t = (const struct task *)tl;
885 entry = sched_activity_entry(tmp_activity, t->process);
Willy Tarreau04e50b32022-09-07 14:49:50 +0200886 if (!TASK_IS_TASKLET(t) && t->wake_date) {
887 lat = now_ns - t->wake_date;
Willy Tarreau75f72332021-01-29 15:04:16 +0100888 if ((int64_t)lat > 0)
889 entry->lat_time += lat;
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100890 }
891 entry->calls++;
892 }
893 }
894 }
895
896 /* hopefully we're done */
897 thread_release();
898
899 chunk_reset(&trash);
900
901 tot_calls = 0;
902 for (i = 0; i < 256; i++)
903 tot_calls += tmp_activity[i].calls;
904
Willy Tarreauf1c8a382021-05-13 10:00:17 +0200905 qsort(tmp_activity, 256, sizeof(tmp_activity[0]), cmp_sched_activity_calls);
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100906
907 chunk_appendf(&trash, "Running tasks: %d (%d threads)\n"
908 " function places %% lat_tot lat_avg\n",
909 (int)tot_calls, global.nbthread);
910
911 for (i = 0; i < 256 && tmp_activity[i].calls; i++) {
912 chunk_reset(name_buffer);
913
914 if (!tmp_activity[i].func)
915 chunk_printf(name_buffer, "other");
916 else
917 resolve_sym_name(name_buffer, "", tmp_activity[i].func);
918
919 /* reserve 35 chars for name+' '+#calls, knowing that longer names
920 * are often used for less often called functions.
921 */
922 max = 35 - name_buffer->data;
923 if (max < 1)
924 max = 1;
925 chunk_appendf(&trash, " %s%*llu %3d.%1d",
926 name_buffer->area, max, (unsigned long long)tmp_activity[i].calls,
927 (int)(100ULL * tmp_activity[i].calls / tot_calls),
928 (int)((1000ULL * tmp_activity[i].calls / tot_calls)%10));
929 print_time_short(&trash, " ", tmp_activity[i].lat_time, "");
930 print_time_short(&trash, " ", tmp_activity[i].lat_time / tmp_activity[i].calls, "\n");
931 }
932
Willy Tarreaud0a06d52022-05-18 15:07:19 +0200933 if (applet_putchk(appctx, &trash) == -1) {
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100934 /* failed, try again */
Willy Tarreau7eff06e2021-01-29 11:32:55 +0100935 return 0;
936 }
937 return 1;
938}
939
Willy Tarreau75c62c22018-11-22 11:02:09 +0100940/* config keyword parsers */
941static struct cfg_kw_list cfg_kws = {ILH, {
Willy Tarreauca3afc22021-05-05 18:33:19 +0200942#ifdef USE_MEMORY_PROFILING
943 { CFG_GLOBAL, "profiling.memory", cfg_parse_prof_memory },
944#endif
Willy Tarreau75c62c22018-11-22 11:02:09 +0100945 { CFG_GLOBAL, "profiling.tasks", cfg_parse_prof_tasks },
946 { 0, NULL, NULL }
947}};
948
Willy Tarreau0108d902018-11-25 19:14:37 +0100949INITCALL1(STG_REGISTER, cfg_register_keywords, &cfg_kws);
950
Willy Tarreau75c62c22018-11-22 11:02:09 +0100951/* register cli keywords */
952static struct cli_kw_list cli_kws = {{ },{
Daniel Corbett67b3cef2021-05-10 14:08:40 -0400953 { { "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 +0200954 { { "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 +0200955 { { "show", "tasks", NULL }, "show tasks : show running tasks", NULL, cli_io_handler_show_tasks, NULL },
Willy Tarreau75c62c22018-11-22 11:02:09 +0100956 {{},}
957}};
958
Willy Tarreau0108d902018-11-25 19:14:37 +0100959INITCALL1(STG_REGISTER, cli_register_kw, &cli_kws);