tools/tests/darwintests/kperf_backtracing.c

   1 #include <CoreSymbolication/CoreSymbolication.h>
   2 #include <darwintest.h>
   3 #include <dispatch/dispatch.h>
   4 #include <kperf/kperf.h>
   5 #include <ktrace.h>
   6 #include <pthread.h>
   7
   8 #include "kperf_helpers.h"
   9
  10 #define PERF_STK_KHDR  UINT32_C(0x25020014)
  11 #define PERF_STK_UHDR  UINT32_C(0x25020018)
  12 #define PERF_STK_KDATA UINT32_C(0x2502000c)
  13 #define PERF_STK_UDATA UINT32_C(0x25020010)
  14
  15 static void
  16 expect_frame(const char **bt, unsigned int bt_len, CSSymbolRef symbol,
  17     unsigned long addr, unsigned int bt_idx, unsigned int max_frames)
  18 {
  19     const char *name;
  20     unsigned int frame_idx = max_frames - bt_idx - 1;
  21
  22     if (!bt[frame_idx]) {
  23         T_LOG("frame %2u: skipping system frame", frame_idx);
  24         return;
  25     }
  26
  27     if (CSIsNull(symbol)) {
  28         T_FAIL("invalid symbol for address %#lx at frame %d", addr, frame_idx);
  29         return;
  30     }
  31
  32     if (frame_idx >= bt_len) {
  33         T_FAIL("unexpected frame '%s' (%#lx) at index %u",
  34             CSSymbolGetName(symbol), addr, frame_idx);
  35         return;
  36     }
  37
  38     name = CSSymbolGetName(symbol);
  39     T_QUIET; T_ASSERT_NOTNULL(name, NULL);
  40     T_EXPECT_EQ_STR(name, bt[frame_idx],
  41         "frame %2u: saw '%s', expected '%s'",
  42         frame_idx, name, bt[frame_idx]);
  43 }
  44
  45 /*
  46  * Expect to see either user or kernel stacks on thread with ID `tid` with a
  47  * signature of `bt` of length `bt_len`.  Updates `stacks_seen` when stack
  48  * is found.
  49  *
  50  * Can also allow stacks to be larger than the signature -- additional frames
  51  * near the current PC will be ignored.  This allows stacks to potentially be
  52  * in the middle of a signalling system call (which signals that it is safe to
  53  * start sampling).
  54  */
  55 static void
  56 expect_backtrace(ktrace_session_t s, uint64_t tid, unsigned int *stacks_seen,
  57     bool kern, const char **bt, unsigned int bt_len, unsigned int allow_larger_by)
  58 {
  59     CSSymbolicatorRef symb;
  60     uint32_t hdr_debugid;
  61     uint32_t data_debugid;
  62     __block unsigned int stacks = 0;
  63     __block unsigned int frames = 0;
  64     __block unsigned int hdr_frames = 0;
  65     __block unsigned int allow_larger = allow_larger_by;
  66
  67     if (kern) {
  68         static CSSymbolicatorRef kern_symb;
  69         static dispatch_once_t kern_symb_once;
  70
  71         hdr_debugid = PERF_STK_KHDR;
  72         data_debugid = PERF_STK_KDATA;
  73
  74         dispatch_once(&kern_symb_once, ^(void) {
  75             kern_symb = CSSymbolicatorCreateWithMachKernel();
  76             T_QUIET; T_ASSERT_FALSE(CSIsNull(kern_symb), NULL);
  77         });
  78         symb = kern_symb;
  79     } else {
  80         static CSSymbolicatorRef user_symb;
  81         static dispatch_once_t user_symb_once;
  82
  83         hdr_debugid = PERF_STK_UHDR;
  84         data_debugid = PERF_STK_UDATA;
  85
  86         dispatch_once(&user_symb_once, ^(void) {
  87             user_symb = CSSymbolicatorCreateWithTask(mach_task_self());
  88             T_QUIET; T_ASSERT_FALSE(CSIsNull(user_symb), NULL);
  89             T_QUIET; T_ASSERT_TRUE(CSSymbolicatorIsTaskValid(user_symb), NULL);
  90         });
  91         symb = user_symb;
  92     }
  93
  94     ktrace_events_single(s, hdr_debugid, ^(struct trace_point *tp) {
  95         if (tid != 0 && tid != tp->threadid) {
  96             return;
  97         }
  98
  99         T_LOG("found stack from thread %#lx", tp->threadid);
 100         stacks++;
 101         if (!(tp->arg1 & 1)) {
 102             T_FAIL("invalid %s stack on thread %#lx", kern ? "kernel" : "user",
 103                 tp->threadid);
 104             return;
 105         }
 106
 107         hdr_frames = (unsigned int)tp->arg2;
 108         /* ignore extra link register or value pointed to by stack pointer */
 109         hdr_frames -= 1;
 110
 111         T_QUIET; T_EXPECT_GE(hdr_frames, bt_len,
 112             "number of frames in header");
 113         T_QUIET; T_EXPECT_LE(hdr_frames, bt_len + allow_larger,
 114             "number of frames in header");
 115         if (hdr_frames > bt_len && allow_larger > 0) {
 116             allow_larger = hdr_frames - bt_len;
 117             hdr_frames = bt_len;
 118         }
 119
 120         T_LOG("%s stack seen", kern ? "kernel" : "user");
 121         frames = 0;
 122     });
 123
 124     ktrace_events_single(s, data_debugid, ^(struct trace_point *tp) {
 125         if (tid != 0 && tid != tp->threadid) {
 126             return;
 127         }
 128
 129         int i = 0;
 130
 131         if (frames == 0 && hdr_frames > bt_len) {
 132             /* skip frames near the PC */
 133             i = (int)allow_larger;
 134             allow_larger -= 4;
 135         }
 136
 137         for (; i < 4 && frames < hdr_frames; i++, frames++) {
 138             unsigned long addr = (&tp->arg1)[i];
 139             CSSymbolRef symbol = CSSymbolicatorGetSymbolWithAddressAtTime(
 140                 symb, addr, kCSNow);
 141
 142             expect_frame(bt, bt_len, symbol, addr, frames, hdr_frames);
 143         }
 144
 145         /* saw the end of the user stack */
 146         if (hdr_frames == frames) {
 147             *stacks_seen += 1;
 148             if (!kern) {
 149                 ktrace_end(s, 1);
 150             }
 151         }
 152     });
 153 }
 154
 155 #define TRIGGERING_DEBUGID (0xfeff0f00)
 156
 157 /*
 158  * These functions must return an int to avoid the function prologue being
 159  * hoisted out of the path to the spin (breaking being able to get a good
 160  * backtrace).
 161  */
 162 static int __attribute__((noinline,not_tail_called))
 163 recurse_a(dispatch_semaphore_t spinning, unsigned int frames);
 164 static int __attribute__((noinline,not_tail_called))
 165 recurse_b(dispatch_semaphore_t spinning, unsigned int frames);
 166
 167 static int __attribute__((noinline,not_tail_called))
 168 recurse_a(dispatch_semaphore_t spinning, unsigned int frames)
 169 {
 170     if (frames == 0) {
 171         if (spinning) {
 172             dispatch_semaphore_signal(spinning);
 173             for (;;);
 174         } else {
 175             kdebug_trace(TRIGGERING_DEBUGID, 0, 0, 0, 0);
 176             return 0;
 177         }
 178     }
 179
 180     return recurse_b(spinning, frames - 1) + 1;
 181 }
 182
 183 static int __attribute__((noinline,not_tail_called))
 184 recurse_b(dispatch_semaphore_t spinning, unsigned int frames)
 185 {
 186     if (frames == 0) {
 187         if (spinning) {
 188             dispatch_semaphore_signal(spinning);
 189             for (;;);
 190         } else {
 191             kdebug_trace(TRIGGERING_DEBUGID, 0, 0, 0, 0);
 192             return 0;
 193         }
 194     }
 195
 196     return recurse_a(spinning, frames - 1) + 1;
 197 }
 198
 199 #define USER_FRAMES       (12)
 200
 201 #if defined(__x86_64__)
 202 #define RECURSE_START_OFFSET (4)
 203 #else /* defined(__x86_64__) */
 204 #define RECURSE_START_OFFSET (3)
 205 #endif /* defined(__x86_64__) */
 206
 207 static const char *user_bt[USER_FRAMES] = {
 208 #if defined(__x86_64__)
 209     NULL,
 210 #endif /* defined(__x86_64__) */
 211     NULL, NULL,
 212     "backtrace_thread",
 213     "recurse_a", "recurse_b", "recurse_a", "recurse_b",
 214     "recurse_a", "recurse_b", "recurse_a",
 215 #if !defined(__x86_64__)
 216     "recurse_b",
 217 #endif /* !defined(__x86_64__) */
 218     NULL
 219 };
 220
 221 #if   defined(__x86_64__)
 222
 223 #define KERNEL_FRAMES (2)
 224 static const char *kernel_bt[KERNEL_FRAMES] = {
 225     "unix_syscall64", "kdebug_trace64"
 226 };
 227
 228 #else
 229 #error "architecture unsupported"
 230 #endif /* defined(__arm__) */
 231
 232 static dispatch_once_t backtrace_once;
 233 static dispatch_semaphore_t backtrace_started;
 234 static dispatch_semaphore_t backtrace_go;
 235
 236 /*
 237  * Another thread to run with a known backtrace.
 238  *
 239  * Take a semaphore that will be signalled when the thread is spinning at the
 240  * correct frame.  If the semaphore is NULL, don't spin and instead make a
 241  * kdebug_trace system call, which can trigger a deterministic backtrace itself.
 242  */
 243 static void *
 244 backtrace_thread(void *arg)
 245 {
 246     dispatch_semaphore_t notify_spinning;
 247     unsigned int calls;
 248
 249     notify_spinning = (dispatch_semaphore_t)arg;
 250
 251     dispatch_semaphore_signal(backtrace_started);
 252     if (!notify_spinning) {
 253         dispatch_semaphore_wait(backtrace_go, DISPATCH_TIME_FOREVER);
 254     }
 255
 256     /*
 257      * backtrace_thread, recurse_a, recurse_b, ...[, __kdebug_trace64]
 258      *
 259      * Always make one less call for this frame (backtrace_thread).
 260      */
 261     calls = USER_FRAMES - RECURSE_START_OFFSET - 1 /* backtrace_thread */;
 262     if (notify_spinning) {
 263         /*
 264          * Spinning doesn't end up calling __kdebug_trace64.
 265          */
 266         calls -= 1;
 267     }
 268
 269     T_LOG("backtrace thread calling into %d frames (already at %d frames)",
 270         calls, RECURSE_START_OFFSET);
 271     (void)recurse_a(notify_spinning, calls);
 272     return NULL;
 273 }
 274
 275 static uint64_t
 276 create_backtrace_thread(dispatch_semaphore_t notify_spinning)
 277 {
 278     pthread_t thread = NULL;
 279     uint64_t tid;
 280
 281     dispatch_once(&backtrace_once, ^{
 282         backtrace_started = dispatch_semaphore_create(0);
 283         T_QUIET; T_ASSERT_NOTNULL(backtrace_started, NULL);
 284
 285         if (!notify_spinning) {
 286             backtrace_go = dispatch_semaphore_create(0);
 287             T_QUIET; T_ASSERT_NOTNULL(backtrace_go, NULL);
 288         }
 289     });
 290
 291     T_QUIET; T_ASSERT_POSIX_ZERO(pthread_create(&thread, NULL, backtrace_thread,
 292         (void *)notify_spinning), NULL);
 293     T_QUIET; T_ASSERT_NOTNULL(thread, "backtrace thread created");
 294     dispatch_semaphore_wait(backtrace_started, DISPATCH_TIME_FOREVER);
 295
 296     T_QUIET; T_ASSERT_POSIX_ZERO(pthread_threadid_np(thread, &tid), NULL);
 297     T_QUIET; T_ASSERT_NE(tid, UINT64_C(0),
 298         "backtrace thread created does not have ID 0");
 299
 300     T_LOG("starting thread with ID 0x%" PRIx64, tid);
 301
 302     return tid;
 303 }
 304
 305 static void
 306 start_backtrace_thread(void)
 307 {
 308     T_QUIET; T_ASSERT_NOTNULL(backtrace_go,
 309         "thread to backtrace created before starting it");
 310     dispatch_semaphore_signal(backtrace_go);
 311 }
 312
 313 #define TEST_TIMEOUT_NS (5 * NSEC_PER_SEC)
 314
 315 T_DECL(kdebug_trigger_backtraces,
 316     "test that backtraces from kdebug trigger are correct",
 317     T_META_ASROOT(true))
 318 {
 319     static unsigned int stacks_seen = 0;
 320     ktrace_session_t s;
 321     kperf_kdebug_filter_t filter;
 322     uint64_t tid;
 323
 324     s = ktrace_session_create();
 325     T_ASSERT_NOTNULL(s, "ktrace session was created");
 326
 327     T_ASSERT_POSIX_ZERO(ktrace_filter_pid(s, getpid()), NULL);
 328
 329     tid = create_backtrace_thread(NULL);
 330     expect_backtrace(s, tid, &stacks_seen, false, user_bt, USER_FRAMES, 0);
 331     expect_backtrace(s, tid, &stacks_seen, true, kernel_bt, KERNEL_FRAMES, 0);
 332
 333     /*
 334      * The triggering event must be traced (and thus registered with libktrace)
 335      * to get backtraces.
 336      */
 337     ktrace_events_single(s, TRIGGERING_DEBUGID,
 338         ^(__unused struct trace_point *tp){ });
 339
 340     ktrace_set_completion_handler(s, ^(void) {
 341         T_EXPECT_GE(stacks_seen, 2U, "saw both kernel and user stacks");
 342         ktrace_session_destroy(s);
 343         kperf_reset();
 344         T_END;
 345     });
 346
 347     filter = kperf_kdebug_filter_create();
 348     T_ASSERT_NOTNULL(filter, "kperf kdebug filter was created");
 349
 350     T_QUIET; T_ASSERT_POSIX_SUCCESS(kperf_kdebug_filter_add_debugid(filter,
 351         TRIGGERING_DEBUGID), NULL);
 352     T_QUIET; T_ASSERT_POSIX_SUCCESS(kperf_kdebug_filter_set(filter), NULL);
 353     (void)kperf_action_count_set(1);
 354     T_QUIET; T_ASSERT_POSIX_SUCCESS(kperf_action_samplers_set(1,
 355         KPERF_SAMPLER_USTACK | KPERF_SAMPLER_KSTACK), NULL);
 356     T_QUIET; T_ASSERT_POSIX_SUCCESS(kperf_kdebug_action_set(1), NULL);
 357     kperf_kdebug_filter_destroy(filter);
 358
 359     T_ASSERT_POSIX_SUCCESS(kperf_sample_set(1), NULL);
 360
 361     T_ASSERT_POSIX_ZERO(ktrace_start(s, dispatch_get_main_queue()), NULL);
 362
 363     start_backtrace_thread();
 364
 365     dispatch_after(dispatch_time(DISPATCH_TIME_NOW, TEST_TIMEOUT_NS),
 366         dispatch_get_main_queue(), ^(void)
 367     {
 368         T_LOG("ending test after timeout");
 369         ktrace_end(s, 0);
 370     });
 371
 372     dispatch_main();
 373 }
 374
 375 T_DECL(user_backtraces_timer,
 376     "test that user backtraces on a timer are correct",
 377     T_META_ASROOT(true))
 378 {
 379     static unsigned int stacks_seen = 0;
 380     ktrace_session_t s;
 381     uint64_t tid;
 382     dispatch_semaphore_t wait_for_spinning = dispatch_semaphore_create(0);
 383
 384     s = ktrace_session_create();
 385     T_QUIET; T_ASSERT_NOTNULL(s, "ktrace_session_create");
 386
 387     ktrace_filter_pid(s, getpid());
 388
 389     configure_kperf_stacks_timer(getpid(), 10);
 390
 391     tid = create_backtrace_thread(wait_for_spinning);
 392     /* potentially calling dispatch function and system call */
 393     expect_backtrace(s, tid, &stacks_seen, false, user_bt, USER_FRAMES - 1, 2);
 394
 395     ktrace_set_completion_handler(s, ^(void) {
 396         T_EXPECT_GE(stacks_seen, 1U, "saw at least one stack");
 397         ktrace_session_destroy(s);
 398         kperf_reset();
 399         T_END;
 400     });
 401
 402     T_QUIET; T_ASSERT_POSIX_SUCCESS(kperf_sample_set(1), NULL);
 403
 404     /* wait until the thread that will be backtraced is spinning */
 405     dispatch_semaphore_wait(wait_for_spinning, DISPATCH_TIME_FOREVER);
 406
 407     T_ASSERT_POSIX_ZERO(ktrace_start(s, dispatch_get_main_queue()), NULL);
 408
 409     dispatch_after(dispatch_time(DISPATCH_TIME_NOW, TEST_TIMEOUT_NS),
 410         dispatch_get_main_queue(), ^(void)
 411     {
 412         T_LOG("ending test after timeout");
 413         ktrace_end(s, 0);
 414     });
 415
 416     dispatch_main();
 417 }
 418
 419 /* TODO test kernel stacks in all modes */
 420 /* TODO legacy PET mode backtracing */
 421 /* TODO test deep stacks, further than 128 frames, make sure they are truncated */
 422 /* TODO test constrained stacks */