From 2813fd13caff246f423f067ca0873f573a768cc6 Mon Sep 17 00:00:00 2001 From: Augustin Cavalier Date: Fri, 28 Jun 2024 12:13:54 -0400 Subject: [PATCH] profiler: Report CPU times and use them to compute "missed" ticks. This shows that the profiler is still pretty broken, because we are missing quite a lot of ticks on average. One run of "profile pkgman search" here produced an output with 66 total ticks and 423 (!) missed ticks. A brief run of WebPositive was not quite as bad (main thread: 1078 total ticks, 157 missed ticks.) Change-Id: Idfc34534e66eff0fe7e948fcc3576be09db879a3 Reviewed-on: https://review.haiku-os.org/c/haiku/+/7820 Reviewed-by: waddlesplash Tested-by: Commit checker robot Reviewed-by: Adrien Destugues --- headers/os/kernel/debugger.h | 1 + headers/private/system/system_profiler_defs.h | 2 ++ src/bin/debug/profile/BasicProfileResult.cpp | 16 +++++++++++++ src/bin/debug/profile/BasicProfileResult.h | 2 ++ .../debug/profile/CallgrindProfileResult.cpp | 8 +++++++ .../debug/profile/CallgrindProfileResult.h | 2 ++ src/bin/debug/profile/ProfileResult.h | 2 ++ .../debug/profile/SummaryProfileResult.cpp | 7 ++++++ src/bin/debug/profile/SummaryProfileResult.h | 1 + src/bin/debug/profile/Thread.cpp | 18 +++++++++++--- src/bin/debug/profile/Thread.h | 9 ++++--- src/bin/debug/profile/profile.cpp | 24 +++++++++++++++---- src/system/kernel/debug/system_profiler.cpp | 8 +++++++ src/system/kernel/debug/user_debugger.cpp | 11 +++++++++ 14 files changed, 100 insertions(+), 11 deletions(-) diff --git a/headers/os/kernel/debugger.h b/headers/os/kernel/debugger.h index 00b3d238e1..c2ac40b1f0 100644 --- a/headers/os/kernel/debugger.h +++ b/headers/os/kernel/debugger.h @@ -622,6 +622,7 @@ typedef struct { // ... bool stopped; // if true, the thread is no longer // being profiled + bigtime_t last_cpu_time; // only set if "stopped" is } debug_profiler_update; // B_DEBUGGER_MESSAGE_HANDED_OVER diff --git a/headers/private/system/system_profiler_defs.h b/headers/private/system/system_profiler_defs.h index 18218393e1..64a1a35526 100644 --- a/headers/private/system/system_profiler_defs.h +++ b/headers/private/system/system_profiler_defs.h @@ -112,12 +112,14 @@ struct system_profiler_thread_added { team_id team; thread_id thread; char name[B_OS_NAME_LENGTH]; + bigtime_t cpu_time; }; // B_SYSTEM_PROFILER_THREAD_REMOVED struct system_profiler_thread_removed { team_id team; thread_id thread; + bigtime_t cpu_time; }; // B_SYSTEM_PROFILER_IMAGE_ADDED diff --git a/src/bin/debug/profile/BasicProfileResult.cpp b/src/bin/debug/profile/BasicProfileResult.cpp index 21eb0e42dd..e7573412e0 100644 --- a/src/bin/debug/profile/BasicProfileResult.cpp +++ b/src/bin/debug/profile/BasicProfileResult.cpp @@ -119,12 +119,20 @@ BasicProfileResult::BasicProfileResult() : fTotalTicks(0), fUnkownTicks(0), + fExpectedTicks(0), fDroppedTicks(0), fTotalSampleCount(0) { } +void +BasicProfileResult::AddExpectedTicks(int32 expected) +{ + fExpectedTicks += expected; +} + + void BasicProfileResult::AddDroppedTicks(int32 dropped) { @@ -172,6 +180,8 @@ BasicProfileResult::PrintResults(ImageProfileResultContainer* container) std::sort(hitSymbols, hitSymbols + hitSymbolCount); int64 totalTicks = fTotalTicks; + const int64 missedTicks = fExpectedTicks - fTotalTicks; + fprintf(gOptions.output, "\nprofiling results for %s \"%s\" " "(%" B_PRId32 "):\n", fEntity->EntityType(), fEntity->EntityName(), fEntity->EntityID()); @@ -180,8 +190,14 @@ BasicProfileResult::PrintResults(ImageProfileResultContainer* container) fprintf(gOptions.output, " total ticks: %" B_PRId64 " (%" B_PRId64 " us)\n", totalTicks, totalTicks * fInterval); + if (fExpectedTicks != 0) { + fprintf(gOptions.output, + " expected ticks: %" B_PRId64 " (missed %" B_PRId64 ")\n", + fExpectedTicks, missedTicks); + } if (totalTicks == 0) totalTicks = 1; + fprintf(gOptions.output, " unknown ticks: %" B_PRId64 " (%" B_PRId64 " us, %6.2f%%)\n", fUnkownTicks, fUnkownTicks * fInterval, diff --git a/src/bin/debug/profile/BasicProfileResult.h b/src/bin/debug/profile/BasicProfileResult.h index de159ca31a..572d37a400 100644 --- a/src/bin/debug/profile/BasicProfileResult.h +++ b/src/bin/debug/profile/BasicProfileResult.h @@ -36,6 +36,7 @@ class BasicProfileResult : public ProfileResult { public: BasicProfileResult(); + virtual void AddExpectedTicks(int32 expected); virtual void AddDroppedTicks(int32 dropped); virtual void PrintResults( ImageProfileResultContainer* container); @@ -47,6 +48,7 @@ public: protected: int64 fTotalTicks; int64 fUnkownTicks; + int64 fExpectedTicks; int64 fDroppedTicks; int64 fTotalSampleCount; }; diff --git a/src/bin/debug/profile/CallgrindProfileResult.cpp b/src/bin/debug/profile/CallgrindProfileResult.cpp index 313c481531..e5bb809f22 100644 --- a/src/bin/debug/profile/CallgrindProfileResult.cpp +++ b/src/bin/debug/profile/CallgrindProfileResult.cpp @@ -122,6 +122,7 @@ CallgrindProfileResult::CallgrindProfileResult() : fTotalTicks(0), fUnkownTicks(0), + fExpectedTicks(0), fDroppedTicks(0), fNextImageOutputIndex(1), fNextFunctionOutputIndex(1) @@ -163,6 +164,13 @@ CallgrindProfileResult::AddSamples(ImageProfileResultContainer* container, } +void +CallgrindProfileResult::AddExpectedTicks(int32 expected) +{ + fExpectedTicks += expected; +} + + void CallgrindProfileResult::AddDroppedTicks(int32 dropped) { diff --git a/src/bin/debug/profile/CallgrindProfileResult.h b/src/bin/debug/profile/CallgrindProfileResult.h index 1407d0c82e..4febc207b0 100644 --- a/src/bin/debug/profile/CallgrindProfileResult.h +++ b/src/bin/debug/profile/CallgrindProfileResult.h @@ -70,6 +70,7 @@ public: virtual void AddSamples( ImageProfileResultContainer* container, addr_t* samples, int32 sampleCount); + virtual void AddExpectedTicks(int32 expected); virtual void AddDroppedTicks(int32 dropped); virtual void PrintResults( ImageProfileResultContainer* container); @@ -85,6 +86,7 @@ private: private: int64 fTotalTicks; int64 fUnkownTicks; + int64 fExpectedTicks; int64 fDroppedTicks; int32 fNextImageOutputIndex; int32 fNextFunctionOutputIndex; diff --git a/src/bin/debug/profile/ProfileResult.h b/src/bin/debug/profile/ProfileResult.h index 009b699923..563ece3068 100644 --- a/src/bin/debug/profile/ProfileResult.h +++ b/src/bin/debug/profile/ProfileResult.h @@ -70,11 +70,13 @@ public: ProfiledEntity* Entity() const { return fEntity; } virtual void SetInterval(bigtime_t interval); + bigtime_t Interval() const { return fInterval; } virtual void AddSamples( ImageProfileResultContainer* container, addr_t* samples, int32 sampleCount) = 0; + virtual void AddExpectedTicks(int32 expected) = 0; virtual void AddDroppedTicks(int32 dropped) = 0; virtual void PrintResults( ImageProfileResultContainer* container) = 0; diff --git a/src/bin/debug/profile/SummaryProfileResult.cpp b/src/bin/debug/profile/SummaryProfileResult.cpp index 40f19fcc25..ee9e9e3977 100644 --- a/src/bin/debug/profile/SummaryProfileResult.cpp +++ b/src/bin/debug/profile/SummaryProfileResult.cpp @@ -75,6 +75,13 @@ SummaryProfileResult::AddSamples(ImageProfileResultContainer* container, } +void +SummaryProfileResult::AddExpectedTicks(int32 expected) +{ + fResult->AddExpectedTicks(expected); +} + + void SummaryProfileResult::AddDroppedTicks(int32 dropped) { diff --git a/src/bin/debug/profile/SummaryProfileResult.h b/src/bin/debug/profile/SummaryProfileResult.h index 57fdd274c7..a5d9a3d246 100644 --- a/src/bin/debug/profile/SummaryProfileResult.h +++ b/src/bin/debug/profile/SummaryProfileResult.h @@ -66,6 +66,7 @@ public: virtual void AddSamples( ImageProfileResultContainer* container, addr_t* samples, int32 sampleCount); + virtual void AddExpectedTicks(int32 expected); virtual void AddDroppedTicks(int32 dropped); virtual void PrintResults( ImageProfileResultContainer* container); diff --git a/src/bin/debug/profile/Thread.cpp b/src/bin/debug/profile/Thread.cpp index b8cec22651..4c101ba082 100644 --- a/src/bin/debug/profile/Thread.cpp +++ b/src/bin/debug/profile/Thread.cpp @@ -38,14 +38,15 @@ ThreadImage::~ThreadImage() } -// #pragma mark - ThreadI +// #pragma mark - Thread -Thread::Thread(thread_id threadID, const char* name, Team* team) +Thread::Thread(Team* team, thread_id threadID, const char* name, bigtime_t initialCPUTime) : + fTeam(team), fID(threadID), fName(name), - fTeam(team), + fLastCPUTime(initialCPUTime), fSampleArea(-1), fSamples(NULL), fProfileResult(NULL), @@ -227,6 +228,17 @@ Thread::AddSamples(addr_t* samples, int32 sampleCount) } +void +Thread::UpdateCPUTime(bigtime_t time) +{ + bigtime_t elapsed = time - fLastCPUTime; + int64 expectedTicks = elapsed / fProfileResult->Interval(); + fLastCPUTime = time; + + fProfileResult->AddExpectedTicks(expectedTicks); +} + + void Thread::PrintResults() { diff --git a/src/bin/debug/profile/Thread.h b/src/bin/debug/profile/Thread.h index 95245d38b1..1b13112bfd 100644 --- a/src/bin/debug/profile/Thread.h +++ b/src/bin/debug/profile/Thread.h @@ -36,8 +36,8 @@ private: class Thread : public ProfiledEntity, public DoublyLinkedListLinkImpl, private ImageProfileResultContainer { public: - Thread(thread_id threadID, const char* name, - Team* team); + Thread(Team* team, thread_id threadID, + const char* name, bigtime_t initialCPUTime); virtual ~Thread(); inline thread_id ID() const; @@ -66,6 +66,8 @@ public: int32 stackDepth, bool variableStackDepth, int32 event); void AddSamples(addr_t* samples, int32 sampleCount); + void UpdateCPUTime(bigtime_t time); + void PrintResults(); private: @@ -82,9 +84,10 @@ private: void _SynchronizeImages(int32 event); private: + ::Team* fTeam; thread_id fID; BString fName; - ::Team* fTeam; + bigtime_t fLastCPUTime; area_id fSampleArea; addr_t* fSamples; ProfileResult* fProfileResult; diff --git a/src/bin/debug/profile/profile.cpp b/src/bin/debug/profile/profile.cpp index 1fc67f3d26..acd28fef3e 100644 --- a/src/bin/debug/profile/profile.cpp +++ b/src/bin/debug/profile/profile.cpp @@ -162,10 +162,11 @@ public: if (error != B_OK) return error; - return AddThread(threadInfo.team, threadID, threadInfo.name); + return AddThread(threadInfo.team, threadID, threadInfo.name, + threadInfo.kernel_time + threadInfo.user_time); } - status_t AddThread(team_id teamID, thread_id threadID, const char* name) + status_t AddThread(team_id teamID, thread_id threadID, const char* name, bigtime_t cpuTime) { if (FindThread(threadID) != NULL) return B_BAD_VALUE; @@ -174,7 +175,7 @@ public: if (team == NULL) return B_BAD_TEAM_ID; - Thread* thread = new(std::nothrow) Thread(threadID, name, team); + Thread* thread = new(std::nothrow) Thread(team, threadID, name, cpuTime); if (thread == NULL) return B_NO_MEMORY; @@ -578,7 +579,7 @@ process_event_buffer(ThreadManager& threadManager, uint8* buffer, = (system_profiler_thread_added*)buffer; if (threadManager.AddThread(event->team, event->thread, - event->name) != B_OK) { + event->name, event->cpu_time) != B_OK) { exit(1); } break; @@ -590,6 +591,7 @@ process_event_buffer(ThreadManager& threadManager, uint8* buffer, = (system_profiler_thread_removed*)buffer; if (Thread* thread = threadManager.FindThread(event->thread)) { + thread->UpdateCPUTime(event->cpu_time); thread->PrintResults(); threadManager.RemoveThread(event->thread); } @@ -765,8 +767,19 @@ profile_all(const char* const* programArgs, int programArgCount) // stop profiling _kern_system_profiler_stop(); + // fetch CPU time for all remaining threads + const int32 threadCount = threadManager.CountThreads(); + for (int32 i = 0; i < threadCount; i++) { + Thread* thread = threadManager.ThreadAt(i); + thread_info threadInfo; + status_t error = get_thread_info(thread->ID(), &threadInfo); + if (error != B_OK) + continue; + + thread->UpdateCPUTime(threadInfo.kernel_time + threadInfo.user_time); + } + // print results - int32 threadCount = threadManager.CountThreads(); for (int32 i = 0; i < threadCount; i++) { Thread* thread = threadManager.ThreadAt(i); thread->PrintResults(); @@ -919,6 +932,7 @@ profile_single(const char* const* programArgs, int programArgCount) message.profiler_update.image_event); if (message.profiler_update.stopped) { + thread->UpdateCPUTime(message.profiler_update.last_cpu_time); thread->PrintResults(); threadManager.RemoveThread(thread->ID()); } diff --git a/src/system/kernel/debug/system_profiler.cpp b/src/system/kernel/debug/system_profiler.cpp index 8a14549c19..5a864e85c3 100644 --- a/src/system/kernel/debug/system_profiler.cpp +++ b/src/system/kernel/debug/system_profiler.cpp @@ -976,6 +976,10 @@ SystemProfiler::_ThreadAdded(Thread* thread) event->team = thread->team->id; event->thread = thread->id; strlcpy(event->name, thread->name, sizeof(event->name)); + { + SpinLocker timeLocker(thread->time_lock); + event->cpu_time = thread->CPUTime(false); + } fHeader->size = fBufferSize; @@ -1003,6 +1007,10 @@ SystemProfiler::_ThreadRemoved(Thread* thread) event->team = thread->team->id; event->thread = thread->id; + { + SpinLocker timeLocker(thread->time_lock); + event->cpu_time = thread->CPUTime(false); + } fHeader->size = fBufferSize; diff --git a/src/system/kernel/debug/user_debugger.cpp b/src/system/kernel/debug/user_debugger.cpp index 4e318a734d..c9041d564b 100644 --- a/src/system/kernel/debug/user_debugger.cpp +++ b/src/system/kernel/debug/user_debugger.cpp @@ -1177,6 +1177,10 @@ user_debug_thread_exiting(Thread* thread) threadDebugInfo.profile.sample_area = -1; threadDebugInfo.profile.samples = NULL; threadDebugInfo.profile.buffer_full = false; + bigtime_t lastCPUTime; { + SpinLocker threadTimeLocker(thread->time_lock); + lastCPUTime = thread->CPUTime(false); + } atomic_or(&threadDebugInfo.flags, B_THREAD_DEBUG_DYING); @@ -1194,6 +1198,7 @@ user_debug_thread_exiting(Thread* thread) message.variable_stack_depth = variableStackDepth; message.image_event = imageEvent; message.stopped = true; + message.last_cpu_time = lastCPUTime; debugger_write(debuggerPort, B_DEBUGGER_MESSAGE_PROFILER_UPDATE, &message, sizeof(message), false); @@ -2375,6 +2380,7 @@ debug_nub_thread(void *) bool variableStackDepth = false; int32 imageEvent = 0; int32 droppedTicks = 0; + bigtime_t lastCPUTime = 0; // get the thread and detach the profile info Thread* thread = Thread::GetAndLock(threadID); @@ -2400,6 +2406,10 @@ debug_nub_thread(void *) threadDebugInfo.profile.samples = NULL; threadDebugInfo.profile.buffer_full = false; threadDebugInfo.profile.dropped_ticks = 0; + { + SpinLocker threadTimeLocker(thread->time_lock); + lastCPUTime = thread->CPUTime(false); + } } else result = B_BAD_VALUE; } else @@ -2417,6 +2427,7 @@ debug_nub_thread(void *) reply.profiler_update.sample_count = sampleCount; reply.profiler_update.dropped_ticks = droppedTicks; reply.profiler_update.stopped = true; + reply.profiler_update.last_cpu_time = lastCPUTime; } else reply.profiler_update.origin.thread = result;