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