From nobody Wed Jun 1 21:27:52 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 1CD5B1B4F89D for ; Wed, 1 Jun 2022 21:27:56 +0000 (UTC) (envelope-from paulf2718@gmail.com) Received: from mail-wr1-x42e.google.com (mail-wr1-x42e.google.com [IPv6:2a00:1450:4864:20::42e]) (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 4LD2LM28wlz4m3Q for ; Wed, 1 Jun 2022 21:27:55 +0000 (UTC) (envelope-from paulf2718@gmail.com) Received: by mail-wr1-x42e.google.com with SMTP id s24so3982036wrb.10 for ; Wed, 01 Jun 2022 14:27:55 -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:subject:content-language:to :references:from:in-reply-to:content-transfer-encoding; bh=cvR8z3hbNs2n5Qtvrb1p/v6EWjXpkm1tUwLI+gEHK80=; b=jU6zzDSQLpxlxNhSkbsQTCU/2BKV1ErZbiWE3B5BaqYhHG8Lnr5ptdtArM6smLCVLI nfOkBpFeIi8mujYu9J/+aZ1pYIjlLsi5habXGXD/Mwk7kujZbP9Mqv0IXN3pWmnQ0nPy eGPwueo9ScliNsuz6HgAkFghLHJZ1tup8oWbAFMkduBNLqZ24maaxbN7BlxnL8GQJ9dG YhXk002g0dhnoGgoNiE6LE6cWutFo9w5sV6UqB1Z/DCpsoEUgGdIbAU5PmSu2mYhVjZL yts3IMM71qCrMDoTZB2BFxAVhDQwyGi8L10s4xVtUms3uWUZ3NKtzEWv1tyh5Ktq8DQo klQA== 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:subject :content-language:to:references:from:in-reply-to :content-transfer-encoding; bh=cvR8z3hbNs2n5Qtvrb1p/v6EWjXpkm1tUwLI+gEHK80=; b=Quq4jo+8994xnrBQV1VlTfNnrLVNu0vjKWGzxRpPdjt6T6eA99UG0hW2wm72WgtnkX sXZl4IgV6uAH6j/HFqc1Obm0DlP1a1k2Rhfc7jKJLWgtZWYD4Esf7unRvc8mrZ4w3Jee sN2GNVULZ/hc/Tgv0yBfJjGBpEVxBLnrdXvMG0XKSF739LwIP7K55mV+qHPv2traKdPJ 8wgAFcUIINbFUQ6iwiL+yFy2+DmA8CUMYz+CXMITVHj9R+0iiI4US/cAcrJYsZ9o4cms GtM7YMQlqtbfuTBLCYW9MS2OybDKYnXsB7Z9L10hbThfK7ygxMEOTw8CZjpa7bj0Qs6J UinA== X-Gm-Message-State: AOAM533LSB7Vd0gz+M7ZCgzrlilSbXUh8j7MAJ8HWAnopREDnXw24RNt RzanSoBc3EgH4heRh5bvXyTgjGxklYgDWg== X-Google-Smtp-Source: ABdhPJyborXVy8gH5eyT5vj8jct7Pt7a/3bC4ZYSQhaHkdnvbVNoq7aQurF7SPjs++wxXEU8dwodEg== X-Received: by 2002:a5d:64ac:0:b0:211:7f3b:a0d4 with SMTP id m12-20020a5d64ac000000b002117f3ba0d4mr1104341wrp.490.1654118874141; Wed, 01 Jun 2022 14:27:54 -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 t14-20020a5d49ce000000b0020d0cdbf7eesm2577996wrs.111.2022.06.01.14.27.53 for (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Wed, 01 Jun 2022 14:27:53 -0700 (PDT) Message-ID: Date: Wed, 1 Jun 2022 23:27:52 +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 Subject: Re: Hang ast / pipelk / piperd Content-Language: en-US To: FreeBSD Hackers References: <84015bf9-8504-1c3c-0ba5-58d0d7824843@gmail.com> From: Paul Floyd In-Reply-To: Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit X-Rspamd-Queue-Id: 4LD2LM28wlz4m3Q X-Spamd-Bar: - Authentication-Results: mx1.freebsd.org; dkim=pass header.d=gmail.com header.s=20210112 header.b=jU6zzDSQ; dmarc=pass (policy=none) header.from=gmail.com; spf=pass (mx1.freebsd.org: domain of paulf2718@gmail.com designates 2a00:1450:4864:20::42e as permitted sender) smtp.mailfrom=paulf2718@gmail.com X-Spamd-Result: default: False [-1.27 / 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]; 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)[]; NEURAL_HAM_MEDIUM(-0.25)[-0.251]; 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]; RCPT_COUNT_ONE(0.00)[1]; NEURAL_SPAM_SHORT(0.98)[0.982]; RCVD_IN_DNSWL_NONE(0.00)[2a00:1450:4864:20::42e:from]; MLMMJ_DEST(0.00)[freebsd-hackers]; RCVD_TLS_ALL(0.00)[] X-ThisMailContainsUnwantedMimeParts: N On 6/1/22 14:16, Mark Johnston wrote: > On Mon, May 30, 2022 at 09:35:05PM +0200, Paul Floyd wrote: >> >> >> On 5/30/22 14:15, Mark Johnston wrote: >> >>> "procstat -kk " might help to reveal what's going on, >>> since it sounds like the hand/livelock is happening somewhere in the >>> kernel. >> >> Not knowing much about the kernel, my guess is that this is related to >> >> commit 4808bab7fa6c3ec49b49476b8326d7a0250a03fa >> Author: Alexander Motin >> Date: Tue Sep 21 18:14:22 2021 -0400 >> >> sched_ule(4): Improve long-term load balancer. >> >> and this bit of ast code >> >> doreti_ast: >> /* >> * Check for ASTs atomically with returning. Disabling CPU >> * interrupts provides sufficient locking even in the SMP case, >> * since we will be informed of any new ASTs by an IPI. >> */ >> cli >> movq PCPU(CURTHREAD),%rax >> testl $TDF_ASTPENDING | TDF_NEEDRESCHED,TD_FLAGS(%rax) >> je doreti_exit >> sti >> movq %rsp,%rdi /* pass a pointer to the trapframe */ >> call ast >> jmp doreti_ast >> >> >> The above commit seems to be migrating loaded threads to another CPU. > > How did you infer that? The long-term load balancer should be running > fairly infrequently. > Well one thread is hung in mi_switch+0xc2 ast+0x1e6 doreti_ast+0x1f I found the above code referring to doreti_ast with grep and thought that if the test always fails then it will loop forever. So I looked for git commits containing TDF_ASTPENDING and TDF_NEEDRESCHED and found a couple of commits mentioning these flags, scheduling and found the above and the followup commit 11f14b33629e552a451fdbfe653ebb0addd27700 Author: Alexander Motin Date: Sun Sep 26 12:03:05 2021 -0400 sched_ule(4): Fix hang with steal_thresh < 2. e745d729be60 caused infinite loop with interrupts disabled in load stealing code if steal_thresh set below 2. Such configuration should not generally be used, but appeared some people are using it to workaround some problems. and I guessed they might be related. > As a side note, I think we are missing ktrcsw() calls in some places, > e.g., in turnstile_wait(). > >> My test system is a VirtualBox amd64 FreeBSD 13.1 with one CPU running >> on a 13.0 host. >> >> I just tried restarting the VM with 2 CPUs and the testcase seems to be >> a lot better - it's been running in a loop for 10 minutes whereas >> previously it would hang at least 1 in 5 times. > > Hmm. Could you, please, show the ktrace output with -H -T passed to > kdump(1), together with fresh "procstat -kk" output? > > The fact that the problem apparently only occurs with 1 CPU suggests a > scheduler bug, indeed. Here is the fresh procstat output paulf@freebsd:~ $ procstat -kk 12339 PID TID COMM TDNAME KSTACK 12339 100089 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 umtxq_sleep+0x143 do_wait+0x3e5 __umtx_op_wait+0x53 sys__umtx_op+0x7e amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100582 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_timedwait_sig+0x12 _sleep+0x1d1 kern_clock_nanosleep+0x1c1 sys_nanosleep+0x3b amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100583 none-amd64-freebsd - mi_switch+0xc2 ast+0x1e6 doreti_ast+0x1f 12339 100584 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0x3d6 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100585 none-amd64-freebsd - mi_switch+0xc2 intr_event_handle+0x167 intr_execute_handlers+0x4b Xapic_isr1+0xdc sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0x3d6 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100586 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0x3d6 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100587 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0x3d6 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100588 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0x3d6 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100589 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0x3d6 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100590 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0x3d6 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100591 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0x3d6 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100592 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0xb3 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100593 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0xb3 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100594 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0xb3 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 12339 100595 none-amd64-freebsd - mi_switch+0xc2 sleepq_catch_signals+0x2e6 sleepq_wait_sig+0x9 _sleep+0x1f2 pipe_read+0xb3 dofileread+0x81 sys_read+0xbc amd64_syscall+0x10c fast_syscall_common+0xf8 And the ktrace 12339 100591 none-amd64-freebsd 1654117859.896834 RET nanosleep 0 12339 100591 none-amd64-freebsd 1654117859.896839 CALL sigprocmask(SIG_SETMASK,0x404563db0,0) 12339 100591 none-amd64-freebsd 1654117859.896840 RET sigprocmask 0 12339 100591 none-amd64-freebsd 1654117859.896842 CALL thr_self(0x404563ca8) 12339 100591 none-amd64-freebsd 1654117859.896844 RET thr_self 0 12339 100591 none-amd64-freebsd 1654117859.896845 CALL read(0x6f57,0x404563cfe,0x1) 12339 100591 none-amd64-freebsd 1654117859.896847 CSW stop kernel "pipelk" 12339 100583 none-amd64-freebsd 1654117859.896849 GIO fd 28503 read 1 byte "T" 12339 100583 none-amd64-freebsd 1654117859.896852 RET read 1 12339 100583 none-amd64-freebsd 1654117859.896853 CSW stop user "ast" 12339 100590 none-amd64-freebsd 1654117859.896854 CSW resume kernel "pipelk" 12339 100590 none-amd64-freebsd 1654117859.896854 CSW stop kernel "piperd" 12339 100589 none-amd64-freebsd 1654117859.896855 CSW resume kernel "pipelk" 12339 100589 none-amd64-freebsd 1654117859.896855 CSW stop kernel "piperd" 12339 100588 none-amd64-freebsd 1654117859.896856 CSW resume kernel "pipelk" 12339 100588 none-amd64-freebsd 1654117859.896856 CSW stop kernel "piperd" [REPEATS, TRIMMMED] 12339 100590 none-amd64-freebsd 1654117859.896896 CSW resume kernel "piperd" 12339 100590 none-amd64-freebsd 1654117859.896897 CSW stop kernel "piperd" 12339 100089 none-amd64-freebsd Events dropped. 12339 100089 none-amd64-freebsd 1654118042.172196 CALL thr_self(0x40268d7f8) 12339 100089 none-amd64-freebsd 1654118042.172198 RET thr_self 0 12339 100089 none-amd64-freebsd 1654118042.172202 CALL thr_self(0x40268d788) 12339 100089 none-amd64-freebsd 1654118042.172204 RET thr_self 0 12339 100089 none-amd64-freebsd 1654118042.172206 CALL read(0x6f57,0x40268d7de,0x1) 12339 100584 none-amd64-freebsd 1654118042.172217 CSW stop kernel "piperd" 12339 100089 none-amd64-freebsd 1654118042.172221 CSW stop kernel "piperd" 12339 100584 none-amd64-freebsd 1654118042.172222 CSW resume kernel "piperd" 12339 100584 none-amd64-freebsd 1654118042.172222 CSW stop kernel "piperd" [REPEATS, TRIMMMED] 12339 100089 none-amd64-freebsd 1654118042.172259 CSW stop kernel "piperd" 12339 100584 none-amd64-freebsd 1654118042.172260 CSW resume kernel "piperd" 12339 100089 none-amd64-freebsd Events dropped. 12337 100093 sh 1654117857.635559 CSW stop kernel "wait" 12337 100093 sh 1654118057.965243 CSW resume kernel "wait" 12337 100093 sh 1654118057.965258 RET wait4 12339/0x3033 12337 100093 sh 1654118057.965356 CALL fstatat(AT_FDCWD,0x7fffffffe0c0,0x7fffffffe4c0,0) 12337 100093 sh 1654118057.965359 NAMI "/usr/share/nls/C.UTF-8/libc.cat" 12337 100093 sh 1654118057.965363 RET fstatat -1 errno 2 No such file or directory 12337 100093 sh 1654118057.965367 CALL fstatat(AT_FDCWD,0x7fffffffe0c0,0x7fffffffe4c0,0) 12337 100093 sh 1654118057.965369 NAMI "/usr/share/nls/libc/C.UTF-8" 12337 100093 sh 1654118057.965371 RET fstatat -1 errno 2 No such file or directory 12337 100093 sh 1654118057.965373 CALL fstatat(AT_FDCWD,0x7fffffffe0c0,0x7fffffffe4c0,0) 12337 100093 sh 1654118057.965375 NAMI "/usr/local/share/nls/C.UTF-8/libc.cat" 12337 100093 sh 1654118057.965377 RET fstatat -1 errno 2 No such file or directory 12337 100093 sh 1654118057.965380 CALL fstatat(AT_FDCWD,0x7fffffffe0c0,0x7fffffffe4c0,0) 12337 100093 sh 1654118057.965381 NAMI "/usr/local/share/nls/libc/C.UTF-8" 12337 100093 sh 1654118057.965383 RET fstatat -1 errno 2 No such file or directory 12337 100093 sh 1654118057.965410 CALL write(0x2,0x80184c000,0x7) 12337 100093 sh 1654118057.965417 GIO fd 2 wrote 7 bytes "Killed " A+ Paul