blob: 07624ca5a47097ee8f69c3922fe272b11e797139 [file] [log] [blame]
Willy Tarreau4e2b6462019-05-16 17:44:30 +02001/*
2 * Process debugging functions.
3 *
4 * Copyright 2000-2019 Willy Tarreau <willy@haproxy.org>.
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
13#include <signal.h>
14#include <time.h>
15#include <stdio.h>
Willy Tarreau6bdf3e92019-05-20 14:25:05 +020016#include <stdlib.h>
Willy Tarreau4e2b6462019-05-16 17:44:30 +020017
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020018#include <common/buf.h>
Willy Tarreau4e2b6462019-05-16 17:44:30 +020019#include <common/config.h>
20#include <common/debug.h>
21#include <common/hathreads.h>
22#include <common/initcall.h>
23#include <common/standard.h>
24
25#include <types/global.h>
26
27#include <proto/cli.h>
28#include <proto/fd.h>
29#include <proto/stream_interface.h>
30#include <proto/task.h>
31
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020032/* Dumps to the buffer some known information for the desired thread, and
33 * optionally extra info for the current thread. The dump will be appended to
34 * the buffer, so the caller is responsible for preliminary initializing it.
35 * The calling thread ID needs to be passed in <calling_tid> to display a star
Willy Tarreaue6a02fa2019-05-22 07:06:44 +020036 * in front of the calling thread's line (usually it's tid). Any stuck thread
37 * is also prefixed with a '>'.
Willy Tarreau4e2b6462019-05-16 17:44:30 +020038 */
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020039void ha_thread_dump(struct buffer *buf, int thr, int calling_tid)
Willy Tarreau4e2b6462019-05-16 17:44:30 +020040{
41 unsigned long thr_bit = 1UL << thr;
Willy Tarreau9c8800a2019-05-20 20:52:20 +020042 unsigned long long p = thread_info[thr].prev_cpu_time;
43 unsigned long long n = now_cpu_time_thread(&thread_info[thr]);
Willy Tarreaue6a02fa2019-05-22 07:06:44 +020044 int stuck = !!(thread_info[thr].flags & TI_FL_STUCK);
Willy Tarreau4e2b6462019-05-16 17:44:30 +020045
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020046 chunk_appendf(buf,
Willy Tarreaue6a02fa2019-05-22 07:06:44 +020047 "%c%cThread %-2u: act=%d glob=%d wq=%d rq=%d tl=%d tlsz=%d rqsz=%d\n"
48 " stuck=%d fdcache=%d prof=%d",
49 (thr == calling_tid) ? '*' : ' ', stuck ? '>' : ' ', thr + 1,
Olivier Houchardcfbb3e62019-05-29 19:22:43 +020050 thread_has_tasks(),
Willy Tarreau4e2b6462019-05-16 17:44:30 +020051 !!(global_tasks_mask & thr_bit),
52 !eb_is_empty(&task_per_thread[thr].timers),
53 !eb_is_empty(&task_per_thread[thr].rqueue),
54 !LIST_ISEMPTY(&task_per_thread[thr].task_list),
55 task_per_thread[thr].task_list_size,
56 task_per_thread[thr].rqueue_size,
Willy Tarreaue6a02fa2019-05-22 07:06:44 +020057 stuck,
Willy Tarreau4e2b6462019-05-16 17:44:30 +020058 !!(fd_cache_mask & thr_bit),
59 !!(task_profiling_mask & thr_bit));
60
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020061 chunk_appendf(buf,
Willy Tarreau4e2b6462019-05-16 17:44:30 +020062 " harmless=%d wantrdv=%d",
63 !!(threads_harmless_mask & thr_bit),
64 !!(threads_want_rdv_mask & thr_bit));
Willy Tarreau4e2b6462019-05-16 17:44:30 +020065
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020066 chunk_appendf(buf, "\n");
Willy Tarreau9c8800a2019-05-20 20:52:20 +020067 chunk_appendf(buf, " cpu_ns: poll=%llu now=%llu diff=%llu\n", p, n, n-p);
Willy Tarreau4e2b6462019-05-16 17:44:30 +020068
69 /* this is the end of what we can dump from outside the thread */
70
71 if (thr != tid)
72 return;
73
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020074 chunk_appendf(buf, " curr_task=");
75 ha_task_dump(buf, curr_task, " ");
Willy Tarreau4e2b6462019-05-16 17:44:30 +020076}
77
78
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020079/* dumps into the buffer some information related to task <task> (which may
Willy Tarreau4e2b6462019-05-16 17:44:30 +020080 * either be a task or a tasklet, and prepend each line except the first one
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020081 * with <pfx>. The buffer is only appended and the first output starts by the
82 * pointer itself. The caller is responsible for making sure the task is not
83 * going to vanish during the dump.
Willy Tarreau4e2b6462019-05-16 17:44:30 +020084 */
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020085void ha_task_dump(struct buffer *buf, const struct task *task, const char *pfx)
Willy Tarreau4e2b6462019-05-16 17:44:30 +020086{
Willy Tarreau578ea8b2019-05-22 09:43:09 +020087 const struct stream *s = NULL;
88
Willy Tarreau14a1ab72019-05-17 10:34:25 +020089 if (!task) {
Willy Tarreau5cf64dd2019-05-17 10:36:08 +020090 chunk_appendf(buf, "0\n");
Willy Tarreau231ec392019-05-17 10:39:47 +020091 return;
92 }
93
Willy Tarreau20db9112019-05-17 14:14:35 +020094 if (TASK_IS_TASKLET(task))
95 chunk_appendf(buf,
96 "%p (tasklet) calls=%u\n",
97 task,
98 task->calls);
99 else
100 chunk_appendf(buf,
101 "%p (task) calls=%u last=%llu%s\n",
102 task,
103 task->calls,
104 task->call_date ? (unsigned long long)(now_mono_time() - task->call_date) : 0,
105 task->call_date ? " ns ago" : "");
Willy Tarreau4e2b6462019-05-16 17:44:30 +0200106
Willy Tarreau5cf64dd2019-05-17 10:36:08 +0200107 chunk_appendf(buf, "%s"
Willy Tarreau4e2b6462019-05-16 17:44:30 +0200108 " fct=%p (%s) ctx=%p\n",
109 pfx,
Willy Tarreau14a1ab72019-05-17 10:34:25 +0200110 task->process,
111 task->process == process_stream ? "process_stream" :
112 task->process == task_run_applet ? "task_run_applet" :
113 task->process == si_cs_io_cb ? "si_cs_io_cb" :
Willy Tarreau4e2b6462019-05-16 17:44:30 +0200114 "?",
Willy Tarreau14a1ab72019-05-17 10:34:25 +0200115 task->context);
Willy Tarreau578ea8b2019-05-22 09:43:09 +0200116
117 if (task->process == process_stream && task->context)
118 s = (struct stream *)task->context;
119 else if (task->process == task_run_applet && task->context)
120 s = si_strm(((struct appctx *)task->context)->owner);
121 else if (task->process == si_cs_io_cb && task->context)
122 s = si_strm((struct stream_interface *)task->context);
123
124 if (s)
125 stream_dump(buf, s, pfx, '\n');
Willy Tarreau4e2b6462019-05-16 17:44:30 +0200126}
127
Willy Tarreau4e2b6462019-05-16 17:44:30 +0200128/* This function dumps all profiling settings. It returns 0 if the output
129 * buffer is full and it needs to be called again, otherwise non-zero.
130 */
131static int cli_io_handler_show_threads(struct appctx *appctx)
132{
133 struct stream_interface *si = appctx->owner;
134 int thr;
135
136 if (unlikely(si_ic(si)->flags & (CF_WRITE_ERROR|CF_SHUTW)))
137 return 1;
138
139 if (appctx->st0)
140 thr = appctx->st1;
141 else
142 thr = 0;
143
Willy Tarreau5cf64dd2019-05-17 10:36:08 +0200144 chunk_reset(&trash);
Willy Tarreauc7091d82019-05-17 10:08:49 +0200145 ha_thread_dump_all_to_trash();
Willy Tarreau5cf64dd2019-05-17 10:36:08 +0200146
147 if (ci_putchk(si_ic(si), &trash) == -1) {
148 /* failed, try again */
149 si_rx_room_blk(si);
150 appctx->st1 = thr;
151 return 0;
152 }
Willy Tarreau4e2b6462019-05-16 17:44:30 +0200153 return 1;
154}
155
Willy Tarreau56131ca2019-05-20 13:48:29 +0200156/* dumps a state of all threads into the trash and on fd #2, then aborts. */
157void ha_panic()
158{
159 chunk_reset(&trash);
Willy Tarreaua9f9fc92019-05-20 17:45:35 +0200160 chunk_appendf(&trash, "Thread %u is about to kill the process.\n", tid + 1);
Willy Tarreau56131ca2019-05-20 13:48:29 +0200161 ha_thread_dump_all_to_trash();
Tim Duesterhusdda11552019-06-12 20:47:30 +0200162 shut_your_big_mouth_gcc(write(2, trash.area, trash.data));
Willy Tarreau56131ca2019-05-20 13:48:29 +0200163 for (;;)
164 abort();
165}
166
Willy Tarreau6bdf3e92019-05-20 14:25:05 +0200167#if defined(DEBUG_DEV)
168/* parse a "debug dev exit" command. It always returns 1, though it should never return. */
169static int debug_parse_cli_exit(char **args, char *payload, struct appctx *appctx, void *private)
170{
171 int code = atoi(args[3]);
172
173 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
174 return 1;
175
176 exit(code);
177 return 1;
178}
179
180/* parse a "debug dev close" command. It always returns 1. */
181static int debug_parse_cli_close(char **args, char *payload, struct appctx *appctx, void *private)
182{
183 int fd;
184
185 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
186 return 1;
187
188 if (!*args[3]) {
189 appctx->ctx.cli.msg = "Missing file descriptor number.\n";
190 goto reterr;
191 }
192
193 fd = atoi(args[3]);
194 if (fd < 0 || fd >= global.maxsock) {
195 appctx->ctx.cli.msg = "File descriptor out of range.\n";
196 goto reterr;
197 }
198
199 if (!fdtab[fd].owner) {
200 appctx->ctx.cli.msg = "File descriptor was already closed.\n";
201 goto retinfo;
202 }
203
204 fd_delete(fd);
205 return 1;
206 retinfo:
207 appctx->ctx.cli.severity = LOG_INFO;
208 appctx->st0 = CLI_ST_PRINT;
209 return 1;
210 reterr:
211 appctx->ctx.cli.severity = LOG_ERR;
212 appctx->st0 = CLI_ST_PRINT;
213 return 1;
214}
215
216/* parse a "debug dev delay" command. It always returns 1. */
217static int debug_parse_cli_delay(char **args, char *payload, struct appctx *appctx, void *private)
218{
219 int delay = atoi(args[3]);
220
221 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
222 return 1;
223
224 usleep((long)delay * 1000);
225 return 1;
226}
227
228/* parse a "debug dev log" command. It always returns 1. */
229static int debug_parse_cli_log(char **args, char *payload, struct appctx *appctx, void *private)
230{
231 int arg;
232
233 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
234 return 1;
235
236 chunk_reset(&trash);
237 for (arg = 3; *args[arg]; arg++) {
238 if (arg > 3)
239 chunk_strcat(&trash, " ");
240 chunk_strcat(&trash, args[arg]);
241 }
242
243 send_log(NULL, LOG_INFO, "%s\n", trash.area);
244 return 1;
245}
246
247/* parse a "debug dev loop" command. It always returns 1. */
248static int debug_parse_cli_loop(char **args, char *payload, struct appctx *appctx, void *private)
249{
250 struct timeval deadline, curr;
251 int loop = atoi(args[3]);
252
253 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
254 return 1;
255
256 gettimeofday(&curr, NULL);
257 tv_ms_add(&deadline, &curr, loop);
258
259 while (tv_ms_cmp(&curr, &deadline) < 0)
260 gettimeofday(&curr, NULL);
261
262 return 1;
263}
264
265/* parse a "debug dev panic" command. It always returns 1, though it should never return. */
266static int debug_parse_cli_panic(char **args, char *payload, struct appctx *appctx, void *private)
267{
268 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
269 return 1;
270
271 ha_panic();
272 return 1;
273}
274
275/* parse a "debug dev exec" command. It always returns 1. */
276static int debug_parse_cli_exec(char **args, char *payload, struct appctx *appctx, void *private)
277{
278 FILE *f;
279 int arg;
280
281 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
282 return 1;
283
284 chunk_reset(&trash);
285 for (arg = 3; *args[arg]; arg++) {
286 if (arg > 3)
287 chunk_strcat(&trash, " ");
288 chunk_strcat(&trash, args[arg]);
289 }
290
291 f = popen(trash.area, "re");
292 if (!f) {
293 appctx->ctx.cli.severity = LOG_ERR;
294 appctx->ctx.cli.msg = "Failed to execute command.\n";
295 appctx->st0 = CLI_ST_PRINT;
296 return 1;
297 }
298
299 chunk_reset(&trash);
300 while (1) {
301 size_t ret = fread(trash.area + trash.data, 1, trash.size - 20 - trash.data, f);
302 if (!ret)
303 break;
304 trash.data += ret;
305 if (trash.data + 20 == trash.size) {
306 chunk_strcat(&trash, "\n[[[TRUNCATED]]]\n");
307 break;
308 }
309 }
310
311 fclose(f);
312 trash.area[trash.data] = 0;
313 appctx->ctx.cli.severity = LOG_INFO;
314 appctx->ctx.cli.msg = trash.area;
315 appctx->st0 = CLI_ST_PRINT;
316 return 1;
317}
318
319/* parse a "debug dev hex" command. It always returns 1. */
320static int debug_parse_cli_hex(char **args, char *payload, struct appctx *appctx, void *private)
321{
322 unsigned long start, len;
323
324 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
325 return 1;
326
327 if (!*args[3]) {
328 appctx->ctx.cli.msg = "Missing memory address to dump from.\n";
329 goto reterr;
330 }
331
332 start = strtoul(args[3], NULL, 0);
333 if (!start) {
334 appctx->ctx.cli.msg = "Will not dump from NULL address.\n";
335 goto reterr;
336 }
337
338 /* by default, dump ~128 till next block of 16 */
339 len = strtoul(args[4], NULL, 0);
340 if (!len)
341 len = ((start + 128) & -16) - start;
342
343 chunk_reset(&trash);
Willy Tarreau37101052019-05-20 16:48:20 +0200344 dump_hex(&trash, " ", (const void *)start, len, 1);
Willy Tarreau6bdf3e92019-05-20 14:25:05 +0200345 trash.area[trash.data] = 0;
346 appctx->ctx.cli.severity = LOG_INFO;
347 appctx->ctx.cli.msg = trash.area;
348 appctx->st0 = CLI_ST_PRINT;
349 return 1;
350 reterr:
351 appctx->ctx.cli.severity = LOG_ERR;
352 appctx->st0 = CLI_ST_PRINT;
353 return 1;
354}
355
356/* parse a "debug dev tkill" command. It always returns 1. */
357static int debug_parse_cli_tkill(char **args, char *payload, struct appctx *appctx, void *private)
358{
359 int thr = 0;
360 int sig = SIGABRT;
361
362 if (!cli_has_level(appctx, ACCESS_LVL_ADMIN))
363 return 1;
364
365 if (*args[3])
366 thr = atoi(args[3]);
367
368 if (thr < 0 || thr > global.nbthread) {
369 appctx->ctx.cli.severity = LOG_ERR;
370 appctx->ctx.cli.msg = "Thread number out of range (use 0 for current).\n";
371 appctx->st0 = CLI_ST_PRINT;
372 return 1;
373 }
374
375 if (*args[4])
376 sig = atoi(args[4]);
377
Willy Tarreau6bdf3e92019-05-20 14:25:05 +0200378 if (thr)
Willy Tarreaufade80d2019-05-22 08:46:59 +0200379 ha_tkill(thr - 1, sig);
Willy Tarreau6bdf3e92019-05-20 14:25:05 +0200380 else
Willy Tarreau6bdf3e92019-05-20 14:25:05 +0200381 raise(sig);
382 return 1;
383}
384
385#endif
386
Willy Tarreauc7091d82019-05-17 10:08:49 +0200387#ifndef USE_THREAD_DUMP
388
389/* This function dumps all threads' state to the trash. This version is the
390 * most basic one, which doesn't inspect other threads.
391 */
392void ha_thread_dump_all_to_trash()
393{
394 unsigned int thr;
395
396 for (thr = 0; thr < global.nbthread; thr++)
397 ha_thread_dump(&trash, thr, tid);
398}
399
400#else /* below USE_THREAD_DUMP is set */
401
Willy Tarreauddd85332019-05-22 06:28:54 +0200402/* The signal to trigger a debug dump on a thread is SIGURG. It has the benefit
403 * of not stopping gdb by default, so that issuing "show threads" in a process
404 * being debugged has no adverse effect.
405 */
406#define DEBUGSIG SIGURG
Willy Tarreauc7091d82019-05-17 10:08:49 +0200407
408/* mask of threads still having to dump, used to respect ordering */
409static volatile unsigned long threads_to_dump;
410
411/* ID of the thread requesting the dump */
412static unsigned int thread_dump_tid;
413
414/* points to the buffer where the dump functions should write. It must
415 * have already been initialized by the requester. Nothing is done if
416 * it's NULL.
417 */
418struct buffer *thread_dump_buffer = NULL;
419
420void ha_thread_dump_all_to_trash()
421{
Willy Tarreauc7091d82019-05-17 10:08:49 +0200422 unsigned long old;
423
424 while (1) {
425 old = 0;
426 if (HA_ATOMIC_CAS(&threads_to_dump, &old, all_threads_mask))
427 break;
428 ha_thread_relax();
429 }
430
431 thread_dump_buffer = &trash;
432 thread_dump_tid = tid;
Willy Tarreaufade80d2019-05-22 08:46:59 +0200433 ha_tkillall(DEBUGSIG);
Willy Tarreauc7091d82019-05-17 10:08:49 +0200434}
435
436/* handles DEBUGSIG to dump the state of the thread it's working on */
437void debug_handler(int sig, siginfo_t *si, void *arg)
438{
439 /* There are 4 phases in the dump process:
440 * 1- wait for our turn, i.e. when all lower bits are gone.
441 * 2- perform the action if our bit is set
442 * 3- remove our bit to let the next one go, unless we're
Willy Tarreauda767ea2019-07-31 19:15:45 +0200443 * the last one and have to put them all as a signal
444 * 4- wait out bit to re-appear, then clear it and quit.
Willy Tarreauc7091d82019-05-17 10:08:49 +0200445 */
446
447 /* wait for all previous threads to finish first */
448 while (threads_to_dump & (tid_bit - 1))
449 ha_thread_relax();
450
451 /* dump if needed */
452 if (threads_to_dump & tid_bit) {
453 if (thread_dump_buffer)
454 ha_thread_dump(thread_dump_buffer, tid, thread_dump_tid);
455 if ((threads_to_dump & all_threads_mask) == tid_bit) {
456 /* last one */
Willy Tarreauda767ea2019-07-31 19:15:45 +0200457 HA_ATOMIC_STORE(&threads_to_dump, all_threads_mask);
Willy Tarreauc7091d82019-05-17 10:08:49 +0200458 thread_dump_buffer = NULL;
459 }
460 else
461 HA_ATOMIC_AND(&threads_to_dump, ~tid_bit);
462 }
463
464 /* now wait for all others to finish dumping. The last one will set all
Willy Tarreauda767ea2019-07-31 19:15:45 +0200465 * bits again to broadcast the leaving condition so we'll see ourselves
466 * present again. This way the threads_to_dump variable never passes to
467 * zero until all visitors have stopped waiting.
Willy Tarreauc7091d82019-05-17 10:08:49 +0200468 */
Willy Tarreauda767ea2019-07-31 19:15:45 +0200469 while (!(threads_to_dump & tid_bit))
470 ha_thread_relax();
471 HA_ATOMIC_AND(&threads_to_dump, ~tid_bit);
Willy Tarreaue6a02fa2019-05-22 07:06:44 +0200472
473 /* mark the current thread as stuck to detect it upon next invocation
474 * if it didn't move.
475 */
476 if (!((threads_harmless_mask|sleeping_thread_mask) & tid_bit))
477 ti->flags |= TI_FL_STUCK;
Willy Tarreauc7091d82019-05-17 10:08:49 +0200478}
479
480static int init_debug_per_thread()
481{
482 sigset_t set;
483
484 /* unblock the DEBUGSIG signal we intend to use */
485 sigemptyset(&set);
486 sigaddset(&set, DEBUGSIG);
487 ha_sigmask(SIG_UNBLOCK, &set, NULL);
488 return 1;
489}
490
491static int init_debug()
492{
493 struct sigaction sa;
494
495 sa.sa_handler = NULL;
496 sa.sa_sigaction = debug_handler;
497 sigemptyset(&sa.sa_mask);
498 sa.sa_flags = SA_SIGINFO;
499 sigaction(DEBUGSIG, &sa, NULL);
500 return 0;
501}
502
503REGISTER_POST_CHECK(init_debug);
504REGISTER_PER_THREAD_INIT(init_debug_per_thread);
505
506#endif /* USE_THREAD_DUMP */
507
Willy Tarreau4e2b6462019-05-16 17:44:30 +0200508/* register cli keywords */
509static struct cli_kw_list cli_kws = {{ },{
Willy Tarreau6bdf3e92019-05-20 14:25:05 +0200510#if defined(DEBUG_DEV)
511 {{ "debug", "dev", "close", NULL }, "debug dev close <fd> : close this file descriptor", debug_parse_cli_close, NULL },
512 {{ "debug", "dev", "delay", NULL }, "debug dev delay [ms] : sleep this long", debug_parse_cli_delay, NULL },
513 {{ "debug", "dev", "exec", NULL }, "debug dev exec [cmd] ... : show this command's output", debug_parse_cli_exec, NULL },
514 {{ "debug", "dev", "exit", NULL }, "debug dev exit [code] : immediately exit the process", debug_parse_cli_exit, NULL },
515 {{ "debug", "dev", "hex", NULL }, "debug dev hex <addr> [len]: dump a memory area", debug_parse_cli_hex, NULL },
516 {{ "debug", "dev", "log", NULL }, "debug dev log [msg] ... : send this msg to global logs", debug_parse_cli_log, NULL },
517 {{ "debug", "dev", "loop", NULL }, "debug dev loop [ms] : loop this long", debug_parse_cli_loop, NULL },
518 {{ "debug", "dev", "panic", NULL }, "debug dev panic : immediately trigger a panic", debug_parse_cli_panic, NULL },
519 {{ "debug", "dev", "tkill", NULL }, "debug dev tkill [thr] [sig] : send signal to thread", debug_parse_cli_tkill, NULL },
520#endif
Willy Tarreau4e2b6462019-05-16 17:44:30 +0200521 { { "show", "threads", NULL }, "show threads : show some threads debugging information", NULL, cli_io_handler_show_threads, NULL },
522 {{},}
523}};
524
525INITCALL1(STG_REGISTER, cli_register_kw, &cli_kws);