blob: 2208ca11bc606832e598845d20c92f7f75cfd26b [file] [log] [blame]
Willy Tarreau7de211c2012-05-25 23:53:16 +02001/*
2 * Function call tracing for gcc >= 2.95
Willy Tarreau9eebd8a2019-08-08 16:53:40 +02003 * WARNING! THIS CODE IS NOT THREAD-SAFE!
Willy Tarreau7de211c2012-05-25 23:53:16 +02004 *
5 * Copyright 2012 Willy Tarreau <w@1wt.eu>
6 *
7 * This program is free software; you can redistribute it and/or
8 * modify it under the terms of the GNU General Public License
9 * as published by the Free Software Foundation; either version
10 * 2 of the License, or (at your option) any later version.
11 *
12 * gcc is able to call a specific function when entering and leaving any
13 * function when compiled with -finstrument-functions. This code must not
14 * be built with this argument. The performance impact is huge, so this
15 * feature should only be used when debugging.
16 *
17 * The entry and exits of all functions will be dumped into a file designated
18 * by the HAPROXY_TRACE environment variable, or by default "trace.out". If the
19 * trace file name is empty or "/dev/null", then traces are disabled. If
20 * opening the trace file fails, then stderr is used. If HAPROXY_TRACE_FAST is
21 * used, then the time is taken from the global <now> variable. Last, if
22 * HAPROXY_TRACE_TSC is used, then the machine's TSC is used instead of the
23 * real time (almost twice as fast).
24 *
25 * The output format is :
26 *
27 * <sec.usec> <level> <caller_ptr> <dir> <callee_ptr>
28 * or :
29 * <tsc> <level> <caller_ptr> <dir> <callee_ptr>
30 *
31 * where <dir> is '>' when entering a function and '<' when leaving.
32 *
Willy Tarreau9eebd8a2019-08-08 16:53:40 +020033 * It is also possible to emit comments using the calltrace() function which uses
Willy Tarreau12963822017-10-24 10:54:08 +020034 * the printf() format. Such comments are then inserted by replacing the caller
35 * pointer with a sharp ('#') like this :
36 *
37 * <sec.usec> <level> # <comment>
38 * or :
39 * <tsc> <level> # <comment>
40 *
Willy Tarreau7de211c2012-05-25 23:53:16 +020041 * The article below is a nice explanation of how this works :
42 * http://balau82.wordpress.com/2010/10/06/trace-and-profile-function-calls-with-gcc/
43 */
44
45#include <sys/time.h>
Willy Tarreau12963822017-10-24 10:54:08 +020046#include <stdarg.h>
Willy Tarreau7de211c2012-05-25 23:53:16 +020047#include <stdio.h>
48#include <stdlib.h>
49#include <string.h>
Willy Tarreau4c7e4b72020-05-27 12:58:42 +020050#include <haproxy/api.h>
Willy Tarreau92b4f132020-06-01 11:05:15 +020051#include <haproxy/time.h>
Willy Tarreau7de211c2012-05-25 23:53:16 +020052
53static FILE *log;
54static int level;
55static int disabled;
56static int fast_time;
57static int use_tsc;
58static struct timeval trace_now;
59static struct timeval *now_ptr;
60static char line[128]; /* more than enough for a message (9+1+6+1+3+1+18+1+1+18+1+1) */
61
62static int open_trace()
63{
64 const char *output = getenv("HAPROXY_TRACE");
65
66 if (!output)
67 output = "trace.out";
68
69 if (!*output || strcmp(output, "/dev/null") == 0) {
70 disabled = 1;
71 return 0;
72 }
73
74 log = fopen(output, "w");
75 if (!log)
76 log = stderr;
77
78 now_ptr = &now;
79 if (getenv("HAPROXY_TRACE_FAST") != NULL) {
80 fast_time = 1;
81 now_ptr = &trace_now;
82 }
83 if (getenv("HAPROXY_TRACE_TSC") != NULL) {
84 fast_time = 1;
85 use_tsc = 1;
86 }
87 return 1;
88}
89
90/* This function first divides the number by 100M then iteratively multiplies it
91 * by 100 (using adds and shifts). The trick is that dividing by 100M is equivalent
92 * to multiplying by 1/100M, which approximates to 1441151881/2^57. All local
93 * variables fit in registers on x86. This version outputs two digits per round.
94 * <min_pairs> indicates the minimum number of pairs of digits that have to be
95 * emitted, which might be left-padded with zeroes.
96 * It returns the pointer to the ending '\0'.
97 */
98static char *ultoad2(unsigned int x, char *out, int min_pairs)
99{
100 unsigned int q;
101 char *p = out;
102 int pos = 4;
103 unsigned long long y;
104
105 static const unsigned short bcd[100] = {
106 0x3030, 0x3130, 0x3230, 0x3330, 0x3430, 0x3530, 0x3630, 0x3730, 0x3830, 0x3930,
107 0x3031, 0x3131, 0x3231, 0x3331, 0x3431, 0x3531, 0x3631, 0x3731, 0x3831, 0x3931,
108 0x3032, 0x3132, 0x3232, 0x3332, 0x3432, 0x3532, 0x3632, 0x3732, 0x3832, 0x3932,
109 0x3033, 0x3133, 0x3233, 0x3333, 0x3433, 0x3533, 0x3633, 0x3733, 0x3833, 0x3933,
110 0x3034, 0x3134, 0x3234, 0x3334, 0x3434, 0x3534, 0x3634, 0x3734, 0x3834, 0x3934,
111 0x3035, 0x3135, 0x3235, 0x3335, 0x3435, 0x3535, 0x3635, 0x3735, 0x3835, 0x3935,
112 0x3036, 0x3136, 0x3236, 0x3336, 0x3436, 0x3536, 0x3636, 0x3736, 0x3836, 0x3936,
113 0x3037, 0x3137, 0x3237, 0x3337, 0x3437, 0x3537, 0x3637, 0x3737, 0x3837, 0x3937,
114 0x3038, 0x3138, 0x3238, 0x3338, 0x3438, 0x3538, 0x3638, 0x3738, 0x3838, 0x3938,
115 0x3039, 0x3139, 0x3239, 0x3339, 0x3439, 0x3539, 0x3639, 0x3739, 0x3839, 0x3939 };
116
117 y = x * 1441151881ULL; /* y>>57 will be the integer part of x/100M */
118 while (1) {
119 q = y >> 57;
120 /* Q is composed of the first digit in the lower byte and the second
121 * digit in the higher byte.
122 */
123 if (p != out || q > 9 || pos < min_pairs) {
124#if defined(__i386__) || defined(__x86_64__)
125 /* unaligned accesses are fast on x86 */
126 *(unsigned short *)p = bcd[q];
127 p += 2;
128#else
129 *(p++) = bcd[q];
130 *(p++) = bcd[q] >> 8;
131#endif
132 }
133 else if (q || !pos) {
134 /* only at most one digit */
135 *(p++) = bcd[q] >> 8;
136 }
137 if (--pos < 0)
138 break;
139
140 y &= 0x1FFFFFFFFFFFFFFULL; // remainder
141
142 if (sizeof(long) >= sizeof(long long)) {
143 /* shifting is preferred on 64-bit archs, while mult is faster on 32-bit.
144 * We multiply by 100 by doing *5, *5 and *4, all of which are trivial.
145 */
146 y += (y << 2);
147 y += (y << 2);
148 y <<= 2;
149 }
150 else
151 y *= 100;
152 }
153
154 *p = '\0';
155 return p;
156}
157
158/* Send <h> as hex into <out>. Returns the pointer to the ending '\0'. */
159static char *emit_hex(unsigned long h, char *out)
160{
161 static unsigned char hextab[16] = "0123456789abcdef";
162 int shift = sizeof(h) * 8 - 4;
163 unsigned int idx;
164
165 do {
166 idx = (h >> shift);
167 if (idx || !shift)
168 *out++ = hextab[idx & 15];
169 shift -= 4;
170 } while (shift >= 0);
171 *out = '\0';
172 return out;
173}
174
Willy Tarreaue8f0f122017-10-24 10:58:20 +0200175static void make_line(void *from, void *to, int level, char dir, long ret)
Willy Tarreau7de211c2012-05-25 23:53:16 +0200176{
177 char *p = line;
178
179 if (unlikely(!log) && !open_trace())
180 return;
181
182 if (unlikely(!fast_time))
183 gettimeofday(now_ptr, NULL);
184
185#ifdef USE_SLOW_FPRINTF
186 if (!use_tsc)
187 fprintf(log, "%u.%06u %d %p %c %p\n",
188 (unsigned int)now_ptr->tv_sec,
189 (unsigned int)now_ptr->tv_usec,
190 level, from, dir, to);
191 else
192 fprintf(log, "%llx %d %p %c %p\n",
193 rdtsc(), level, from, dir, to);
194 return;
195#endif
196
197 if (unlikely(!use_tsc)) {
198 /* "%u.06u", tv_sec, tv_usec */
199 p = ultoad2(now_ptr->tv_sec, p, 0);
200 *p++ = '.';
201 p = ultoad2(now_ptr->tv_usec, p, 3);
202 } else {
203 /* "%08x%08x", high, low */
204 unsigned long long t = rdtsc();
205 if (sizeof(long) < sizeof(long long))
206 p = emit_hex((unsigned long)(t >> 32U), p);
207 p = emit_hex((unsigned long)(t), p);
208 }
209
210 /* " %u", level */
211 *p++ = ' ';
212 p = ultoad2(level, p, 0);
213
214 /* " %p", from */
215 *p++ = ' '; *p++ = '0'; *p++ = 'x';
216 p = emit_hex((unsigned long)from, p);
217
218 /* " %c", dir */
219 *p++ = ' '; *p++ = dir;
220
221 /* " %p", to */
222 *p++ = ' '; *p++ = '0'; *p++ = 'x';
223 p = emit_hex((unsigned long)to, p);
224
Willy Tarreaue8f0f122017-10-24 10:58:20 +0200225 if (dir == '<') {
226 /* " %x", ret */
227 *p++ = ' '; *p++ = '0'; *p++ = 'x';
228 p = emit_hex(ret, p);
229 }
230
Willy Tarreau7de211c2012-05-25 23:53:16 +0200231 *p++ = '\n';
232
233 fwrite(line, p - line, 1, log);
234}
235
236/* These are the functions GCC calls */
237void __cyg_profile_func_enter(void *to, void *from)
238{
239 if (!disabled)
Willy Tarreaue8f0f122017-10-24 10:58:20 +0200240 return make_line(from, to, ++level, '>', 0);
Willy Tarreau7de211c2012-05-25 23:53:16 +0200241}
242
243void __cyg_profile_func_exit(void *to, void *from)
244{
Willy Tarreaue8f0f122017-10-24 10:58:20 +0200245 long ret = 0;
246
247#if defined(__x86_64__)
248 /* on x86_64, the return value (eax) is temporarily stored in ebx
249 * during the call to __cyg_profile_func_exit() so we can snoop it.
250 */
251 asm volatile("mov %%rbx, %0" : "=r"(ret));
252#endif
Willy Tarreau7de211c2012-05-25 23:53:16 +0200253 if (!disabled)
Willy Tarreaue8f0f122017-10-24 10:58:20 +0200254 return make_line(from, to, level--, '<', ret);
Willy Tarreau7de211c2012-05-25 23:53:16 +0200255}
Willy Tarreau12963822017-10-24 10:54:08 +0200256
257/* the one adds comments in the trace above. The output format is :
258 * <timestamp> <level> # <string>
259 */
260__attribute__((format(printf, 1, 2)))
Willy Tarreau9eebd8a2019-08-08 16:53:40 +0200261void calltrace(char *fmt, ...)
Willy Tarreau12963822017-10-24 10:54:08 +0200262{
263 va_list ap;
264
265 if (unlikely(!log) && !open_trace())
266 return;
267
268 if (unlikely(!fast_time))
269 gettimeofday(now_ptr, NULL);
270
271 if (!use_tsc)
272 fprintf(log, "%u.%06u %d # ",
273 (unsigned int)now_ptr->tv_sec,
274 (unsigned int)now_ptr->tv_usec,
275 level + 1);
276 else
277 fprintf(log, "%llx %d # ",
278 rdtsc(), level + 1);
279
280 va_start(ap, fmt);
281 vfprintf(log, fmt, ap);
282 va_end(ap);
283 fputc('\n', log);
284 fflush(log);
285}