From nobody Sun May 29 22:19:15 2022 X-Original-To: freebsd-hackers@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id A38921B5B1A6 for ; Sun, 29 May 2022 22:19:19 +0000 (UTC) (envelope-from paulf2718@gmail.com) Received: from mail-wm1-x330.google.com (mail-wm1-x330.google.com [IPv6:2a00:1450:4864:20::330]) (using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (2048 bits) client-digest SHA256) (Client CN "smtp.gmail.com", Issuer "GTS CA 1D4" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4LBCd24g1Zz3kfM for ; Sun, 29 May 2022 22:19:18 +0000 (UTC) (envelope-from paulf2718@gmail.com) Received: by mail-wm1-x330.google.com with SMTP id h62-20020a1c2141000000b0039aa4d054e2so1370594wmh.1 for ; Sun, 29 May 2022 15:19:18 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=message-id:date:mime-version:user-agent:from:subject:to:references :content-language:in-reply-to:content-transfer-encoding; bh=+SOACLx5Sq7mJBzu5aNqtkgiAOzzRYs0rp5ucWGRMa8=; b=ebdCMYcg5cgdWDmSO8rzrQEB51d9mR18HGJ15xLOwD5GIh3/ORR6KzdOqdpwXIYTtz KUhaJ6Qoq7BB82ZUFZI6zpuSZhsuk5qlOLgVd1lAjIuL+yRHhdo6PBfjQHmkb8CJ4KZj yMwo55Go35qpbkiqz0fz+RGnX13cOu3MG6i3p0VwqGjm8rjRYuJmfJ8dDNrZ/9fZAzx4 f86iSzr2WMc/CMLxDB1S5Et9034Dc5uZDNGmFT7yixLsj1ioYIUEV3GI/iE6cVb8gUqW 0x6snuL94q4N6GKElHLqws4OJbRyfWAKu1k99OdG8UPxodrPocvhr/G10nuF1OOjLTIJ KTtg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:message-id:date:mime-version:user-agent:from :subject:to:references:content-language:in-reply-to :content-transfer-encoding; bh=+SOACLx5Sq7mJBzu5aNqtkgiAOzzRYs0rp5ucWGRMa8=; b=wsyZZ11VyemTJgL81g9EmANsXC2Oyrxp4VOo6jb9LAWhzLrLQYd+Jp7bRIGi1qwgse MWqBEfqEEkhQOD6gbAxjAKvnYKdXMlY2OlGdW+mejmIqFya1A5RSwYhNnLNL/U7ko4WE QlR9WIXXdTAjp12b4PR9ePlrowJdJN7EsgiEvXOYtDpbGj8NMrXWX1NXNnzi+wvH4lkJ y54cZY8jPetDrtNJ+T0kN+TGpZwmJ55ihRX2r02OVv4D8m9p+BKZ2xgzhluhi10iylXF Db1fWnsRRS9uag2wMN/omGY0a1S1mDn3Goj44QAPLVOOED9C65EwDeVsjrG8aqsOttMv 00Fw== X-Gm-Message-State: AOAM532WsiL5W/14vvqKJo2AJ9Hmkbr11DJl2O210OUF8Oor/YjT8Vts zffwDKJeeerGim1uYseHnY1BZ0MkHgY= X-Google-Smtp-Source: ABdhPJxv3uCJ6uru+OkiN5mmxgGBPxBXSFgFWxadoWP7kiBBdu+UgmB4Hvh2WLPvUPbF0tKHUNnhew== X-Received: by 2002:a05:600c:acf:b0:397:345f:fe10 with SMTP id c15-20020a05600c0acf00b00397345ffe10mr16739510wmr.15.1653862757414; Sun, 29 May 2022 15:19:17 -0700 (PDT) Received: from [192.168.1.28] (lfbn-lyo-1-398-93.w2-7.abo.wanadoo.fr. [2.7.225.93]) by smtp.gmail.com with ESMTPSA id e15-20020a056000178f00b002102f2fac37sm2706054wrg.51.2022.05.29.15.19.16 for (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Sun, 29 May 2022 15:19:17 -0700 (PDT) Message-ID: Date: Mon, 30 May 2022 00:19:15 +0200 List-Id: Technical discussions relating to FreeBSD List-Archive: https://lists.freebsd.org/archives/freebsd-hackers List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-hackers@freebsd.org MIME-Version: 1.0 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:91.0) Gecko/20100101 Thunderbird/91.10.0 From: Paul Floyd Subject: Re: Hang ast / pipelk / piperd To: FreeBSD Hackers References: <84015bf9-8504-1c3c-0ba5-58d0d7824843@gmail.com> Content-Language: en-US In-Reply-To: <84015bf9-8504-1c3c-0ba5-58d0d7824843@gmail.com> Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit X-Rspamd-Queue-Id: 4LBCd24g1Zz3kfM X-Spamd-Bar: -- Authentication-Results: mx1.freebsd.org; dkim=pass header.d=gmail.com header.s=20210112 header.b=ebdCMYcg; dmarc=pass (policy=none) header.from=gmail.com; spf=pass (mx1.freebsd.org: domain of paulf2718@gmail.com designates 2a00:1450:4864:20::330 as permitted sender) smtp.mailfrom=paulf2718@gmail.com X-Spamd-Result: default: False [-2.03 / 15.00]; RCVD_VIA_SMTP_AUTH(0.00)[]; R_SPF_ALLOW(-0.20)[+ip6:2a00:1450:4000::/36:c]; FREEMAIL_FROM(0.00)[gmail.com]; RCVD_COUNT_THREE(0.00)[3]; TO_DN_ALL(0.00)[]; DKIM_TRACE(0.00)[gmail.com:+]; DMARC_POLICY_ALLOW(-0.50)[gmail.com,none]; NEURAL_HAM_SHORT(-1.00)[-0.999]; RECEIVED_SPAMHAUS_PBL(0.00)[2.7.225.93:received]; FROM_EQ_ENVFROM(0.00)[]; MIME_TRACE(0.00)[0:+]; FREEMAIL_ENVFROM(0.00)[gmail.com]; ASN(0.00)[asn:15169, ipnet:2a00:1450::/32, country:US]; MID_RHS_MATCH_FROM(0.00)[]; DWL_DNSWL_NONE(0.00)[gmail.com:dkim]; ARC_NA(0.00)[]; R_DKIM_ALLOW(-0.20)[gmail.com:s=20210112]; FROM_HAS_DN(0.00)[]; TO_MATCH_ENVRCPT_ALL(0.00)[]; NEURAL_HAM_LONG(-1.00)[-1.000]; MIME_GOOD(-0.10)[text/plain]; PREVIOUSLY_DELIVERED(0.00)[freebsd-hackers@freebsd.org]; NEURAL_SPAM_MEDIUM(0.97)[0.966]; RCPT_COUNT_ONE(0.00)[1]; RCVD_IN_DNSWL_NONE(0.00)[2a00:1450:4864:20::330:from]; MLMMJ_DEST(0.00)[freebsd-hackers]; RCVD_TLS_ALL(0.00)[] X-ThisMailContainsUnwantedMimeParts: N 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