xref: /xnu-11215/tests/task_suspend_stats.c (revision 8d741a5d)
1 /*
2  * Copyright (c) 2023 Apple Inc. All rights reserved.
3  *
4  * @APPLE_OSREFERENCE_LICENSE_HEADER_START@
5  *
6  * This file contains Original Code and/or Modifications of Original Code
7  * as defined in and that are subject to the Apple Public Source License
8  * Version 2.0 (the 'License'). You may not use this file except in
9  * compliance with the License. The rights granted to you under the License
10  * may not be used to create, or enable the creation or redistribution of,
11  * unlawful or unlicensed copies of an Apple operating system, or to
12  * circumvent, violate, or enable the circumvention or violation of, any
13  * terms of an Apple operating system software license agreement.
14  *
15  * Please obtain a copy of the License at
16  * http://www.opensource.apple.com/apsl/ and read it before using this file.
17  *
18  * The Original Code and all software distributed under the License are
19  * distributed on an 'AS IS' basis, WITHOUT WARRANTY OF ANY KIND, EITHER
20  * EXPRESS OR IMPLIED, AND APPLE HEREBY DISCLAIMS ALL SUCH WARRANTIES,
21  * INCLUDING WITHOUT LIMITATION, ANY WARRANTIES OF MERCHANTABILITY,
22  * FITNESS FOR A PARTICULAR PURPOSE, QUIET ENJOYMENT OR NON-INFRINGEMENT.
23  * Please see the License for the specific language governing rights and
24  * limitations under the License.
25  *
26  * @APPLE_OSREFERENCE_LICENSE_HEADER_END@
27  */
28 #include <libproc.h>
29 #include <mach/mach.h>
30 #include <mach/mach_time.h>
31 #include <mach/task.h>
32 #include <mach/task_info.h>
33 #include <mach-o/dyld.h>
34 #include <notify.h>
35 #include <signal.h>
36 #include <stdint.h>
37 #include <strings.h>
38 #include <sys/sysctl.h>
39 #include <sys/types.h>
40 #include <TargetConditionals.h>
41 #include <unistd.h>
42 
43 #include <darwintest.h>
44 #include <darwintest_utils.h>
45 
46 T_GLOBAL_META(
47 	T_META_NAMESPACE("kern.task"),
48 	T_META_RADAR_COMPONENT_NAME("xnu"),
49 	T_META_RADAR_COMPONENT_VERSION("performance"),
50 	T_META_OWNER("jarrad"),
51 	T_META_RUN_CONCURRENTLY(true),
52 	T_META_ASROOT(true),
53 	// rdar://112041307
54 	T_META_REQUIRES_SYSCTL_EQ("kern.hv_vmm_present", 0),
55 	T_META_TAG_VM_NOT_ELIGIBLE);
56 
57 // sleep for 1 sec between suspend/resume
58 static unsigned int sleep_duration = 1;
59 
60 static uint64_t
get_thread_id(void)61 get_thread_id(void)
62 {
63 	kern_return_t kr;
64 	mach_msg_type_number_t count = THREAD_IDENTIFIER_INFO_COUNT;
65 	thread_identifier_info_data_t data;
66 	kr = thread_info(mach_thread_self(), THREAD_IDENTIFIER_INFO, (thread_info_t)&data, &count);
67 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "thread_info");
68 	return data.thread_id;
69 }
70 
71 static void
get_procname(char * dest,size_t size)72 get_procname(char *dest, size_t size)
73 {
74 	int ret;
75 	ret = proc_name(getpid(), dest, (uint32_t)size);
76 	T_QUIET; T_ASSERT_GE(ret, 0, "proc_name");
77 }
78 
79 static void
get_stats(task_t task,task_suspend_stats_t _Nonnull out)80 get_stats(task_t task, task_suspend_stats_t _Nonnull out)
81 {
82 	kern_return_t kr;
83 	mach_msg_type_number_t count = TASK_SUSPEND_STATS_INFO_COUNT;
84 
85 	kr = task_info(task, TASK_SUSPEND_STATS_INFO, (task_info_t)out, &count);
86 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_info(TASK_SUSPEND_STATS_INFO)");
87 }
88 
89 static void
get_sources(task_t task,task_suspend_source_t _Nonnull out)90 get_sources(task_t task, task_suspend_source_t _Nonnull out)
91 {
92 	kern_return_t kr;
93 	mach_msg_type_number_t count = TASK_SUSPEND_SOURCES_INFO_COUNT;
94 
95 	kr = task_info(task, TASK_SUSPEND_SOURCES_INFO, (task_info_t)out, &count);
96 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_info(TASK_SUSPEND_SOURCES_INFO)");
97 }
98 
99 static void
log_stats(mach_timebase_info_data_t timebase,uint64_t now,const char * name,task_suspend_stats_t _Nonnull stats)100 log_stats(mach_timebase_info_data_t timebase, uint64_t now, const char *name, task_suspend_stats_t _Nonnull stats)
101 {
102 	uint64_t last_start_ago = (now - stats->tss_last_start) * timebase.numer / timebase.denom;
103 	uint64_t last_end_ago = (now - stats->tss_last_end) * timebase.numer / timebase.denom;
104 	uint64_t last_duration = (stats->tss_last_end - stats->tss_last_start) * timebase.numer / timebase.denom;
105 	uint64_t total_duration = (stats->tss_duration) * timebase.numer / timebase.denom;
106 
107 	uint64_t nanosec = 1000000000llu;
108 	T_LOG("%s: %8lld suspensions, %10lld.%09lld total secs, last start %lld.%09lld secs ago, last end %lld.%09lld secs ago, %lld.%09lld secs long",
109 	    name, stats->tss_count,
110 	    total_duration / nanosec, total_duration % nanosec,
111 	    last_start_ago / nanosec, last_start_ago % nanosec,
112 	    last_end_ago / nanosec, last_end_ago % nanosec,
113 	    last_duration / nanosec, last_duration % nanosec);
114 }
115 
116 static void
log_sources(mach_timebase_info_data_t timebase,uint64_t now,const char * name,task_suspend_source_array_t _Nonnull sources)117 log_sources(mach_timebase_info_data_t timebase, uint64_t now, const char *name, task_suspend_source_array_t _Nonnull sources)
118 {
119 	uint64_t nanosec = 1000000000llu;
120 	for (int i = 0; i < TASK_SUSPEND_SOURCES_MAX; i++) {
121 		task_suspend_source_t source = &sources[i];
122 		uint64_t source_ago = (now - source->tss_time) * timebase.numer / timebase.denom;
123 		T_LOG("%s suspender #%d: start %lld.%09lld secs ago, pid %d, tid %llu, procname \"%s\"",
124 		    name, i, source_ago / nanosec, source_ago % nanosec, source->tss_pid, source->tss_tid, source->tss_procname);
125 	}
126 }
127 
128 static void
log_time(mach_timebase_info_data_t timebase,uint64_t now,uint64_t time,const char * name)129 log_time(mach_timebase_info_data_t timebase, uint64_t now, uint64_t time, const char *name)
130 {
131 	uint64_t nanosec = 1000000000llu;
132 	uint64_t time_ago = (now - time) * timebase.numer / timebase.denom;
133 	T_LOG("%s: %lld.%09lld secs ago",
134 	    name, time_ago / nanosec, time_ago % nanosec);
135 }
136 
137 static void
verify_source(task_suspend_source_t source)138 verify_source(task_suspend_source_t source)
139 {
140 	char procname[65];
141 	get_procname(procname, sizeof(procname));
142 
143 	T_EXPECT_EQ(source->tss_pid, getpid(), "suspend source should mark suspender as current task");
144 	T_EXPECT_EQ(source->tss_tid, get_thread_id(), "suspend source should mark suspender as current thread");
145 	T_EXPECT_GT(source->tss_time, 0ull, "suspend source should have non-zero time");
146 	T_EXPECT_EQ_STR(source->tss_procname, procname, "suspend source should have procname matching current proc");
147 }
148 
149 static void
verify_stats(mach_timebase_info_data_t timebase,task_suspend_stats_t _Nonnull pre,task_suspend_stats_t _Nonnull post)150 verify_stats(mach_timebase_info_data_t timebase, task_suspend_stats_t _Nonnull pre, task_suspend_stats_t _Nonnull post)
151 {
152 	uint64_t now = mach_absolute_time();
153 
154 	log_stats(timebase, now, "  pre", pre);
155 	log_stats(timebase, now, " post", post);
156 
157 	int64_t delta_suspensions = (int64_t)(post->tss_count - pre->tss_count);
158 	int64_t delta_duration = (int64_t)(post->tss_duration - pre->tss_duration) * (int64_t)timebase.numer / (int64_t)timebase.denom;
159 	int64_t delta_nsec = delta_duration % 1000000000ll;
160 	if (delta_nsec < 0) {
161 		delta_nsec += 1000000000ll;
162 	}
163 	T_LOG("delta: %+8lld suspensions, %+10lld.%09lld total nsecs", delta_suspensions, delta_duration / 1000000000ll, delta_nsec);
164 
165 	T_EXPECT_LT(pre->tss_count, post->tss_count, "suspension count should increase when task is suspended");
166 	T_EXPECT_LT(pre->tss_duration, post->tss_duration, "suspension duration should increase when task is suspended");
167 	T_EXPECT_LT(post->tss_last_start, post->tss_last_end, "post: suspension should take time");
168 }
169 
170 static int
spawn_helper(char * helper)171 spawn_helper(char *helper)
172 {
173 	char **launch_tool_args;
174 	char testpath[PATH_MAX];
175 	uint32_t testpath_buf_size;
176 	int ret;
177 	pid_t child_pid;
178 
179 	testpath_buf_size = sizeof(testpath);
180 	ret = _NSGetExecutablePath(testpath, &testpath_buf_size);
181 	T_QUIET; T_ASSERT_POSIX_ZERO(ret, "_NSGetExecutablePath");
182 	T_LOG("Executable path: %s", testpath);
183 	launch_tool_args = (char *[]){
184 		testpath,
185 		"-n",
186 		helper,
187 		NULL
188 	};
189 
190 	// Spawn the child process
191 	ret = dt_launch_tool(&child_pid, launch_tool_args, false, NULL, NULL);
192 	if (ret != 0) {
193 		T_LOG("dt_launch tool returned %d with error code %d", ret, errno);
194 	}
195 	T_QUIET; T_ASSERT_POSIX_SUCCESS(child_pid, "dt_launch_tool");
196 
197 	return child_pid;
198 }
199 
200 static void
wakeup_helper(pid_t pid)201 wakeup_helper(pid_t pid)
202 {
203 	int ret = kill(pid, SIGKILL);
204 	T_QUIET; T_ASSERT_POSIX_ZERO(ret, "kill()");
205 }
206 
207 T_HELPER_DECL(wait_for_finished,
208     "spin waiting for signal",
209     T_META_CHECK_LEAKS(false))
210 {
211 	pause();
212 	exit(0);
213 }
214 
215 T_DECL(get_suspend_stats,
216     "test that task suspension statistics can be read out")
217 {
218 	mach_timebase_info_data_t timebase = {0, 0};
219 	mach_timebase_info(&timebase);
220 
221 	struct task_suspend_stats_s stats;
222 
223 	get_stats(current_task(), &stats);
224 	log_stats(timebase, mach_absolute_time(), "stats", &stats);
225 }
226 
227 T_DECL(get_suspend_sources,
228     "test that task suspension debug info can be read out")
229 {
230 	mach_timebase_info_data_t timebase = {0, 0};
231 	mach_timebase_info(&timebase);
232 
233 	task_suspend_source_array_t sources;
234 
235 	get_sources(current_task(), sources);
236 	log_sources(timebase, mach_absolute_time(), "sources", sources);
237 }
238 
239 T_DECL(suspend_stats_update_on_pidsuspend,
240     "test that task suspension info are updated on pidsuspend")
241 {
242 	kern_return_t kr;
243 	pid_t child_pid;
244 	task_t child_task;
245 	int rc;
246 	struct task_suspend_stats_s pre, post;
247 	task_suspend_source_array_t sources;
248 	mach_timebase_info_data_t timebase = {0, 0};
249 
250 	mach_timebase_info(&timebase);
251 
252 	child_pid = spawn_helper("wait_for_finished");
253 	kr = task_for_pid(mach_task_self(), child_pid, &child_task);
254 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_for_pid(%d)", child_pid);
255 
256 	get_stats(child_task, &pre);
257 
258 	T_LOG("Suspending helper...");
259 	rc = pid_suspend(child_pid);
260 	T_QUIET; T_ASSERT_POSIX_SUCCESS(rc, "pid_suspend");
261 
262 	T_LOG("Sleeping %d sec...", sleep_duration);
263 	sleep(sleep_duration);
264 
265 	T_LOG("Resuming helper...");
266 	rc = pid_resume(child_pid);
267 	T_QUIET; T_ASSERT_POSIX_SUCCESS(rc, "pid_resume");
268 
269 	get_stats(child_task, &post);
270 	verify_stats(timebase, &pre, &post);
271 	get_sources(child_task, sources);
272 	log_sources(timebase, mach_absolute_time(), "sources", sources);
273 	verify_source(&sources[0]);
274 
275 	wakeup_helper(child_pid);
276 	mach_port_deallocate(mach_task_self(), child_task);
277 }
278 
279 T_DECL(suspend_stats_update_on_task_suspend,
280     "test that task suspension info are updated on task_suspend")
281 {
282 	kern_return_t kr;
283 	pid_t child_pid;
284 	task_t child_task;
285 	struct task_suspend_stats_s pre, post;
286 	task_suspend_source_array_t sources;
287 	mach_timebase_info_data_t timebase = {0, 0};
288 
289 	mach_timebase_info(&timebase);
290 
291 	child_pid = spawn_helper("wait_for_finished");
292 	kr = task_for_pid(mach_task_self(), child_pid, &child_task);
293 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_for_pid(%d)", child_pid);
294 
295 	get_stats(child_task, &pre);
296 
297 	T_LOG("Suspending helper...");
298 	kr = task_suspend(child_task);
299 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_suspend");
300 
301 	T_LOG("Sleeping %d sec...", sleep_duration);
302 	sleep(sleep_duration);
303 
304 	T_LOG("Resuming helper...");
305 	kr = task_resume(child_task);
306 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_resume");
307 
308 	get_stats(child_task, &post);
309 	verify_stats(timebase, &pre, &post);
310 	get_sources(child_task, sources);
311 	log_sources(timebase, mach_absolute_time(), "sources", sources);
312 	verify_source(&sources[0]);
313 
314 	wakeup_helper(child_pid);
315 	mach_port_deallocate(mach_task_self(), child_task);
316 }
317 
318 T_DECL(suspend_stats_update_on_forkcorpse,
319     "test that task suspension info are updated on fork corpse")
320 {
321 	kern_return_t kr;
322 	pid_t child_pid;
323 	task_t child_task;
324 	mach_port_t cp;
325 	struct task_suspend_stats_s pre, post;
326 	task_suspend_source_array_t sources;
327 	mach_timebase_info_data_t timebase = {0, 0};
328 
329 	mach_timebase_info(&timebase);
330 
331 	child_pid = spawn_helper("wait_for_finished");
332 	kr = task_for_pid(mach_task_self(), child_pid, &child_task);
333 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_for_pid(%d)", child_pid);
334 
335 	get_stats(child_task, &pre);
336 
337 	T_LOG("Generating corpse of helper...");
338 	kr = task_generate_corpse(child_task, &cp);
339 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_generate_corpse");
340 
341 	get_stats(child_task, &post);
342 	verify_stats(timebase, &pre, &post);
343 	get_sources(child_task, sources);
344 	log_sources(timebase, mach_absolute_time(), "sources", sources);
345 	verify_source(&sources[0]);
346 
347 	kr = mach_port_deallocate(mach_task_self(), cp);
348 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "mach_port_deallocate");
349 
350 	wakeup_helper(child_pid);
351 	kr = mach_port_deallocate(mach_task_self(), child_task);
352 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "mach_port_deallocate");
353 }
354 
355 #define NUM_SUSPEND_RESUME (TASK_SUSPEND_SOURCES_MAX * 2)
356 T_DECL(suspend_source_created_for_every_suspend,
357     "test that suspend sources are created for every suspend call")
358 {
359 	kern_return_t kr;
360 	pid_t child_pid;
361 	task_t child_task;
362 	struct task_suspend_stats_s pre, post;
363 	task_suspend_source_array_t sources;
364 	mach_timebase_info_data_t timebase = {0, 0};
365 	uint64_t first_suspend_time = 0;
366 
367 	mach_timebase_info(&timebase);
368 
369 	child_pid = spawn_helper("wait_for_finished");
370 	kr = task_for_pid(mach_task_self(), child_pid, &child_task);
371 	T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_for_pid(%d)", child_pid);
372 
373 	get_stats(child_task, &pre);
374 
375 	T_LOG("Suspending helper...");
376 
377 	for (int i = 0; i < NUM_SUSPEND_RESUME; i++) {
378 		kr = task_suspend(child_task);
379 		T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_suspend");
380 		if (i == 0) {
381 			first_suspend_time = mach_absolute_time();
382 		}
383 	}
384 
385 	T_LOG("Sleeping %d sec...", sleep_duration);
386 	sleep(sleep_duration);
387 
388 	T_LOG("Resuming helper...");
389 	for (int i = 0; i < NUM_SUSPEND_RESUME; i++) {
390 		kr = task_resume(child_task);
391 		T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "task_resume");
392 	}
393 
394 	uint64_t now = mach_absolute_time();
395 
396 	get_stats(child_task, &post);
397 	verify_stats(timebase, &pre, &post);
398 	get_sources(child_task, sources);
399 	log_sources(timebase, now, "sources", sources);
400 	log_time(timebase, now, first_suspend_time, "first_suspend");
401 
402 	for (int i = 0; i < TASK_SUSPEND_SOURCES_MAX; i++) {
403 		T_LOG("Verifying suspender no. %d", i);
404 		task_suspend_source_t source = &sources[i];
405 		verify_source(source);
406 		T_EXPECT_LT(source->tss_time, post.tss_last_end, "suspend source timestamp should be < last suspension end");
407 		T_EXPECT_GT(source->tss_time, first_suspend_time, "suspend source timestamp should be > first suspend");
408 	}
409 
410 	wakeup_helper(child_pid);
411 	mach_port_deallocate(mach_task_self(), child_task);
412 }
413