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