From 788da26bbcf97e64f019701c691cf086c526dcac Mon Sep 17 00:00:00 2001 From: Augustin Cavalier Date: Fri, 6 Sep 2024 13:21:43 -0400 Subject: [PATCH] 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 Reviewed-by: waddlesplash --- headers/private/kernel/user_debugger.h | 9 ++-- src/bin/debug/strace/strace.cpp | 11 +++-- src/system/kernel/arch/x86/32/interrupts.S | 21 +--------- src/system/kernel/arch/x86/64/entry_compat.S | 3 -- src/system/kernel/arch/x86/64/interrupts.S | 6 +-- src/system/kernel/debug/user_debugger.cpp | 44 +++++++++++++------- src/system/kernel/syscalls.cpp | 6 +-- 7 files changed, 44 insertions(+), 56 deletions(-) diff --git a/headers/private/kernel/user_debugger.h b/headers/private/kernel/user_debugger.h index e05db32157..b67e8eeb3e 100644 --- a/headers/private/kernel/user_debugger.h +++ b/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; - // sampling interval + union { + 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, - bigtime_t startTime); +void user_debug_post_syscall(uint32 syscall, void *args, uint64 returnValue); 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); diff --git a/src/bin/debug/strace/strace.cpp b/src/bin/debug/strace/strace.cpp index 3928ae83de..8df9c9c4f9 100644 --- a/src/bin/debug/strace/strace.cpp +++ b/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", - message.end_time - message.start_time); + print_to_string(&string, &length, " (%lld us)\n", duration); } //for (int32 i = 0; i < 16; i++) { diff --git a/src/system/kernel/arch/x86/32/interrupts.S b/src/system/kernel/arch/x86/32/interrupts.S index 9f79ad6269..080c8a39ad 100644 --- a/src/system/kernel/arch/x86/32/interrupts.S +++ b/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() - // leave the time on the stack (needed for post syscall debugging) + UPDATE_THREAD_USER_TIME() 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 diff --git a/src/system/kernel/arch/x86/64/entry_compat.S b/src/system/kernel/arch/x86/64/entry_compat.S index 855044ae9c..2dc09aab0f 100644 --- a/src/system/kernel/arch/x86/64/entry_compat.S +++ b/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: diff --git a/src/system/kernel/arch/x86/64/interrupts.S b/src/system/kernel/arch/x86/64/interrupts.S index 1821f2a2dc..f8a197a6c8 100644 --- a/src/system/kernel/arch/x86/64/interrupts.S +++ b/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 -// also be preserved. +// to be obtained once. #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: diff --git a/src/system/kernel/debug/user_debugger.cpp b/src/system/kernel/debug/user_debugger.cpp index 7f5b21ec3f..997dd12035 100644 --- a/src/system/kernel/debug/user_debugger.cpp +++ b/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) - && !(threadDebugFlags & B_THREAD_DEBUG_PRE_SYSCALL)) { - return; + if ((teamDebugFlags & B_TEAM_DEBUG_PRE_SYSCALL) + || (threadDebugFlags & B_THREAD_DEBUG_PRE_SYSCALL)) { + // 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 - 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); + if ((teamDebugFlags & B_TEAM_DEBUG_POST_SYSCALL) + || (threadDebugFlags & B_THREAD_DEBUG_POST_SYSCALL)) { + // The syscall_start_time storage is shared with the profiler's interval. + if (thread->debug_info.profile.samples == NULL) + thread->debug_info.profile.syscall_start_time = system_time(); } - - thread_hit_debug_event(B_DEBUGGER_MESSAGE_PRE_SYSCALL, &message, - sizeof(message), true); } void -user_debug_post_syscall(uint32 syscall, void *args, uint64 returnValue, - bigtime_t startTime) +user_debug_post_syscall(uint32 syscall, void *args, uint64 returnValue) { // 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; diff --git a/src/system/kernel/syscalls.cpp b/src/system/kernel/syscalls.cpp index e55bd501d9..bdeb922e79 100644 --- a/src/system/kernel/syscalls.cpp +++ b/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);