Waiting for bufdaemon

Fri Jan 15 18:49:08 UTC 2021

Am 15.01.21 um 16:45 schrieb Konstantin Belousov:
> On Fri, Jan 15, 2021 at 04:30:19PM +0100, Mikaël Urankar wrote:
>> On 15/01/2021 16:02, Konstantin Belousov wrote:
>>> On Fri, Jan 15, 2021 at 03:56:01PM +0100, Mikaël Urankar wrote:
>>>> On 15/01/2021 11:26, Jakob Alvermark wrote:
>>>>> Hi,
>>>>>
>>>>>
>>>>> When rebooting my thinkpad the 'bufdaemon' times out:
>>>>>
>>>>> Waiting (max 60 seconds) for system thread 'bufdaemon' to stop ... timed
>>>>> out
>>>>>
>>>>> Waiting (max 60 seconds) for system thread 'bufspacedaemon-0' to stop
>>>>> ... timed out
>>>>>
>>>>> Waiting (max 60 seconds) for system thread 'bufspacedaemon-1' to stop
>>>>> ... timed out
>>>>>
>>>>> Waiting (max 60 seconds) for system thread 'bufspacedaemon-2' to stop
>>>>> ... timed out
>>>>>
>>>>> Waiting (max 60 seconds) for system thread 'bufspacedaemon-3' to stop
>>>>> ... timed out
>>>>>
>>>>> Waiting (max 60 seconds) for system thread 'bufspacedaemon-4' to stop
>>>>> ... timed out
>>>>>
>>>>> Waiting (max 60 seconds) for system thread 'bufspacedaemon-5' to stop
>>>>> ... timed out
>>>>>
>>>>>
>>>>> This started happening recently (within the last week I think).
>>>>
>>>> Hi,
>>>>
>>>> I'm also affected. I have an AMD Ryzen 9 3900X cpu, running bare metal.
>>>>
>>>> 5844bd058aed6f3d0c8cbbddd6aa95993ece0189 (jobc: rework detection of orphaned
>>>> groups) "seems" ok
>>>>
>>>> cd240c9cf100bec3def38ceb4a320611b1d02693 (x86 vdso gettc: Add RDTSCP
>>>> support), affected by the timeout.
>>>>
>>>> I haven't tried the intermediate commit yet.
>>>>
>>>> My intel machine doesn't seem to be affected
>>>
>>> If you revert only 9e680e4005b7, is it fixed ?
>>>
>> Yes it seems to be fixed with 9e680e4005b7 reverted (I've only done 2 tests,
>> I can do more if you want)
> Please show me the output from sysctl
> kern.timecounter
> kern.eventtimer
> and first 100 lines of dmesg from the verbose boot (that contains the CPU
> ident lines).

I also have this timeout issue only on AMD, here Ryzen 3950X:

[...]
Waiting for PIDS: 2905
90 seconds watchdog timeout expired. Shutdown terminated.
Fri Jan 15 19:21:01 xxxxxx init[1]: /etc/rc.shutdown terminated
abnormally, going to single user mode
Fri Jan 15 19:21:01 xxxxxx syslogd: exiting on signal 15
wg0: link state changed to DOWN
Waiting (max 69 seconds) for system process `vnlru' to stop... done
Waiting (max 60 seconds) for system process `syncer' to stop...
Syncing disks, vnodes remaining... 22 23 23 1 1 0 0 0 done
Waiting (max 60 seconds) for system thread `bufdaemon' to stop... done
Waiting (max 60 seconds) for system thread `bufspacedaemon-0' to stop...
done
Waiting (max 60 seconds) for system thread `bufspacedaemon-1' to stop...
done
Waiting (max 60 seconds) for system thread `bufspacedaemon-2' to stop...
done
Waiting (max 60 seconds) for system thread `bufspacedaemon-3' to stop...
timeout
Waiting (max 60 seconds) for system thread `bufspacedaemon-4' to stop...
timeout
Waiting (max 60 seconds) for system thread `bufspacedaemon-5' to stop...
done
Waiting (max 60 seconds) for system thread `bufspacedaemon-6' to stop...

You will find the wanted output from sysctl and boot -v in the attachment.

HTH,
Rainer Hurling
-------------- next part --------------
#sysctl kern.timecounter
kern.timecounter.tsc_shift: 1
kern.timecounter.smp_tsc_adjust: 0
kern.timecounter.smp_tsc: 1
kern.timecounter.invariant_tsc: 1
kern.timecounter.fast_gettime: 1
kern.timecounter.tick: 1
kern.timecounter.choice: ACPI-fast(900) HPET(950) i8254(0) TSC-low(1000) dummy(-1000000)
kern.timecounter.hardware: TSC-low
kern.timecounter.alloweddeviation: 5
kern.timecounter.timehands_count: 2
kern.timecounter.stepwarnings: 0
kern.timecounter.tc.ACPI-fast.quality: 900
kern.timecounter.tc.ACPI-fast.frequency: 3579545
kern.timecounter.tc.ACPI-fast.counter: 3355373301
kern.timecounter.tc.ACPI-fast.mask: 4294967295
kern.timecounter.tc.HPET.quality: 950
kern.timecounter.tc.HPET.frequency: 14318180
kern.timecounter.tc.HPET.counter: 3626460971
kern.timecounter.tc.HPET.mask: 4294967295
kern.timecounter.tc.i8254.quality: 0
kern.timecounter.tc.i8254.frequency: 1193182
kern.timecounter.tc.i8254.counter: 21196
kern.timecounter.tc.i8254.mask: 65535
kern.timecounter.tc.TSC-low.quality: 1000
kern.timecounter.tc.TSC-low.frequency: 1746752087
kern.timecounter.tc.TSC-low.counter: 869144438
kern.timecounter.tc.TSC-low.mask: 4294967295

#sysctl kern.eventtimer
kern.eventtimer.choice: LAPIC(600) HPET(350) HPET1(350) HPET2(350) i8254(100) RTC(0)
kern.eventtimer.et.HPET2.quality: 350
kern.eventtimer.et.HPET2.frequency: 14318180
kern.eventtimer.et.HPET2.flags: 3
kern.eventtimer.et.HPET1.quality: 350
kern.eventtimer.et.HPET1.frequency: 14318180
kern.eventtimer.et.HPET1.flags: 3
kern.eventtimer.et.HPET.quality: 350
kern.eventtimer.et.HPET.frequency: 14318180
kern.eventtimer.et.HPET.flags: 3
kern.eventtimer.et.RTC.quality: 0
kern.eventtimer.et.RTC.frequency: 32768
kern.eventtimer.et.RTC.flags: 17
kern.eventtimer.et.i8254.quality: 100
kern.eventtimer.et.i8254.frequency: 1193182
kern.eventtimer.et.i8254.flags: 1
kern.eventtimer.et.LAPIC.quality: 600
kern.eventtimer.et.LAPIC.frequency: 49907198
kern.eventtimer.et.LAPIC.flags: 7
kern.eventtimer.periodic: 0
kern.eventtimer.timer: LAPIC
kern.eventtimer.idletick: 0
kern.eventtimer.singlemul: 2

# dmesg | head -n 100
---<<BOOT>>---
VERBOSE_SYSINIT: DDB not enabled, symbol lookups disabled.
APIC: Using the MADT enumerator.
Copyright (c) 1992-2021 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
	The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 13.0-ALPHA1 #8 main-c255963-g54c743e5b29: Thu Jan 14 19:59:08 CET 2021
    rhurlin at krabat.raven.hur:/usr/obj/usr/src/amd64.amd64/sys/RHURLIN amd64
FreeBSD clang version 11.0.1 (git at github.com:llvm/llvm-project.git llvmorg-11.0.1-rc2-0-g43ff75f2c3f)
PPIM 0: PA=0xe1000000, VA=0xffffffff81910000, size=0x300000, mode=0x1
pmap: large map 8 PML4 slots (4096 GB)
VT(efifb): resolution 1024x768
Preloaded elf kernel "/boot/kernel/kernel" at 0xffffffff816f8000.
Preloaded boot_entropy_cache "/boot/entropy" at 0xffffffff81704588.
Preloaded elf obj module "/boot/kernel/xhci.ko" at 0xffffffff817045e0.
Preloaded elf obj module "/boot/kernel/ums.ko" at 0xffffffff81704bc8.
Preloaded elf obj module "/boot/kernel/cpuctl.ko" at 0xffffffff817051f0.
Preloaded elf obj module "/boot/kernel/linux64.ko" at 0xffffffff817057d8.
Preloaded elf obj module "/boot/kernel/linux_common.ko" at 0xffffffff81705ec0.
Preloaded elf obj module "/boot/kernel/cuse.ko" at 0xffffffff817065b0.
Preloaded cpu_microcode "/boot/firmware/intel-ucode.bin" at 0xffffffff81706c18.
Preloaded elf obj module "/boot/kernel/snd_hda.ko" at 0xffffffff81706c78.
Preloaded elf obj module "/boot/kernel/sound.ko" at 0xffffffff81707260.
Preloaded elf obj module "/boot/kernel/snd_uaudio.ko" at 0xffffffff817078c8.
Preloaded elf obj module "/boot/kernel/amdtemp.ko" at 0xffffffff81707ef8.
Preloaded elf obj module "/boot/kernel/amdsmn.ko" at 0xffffffff81708460.
Preloaded elf obj module "/boot/kernel/fusefs.ko" at 0xffffffff817089c8.
Preloaded hostuuid "/etc/hostid" at 0xffffffff81709030.
Preloaded elf obj module "/boot/kernel/tmpfs.ko" at 0xffffffff81709080.
VERBOSE_SYSINIT: DDB not enabled, symbol lookups disabled.
module_register: cannot register pci/xhci from kernel; already loaded from xhci.ko
Module pci/xhci failed to register: 17
module_register: cannot register tmpfs from kernel; already loaded from tmpfs.ko
Module tmpfs failed to register: 17
Calibrating TSC clock ... TSC clock: 3493512715 Hz
CPU: AMD Ryzen 9 3950X 16-Core Processor             (3493.51-MHz K8-class CPU)
  Origin="AuthenticAMD"  Id=0x870f10  Family=0x17  Model=0x71  Stepping=0
  Features=0x178bfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,MMX,FXSR,SSE,SSE2,HTT>
  Features2=0x7ed8320b<SSE3,PCLMULQDQ,MON,SSSE3,FMA,CX16,SSE4.1,SSE4.2,MOVBE,POPCNT,AESNI,XSAVE,OSXSAVE,AVX,F16C,RDRAND>
  AMD Features=0x2e500800<SYSCALL,NX,MMX+,FFXSR,Page1GB,RDTSCP,LM>
  AMD Features2=0x75c237ff<LAHF,CMP,SVM,ExtAPIC,CR8,ABM,SSE4A,MAS,Prefetch,OSVW,IBS,SKINIT,WDT,TCE,Topology,PCXC,PNXC,DBE,PL2I,MWAITX,ADMSKX>
  Structured Extended Features=0x219c91a9<FSGSBASE,BMI1,AVX2,SMEP,BMI2,PQM,PQE,RDSEED,ADX,SMAP,CLFLUSHOPT,CLWB,SHA>
  Structured Extended Features2=0x400004<UMIP,RDPID>
  XSAVE Features=0xf<XSAVEOPT,XSAVEC,XINUSE,XSAVES>
  AMD Extended Feature Extensions ID EBX=0x108b657<CLZERO,IRPerf,XSaveErPtr,RDPRU,WBNOINVD,IBPB,STIBP,SSBD>
  SVM: (disabled in BIOS) Features=0x13bcff<NP,LbrVirt,SVML,NRIPS,TscRateMsr,VmcbClean,FlushByAsid,DecodeAssist,PauseFilter,EncryptedMcodePatch,PauseFilterThreshold,AVIC,V_VMSAVE_VMLOAD,vGIF,GMET,GuesSpecCtl>
Revision=1, ASIDs=32768
  TSC: P-state invariant, performance statistics
L1 2MB data TLB: 64 entries, fully associative
L1 2MB instruction TLB: 64 entries, fully associative
L1 4KB data TLB: 64 entries, fully associative
L1 4KB instruction TLB: 64 entries, fully associative
L1 data cache: 32 kbytes, 64 bytes/line, 1 lines/tag, 8-way associative
L1 instruction cache: 32 kbytes, 64 bytes/line, 1 lines/tag, 8-way associative
L2 2MB data TLB: 2048 entries, 4-way associative
L2 2MB instruction TLB: 1024 entries, 4-way associative
L2 4KB data TLB: 2048 entries, 8-way associative
L2 4KB instruction TLB: 2048 entries, 8-way associative
L2 unified cache: 512 kbytes, 64 bytes/line, 1 lines/tag, 8-way associative
real memory  = 68717379584 (65534 MB)
Physical memory chunk(s):
0x0000000000010000 - 0x000000000009efff, 585728 bytes (143 pages)
0x0000000000100000 - 0x00000000001fffff, 1048576 bytes (256 pages)
0x0000000001900000 - 0x0000000009e1ffff, 139591680 bytes (34080 pages)
0x000000000a000000 - 0x000000000a1fffff, 2097152 bytes (512 pages)
0x000000000a213000 - 0x00000000bc654fff, 2990809088 bytes (730178 pages)
0x00000000bde03000 - 0x00000000beffffff, 18862080 bytes (4605 pages)
0x0000000100002000 - 0x0000000fd510cfff, 63704182784 bytes (15552779 pages)
avail memory = 66768715776 (63675 MB)
MADT: Found CPU APIC ID 0 ACPI ID 0: enabled
SMP: Added CPU 0 (AP)
MADT: Found CPU APIC ID 2 ACPI ID 2: enabled
SMP: Added CPU 2 (AP)
MADT: Found CPU APIC ID 4 ACPI ID 4: enabled
SMP: Added CPU 4 (AP)
MADT: Found CPU APIC ID 6 ACPI ID 6: enabled
SMP: Added CPU 6 (AP)
MADT: Found CPU APIC ID 8 ACPI ID 8: enabled
SMP: Added CPU 8 (AP)
MADT: Found CPU APIC ID 10 ACPI ID 10: enabled
SMP: Added CPU 10 (AP)
MADT: Found CPU APIC ID 12 ACPI ID 12: enabled
SMP: Added CPU 12 (AP)
MADT: Found CPU APIC ID 14 ACPI ID 14: enabled
SMP: Added CPU 14 (AP)
MADT: Found CPU APIC ID 16 ACPI ID 16: enabled
SMP: Added CPU 16 (AP)
MADT: Found CPU APIC ID 18 ACPI ID 18: enabled
SMP: Added CPU 18 (AP)
MADT: Found CPU APIC ID 20 ACPI ID 20: enabled
SMP: Added CPU 20 (AP)
MADT: Found CPU APIC ID 22 ACPI ID 22: enabled
SMP: Added CPU 22 (AP)
MADT: Found CPU APIC ID 24 ACPI ID 24: enabled
SMP: Added CPU 24 (AP)
MADT: Found CPU APIC ID 26 ACPI ID 26: enabled
SMP: Added CPU 26 (AP)
MADT: Found CPU APIC ID 28 ACPI ID 28: enabled
SMP: Added CPU 28 (AP)
MADT: Found CPU APIC ID 30 ACPI ID 30: enabled
SMP: Added CPU 30 (AP)
MADT: Found CPU APIC ID 1 ACPI ID 1: enabled
SMP: Added CPU 1 (AP)
MADT: Found CPU APIC ID 3 ACPI ID 3: enabled
SMP: Added CPU 3 (AP)
MADT: Found CPU APIC ID 5 ACPI ID 5: enabled
SMP: Added CPU 5 (AP)
MADT: Found CPU APIC ID 7 ACPI ID 7: enabled
SMP: Added CPU 7 (AP)
MADT: Found CPU APIC ID 9 ACPI ID 9: enabled
SMP: Added CPU 9 (AP)
MADT: Found CPU APIC ID 11 ACPI ID 11: enabled
SMP: Added CPU 11 (AP)
MADT: Found CPU APIC ID 13 ACPI ID 13: enabled
SMP: Added CPU 13 (AP)
MADT: Found CPU APIC ID 15 ACPI ID 15: enabled
SMP: Added CPU 15 (AP)
MADT: Found CPU APIC ID 17 ACPI ID 17: enabled
SMP: Added CPU 17 (AP)
MADT: Found CPU APIC ID 19 ACPI ID 19: enabled
SMP: Added CPU 19 (AP)
MADT: Found CPU APIC ID 21 ACPI ID 21: enabled
SMP: Added CPU 21 (AP)
MADT: Found CPU APIC ID 23 ACPI ID 23: enabled
SMP: Added CPU 23 (AP)
MADT: Found CPU APIC ID 25 ACPI ID 25: enabled
SMP: Added CPU 25 (AP)
MADT: Found CPU APIC ID 27 ACPI ID 27: enabled
SMP: Added CPU 27 (AP)
MADT: Found CPU APIC ID 29 ACPI ID 29: enabled
SMP: Added CPU 29 (AP)
MADT: Found CPU APIC ID 31 ACPI ID 31: enabled
SMP: Added CPU 31 (AP)
Event timer "LAPIC" quality 600
LAPIC: ipi_wait() us multiplier 16 (r 21347480 tsc 3493512715)
ACPI APIC Table: <ALASKA A M I >
Package ID shift: 7
L3 cache ID shift: 3
L2 cache ID shift: 1
L1 cache ID shift: 1