1 // Copyright (c) 2020 Apple Inc. All rights reserved.
2
3 #include <darwintest.h>
4 #include <darwintest_utils.h>
5 #include <dispatch/dispatch.h>
6 #include <inttypes.h>
7 #include <ktrace/session.h>
8 #include <ktrace/private.h>
9 #include <kperf/kperf.h>
10 #include <stdlib.h>
11 #include <sys/kdebug.h>
12 #include <sys/kdebug_private.h>
13 #include <sys/sysctl.h>
14 #include <stdint.h>
15
16 #include "ktrace_helpers.h"
17 #include "test_utils.h"
18 #include "ktrace_meta.h"
19
20 static const uint32_t frame_eventid = KDBG_EVENTID(DBG_BSD,
21 DBG_BSD_KDEBUG_TEST, 1);
22
23 static ktrace_session_t
future_events_session(void)24 future_events_session(void)
25 {
26 ktrace_session_t ktsess = ktrace_session_create();
27 T_QUIET; T_WITH_ERRNO; T_ASSERT_NOTNULL(ktsess, "failed to create session");
28
29 ktrace_events_single(ktsess, KDBG_EVENTID(DBG_BSD, DBG_BSD_KDEBUG_TEST, 0),
30 ^(struct trace_point *tp __unused) {
31 T_FAIL("saw future test event from IOP");
32 });
33 ktrace_events_single(ktsess, frame_eventid, ^(struct trace_point *tp) {
34 if (tp->debugid & DBG_FUNC_START) {
35 T_LOG("saw start event");
36 } else {
37 T_LOG("saw event traced after trying to trace future event, ending");
38 ktrace_end(ktsess, 1);
39 }
40 });
41
42 ktrace_set_collection_interval(ktsess, 100);
43 return ktsess;
44 }
45
46 T_DECL(future_iop_events,
47 "make sure IOPs cannot trace events in the future while live tracing",
48 T_META_TAG_VM_NOT_PREFERRED)
49 {
50 start_controlling_ktrace();
51 ktrace_session_t ktsess = future_events_session();
52 ktrace_set_completion_handler(ktsess, ^{
53 ktrace_session_destroy(ktsess);
54 T_END;
55 });
56
57 T_ASSERT_POSIX_ZERO(ktrace_start(ktsess, dispatch_get_main_queue()),
58 "start tracing");
59 kdebug_trace(frame_eventid | DBG_FUNC_START, 0, 0, 0, 0);
60 assert_kdebug_test(KDTEST_FUTURE_TIMESTAMP, "induce future times");
61 kdebug_trace(frame_eventid | DBG_FUNC_END, 0, 0, 0, 0);
62
63 dispatch_after(dispatch_time(DISPATCH_TIME_NOW, 5 * NSEC_PER_SEC),
64 dispatch_get_main_queue(), ^{
65 T_FAIL("ending tracing after timeout");
66 ktrace_end(ktsess, 0);
67 });
68
69 dispatch_main();
70 }
71
72 T_DECL(future_iop_events_disabled,
73 "make sure IOPs cannot trace events in the future after disabling tracing",
74 T_META_TAG_VM_NOT_PREFERRED)
75 {
76 start_controlling_ktrace();
77 ktrace_session_t ktsess = future_events_session();
78 T_ASSERT_POSIX_ZERO(ktrace_configure(ktsess), "configure tracing");
79
80 kdebug_trace(frame_eventid | DBG_FUNC_START, 0, 0, 0, 0);
81 assert_kdebug_test(KDTEST_FUTURE_TIMESTAMP, "induce future times");
82 kdebug_trace(frame_eventid | DBG_FUNC_END, 0, 0, 0, 0);
83
84 T_ASSERT_POSIX_ZERO(ktrace_disable_configured(ktsess),
85 "disable tracing");
86 ktrace_session_destroy(ktsess);
87
88 ktsess = future_events_session();
89 T_QUIET;
90 T_ASSERT_POSIX_ZERO(ktrace_set_use_existing(ktsess), "use existing trace");
91 ktrace_set_completion_handler(ktsess, ^{
92 ktrace_session_destroy(ktsess);
93 T_END;
94 });
95
96 T_ASSERT_POSIX_ZERO(ktrace_start(ktsess, dispatch_get_main_queue()),
97 "start tracing existing session");
98
99 dispatch_main();
100 }
101
102 T_DECL(iop_events_disable,
103 "make sure IOP events are flushed before disabling trace",
104 T_META_TAG_VM_PREFERRED)
105 {
106 start_controlling_ktrace();
107 ktrace_session_t ktsess = future_events_session();
108
109 assert_kdebug_test(KDTEST_SETUP_IOP, "setup sync flush IOP");
110 T_ASSERT_POSIX_ZERO(ktrace_configure(ktsess), "configure tracing");
111
112 kdebug_trace(frame_eventid | DBG_FUNC_START, 0, 0, 0, 0);
113
114 T_ASSERT_POSIX_ZERO(ktrace_disable_configured(ktsess),
115 "disable tracing");
116 ktrace_session_destroy(ktsess);
117
118 ktsess = ktrace_session_create();
119 T_QUIET; T_WITH_ERRNO;
120 T_ASSERT_NOTNULL(ktsess, "create session");
121
122 ktrace_events_single(ktsess,
123 KDBG_EVENTID(DBG_BSD, DBG_BSD_KDEBUG_TEST, 0xff),
124 ^(struct trace_point *tp __unused) {
125 T_PASS("saw IOP event from sync flush");
126 });
127
128 T_QUIET;
129 T_ASSERT_POSIX_ZERO(ktrace_set_use_existing(ktsess), "use existing trace");
130 ktrace_set_completion_handler(ktsess, ^{
131 ktrace_session_destroy(ktsess);
132 T_END;
133 });
134
135 T_ASSERT_POSIX_ZERO(ktrace_start(ktsess, dispatch_get_main_queue()),
136 "start tracing existing session");
137
138 dispatch_main();
139 }
140
141 T_DECL(past_coproc_events,
142 "make sure past events from coprocessors log a TRACE_PAST_EVENTS event",
143 T_META_TAG_VM_PREFERRED)
144 {
145 start_controlling_ktrace();
146 ktrace_session_t ktsess = future_events_session();
147 T_ASSERT_POSIX_ZERO(ktrace_configure(ktsess), "configure tracing");
148
149 kdebug_trace(frame_eventid | DBG_FUNC_START, 0, 0, 0, 0);
150 assert_kdebug_test(KDTEST_PAST_EVENT, "induce past events");
151 kdebug_trace(frame_eventid | DBG_FUNC_END, 0, 0, 0, 0);
152
153 T_ASSERT_POSIX_ZERO(ktrace_disable_configured(ktsess), "disable tracing");
154 ktrace_session_destroy(ktsess);
155
156 ktsess = future_events_session();
157 T_QUIET;
158 T_ASSERT_POSIX_ZERO(ktrace_set_use_existing(ktsess), "use existing trace");
159 __block bool saw_past_event = false;
160 ktrace_events_single(ktsess, TRACE_PAST_EVENTS,
161 ^(__unused ktrace_event_t event) {
162 saw_past_event = true;
163 });
164 ktrace_set_completion_handler(ktsess, ^{
165 ktrace_session_destroy(ktsess);
166 T_EXPECT_TRUE(saw_past_event, "saw past event");
167 T_END;
168 });
169
170 T_ASSERT_POSIX_ZERO(ktrace_start(ktsess, dispatch_get_main_queue()),
171 "start tracing existing session");
172
173 dispatch_main();
174 }
175
176 static void
expect_convert_between_abs_cont(bool abs_to_cont)177 expect_convert_between_abs_cont(bool abs_to_cont)
178 {
179 uint64_t cur_abs_time, cur_cont_time;
180 kern_return_t kr = mach_get_times(&cur_abs_time, &cur_cont_time, NULL);
181 T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "mach_get_times");
182 bool hasnt_slept = cur_abs_time == cur_cont_time;
183 if (hasnt_slept) {
184 T_LOG("system hasn't slept, so continuous and absolute times are equal");
185 T_LOG("this test cannot ensure time conversions are done properly");
186 } else {
187 T_LOG("system has slept, times differ by %llu",
188 cur_cont_time - cur_abs_time);
189 }
190
191 start_controlling_ktrace();
192 ktrace_session_t ktsess = ktrace_session_create();
193 ktrace_set_collection_interval(ktsess, 100);
194 if (abs_to_cont) {
195 ktrace_set_continuous_timestamps(ktsess, true);
196 }
197
198 __block bool found_abs_event = false;
199 __block bool found_cont_event = false;
200 const uint32_t abs_eventid = KDBG_EVENTID(DBG_BSD, DBG_BSD_KDEBUG_TEST, 0);
201 ktrace_events_single(ktsess, abs_eventid, ^(struct trace_point *tp) {
202 found_abs_event = true;
203 uint64_t arg_timestamp = (tp->arg1 & UINT32_MAX) | (tp->arg2 << 32);
204 if (abs_to_cont) {
205 if (hasnt_slept) {
206 T_MAYFAIL;
207 }
208 T_EXPECT_NE(tp->timestamp, arg_timestamp,
209 "timestamp from absolute time IOP should be converted");
210 } else {
211 T_EXPECT_EQ(tp->timestamp, arg_timestamp,
212 "timestamp from absolute time IOP should not be converted");
213 }
214 if (found_cont_event && found_abs_event) {
215 ktrace_end(ktsess, 1);
216 }
217 });
218
219 const uint32_t cont_eventid = KDBG_EVENTID(DBG_BSD, DBG_BSD_KDEBUG_TEST, 1);
220 ktrace_events_single(ktsess, cont_eventid, ^(struct trace_point *tp) {
221 found_cont_event = true;
222 uint64_t arg_timestamp = (tp->arg1 & UINT32_MAX) | (tp->arg2 << 32);
223 if (abs_to_cont) {
224 T_EXPECT_EQ(tp->timestamp, arg_timestamp,
225 "timestamp from continuous time coprocessor should not be "
226 "converted");
227 } else {
228 if (hasnt_slept) {
229 T_MAYFAIL;
230 }
231 T_EXPECT_NE(tp->timestamp, arg_timestamp,
232 "timestamp from continuous time coprocessor should be "
233 "converted");
234 }
235 if (found_cont_event && found_abs_event) {
236 ktrace_end(ktsess, 1);
237 }
238 });
239
240 ktrace_set_completion_handler(ktsess, ^{
241 T_EXPECT_TRUE(found_abs_event, "absolute time event present");
242 T_EXPECT_TRUE(found_cont_event, "continuous time event present");
243 ktrace_session_destroy(ktsess);
244 T_END;
245 });
246
247 assert_kdebug_test(KDTEST_SETUP_IOP, "setup sync flush IOP");
248 assert_kdebug_test(KDTEST_SETUP_COPROCESSOR, "setup coprocessor");
249
250 T_ASSERT_POSIX_ZERO(ktrace_start(ktsess, dispatch_get_main_queue()),
251 "start tracing");
252 assert_kdebug_test(KDTEST_ABSOLUTE_TIMESTAMP, "induce absolute times");
253 assert_kdebug_test(KDTEST_CONTINUOUS_TIMESTAMP, "induce continuous times");
254 T_QUIET;
255 T_EXPECT_EQ(kdebug_using_continuous_time(), abs_to_cont,
256 "should be using continuous time");
257
258 dispatch_after(dispatch_time(DISPATCH_TIME_NOW, 5 * NSEC_PER_SEC),
259 dispatch_get_main_queue(), ^{
260 T_LOG("ending tracing after timeout");
261 ktrace_end(ktsess, 0);
262 });
263 }
264
265 T_DECL(absolute_to_continuous_iop,
266 "expect IOPs issuing absolute times show up as continuous in the stream",
267 T_META_TAG_VM_PREFERRED)
268 {
269 expect_convert_between_abs_cont(true);
270 dispatch_main();
271 }
272
273 T_DECL(continuous_to_absolute_coproc,
274 "expect IOPs issuing absolute times show up as continuous in the stream",
275 T_META_TAG_VM_PREFERRED)
276 {
277 expect_convert_between_abs_cont(false);
278 dispatch_main();
279 }
280