src/system/kernel/scheduler/scheduler_profiler.cpp

   1 /*
   2  * Copyright 2013, Paweł Dziepak, pdziepak@quarnos.org.
   3  * Distributed under the terms of the MIT License.
   4  */
   5
   6 #include "scheduler_profiler.h"
   7
   8 #include <debug.h>
   9 #include <util/AutoLock.h>
  10
  11 #include <algorithm>
  12
  13
  14 #ifdef SCHEDULER_PROFILING
  15
  16
  17 using namespace Scheduler;
  18 using namespace Scheduler::Profiling;
  19
  20
  21 static Profiler* sProfiler;
  22
  23 static int dump_profiler(int argc, char** argv);
  24
  25
  26 Profiler::Profiler()
  27         :
  28         kMaxFunctionEntries(1024),
  29         kMaxFunctionStackEntries(512),
  30         fFunctionData(new(std::nothrow) FunctionData[kMaxFunctionEntries]),
  31         fStatus(B_OK)
  32 {
  33         B_INITIALIZE_SPINLOCK(&fFunctionLock);
  34
  35         if (fFunctionData == NULL) {
  36                 fStatus = B_NO_MEMORY;
  37                 return;
  38         }
  39         memset(fFunctionData, 0, sizeof(FunctionData) * kMaxFunctionEntries);
  40
  41         for (int32 i = 0; i < smp_get_num_cpus(); i++) {
  42                 fFunctionStacks[i]
  43                         = new(std::nothrow) FunctionEntry[kMaxFunctionStackEntries];
  44                 if (fFunctionStacks[i] == NULL) {
  45                         fStatus = B_NO_MEMORY;
  46                         return;
  47                 }
  48                 memset(fFunctionStacks[i], 0,
  49                         sizeof(FunctionEntry) * kMaxFunctionStackEntries);
  50         }
  51         memset(fFunctionStackPointers, 0, sizeof(int32) * smp_get_num_cpus());
  52 }
  53
  54
  55 void
  56 Profiler::EnterFunction(int32 cpu, const char* functionName)
  57 {
  58         nanotime_t start = system_time_nsecs();
  59
  60         FunctionData* function = _FindFunction(functionName);
  61         if (function == NULL)
  62                 return;
  63         atomic_add((int32*)&function->fCalled, 1);
  64
  65         FunctionEntry* stackEntry
  66                 = &fFunctionStacks[cpu][fFunctionStackPointers[cpu]];
  67         fFunctionStackPointers[cpu]++;
  68
  69         ASSERT(fFunctionStackPointers[cpu] < kMaxFunctionStackEntries);
  70
  71         stackEntry->fFunction = function;
  72         stackEntry->fEntryTime = start;
  73         stackEntry->fOthersTime = 0;
  74
  75         nanotime_t stop = system_time_nsecs();
  76         stackEntry->fProfilerTime = stop - start;
  77 }
  78
  79
  80 void
  81 Profiler::ExitFunction(int32 cpu, const char* functionName)
  82 {
  83         nanotime_t start = system_time_nsecs();
  84
  85         ASSERT(fFunctionStackPointers[cpu] > 0);
  86         fFunctionStackPointers[cpu]--;
  87         FunctionEntry* stackEntry
  88                 = &fFunctionStacks[cpu][fFunctionStackPointers[cpu]];
  89
  90         nanotime_t timeSpent = start - stackEntry->fEntryTime;
  91         timeSpent -= stackEntry->fProfilerTime;
  92
  93         atomic_add64(&stackEntry->fFunction->fTimeInclusive, timeSpent);
  94         atomic_add64(&stackEntry->fFunction->fTimeExclusive,
  95                 timeSpent - stackEntry->fOthersTime);
  96
  97         nanotime_t profilerTime = stackEntry->fProfilerTime;
  98         if (fFunctionStackPointers[cpu] > 0) {
  99                 stackEntry = &fFunctionStacks[cpu][fFunctionStackPointers[cpu] - 1];
 100                 stackEntry->fOthersTime += timeSpent;
 101                 stackEntry->fProfilerTime += profilerTime;
 102
 103                 nanotime_t stop = system_time_nsecs();
 104                 stackEntry->fProfilerTime += stop - start;
 105         }
 106 }
 107
 108
 109 void
 110 Profiler::DumpCalled(uint32 maxCount)
 111 {
 112         uint32 count = _FunctionCount();
 113
 114         qsort(fFunctionData, count, sizeof(FunctionData),
 115                 &_CompareFunctions<uint32, &FunctionData::fCalled>);
 116
 117         if (maxCount > 0)
 118                 count = std::min(count, maxCount);
 119         _Dump(count);
 120 }
 121
 122
 123 void
 124 Profiler::DumpTimeInclusive(uint32 maxCount)
 125 {
 126         uint32 count = _FunctionCount();
 127
 128         qsort(fFunctionData, count, sizeof(FunctionData),
 129                 &_CompareFunctions<nanotime_t, &FunctionData::fTimeInclusive>);
 130
 131         if (maxCount > 0)
 132                 count = std::min(count, maxCount);
 133         _Dump(count);
 134 }
 135
 136
 137 void
 138 Profiler::DumpTimeExclusive(uint32 maxCount)
 139 {
 140         uint32 count = _FunctionCount();
 141
 142         qsort(fFunctionData, count, sizeof(FunctionData),
 143                 &_CompareFunctions<nanotime_t, &FunctionData::fTimeExclusive>);
 144
 145         if (maxCount > 0)
 146                 count = std::min(count, maxCount);
 147         _Dump(count);
 148 }
 149
 150
 151 void
 152 Profiler::DumpTimeInclusivePerCall(uint32 maxCount)
 153 {
 154         uint32 count = _FunctionCount();
 155
 156         qsort(fFunctionData, count, sizeof(FunctionData),
 157                 &_CompareFunctionsPerCall<nanotime_t, &FunctionData::fTimeInclusive>);
 158
 159         if (maxCount > 0)
 160                 count = std::min(count, maxCount);
 161         _Dump(count);
 162 }
 163
 164
 165 void
 166 Profiler::DumpTimeExclusivePerCall(uint32 maxCount)
 167 {
 168         uint32 count = _FunctionCount();
 169
 170         qsort(fFunctionData, count, sizeof(FunctionData),
 171                 &_CompareFunctionsPerCall<nanotime_t, &FunctionData::fTimeExclusive>);
 172
 173         if (maxCount > 0)
 174                 count = std::min(count, maxCount);
 175         _Dump(count);
 176 }
 177
 178
 179 /* static */ Profiler*
 180 Profiler::Get()
 181 {
 182         return sProfiler;
 183 }
 184
 185
 186 /* static */ void
 187 Profiler::Initialize()
 188 {
 189         sProfiler = new(std::nothrow) Profiler;
 190         if (sProfiler == NULL || sProfiler->GetStatus() != B_OK)
 191                 panic("Scheduler::Profiling::Profiler: could not initialize profiler");
 192
 193         add_debugger_command_etc("scheduler_profiler", &dump_profiler,
 194                 "Show data collected by scheduler profiler",
 195                 "[ <field> [ <count> ] ]\n"
 196                 "Shows data collected by scheduler profiler\n"
 197                 "  <field>   - Field used to sort functions. Available: called,"
 198                         " time-inclusive, time-inclusive-per-call, time-exclusive,"
 199                         " time-exclusive-per-call.\n"
 200                 "              (defaults to \"called\")\n"
 201                 "  <count>   - Maximum number of showed functions.\n", 0);
 202 }
 203
 204
 205 uint32
 206 Profiler::_FunctionCount() const
 207 {
 208         uint32 count;
 209         for (count = 0; count < kMaxFunctionEntries; count++) {
 210                 if (fFunctionData[count].fFunction == NULL)
 211                         break;
 212         }
 213         return count;
 214 }
 215
 216
 217 void
 218 Profiler::_Dump(uint32 count)
 219 {
 220         kprintf("Function calls (%" B_PRId32 " functions):\n", count);
 221         kprintf("    called time-inclusive per-call time-exclusive per-call "
 222                 "function\n");
 223         for (uint32 i = 0; i < count; i++) {
 224                 FunctionData* function = &fFunctionData[i];
 225                 kprintf("%10" B_PRId32 " %14" B_PRId64 " %8" B_PRId64 " %14" B_PRId64
 226                         " %8" B_PRId64 " %s\n", function->fCalled,
 227                         function->fTimeInclusive,
 228                         function->fTimeInclusive / function->fCalled,
 229                         function->fTimeExclusive,
 230                         function->fTimeExclusive / function->fCalled, function->fFunction);
 231         }
 232 }
 233
 234
 235 Profiler::FunctionData*
 236 Profiler::_FindFunction(const char* function)
 237 {
 238         for (uint32 i = 0; i < kMaxFunctionEntries; i++) {
 239                 if (fFunctionData[i].fFunction == NULL)
 240                         break;
 241                 if (!strcmp(fFunctionData[i].fFunction, function))
 242                         return fFunctionData + i;
 243         }
 244
 245         SpinLocker _(fFunctionLock);
 246         for (uint32 i = 0; i < kMaxFunctionEntries; i++) {
 247                 if (fFunctionData[i].fFunction == NULL) {
 248                         fFunctionData[i].fFunction = function;
 249                         return fFunctionData + i;
 250                 }
 251                 if (!strcmp(fFunctionData[i].fFunction, function))
 252                         return fFunctionData + i;
 253         }
 254
 255         return NULL;
 256 }
 257
 258
 259 template<typename Type, Type Profiler::FunctionData::*Member>
 260 /* static */ int
 261 Profiler::_CompareFunctions(const void* _a, const void* _b)
 262 {
 263         const FunctionData* a = static_cast<const FunctionData*>(_a);
 264         const FunctionData* b = static_cast<const FunctionData*>(_b);
 265
 266         if (b->*Member > a->*Member)
 267                 return 1;
 268         if (b->*Member < a->*Member)
 269                 return -1;
 270         return 0;
 271 }
 272
 273
 274 template<typename Type, Type Profiler::FunctionData::*Member>
 275 /* static */ int
 276 Profiler::_CompareFunctionsPerCall(const void* _a, const void* _b)
 277 {
 278         const FunctionData* a = static_cast<const FunctionData*>(_a);
 279         const FunctionData* b = static_cast<const FunctionData*>(_b);
 280
 281         Type valueA = a->*Member / a->fCalled;
 282         Type valueB = b->*Member / b->fCalled;
 283
 284         if (valueB > valueA)
 285                 return 1;
 286         if (valueB < valueA)
 287                 return -1;
 288         return 0;
 289 }
 290
 291
 292 static int
 293 dump_profiler(int argc, char** argv)
 294 {
 295         if (argc < 2) {
 296                 Profiler::Get()->DumpCalled(0);
 297                 return 0;
 298         }
 299
 300         int32 count = 0;
 301         if (argc >= 3)
 302                 count = parse_expression(argv[2]);
 303         count = std::max(count, int32(0));
 304
 305         if (!strcmp(argv[1], "called"))
 306                 Profiler::Get()->DumpCalled(count);
 307         else if (!strcmp(argv[1], "time-inclusive"))
 308                 Profiler::Get()->DumpTimeInclusive(count);
 309         else if (!strcmp(argv[1], "time-inclusive-per-call"))
 310                 Profiler::Get()->DumpTimeInclusivePerCall(count);
 311         else if (!strcmp(argv[1], "time-exclusive"))
 312                 Profiler::Get()->DumpTimeExclusive(count);
 313         else if (!strcmp(argv[1], "time-exclusive-per-call"))
 314                 Profiler::Get()->DumpTimeExclusivePerCall(count);
 315         else
 316                 print_debugger_command_usage(argv[0]);
 317
 318         return 0;
 319 }
 320
 321
 322 #endif  // SCHEDULER_PROFILING
 323