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 17using namespace Scheduler; 18using namespace Scheduler::Profiling; 19 20 21static Profiler* sProfiler; 22 23static int dump_profiler(int argc, char** argv); 24 25 26Profiler::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 55void 56Profiler::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 80void 81Profiler::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 109void 110Profiler::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 123void 124Profiler::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 137void 138Profiler::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 151void 152Profiler::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 165void 166Profiler::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* 180Profiler::Get() 181{ 182 return sProfiler; 183} 184 185 186/* static */ void 187Profiler::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 205uint32 206Profiler::_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 217void 218Profiler::_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 235Profiler::FunctionData* 236Profiler::_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 259template<typename Type, Type Profiler::FunctionData::*Member> 260/* static */ int 261Profiler::_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 274template<typename Type, Type Profiler::FunctionData::*Member> 275/* static */ int 276Profiler::_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 292static int 293dump_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 324