/* * Copyright 2008, Ingo Weinhold, ingo_weinhold@gmx.de. * Copyright 2002-2007, Axel Dörfler, axeld@pinc-software.de. * Distributed under the terms of the MIT License. */ #include "scheduler_tracing.h" #include #if SCHEDULER_TRACING namespace SchedulerTracing { // #pragma mark - EnqueueThread void EnqueueThread::AddDump(TraceOutput& out) { out.Print("scheduler enqueue %" B_PRId32 " \"%s\", effective priority %" B_PRId32 ", real priority %" B_PRId32, fID, fName, fEffectivePriority, fPriority); } const char* EnqueueThread::Name() const { return fName; } // #pragma mark - RemoveThread void RemoveThread::AddDump(TraceOutput& out) { out.Print("scheduler remove %" B_PRId32 ", priority %" B_PRId32, fID, fPriority); } const char* RemoveThread::Name() const { return NULL; } // #pragma mark - ScheduleThread void ScheduleThread::AddDump(TraceOutput& out) { out.Print("schedule %" B_PRId32 " \"%s\", priority %" B_PRId32 ", CPU %" B_PRId32 ", previous thread: %" B_PRId32 " (", fID, fName, fPriority, fCPU, fPreviousID); if (fPreviousState == B_THREAD_WAITING) { switch (fPreviousWaitObjectType) { case THREAD_BLOCK_TYPE_SEMAPHORE: out.Print("sem %" B_PRId32, (sem_id)(addr_t)fPreviousWaitObject); break; case THREAD_BLOCK_TYPE_CONDITION_VARIABLE: out.Print("cvar %p", fPreviousWaitObject); break; case THREAD_BLOCK_TYPE_SNOOZE: out.Print("snooze()"); break; case THREAD_BLOCK_TYPE_SIGNAL: out.Print("signal"); break; case THREAD_BLOCK_TYPE_MUTEX: out.Print("mutex %p", fPreviousWaitObject); break; case THREAD_BLOCK_TYPE_RW_LOCK: out.Print("rwlock %p", fPreviousWaitObject); break; case THREAD_BLOCK_TYPE_USER: out.Print("_user_block_thread()"); break; case THREAD_BLOCK_TYPE_OTHER: out.Print("other (%p)", fPreviousWaitObject); // We could print the string, but it might come from a // kernel module that has already been unloaded. break; case THREAD_BLOCK_TYPE_OTHER_OBJECT: out.Print("other object (%p)", fPreviousWaitObject); break; default: out.Print("unknown (%p)", fPreviousWaitObject); break; } #if SCHEDULER_TRACING >= 2 } else if (fPreviousState == B_THREAD_READY) { out.Print("ready at %p", fPreviousPC); #endif } else out.Print("%s", thread_state_to_text(NULL, fPreviousState)); out.Print(")"); } const char* ScheduleThread::Name() const { return fName; } } // namespace SchedulerTracing // #pragma mark - int cmd_scheduler(int argc, char** argv) { using namespace SchedulerTracing; int64 threadID; if (argc != 2 || !evaluate_debug_expression(argv[1], (uint64*)&threadID, true)) { print_debugger_command_usage(argv[0]); return 0; } if (threadID <= 0) { kprintf("Invalid thread ID: %" B_PRId64 "\n", threadID); return 0; } ScheduleState state = UNKNOWN; bigtime_t lastTime = 0; int64 runs = 0; bigtime_t totalRunTime = 0; bigtime_t minRunTime = -1; bigtime_t maxRunTime = -1; int64 latencies = 0; bigtime_t totalLatency = 0; bigtime_t minLatency = -1; bigtime_t maxLatency = -1; int32 maxLatencyEntry = -1; int64 reruns = 0; bigtime_t totalRerunTime = 0; bigtime_t minRerunTime = -1; bigtime_t maxRerunTime = -1; int32 maxRerunEntry = -1; int64 preemptions = 0; TraceEntryIterator iterator; while (TraceEntry* _entry = iterator.Next()) { if (dynamic_cast(_entry) == NULL) continue; if (ScheduleThread* entry = dynamic_cast(_entry)) { if (entry->ThreadID() == threadID) { // thread scheduled bigtime_t diffTime = entry->Time() - lastTime; if (state == READY) { // thread scheduled after having been woken up latencies++; totalLatency += diffTime; if (minLatency < 0 || diffTime < minLatency) minLatency = diffTime; if (diffTime > maxLatency) { maxLatency = diffTime; maxLatencyEntry = iterator.Index(); } } else if (state == PREEMPTED) { // thread scheduled after having been preempted before reruns++; totalRerunTime += diffTime; if (minRerunTime < 0 || diffTime < minRerunTime) minRerunTime = diffTime; if (diffTime > maxRerunTime) { maxRerunTime = diffTime; maxRerunEntry = iterator.Index(); } } if (state == STILL_RUNNING) { // Thread was running and continues to run. state = RUNNING; } if (state != RUNNING) { lastTime = entry->Time(); state = RUNNING; } } else if (entry->PreviousThreadID() == threadID) { // thread unscheduled bigtime_t diffTime = entry->Time() - lastTime; if (state == STILL_RUNNING) { // thread preempted runs++; preemptions++; totalRunTime += diffTime; if (minRunTime < 0 || diffTime < minRunTime) minRunTime = diffTime; if (diffTime > maxRunTime) maxRunTime = diffTime; state = PREEMPTED; lastTime = entry->Time(); } else if (state == RUNNING) { // thread starts waiting (it hadn't been added to the run // queue before being unscheduled) bigtime_t diffTime = entry->Time() - lastTime; runs++; totalRunTime += diffTime; if (minRunTime < 0 || diffTime < minRunTime) minRunTime = diffTime; if (diffTime > maxRunTime) maxRunTime = diffTime; state = WAITING; lastTime = entry->Time(); } } } else if (EnqueueThread* entry = dynamic_cast(_entry)) { if (entry->ThreadID() != threadID) continue; // thread enqueued in run queue if (state == RUNNING || state == STILL_RUNNING) { // Thread was running and is reentered into the run queue. This // is done by the scheduler, if the thread remains ready. state = STILL_RUNNING; } else { // Thread was waiting and is ready now. lastTime = entry->Time(); state = READY; } } else if (RemoveThread* entry = dynamic_cast(_entry)) { if (entry->ThreadID() != threadID) continue; // thread removed from run queue // This really only happens when the thread priority is changed // while the thread is ready. if (state == RUNNING) { // This should never happen. bigtime_t diffTime = entry->Time() - lastTime; runs++; totalRunTime += diffTime; if (minRunTime < 0 || diffTime < minRunTime) minRunTime = diffTime; if (diffTime > maxRunTime) maxRunTime = diffTime; } state = WAITING; } } // print results if (runs == 0) { kprintf("thread %" B_PRId64 " never ran.\n", threadID); return 0; } kprintf("scheduling statistics for thread %" B_PRId64 ":\n", threadID); kprintf("runs:\n"); kprintf(" total #: %" B_PRId64 "\n", runs); kprintf(" total: %" B_PRIdBIGTIME " us\n", totalRunTime); kprintf(" average: %#.2f us\n", (double)totalRunTime / runs); kprintf(" min: %" B_PRIdBIGTIME " us\n", minRunTime); kprintf(" max: %" B_PRIdBIGTIME " us\n", maxRunTime); if (latencies > 0) { kprintf("scheduling latency after wake up:\n"); kprintf(" total #: %" B_PRIdBIGTIME "\n", latencies); kprintf(" total: %" B_PRIdBIGTIME " us\n", totalLatency); kprintf(" average: %#.2f us\n", (double)totalLatency / latencies); kprintf(" min: %" B_PRIdBIGTIME " us\n", minLatency); kprintf(" max: %" B_PRIdBIGTIME " us\n", maxLatency); kprintf(" max: %" B_PRIdBIGTIME " us (at tracing entry %" B_PRId32 ")\n", maxLatency, maxLatencyEntry); } else kprintf("thread was never run after having been woken up\n"); if (reruns > 0) { kprintf("scheduling latency after preemption:\n"); kprintf(" total #: %" B_PRId64 "\n", reruns); kprintf(" total: %" B_PRIdBIGTIME " us\n", totalRerunTime); kprintf(" average: %#.2f us\n", (double)totalRerunTime / reruns); kprintf(" min: %" B_PRIdBIGTIME " us\n", minRerunTime); kprintf(" max: %" B_PRIdBIGTIME " us (at tracing entry %" B_PRId32 ")\n", maxRerunTime, maxRerunEntry); } else kprintf("thread was never rerun after preemption\n"); if (preemptions > 0) kprintf("thread was preempted %" B_PRId64 " times\n", preemptions); else kprintf("thread was never preempted\n"); return 0; } #endif // SCHEDULER_TRACING