Date: Mon, 30 May 2022 00:19:15 +0200 From: Paul Floyd <paulf2718@gmail.com> To: FreeBSD Hackers <freebsd-hackers@freebsd.org> Subject: Re: Hang ast / pipelk / piperd Message-ID: <dca6a5b4-6f0c-98c0-2f2d-6e5da7405af4@gmail.com> In-Reply-To: <84015bf9-8504-1c3c-0ba5-58d0d7824843@gmail.com> References: <84015bf9-8504-1c3c-0ba5-58d0d7824843@gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
On 5/27/22 22:13, Paul Floyd wrote: > > Hi > > I'm debugging two issues with Valgrind on FreeBSD 13.1 and 14, one on > amd64 and one on i386. > ... > |Both hangs seem quite sensitive to timing - in both cases adding or > changing nanosleep times seem to make them no longer hang. | > |Adding debug statements to Valgrind can also change the behaviour > (and is also unsafe when not holding the scheduler lock). Does this > look like a kernel bug? | thunderbird munged the formatting when I switched to plain text so I'm sending again. One important detail I missed out. Why is Valgrind releasing the scheduler lock?| To make a client syscall. This needs to be done in "client-like" circumstances - specifically, with the client signal mask (rather than the Valgrind mask, which is to mask all signals so that Valgrind has full control).| Two things can happen with a client syscall.| 1/ it succeeds, and Valgrind will re-acquire the lock and continue.| 2/ it gets interrupted, Valgrind re-acquires the lock, does a load of stuff to fixup the guest state and take the appropriate action (restart, return EINTR, save carry etc).| I did think that 2/ might be prone to get into an infinite loop, especially with restart. But I don't see anything like that in the Valgrind logs.| PJF thread 14 making a client nanosleep syscall |SYSCALL[5379,14](240) sys_nanosleep ( 0x200890, 0x0 ) --> [async] ... PJF -thread 14 releases the scheduler lock --5379-- SCHED[14]: releasing lock (VG_(client_syscall)[async]) -> VgTs_WaitSys PJF thread 2 acquires the scheduler lock --5379-- SCHED[2]: acquired lock (VG_(client_syscall)[async]) PJF thread 2 return from nanosleep SYSCALL[5379,2](240) ... [async] --> Success(0x0) PJF thread 2 making a client write syscall SYSCALL[5379,2]( 4) sys_write ( 1, 0x4ea9000, 48 ) --> [async] ... PJF thread 2 releases the scheduler lock --5379-- SCHED[2]: releasing lock (VG_(client_syscall)[async]) -> VgTs_WaitSys PJF this is the thread 2 printf from syscall write tls_ptr: case "race" has mismatch: *ip=8 here=4 PJF thread 2 acquires the scheduler lock --5379-- SCHED[2]: acquired lock (VG_(client_syscall)[async]) PJF thread 2 return from write (30 bytes written) SYSCALL[5379,2]( 4) ... [async] --> Success(0x30) PJF thread 2 making a client nanosleep syscall SYSCALL[5379,2](240) sys_nanosleep ( 0x200890, 0x0 ) --> [async] ... PJF thread 2 releases the scheduler lock --5379-- SCHED[2]: releasing lock (VG_(client_syscall)[async]) -> VgTs_WaitSys And that's it, it hangs making the client nanosleep syscall. Under gdb I see (and this is quite variable) (gdb) info thread Id Target Id Frame * 1 LWP 100073 of process 861 vgModuleLocal_do_syscall_for_client_WRK () at m_syswrap/syscall-amd64-freebsd.S:135 2 LWP 100215 of process 861 vgModuleLocal_do_syscall_for_client_WRK () at m_syswrap/syscall-amd64-freebsd.S:135 3 LWP 100216 of process 861 0x00000000380bffac in do_syscall_WRK () 4 LWP 100217 of process 861 0x00000000380bffac in do_syscall_WRK () 5 LWP 100218 of process 861 0x00000000380bffac in do_syscall_WRK () 6 LWP 100219 of process 861 0x00000000380bffac in do_syscall_WRK () 7 LWP 100220 of process 861 0x00000000380bffac in do_syscall_WRK () 8 LWP 100221 of process 861 0x00000000380bffac in do_syscall_WRK () 9 LWP 100222 of process 861 0x00000000380bffac in do_syscall_WRK () 10 LWP 100223 of process 861 0x00000000380bffac in do_syscall_WRK () 11 LWP 100224 of process 861 0x00000000380bffac in do_syscall_WRK () 12 LWP 100225 of process 861 0x00000000380bffac in do_syscall_WRK () 13 LWP 100226 of process 861 0x00000000380bffac in do_syscall_WRK () 14 LWP 100227 of process 861 0x00000000380bffac in do_syscall_WRK () 15 LWP 100228 of process 861 0x00000000380bffac in do_syscall_WRK () do_syscall_WRK is the syscall interface for the Valgrind host, and that will be the threads waiting for the lock. Thread 1 and 2 are in do_syscall_for_client, the interface for guest syscalls. Thread 1 is doing a _umtx_op syscall, for the pthread_join. Thrread 2 is doing a nanosleep. These are blocking syscalls so they release the lock before making the syscall to allow other threads to execute. I think that in the snapshot above, the lock is released and one of threads 3 to 15 should be obtaining the lock and running. That's where the kernel context switch / AST seems to be going wrong. I don't see anything particularly wrong on the Valgrind side. Any ideas what I can do to see why the context switch is hanging? A+ Paul
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?dca6a5b4-6f0c-98c0-2f2d-6e5da7405af4>