1 /* Copyright (c) 2018-2021 Apple Inc. All rights reserved. */ 2 3 #include <CoreFoundation/CoreFoundation.h> 4 #include <darwintest.h> 5 #include <darwintest_utils.h> 6 #include <dispatch/dispatch.h> 7 #include <ktrace/ktrace.h> 8 #include <kperf/kperf.h> 9 #include <kern/debug.h> 10 #include <notify.h> 11 #include <sys/kdebug.h> 12 #include <sys/sysctl.h> 13 #include <TargetConditionals.h> 14 15 #include "ktrace/ktrace_helpers.h" 16 17 enum telemetry_pmi { 18 TELEMETRY_PMI_NONE, 19 TELEMETRY_PMI_INSTRS, 20 TELEMETRY_PMI_CYCLES, 21 }; 22 #define TELEMETRY_CMD_PMI_SETUP 3 23 24 T_GLOBAL_META(T_META_NAMESPACE("xnu.stackshot.microstackshot"), 25 T_META_RADAR_COMPONENT_NAME("xnu"), 26 T_META_RADAR_COMPONENT_VERSION("stackshot"), 27 T_META_OWNER("mwidmann"), 28 T_META_CHECK_LEAKS(false), 29 T_META_ASROOT(true)); 30 31 extern int __telemetry(uint64_t cmd, uint64_t deadline, uint64_t interval, 32 uint64_t leeway, uint64_t arg4, uint64_t arg5); 33 34 /* 35 * Data Analytics (da) also has a microstackshot configuration -- set a PMI 36 * cycle interval of 0 to force it to disable microstackshot on PMI. 37 */ 38 39 static void 40 set_da_microstackshot_period(CFNumberRef num) 41 { 42 CFPreferencesSetValue(CFSTR("microstackshotPMICycleInterval"), num, 43 CFSTR("com.apple.da"), 44 #if TARGET_OS_IPHONE 45 CFSTR("mobile"), 46 #else // TARGET_OS_IPHONE 47 CFSTR("root"), 48 #endif // !TARGET_OS_IPHONE 49 kCFPreferencesCurrentHost); 50 51 notify_post("com.apple.da.tasking_changed"); 52 } 53 54 static void 55 disable_da_microstackshots(void) 56 { 57 int64_t zero = 0; 58 CFNumberRef num = CFNumberCreate(NULL, kCFNumberSInt64Type, &zero); 59 set_da_microstackshot_period(num); 60 T_LOG("notified da of tasking change, sleeping"); 61 #if TARGET_OS_WATCH 62 sleep(8); 63 #else /* TARGET_OS_WATCH */ 64 sleep(3); 65 #endif /* !TARGET_OS_WATCH */ 66 } 67 68 /* 69 * Unset the preference to allow da to reset its configuration. 70 */ 71 static void 72 reenable_da_microstackshots(void) 73 { 74 set_da_microstackshot_period(NULL); 75 } 76 77 /* 78 * Clean up the test's configuration and allow da to activate again. 79 */ 80 static void 81 telemetry_cleanup(void) 82 { 83 (void)__telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_NONE, 0, 0, 0, 0); 84 reenable_da_microstackshots(); 85 } 86 87 /* 88 * Make sure da hasn't configured the microstackshots -- otherwise the PMI 89 * setup command will return EBUSY. 90 */ 91 static void 92 telemetry_init(void) 93 { 94 disable_da_microstackshots(); 95 T_LOG("installing cleanup handler"); 96 T_ATEND(telemetry_cleanup); 97 } 98 99 volatile static bool spinning = true; 100 101 static void * 102 thread_spin(__unused void *arg) 103 { 104 while (spinning) { 105 } 106 return NULL; 107 } 108 109 static bool 110 query_pmi_params(unsigned int *pmi_counter, uint64_t *pmi_period) 111 { 112 bool pmi_support = true; 113 size_t sysctl_size = sizeof(pmi_counter); 114 int ret = sysctlbyname( 115 "kern.microstackshot.pmi_sample_counter", 116 pmi_counter, &sysctl_size, NULL, 0); 117 if (ret == -1 && errno == ENOENT) { 118 pmi_support = false; 119 T_LOG("no PMI support"); 120 } else { 121 T_QUIET; T_ASSERT_POSIX_SUCCESS(ret, "query PMI counter"); 122 } 123 if (pmi_support) { 124 sysctl_size = sizeof(*pmi_period); 125 T_QUIET; T_ASSERT_POSIX_SUCCESS(sysctlbyname( 126 "kern.microstackshot.pmi_sample_period", 127 pmi_period, &sysctl_size, NULL, 0), 128 "query PMI period"); 129 } 130 return pmi_support; 131 } 132 133 #define MT_MICROSTACKSHOT KDBG_EVENTID(DBG_MONOTONIC, 2, 1) 134 #define MS_RECORD MACHDBG_CODE(DBG_MACH_STACKSHOT, \ 135 MICROSTACKSHOT_RECORD) 136 #if defined(__arm64__) 137 #define INSTRS_PERIOD (100ULL * 1000 * 1000) 138 #else /* defined(__arm64__) */ 139 #define INSTRS_PERIOD (1ULL * 1000 * 1000 * 1000) 140 #endif /* defined(__arm64__) */ 141 #define SLEEP_SECS 10 142 143 T_DECL(pmi_sampling, "attempt to configure microstackshots on PMI", 144 T_META_REQUIRES_SYSCTL_EQ("kern.monotonic.supported", 1), T_META_TAG_VM_NOT_ELIGIBLE) 145 { 146 start_controlling_ktrace(); 147 148 T_SETUPBEGIN; 149 ktrace_session_t s = ktrace_session_create(); 150 T_QUIET; T_WITH_ERRNO; T_ASSERT_NOTNULL(s, "session create"); 151 152 __block int pmi_events = 0; 153 __block int microstackshot_record_events = 0; 154 __block int pmi_records = 0; 155 __block int io_records = 0; 156 __block int interrupt_records = 0; 157 __block int timer_arm_records = 0; 158 __block int unknown_records = 0; 159 __block int empty_records = 0; 160 161 ktrace_events_single(s, MT_MICROSTACKSHOT, ^(__unused struct trace_point *tp) { 162 pmi_events++; 163 }); 164 ktrace_events_single_paired(s, MS_RECORD, 165 ^(struct trace_point *start, __unused struct trace_point *end) { 166 if (start->arg1 & kPMIRecord) { 167 pmi_records++; 168 } 169 if (start->arg1 & kIORecord) { 170 io_records++; 171 } 172 if (start->arg1 & kInterruptRecord) { 173 interrupt_records++; 174 } 175 if (start->arg1 & kTimerArmingRecord) { 176 timer_arm_records++; 177 } 178 179 if (start->arg2 == end->arg2) { 180 /* 181 * The buffer didn't grow for this record -- there was 182 * an error. 183 */ 184 empty_records++; 185 } 186 187 const uint8_t any_record = kPMIRecord | kIORecord | kInterruptRecord | 188 kTimerArmingRecord; 189 if ((start->arg1 & any_record) == 0) { 190 unknown_records++; 191 } 192 193 microstackshot_record_events++; 194 }); 195 196 ktrace_set_completion_handler(s, ^{ 197 ktrace_session_destroy(s); 198 T_EXPECT_GT(pmi_events, 0, "saw non-zero PMIs (%g/sec)", 199 pmi_events / (double)SLEEP_SECS); 200 T_EXPECT_GT(pmi_records, 0, "saw non-zero PMI record events (%g/sec)", 201 pmi_records / (double)SLEEP_SECS); 202 T_LOG("saw %d unknown record events", unknown_records); 203 T_EXPECT_GT(microstackshot_record_events, 0, 204 "saw non-zero microstackshot record events (%d -- %g/sec)", 205 microstackshot_record_events, 206 microstackshot_record_events / (double)SLEEP_SECS); 207 T_EXPECT_NE(empty_records, microstackshot_record_events, 208 "saw non-empty records (%d empty)", empty_records); 209 210 if (interrupt_records > 0) { 211 T_LOG("saw %g interrupt records per second", 212 interrupt_records / (double)SLEEP_SECS); 213 } else { 214 T_LOG("saw no interrupt records"); 215 } 216 if (io_records > 0) { 217 T_LOG("saw %g I/O records per second", 218 io_records / (double)SLEEP_SECS); 219 } else { 220 T_LOG("saw no I/O records"); 221 } 222 if (timer_arm_records > 0) { 223 T_LOG("saw %g timer arming records per second", 224 timer_arm_records / (double)SLEEP_SECS); 225 } else { 226 T_LOG("saw no timer arming records"); 227 } 228 229 T_END; 230 }); 231 232 T_SETUPEND; 233 234 telemetry_init(); 235 236 /* 237 * Start sampling via telemetry on the instructions PMI. 238 */ 239 int ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_INSTRS, 240 INSTRS_PERIOD, 0, 0, 0); 241 T_ASSERT_POSIX_SUCCESS(ret, 242 "telemetry syscall succeeded, started microstackshots"); 243 244 unsigned int pmi_counter = 0; 245 uint64_t pmi_period = 0; 246 bool pmi_support = query_pmi_params(&pmi_counter, &pmi_period); 247 T_QUIET; T_ASSERT_TRUE(pmi_support, "PMI should be supported"); 248 249 T_LOG("PMI counter: %u", pmi_counter); 250 T_LOG("PMI period: %llu", pmi_period); 251 #if defined(__arm64__) 252 const unsigned int instrs_counter = 1; 253 #else 254 const unsigned int instrs_counter = 0; 255 #endif // defined(__arm64__) 256 T_QUIET; T_ASSERT_EQ(pmi_counter, instrs_counter, 257 "PMI on instructions retired"); 258 T_QUIET; T_ASSERT_EQ(pmi_period, INSTRS_PERIOD, "PMI period is set"); 259 260 pthread_t thread; 261 int error = pthread_create(&thread, NULL, thread_spin, NULL); 262 T_ASSERT_POSIX_ZERO(error, "started thread to spin"); 263 264 error = ktrace_start(s, dispatch_get_main_queue()); 265 T_ASSERT_POSIX_ZERO(error, "started tracing"); 266 267 dispatch_after(dispatch_time(DISPATCH_TIME_NOW, SLEEP_SECS * NSEC_PER_SEC), 268 dispatch_get_main_queue(), ^{ 269 spinning = false; 270 ktrace_end(s, 0); 271 (void)pthread_join(thread, NULL); 272 T_LOG("ending trace session after %d seconds", SLEEP_SECS); 273 }); 274 275 dispatch_main(); 276 } 277 278 T_DECL(error_handling, 279 "ensure that error conditions for the telemetry syscall are observed", 280 T_META_REQUIRES_SYSCTL_EQ("kern.monotonic.supported", 1), T_META_TAG_VM_NOT_ELIGIBLE) 281 { 282 telemetry_init(); 283 284 int ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_INSTRS, 285 1, 0, 0, 0); 286 T_EXPECT_EQ(ret, -1, "telemetry shouldn't allow PMI every instruction"); 287 288 ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_INSTRS, 289 1000 * 1000, 0, 0, 0); 290 T_EXPECT_EQ(ret, -1, 291 "telemetry shouldn't allow PMI every million instructions"); 292 293 ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_CYCLES, 294 1, 0, 0, 0); 295 T_EXPECT_EQ(ret, -1, "telemetry shouldn't allow PMI every cycle"); 296 297 ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_CYCLES, 298 1000 * 1000, 0, 0, 0); 299 T_EXPECT_EQ(ret, -1, 300 "telemetry shouldn't allow PMI every million cycles"); 301 302 ret = __telemetry(TELEMETRY_CMD_PMI_SETUP, TELEMETRY_PMI_CYCLES, 303 UINT64_MAX, 0, 0, 0); 304 T_EXPECT_EQ(ret, -1, "telemetry shouldn't allow PMI every UINT64_MAX cycles"); 305 } 306 307 #define START_EVENT (0xfeedfad0) 308 #define STOP_EVENT (0xfeedfac0) 309 310 T_DECL(excessive_sampling, 311 "ensure that microstackshots are not being sampled too frequently", 312 T_META_REQUIRES_SYSCTL_EQ("kern.monotonic.supported", 1), T_META_TAG_VM_NOT_ELIGIBLE) 313 { 314 unsigned int interrupt_sample_rate = 0; 315 size_t sysctl_size = sizeof(interrupt_sample_rate); 316 T_QUIET; 317 T_ASSERT_POSIX_SUCCESS(sysctlbyname( 318 "kern.microstackshot.interrupt_sample_rate", 319 &interrupt_sample_rate, &sysctl_size, NULL, 0), 320 "query interrupt sample rate"); 321 unsigned int pmi_counter = 0; 322 uint64_t pmi_period = 0; 323 (void)query_pmi_params(&pmi_counter, &pmi_period); 324 325 T_LOG("interrupt sample rate: %uHz", interrupt_sample_rate); 326 T_LOG("PMI counter: %u", pmi_counter); 327 T_LOG("PMI period: %llu", pmi_period); 328 329 start_controlling_ktrace(); 330 331 T_SETUPBEGIN; 332 ktrace_session_t s = ktrace_session_create(); 333 T_QUIET; T_WITH_ERRNO; T_ASSERT_NOTNULL(s, "session create"); 334 335 __block int microstackshot_record_events = 0; 336 __block int pmi_records = 0; 337 __block int io_records = 0; 338 __block int interrupt_records = 0; 339 __block int timer_arm_records = 0; 340 __block int unknown_records = 0; 341 __block int empty_records = 0; 342 __block uint64_t first_timestamp_ns = 0; 343 __block uint64_t last_timestamp_ns = 0; 344 345 ktrace_events_single_paired(s, MS_RECORD, 346 ^(struct trace_point *start, __unused struct trace_point *end) { 347 if (start->arg1 & kPMIRecord) { 348 pmi_records++; 349 } 350 if (start->arg1 & kIORecord) { 351 io_records++; 352 } 353 if (start->arg1 & kInterruptRecord) { 354 interrupt_records++; 355 } 356 if (start->arg1 & kTimerArmingRecord) { 357 timer_arm_records++; 358 } 359 360 if (start->arg2 == end->arg2) { 361 /* 362 * The buffer didn't grow for this record -- there was 363 * an error. 364 */ 365 empty_records++; 366 } 367 368 const uint8_t any_record = kPMIRecord | kIORecord | kInterruptRecord | 369 kTimerArmingRecord; 370 if ((start->arg1 & any_record) == 0) { 371 unknown_records++; 372 } 373 374 microstackshot_record_events++; 375 }); 376 377 ktrace_events_single(s, START_EVENT, ^(struct trace_point *tp) { 378 int error = ktrace_convert_timestamp_to_nanoseconds(s, 379 tp->timestamp, &first_timestamp_ns); 380 T_QUIET; 381 T_ASSERT_POSIX_ZERO(error, "converted timestamp to nanoseconds"); 382 }); 383 384 ktrace_events_single(s, STOP_EVENT, ^(struct trace_point *tp) { 385 int error = ktrace_convert_timestamp_to_nanoseconds(s, 386 tp->timestamp, &last_timestamp_ns); 387 T_QUIET; 388 T_ASSERT_POSIX_ZERO(error, "converted timestamp to nanoseconds"); 389 ktrace_end(s, 1); 390 }); 391 392 ktrace_set_completion_handler(s, ^{ 393 ktrace_session_destroy(s); 394 395 uint64_t duration_ns = last_timestamp_ns - first_timestamp_ns; 396 double duration_secs = (double)duration_ns / 1e9; 397 398 T_LOG("test lasted %g seconds", duration_secs); 399 400 T_MAYFAIL; 401 T_EXPECT_EQ(unknown_records, 0, "saw zero unknown record events"); 402 T_MAYFAIL; 403 T_EXPECT_GT(microstackshot_record_events, 0, 404 "saw non-zero microstackshot record events (%d, %gHz)", 405 microstackshot_record_events, 406 microstackshot_record_events / duration_secs); 407 T_EXPECT_NE(empty_records, microstackshot_record_events, 408 "saw non-empty records (%d empty)", empty_records); 409 410 double record_rate_hz = microstackshot_record_events / duration_secs; 411 T_LOG("record rate: %gHz", record_rate_hz); 412 T_LOG("PMI record rate: %gHz", pmi_records / duration_secs); 413 T_LOG("interrupt record rate: %gHz", 414 interrupt_records / duration_secs); 415 T_LOG("I/O record rate: %gHz", io_records / duration_secs); 416 T_LOG("timer arm record rate: %gHz", 417 timer_arm_records / duration_secs); 418 419 T_EXPECT_LE(record_rate_hz, (double)(dt_ncpu() * 50), 420 "found appropriate rate of microstackshots"); 421 422 T_END; 423 }); 424 425 pthread_t thread; 426 int error = pthread_create(&thread, NULL, thread_spin, NULL); 427 T_ASSERT_POSIX_ZERO(error, "started thread to spin"); 428 429 T_SETUPEND; 430 431 error = ktrace_start(s, dispatch_get_main_queue()); 432 T_ASSERT_POSIX_ZERO(error, "started tracing"); 433 kdebug_trace(START_EVENT, 0, 0, 0, 0); 434 435 dispatch_after(dispatch_time(DISPATCH_TIME_NOW, SLEEP_SECS * NSEC_PER_SEC), 436 dispatch_get_main_queue(), ^{ 437 spinning = false; 438 kdebug_trace(STOP_EVENT, 0, 0, 0, 0); 439 (void)pthread_join(thread, NULL); 440 T_LOG("ending trace session after %d seconds", SLEEP_SECS); 441 }); 442 443 dispatch_main(); 444 } 445