tests/telemetry.c

   1 #include <darwintest.h>
   2 #include <dispatch/dispatch.h>
   3 #include <ktrace/ktrace.h>
   4 #include <kern/debug.h>
   5 #include <sys/kdebug.h>
   6 #include <TargetConditionals.h>
   7
   8 enum telemetry_pmi {
   9         TELEMETRY_PMI_NONE,
  10         TELEMETRY_PMI_INSTRS,
  11         TELEMETRY_PMI_CYCLES,
  12 };
  13 #define TELEMETRY_CMD_PMI_SETUP 3
  14
  15 T_GLOBAL_META(T_META_NAMESPACE("xnu.debugging.telemetry"),
  16                 T_META_CHECK_LEAKS(false),
  17                 T_META_ASROOT(true));
  18
  19 extern int __telemetry(uint64_t cmd, uint64_t deadline, uint64_t interval,
  20                 uint64_t leeway, uint64_t arg4, uint64_t arg5);
  21
  22 static void
  23 telemetry_cleanup(void)
  24 {
  25         int ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_NONE, 0, 0, 0, 0);
  26         T_EXPECT_POSIX_SUCCESS(ret, "telemetry(... NONE ...)");
  27 }
  28
  29 volatile static bool spinning = true;
  30 static void *
  31 thread_spin(__unused void *arg)
  32 {
  33         while (spinning) {
  34         }
  35         return NULL;
  36 }
  37
  38 #define MT_MICROSTACKSHOT KDBG_EVENTID(DBG_MONOTONIC, 2, 1)
  39 #define MS_RECORD MACHDBG_CODE(DBG_MACH_STACKSHOT, \
  40                 MICROSTACKSHOT_RECORD)
  41 #if defined(__arm64__) || defined(__arm__)
  42 #define INSTRS_PERIOD (100ULL * 1000 * 1000)
  43 #else /* defined(__arm64__) || defined(__arm__) */
  44 #define INSTRS_PERIOD (1ULL * 1000 * 1000 * 1000)
  45 #endif /* !defined(__arm64__) && !defined(__arm__) */
  46 #define SLEEP_SECS 10
  47
  48 T_DECL(microstackshot_pmi, "attempt to configure microstackshots on PMI")
  49 {
  50 #if TARGET_OS_WATCH
  51         T_SKIP("unsupported platform");
  52 #endif /* TARGET_OS_WATCH */
  53
  54         T_SETUPBEGIN;
  55         ktrace_session_t s = ktrace_session_create();
  56         T_QUIET; T_WITH_ERRNO; T_ASSERT_NOTNULL(s, "session create");
  57
  58         __block int pmi_events = 0;
  59         __block int microstackshot_record_events = 0;
  60         __block int pmi_records = 0;
  61         __block int io_records = 0;
  62         __block int interrupt_records = 0;
  63         __block int timer_arm_records = 0;
  64         __block int unknown_records = 0;
  65         __block int multi_records = 0;
  66
  67         ktrace_events_single(s, MT_MICROSTACKSHOT, ^(__unused struct trace_point *tp) {
  68                 pmi_events++;
  69         });
  70         ktrace_events_single_paired(s, MS_RECORD,
  71                         ^(struct trace_point *start, __unused struct trace_point *end) {
  72                 if (start->arg1 & kPMIRecord) {
  73                         pmi_records++;
  74                 }
  75                 if (start->arg1 & kIORecord) {
  76                         io_records++;
  77                 }
  78                 if (start->arg1 & kInterruptRecord) {
  79                         interrupt_records++;
  80                 }
  81                 if (start->arg1 & kTimerArmingRecord) {
  82                         timer_arm_records++;
  83                 }
  84
  85                 const uint8_t any_record = kPMIRecord | kIORecord | kInterruptRecord |
  86                                 kTimerArmingRecord;
  87                 if ((start->arg1 & any_record) == 0) {
  88                         unknown_records++;
  89                 }
  90                 if (__builtin_popcount(start->arg1 & any_record) != 1) {
  91                         multi_records++;
  92                 }
  93
  94                 microstackshot_record_events++;
  95         });
  96
  97         ktrace_set_completion_handler(s, ^{
  98                 ktrace_session_destroy(s);
  99                 T_EXPECT_GT(pmi_events, 0,
 100                                 "saw non-zero PMIs (%g/sec)", pmi_events / (double)SLEEP_SECS);
 101                 T_EXPECT_GT(pmi_records, 0, "saw non-zero PMI record events (%g/sec)",
 102                                 pmi_records / (double)SLEEP_SECS);
 103                 T_EXPECT_EQ(unknown_records, 0, "saw zero unknown record events");
 104                 T_EXPECT_EQ(multi_records, 0, "saw zero multiple record events");
 105                 T_EXPECT_GT(microstackshot_record_events, 0,
 106                                 "saw non-zero microstackshot record events (%g/sec)",
 107                                 microstackshot_record_events / (double)SLEEP_SECS);
 108
 109                 if (interrupt_records > 0) {
 110                         T_LOG("saw %g interrupt records per second",
 111                                         interrupt_records / (double)SLEEP_SECS);
 112                 } else {
 113                         T_LOG("saw no interrupt records");
 114                 }
 115                 if (io_records > 0) {
 116                         T_LOG("saw %g I/O records per second",
 117                                         io_records / (double)SLEEP_SECS);
 118                 } else {
 119                         T_LOG("saw no I/O records");
 120                 }
 121                 if (timer_arm_records > 0) {
 122                         T_LOG("saw %g timer arming records per second",
 123                                         timer_arm_records / (double)SLEEP_SECS);
 124                 } else {
 125                         T_LOG("saw no timer arming records");
 126                 }
 127
 128                 T_END;
 129         });
 130
 131         T_SETUPEND;
 132
 133         /*
 134          * Start sampling via telemetry on the instructions PMI.
 135          */
 136         int ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_INSTRS,
 137                         INSTRS_PERIOD, 0, 0, 0);
 138         if (ret < 0 && errno == EBUSY) {
 139                 T_PASS("telemetry is busy/active, maybe the events will be seen");
 140         } else {
 141                 T_ASSERT_POSIX_SUCCESS(ret,
 142                                 "telemetry syscall succeeded, started microstackshots");
 143                 T_LOG("installing cleanup handler");
 144                 T_ATEND(telemetry_cleanup);
 145         }
 146
 147         pthread_t thread;
 148         int error = pthread_create(&thread, NULL, thread_spin, NULL);
 149         T_ASSERT_POSIX_ZERO(error, "started thread to spin");
 150
 151         error = ktrace_start(s, dispatch_get_main_queue());
 152         T_ASSERT_POSIX_ZERO(error, "started tracing");
 153
 154         dispatch_after(dispatch_time(DISPATCH_TIME_NOW, SLEEP_SECS * NSEC_PER_SEC),
 155                         dispatch_get_main_queue(), ^{
 156                 spinning = false;
 157                 ktrace_end(s, 0);
 158                 (void)pthread_join(thread, NULL);
 159                 T_LOG("ending trace session after %d seconds", SLEEP_SECS);
 160         });
 161
 162         dispatch_main();
 163 }
 164
 165 T_DECL(error_handling,
 166                 "ensure that error conditions for the telemetry syscall are observed")
 167 {
 168         int ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_INSTRS,
 169                         1, 0, 0, 0);
 170         T_EXPECT_EQ(ret, -1, "telemetry shouldn't allow PMI every instruction");
 171
 172         ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_INSTRS,
 173                         1000 * 1000, 0, 0, 0);
 174         T_EXPECT_EQ(ret, -1,
 175                         "telemetry shouldn't allow PMI every million instructions");
 176
 177         ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_CYCLES,
 178                         1, 0, 0, 0);
 179         T_EXPECT_EQ(ret, -1, "telemetry shouldn't allow PMI every cycle");
 180
 181         ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_CYCLES,
 182                         1000 * 1000, 0, 0, 0);
 183         T_EXPECT_EQ(ret, -1,
 184                         "telemetry shouldn't allow PMI every million cycles");
 185 }