tests/kperf.c

   1 #ifdef T_NAMESPACE
   2 #undef T_NAMESPACE
   3 #endif /* defined(T_NAMESPACE) */
   4
   5 #include <darwintest.h>
   6 #include <darwintest_utils.h>
   7 #include <dispatch/dispatch.h>
   8 #include <inttypes.h>
   9 #include <ktrace/session.h>
  10 #include <ktrace/private.h>
  11 #include <System/sys/kdebug.h>
  12 #include <kperf/kperf.h>
  13 #include <kperfdata/kpdecode.h>
  14 #include <os/assumes.h>
  15 #include <stdint.h>
  16 #include <sys/sysctl.h>
  17
  18 #include "kperf_helpers.h"
  19
  20 T_GLOBAL_META(
  21         T_META_NAMESPACE("xnu.kperf"),
  22         T_META_CHECK_LEAKS(false),
  23         T_META_ASROOT(true));
  24
  25 #define MAX_CPUS    64
  26 #define MAX_THREADS 64
  27
  28 volatile static bool running_threads = true;
  29
  30 static void *
  31 spinning_thread(void *semp)
  32 {
  33         T_QUIET;
  34         T_ASSERT_NOTNULL(semp, "semaphore passed to thread should not be NULL");
  35         dispatch_semaphore_signal(*(dispatch_semaphore_t *)semp);
  36
  37         while (running_threads) {
  38                 ;
  39         }
  40         return NULL;
  41 }
  42
  43 #define PERF_STK_KHDR  UINT32_C(0x25020014)
  44 #define PERF_STK_UHDR  UINT32_C(0x25020018)
  45 #define PERF_TMR_FIRE  KDBG_EVENTID(DBG_PERF, 3, 0)
  46 #define PERF_TMR_HNDLR KDBG_EVENTID(DBG_PERF, 3, 2)
  47 #define PERF_TMR_PEND  KDBG_EVENTID(DBG_PERF, 3, 3)
  48 #define PERF_TMR_SKIP  KDBG_EVENTID(DBG_PERF, 3, 4)
  49
  50 #define SCHED_HANDOFF KDBG_EVENTID(DBG_MACH, DBG_MACH_SCHED, \
  51                 MACH_STACK_HANDOFF)
  52 #define SCHED_SWITCH  KDBG_EVENTID(DBG_MACH, DBG_MACH_SCHED, MACH_SCHED)
  53 #define SCHED_IDLE    KDBG_EVENTID(DBG_MACH, DBG_MACH_SCHED, MACH_IDLE)
  54
  55 #define MP_CPUS_CALL UINT32_C(0x1900004)
  56
  57 #define DISPATCH_AFTER_EVENT UINT32_C(0xfefffffc)
  58 #define TIMEOUT_SECS 10
  59
  60 #define TIMER_PERIOD_NS (1 * NSEC_PER_MSEC)
  61
  62 static void
  63 reset_ktrace(void)
  64 {
  65         kperf_reset();
  66 }
  67
  68 /*
  69  * Ensure that kperf is correctly IPIing CPUs that are actively scheduling by
  70  * bringing up threads and ensuring that threads on-core are sampled by each
  71  * timer fire.
  72  */
  73
  74 T_DECL(ipi_active_cpus,
  75     "make sure that kperf IPIs all active CPUs")
  76 {
  77         int ncpus = dt_ncpu();
  78         T_QUIET;
  79         T_ASSERT_LT(ncpus, MAX_CPUS,
  80             "only supports up to %d CPUs", MAX_CPUS);
  81         T_LOG("found %d CPUs", ncpus);
  82
  83         int nthreads = ncpus - 1;
  84         T_QUIET;
  85         T_ASSERT_LT(nthreads, MAX_THREADS,
  86             "only supports up to %d threads", MAX_THREADS);
  87
  88         static pthread_t threads[MAX_THREADS];
  89
  90         /*
  91          * TODO options to write this to a file and reinterpret a file...
  92          */
  93
  94         /*
  95          * Create threads to bring up all of the CPUs.
  96          */
  97
  98         dispatch_semaphore_t thread_spinning = dispatch_semaphore_create(0);
  99
 100         for (int i = 0; i < nthreads; i++) {
 101                 T_QUIET;
 102                 T_ASSERT_POSIX_ZERO(
 103                         pthread_create(&threads[i], NULL, &spinning_thread,
 104                         &thread_spinning), NULL);
 105                 dispatch_semaphore_wait(thread_spinning, DISPATCH_TIME_FOREVER);
 106         }
 107
 108         T_LOG("spun up %d thread%s", nthreads, nthreads == 1 ? "" : "s");
 109
 110         ktrace_session_t s = ktrace_session_create();
 111         T_WITH_ERRNO; T_ASSERT_NOTNULL(s, "ktrace_session_create");
 112
 113         dispatch_queue_t q = dispatch_get_global_queue(QOS_CLASS_USER_INITIATED, 0);
 114
 115         /*
 116          * Only set the timeout after we've seen an event that was traced by us.
 117          * This helps set a reasonable timeout after we're guaranteed to get a
 118          * few events.
 119          */
 120
 121         ktrace_events_single(s, DISPATCH_AFTER_EVENT,
 122             ^(__unused struct trace_point *tp)
 123         {
 124                 dispatch_after(dispatch_time(DISPATCH_TIME_NOW,
 125                 TIMEOUT_SECS * NSEC_PER_SEC), q, ^{
 126                         ktrace_end(s, 0);
 127                 });
 128         });
 129
 130         __block uint64_t nfires = 0;
 131         __block uint64_t nsamples = 0;
 132         static uint64_t idle_tids[MAX_CPUS] = { 0 };
 133         __block int nidles = 0;
 134
 135         ktrace_set_completion_handler(s, ^{
 136                 T_LOG("stopping threads");
 137
 138                 running_threads = false;
 139
 140                 for (int i = 0; i < nthreads; i++) {
 141                         T_QUIET;
 142                         T_ASSERT_POSIX_ZERO(pthread_join(threads[i], NULL), NULL);
 143                 }
 144
 145                 for (int i = 0; i < nidles; i++) {
 146                         T_LOG("CPU %d idle thread: %#" PRIx64, i, idle_tids[i]);
 147                 }
 148
 149                 T_LOG("saw %" PRIu64 " timer fires, %" PRIu64 " samples, "
 150                 "%g samples/fire", nfires, nsamples,
 151                 (double)nsamples / (double)nfires);
 152
 153                 T_END;
 154         });
 155
 156         /*
 157          * Track which threads are running on each CPU.
 158          */
 159
 160         static uint64_t tids_on_cpu[MAX_CPUS] = { 0 };
 161
 162         void (^switch_cb)(struct trace_point *) = ^(struct trace_point *tp) {
 163                 uint64_t new_thread = tp->arg2;
 164                 // uint64_t old_thread = tp->threadid;
 165
 166                 for (int i = 0; i < nidles; i++) {
 167                         if (idle_tids[i] == new_thread) {
 168                                 return;
 169                         }
 170                 }
 171
 172                 tids_on_cpu[tp->cpuid] = new_thread;
 173         };
 174
 175         ktrace_events_single(s, SCHED_SWITCH, switch_cb);
 176         ktrace_events_single(s, SCHED_HANDOFF, switch_cb);
 177
 178         /*
 179          * Determine the thread IDs of the idle threads on each CPU.
 180          */
 181
 182         ktrace_events_single(s, SCHED_IDLE, ^(struct trace_point *tp) {
 183                 uint64_t idle_thread = tp->threadid;
 184
 185                 tids_on_cpu[tp->cpuid] = 0;
 186
 187                 for (int i = 0; i < nidles; i++) {
 188                         if (idle_tids[i] == idle_thread) {
 189                                 return;
 190                         }
 191                 }
 192
 193                 idle_tids[nidles++] = idle_thread;
 194         });
 195
 196         /*
 197          * On each timer fire, go through all the cores and mark any threads
 198          * that should be sampled.
 199          */
 200
 201         __block int last_fire_cpu = -1;
 202         __block uint64_t sample_missing = 0;
 203         static uint64_t tids_snap[MAX_CPUS] = { 0 };
 204         __block int nexpected = 0;
 205 #if defined(__x86_64__)
 206         __block int xcall_from_cpu = -1;
 207 #endif /* defined(__x86_64__) */
 208         __block uint64_t xcall_mask = 0;
 209
 210         ktrace_events_single(s, PERF_TMR_FIRE, ^(struct trace_point *tp) {
 211                 int last_expected = nexpected;
 212                 nfires++;
 213
 214                 nexpected = 0;
 215                 for (int i = 0; i < ncpus; i++) {
 216                         uint64_t i_bit = UINT64_C(1) << i;
 217                         if (sample_missing & i_bit) {
 218                                 T_LOG("missed sample on CPU %d for thread %#llx from timer on CPU %d (xcall mask = %llx, expected %d samples)",
 219                                 tp->cpuid, tids_snap[i], last_fire_cpu,
 220                                 xcall_mask, last_expected);
 221                                 sample_missing &= ~i_bit;
 222                         }
 223
 224                         if (tids_on_cpu[i] != 0) {
 225                                 tids_snap[i] = tids_on_cpu[i];
 226                                 sample_missing |= i_bit;
 227                                 nexpected++;
 228                         }
 229                 }
 230
 231                 T_QUIET;
 232                 T_ASSERT_LT((int)tp->cpuid, ncpus, "timer fire should not occur on an IOP");
 233                 last_fire_cpu = (int)tp->cpuid;
 234 #if defined(__x86_64__)
 235                 xcall_from_cpu = (int)tp->cpuid;
 236 #endif /* defined(__x86_64__) */
 237         });
 238
 239 #if defined(__x86_64__)
 240         /*
 241          * Watch for the cross-call on Intel, make sure they match what kperf
 242          * should be doing.
 243          */
 244
 245         ktrace_events_single(s, MP_CPUS_CALL, ^(struct trace_point *tp) {
 246                 if (xcall_from_cpu != (int)tp->cpuid) {
 247                         return;
 248                 }
 249
 250                 xcall_mask = tp->arg1;
 251                 xcall_from_cpu = -1;
 252         });
 253 #endif /* defined(__x86_64__) */
 254
 255         /*
 256          * On the timer handler for each CPU, unset the missing sample bitmap.
 257          */
 258
 259         ktrace_events_single(s, PERF_TMR_HNDLR, ^(struct trace_point *tp) {
 260                 nsamples++;
 261                 if ((int)tp->cpuid > ncpus) {
 262                         /* skip IOPs; they're not scheduling our threads */
 263                         return;
 264                 }
 265
 266                 sample_missing &= ~(UINT64_C(1) << tp->cpuid);
 267         });
 268
 269         /*
 270          * Configure kperf and ktrace.
 271          */
 272
 273         (void)kperf_action_count_set(1);
 274         T_QUIET;
 275         T_ASSERT_POSIX_SUCCESS(kperf_action_samplers_set(1, KPERF_SAMPLER_KSTACK),
 276             NULL);
 277         (void)kperf_timer_count_set(1);
 278         T_QUIET;
 279         T_ASSERT_POSIX_SUCCESS(kperf_timer_period_set(0,
 280             kperf_ns_to_ticks(TIMER_PERIOD_NS)), NULL);
 281         T_QUIET;
 282         T_ASSERT_POSIX_SUCCESS(kperf_timer_action_set(0, 1), NULL);
 283
 284         T_ASSERT_POSIX_SUCCESS(kperf_sample_set(1), "start kperf sampling");
 285         T_ATEND(reset_ktrace);
 286
 287         T_ASSERT_POSIX_ZERO(ktrace_start(s,
 288             dispatch_get_global_queue(QOS_CLASS_USER_INITIATED, 0)),
 289             "start ktrace");
 290
 291         kdebug_trace(DISPATCH_AFTER_EVENT, 0, 0, 0, 0);
 292
 293         dispatch_main();
 294 }
 295
 296 #pragma mark kdebug triggers
 297
 298 #define KDEBUG_TRIGGER_TIMEOUT_NS (10 * NSEC_PER_SEC)
 299
 300 #define NON_TRIGGER_CLASS    UINT8_C(0xfd)
 301 #define NON_TRIGGER_SUBCLASS UINT8_C(0xff)
 302 #define NON_TRIGGER_CODE     UINT8_C(0xff)
 303
 304 #define NON_TRIGGER_EVENT \
 305                 (KDBG_EVENTID(NON_TRIGGER_CLASS, NON_TRIGGER_SUBCLASS, \
 306                 NON_TRIGGER_CODE))
 307
 308 static void
 309 expect_kdebug_trigger(const char *filter_desc, const uint32_t *debugids,
 310     unsigned int n_debugids)
 311 {
 312         __block int missing_kernel_stacks = 0;
 313         __block int missing_user_stacks = 0;
 314         ktrace_session_t s;
 315         kperf_kdebug_filter_t filter;
 316
 317         s = ktrace_session_create();
 318         T_QUIET; T_ASSERT_NOTNULL(s, NULL);
 319
 320         ktrace_events_single(s, PERF_STK_KHDR, ^(struct trace_point *tp) {
 321                 missing_kernel_stacks--;
 322                 T_LOG("saw kernel stack with %lu frames, flags = %#lx", tp->arg2,
 323                 tp->arg1);
 324         });
 325         ktrace_events_single(s, PERF_STK_UHDR, ^(struct trace_point *tp) {
 326                 missing_user_stacks--;
 327                 T_LOG("saw user stack with %lu frames, flags = %#lx", tp->arg2,
 328                 tp->arg1);
 329         });
 330
 331         for (unsigned int i = 0; i < n_debugids; i++) {
 332                 ktrace_events_single(s, debugids[i], ^(struct trace_point *tp) {
 333                         missing_kernel_stacks++;
 334                         missing_user_stacks++;
 335                         T_LOG("saw event with debugid 0x%" PRIx32, tp->debugid);
 336                 });
 337         }
 338
 339         ktrace_events_single(s, NON_TRIGGER_EVENT,
 340             ^(__unused struct trace_point *tp)
 341         {
 342                 ktrace_end(s, 0);
 343         });
 344
 345         ktrace_set_completion_handler(s, ^{
 346                 T_EXPECT_LE(missing_kernel_stacks, 0, NULL);
 347                 T_EXPECT_LE(missing_user_stacks, 0, NULL);
 348
 349                 ktrace_session_destroy(s);
 350                 T_END;
 351         });
 352
 353         /* configure kperf */
 354
 355         kperf_reset();
 356
 357         (void)kperf_action_count_set(1);
 358         T_ASSERT_POSIX_SUCCESS(kperf_action_samplers_set(1,
 359             KPERF_SAMPLER_KSTACK | KPERF_SAMPLER_USTACK), NULL);
 360
 361         filter = kperf_kdebug_filter_create();
 362         T_ASSERT_NOTNULL(filter, NULL);
 363
 364         T_ASSERT_POSIX_SUCCESS(kperf_kdebug_action_set(1), NULL);
 365         T_ASSERT_POSIX_SUCCESS(kperf_kdebug_filter_add_desc(filter, filter_desc),
 366             NULL);
 367         T_ASSERT_POSIX_SUCCESS(kperf_kdebug_filter_set(filter), NULL);
 368         kperf_kdebug_filter_destroy(filter);
 369
 370         T_ASSERT_POSIX_SUCCESS(kperf_sample_set(1), NULL);
 371
 372         T_ASSERT_POSIX_ZERO(ktrace_start(s, dispatch_get_main_queue()), NULL);
 373
 374         /* trace the triggering debugids */
 375
 376         for (unsigned int i = 0; i < n_debugids; i++) {
 377                 T_ASSERT_POSIX_SUCCESS(kdebug_trace(debugids[i], 0, 0, 0, 0), NULL);
 378         }
 379
 380         T_ASSERT_POSIX_SUCCESS(kdebug_trace(NON_TRIGGER_EVENT, 0, 0, 0, 0), NULL);
 381
 382         dispatch_after(dispatch_time(DISPATCH_TIME_NOW, KDEBUG_TRIGGER_TIMEOUT_NS),
 383             dispatch_get_main_queue(), ^(void)
 384         {
 385                 ktrace_end(s, 1);
 386         });
 387 }
 388
 389 #define TRIGGER_CLASS     UINT8_C(0xfe)
 390 #define TRIGGER_CLASS_END UINT8_C(0xfd)
 391 #define TRIGGER_SUBCLASS  UINT8_C(0xff)
 392 #define TRIGGER_CODE      UINT8_C(0)
 393 #define TRIGGER_DEBUGID \
 394                 (KDBG_EVENTID(TRIGGER_CLASS, TRIGGER_SUBCLASS, TRIGGER_CODE))
 395
 396 T_DECL(kdebug_trigger_classes,
 397     "test that kdebug trigger samples on classes")
 398 {
 399         const uint32_t class_debugids[] = {
 400                 KDBG_EVENTID(TRIGGER_CLASS, 1, 1),
 401                 KDBG_EVENTID(TRIGGER_CLASS, 2, 1),
 402                 KDBG_EVENTID(TRIGGER_CLASS_END, 1, 1) | DBG_FUNC_END,
 403                 KDBG_EVENTID(TRIGGER_CLASS_END, 2, 1) | DBG_FUNC_END,
 404         };
 405
 406         expect_kdebug_trigger("C0xfe,C0xfdr", class_debugids,
 407             sizeof(class_debugids) / sizeof(class_debugids[0]));
 408         dispatch_main();
 409 }
 410
 411 T_DECL(kdebug_trigger_subclasses,
 412     "test that kdebug trigger samples on subclasses")
 413 {
 414         const uint32_t subclass_debugids[] = {
 415                 KDBG_EVENTID(TRIGGER_CLASS, TRIGGER_SUBCLASS, 0),
 416                 KDBG_EVENTID(TRIGGER_CLASS, TRIGGER_SUBCLASS, 1),
 417                 KDBG_EVENTID(TRIGGER_CLASS_END, TRIGGER_SUBCLASS, 0) | DBG_FUNC_END,
 418                 KDBG_EVENTID(TRIGGER_CLASS_END, TRIGGER_SUBCLASS, 1) | DBG_FUNC_END
 419         };
 420
 421         expect_kdebug_trigger("S0xfeff,S0xfdffr", subclass_debugids,
 422             sizeof(subclass_debugids) / sizeof(subclass_debugids[0]));
 423         dispatch_main();
 424 }
 425
 426 T_DECL(kdebug_trigger_debugids,
 427     "test that kdebug trigger samples on debugids")
 428 {
 429         const uint32_t debugids[] = {
 430                 TRIGGER_DEBUGID
 431         };
 432
 433         expect_kdebug_trigger("D0xfeff0000", debugids,
 434             sizeof(debugids) / sizeof(debugids[0]));
 435         dispatch_main();
 436 }
 437
 438 /*
 439  * TODO Set a single function specifier filter, expect not to trigger of all
 440  * events from that class.
 441  */
 442
 443 T_DECL(kdbg_callstacks,
 444     "test that the kdbg_callstacks samples on syscalls")
 445 {
 446         ktrace_session_t s;
 447         __block bool saw_user_stack = false;
 448
 449         s = ktrace_session_create();
 450         T_ASSERT_NOTNULL(s, NULL);
 451
 452         /*
 453          * Make sure BSD events are traced in order to trigger samples on syscalls.
 454          */
 455         ktrace_events_class(s, DBG_BSD, ^void (__unused struct trace_point *tp) {});
 456
 457         ktrace_events_single(s, PERF_STK_UHDR, ^(__unused struct trace_point *tp) {
 458                 saw_user_stack = true;
 459                 ktrace_end(s, 1);
 460         });
 461
 462         ktrace_set_completion_handler(s, ^{
 463                 ktrace_session_destroy(s);
 464
 465                 T_EXPECT_TRUE(saw_user_stack,
 466                 "saw user stack after configuring kdbg_callstacks");
 467                 T_END;
 468         });
 469
 470 #pragma clang diagnostic push
 471 #pragma clang diagnostic ignored "-Wdeprecated-declarations"
 472         T_ASSERT_POSIX_SUCCESS(kperf_kdbg_callstacks_set(1), NULL);
 473 #pragma clang diagnostic pop
 474         T_ATEND(kperf_reset);
 475
 476         T_ASSERT_POSIX_ZERO(ktrace_start(s, dispatch_get_main_queue()), NULL);
 477
 478         dispatch_after(dispatch_time(DISPATCH_TIME_NOW, 10 * NSEC_PER_SEC),
 479             dispatch_get_main_queue(), ^(void) {
 480                 ktrace_end(s, 1);
 481         });
 482
 483         dispatch_main();
 484 }
 485
 486 #pragma mark PET
 487
 488 #define STACKS_WAIT_DURATION_NS (3 * NSEC_PER_SEC)
 489
 490 static void
 491 expect_stacks_traced(void (^cb)(void))
 492 {
 493         ktrace_session_t s;
 494
 495         s = ktrace_session_create();
 496         T_QUIET; T_ASSERT_NOTNULL(s, "ktrace_session_create");
 497
 498         __block unsigned int user_stacks = 0;
 499         __block unsigned int kernel_stacks = 0;
 500
 501         ktrace_events_single(s, PERF_STK_UHDR, ^(__unused struct trace_point *tp) {
 502                 user_stacks++;
 503         });
 504         ktrace_events_single(s, PERF_STK_KHDR, ^(__unused struct trace_point *tp) {
 505                 kernel_stacks++;
 506         });
 507
 508         ktrace_set_completion_handler(s, ^(void) {
 509                 ktrace_session_destroy(s);
 510                 T_EXPECT_GT(user_stacks, 0U, NULL);
 511                 T_EXPECT_GT(kernel_stacks, 0U, NULL);
 512                 cb();
 513         });
 514
 515         T_QUIET; T_ASSERT_POSIX_SUCCESS(kperf_sample_set(1), NULL);
 516
 517         T_ASSERT_POSIX_ZERO(ktrace_start(s, dispatch_get_main_queue()), NULL);
 518
 519         dispatch_after(dispatch_time(DISPATCH_TIME_NOW, STACKS_WAIT_DURATION_NS),
 520             dispatch_get_main_queue(), ^(void)
 521         {
 522                 kperf_reset();
 523                 ktrace_end(s, 0);
 524         });
 525 }
 526
 527 T_DECL(pet, "test that PET mode samples kernel and user stacks")
 528 {
 529         configure_kperf_stacks_timer(-1, 10);
 530         T_ASSERT_POSIX_SUCCESS(kperf_timer_pet_set(0), NULL);
 531
 532         expect_stacks_traced(^(void) {
 533                 T_END;
 534         });
 535
 536         dispatch_main();
 537 }
 538
 539 T_DECL(lightweight_pet,
 540     "test that lightweight PET mode samples kernel and user stacks",
 541     T_META_ASROOT(true))
 542 {
 543         int set = 1;
 544
 545         configure_kperf_stacks_timer(-1, 10);
 546         T_ASSERT_POSIX_SUCCESS(sysctlbyname("kperf.lightweight_pet", NULL, NULL,
 547             &set, sizeof(set)), NULL);
 548         T_ASSERT_POSIX_SUCCESS(kperf_timer_pet_set(0), NULL);
 549
 550         expect_stacks_traced(^(void) {
 551                 T_END;
 552         });
 553
 554         dispatch_main();
 555 }
 556
 557 T_DECL(pet_stress, "repeatedly enable and disable PET mode")
 558 {
 559         int niters = 1000;
 560         while (niters--) {
 561                 configure_kperf_stacks_timer(-1, 10);
 562                 T_QUIET; T_ASSERT_POSIX_SUCCESS(kperf_timer_pet_set(0), NULL);
 563                 usleep(20);
 564                 kperf_reset();
 565         }
 566         ;
 567 }
 568
 569 T_DECL(timer_stress, "repeatedly enable and disable timers")
 570 {
 571         int niters = 1000;
 572         while (niters--) {
 573                 configure_kperf_stacks_timer(-1, 1);
 574                 usleep(20);
 575                 kperf_reset();
 576         }
 577         ;
 578 }