1 // Copyright (c) 2023 Apple Inc. All rights reserved.
2
3 #include <unistd.h>
4 #include <stdlib.h>
5 #include <stdio.h>
6 #include <pthread.h>
7 #include <string.h>
8 #include <mach/mach.h>
9 #include <mach/mach_time.h>
10 #include <sys/stat.h>
11 #include <sys/sysctl.h>
12 #include <stdatomic.h>
13 #include <sys/work_interval.h>
14 #include <ktrace.h>
15 #include <sys/kdebug.h>
16
17 #include <darwintest.h>
18 #include <darwintest_utils.h>
19 #include "test_utils.h"
20 #include "sched_test_utils.h"
21
22 T_GLOBAL_META(T_META_NAMESPACE("xnu.scheduler"),
23 T_META_RADAR_COMPONENT_NAME("xnu"),
24 T_META_RADAR_COMPONENT_VERSION("scheduler"),
25 T_META_TAG_VM_NOT_ELIGIBLE);
26
27 static int BACKGROUND_PRI;
28 static int NUM_THREADS;
29 static uint64_t SLEEP_SECONDS;
30 static uint64_t INTERRUPT_DISABLE_TIMEOUT_NS;
31
32 static uint64_t start_timestamp = 0ULL;
33 static volatile int sum = 0; // Keeps the spin-loop below from compiling-out
34
35 static void *
make_tg_and_spin(__unused void * arg)36 make_tg_and_spin(__unused void *arg)
37 {
38 int ret;
39 assert(SLEEP_SECONDS > 2);
40
41 /* Create and join a new thread group (TG) */
42 work_interval_t wi_handle;
43 ret = work_interval_create(&wi_handle, WORK_INTERVAL_FLAG_GROUP);
44 T_QUIET; T_ASSERT_POSIX_ZERO(ret, 0, "work_interval_create");
45
46 /* Allow other threads a chance to get on-core and create/join their own TGs */
47 uint64_t yield_deadline = start_timestamp + nanos_to_abs(1 * NSEC_PER_SEC);
48 while (mach_absolute_time() < yield_deadline) {
49 sched_yield();
50 }
51
52 /*
53 * Remain runnable long enough for the sched_maintenance_thread to scan the
54 * many created TGs all at the same time in one scheduler tick.
55 */
56 uint64_t spin_deadline = start_timestamp + nanos_to_abs((SLEEP_SECONDS - 2) * NSEC_PER_SEC);
57 while (mach_absolute_time() < spin_deadline) {
58 sum++;
59 }
60
61 /*
62 * Terminate with about a second to spare of SLEEP_SECONDS, so that we have
63 * time to bring down the number of runnable thread groups before the test
64 * case reenables the previous kern.interrupt_masked_debug_mode value.
65 * Otherwise, a system failing this test could panic.
66 */
67 return NULL;
68 }
69
70 static void
start_threads(pthread_t * threads,void * (* start_routine)(void *),int priority,int num_threads)71 start_threads(pthread_t *threads, void *(*start_routine)(void *), int priority, int num_threads)
72 {
73 int rv;
74 pthread_attr_t attr;
75
76 rv = pthread_attr_init(&attr);
77 T_QUIET; T_ASSERT_POSIX_ZERO(rv, "pthread_attr_init");
78
79 for (int i = 0; i < num_threads; i++) {
80 struct sched_param param = { .sched_priority = priority };
81
82 rv = pthread_attr_setschedparam(&attr, ¶m);
83 T_QUIET; T_ASSERT_POSIX_ZERO(rv, "pthread_attr_setschedparam");
84
85 rv = pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED);
86 T_QUIET; T_ASSERT_POSIX_ZERO(rv, "pthread_attr_setdetachstate");
87
88 /* Make the thread stacks smaller, so pthread will let us make more */
89 rv = pthread_attr_setstacksize(&attr, PTHREAD_STACK_MIN);
90 T_QUIET; T_ASSERT_POSIX_ZERO(rv, "pthread_attr_setstacksize");
91
92 rv = pthread_create(&threads[i], &attr, start_routine, NULL);
93 T_QUIET; T_ASSERT_POSIX_ZERO(rv, "pthread_create");
94 }
95
96 rv = pthread_attr_destroy(&attr);
97 T_QUIET; T_ASSERT_POSIX_ZERO(rv, "pthread_attr_destroy");
98 }
99
100 static uint64_t old_preemption_debug_mode = 0;
101 static size_t old_preemption_debug_mode_size = sizeof(old_preemption_debug_mode);
102
103 static void
restore_preemption_disable_debug_mode(void)104 restore_preemption_disable_debug_mode(void)
105 {
106 int ret = sysctlbyname("kern.sched_preemption_disable_debug_mode", NULL, NULL,
107 &old_preemption_debug_mode, old_preemption_debug_mode_size);
108 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "kern.sched_preemption_disable_debug_mode");
109 T_LOG("kern.sched_preemption_disable_debug_mode restored to previous value: %llu", old_preemption_debug_mode);
110 }
111
112 static uint64_t old_interrupt_debug_mode = 0;
113 static size_t old_interrupt_debug_mode_size = sizeof(old_interrupt_debug_mode);
114
115 static void
restore_interrupt_disable_debug_mode(void)116 restore_interrupt_disable_debug_mode(void)
117 {
118 int ret = sysctlbyname("kern.interrupt_masked_debug_mode", NULL, NULL,
119 &old_interrupt_debug_mode, old_interrupt_debug_mode_size);
120 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "kern.interrupt_masked_debug_mode");
121 T_LOG("kern.interrupt_masked_debug_mode restored to previous value: %llu", old_interrupt_debug_mode);
122 }
123
124 static uint64_t old_interrupt_disable_timeout = 0;
125 static size_t old_interrupt_disable_timeout_size = sizeof(old_interrupt_disable_timeout);
126
127 static void
restore_interrupt_disable_timeout(void)128 restore_interrupt_disable_timeout(void)
129 {
130 int ret = sysctlbyname("kern.interrupt_masked_threshold_mt", NULL, NULL,
131 &old_interrupt_disable_timeout, old_interrupt_disable_timeout_size);
132 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "kern.interrupt_masked_threshold_mt");
133 T_LOG("kern.interrupt_masked_threshold_mt restored to previous value: %llu", old_interrupt_disable_timeout);
134 }
135
136 static char *trace_location = NULL;
137
138 static void
delete_trace_file(void)139 delete_trace_file(void)
140 {
141 int ret;
142 /* Delete trace file in order to reclaim disk space on the test device */
143 ret = remove(trace_location);
144 T_QUIET; T_WITH_ERRNO; T_ASSERT_POSIX_SUCCESS(ret, "remove trace file");
145 }
146
147 static const char *ktrace_file_short_name = "overload_runqueue_with_thread_groups.ktrace";
148
149 static void
save_collected_ktrace(char * trace_path)150 save_collected_ktrace(char *trace_path)
151 {
152 int ret;
153
154 T_LOG("ktrace file saved at \"%s\"", trace_path);
155 ret = chmod(trace_path, 0666);
156 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "chmod");
157
158 char compressed_path[MAXPATHLEN];
159 snprintf(compressed_path, MAXPATHLEN, "%s.tar.gz", ktrace_file_short_name);
160 ret = dt_resultfile(compressed_path, sizeof(compressed_path));
161 T_QUIET; T_ASSERT_POSIX_SUCCESS(ret, "dt_resultfile marking \"%s\" for collection", compressed_path);
162 T_LOG("\"%s\" marked for upload", compressed_path);
163
164 char *tar_args[] = {"/usr/bin/tar", "-czvf", compressed_path, trace_path, NULL};
165 pid_t tar_pid = dt_launch_tool_pipe(tar_args, false, NULL,
166 ^bool (__unused char *data, __unused size_t data_size, __unused dt_pipe_data_handler_context_t *context) {
167 return true;
168 },
169 ^bool (char *data, __unused size_t data_size, __unused dt_pipe_data_handler_context_t *context) {
170 T_LOG("[tar] Error msg: %s", data);
171 return true;
172 },
173 BUFFER_PATTERN_LINE, NULL);
174
175 T_QUIET; T_ASSERT_TRUE(tar_pid, "[tar] pid %d", tar_pid);
176 ret = dt_waitpid(tar_pid, NULL, NULL, 0);
177 T_QUIET; T_ASSERT_POSIX_SUCCESS(ret, "dt_waitpid");
178
179 ret = chmod(compressed_path, 0666);
180 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "chmod");
181 }
182
183 /*
184 * Parse the recorded ktrace file to see if we crossed the set interrupt-disabled
185 * timeout and thus failed the test.
186 */
187 static void
search_for_interrupt_disable_timeout_tracepoint(char * trace_path)188 search_for_interrupt_disable_timeout_tracepoint(char *trace_path)
189 {
190 __block int ret;
191 trace_location = trace_path;
192 T_ATEND(delete_trace_file);
193 ktrace_session_t read_session = ktrace_session_create();
194 ret = ktrace_set_file(read_session, trace_path);
195 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "ktrace_set_file");
196 __block const char *offending_thread = NULL;
197
198 ktrace_events_single(read_session, MACHDBG_CODE(DBG_MACH_SCHED, MACH_INT_MASKED_EXPIRED), ^(ktrace_event_t e) {
199 if (offending_thread == NULL) {
200 T_LOG("Interrupts were held disabled for %llu ns, crossing the %llu ns threshold:", abs_to_nanos(e->arg1), INTERRUPT_DISABLE_TIMEOUT_NS);
201 ret = ktrace_print_trace_point(stdout, read_session, e, KTP_KIND_CSV,
202 KTP_FLAG_WALLTIME | KTP_FLAG_THREADNAME | KTP_FLAG_PID | KTP_FLAG_EVENTNAME | KTP_FLAG_EXECNAME);
203 T_QUIET; T_ASSERT_POSIX_SUCCESS(ret, "ktrace_print_trace_point output");
204 printf("\n"); // Flush output from ktrace_print_trace_point
205 offending_thread = ktrace_get_name_for_thread(read_session, e->threadid);
206 ktrace_end(read_session, 0);
207 }
208 });
209
210 ktrace_set_completion_handler(read_session, ^{
211 if (offending_thread == NULL) {
212 T_PASS("Scheduler survived %d simulatenously runnable thread groups without disabling interrupts for more than %llu ns!", NUM_THREADS, INTERRUPT_DISABLE_TIMEOUT_NS);
213 } else {
214 save_collected_ktrace(trace_path);
215 T_FAIL("Interrupts held disabled for more than %llu ns by thread \"%s\"", INTERRUPT_DISABLE_TIMEOUT_NS, offending_thread);
216 }
217 T_END;
218 });
219
220 ret = ktrace_start(read_session, dispatch_get_main_queue());
221 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "ktrace_start");
222 }
223
224 T_DECL(overload_runqueue_with_thread_groups,
225 "Overload the runqueue with distinct thread groups to verify that the scheduler"
226 "does not trip an interrupts-disabled timeout whenever it scans the runqueue",
227 T_META_ASROOT(true), XNU_T_META_SOC_SPECIFIC, T_META_ENABLED(TARGET_OS_IOS))
228 {
229 BACKGROUND_PRI = 4;
230 NUM_THREADS = 1000;
231 SLEEP_SECONDS = 20;
232 /* Matches DEFAULT_INTERRUPT_MASKED_TIMEOUT value in XNU */
233 INTERRUPT_DISABLE_TIMEOUT_NS = 500 * NSEC_PER_USEC; // 500 microseconds
234
235 __block int ret;
236
237 /* Configure interrupts-disabled timeout to drop a ktracepoint */
238 uint64_t emit_tracepoint_mode = 1;
239 ret = sysctlbyname("kern.interrupt_masked_debug_mode",
240 &old_interrupt_debug_mode, &old_interrupt_debug_mode_size,
241 &emit_tracepoint_mode, sizeof(emit_tracepoint_mode));
242 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "kern.interrupt_masked_debug_mode");
243 T_ATEND(restore_interrupt_disable_debug_mode);
244 /* Configure the preemption-disabled debug mode as well, to avoid panicking if the test fails */
245 ret = sysctlbyname("kern.sched_preemption_disable_debug_mode",
246 &old_preemption_debug_mode, &old_preemption_debug_mode_size,
247 &emit_tracepoint_mode, sizeof(emit_tracepoint_mode));
248 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "kern.sched_preemption_disable_debug_mode");
249 T_ATEND(restore_preemption_disable_debug_mode);
250
251 /* Set interrupts-disabled timeout threshold */
252 uint64_t disable_timeout = nanos_to_abs(INTERRUPT_DISABLE_TIMEOUT_NS);
253 ret = sysctlbyname("kern.interrupt_masked_threshold_mt",
254 &old_interrupt_disable_timeout, &old_interrupt_disable_timeout_size,
255 &disable_timeout, sizeof(disable_timeout));
256 T_QUIET; T_WITH_ERRNO; T_ASSERT_POSIX_ZERO(ret, "kern.interrupt_masked_threshold_mt");
257 T_ATEND(restore_interrupt_disable_timeout);
258
259 /* Use ktrace to observe if the interrupt-disable timeout drops a tracepoint */
260 ktrace_session_t session = ktrace_session_create();
261 T_QUIET; T_WITH_ERRNO; T_ASSERT_NOTNULL(session, "ktrace_session_create");
262 char filepath_arr[MAXPATHLEN] = "";
263 const char *tmp_dir = dt_tmpdir();
264 strlcpy(filepath_arr, tmp_dir, sizeof(filepath_arr));
265 strlcat(filepath_arr, "/", sizeof(filepath_arr));
266 strlcat(filepath_arr, ktrace_file_short_name, sizeof(filepath_arr));
267 ret = remove(filepath_arr);
268 T_QUIET; T_WITH_ERRNO; T_ASSERT_TRUE((ret == 0) || (errno == ENOENT), "remove");
269 char *filepath = filepath_arr;
270 ret = ktrace_events_filter(session, "C0x01", ^(__unused ktrace_event_t event){}); // records scheduler tracepoints
271 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "ktrace_events_filter");
272 ktrace_set_completion_handler(session, ^{
273 search_for_interrupt_disable_timeout_tracepoint(filepath);
274 });
275 ret = ktrace_start_writing_path(session, filepath, 0);
276 T_QUIET; T_ASSERT_POSIX_ZERO(ret, "ktrace_start_writing_path");
277
278 /* Spin up lots of threads, each creating and joining its own thread group */
279 T_LOG("Creating %d threads at pri %d, each with a unique thread group", NUM_THREADS, BACKGROUND_PRI);
280 start_timestamp = mach_absolute_time();
281 pthread_t *bg_threads = malloc(sizeof(pthread_t) * (size_t)NUM_THREADS);
282 start_threads(bg_threads, make_tg_and_spin, BACKGROUND_PRI, NUM_THREADS);
283
284 T_LOG("Waiting %llu seconds to see if the scheduler can handle it...", SLEEP_SECONDS);
285 dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(SLEEP_SECONDS * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
286 ktrace_end(session, 0);
287 });
288 dispatch_main();
289 }
290