1/*
2 * Copyright 2008, Ingo Weinhold, ingo_weinhold@gmx.de.
3 * Copyright 2002-2007, Axel D��rfler, axeld@pinc-software.de.
4 * Distributed under the terms of the MIT License.
5 */
6
7#include "scheduler_tracing.h"
8
9#include <debug.h>
10
11
12#if SCHEDULER_TRACING
13
14namespace SchedulerTracing {
15
16// #pragma mark - EnqueueThread
17
18
19void
20EnqueueThread::AddDump(TraceOutput& out)
21{
22	out.Print("scheduler enqueue %" B_PRId32 " \"%s\", effective priority %"
23		B_PRId32 ", real priority %" B_PRId32, fID, fName, fEffectivePriority,
24		fPriority);
25}
26
27
28const char*
29EnqueueThread::Name() const
30{
31	return fName;
32}
33
34
35// #pragma mark - RemoveThread
36
37
38void
39RemoveThread::AddDump(TraceOutput& out)
40{
41	out.Print("scheduler remove %" B_PRId32 ", priority %" B_PRId32, fID,
42		fPriority);
43}
44
45const char*
46RemoveThread::Name() const
47{
48	return NULL;
49}
50
51
52// #pragma mark - ScheduleThread
53
54
55void
56ScheduleThread::AddDump(TraceOutput& out)
57{
58	out.Print("schedule %" B_PRId32 " \"%s\", priority %" B_PRId32 ", CPU %"
59		B_PRId32 ", previous thread: %" B_PRId32 " (", fID, fName, fPriority,
60		fCPU, fPreviousID);
61	if (fPreviousState == B_THREAD_WAITING) {
62		switch (fPreviousWaitObjectType) {
63			case THREAD_BLOCK_TYPE_SEMAPHORE:
64				out.Print("sem %" B_PRId32,
65					(sem_id)(addr_t)fPreviousWaitObject);
66				break;
67			case THREAD_BLOCK_TYPE_CONDITION_VARIABLE:
68				out.Print("cvar %p", fPreviousWaitObject);
69				break;
70			case THREAD_BLOCK_TYPE_SNOOZE:
71				out.Print("snooze()");
72				break;
73			case THREAD_BLOCK_TYPE_SIGNAL:
74				out.Print("signal");
75				break;
76			case THREAD_BLOCK_TYPE_MUTEX:
77				out.Print("mutex %p", fPreviousWaitObject);
78				break;
79			case THREAD_BLOCK_TYPE_RW_LOCK:
80				out.Print("rwlock %p", fPreviousWaitObject);
81				break;
82			case THREAD_BLOCK_TYPE_USER:
83				out.Print("_user_block_thread()");
84				break;
85			case THREAD_BLOCK_TYPE_OTHER:
86				out.Print("other (%p)", fPreviousWaitObject);
87					// We could print the string, but it might come from a
88					// kernel module that has already been unloaded.
89				break;
90			case THREAD_BLOCK_TYPE_OTHER_OBJECT:
91				out.Print("other object (%p)", fPreviousWaitObject);
92				break;
93			default:
94				out.Print("unknown (%p)", fPreviousWaitObject);
95				break;
96		}
97#if SCHEDULER_TRACING >= 2
98	} else if (fPreviousState == B_THREAD_READY) {
99		out.Print("ready at %p", fPreviousPC);
100#endif
101	} else
102		out.Print("%s", thread_state_to_text(NULL, fPreviousState));
103
104	out.Print(")");
105}
106
107
108const char*
109ScheduleThread::Name() const
110{
111	return fName;
112}
113
114}	// namespace SchedulerTracing
115
116
117// #pragma mark -
118
119
120int
121cmd_scheduler(int argc, char** argv)
122{
123	using namespace SchedulerTracing;
124
125	int64 threadID;
126	if (argc != 2
127		|| !evaluate_debug_expression(argv[1], (uint64*)&threadID, true)) {
128		print_debugger_command_usage(argv[0]);
129		return 0;
130	}
131
132	if (threadID <= 0) {
133		kprintf("Invalid thread ID: %" B_PRId64 "\n", threadID);
134		return 0;
135	}
136
137	ScheduleState state = UNKNOWN;
138	bigtime_t lastTime = 0;
139
140	int64 runs = 0;
141	bigtime_t totalRunTime = 0;
142	bigtime_t minRunTime = -1;
143	bigtime_t maxRunTime = -1;
144
145	int64 latencies = 0;
146	bigtime_t totalLatency = 0;
147	bigtime_t minLatency = -1;
148	bigtime_t maxLatency = -1;
149	int32 maxLatencyEntry = -1;
150
151	int64 reruns = 0;
152	bigtime_t totalRerunTime = 0;
153	bigtime_t minRerunTime = -1;
154	bigtime_t maxRerunTime = -1;
155	int32 maxRerunEntry = -1;
156
157	int64 preemptions = 0;
158
159	TraceEntryIterator iterator;
160	while (TraceEntry* _entry = iterator.Next()) {
161		if (dynamic_cast<SchedulerTraceEntry*>(_entry) == NULL)
162			continue;
163
164		if (ScheduleThread* entry = dynamic_cast<ScheduleThread*>(_entry)) {
165			if (entry->ThreadID() == threadID) {
166				// thread scheduled
167				bigtime_t diffTime = entry->Time() - lastTime;
168
169				if (state == READY) {
170					// thread scheduled after having been woken up
171					latencies++;
172					totalLatency += diffTime;
173					if (minLatency < 0 || diffTime < minLatency)
174						minLatency = diffTime;
175					if (diffTime > maxLatency) {
176						maxLatency = diffTime;
177						maxLatencyEntry = iterator.Index();
178					}
179				} else if (state == PREEMPTED) {
180					// thread scheduled after having been preempted before
181					reruns++;
182					totalRerunTime += diffTime;
183					if (minRerunTime < 0 || diffTime < minRerunTime)
184						minRerunTime = diffTime;
185					if (diffTime > maxRerunTime) {
186						maxRerunTime = diffTime;
187						maxRerunEntry = iterator.Index();
188					}
189				}
190
191				if (state == STILL_RUNNING) {
192					// Thread was running and continues to run.
193					state = RUNNING;
194				}
195
196				if (state != RUNNING) {
197					lastTime = entry->Time();
198					state = RUNNING;
199				}
200			} else if (entry->PreviousThreadID() == threadID) {
201				// thread unscheduled
202				bigtime_t diffTime = entry->Time() - lastTime;
203
204				if (state == STILL_RUNNING) {
205					// thread preempted
206					runs++;
207					preemptions++;
208					totalRunTime += diffTime;
209					if (minRunTime < 0 || diffTime < minRunTime)
210						minRunTime = diffTime;
211					if (diffTime > maxRunTime)
212						maxRunTime = diffTime;
213
214					state = PREEMPTED;
215					lastTime = entry->Time();
216				} else if (state == RUNNING) {
217					// thread starts waiting (it hadn't been added to the run
218					// queue before being unscheduled)
219					bigtime_t diffTime = entry->Time() - lastTime;
220					runs++;
221					totalRunTime += diffTime;
222					if (minRunTime < 0 || diffTime < minRunTime)
223						minRunTime = diffTime;
224					if (diffTime > maxRunTime)
225						maxRunTime = diffTime;
226
227					state = WAITING;
228					lastTime = entry->Time();
229				}
230			}
231		} else if (EnqueueThread* entry
232				= dynamic_cast<EnqueueThread*>(_entry)) {
233			if (entry->ThreadID() != threadID)
234				continue;
235
236			// thread enqueued in run queue
237
238			if (state == RUNNING || state == STILL_RUNNING) {
239				// Thread was running and is reentered into the run queue. This
240				// is done by the scheduler, if the thread remains ready.
241				state = STILL_RUNNING;
242			} else {
243				// Thread was waiting and is ready now.
244				lastTime = entry->Time();
245				state = READY;
246			}
247		} else if (RemoveThread* entry = dynamic_cast<RemoveThread*>(_entry)) {
248			if (entry->ThreadID() != threadID)
249				continue;
250
251			// thread removed from run queue
252
253			// This really only happens when the thread priority is changed
254			// while the thread is ready.
255
256			if (state == RUNNING) {
257				// This should never happen.
258				bigtime_t diffTime = entry->Time() - lastTime;
259				runs++;
260				totalRunTime += diffTime;
261				if (minRunTime < 0 || diffTime < minRunTime)
262					minRunTime = diffTime;
263				if (diffTime > maxRunTime)
264					maxRunTime = diffTime;
265			}
266
267			state = WAITING;
268		}
269	}
270
271	// print results
272	if (runs == 0) {
273		kprintf("thread %" B_PRId64 " never ran.\n", threadID);
274		return 0;
275	}
276
277	kprintf("scheduling statistics for thread %" B_PRId64 ":\n", threadID);
278	kprintf("runs:\n");
279	kprintf("  total #: %" B_PRId64 "\n", runs);
280	kprintf("  total:   %" B_PRIdBIGTIME " us\n", totalRunTime);
281	kprintf("  average: %#.2f us\n", (double)totalRunTime / runs);
282	kprintf("  min:     %" B_PRIdBIGTIME " us\n", minRunTime);
283	kprintf("  max:     %" B_PRIdBIGTIME " us\n", maxRunTime);
284
285	if (latencies > 0) {
286		kprintf("scheduling latency after wake up:\n");
287		kprintf("  total #: %" B_PRIdBIGTIME "\n", latencies);
288		kprintf("  total:   %" B_PRIdBIGTIME " us\n", totalLatency);
289		kprintf("  average: %#.2f us\n", (double)totalLatency / latencies);
290		kprintf("  min:     %" B_PRIdBIGTIME " us\n", minLatency);
291		kprintf("  max:     %" B_PRIdBIGTIME " us\n", maxLatency);
292		kprintf("  max:     %" B_PRIdBIGTIME " us (at tracing entry %" B_PRId32
293			")\n", maxLatency, maxLatencyEntry);
294	} else
295		kprintf("thread was never run after having been woken up\n");
296
297	if (reruns > 0) {
298		kprintf("scheduling latency after preemption:\n");
299		kprintf("  total #: %" B_PRId64 "\n", reruns);
300		kprintf("  total:   %" B_PRIdBIGTIME " us\n", totalRerunTime);
301		kprintf("  average: %#.2f us\n", (double)totalRerunTime / reruns);
302		kprintf("  min:     %" B_PRIdBIGTIME " us\n", minRerunTime);
303		kprintf("  max:     %" B_PRIdBIGTIME " us (at tracing entry %" B_PRId32
304			")\n", maxRerunTime, maxRerunEntry);
305	} else
306		kprintf("thread was never rerun after preemption\n");
307
308	if (preemptions > 0)
309		kprintf("thread was preempted %" B_PRId64 " times\n", preemptions);
310	else
311		kprintf("thread was never preempted\n");
312
313	return 0;
314}
315
316#endif	// SCHEDULER_TRACING
317