[apple/xnu.git] / tools / trace / kqtrace.lua

#!/usr/local/bin/luatrace -s

trace_eventname = function(codename, callback)
	local debugid = trace.debugid(codename)
	if debugid ~= 0 then
		trace.single(debugid,callback)
	else
		printf("WARNING: Cannot locate debugid for '%s'\n", codename)
	end
end

initial_timestamp = 0

function event_prefix_string(buf, workq)
	if initial_timestamp == 0 then
		initial_timestamp = buf.timestamp
	end
	local secs = trace.convert_timestamp_to_nanoseconds(buf.timestamp - initial_timestamp) / 1000000000

	local type
	if trace.debugid_is_start(buf.debugid) then
		type = "→"
	elseif trace.debugid_is_end(buf.debugid) then
		type = "←"
	else
		type = "↔"
	end

	proc = buf.command

	local prefix = string.format("%s %6.9f %-17s [%05d.%06x] %-28s\t",
		type, secs, proc, buf.pid, buf.threadid, buf.debugname)
	if not workq then
		prefix = prefix .. string.format(" 0x%16x", buf.arg1)
	end

	return prefix
end

function qos_string(qos)
	if qos == 0 then
		return "--"
	elseif qos == 1 then
		return "MT"
	elseif qos == 2 then
		return "BG"
	elseif qos == 3 then
		return "UT"
	elseif qos == 4 then
		return "DF"
	elseif qos == 5 then
		return "IN"
	elseif qos == 6 then
		return "UI"
	elseif qos == 7 then
		return "MG"
	else
		return string.format("??[0x%x]", qos)
	end
end

function state_string(strings, state)
	local str = ''
	local first = true
	for name, bit in pairs(strings) do
		if (state & bit) == bit then
			if not first then
				str = str .. ' '
			end
			str = str .. name
			first = false
		end
	end
	return str
end

kqrequest_state_strings = {
	['PROCESSING'] = 0x1,
	['THREQUESTED'] = 0x2,
	['WAKEUP'] = 0x4
}

kqueue_state_strings = {
	['SEL'] = 0x001,
	['SLEEP'] = 0x002,
	['PROCWAIT'] = 0x004,
	['KEV32'] = 0x008,
	['KEV64'] = 0x010,
	['KEV_QOS'] = 0x020,
	['WORKQ'] = 0x040,
	['WORKLOOP'] = 0x080,
	['PROCESSING'] = 0x100,
	['DRAIN'] = 0x200,
	['WAKEUP'] = 0x400,
	['DYNAMIC'] = 0x800,
}

knote_state_strings = {
	['ACTIVE'] = 0x0001,
	['QUEUED'] = 0x0002,
	['DISABLED'] = 0x0004,
	['DROPPING'] = 0x0008,
	['USEWAIT'] = 0x0010,
	['ATTACHING'] = 0x0020,
	['STAYACTIVE'] = 0x0040,
	['DEFERDELETE'] = 0x0080,
	['ATTACHED'] = 0x0100,
	['DISPATCH'] = 0x0200,
	['UDATA_SPECIFIC'] = 0x0400,
	['SUPPRESSED'] = 0x0800,
	['STOLENDROP'] = 0x1000,
	['REQVANISH'] = 0x2000,
	['VANISHED'] = 0x4000,
}
knote_state_strings = {
	['ACTIVE'] = 0x0001,
	['QUEUED'] = 0x0002,
	['DISABLED'] = 0x0004,
	['DROPPING'] = 0x0008,
	['USEWAIT'] = 0x0010,
	['ATTACHING'] = 0x0020,
	['STAYACTIVE'] = 0x0040,
	['DEFERDELETE'] = 0x0080,
	['ATTACHED'] = 0x0100,
	['DISPATCH'] = 0x0200,
	['UDATA_SPECIFIC'] = 0x0400,
	['SUPPRESSED'] = 0x0800,
	['STOLENDROP'] = 0x1000,
	['REQVANISH'] = 0x2000,
	['VANISHED'] = 0x4000,
}


kevent_flags_strings = {
	['ADD'] = 0x0001,
	['DELETE'] = 0x0002,
	['ENABLE'] = 0x0004,
	['DISABLE'] = 0x0008,
	['ONESHOT'] = 0x0010,
	['CLEAR'] = 0x0020,
	['RECEIPT'] = 0x0040,
	['DISPATCH'] = 0x0080,
	['UDATA_SPECIFIC'] = 0x0100,
	['VANISHED'] = 0x0200,
	['FLAG0'] = 0x1000,
	['FLAG1'] = 0x2000,
	['EOF'] = 0x8000,
	['ERROR'] = 0x4000,
}

function kevent_filter_string(filt)
	if filt == -1 then
		return 'READ'
	elseif filt == -2 then
		return 'WRITE'
	elseif filt == -3 then
		return 'AIO'
	elseif filt == -4 then
		return 'VNODE'
	elseif filt == -5 then
		return 'PROC'
	elseif filt == -6 then
		return 'SIGNAL'
	elseif filt == -7 then
		return 'TIMER'
	elseif filt == -8 then
		return 'MACHPORT'
	elseif filt == -9 then
		return 'FS'
	elseif filt == -10 then
		return 'USER'
	-- -11 unused
	elseif filt == -12 then
		return 'VM'
	elseif filt == -13 then
		return 'SOCK'
	elseif filt == -14 then
		return 'MEMORYSTATUS'
	elseif filt == 15 then
		return 'KQREAD'
	elseif filt == 16 then
		return 'PIPE_R'
	elseif filt == 17 then
		return 'PIPE_W'
	elseif filt == 18 then
		return 'PTSD'
	elseif filt == 19 then
		return 'SOWRITE'
	elseif filt == 20 then
		return 'SOEXCEPT'
	elseif filt == 21 then
		return 'SPEC'
	elseif filt == 22 then
		return 'BPFREAD'
	elseif filt == 23 then
		return 'NECP_FD'
	elseif filt == 24 then
		return 'SKYWALK_CHANNEL_W'
	elseif filt == 25 then
		return 'SKYWALK_CHANNEL_R'
	elseif filt == 26 then
		return 'FSEVENT'
	elseif filt == 27 then
		return 'VN'
	elseif filt == 28 then
		return 'SKYWALK_CHANNEL_E'
	elseif filt == 29 then
		return 'TTY'
	else
		return string.format('[%d]', filt)
	end
end

-- kqueue lifecycle

function processing_begin(workq)
	return function(buf)
		local prefix = event_prefix_string(buf, workq)
		if trace.debugid_is_start(buf.debugid) then
			local qos
			if workq then
				qos = buf.arg2
			else
				qos = buf.arg3
			end
			printf("%s QoS = %s\n", prefix, qos_string(qos))
		else
			printf("%s request thread = 0x%x, kqrequest state = %s\n", prefix,
					buf.arg1, state_string(kqrequest_state_strings, buf.arg2))
		end
	end
end

trace_eventname("KEVENT_kq_processing_begin", processing_begin(false))
trace_eventname("KEVENT_kqwq_processing_begin", processing_begin(true))
trace_eventname("KEVENT_kqwl_processing_begin", processing_begin(false))

function processing_end(workq)
	return function(buf)
		local qos
		if workq then
			qos = buf.arg2
		else
			qos = buf.arg3
		end
		printf("%s QoS = %s\n", event_prefix_string(buf, workq), qos_string(qos))
	end
end

trace_eventname("KEVENT_kq_processing_end", processing_end(false))
trace_eventname("KEVENT_kqwq_processing_end", processing_end(true))
trace_eventname("KEVENT_kqwl_processing_end", processing_end(false))

trace_eventname("KEVENT_kqwq_bind", function(buf)
	printf("%s thread = 0x%x, QoS = %s, kqrequest state = %s\n",
			event_prefix_string(buf, true), buf.arg1, qos_string(buf.arg3),
			state_string(kqrequest_state_strings, buf.arg4))
end)

trace_eventname("KEVENT_kqwq_unbind", function(buf)
	printf("%s thread = 0x%x, QoS = %s\n", event_prefix_string(buf, true),
			buf.arg1, qos_string(buf.arg3))
end)

trace_eventname("KEVENT_kqwl_bind", function(buf)
	qos = buf.arg3 & 0xff
	duplicate = buf.arg3 & (1 << 8)
	kqr_override_qos_delta = buf.arg4 >> 8
	kqr_state = buf.arg4 & 0xff

	printf("%s thread = 0x%x, QoS = %s, override QoS delta = %d, kqrequest state = %s%s\n",
			event_prefix_string(buf, false), buf.arg2, qos_string(qos),
			kqr_override_qos_delta,
			state_string(kqrequest_state_strings, kqr_state),
			duplicate ? ", duplicate" : "")
end)

trace_eventname("KEVENT_kqwl_unbind", function(buf)
	flags = buf.arg3
	qos = buf.arg4

	printf("%s thread = 0x%x, QoS = %s, flags = 0x%x\n", event_prefix_string(buf, false),
			buf.arg2, qos_string(qos), flags)
end)

function thread_request(workq)
	return function(buf)
		printf("%s QoS = %s, kqrequest state = %s, override QoS delta = %d\n",
				event_prefix_string(buf, workq), qos_string(buf.arg2),
				state_string(kqrequest_state_strings, buf.arg3), buf.arg3 >> 8)
	end
end

function thread_adjust(buf)
	tid = buf.arg2
	kqr_qos = buf.arg3 >> 8
	new_qos = buf.arg3 & 0xff
	kqr_qos_override = buf.arg4 >> 8
	kqr_state = buf.arg4 & 0xff

	printf("%s thread = 0x%x, old/new QoS = %s/%s, old/new override QoS delta = %d/%d, kqrequest state = %s\n",
			event_prefix_string(buf, false),
			tid,
			qos_string(kqr_qos),
			qos_string(new_qos),
			kqr_qos_override,
			new_qos - kqr_qos,
			state_string(kqrequest_state_strings, kqr_state))
end

trace_eventname("KEVENT_kqwq_thread_request", thread_request(true))
trace_eventname("KEVENT_kqwl_thread_request", thread_request(false))
trace_eventname("KEVENT_kqwl_thread_adjust", thread_adjust)

function kevent_register(workq)
	return function(buf)
		printf("%s kevent udata = 0x%x, kevent filter = %s, kevent flags = %s\n",
				event_prefix_string(buf, workq), buf.arg2,
				kevent_filter_string(buf.arg4),
				state_string(kevent_flags_strings, buf.arg3))
	end
end

trace_eventname("KEVENT_kq_register", kevent_register(false))
trace_eventname("KEVENT_kqwq_register", kevent_register(true))
trace_eventname("KEVENT_kqwl_register", kevent_register(false))

function kevent_process(workq)
	return function(buf)
		printf("%s kevent ident = 0x%x, udata = 0x%x, kevent filter = %s, knote status = %s\n",
				event_prefix_string(buf, workq), buf.arg3 >> 32, buf.arg2,
				kevent_filter_string(buf.arg4),
				state_string(knote_state_strings, buf.arg3 & 0xffffffff))
	end
end

trace_eventname("KEVENT_kq_process", kevent_process(false))
trace_eventname("KEVENT_kqwq_process", kevent_process(true))
trace_eventname("KEVENT_kqwl_process", kevent_process(false))
Commit	Line	Data
5ba3f43e A	1	#!/usr/local/bin/luatrace -s
	2
	3	trace_eventname = function(codename, callback)
	4	local debugid = trace.debugid(codename)
	5	if debugid ~= 0 then
	6	trace.single(debugid,callback)
	7	else
	8	printf("WARNING: Cannot locate debugid for '%s'\n", codename)
	9	end
	10	end
	11
	12	initial_timestamp = 0
	13
	14	function event_prefix_string(buf, workq)
	15	if initial_timestamp == 0 then
	16	initial_timestamp = buf.timestamp
	17	end
	18	local secs = trace.convert_timestamp_to_nanoseconds(buf.timestamp - initial_timestamp) / 1000000000
	19
	20	local type
	21	if trace.debugid_is_start(buf.debugid) then
	22	type = "→"
	23	elseif trace.debugid_is_end(buf.debugid) then
	24	type = "←"
	25	else
	26	type = "↔"
	27	end
	28
	29	proc = buf.command
	30
	31	local prefix = string.format("%s %6.9f %-17s [%05d.%06x] %-28s\t",
	32	type, secs, proc, buf.pid, buf.threadid, buf.debugname)
	33	if not workq then
	34	prefix = prefix .. string.format(" 0x%16x", buf.arg1)
	35	end
	36
	37	return prefix
	38	end
	39
	40	function qos_string(qos)
	41	if qos == 0 then
	42	return "--"
	43	elseif qos == 1 then
	44	return "MT"
	45	elseif qos == 2 then
	46	return "BG"
	47	elseif qos == 3 then
	48	return "UT"
	49	elseif qos == 4 then
	50	return "DF"
	51	elseif qos == 5 then
	52	return "IN"
	53	elseif qos == 6 then
	54	return "UI"
	55	elseif qos == 7 then
	56	return "MG"
	57	else
	58	return string.format("??[0x%x]", qos)
	59	end
	60	end
	61
	62	function state_string(strings, state)
	63	local str = ''
	64	local first = true
65	for name, bit in pairs(strings) do
66	if (state & bit) == bit then
67	if not first then
68	str = str .. ' '
69	end
70	str = str .. name
71	first = false
72	end
73	end
74	return str
75	end
76
77	kqrequest_state_strings = {
78	['PROCESSING'] = 0x1,
79	['THREQUESTED'] = 0x2,
80	['WAKEUP'] = 0x4
81	}
82
83	kqueue_state_strings = {
84	['SEL'] = 0x001,
85	['SLEEP'] = 0x002,
86	['PROCWAIT'] = 0x004,
87	['KEV32'] = 0x008,
88	['KEV64'] = 0x010,
89	['KEV_QOS'] = 0x020,
90	['WORKQ'] = 0x040,
91	['WORKLOOP'] = 0x080,
92	['PROCESSING'] = 0x100,
93	['DRAIN'] = 0x200,
94	['WAKEUP'] = 0x400,
95	['DYNAMIC'] = 0x800,
96	}
97
98	knote_state_strings = {
99	['ACTIVE'] = 0x0001,
100	['QUEUED'] = 0x0002,
101	['DISABLED'] = 0x0004,
102	['DROPPING'] = 0x0008,
103	['USEWAIT'] = 0x0010,
104	['ATTACHING'] = 0x0020,
105	['STAYACTIVE'] = 0x0040,
106	['DEFERDELETE'] = 0x0080,
107	['ATTACHED'] = 0x0100,
108	['DISPATCH'] = 0x0200,
109	['UDATA_SPECIFIC'] = 0x0400,
110	['SUPPRESSED'] = 0x0800,
111	['STOLENDROP'] = 0x1000,
112	['REQVANISH'] = 0x2000,
113	['VANISHED'] = 0x4000,
114	}
115	knote_state_strings = {
116	['ACTIVE'] = 0x0001,
117	['QUEUED'] = 0x0002,
118	['DISABLED'] = 0x0004,
119	['DROPPING'] = 0x0008,
120	['USEWAIT'] = 0x0010,
121	['ATTACHING'] = 0x0020,
122	['STAYACTIVE'] = 0x0040,
123	['DEFERDELETE'] = 0x0080,
124	['ATTACHED'] = 0x0100,
125	['DISPATCH'] = 0x0200,
126	['UDATA_SPECIFIC'] = 0x0400,
127	['SUPPRESSED'] = 0x0800,
128	['STOLENDROP'] = 0x1000,
129	['REQVANISH'] = 0x2000,
130	['VANISHED'] = 0x4000,
131	}
132
133
134	kevent_flags_strings = {
135	['ADD'] = 0x0001,
136	['DELETE'] = 0x0002,
137	['ENABLE'] = 0x0004,
138	['DISABLE'] = 0x0008,
139	['ONESHOT'] = 0x0010,
140	['CLEAR'] = 0x0020,
141	['RECEIPT'] = 0x0040,
142	['DISPATCH'] = 0x0080,
143	['UDATA_SPECIFIC'] = 0x0100,
144	['VANISHED'] = 0x0200,
145	['FLAG0'] = 0x1000,
146	['FLAG1'] = 0x2000,
147	['EOF'] = 0x8000,
148	['ERROR'] = 0x4000,
149	}
150
151	function kevent_filter_string(filt)
152	if filt == -1 then
153	return 'READ'
154	elseif filt == -2 then
155	return 'WRITE'
156	elseif filt == -3 then
157	return 'AIO'
158	elseif filt == -4 then
159	return 'VNODE'
160	elseif filt == -5 then
161	return 'PROC'
162	elseif filt == -6 then
163	return 'SIGNAL'
164	elseif filt == -7 then
165	return 'TIMER'
166	elseif filt == -8 then
167	return 'MACHPORT'
168	elseif filt == -9 then
169	return 'FS'
170	elseif filt == -10 then
171	return 'USER'
172	-- -11 unused
173	elseif filt == -12 then
174	return 'VM'
175	elseif filt == -13 then
176	return 'SOCK'
177	elseif filt == -14 then
178	return 'MEMORYSTATUS'
179	elseif filt == 15 then
180	return 'KQREAD'
181	elseif filt == 16 then
182	return 'PIPE_R'
183	elseif filt == 17 then
184	return 'PIPE_W'
185	elseif filt == 18 then
186	return 'PTSD'
187	elseif filt == 19 then
188	return 'SOWRITE'
189	elseif filt == 20 then
190	return 'SOEXCEPT'
191	elseif filt == 21 then
192	return 'SPEC'
193	elseif filt == 22 then
194	return 'BPFREAD'
195	elseif filt == 23 then
196	return 'NECP_FD'
197	elseif filt == 24 then
198	return 'SKYWALK_CHANNEL_W'
199	elseif filt == 25 then
200	return 'SKYWALK_CHANNEL_R'
201	elseif filt == 26 then
202	return 'FSEVENT'
203	elseif filt == 27 then
204	return 'VN'
205	elseif filt == 28 then
206	return 'SKYWALK_CHANNEL_E'
207	elseif filt == 29 then
208	return 'TTY'
209	else
210	return string.format('[%d]', filt)
211	end
212	end
213
214	-- kqueue lifecycle
215
216	function processing_begin(workq)
217	return function(buf)
218	local prefix = event_prefix_string(buf, workq)
219	if trace.debugid_is_start(buf.debugid) then
220	local qos
221	if workq then
222	qos = buf.arg2
223	else
224	qos = buf.arg3
225	end
226	printf("%s QoS = %s\n", prefix, qos_string(qos))
227	else
228	printf("%s request thread = 0x%x, kqrequest state = %s\n", prefix,
229	buf.arg1, state_string(kqrequest_state_strings, buf.arg2))
230	end
231	end
232	end
233
234	trace_eventname("KEVENT_kq_processing_begin", processing_begin(false))
235	trace_eventname("KEVENT_kqwq_processing_begin", processing_begin(true))
236	trace_eventname("KEVENT_kqwl_processing_begin", processing_begin(false))
237
238	function processing_end(workq)
239	return function(buf)
240	local qos
241	if workq then
242	qos = buf.arg2
243	else
244	qos = buf.arg3
245	end
246	printf("%s QoS = %s\n", event_prefix_string(buf, workq), qos_string(qos))
247	end
248	end
249
250	trace_eventname("KEVENT_kq_processing_end", processing_end(false))
251	trace_eventname("KEVENT_kqwq_processing_end", processing_end(true))
252	trace_eventname("KEVENT_kqwl_processing_end", processing_end(false))
253
254	trace_eventname("KEVENT_kqwq_bind", function(buf)
255	printf("%s thread = 0x%x, QoS = %s, kqrequest state = %s\n",
256	event_prefix_string(buf, true), buf.arg1, qos_string(buf.arg3),
257	state_string(kqrequest_state_strings, buf.arg4))
258	end)
259
260	trace_eventname("KEVENT_kqwq_unbind", function(buf)
261	printf("%s thread = 0x%x, QoS = %s\n", event_prefix_string(buf, true),
262	buf.arg1, qos_string(buf.arg3))
263	end)
264
265	trace_eventname("KEVENT_kqwl_bind", function(buf)
266	qos = buf.arg3 & 0xff
267	duplicate = buf.arg3 & (1 << 8)
268	kqr_override_qos_delta = buf.arg4 >> 8
269	kqr_state = buf.arg4 & 0xff
270
271	printf("%s thread = 0x%x, QoS = %s, override QoS delta = %d, kqrequest state = %s%s\n",
272	event_prefix_string(buf, false), buf.arg2, qos_string(qos),
273	kqr_override_qos_delta,
274	state_string(kqrequest_state_strings, kqr_state),
275	duplicate ? ", duplicate" : "")
276	end)
277
278	trace_eventname("KEVENT_kqwl_unbind", function(buf)
279	flags = buf.arg3
280	qos = buf.arg4
281
282	printf("%s thread = 0x%x, QoS = %s, flags = 0x%x\n", event_prefix_string(buf, false),
283	buf.arg2, qos_string(qos), flags)
284	end)
285
286	function thread_request(workq)
287	return function(buf)
288	printf("%s QoS = %s, kqrequest state = %s, override QoS delta = %d\n",
289	event_prefix_string(buf, workq), qos_string(buf.arg2),
290	state_string(kqrequest_state_strings, buf.arg3), buf.arg3 >> 8)
291	end
292	end
293
294	function thread_adjust(buf)
295	tid = buf.arg2
296	kqr_qos = buf.arg3 >> 8
297	new_qos = buf.arg3 & 0xff
298	kqr_qos_override = buf.arg4 >> 8
299	kqr_state = buf.arg4 & 0xff
300
301	printf("%s thread = 0x%x, old/new QoS = %s/%s, old/new override QoS delta = %d/%d, kqrequest state = %s\n",
302	event_prefix_string(buf, false),
303	tid,
304	qos_string(kqr_qos),
305	qos_string(new_qos),
306	kqr_qos_override,
307	new_qos - kqr_qos,
308	state_string(kqrequest_state_strings, kqr_state))
309	end
310
311	trace_eventname("KEVENT_kqwq_thread_request", thread_request(true))
312	trace_eventname("KEVENT_kqwl_thread_request", thread_request(false))
313	trace_eventname("KEVENT_kqwl_thread_adjust", thread_adjust)
314
315	function kevent_register(workq)
316	return function(buf)
317	printf("%s kevent udata = 0x%x, kevent filter = %s, kevent flags = %s\n",
318	event_prefix_string(buf, workq), buf.arg2,
319	kevent_filter_string(buf.arg4),
320	state_string(kevent_flags_strings, buf.arg3))
321	end
322	end
323
324	trace_eventname("KEVENT_kq_register", kevent_register(false))
325	trace_eventname("KEVENT_kqwq_register", kevent_register(true))
326	trace_eventname("KEVENT_kqwl_register", kevent_register(false))
327
328	function kevent_process(workq)
329	return function(buf)
330	printf("%s kevent ident = 0x%x, udata = 0x%x, kevent filter = %s, knote status = %s\n",
331	event_prefix_string(buf, workq), buf.arg3 >> 32, buf.arg2,
332	kevent_filter_string(buf.arg4),
333	state_string(knote_state_strings, buf.arg3 & 0xffffffff))
334	end
335	end
336
337	trace_eventname("KEVENT_kq_process", kevent_process(false))
338	trace_eventname("KEVENT_kqwq_process", kevent_process(true))
339	trace_eventname("KEVENT_kqwl_process", kevent_process(false))