[apple/libpthread.git] / tools / wqtrace.lua

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

trace_codename = 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
workqueue_ptr_map = {};
get_prefix = function(buf)
	if initial_timestamp == 0 then
		initial_timestamp = buf.timestamp
	end
	local secs = trace.convert_timestamp_to_nanoseconds(buf.timestamp - initial_timestamp) / 1000000000

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

	local proc
	if buf.command ~= "kernel_task" then
		proc = buf.command
		workqueue_ptr_map[buf[1]] = buf.command
	elseif workqueue_ptr_map[buf[1]] ~= nil then
		proc = workqueue_ptr_map[buf[1]]
	else
		proc = "UNKNOWN"
	end

	return string.format("%s %6.9f %-17s [%05d.%06x] %-24s",
		prefix, secs, proc, buf.pid, buf.threadid, buf.debugname)
end

parse_pthread_priority = function(pri)
	pri = pri & 0xffffffff
	if (pri & 0x02000000) == 0x02000000 then
		return "Manager"
	end
	local qos = (pri & 0x00ffff00) >> 8
	if qos == 0x20 then
		return string.format("UI[%x]", pri);
	elseif qos == 0x10 then
		return string.format("IN[%x]", pri);
	elseif qos == 0x08 then
		return string.format("DF[%x]", pri);
	elseif qos == 0x04 then
		return string.format("UT[%x]", pri);
	elseif qos == 0x02 then
		return string.format("BG[%x]", pri);
	elseif qos == 0x01 then
		return string.format("MT[%x]", pri);
	elseif qos == 0x00 then
		return string.format("--[%x]", pri);
	else
		return string.format("??[%x]", pri);
	end
end

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

parse_thactive_req_bucket = function(pri)
    if pri ~= 6 then
        return parse_qos_bucket(pri)
    end
    return "None"
end

get_thactive = function(low, high)
    return string.format("req: %s, MG: %d, UI: %d, IN: %d, DE: %d, UT: %d, BG: %d, MT: %d",
           parse_thactive_req_bucket(high >> (16 * 3)), (high >> (2 * 16)) & 0xffff,
           (low  >> (0 * 16)) & 0xffff, (low  >> (1 * 16)) & 0xffff,
           (low  >> (2 * 16)) & 0xffff, (low  >> (3 * 16)) & 0xffff,
           (high >> (0 * 16)) & 0xffff, (high >> (1 * 16)) & 0xffff)
end

-- workqueue lifecycle

trace_codename("wq_pthread_exit", function(buf)
	local prefix = get_prefix(buf)
	if trace.debugid_is_start(buf.debugid) then
		printf("%s\tprocess is exiting\n",prefix)
	else
		printf("%s\tworkqueue marked as exiting and timer is complete\n",prefix)
	end
end)

trace_codename("wq_workqueue_exit", function(buf)
	local prefix = get_prefix(buf)
	if trace.debugid_is_start(buf.debugid) then
		printf("%s\tall threads have exited, cleaning up\n",prefix)
	else
		printf("%s\tclean up complete\n",prefix)
	end
end)

trace_codename("wq_start_add_timer", function(buf)
	local prefix = get_prefix(buf)
	printf("%s\tarming timer to fire in %d us (flags: %x, reqcount: %d)\n",
		prefix, buf.arg4, buf.arg3, buf.arg2)
end)

trace_codename("wq_add_timer", function(buf)
	local prefix = get_prefix(buf)
	if trace.debugid_is_start(buf.debugid) then
		printf("%s\tadd_timer fired (flags: %x, nthreads: %d, thidlecount: %d)\n",
			prefix, buf.arg2, buf.arg3, buf.arg4)
	elseif trace.debugid_is_end(buf.debugid) then
		printf("%s\tadd_timer completed (start_timer: %x, nthreads: %d, thidlecount: %d)\n",
			prefix, buf.arg2, buf.arg3, buf.arg4)
	else
		printf("%s\tadd_timer added threads (reqcount: %d, thidlecount: %d, busycount: %d)\n",
			prefix, buf.arg2, buf.arg3, buf.arg4)

	end
end)

trace_codename("wq_run_threadreq", function(buf)
	local prefix = get_prefix(buf)
	if trace.debugid_is_start(buf.debugid) then
		if buf[2] > 0 then
			printf("%s\trun_threadreq: %x (priority: %s, flags: %d) on %x\n",
					prefix, buf[2], parse_qos_bucket(buf[4] >> 16), buf[4] & 0xff, buf[3])
		else
			printf("%s\trun_threadreq: <none> on %x\n",
					prefix, buf[3])
		end
	else
		if buf[2] == 1 then
			printf("%s\tpended event manager, already running\n", prefix)
		elseif buf[2] == 2 then
			printf("%s\tnothing to do\n", prefix)
		elseif buf[2] == 3 then
			printf("%s\tno eligible request found\n", prefix)
		elseif buf[2] == 4 then
			printf("%s\tadmission control failed\n", prefix)
		elseif buf[2] == 5 then
			printf("%s\tunable to add new thread (may_add_new_thread: %d, nthreads: %d)\n", prefix, buf[3], buf[4])
		elseif buf[2] == 6 then
			printf("%s\tthread creation failed\n", prefix)
		elseif buf[2] == 0 then
			printf("%s\tsuccess\n", prefix)
		else
			printf("%s\tWARNING: UNKNOWN END CODE:%d\n", prefix, buf.arg4)
		end
	end
end)

trace_codename("wq_run_threadreq_mgr_merge", function(buf)
	local prefix = get_prefix(buf)
	printf("%s\t\tmerging incoming manager request into existing\n", prefix)
end)

trace_codename("wq_run_threadreq_req_select", function(buf)
	local prefix = get_prefix(buf)
	if buf[3] == 1 then
		printf("%s\t\tselected event manager request %x\n", prefix, buf[2])
	elseif buf[3] == 2 then
		printf("%s\t\tselected overcommit request %x\n", prefix, buf[2])
	elseif buf[3] == 3 then
		printf("%s\t\tselected constrained request %x\n", prefix, buf[2])
	else
		printf("%s\t\tWARNING: UNKNOWN DECISION CODE:%d\n", prefix, buf.arg[3])
	end
end)

trace_codename("wq_run_threadreq_thread_select", function(buf)
	local prefix = get_prefix(buf)
	if buf[2] == 1 then
		printf("%s\t\trunning on current thread %x\n", prefix, buf[3])
	elseif buf[2] == 2 then
		printf("%s\t\trunning on idle thread %x\n", prefix, buf[3])
	elseif buf[2] == 3 then
		printf("%s\t\tcreated new thread\n", prefix)
	else
		printf("%s\t\tWARNING: UNKNOWN DECISION CODE:%d\n", prefix, buf.arg[2])
	end
end)

trace_codename("wq_thread_reset_priority", function(buf)
	local prefix = get_prefix(buf)
	local old_qos = buf[3] >> 16;
	local new_qos = buf[3] & 0xff;
	if buf[4] == 1 then
		printf("%s\t\treset priority of %x from %s to %s\n", prefix, buf[2], parse_qos_bucket(old_qos), parse_qos_bucket(new_qos))
	elseif buf[4] == 2 then
		printf("%s\t\treset priority of %x from %s to %s for reserve manager\n", prefix, buf[2], parse_qos_bucket(old_qos), parse_qos_bucket(new_qos))
	elseif buf[4] == 3 then
		printf("%s\t\treset priority of %x from %s to %s for cleanup\n", prefix, buf[2], parse_qos_bucket(old_qos), parse_qos_bucket(new_qos))
	end
end)

trace_codename("wq_thread_park", function(buf)
	local prefix = get_prefix(buf)
	if trace.debugid_is_start(buf.debugid) then
		printf("%s\tthread parking\n", prefix)
	else
		printf("%s\tthread woken\n", prefix)
	end
end)

trace_codename("wq_thread_squash", function(buf)
	local prefix = get_prefix(buf)
	printf("%s\tthread squashed from %s to %s\n", prefix,
			parse_qos_bucket(buf[2]), parse_qos_bucket(buf[3]))
end)

trace.enable_thread_cputime()
runitem_time_map = {}
runitem_cputime_map = {}
trace_codename("wq_runitem", function(buf)
	local prefix = get_prefix(buf)
	if trace.debugid_is_start(buf.debugid) then
		runitem_time_map[buf.threadid] = buf.timestamp;
		runitem_cputime_map[buf.threadid] = trace.cputime_for_thread(buf.threadid);

		printf("%s\tSTART running item @ %s\n", prefix, parse_qos_bucket(buf[3]))
	elseif runitem_time_map[buf.threadid] then
		local time = buf.timestamp - runitem_time_map[buf.threadid]
		local cputime = trace.cputime_for_thread(buf.threadid) - runitem_cputime_map[buf.threadid]

		local time_ms = trace.convert_timestamp_to_nanoseconds(time) / 1000000
		local cputime_ms = trace.convert_timestamp_to_nanoseconds(cputime) / 1000000

		printf("%s\tDONE running item @ %s: time = %6.6f ms, cputime = %6.6f ms\n",
				prefix, parse_qos_bucket(buf[2]), time_ms, cputime_ms)

		runitem_time_map[buf.threadid] = 0
		runitem_cputime_map[buf.threadid] = 0
	else
		printf("%s\tDONE running item @ %s\n", prefix, parse_qos_bucket(buf[2]))
	end
end)

trace_codename("wq_runthread", function(buf)
	local prefix = get_prefix(buf)
	if trace.debugid_is_start(buf.debugid) then
		printf("%s\tSTART running thread\n", prefix)
	elseif trace.debugid_is_end(buf.debugid) then
		printf("%s\tDONE running thread\n", prefix)
	end
end)

trace_codename("wq_thactive_update", function(buf)
    local prefix = get_prefix(buf)
    local thactive = get_thactive(buf[2], buf[3])
    if buf[1] == 1 then
        printf("%s\tthactive constrained pre-post (%s)\n", prefix, thactive)
    elseif buf[1] == 2 then
        printf("%s\tthactive constrained run (%s)\n", prefix, thactive)
    else
        return
    end
end)

trace_codename("wq_thread_block", function(buf)
	local prefix = get_prefix(buf)
        local req_pri = parse_thactive_req_bucket(buf[3] >> 8)
	if trace.debugid_is_start(buf.debugid) then
		printf("%s\tthread blocked (activecount: %d, priority: %s, req_pri: %s, reqcount: %d, start_timer: %d)\n",
			prefix, buf[2], parse_qos_bucket(buf[3] & 0xff), req_pri, buf[4] >> 1, buf[4] & 0x1)
	else
		printf("%s\tthread unblocked (activecount: %d, priority: %s, req_pri: %s, threads_scheduled: %d)\n",
			prefix, buf[2], parse_qos_bucket(buf[3] & 0xff), req_pri, buf[4])
	end
end)

trace_codename("wq_thread_create_failed", function(buf)
	local prefix = get_prefix(buf)
	if buf[3] == 0 then
		printf("%s\tfailed to create new workqueue thread, kern_return: 0x%x\n",
			prefix, buf[2])
	elseif buf[3] == 1 then
		printf("%s\tfailed to vm_map workq thread stack: 0x%x\n", prefix, buf[2])
	elseif buf[3] == 2 then
		printf("%s\tfailed to vm_protect workq thread guardsize: 0x%x\n", prefix, buf[2])
	end
end)

trace_codename("wq_thread_create", function(buf)
	printf("%s\tcreated new workqueue thread\n", get_prefix(buf))
end)

trace_codename("wq_wqops_reqthreads", function(buf)
	local prefix = get_prefix(buf)
	printf("%s\tuserspace requested %d threads at %s\n", prefix, buf[2], parse_pthread_priority(buf[3]));
end)

trace_codename("wq_kevent_reqthreads", function(buf)
	local prefix = get_prefix(buf)
	if buf[4] == 0 then
		printf("%s\tkevent requested a thread at %s\n", prefix, parse_pthread_priority(buf[3]));
	elseif buf[4] == 1 then
		printf("%s\tworkloop requested a thread for req %x at %s\n", prefix, buf[2], parse_pthread_priority(buf[3]));
	elseif buf[4] == 2 then
		printf("%s\tworkloop updated priority of req %x to %s\n", prefix, buf[2], parse_pthread_priority(buf[3]));
	elseif buf[4] == 3 then
		printf("%s\tworkloop canceled req %x\n", prefix, buf[2], parse_pthread_priority(buf[3]));
	elseif buf[4] == 4 then
		printf("%s\tworkloop redrove a thread request\n", prefix);
	end
end)

trace_codename("wq_constrained_admission", function(buf)
	local prefix = get_prefix(buf)
	if buf[2] == 1 then
		printf("fail: %s\twq_constrained_threads_scheduled=%d >= wq_max_constrained_threads=%d\n",
                prefix, buf[3], buf[4])
	elseif (buf[2] == 2) or (buf[2] == 3) then
		local success = nil;
		if buf[2] == 2 then success = "success"
		else success = "fail" end
		printf("%s: %s\tthactive_count=%d + busycount=%d >= wq->wq_max_concurrency\n",
				prefix, success, buf[3], buf[4])
	end
end)

-- The trace codes we need aren't enabled by default
darwin.sysctlbyname("kern.pthread_debug_tracing", 1)
completion_handler = function()
	darwin.sysctlbyname("kern.pthread_debug_tracing", 0)
end
trace.set_completion_handler(completion_handler)
Commit	Line	Data
964d3577 A	1	#!/usr/local/bin/luatrace -s
	2
	3	trace_codename = function(codename, callback)
	4	local debugid = trace.debugid(codename)
a0619f9c	5	if debugid ~= 0 then
010efe49	6	trace.single(debugid,callback)
2546420a A	7	else
2546420a A	8	printf("WARNING: Cannot locate debugid for '%s'\n", codename)
964d3577 A	9	end
	10	end
	11
	12	initial_timestamp = 0
2546420a	13	workqueue_ptr_map = {};
964d3577 A	14	get_prefix = function(buf)
	15	if initial_timestamp == 0 then
	16	initial_timestamp = buf.timestamp
	17	end
010efe49	18	local secs = trace.convert_timestamp_to_nanoseconds(buf.timestamp - initial_timestamp) / 1000000000
2546420a	19
964d3577	20	local prefix
010efe49 A	21	if trace.debugid_is_start(buf.debugid) then
	22	prefix = "→"
	23	elseif trace.debugid_is_end(buf.debugid) then
	24	prefix = "←"
	25	else
	26	prefix = "↔"
964d3577	27	end
2546420a A	28
	29	local proc
	30	if buf.command ~= "kernel_task" then
	31	proc = buf.command
	32	workqueue_ptr_map[buf[1]] = buf.command
	33	elseif workqueue_ptr_map[buf[1]] ~= nil then
	34	proc = workqueue_ptr_map[buf[1]]
	35	else
	36	proc = "UNKNOWN"
	37	end
	38
	39	return string.format("%s %6.9f %-17s [%05d.%06x] %-24s",
	40	prefix, secs, proc, buf.pid, buf.threadid, buf.debugname)
964d3577 A	41	end
	42
	43	parse_pthread_priority = function(pri)
2546420a A	44	pri = pri & 0xffffffff
	45	if (pri & 0x02000000) == 0x02000000 then
	46	return "Manager"
	47	end
	48	local qos = (pri & 0x00ffff00) >> 8
964d3577	49	if qos == 0x20 then
a0619f9c	50	return string.format("UI[%x]", pri);
964d3577	51	elseif qos == 0x10 then
a0619f9c	52	return string.format("IN[%x]", pri);
964d3577	53	elseif qos == 0x08 then
a0619f9c	54	return string.format("DF[%x]", pri);
964d3577	55	elseif qos == 0x04 then
a0619f9c	56	return string.format("UT[%x]", pri);
964d3577	57	elseif qos == 0x02 then
2546420a	58	return string.format("BG[%x]", pri);
964d3577	59	elseif qos == 0x01 then
a0619f9c	60	return string.format("MT[%x]", pri);
964d3577	61	elseif qos == 0x00 then
a0619f9c	62	return string.format("--[%x]", pri);
964d3577	63	else
a0619f9c	64	return string.format("??[%x]", pri);
964d3577 A	65	end
	66	end
	67
a0619f9c A	68	parse_qos_bucket = function(pri)
	69	if pri == 0 then
	70	return string.format("UI[%x]", pri);
	71	elseif pri == 1 then
	72	return string.format("IN[%x]", pri);
	73	elseif pri == 2 then
	74	return string.format("DF[%x]", pri);
	75	elseif pri == 3 then
	76	return string.format("UT[%x]", pri);
	77	elseif pri == 4 then
	78	return string.format("BG[%x]", pri);
	79	elseif pri == 5 then
	80	return string.format("MT[%x]", pri);
	81	elseif pri == 6 then
	82	return string.format("MG[%x]", pri);
	83	else
	84	return string.format("??[%x]", pri);
	85	end
	86	end
	87
	88	parse_thactive_req_bucket = function(pri)
	89	if pri ~= 6 then
	90	return parse_qos_bucket(pri)
	91	end
	92	return "None"
	93	end
	94
	95	get_thactive = function(low, high)
	96	return string.format("req: %s, MG: %d, UI: %d, IN: %d, DE: %d, UT: %d, BG: %d, MT: %d",
	97	parse_thactive_req_bucket(high >> (16 * 3)), (high >> (2 * 16)) & 0xffff,
	98	(low >> (0 * 16)) & 0xffff, (low >> (1 * 16)) & 0xffff,
	99	(low >> (2 * 16)) & 0xffff, (low >> (3 * 16)) & 0xffff,
	100	(high >> (0 * 16)) & 0xffff, (high >> (1 * 16)) & 0xffff)
	101	end
	102
964d3577 A	103	-- workqueue lifecycle
	104
	105	trace_codename("wq_pthread_exit", function(buf)
	106	local prefix = get_prefix(buf)
	107	if trace.debugid_is_start(buf.debugid) then
	108	printf("%s\tprocess is exiting\n",prefix)
	109	else
	110	printf("%s\tworkqueue marked as exiting and timer is complete\n",prefix)
	111	end
	112	end)
	113
	114	trace_codename("wq_workqueue_exit", function(buf)
	115	local prefix = get_prefix(buf)
	116	if trace.debugid_is_start(buf.debugid) then
	117	printf("%s\tall threads have exited, cleaning up\n",prefix)
	118	else
	119	printf("%s\tclean up complete\n",prefix)
	120	end
	121	end)
	122
964d3577 A	123	trace_codename("wq_start_add_timer", function(buf)
	124	local prefix = get_prefix(buf)
	125	printf("%s\tarming timer to fire in %d us (flags: %x, reqcount: %d)\n",
	126	prefix, buf.arg4, buf.arg3, buf.arg2)
	127	end)
	128
	129	trace_codename("wq_add_timer", function(buf)
	130	local prefix = get_prefix(buf)
	131	if trace.debugid_is_start(buf.debugid) then
	132	printf("%s\tadd_timer fired (flags: %x, nthreads: %d, thidlecount: %d)\n",
	133	prefix, buf.arg2, buf.arg3, buf.arg4)
	134	elseif trace.debugid_is_end(buf.debugid) then
	135	printf("%s\tadd_timer completed (start_timer: %x, nthreads: %d, thidlecount: %d)\n",
	136	prefix, buf.arg2, buf.arg3, buf.arg4)
	137	else
	138	printf("%s\tadd_timer added threads (reqcount: %d, thidlecount: %d, busycount: %d)\n",
	139	prefix, buf.arg2, buf.arg3, buf.arg4)
	140
	141	end
	142	end)
	143
a0619f9c A	144	trace_codename("wq_run_threadreq", function(buf)
	145	local prefix = get_prefix(buf)
	146	if trace.debugid_is_start(buf.debugid) then
	147	if buf[2] > 0 then
	148	printf("%s\trun_threadreq: %x (priority: %s, flags: %d) on %x\n",
	149	prefix, buf[2], parse_qos_bucket(buf[4] >> 16), buf[4] & 0xff, buf[3])
	150	else
	151	printf("%s\trun_threadreq: <none> on %x\n",
	152	prefix, buf[3])
	153	end
	154	else
	155	if buf[2] == 1 then
	156	printf("%s\tpended event manager, already running\n", prefix)
	157	elseif buf[2] == 2 then
	158	printf("%s\tnothing to do\n", prefix)
	159	elseif buf[2] == 3 then
	160	printf("%s\tno eligible request found\n", prefix)
	161	elseif buf[2] == 4 then
	162	printf("%s\tadmission control failed\n", prefix)
	163	elseif buf[2] == 5 then
	164	printf("%s\tunable to add new thread (may_add_new_thread: %d, nthreads: %d)\n", prefix, buf[3], buf[4])
	165	elseif buf[2] == 6 then
	166	printf("%s\tthread creation failed\n", prefix)
	167	elseif buf[2] == 0 then
	168	printf("%s\tsuccess\n", prefix)
	169	else
	170	printf("%s\tWARNING: UNKNOWN END CODE:%d\n", prefix, buf.arg4)
	171	end
	172	end
	173	end)
	174
	175	trace_codename("wq_run_threadreq_mgr_merge", function(buf)
	176	local prefix = get_prefix(buf)
	177	printf("%s\t\tmerging incoming manager request into existing\n", prefix)
	178	end)
	179
	180	trace_codename("wq_run_threadreq_req_select", function(buf)
964d3577	181	local prefix = get_prefix(buf)
a0619f9c A	182	if buf[3] == 1 then
	183	printf("%s\t\tselected event manager request %x\n", prefix, buf[2])
	184	elseif buf[3] == 2 then
	185	printf("%s\t\tselected overcommit request %x\n", prefix, buf[2])
	186	elseif buf[3] == 3 then
	187	printf("%s\t\tselected constrained request %x\n", prefix, buf[2])
964d3577	188	else
a0619f9c	189	printf("%s\t\tWARNING: UNKNOWN DECISION CODE:%d\n", prefix, buf.arg[3])
964d3577 A	190	end
	191	end)
	192
a0619f9c	193	trace_codename("wq_run_threadreq_thread_select", function(buf)
964d3577	194	local prefix = get_prefix(buf)
a0619f9c A	195	if buf[2] == 1 then
	196	printf("%s\t\trunning on current thread %x\n", prefix, buf[3])
	197	elseif buf[2] == 2 then
	198	printf("%s\t\trunning on idle thread %x\n", prefix, buf[3])
	199	elseif buf[2] == 3 then
	200	printf("%s\t\tcreated new thread\n", prefix)
	201	else
	202	printf("%s\t\tWARNING: UNKNOWN DECISION CODE:%d\n", prefix, buf.arg[2])
	203	end
964d3577 A	204	end)
964d3577 A	205
a0619f9c A	206	trace_codename("wq_thread_reset_priority", function(buf)
	207	local prefix = get_prefix(buf)
	208	local old_qos = buf[3] >> 16;
	209	local new_qos = buf[3] & 0xff;
	210	if buf[4] == 1 then
	211	printf("%s\t\treset priority of %x from %s to %s\n", prefix, buf[2], parse_qos_bucket(old_qos), parse_qos_bucket(new_qos))
	212	elseif buf[4] == 2 then
	213	printf("%s\t\treset priority of %x from %s to %s for reserve manager\n", prefix, buf[2], parse_qos_bucket(old_qos), parse_qos_bucket(new_qos))
	214	elseif buf[4] == 3 then
	215	printf("%s\t\treset priority of %x from %s to %s for cleanup\n", prefix, buf[2], parse_qos_bucket(old_qos), parse_qos_bucket(new_qos))
	216	end
	217	end)
964d3577	218
a0619f9c	219	trace_codename("wq_thread_park", function(buf)
964d3577 A	220	local prefix = get_prefix(buf)
964d3577 A	221	if trace.debugid_is_start(buf.debugid) then
a0619f9c	222	printf("%s\tthread parking\n", prefix)
964d3577	223	else
a0619f9c	224	printf("%s\tthread woken\n", prefix)
964d3577 A	225	end
	226	end)
	227
a0619f9c A	228	trace_codename("wq_thread_squash", function(buf)
	229	local prefix = get_prefix(buf)
	230	printf("%s\tthread squashed from %s to %s\n", prefix,
	231	parse_qos_bucket(buf[2]), parse_qos_bucket(buf[3]))
	232	end)
	233
010efe49 A	234	trace.enable_thread_cputime()
	235	runitem_time_map = {}
	236	runitem_cputime_map = {}
964d3577 A	237	trace_codename("wq_runitem", function(buf)
	238	local prefix = get_prefix(buf)
	239	if trace.debugid_is_start(buf.debugid) then
010efe49 A	240	runitem_time_map[buf.threadid] = buf.timestamp;
	241	runitem_cputime_map[buf.threadid] = trace.cputime_for_thread(buf.threadid);
	242
a0619f9c	243	printf("%s\tSTART running item @ %s\n", prefix, parse_qos_bucket(buf[3]))
010efe49 A	244	elseif runitem_time_map[buf.threadid] then
	245	local time = buf.timestamp - runitem_time_map[buf.threadid]
	246	local cputime = trace.cputime_for_thread(buf.threadid) - runitem_cputime_map[buf.threadid]
	247
	248	local time_ms = trace.convert_timestamp_to_nanoseconds(time) / 1000000
	249	local cputime_ms = trace.convert_timestamp_to_nanoseconds(cputime) / 1000000
	250
a0619f9c A	251	printf("%s\tDONE running item @ %s: time = %6.6f ms, cputime = %6.6f ms\n",
a0619f9c A	252	prefix, parse_qos_bucket(buf[2]), time_ms, cputime_ms)
010efe49 A	253
	254	runitem_time_map[buf.threadid] = 0
	255	runitem_cputime_map[buf.threadid] = 0
964d3577	256	else
a0619f9c	257	printf("%s\tDONE running item @ %s\n", prefix, parse_qos_bucket(buf[2]))
964d3577 A	258	end
	259	end)
	260
a0619f9c	261	trace_codename("wq_runthread", function(buf)
964d3577 A	262	local prefix = get_prefix(buf)
964d3577 A	263	if trace.debugid_is_start(buf.debugid) then
a0619f9c A	264	printf("%s\tSTART running thread\n", prefix)
	265	elseif trace.debugid_is_end(buf.debugid) then
	266	printf("%s\tDONE running thread\n", prefix)
964d3577 A	267	end
	268	end)
	269
a0619f9c A	270	trace_codename("wq_thactive_update", function(buf)
	271	local prefix = get_prefix(buf)
	272	local thactive = get_thactive(buf[2], buf[3])
	273	if buf[1] == 1 then
	274	printf("%s\tthactive constrained pre-post (%s)\n", prefix, thactive)
	275	elseif buf[1] == 2 then
	276	printf("%s\tthactive constrained run (%s)\n", prefix, thactive)
	277	else
	278	return
	279	end
964d3577 A	280	end)
964d3577 A	281
a0619f9c	282	trace_codename("wq_thread_block", function(buf)
964d3577	283	local prefix = get_prefix(buf)
a0619f9c	284	local req_pri = parse_thactive_req_bucket(buf[3] >> 8)
964d3577	285	if trace.debugid_is_start(buf.debugid) then
a0619f9c A	286	printf("%s\tthread blocked (activecount: %d, priority: %s, req_pri: %s, reqcount: %d, start_timer: %d)\n",
a0619f9c A	287	prefix, buf[2], parse_qos_bucket(buf[3] & 0xff), req_pri, buf[4] >> 1, buf[4] & 0x1)
964d3577	288	else
a0619f9c A	289	printf("%s\tthread unblocked (activecount: %d, priority: %s, req_pri: %s, threads_scheduled: %d)\n",
a0619f9c A	290	prefix, buf[2], parse_qos_bucket(buf[3] & 0xff), req_pri, buf[4])
964d3577 A	291	end
	292	end)
	293
a0619f9c	294	trace_codename("wq_thread_create_failed", function(buf)
964d3577	295	local prefix = get_prefix(buf)
a0619f9c A	296	if buf[3] == 0 then
	297	printf("%s\tfailed to create new workqueue thread, kern_return: 0x%x\n",
	298	prefix, buf[2])
	299	elseif buf[3] == 1 then
	300	printf("%s\tfailed to vm_map workq thread stack: 0x%x\n", prefix, buf[2])
	301	elseif buf[3] == 2 then
	302	printf("%s\tfailed to vm_protect workq thread guardsize: 0x%x\n", prefix, buf[2])
964d3577	303	end
964d3577 A	304	end)
964d3577 A	305
a0619f9c A	306	trace_codename("wq_thread_create", function(buf)
a0619f9c A	307	printf("%s\tcreated new workqueue thread\n", get_prefix(buf))
964d3577 A	308	end)
964d3577 A	309
a0619f9c	310	trace_codename("wq_wqops_reqthreads", function(buf)
964d3577	311	local prefix = get_prefix(buf)
a0619f9c	312	printf("%s\tuserspace requested %d threads at %s\n", prefix, buf[2], parse_pthread_priority(buf[3]));
964d3577 A	313	end)
964d3577 A	314
a0619f9c	315	trace_codename("wq_kevent_reqthreads", function(buf)
964d3577	316	local prefix = get_prefix(buf)
a0619f9c A	317	if buf[4] == 0 then
	318	printf("%s\tkevent requested a thread at %s\n", prefix, parse_pthread_priority(buf[3]));
	319	elseif buf[4] == 1 then
	320	printf("%s\tworkloop requested a thread for req %x at %s\n", prefix, buf[2], parse_pthread_priority(buf[3]));
	321	elseif buf[4] == 2 then
	322	printf("%s\tworkloop updated priority of req %x to %s\n", prefix, buf[2], parse_pthread_priority(buf[3]));
	323	elseif buf[4] == 3 then
	324	printf("%s\tworkloop canceled req %x\n", prefix, buf[2], parse_pthread_priority(buf[3]));
	325	elseif buf[4] == 4 then
	326	printf("%s\tworkloop redrove a thread request\n", prefix);
964d3577 A	327	end
	328	end)
	329
a0619f9c	330	trace_codename("wq_constrained_admission", function(buf)
2546420a	331	local prefix = get_prefix(buf)
a0619f9c A	332	if buf[2] == 1 then
	333	printf("fail: %s\twq_constrained_threads_scheduled=%d >= wq_max_constrained_threads=%d\n",
	334	prefix, buf[3], buf[4])
	335	elseif (buf[2] == 2) or (buf[2] == 3) then
	336	local success = nil;
	337	if buf[2] == 2 then success = "success"
	338	else success = "fail" end
	339	printf("%s: %s\tthactive_count=%d + busycount=%d >= wq->wq_max_concurrency\n",
	340	prefix, success, buf[3], buf[4])
	341	end
2546420a A	342	end)
2546420a A	343
964d3577 A	344	-- The trace codes we need aren't enabled by default
	345	darwin.sysctlbyname("kern.pthread_debug_tracing", 1)
	346	completion_handler = function()
	347	darwin.sysctlbyname("kern.pthread_debug_tracing", 0)
	348	end
	349	trace.set_completion_handler(completion_handler)