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
set_da_microstackshot_period(CFNumberRef num)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
disable_da_microstackshots(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
reenable_da_microstackshots(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
telemetry_cleanup(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
telemetry_init(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 *
thread_spin(__unused void * arg)102 thread_spin(__unused void *arg)
103 {
104 while (spinning) {
105 }
106 return NULL;
107 }
108
109 static bool
query_pmi_params(unsigned int * pmi_counter,uint64_t * pmi_period)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