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