microsoft / WSL

Issues found on WSL
https://docs.microsoft.com/windows/wsl
MIT License
17.54k stars 823 forks source link

Very slow startup (40 seconds) #8569

Open mprevot opened 2 years ago

mprevot commented 2 years ago

Version

Microsoft Windows [Version 10.0.19044.1766]

WSL Version

Kernel Version

5.10.102.1-microsoft-standard-WSL2

Distro Version

Ubuntu 20.04

Other Software

No response

Repro Steps

Start Ubuntu distro.

Expected Behavior

Faster (sub 2sec) startup.

Actual Behavior

It takes about 40 seconds to boot.

Diagnostic Logs

[ 0.000000] Linux version 5.10.102.1-microsoft-standard-WSL2 (oe-user@oe-host) (x86_64-msft-linux-gcc (GCC) 9.3.0, GNU ld (GNU Binutils) 2.34.0.20200220) https://github.com/microsoft/WSL/issues/1 SMP Wed Mar 2 00:30:59 UTC 2022 [ 0.000000] Command line: initrd=\initrd.img panic=-1 pty.legacy_count=0 nr_cpus=16 [ 0.000000] KERNEL supported cpus: [ 0.000000] Intel GenuineIntel [ 0.000000] AMD AuthenticAMD [ 0.000000] Centaur CentaurHauls [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'

[ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'compacted' format. [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable [ 0.000000] BIOS-e820: [mem 0x00000000000e0000-0x00000000000e0fff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000001fffff] ACPI data [ 0.000000] BIOS-e820: [mem 0x0000000000200000-0x00000000f7ffffff] usable [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000bffffffff] usable [ 0.000000] BIOS-e820: [mem 0x0000001000000000-0x0000001d9d3fffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] DMI not present or invalid. [ 0.000000] Hypervisor detected: Microsoft Hyper-V [ 0.000000] Hyper-V: privilege flags low 0x2e7f, high 0x3b8030, hints 0x20c2c, misc 0x20bed7b2 [ 0.000000] Hyper-V Host Build:19041-10.0-1-0.1766 [ 0.000000] Hyper-V: LAPIC Timer Frequency: 0x1e8480 [ 0.000000] Hyper-V: Using hypercall for remote TLB flush [ 0.000000] clocksource: hyperv_clocksource_tsc_page: mask: 0xffffffffffffffff max_cycles: 0x24e6a1710, max_idle_ns: 440795202120 ns [ 0.000000] tsc: Marking TSC unstable due to running on Hyper-V [ 0.000001] tsc: Detected 3600.010 MHz processor [ 0.000008] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved [ 0.000009] e820: remove [mem 0x000a0000-0x000fffff] usable [ 0.000011] last_pfn = 0x1d9d400 max_arch_pfn = 0x400000000 [ 0.000023] MTRR default type: uncachable [ 0.000023] MTRR fixed ranges enabled: [ 0.000024] 00000-3FFFF write-back [ 0.000024] 40000-7FFFF uncachable [ 0.000024] 80000-8FFFF write-back [ 0.000025] 90000-FFFFF uncachable [ 0.000025] MTRR variable ranges enabled: [ 0.000026] 0 base 0000000000 mask 7F00000000 write-back [ 0.000026] 1 base 0100000000 mask 7000000000 write-back [ 0.000027] 2 base 1000000000 mask 0000000000 write-back [ 0.000027] 3 disabled [ 0.000028] 4 disabled [ 0.000028] 5 disabled [ 0.000028] 6 disabled [ 0.000028] 7 disabled [ 0.000032] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000039] last_pfn = 0xf8000 max_arch_pfn = 0x400000000 [ 0.000046] Using GB pages for direct mapping [ 0.000293] RAMDISK: [mem 0x03835000-0x03844fff] [ 0.000294] ACPI: Early table checksum verification disabled [ 0.000301] ACPI: RSDP 0x00000000000E0000 000024 (v02 VRTUAL) [ 0.000304] ACPI: XSDT 0x0000000000100000 000044 (v01 VRTUAL MICROSFT 00000001 MSFT 00000001) [ 0.000307] ACPI: FACP 0x0000000000101000 000114 (v06 VRTUAL MICROSFT 00000001 MSFT 00000001) [ 0.000310] ACPI: DSDT 0x00000000001011B8 01E184 (v02 MSFTVM DSDT01 00000001 MSFT 05000000) [ 0.000312] ACPI: FACS 0x0000000000101114 000040 [ 0.000313] ACPI: OEM0 0x0000000000101154 000064 (v01 VRTUAL MICROSFT 00000001 MSFT 00000001) [ 0.000315] ACPI: SRAT 0x000000000011F33C 000310 (v02 VRTUAL MICROSFT 00000001 MSFT 00000001) [ 0.000317] ACPI: APIC 0x000000000011F64C 0000C8 (v04 VRTUAL MICROSFT 00000001 MSFT 00000001) [ 0.000318] ACPI: Reserving FACP table memory at [mem 0x101000-0x101113] [ 0.000319] ACPI: Reserving DSDT table memory at [mem 0x1011b8-0x11f33b] [ 0.000319] ACPI: Reserving FACS table memory at [mem 0x101114-0x101153] [ 0.000320] ACPI: Reserving OEM0 table memory at [mem 0x101154-0x1011b7] [ 0.000320] ACPI: Reserving SRAT table memory at [mem 0x11f33c-0x11f64b] [ 0.000321] ACPI: Reserving APIC table memory at [mem 0x11f64c-0x11f713] [ 0.000325] ACPI: Local APIC address 0xfee00000 [ 0.000515] Zone ranges: [ 0.000516] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000517] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000518] Normal [mem 0x0000000100000000-0x0000001d9d3fffff] [ 0.000519] Device empty [ 0.000519] Movable zone start for each node [ 0.000520] Early memory node ranges [ 0.000520] node 0: [mem 0x0000000000001000-0x000000000009ffff] [ 0.000521] node 0: [mem 0x0000000000200000-0x00000000f7ffffff] [ 0.000522] node 0: [mem 0x0000000100000000-0x0000000bffffffff] [ 0.000523] node 0: [mem 0x0000001000000000-0x0000001d9d3fffff] [ 0.000526] Initmem setup node 0 [mem 0x0000000000001000-0x0000001d9d3fffff] [ 0.000527] On node 0 totalpages: 26825375 [ 0.000527] DMA zone: 59 pages used for memmap [ 0.000528] DMA zone: 22 pages reserved [ 0.000528] DMA zone: 3743 pages, LIFO batch:0 [ 0.000529] DMA32 zone: 16320 pages used for memmap [ 0.000529] DMA32 zone: 1011712 pages, LIFO batch:63 [ 0.000530] Normal zone: 403280 pages used for memmap [ 0.000530] Normal zone: 25809920 pages, LIFO batch:63 [ 0.000673] On node 0, zone DMA: 1 pages in unavailable ranges [ 0.000692] On node 0, zone DMA: 352 pages in unavailable ranges [ 0.010651] On node 0, zone Normal: 11264 pages in unavailable ranges [ 0.010672] ACPI: Local APIC address 0xfee00000 [ 0.010676] ACPI: LAPIC_NMI (acpi_id[0x01] dfl dfl lint[0x1]) [ 0.010854] IOAPIC[0]: apic_id 16, version 17, address 0xfec00000, GSI 0-23 [ 0.010857] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.010858] ACPI: IRQ9 used by override. [ 0.010859] Using ACPI (MADT) for SMP configuration information [ 0.010863] smpboot: Allowing 16 CPUs, 0 hotplug CPUs [ 0.010867] [mem 0xf8000000-0xffffffff] available for PCI devices [ 0.010868] Booting paravirtualized kernel on Hyper-V [ 0.010869] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.014235] setup_percpu: NR_CPUS:256 nr_cpumask_bits:256 nr_cpu_ids:16 nr_node_ids:1 [ 0.014711] percpu: Embedded 56 pages/cpu s190040 r8192 d31144 u262144 [ 0.014714] pcpu-alloc: s190040 r8192 d31144 u262144 alloc=1*2097152 [ 0.014716] pcpu-alloc: [0] 00 01 02 03 04 05 06 07 [0] 08 09 10 11 12 13 14 15 [ 0.014728] Hyper-V: PV spinlocks enabled [ 0.014729] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.014731] Built 1 zonelists, mobility grouping on. Total pages: 26405694 [ 0.014732] Kernel command line: initrd=\initrd.img panic=-1 pty.legacy_count=0 nr_cpus=16 [ 0.020981] Dentry cache hash table entries: 8388608 (order: 14, 67108864 bytes, linear) [ 0.024138] Inode-cache hash table entries: 4194304 (order: 13, 33554432 bytes, linear) [ 0.024251] mem auto-init: stack:off, heap alloc:off, heap free:off [ 0.041980] Memory: 4085908K/107301500K available (16404K kernel code, 2544K rwdata, 9048K rodata, 1580K init, 2772K bss, 1886388K reserved, 0K cma-reserved) [ 0.042013] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=16, Nodes=1 [ 0.042018] ftrace: allocating 51665 entries in 202 pages [ 0.053276] ftrace: allocated 202 pages with 4 groups [ 0.053473] rcu: Hierarchical RCU implementation. [ 0.053474] rcu: RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=16. [ 0.053475] Rude variant of Tasks RCU enabled. [ 0.053475] Tracing variant of Tasks RCU enabled. [ 0.053476] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies. [ 0.053476] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=16 [ 0.055699] Using NULL legacy PIC [ 0.055700] NR_IRQS: 16640, nr_irqs: 552, preallocated irqs: 0 [ 0.056038] random: crng done (trusting CPU's manufacturer) [ 0.056054] Console: colour dummy device 80x25 [ 0.056059] printk: console [tty0] enabled [ 0.056064] ACPI: Core revision 20200925 [ 0.056185] Failed to register legacy timer interrupt [ 0.056185] APIC: Switch to symmetric I/O mode setup [ 0.056187] Switched APIC routing to physical flat. [ 0.056198] Hyper-V: Using IPI hypercalls [ 0.056198] Hyper-V: Using enlightened APIC (xapic mode) [ 0.056253] Calibrating delay loop (skipped), value calculated using timer frequency.. 7200.02 BogoMIPS (lpj=36000100) [ 0.056255] pid_max: default: 32768 minimum: 301 [ 0.056269] LSM: Security Framework initializing [ 0.056341] Mount-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear) [ 0.056551] Mountpoint-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear) [ 0.056742] Last level iTLB entries: 4KB 64, 2MB 8, 4MB 8 [ 0.056743] Last level dTLB entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4 [ 0.056745] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization [ 0.056745] Spectre V2 : Mitigation: Full generic retpoline [ 0.056746] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch [ 0.056746] Spectre V2 : Enabling Restricted Speculation for firmware calls [ 0.056747] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier [ 0.056747] Spectre V2 : User space: Mitigation: STIBP via seccomp and prctl [ 0.056748] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp [ 0.056749] TAA: Vulnerable: Clear CPU buffers attempted, no microcode [ 0.056750] SRBDS: Unknown: Dependent on hypervisor status [ 0.056750] MDS: Vulnerable: Clear CPU buffers attempted, no microcode [ 0.056852] Freeing SMP alternatives memory: 56K [ 0.057709] smpboot: CPU0: Intel(R) Core(TM) i9-9900K CPU @ 3.60GHz (family: 0x6, model: 0x9e, stepping: 0xc) [ 0.057763] Performance Events: unsupported p6 CPU model 158 no PMU driver, software events only. [ 0.057777] rcu: Hierarchical SRCU implementation. [ 0.058066] smp: Bringing up secondary CPUs ... [ 0.058104] x86: Booting SMP configuration: [ 0.058105] .... node #0, CPUs: https://github.com/microsoft/WSL/issues/1 [ 0.058391] MDS CPU bug present and SMT on, data leak possible. See https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/mds.html for more details. [ 0.058391] TAA CPU bug present and SMT on, data leak possible. See https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/tsx_async_abort.html for more details. [ 0.058391] https://github.com/microsoft/WSL/issues/2 https://github.com/microsoft/WSL/issues/3 https://github.com/microsoft/WSL/issues/4 https://github.com/microsoft/WSL/issues/5 https://github.com/microsoft/WSL/issues/6 https://github.com/microsoft/WSL/issues/7 https://github.com/microsoft/WSL/issues/8 https://github.com/microsoft/WSL/issues/9 https://github.com/microsoft/WSL/issues/10 https://github.com/microsoft/WSL/issues/11 https://github.com/microsoft/WSL/issues/12 https://github.com/microsoft/WSL/issues/13 https://github.com/microsoft/WSL/issues/14 https://github.com/microsoft/WSL/issues/15 [ 0.058391] smp: Brought up 1 node, 16 CPUs [ 0.058391] smpboot: Max logical packages: 1 [ 0.058391] smpboot: Total of 16 processors activated (115200.32 BogoMIPS) [ 0.176277] node 0 deferred pages initialised in 120ms [ 0.177206] devtmpfs: initialized [ 0.177206] x86/mm: Memory block size: 128MB [ 0.178294] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.178294] futex hash table entries: 4096 (order: 6, 262144 bytes, linear) [ 0.178294] NET: Registered protocol family 16 [ 0.178294] thermal_sys: Registered thermal governor 'step_wise' [ 0.178294] cpuidle: using governor menu [ 0.178294] ACPI: bus type PCI registered [ 0.178294] PCI: Fatal: No config space access function found [ 0.178294] Kprobes globally optimized [ 0.178294] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.178294] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.178294] raid6: skip pq benchmark and using algorithm avx2x4 [ 0.178294] raid6: using avx2x2 recovery algorithm [ 0.178294] ACPI: Added _OSI(Module Device) [ 0.178294] ACPI: Added _OSI(Processor Device) [ 0.178294] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.178294] ACPI: Added _OSI(Processor Aggregator Device) [ 0.178294] ACPI: Added _OSI(Linux-Dell-Video) [ 0.178294] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio) [ 0.178294] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics) [ 0.187157] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.187778] ACPI: Interpreter enabled [ 0.187780] ACPI: (supports S0 S5) [ 0.187781] ACPI: Using IOAPIC for interrupt routing [ 0.187785] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.187890] ACPI: Enabled 1 GPEs in block 00 to 0F [ 0.188543] iommu: Default domain type: Translated [ 0.188592] SCSI subsystem initialized [ 0.188594] ACPI: bus type USB registered [ 0.188600] usbcore: registered new interface driver usbfs [ 0.188602] usbcore: registered new interface driver hub [ 0.188608] usbcore: registered new device driver usb [ 0.188630] hv_vmbus: Vmbus version:5.2 [ 0.188630] PCI: Using ACPI for IRQ routing [ 0.188630] PCI: System does not support PCI [ 0.188630] hv_vmbus: Unknown GUID: c376c1c3-d276-48d2-90a9-c04748072c60 [ 0.188630] clocksource: Switched to clocksource hyperv_clocksource_tsc_page [ 0.304982] VFS: Disk quotas dquot_6.6.0 [ 0.304989] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.305001] FS-Cache: Loaded [ 0.305017] pnp: PnP ACPI init [ 0.305044] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active) [ 0.305082] pnp: PnP ACPI: found 1 devices [ 0.309505] NET: Registered protocol family 2 [ 0.309750] IP idents hash table entries: 262144 (order: 9, 2097152 bytes, linear) [ 0.310889] tcp_listen_portaddr_hash hash table entries: 65536 (order: 8, 1048576 bytes, linear) [ 0.311110] TCP established hash table entries: 524288 (order: 10, 4194304 bytes, linear) [ 0.311715] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes, linear) [ 0.311792] TCP: Hash tables configured (established 524288 bind 65536) [ 0.311818] UDP hash table entries: 65536 (order: 9, 2097152 bytes, linear) [ 0.312095] UDP-Lite hash table entries: 65536 (order: 9, 2097152 bytes, linear) [ 0.312388] NET: Registered protocol family 1 [ 0.312939] RPC: Registered named UNIX socket transport module. [ 0.312939] RPC: Registered udp transport module. [ 0.312940] RPC: Registered tcp transport module. [ 0.312940] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.312942] PCI: CLS 0 bytes, default 64 [ 0.312989] Trying to unpack rootfs image as initramfs... [ 0.313155] Freeing initrd memory: 64K [ 0.313157] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 0.313158] software IO TLB: mapped [mem 0x00000000f4000000-0x00000000f8000000] (64MB) [ 0.313219] kvm: no hardware support [ 0.313220] has_svm: not amd or hygon [ 0.313220] kvm: no hardware support [ 0.316023] Initialise system trusted keyrings [ 0.316090] workingset: timestamp_bits=46 max_order=25 bucket_order=0 [ 0.316811] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ 0.316924] NFS: Registering the id_resolver key type [ 0.316931] Key type id_resolver registered [ 0.316931] Key type id_legacy registered [ 0.316933] nfs4filelayout_init: NFSv4 File Layout Driver Registering... [ 0.316934] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering... [ 0.316935] Installing knfsd (copyright (C) 1996 okir@monad.swb.de). [ 0.317308] Key type cifs.idmap registered [ 0.317351] fuse: init (API version 7.32) [ 0.317447] SGI XFS with ACLs, security attributes, realtime, scrub, repair, quota, no debug enabled [ 0.317650] 9p: Installing v9fs 9p2000 file system support [ 0.317656] FS-Cache: Netfs '9p' registered for caching [ 0.317683] FS-Cache: Netfs 'ceph' registered for caching [ 0.317685] ceph: loaded (mds proto 32) [ 0.322760] NET: Registered protocol family 38 [ 0.322761] xor: automatically using best checksumming function avx [ 0.322763] Key type asymmetric registered [ 0.322764] Asymmetric key parser 'x509' registered [ 0.322915] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250) [ 0.324184] hv_vmbus: registering driver hv_pci [ 0.324705] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled [ 0.325088] Non-volatile memory driver v1.3 [ 0.327942] brd: module loaded [ 0.328736] loop: module loaded [ 0.328765] hv_vmbus: registering driver hv_storvsc [ 0.329096] wireguard: WireGuard 1.0.0 loaded. See www.wireguard.com for information. [ 0.329096] wireguard: Copyright (C) 2015-2019 Jason A. Donenfeld Jason@zx2c4.com. All Rights Reserved. [ 0.329105] tun: Universal TUN/TAP device driver, 1.6 [ 0.329176] PPP generic driver version 2.4.2 [ 0.329271] PPP BSD Compression module registered [ 0.329272] PPP Deflate Compression module registered [ 0.329274] PPP MPPE Compression module registered [ 0.329274] NET: Registered protocol family 24 [ 0.329281] usbcore: registered new interface driver cdc_ether [ 0.329286] usbcore: registered new interface driver cdc_ncm [ 0.329286] hv_vmbus: registering driver hv_netvsc [ 0.329374] VFIO - User Level meta-driver version: 0.3 [ 0.329505] usbcore: registered new interface driver cdc_acm [ 0.329505] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters [ 0.329512] usbcore: registered new interface driver ch341 [ 0.329513] usbserial: USB Serial support registered for ch341-uart [ 0.329516] usbcore: registered new interface driver cp210x [ 0.329518] usbserial: USB Serial support registered for cp210x [ 0.329521] usbcore: registered new interface driver ftdi_sio [ 0.329523] usbserial: USB Serial support registered for FTDI USB Serial Device [ 0.329671] vhci_hcd vhci_hcd.0: USB/IP Virtual Host Controller [ 0.329673] vhci_hcd vhci_hcd.0: new USB bus registered, assigned bus number 1 [ 0.329676] vhci_hcd: created sysfs vhci_hcd.0 [ 0.329878] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10 [ 0.329879] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 0.329879] usb usb1: Product: USB/IP Virtual Host Controller [ 0.329880] usb usb1: Manufacturer: Linux 5.10.102.1-microsoft-standard-WSL2 vhci_hcd [ 0.329880] usb usb1: SerialNumber: vhci_hcd.0 [ 0.330061] hub 1-0:1.0: USB hub found [ 0.330117] hub 1-0:1.0: 8 ports detected [ 0.330454] scsi host0: storvsc_host_t [ 0.330479] vhci_hcd vhci_hcd.0: USB/IP Virtual Host Controller [ 0.330480] vhci_hcd vhci_hcd.0: new USB bus registered, assigned bus number 2 [ 0.330600] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. [ 0.330882] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.10 [ 0.330883] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 0.330883] usb usb2: Product: USB/IP Virtual Host Controller [ 0.330884] usb usb2: Manufacturer: Linux 5.10.102.1-microsoft-standard-WSL2 vhci_hcd [ 0.330884] usb usb2: SerialNumber: vhci_hcd.0 [ 0.331012] hub 2-0:1.0: USB hub found [ 0.331056] hub 2-0:1.0: 8 ports detected [ 0.331246] hv_vmbus: registering driver hyperv_keyboard [ 0.331370] rtc_cmos 00:00: RTC can wake from S4 [ 0.332522] rtc_cmos 00:00: registered as rtc0 [ 0.332802] rtc_cmos 00:00: setting system clock to 2022-06-30T13:01:27 UTC (1656594087) [ 0.332810] rtc_cmos 00:00: alarms up to one month, 114 bytes nvram [ 0.333055] device-mapper: ioctl: 4.43.0-ioctl (2020-10-01) initialised: dm-devel@redhat.com [ 0.333206] device-mapper: raid: Loading target version 1.15.1 [ 0.333228] usbcore: registered new interface driver usbhid [ 0.333229] usbhid: USB HID core driver [ 0.333311] hv_utils: Registering HyperV Utility Driver [ 0.333312] hv_vmbus: registering driver hv_utils [ 0.333334] hv_vmbus: registering driver hv_balloon [ 0.333338] hv_utils: cannot register PTP clock: 0 [ 0.333355] hv_vmbus: registering driver dxgkrnl [ 0.333359] (NULL device ): dxgk: dxg_drv_init Version: 2216 [ 0.333373] drop_monitor: Initializing network drop monitor service [ 0.333385] Mirror/redirect action on [ 0.333767] hv_utils: TimeSync IC version 4.0 [ 0.333800] hv_balloon: Using Dynamic Memory protocol version 2.0 [ 0.333898] IPVS: Registered protocols (TCP, UDP) [ 0.333924] IPVS: Connection hash table configured (size=4096, memory=64Kbytes) [ 0.333952] IPVS: ipvs loaded. [ 0.333953] IPVS: [rr] scheduler registered. [ 0.333954] IPVS: [wrr] scheduler registered. [ 0.333954] IPVS: [sh] scheduler registered. [ 0.334177] ipip: IPv4 and MPLS over IPv4 tunneling driver [ 0.334374] Free page reporting enabled [ 0.334375] hv_balloon: Cold memory discard hint enabled [ 0.335752] ipt_CLUSTERIP: ClusterIP Version 0.8 loaded successfully [ 0.336103] Initializing XFRM netlink socket [ 0.336140] NET: Registered protocol family 10 [ 0.336341] Segment Routing with IPv6 [ 0.337334] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver [ 0.337384] NET: Registered protocol family 17 [ 0.337396] Bridge firewalling registered [ 0.337401] 8021q: 802.1Q VLAN Support v1.8 [ 0.337414] sctp: Hash tables configured (bind 2048/2048) [ 0.337602] 9pnet: Installing 9P2000 support [ 0.337612] Key type dns_resolver registered [ 0.337615] Key type ceph registered [ 0.337695] libceph: loaded (mon/osd proto 15/24) [ 0.337739] NET: Registered protocol family 40 [ 0.337739] hv_vmbus: registering driver hv_sock [ 0.337756] IPI shorthand broadcast: enabled [ 0.337761] sched_clock: Marking stable (337402400, 328500)->(344566800, -6835900) [ 0.337951] registered taskstats version 1 [ 0.337957] Loading compiled-in X.509 certificates [ 0.338089] Btrfs loaded, crc32c=crc32c-generic [ 0.340368] Freeing unused kernel image (initmem) memory: 1580K [ 0.406412] Write protecting the kernel read-only data: 28672k [ 0.407103] Freeing unused kernel image (text/rodata gap) memory: 2024K [ 0.407504] Freeing unused kernel image (rodata/data gap) memory: 1192K [ 0.407506] Run /init as init process [ 0.407506] with arguments: [ 0.407506] /init [ 0.407507] with environment: [ 0.407507] HOME=/ [ 0.407507] TERM=linux [ 38.826209] hv_vmbus: Unknown GUID: 6e382d18-3336-4f4b-acc4-2b7703d4df4a [ 38.826268] hv_vmbus: Unknown GUID: dde9cbc0-5060-4436-9448-ea1254a5d177 [ 38.828949] hv_pci ff4c2fda-0b6c-4969-aee1-ee6b25a26548: PCI VMBus probing: Using version 0x10003 [ 38.829810] hv_pci ff4c2fda-0b6c-4969-aee1-ee6b25a26548: PCI host bridge to bus 0b6c:00 [ 38.830071] pci 0b6c:00:00.0: [1414:008e] type 00 class 0x030200 [ 38.834793] (NULL device ): dxgk: mmio allocated c00000000 200000000 c00000000 dffffffff [ 38.957277] scsi 0:0:0:0: Direct-Access Msft Virtual Disk 1.0 PQ: 0 ANSI: 5 [ 38.957777] sd 0:0:0:0: Attached scsi generic sg0 type 0 [ 38.958799] sd 0:0:0:0: [sda] 536870912 512-byte logical blocks: (275 GB/256 GiB) [ 38.958800] sd 0:0:0:0: [sda] 4096-byte physical blocks [ 38.959023] sd 0:0:0:0: [sda] Write Protect is off [ 38.959025] sd 0:0:0:0: [sda] Mode Sense: 0f 00 00 00 [ 38.959368] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 38.960707] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 39.242092] EXT4-fs (sda): mounted filesystem with ordered data mode. Opts: discard,errors=remount-ro,data=ordered [ 39.346759] sd 0:0:0:0: [sda] Attached SCSI disk [ 40.446435] Adding 27262976k swap on /swap/file. Priority:-2 extents:5 across:27295744k [ 41.116585] scsi 0:0:0:1: Direct-Access Msft Virtual Disk 1.0 PQ: 0 ANSI: 5 [ 41.117146] sd 0:0:0:1: Attached scsi generic sg1 type 0 [ 41.118205] sd 0:0:0:1: [sdb] 536870912 512-byte logical blocks: (275 GB/256 GiB) [ 41.118206] sd 0:0:0:1: [sdb] 4096-byte physical blocks [ 41.118328] sd 0:0:0:1: [sdb] Write Protect is off [ 41.118329] sd 0:0:0:1: [sdb] Mode Sense: 0f 00 00 00 [ 41.118625] sd 0:0:0:1: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 41.121488] sd 0:0:0:1: [sdb] Attached SCSI disk [ 41.133377] EXT4-fs (sdb): mounted filesystem with ordered data mode. Opts: discard,errors=remount-ro,data=ordered [ 41.143652] FS-Cache: Duplicate cookie detected [ 41.143653] FS-Cache: O-cookie c=00000000dd6b555d [p=000000001bc55327 fl=222 nc=0 na=1] [ 41.143654] FS-Cache: O-cookie d=0000000083bfbaeb n=000000000f13ab36 [ 41.143654] FS-Cache: O-key=[10] '34323934393431343035' [ 41.143657] FS-Cache: N-cookie c=0000000089a002d8 [p=000000001bc55327 fl=2 nc=0 na=1] [ 41.143658] FS-Cache: N-cookie d=0000000083bfbaeb n=00000000a41eebbb [ 41.143658] FS-Cache: N-key=[10] '34323934393431343035' [ 41.269501] FS-Cache: Duplicate cookie detected [ 41.269502] FS-Cache: O-cookie c=0000000068ab73f0 [p=000000001bc55327 fl=222 nc=0 na=1] [ 41.269503] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000cb304dd0 [ 41.269503] FS-Cache: O-key=[10] '34323934393431343138' [ 41.269507] FS-Cache: N-cookie c=00000000f8ae9a8b [p=000000001bc55327 fl=2 nc=0 na=1] [ 41.269507] FS-Cache: N-cookie d=0000000083bfbaeb n=00000000a974287d [ 41.269507] FS-Cache: N-key=[10] '34323934393431343138' [ 41.271220] FS-Cache: Duplicate cookie detected [ 41.271221] FS-Cache: O-cookie c=0000000068ab73f0 [p=000000001bc55327 fl=222 nc=0 na=1] [ 41.271221] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000cb304dd0 [ 41.271222] FS-Cache: O-key=[10] '34323934393431343138' [ 41.271225] FS-Cache: N-cookie c=000000008cce34cf [p=000000001bc55327 fl=2 nc=0 na=1] [ 41.271225] FS-Cache: N-cookie d=0000000083bfbaeb n=000000007debbb98 [ 41.271226] FS-Cache: N-key=[10] '34323934393431343138' [ 41.272900] FS-Cache: Duplicate cookie detected [ 41.272901] FS-Cache: O-cookie c=0000000068ab73f0 [p=000000001bc55327 fl=222 nc=0 na=1] [ 41.272902] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000cb304dd0 [ 41.272902] FS-Cache: O-key=[10] '34323934393431343138' [ 41.272905] FS-Cache: N-cookie c=00000000119ca479 [p=000000001bc55327 fl=2 nc=0 na=1] [ 41.272906] FS-Cache: N-cookie d=0000000083bfbaeb n=000000005c433c92 [ 41.272906] FS-Cache: N-key=[10] '34323934393431343138' [ 41.274450] FS-Cache: Duplicate cookie detected [ 41.274451] FS-Cache: O-cookie c=0000000068ab73f0 [p=000000001bc55327 fl=222 nc=0 na=1] [ 41.274451] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000cb304dd0 [ 41.274452] FS-Cache: O-key=[10] '34323934393431343138' [ 41.274455] FS-Cache: N-cookie c=00000000119ca479 [p=000000001bc55327 fl=2 nc=0 na=1] [ 41.274456] FS-Cache: N-cookie d=0000000083bfbaeb n=00000000b4b79833 [ 41.274456] FS-Cache: N-key=[10] '34323934393431343138' [ 41.275958] FS-Cache: Duplicate cookie detected [ 41.275960] FS-Cache: O-cookie c=0000000068ab73f0 [p=000000001bc55327 fl=222 nc=0 na=1] [ 41.275960] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000cb304dd0 [ 41.275960] FS-Cache: O-key=[10] '34323934393431343138' [ 41.275964] FS-Cache: N-cookie c=00000000119ca479 [p=000000001bc55327 fl=2 nc=0 na=1] [ 41.275964] FS-Cache: N-cookie d=0000000083bfbaeb n=00000000d26055ac [ 41.275964] FS-Cache: N-key=[10] '34323934393431343138' [ 49.208537] hv_balloon: Max. dynamic memory size: 104788 MB [ 68.910114] EXT4-fs (sdb): mounted filesystem with ordered data mode. Opts: discard,errors=remount-ro,data=ordered [ 68.921484] FS-Cache: Duplicate cookie detected [ 68.921486] FS-Cache: O-cookie c=00000000bc269de8 [p=000000001bc55327 fl=222 nc=0 na=1] [ 68.921487] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000c5f50706 [ 68.921487] FS-Cache: O-key=[10] '34323934393434313833' [ 68.921490] FS-Cache: N-cookie c=00000000de05fe51 [p=000000001bc55327 fl=2 nc=0 na=1] [ 68.921491] FS-Cache: N-cookie d=0000000083bfbaeb n=00000000d6f5c564 [ 68.921491] FS-Cache: N-key=[10] '34323934393434313833' [ 69.049679] FS-Cache: Duplicate cookie detected [ 69.049681] FS-Cache: O-cookie c=00000000720c1e76 [p=000000001bc55327 fl=222 nc=0 na=1] [ 69.049682] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000d4ae87e6 [ 69.049682] FS-Cache: O-key=[10] '34323934393434313936' [ 69.049685] FS-Cache: N-cookie c=0000000089a002d8 [p=000000001bc55327 fl=2 nc=0 na=1] [ 69.049686] FS-Cache: N-cookie d=0000000083bfbaeb n=000000008869727e [ 69.049686] FS-Cache: N-key=[10] '34323934393434313936' [ 69.051121] FS-Cache: Duplicate cookie detected [ 69.051122] FS-Cache: O-cookie c=00000000720c1e76 [p=000000001bc55327 fl=222 nc=0 na=1] [ 69.051122] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000d4ae87e6 [ 69.051123] FS-Cache: O-key=[10] '34323934393434313936' [ 69.051126] FS-Cache: N-cookie c=000000008cce34cf [p=000000001bc55327 fl=2 nc=0 na=1] [ 69.051127] FS-Cache: N-cookie d=0000000083bfbaeb n=00000000080ff813 [ 69.051127] FS-Cache: N-key=[10] '34323934393434313936' [ 69.052353] FS-Cache: Duplicate cookie detected [ 69.052354] FS-Cache: O-cookie c=00000000720c1e76 [p=000000001bc55327 fl=222 nc=0 na=1] [ 69.052355] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000d4ae87e6 [ 69.052355] FS-Cache: O-key=[10] '34323934393434313936' [ 69.052358] FS-Cache: N-cookie c=00000000f8ae9a8b [p=000000001bc55327 fl=2 nc=0 na=1] [ 69.052359] FS-Cache: N-cookie d=0000000083bfbaeb n=000000001ecc1257 [ 69.052359] FS-Cache: N-key=[10] '34323934393434313936' [ 69.053636] FS-Cache: Duplicate cookie detected [ 69.053637] FS-Cache: O-cookie c=00000000720c1e76 [p=000000001bc55327 fl=222 nc=0 na=1] [ 69.053637] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000d4ae87e6 [ 69.053638] FS-Cache: O-key=[10] '34323934393434313936' [ 69.053641] FS-Cache: N-cookie c=00000000f8ae9a8b [p=000000001bc55327 fl=2 nc=0 na=1] [ 69.053641] FS-Cache: N-cookie d=0000000083bfbaeb n=00000000174e009c [ 69.053642] FS-Cache: N-key=[10] '34323934393434313936' [ 69.055108] FS-Cache: Duplicate cookie detected [ 69.055109] FS-Cache: O-cookie c=00000000720c1e76 [p=000000001bc55327 fl=222 nc=0 na=1] [ 69.055109] FS-Cache: O-cookie d=0000000083bfbaeb n=00000000d4ae87e6 [ 69.055110] FS-Cache: O-key=[10] '34323934393434313936' [ 69.055113] FS-Cache: N-cookie c=00000000f8ae9a8b [p=000000001bc55327 fl=2 nc=0 na=1] [ 69.055113] FS-Cache: N-cookie d=0000000083bfbaeb n=0000000023001571 [ 69.055114] FS-Cache: N-key=[10] '34323934393434313936' [ 99.961212] WSL2: Performing memory compaction.

benhillis commented 2 years ago

Interesting, I have not seen this. /logs

ghost commented 2 years ago

Hello! Could you please provide more logs to help us better diagnose your issue?

To collect WSL logs, download and execute collect-wsl-logs.ps1 in an administrative powershell prompt:

Invoke-WebRequest -UseBasicParsing "https://raw.githubusercontent.com/microsoft/WSL/master/diagnostics/collect-wsl-logs.ps1" -OutFile collect-wsl-logs.ps1
Set-ExecutionPolicy Bypass -Scope Process -Force
.\collect-wsl-logs.ps1

The scipt will output the path of the log file once done.

Once completed please upload the output files to this Github issue.

Click here for more info on logging

Thank you!

mprevot commented 2 years ago

On my machine C:\ProgramData\Microsoft\Windows\WindowsApps does not exists.

Here are the logs anyway:: WslLogs-2022-07-05_21-11-28.zip

plsedv commented 1 year ago

Same issue here. I attached the log file. WslLogs-2023-01-25_08-09-03.zip

logularjason commented 1 year ago

Same issue. dmesg suggests that the startup delays occur at the lines hv_pci and also hv_balloon. Logs attached.

WslLogs-2023-01-26_12-10-38.zip

dicoeenvoud commented 1 year ago

Same issue here, with a startup time of around 4 minutes. Yesterday it still started in a couple of seconds.

WslLogs-2023-02-07_09-51-19.zip

christianjunk commented 1 year ago

Same issue here. Startup takes more than one minute.

lister169126 commented 1 year ago

Same here. Windows 10 21H2 19044.2604 it's happening every start after update wsl. WSL version: WSL: 1.1.3.0 kernel: 5.15.90.1 WSLg: 1.0.49 MSRDC: 1.2.3770 Direct3D: 1.608.2-61064218 DXCore: 10.0.25131.1002-220531-1700.rs-onecore-base2-hyp Windows: 10.0.19044.2604

It works fine on previous version Windows/WSL: 10.0.19041.2311

Here's dmesg from old version of wsl and new version. I can send extended logs as above, but it's the same. new_ver.log old_ver.log

deviantdev commented 1 year ago

guys, just use this path to run wsl, remove/reinit the previous links at your system and be happy!

%programfiles%\WindowsApps\MicrosoftCorporationII.WindowsSubsystemForLinux_1.1.6.0_x64__8wekyb3d8bbwe\wsl.exe

example: "C:\Program Files\WindowsApps\MicrosoftCorporationII.WindowsSubsystemForLinux_1.1.6.0_x64__8wekyb3d8bbwe\wsl.exe" -d Ubuntu -- echo "$PATH"

tilenkranjc commented 1 year ago

What worked for me was to unmap all inaccessible network drives, as in #9358 . Now it takes only a few seconds.

oomek commented 1 year ago

Disconnectting mapped drives is not a solution. I have 6 mostly offline mapped drives and WSL start takes 4 minutes and 17 seconds. This issue also should be reopened.

mprevot commented 1 year ago

A solution would be to be able to set the timeout for network drives, and maybe do a parallel check of drives (I suspect is is sequential).

mrajweir commented 1 year ago

What worked for me was to unmap all inaccessible network drives, as in #9358 . Now it takes only a few seconds.

This was the cause of the delay for me, but as others have said - it's not a solution. Thanks for sharing. How did you even think to check network drives in the first place?

hoegge commented 1 year ago

Is there really no way to troubleshoot this?

mrajweir commented 1 year ago

Is there really no way to troubleshoot this?

It looks like it's been extensively debugged between:

Going back to the point - the best thing to do is unmap disconnected drives for now and keep checking those tickets for updates.

Luuk34 commented 10 months ago

Still not solved?????? 🤬😁😉

pedrohgmacedo commented 10 months ago

This happens for me as well in WSL1, when automount is set to true in wsl.conf.

oHervis commented 10 months ago

Same issue here. :/

mrajweir commented 10 months ago

Same issue here. :/

Check your network drives and unmap any disconnected ones. They slow WSL on initialization.

oomek commented 10 months ago

Same issue here. :/

Check your network drives and unmap any disconnected ones. They slow WSL on initialization.

Hey Sherlock, the whole point of this issue is not being forced to constantly map and unpap inactive drives.

JacktheGodzillaSlayer commented 8 months ago

Same here, my OS SSD swapped from machine to machine, and ever did many network drive mapping, slow to start wsl as well, also the OS has difficulty to show quick lunch and network item on explorer on the left bar. Last time while I tried to copy a bunch of files from wsl system to usb, it stuck, then I reboot the system now the WSL2 won't even start... image

JacktheGodzillaSlayer commented 8 months ago

Try to use the reset options for "Windows Subsystem for Linux" then restart? I resolved the wsl stuck issue by doing this. image image

BreizhHardware commented 8 months ago

WslLogs-2024-04-01_11-38-42.zip Same issues here, know I cannot start WSL (debian)

xuefer commented 7 months ago

dmsg shows hv_ballon takes 40 seconds

david-blanchard commented 6 months ago

@JacktheGodzillaSlayer, neither removing the Windows Siubsystem for Linux Update or repairing the main app did work for me.

Instead I had to pay attention that all remote units were available (E:, F: G:, etc), because Linux guests try to mount these units too. When they don't find them, it takes a while before the system decide to stop mounting them.

Kaiser-Yang commented 4 months ago

I meet with this, and I figure out that I set auto mount with sshfs in /etc/fstab. And, I reach another network and I forget to set thevpn to access the server, so every time I restart the distro it takes time (must wait the ssh be timed out), I just remove the auto mount, then everything works well. Thanks for your comment giving me inspirations @david-blanchard