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 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* 29 EnqueueThread::Name() const 30 { 31 return fName; 32 } 33 34 35 // #pragma mark - RemoveThread 36 37 38 void 39 RemoveThread::AddDump(TraceOutput& out) 40 { 41 out.Print("scheduler remove %" B_PRId32 ", priority %" B_PRId32, fID, 42 fPriority); 43 } 44 45 const char* 46 RemoveThread::Name() const 47 { 48 return NULL; 49 } 50 51 52 // #pragma mark - ScheduleThread 53 54 55 void 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_OTHER: 83 out.Print("other (%p)", fPreviousWaitObject); 84 // We could print the string, but it might come from a 85 // kernel module that has already been unloaded. 86 break; 87 default: 88 out.Print("unknown (%p)", fPreviousWaitObject); 89 break; 90 } 91 #if SCHEDULER_TRACING >= 2 92 } else if (fPreviousState == B_THREAD_READY) { 93 out.Print("ready at %p", fPreviousPC); 94 #endif 95 } else 96 out.Print("%s", thread_state_to_text(NULL, fPreviousState)); 97 98 out.Print(")"); 99 } 100 101 102 const char* 103 ScheduleThread::Name() const 104 { 105 return fName; 106 } 107 108 } // namespace SchedulerTracing 109 110 111 // #pragma mark - 112 113 114 int 115 cmd_scheduler(int argc, char** argv) 116 { 117 using namespace SchedulerTracing; 118 119 int64 threadID; 120 if (argc != 2 121 || !evaluate_debug_expression(argv[1], (uint64*)&threadID, true)) { 122 print_debugger_command_usage(argv[0]); 123 return 0; 124 } 125 126 if (threadID <= 0) { 127 kprintf("Invalid thread ID: %" B_PRId64 "\n", threadID); 128 return 0; 129 } 130 131 ScheduleState state = UNKNOWN; 132 bigtime_t lastTime = 0; 133 134 int64 runs = 0; 135 bigtime_t totalRunTime = 0; 136 bigtime_t minRunTime = -1; 137 bigtime_t maxRunTime = -1; 138 139 int64 latencies = 0; 140 bigtime_t totalLatency = 0; 141 bigtime_t minLatency = -1; 142 bigtime_t maxLatency = -1; 143 int32 maxLatencyEntry = -1; 144 145 int64 reruns = 0; 146 bigtime_t totalRerunTime = 0; 147 bigtime_t minRerunTime = -1; 148 bigtime_t maxRerunTime = -1; 149 int32 maxRerunEntry = -1; 150 151 int64 preemptions = 0; 152 153 TraceEntryIterator iterator; 154 while (TraceEntry* _entry = iterator.Next()) { 155 if (dynamic_cast<SchedulerTraceEntry*>(_entry) == NULL) 156 continue; 157 158 if (ScheduleThread* entry = dynamic_cast<ScheduleThread*>(_entry)) { 159 if (entry->ThreadID() == threadID) { 160 // thread scheduled 161 bigtime_t diffTime = entry->Time() - lastTime; 162 163 if (state == READY) { 164 // thread scheduled after having been woken up 165 latencies++; 166 totalLatency += diffTime; 167 if (minLatency < 0 || diffTime < minLatency) 168 minLatency = diffTime; 169 if (diffTime > maxLatency) { 170 maxLatency = diffTime; 171 maxLatencyEntry = iterator.Index(); 172 } 173 } else if (state == PREEMPTED) { 174 // thread scheduled after having been preempted before 175 reruns++; 176 totalRerunTime += diffTime; 177 if (minRerunTime < 0 || diffTime < minRerunTime) 178 minRerunTime = diffTime; 179 if (diffTime > maxRerunTime) { 180 maxRerunTime = diffTime; 181 maxRerunEntry = iterator.Index(); 182 } 183 } 184 185 if (state == STILL_RUNNING) { 186 // Thread was running and continues to run. 187 state = RUNNING; 188 } 189 190 if (state != RUNNING) { 191 lastTime = entry->Time(); 192 state = RUNNING; 193 } 194 } else if (entry->PreviousThreadID() == threadID) { 195 // thread unscheduled 196 bigtime_t diffTime = entry->Time() - lastTime; 197 198 if (state == STILL_RUNNING) { 199 // thread preempted 200 runs++; 201 preemptions++; 202 totalRunTime += diffTime; 203 if (minRunTime < 0 || diffTime < minRunTime) 204 minRunTime = diffTime; 205 if (diffTime > maxRunTime) 206 maxRunTime = diffTime; 207 208 state = PREEMPTED; 209 lastTime = entry->Time(); 210 } else if (state == RUNNING) { 211 // thread starts waiting (it hadn't been added to the run 212 // queue before being unscheduled) 213 bigtime_t diffTime = entry->Time() - lastTime; 214 runs++; 215 totalRunTime += diffTime; 216 if (minRunTime < 0 || diffTime < minRunTime) 217 minRunTime = diffTime; 218 if (diffTime > maxRunTime) 219 maxRunTime = diffTime; 220 221 state = WAITING; 222 lastTime = entry->Time(); 223 } 224 } 225 } else if (EnqueueThread* entry 226 = dynamic_cast<EnqueueThread*>(_entry)) { 227 if (entry->ThreadID() != threadID) 228 continue; 229 230 // thread enqueued in run queue 231 232 if (state == RUNNING || state == STILL_RUNNING) { 233 // Thread was running and is reentered into the run queue. This 234 // is done by the scheduler, if the thread remains ready. 235 state = STILL_RUNNING; 236 } else { 237 // Thread was waiting and is ready now. 238 lastTime = entry->Time(); 239 state = READY; 240 } 241 } else if (RemoveThread* entry = dynamic_cast<RemoveThread*>(_entry)) { 242 if (entry->ThreadID() != threadID) 243 continue; 244 245 // thread removed from run queue 246 247 // This really only happens when the thread priority is changed 248 // while the thread is ready. 249 250 if (state == RUNNING) { 251 // This should never happen. 252 bigtime_t diffTime = entry->Time() - lastTime; 253 runs++; 254 totalRunTime += diffTime; 255 if (minRunTime < 0 || diffTime < minRunTime) 256 minRunTime = diffTime; 257 if (diffTime > maxRunTime) 258 maxRunTime = diffTime; 259 } 260 261 state = WAITING; 262 } 263 } 264 265 // print results 266 if (runs == 0) { 267 kprintf("thread %" B_PRId64 " never ran.\n", threadID); 268 return 0; 269 } 270 271 kprintf("scheduling statistics for thread %" B_PRId64 ":\n", threadID); 272 kprintf("runs:\n"); 273 kprintf(" total #: %" B_PRId64 "\n", runs); 274 kprintf(" total: %" B_PRIdBIGTIME " us\n", totalRunTime); 275 kprintf(" average: %#.2f us\n", (double)totalRunTime / runs); 276 kprintf(" min: %" B_PRIdBIGTIME " us\n", minRunTime); 277 kprintf(" max: %" B_PRIdBIGTIME " us\n", maxRunTime); 278 279 if (latencies > 0) { 280 kprintf("scheduling latency after wake up:\n"); 281 kprintf(" total #: %" B_PRIdBIGTIME "\n", latencies); 282 kprintf(" total: %" B_PRIdBIGTIME " us\n", totalLatency); 283 kprintf(" average: %#.2f us\n", (double)totalLatency / latencies); 284 kprintf(" min: %" B_PRIdBIGTIME " us\n", minLatency); 285 kprintf(" max: %" B_PRIdBIGTIME " us\n", maxLatency); 286 kprintf(" max: %" B_PRIdBIGTIME " us (at tracing entry %" B_PRId32 287 ")\n", maxLatency, maxLatencyEntry); 288 } else 289 kprintf("thread was never run after having been woken up\n"); 290 291 if (reruns > 0) { 292 kprintf("scheduling latency after preemption:\n"); 293 kprintf(" total #: %" B_PRId64 "\n", reruns); 294 kprintf(" total: %" B_PRIdBIGTIME " us\n", totalRerunTime); 295 kprintf(" average: %#.2f us\n", (double)totalRerunTime / reruns); 296 kprintf(" min: %" B_PRIdBIGTIME " us\n", minRerunTime); 297 kprintf(" max: %" B_PRIdBIGTIME " us (at tracing entry %" B_PRId32 298 ")\n", maxRerunTime, maxRerunEntry); 299 } else 300 kprintf("thread was never rerun after preemption\n"); 301 302 if (preemptions > 0) 303 kprintf("thread was preempted %" B_PRId64 " times\n", preemptions); 304 else 305 kprintf("thread was never preempted\n"); 306 307 return 0; 308 } 309 310 #endif // SCHEDULER_TRACING 311