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_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* 109 ScheduleThread::Name() const 110 { 111 return fName; 112 } 113 114 } // namespace SchedulerTracing 115 116 117 // #pragma mark - 118 119 120 int 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