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
14 namespace SchedulerTracing {
15
16 // #pragma mark - EnqueueThread
17
18
19 void
AddDump(TraceOutput & out)20 EnqueueThread::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
28 const char*
Name() const29 EnqueueThread::Name() const
30 {
31 return fName;
32 }
33
34
35 // #pragma mark - RemoveThread
36
37
38 void
AddDump(TraceOutput & out)39 RemoveThread::AddDump(TraceOutput& out)
40 {
41 out.Print("scheduler remove %" B_PRId32 ", priority %" B_PRId32, fID,
42 fPriority);
43 }
44
45 const char*
Name() const46 RemoveThread::Name() const
47 {
48 return NULL;
49 }
50
51
52 // #pragma mark - ScheduleThread
53
54
55 void
AddDump(TraceOutput & out)56 ScheduleThread::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
108 const char*
Name() const109 ScheduleThread::Name() const
110 {
111 return fName;
112 }
113
114 } // namespace SchedulerTracing
115
116
117 // #pragma mark -
118
119
120 int
cmd_scheduler(int argc,char ** argv)121 cmd_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