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 static void
expect_convert_between_abs_cont(bool abs_to_cont)139 expect_convert_between_abs_cont(bool abs_to_cont)
140 {
141 uint64_t cur_abs_time, cur_cont_time;
142 kern_return_t kr = mach_get_times(&cur_abs_time, &cur_cont_time, NULL);
143 T_QUIET; T_ASSERT_MACH_SUCCESS(kr, "mach_get_times");
144 bool hasnt_slept = cur_abs_time == cur_cont_time;
145 if (hasnt_slept) {
146 T_LOG("system hasn't slept, so continuous and absolute times are equal");
147 T_LOG("this test cannot ensure time conversions are done properly");
148 } else {
149 T_LOG("system has slept, times differ by %llu",
150 cur_cont_time - cur_abs_time);
151 }
152
153 start_controlling_ktrace();
154 ktrace_session_t ktsess = ktrace_session_create();
155 ktrace_set_collection_interval(ktsess, 100);
156 if (abs_to_cont) {
157 ktrace_set_continuous_timestamps(ktsess, true);
158 }
159
160 __block bool found_abs_event = false;
161 __block bool found_cont_event = false;
162 const uint32_t abs_eventid = KDBG_EVENTID(DBG_BSD, DBG_BSD_KDEBUG_TEST, 0);
163 ktrace_events_single(ktsess, abs_eventid, ^(struct trace_point *tp) {
164 found_abs_event = true;
165 uint64_t arg_timestamp = (tp->arg1 & UINT32_MAX) | (tp->arg2 << 32);
166 if (abs_to_cont) {
167 if (hasnt_slept) {
168 T_MAYFAIL;
169 }
170 T_EXPECT_NE(tp->timestamp, arg_timestamp,
171 "timestamp from absolute time IOP should be converted");
172 } else {
173 T_EXPECT_EQ(tp->timestamp, arg_timestamp,
174 "timestamp from absolute time IOP should not be converted");
175 }
176 if (found_cont_event && found_abs_event) {
177 ktrace_end(ktsess, 1);
178 }
179 });
180
181 const uint32_t cont_eventid = KDBG_EVENTID(DBG_BSD, DBG_BSD_KDEBUG_TEST, 1);
182 ktrace_events_single(ktsess, cont_eventid, ^(struct trace_point *tp) {
183 found_cont_event = true;
184 uint64_t arg_timestamp = (tp->arg1 & UINT32_MAX) | (tp->arg2 << 32);
185 if (abs_to_cont) {
186 T_EXPECT_EQ(tp->timestamp, arg_timestamp,
187 "timestamp from continuous time coprocessor should not be "
188 "converted");
189 } else {
190 if (hasnt_slept) {
191 T_MAYFAIL;
192 }
193 T_EXPECT_NE(tp->timestamp, arg_timestamp,
194 "timestamp from continuous time coprocessor should be "
195 "converted");
196 }
197 if (found_cont_event && found_abs_event) {
198 ktrace_end(ktsess, 1);
199 }
200 });
201
202 ktrace_set_completion_handler(ktsess, ^{
203 T_EXPECT_TRUE(found_abs_event, "absolute time event present");
204 T_EXPECT_TRUE(found_cont_event, "continuous time event present");
205 ktrace_session_destroy(ktsess);
206 T_END;
207 });
208
209 assert_kdebug_test(KDTEST_SETUP_IOP, "setup sync flush IOP");
210 assert_kdebug_test(KDTEST_SETUP_COPROCESSOR, "setup coprocessor");
211
212 T_ASSERT_POSIX_ZERO(ktrace_start(ktsess, dispatch_get_main_queue()),
213 "start tracing");
214 assert_kdebug_test(KDTEST_ABSOLUTE_TIMESTAMP, "induce absolute times");
215 assert_kdebug_test(KDTEST_CONTINUOUS_TIMESTAMP, "induce continuous times");
216 T_QUIET;
217 T_EXPECT_EQ(kdebug_using_continuous_time(), abs_to_cont,
218 "should be using continuous time");
219
220 dispatch_after(dispatch_time(DISPATCH_TIME_NOW, 5 * NSEC_PER_SEC),
221 dispatch_get_main_queue(), ^{
222 T_LOG("ending tracing after timeout");
223 ktrace_end(ktsess, 0);
224 });
225 }
226
227 T_DECL(absolute_to_continuous_iop,
228 "expect IOPs issuing absolute times show up as continuous in the stream")
229 {
230 expect_convert_between_abs_cont(true);
231 dispatch_main();
232 }
233
234 T_DECL(continuous_to_absolute_coproc,
235 "expect IOPs issuing absolute times show up as continuous in the stream")
236 {
237 expect_convert_between_abs_cont(false);
238 dispatch_main();
239 }
240