kernel: Let user_debugger take care of tracking syscall runtime.

If we just use the kernel entry time, then the pre-syscall tracing
routine (with a debugger message send) will be counted in the syscall's
runtime.

Makes the output of timing in strace and strace -c much more accurate,
however it won't include the "syscall overhead" (time spent in the
syscall entry routines, etc.) But we already can't account for time
spent in the userland-to-kernel transition, so that should probably
be measured some other way if knowing it is desired.

In fact, on architectures which used the generic syscall dispatcher
(e.g. RISC-V), this is the behavior that already existed. So this just
makes x86 consistent with them.

Change-Id: I8cef6111e478ab49b0584e15575172eea77a8760
Reviewed-on: https://review.haiku-os.org/c/haiku/+/8240
Tested-by: Commit checker robot <[email protected]>
Reviewed-by: waddlesplash <[email protected]>

headers/private/kernel/user_debugger.h

@@ -122,8 +122,10 @@ struct thread_debug_info {
 
 	// profiling related part; if samples != NULL, the thread is profiled
 	struct {
-		bigtime_t		interval;
+		union {
-			// sampling interval
+			bigtime_t		interval;
+			bigtime_t		syscall_start_time;
+		};
 		area_id			sample_area;
 			// cloned sample buffer area
 		addr_t*			samples;
@@ -253,8 +255,7 @@ void init_user_debug();
 // debug event callbacks
 
 void user_debug_pre_syscall(uint32 syscall, void *args);
-void user_debug_post_syscall(uint32 syscall, void *args, uint64 returnValue,
+void user_debug_post_syscall(uint32 syscall, void *args, uint64 returnValue);
-		bigtime_t startTime);
 bool user_debug_exception_occurred(debug_exception_type exception, int signal);
 bool user_debug_handle_signal(int signal, struct sigaction *handler,
 		siginfo_t *info, bool deadly);

src/bin/debug/strace/strace.cpp

@@ -300,6 +300,9 @@ record_syscall_stats(const Syscall& syscall, debug_post_syscall& message)
 	syscall_stats& stats = sSyscallStats[syscall.Name()];
 	stats.count++;
 
+	if (message.start_time == 0)
+		return;
+
 	bigtime_t time = message.end_time - message.start_time;
 	stats.time += time;
 	sSyscallTime += time;
@@ -457,12 +460,14 @@ print_syscall(FILE *outputFile, Syscall* syscall, debug_post_syscall &message,
 			print_to_string(&string, &length, ")");
 	}
 
+	bigtime_t duration = 0;
+	if (message.start_time != 0)
+		duration = message.end_time - message.start_time;
 	if (colorize) {
 		print_to_string(&string, &length, " %s(%lld us)%s\n", kTerminalTextMagenta,
-			message.end_time - message.start_time, kTerminalTextNormal);
+			duration, kTerminalTextNormal);
 	} else {
-		print_to_string(&string, &length, " (%lld us)\n",
+		print_to_string(&string, &length, " (%lld us)\n", duration);
-			message.end_time - message.start_time);
 	}
 
 //for (int32 i = 0; i < 16; i++) {

src/system/kernel/arch/x86/32/interrupts.S

@@ -57,22 +57,6 @@
 	UPDATE_THREAD_USER_TIME_COMMON()						\
 	UNLOCK_THREAD_TIME()
 
-#define UPDATE_THREAD_USER_TIME_PUSH_TIME()					\
-	call	system_time;									\
-	push	%edx;											\
-	push	%eax;											\
-															\
-	LOCK_THREAD_TIME()										\
-															\
-	/* recover the system time, note that */				\
-	/* LOCK_THREAD_TIME() leaves an address on the stack */	\
-	movl	4(%esp), %eax;									\
-	movl	8(%esp), %edx;									\
-															\
-	UPDATE_THREAD_USER_TIME_COMMON()						\
-															\
-	UNLOCK_THREAD_TIME()
-
 #define UPDATE_THREAD_KERNEL_TIME()							\
 	LOCK_THREAD_TIME()										\
 															\
@@ -624,8 +608,7 @@ STATIC_FUNCTION(handle_syscall):
 	STOP_USER_DEBUGGING()
 
 	// update the thread's user time
-	UPDATE_THREAD_USER_TIME_PUSH_TIME()
+	UPDATE_THREAD_USER_TIME()
-		// leave the time on the stack (needed for post syscall debugging)
 
 	sti								// enable interrupts
 
@@ -687,8 +670,6 @@ FUNCTION_END(handle_syscall)
 	// post syscall debugging
 	testl	$THREAD_FLAGS_DEBUGGER_INSTALLED, THREAD_flags(%edi)
 	jz		2f
-	pushl	-8(%ebp)				// syscall start time
-	pushl	-12(%ebp)
 	xor		%edx, %edx
 	testl	$THREAD_FLAGS_64_BIT_SYSCALL_RETURN, THREAD_flags(%edi)
 	jz		1f

src/system/kernel/arch/x86/64/entry_compat.S

@@ -81,8 +81,6 @@
 	LOCK_THREAD_TIME()											\
 																\
 	call	system_time;										\
-																\
-	/* Preserve system_time for post syscall debug */			\
 	movq	%rax, %r13;											\
 																\
 	/* thread->user_time += now - thread->last_time; */			\
@@ -364,7 +362,6 @@ FUNCTION(x86_64_sysenter32_entry):
 	movq	%r14, %rdi				// syscall number
 	movq	%rsp, %rsi
 	movq	IFRAME_ax(%rbp), %rdx	// return value
-	movq	%r13, %rcx				// start time, preserved earlier
 	call	user_debug_post_syscall
 	addq	$48, %rsp
 1:

src/system/kernel/arch/x86/64/interrupts.S

@@ -64,8 +64,7 @@
 
 // The macros below require R12 to contain the current thread pointer. R12 is
 // callee-save so will be preserved through all function calls and only needs
-// to be obtained once. R13 is used to store the system call start time, will
+// to be obtained once.
-// also be preserved.
 
 #define LOCK_THREAD_TIME()										\
 	leaq	THREAD_time_lock(%r12), %rdi;						\
@@ -79,8 +78,6 @@
 	LOCK_THREAD_TIME()											\
 																\
 	call	system_time;										\
-																\
-	/* Preserve system_time for post syscall debug */			\
 	movq	%rax, %r13;											\
 																\
 	/* thread->user_time += now - thread->last_time; */			\
@@ -526,7 +523,6 @@ FUNCTION(x86_64_syscall_entry):
 	movq	%r14, %rdi				// syscall number
 	movq	%rsp, %rsi
 	movq	IFRAME_ax(%rbp), %rdx	// return value
-	movq	%r13, %rcx				// start time, preserved earlier
 	call	user_debug_post_syscall
 	addq	$48, %rsp
 1:

src/system/kernel/debug/user_debugger.cpp

@@ -309,6 +309,7 @@ init_thread_debug_info(struct thread_debug_info *info)
 		info->ignore_signals = 0;
 		info->ignore_signals_once = 0;
 		info->profile.sample_area = -1;
+		info->profile.interval = 0;
 		info->profile.samples = NULL;
 		info->profile.flush_needed = false;
 		info->profile.installed_timer = NULL;
@@ -337,6 +338,7 @@ clear_thread_debug_info(struct thread_debug_info *info, bool dying)
 		info->ignore_signals = 0;
 		info->ignore_signals_once = 0;
 		info->profile.sample_area = -1;
+		info->profile.interval = 0;
 		info->profile.samples = NULL;
 		info->profile.flush_needed = false;
 	}
@@ -841,29 +843,33 @@ user_debug_pre_syscall(uint32 syscall, void *args)
 
 	// check whether pre-syscall tracing is enabled for team or thread
 	int32 threadDebugFlags = atomic_get(&thread->debug_info.flags);
-	if (!(teamDebugFlags & B_TEAM_DEBUG_PRE_SYSCALL)
+	if ((teamDebugFlags & B_TEAM_DEBUG_PRE_SYSCALL)
-			&& !(threadDebugFlags & B_THREAD_DEBUG_PRE_SYSCALL)) {
+			|| (threadDebugFlags & B_THREAD_DEBUG_PRE_SYSCALL)) {
-		return;
+		// prepare the message
+		debug_pre_syscall message;
+		message.syscall = syscall;
+
+		// copy the syscall args
+		if (syscall < (uint32)kSyscallCount) {
+			if (kSyscallInfos[syscall].parameter_size > 0)
+				memcpy(message.args, args, kSyscallInfos[syscall].parameter_size);
+		}
+
+		thread_hit_debug_event(B_DEBUGGER_MESSAGE_PRE_SYSCALL, &message,
+			sizeof(message), true);
 	}
 
-	// prepare the message
+	if ((teamDebugFlags & B_TEAM_DEBUG_POST_SYSCALL)
-	debug_pre_syscall message;
+			|| (threadDebugFlags & B_THREAD_DEBUG_POST_SYSCALL)) {
-	message.syscall = syscall;
+		// The syscall_start_time storage is shared with the profiler's interval.
-
+		if (thread->debug_info.profile.samples == NULL)
-	// copy the syscall args
+			thread->debug_info.profile.syscall_start_time = system_time();
-	if (syscall < (uint32)kSyscallCount) {
-		if (kSyscallInfos[syscall].parameter_size > 0)
-			memcpy(message.args, args, kSyscallInfos[syscall].parameter_size);
 	}
-
-	thread_hit_debug_event(B_DEBUGGER_MESSAGE_PRE_SYSCALL, &message,
-		sizeof(message), true);
 }
 
 
 void
-user_debug_post_syscall(uint32 syscall, void *args, uint64 returnValue,
+user_debug_post_syscall(uint32 syscall, void *args, uint64 returnValue)
-	bigtime_t startTime)
 {
 	// check whether a debugger is installed
 	Thread *thread = thread_get_current_thread();
@@ -882,6 +888,12 @@ user_debug_post_syscall(uint32 syscall, void *args, uint64 returnValue,
 		return;
 	}
 
+	bigtime_t startTime = 0;
+	if (thread->debug_info.profile.samples == NULL) {
+		startTime = thread->debug_info.profile.syscall_start_time;
+		thread->debug_info.profile.syscall_start_time = 0;
+	}
+
 	// prepare the message
 	debug_post_syscall message;
 	message.start_time = startTime;

src/system/kernel/syscalls.cpp

@@ -194,15 +194,11 @@ _user_is_computer_on(void)
 int32
 syscall_dispatcher(uint32 callIndex, void* args, uint64* _returnValue)
 {
-	bigtime_t startTime;
-
 //	dprintf("syscall_dispatcher: thread 0x%x call 0x%x, arg0 0x%x, arg1 0x%x arg2 0x%x arg3 0x%x arg4 0x%x\n",
 //		thread_get_current_thread_id(), call_num, arg0, arg1, arg2, arg3, arg4);
 
 	user_debug_pre_syscall(callIndex, args);
 
-	startTime = system_time();
-
 	switch (callIndex) {
 		// the cases are auto-generated
 		#include "syscall_dispatcher.h"
@@ -211,7 +207,7 @@ syscall_dispatcher(uint32 callIndex, void* args, uint64* _returnValue)
 			*_returnValue = (uint64)B_BAD_VALUE;
 	}
 
-	user_debug_post_syscall(callIndex, args, *_returnValue, startTime);
+	user_debug_post_syscall(callIndex, args, *_returnValue);
 
 //	dprintf("syscall_dispatcher: done with syscall 0x%x\n", callIndex);