root/src/system/kernel/scheduler/scheduler_tracing.cpp
/*
 * 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 <debug.h>


#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<SchedulerTraceEntry*>(_entry) == NULL)
                        continue;

                if (ScheduleThread* entry = dynamic_cast<ScheduleThread*>(_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<EnqueueThread*>(_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<RemoveThread*>(_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