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 <[email protected]>
Tested-by: Commit checker robot <[email protected]>
Reviewed-by: Adrien Destugues <[email protected]>

headers/os/kernel/debugger.h

@@ -622,6 +622,7 @@ typedef struct {
 										//   <sample 1> ... <sample stack_depth>
 	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

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

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,

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;
 };

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)
 {

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;

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;

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)
 {

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);

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()
 {

src/bin/debug/profile/Thread.h

@@ -36,8 +36,8 @@ private:
 class Thread : public ProfiledEntity, public DoublyLinkedListLinkImpl<Thread>,
 	private ImageProfileResultContainer {
 public:
-								Thread(thread_id threadID, const char* name,
+								Thread(Team* team, thread_id threadID,
-									Team* team);
+									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;

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());
 				}

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;
 

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;