Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"first boot of the day" takes wsl a long time to start #5680

Closed
patricknazar opened this issue Jul 30, 2020 · 11 comments
Closed

"first boot of the day" takes wsl a long time to start #5680

patricknazar opened this issue Jul 30, 2020 · 11 comments

Comments

@patricknazar
Copy link

patricknazar commented Jul 30, 2020

Environment

Windows build number: Win32NT             10.0.20175.0 Microsoft Windows NT 10.0.20175.0
Your Distribution version: Release:        18.04
Whether the issue is on WSL 2 and/or WSL 1: it's 2: Linux version 4.19.104-microsoft-standard (oe-user@oe-host) (gcc version 8.2.0 (GCC)) #1 SMP Wed Feb 19 06:37:35 UTC 2020

Steps to reproduce

Every "first boot of the day" my wsl will delay starting up, which then causes my docker-desktop to not start etc.

Expected behavior

Doesn't have this big delay starting up.

Actual behavior

Has unusual delay starting up.

wsl "dmesg" output (note the last line):

[    0.000000] Linux version 4.19.104-microsoft-standard (oe-user@oe-host) (gcc version 8.2.0 (GCC)) #1 SMP Wed Feb 19 06:37:35 UTC 2020
[    0.000000] Command line: initrd=\initrd.img panic=-1 nr_cpus=4 swiotlb=force  pty.legacy_count=0
[    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: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    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-0x00000002057fffff] 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: features 0xae7f, hints 0x2c2c
[    0.000000] Hyper-V Host Build:20175-10.0-1-0.1000
[    0.000000] Hyper-V: LAPIC Timer Frequency: 0x1e8480
[    0.000000] tsc: Marking TSC unstable due to running on Hyper-V
[    0.000000] Hyper-V: Using hypercall for remote TLB flush
[    0.000000] tsc: Detected 3693.106 MHz processor
[    0.000005] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000006] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000008] last_pfn = 0x205800 max_arch_pfn = 0x400000000
[    0.000033] MTRR default type: uncachable
[    0.000034] MTRR fixed ranges disabled:
[    0.000034]   00000-FFFFF uncachable
[    0.000035] MTRR variable ranges disabled:
[    0.000035]   0 disabled
[    0.000035]   1 disabled
[    0.000036]   2 disabled
[    0.000036]   3 disabled
[    0.000036]   4 disabled
[    0.000036]   5 disabled
[    0.000036]   6 disabled
[    0.000037]   7 disabled
[    0.000037] Disabled
[    0.000038] x86/PAT: MTRRs disabled, skipping PAT initialization too.
[    0.000045] CPU MTRRs all blank - virtualized system.
[    0.000046] x86/PAT: Configuration [0-7]: WB  WT  UC- UC  WB  WT  UC- UC
[    0.000047] last_pfn = 0xf8000 max_arch_pfn = 0x400000000
[    0.000061] Using GB pages for direct mapping
[    0.000062] BRK [0x02e00000, 0x02e00fff] PGTABLE
[    0.000063] BRK [0x02e01000, 0x02e01fff] PGTABLE
[    0.000063] BRK [0x02e02000, 0x02e02fff] PGTABLE
[    0.000106] BRK [0x02e03000, 0x02e03fff] PGTABLE
[    0.000409] RAMDISK: [mem 0x02e35000-0x02e45fff]
[    0.000412] ACPI: Early table checksum verification disabled
[    0.000419] ACPI: RSDP 0x00000000000E0000 000024 (v02 VRTUAL)
[    0.000422] ACPI: XSDT 0x0000000000100000 000044 (v01 VRTUAL MICROSFT 00000001 MSFT 00000001)
[    0.000425] ACPI: FACP 0x0000000000101000 000114 (v06 VRTUAL MICROSFT 00000001 MSFT 00000001)
[    0.000429] ACPI: DSDT 0x00000000001011B8 01E184 (v02 MSFTVM DSDT01   00000001 MSFT 05000000)
[    0.000431] ACPI: FACS 0x0000000000101114 000040
[    0.000433] ACPI: OEM0 0x0000000000101154 000064 (v01 VRTUAL MICROSFT 00000001 MSFT 00000001)
[    0.000434] ACPI: SRAT 0x000000000011F33C 0002F0 (v02 VRTUAL MICROSFT 00000001 MSFT 00000001)
[    0.000436] ACPI: APIC 0x000000000011F62C 000068 (v04 VRTUAL MICROSFT 00000001 MSFT 00000001)
[    0.000440] ACPI: Local APIC address 0xfee00000
[    0.000772] Zone ranges:
[    0.000773]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000774]   DMA32    [mem 0x0000000001000000-0x00000000ffffffff]
[    0.000775]   Normal   [mem 0x0000000100000000-0x00000002057fffff]
[    0.000776] Movable zone start for each node
[    0.000776] Early memory node ranges
[    0.000776]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.000777]   node   0: [mem 0x0000000000200000-0x00000000f7ffffff]
[    0.000777]   node   0: [mem 0x0000000100000000-0x00000002057fffff]
[    0.001261] Zeroed struct page in unavailable ranges: 10593 pages
[    0.001263] Initmem setup node 0 [mem 0x0000000000001000-0x00000002057fffff]
[    0.001264] On node 0 totalpages: 2086559
[    0.001265]   DMA zone: 59 pages used for memmap
[    0.001265]   DMA zone: 22 pages reserved
[    0.001266]   DMA zone: 3743 pages, LIFO batch:0
[    0.001322]   DMA32 zone: 16320 pages used for memmap
[    0.001323]   DMA32 zone: 1011712 pages, LIFO batch:63
[    0.022614]   Normal zone: 16736 pages used for memmap
[    0.022615]   Normal zone: 1071104 pages, LIFO batch:63
[    0.023290] ACPI: Local APIC address 0xfee00000
[    0.023296] ACPI: LAPIC_NMI (acpi_id[0x01] dfl dfl lint[0x1])
[    0.023603] IOAPIC[0]: apic_id 4, version 17, address 0xfec00000, GSI 0-23
[    0.023606] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.023607] ACPI: IRQ9 used by override.
[    0.023609] Using ACPI (MADT) for SMP configuration information
[    0.023614] smpboot: Allowing 4 CPUs, 0 hotplug CPUs
[    0.023623] [mem 0xf8000000-0xffffffff] available for PCI devices
[    0.023623] Booting paravirtualized kernel on bare hardware
[    0.023625] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.136393] random: get_random_bytes called from start_kernel+0x93/0x4bb with crng_init=0
[    0.136399] setup_percpu: NR_CPUS:256 nr_cpumask_bits:256 nr_cpu_ids:4 nr_node_ids:1
[    0.136765] percpu: Embedded 42 pages/cpu s133400 r8192 d30440 u524288
[    0.136769] pcpu-alloc: s133400 r8192 d30440 u524288 alloc=1*2097152
[    0.136769] pcpu-alloc: [0] 0 1 2 3
[    0.136779] Built 1 zonelists, mobility grouping on.  Total pages: 2053422
[    0.136781] Kernel command line: initrd=\initrd.img panic=-1 nr_cpus=4 swiotlb=force  pty.legacy_count=0
[    0.138162] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes)
[    0.138891] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.159171] Memory: 4096400K/8346236K available (14360K kernel code, 1575K rwdata, 2836K rodata, 1504K init, 2792K bss, 240988K reserved, 0K cma-reserved)
[    0.159427] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.159435] ftrace: allocating 41537 entries in 163 pages
[    0.170395] rcu: Hierarchical RCU implementation.
[    0.170396] rcu:     RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4.
[    0.170397]  All grace periods are expedited (rcu_expedited).
[    0.170397] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.172153] Using NULL legacy PIC
[    0.172154] NR_IRQS: 16640, nr_irqs: 456, preallocated irqs: 0
[    0.172472] Console: colour dummy device 80x25
[    0.172474] console [tty0] enabled
[    0.172478] ACPI: Core revision 20180810
[    0.172563] Failed to register legacy timer interrupt
[    0.172571] APIC: Switch to symmetric I/O mode setup
[    0.172587] Hyper-V: Using IPI hypercalls
[    0.172587] Hyper-V: Using MSR based APIC access
[    0.172592] clocksource: hyperv_clocksource_tsc_page: mask: 0xffffffffffffffff max_cycles: 0x24e6a1710, max_idle_ns: 440795202120 ns
[    0.172683] Calibrating delay loop (skipped), value calculated using timer frequency.. 7386.21 BogoMIPS (lpj=36931060)
[    0.172684] pid_max: default: 32768 minimum: 301
[    0.172696] Security Framework initialized
[    0.172712] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes)
[    0.172735] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes)
[    0.172955] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 512
[    0.172955] Last level dTLB entries: 4KB 1536, 2MB 1536, 4MB 768, 1GB 0
[    0.172956] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[    0.172957] Spectre V2 : Spectre mitigation: LFENCE not serializing, switching to generic retpoline
[    0.172957] Spectre V2 : Mitigation: Full generic retpoline
[    0.172958] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.172961] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
[    0.172961] Spectre V2 : User space: Vulnerable
[    0.172962] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[    0.173145] Freeing SMP alternatives memory: 44K
[    0.173864] smpboot: CPU0: AMD Ryzen 7 2700X Eight-Core Processor (family: 0x17, model: 0x8, stepping: 0x2)
[    0.173916] Performance Events: PMU not available due to virtualization, using software events only.
[    0.174045] rcu: Hierarchical SRCU implementation.
[    0.174333] random: crng done (trusting CPU's manufacturer)
[    0.174363] smp: Bringing up secondary CPUs ...
[    0.174407] x86: Booting SMP configuration:
[    0.174407] .... node  #0, CPUs:      #1 #2 #3
[    0.622764] smp: Brought up 1 node, 4 CPUs
[    0.622764] smpboot: Max logical packages: 1
[    0.622764] smpboot: Total of 4 processors activated (29545.61 BogoMIPS)
[    0.642687] node 0 initialised, 1002212 pages in 20ms
[    0.643291] devtmpfs: initialized
[    0.643291] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.643291] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.643291] xor: automatically using best checksumming function   avx
[    0.643763] NET: Registered protocol family 16
[    0.643934] ACPI: bus type PCI registered
[    0.643934] PCI: Fatal: No config space access function found
[    0.643934] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.643934] raid6: Forced to use recovery algorithm avx2x2
[    0.643934] raid6: Forced gen() algo avx2x4
[    0.643934] ACPI: Added _OSI(Module Device)
[    0.643934] ACPI: Added _OSI(Processor Device)
[    0.643934] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.643934] ACPI: Added _OSI(Processor Aggregator Device)
[    0.643934] ACPI: Added _OSI(Linux-Dell-Video)
[    0.643934] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    0.655261] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.655934] ACPI: Interpreter enabled
[    0.655934] ACPI: (supports S0 S5)
[    0.655934] ACPI: Using IOAPIC for interrupt routing
[    0.655934] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.655934] ACPI: Enabled 1 GPEs in block 00 to 0F
[    0.655954] SCSI subsystem initialized
[    0.655954] hv_vmbus: Vmbus version:5.0
[    0.655954] PCI: Using ACPI for IRQ routing
[    0.655954] PCI: System does not support PCI
[    0.655954] hv_vmbus: Unknown GUID: c376c1c3-d276-48d2-90a9-c04748072c60
[    0.655954] hv_vmbus: Unknown GUID: 6e382d18-3336-4f4b-acc4-2b7703d4df4a
[    0.655954] hv_vmbus: Unknown GUID: dde9cbc0-5060-4436-9448-ea1254a5d177
[    0.655954] clocksource: Switched to clocksource hyperv_clocksource_tsc_page
[    0.664419] VFS: Disk quotas dquot_6.6.0
[    0.664430] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.664463] FS-Cache: Loaded
[    0.664487] pnp: PnP ACPI init
[    0.664528] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.664542] pnp: PnP ACPI: found 1 devices
[    0.669086] NET: Registered protocol family 2
[    0.669194] tcp_listen_portaddr_hash hash table entries: 4096 (order: 4, 65536 bytes)
[    0.669202] TCP established hash table entries: 65536 (order: 7, 524288 bytes)
[    0.669457] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes)
[    0.669539] TCP: Hash tables configured (established 65536 bind 65536)
[    0.669558] UDP hash table entries: 4096 (order: 5, 131072 bytes)
[    0.669570] UDP-Lite hash table entries: 4096 (order: 5, 131072 bytes)
[    0.669598] NET: Registered protocol family 1
[    0.669904] RPC: Registered named UNIX socket transport module.
[    0.669904] RPC: Registered udp transport module.
[    0.669905] RPC: Registered tcp transport module.
[    0.669905] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.669906] PCI: CLS 0 bytes, default 64
[    0.669929] Trying to unpack rootfs image as initramfs...
[    0.670119] Freeing initrd memory: 68K
[    0.670122] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    0.670123] software IO TLB: mapped [mem 0xf4000000-0xf8000000] (64MB)
[    0.670455] kvm: no hardware support
[    0.670661] kvm: Nested Virtualization enabled
[    0.670662] kvm: Nested Paging enabled
[    0.670662] SVM: Virtual VMLOAD VMSAVE supported
[    0.671179] Initialise system trusted keyrings
[    0.671281] workingset: timestamp_bits=46 max_order=21 bucket_order=0
[    0.672234] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.672446] NFS: Registering the id_resolver key type
[    0.672450] Key type id_resolver registered
[    0.672451] Key type id_legacy registered
[    0.672452] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[    0.672880] Key type cifs.idmap registered
[    0.672942] fuse init (API version 7.27)
[    0.673084] SGI XFS with ACLs, security attributes, realtime, scrub, no debug enabled
[    0.673708] 9p: Installing v9fs 9p2000 file system support
[    0.673717] FS-Cache: Netfs '9p' registered for caching
[    0.673760] FS-Cache: Netfs 'ceph' registered for caching
[    0.673763] ceph: loaded (mds proto 32)
[    0.677892] NET: Registered protocol family 38
[    0.677894] Key type asymmetric registered
[    0.677894] Asymmetric key parser 'x509' registered
[    0.677905] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.677906] io scheduler noop registered (default)
[    0.678133] hv_vmbus: registering driver hv_pci
[    0.678566] hv_pci be54b768-5305-4f82-b76f-e468452a1554: PCI VMBus probing: Using version 0x10002
[    0.679184] hv_pci be54b768-5305-4f82-b76f-e468452a1554: PCI host bridge to bus b76f:00
[    0.679427] pci b76f:00:00.0: [1414:008e] type 00 class 0x030200
[    0.684845] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
[    0.685243] Non-volatile memory driver v1.3
[    0.687428] brd: module loaded
[    0.688216] loop: module loaded
[    0.688302] hv_vmbus: registering driver hv_storvsc
[    0.688343] Ethernet Channel Bonding Driver: v3.7.1 (April 27, 2011)
[    0.688692] tun: Universal TUN/TAP device driver, 1.6
[    0.688764] PPP generic driver version 2.4.2
[    0.688827] PPP BSD Compression module registered
[    0.688828] PPP Deflate Compression module registered
[    0.688833] PPP MPPE Compression module registered
[    0.688834] NET: Registered protocol family 24
[    0.688838] hv_vmbus: registering driver hv_netvsc
[    0.690256] scsi host0: storvsc_host_t
[    0.697609] VFIO - User Level meta-driver version: 0.3
[    0.697902] hv_vmbus: registering driver hyperv_keyboard
[    0.698089] rtc_cmos 00:00: RTC can wake from S4
[    0.699545] rtc_cmos 00:00: registered as rtc0
[    0.699553] rtc_cmos 00:00: alarms up to one month, 114 bytes nvram
[    0.699989] device-mapper: ioctl: 4.39.0-ioctl (2018-04-03) initialised: dm-devel@redhat.com
[    0.700241] hv_utils: Registering HyperV Utility Driver
[    0.700242] hv_vmbus: registering driver hv_util
[    0.700266] hv_vmbus: registering driver hv_balloon
[    0.700292] hv_utils: cannot register PTP clock: 0
[    0.700307] drop_monitor: Initializing network drop monitor service
[    0.700529] hv_utils: TimeSync IC version 4.0
[    0.700989] hv_balloon: Using Dynamic Memory protocol version 2.0
[    0.701528] Mirror/redirect action on
[    0.701570] hv_balloon: cold memory discard enabled
[    0.701811] IPVS: Registered protocols (TCP, UDP)
[    0.701829] IPVS: Connection hash table configured (size=4096, memory=64Kbytes)
[    0.702636] IPVS: ipvs loaded.
[    0.702637] IPVS: [rr] scheduler registered.
[    0.702638] IPVS: [wrr] scheduler registered.
[    0.702638] IPVS: [sh] scheduler registered.
[    0.703915] ipt_CLUSTERIP: ClusterIP Version 0.8 loaded successfully
[    0.704103] Initializing XFRM netlink socket
[    0.704150] NET: Registered protocol family 10
[    0.704488] Segment Routing with IPv6
[    0.705778] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[    0.705853] NET: Registered protocol family 17
[    0.705867] Bridge firewalling registered
[    0.705874] 8021q: 802.1Q VLAN Support v1.8
[    0.705891] sctp: Hash tables configured (bind 256/256)
[    0.705929] 9pnet: Installing 9P2000 support
[    0.705941] Key type dns_resolver registered
[    0.705945] Key type ceph registered
[    0.706128] libceph: loaded (mon/osd proto 15/24)
[    0.706130] hv_vmbus: registering driver hv_sock
[    0.706215] NET: Registered protocol family 40
[    0.706493] registered taskstats version 1
[    0.706497] Loading compiled-in X.509 certificates
[    0.706876] Btrfs loaded, crc32c=crc32c-generic
[    0.707357] rtc_cmos 00:00: setting system clock to 2020-07-30 00:57:41 UTC (1596070661)
[    0.707369] Unstable clock detected, switching default tracing clock to "global"
               If you want to keep using the local clock, then add:
                 "trace_clock=local"
               on the kernel command line
[    0.708787] Freeing unused kernel image memory: 1504K
[    0.772728] Write protecting the kernel read-only data: 20480k
[    0.773182] Freeing unused kernel image memory: 1988K
[    0.773332] Freeing unused kernel image memory: 1260K
[    0.773333] Run /init as init process
[    0.961692] scsi 0:0:0:0: Direct-Access     Msft     Virtual Disk     1.0  PQ: 0 ANSI: 5
[    0.962023] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    0.962665] sd 0:0:0:0: [sda] 536870912 512-byte logical blocks: (275 GB/256 GiB)
[    0.962666] sd 0:0:0:0: [sda] 4096-byte physical blocks
[    0.962727] sd 0:0:0:0: [sda] Write Protect is off
[    0.962728] sd 0:0:0:0: [sda] Mode Sense: 0f 00 00 00
[    0.962920] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    0.963562] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    0.966402] sd 0:0:0:0: [sda] Attached SCSI disk
[    0.976530] EXT4-fs (sda): mounted filesystem with ordered data mode. Opts: discard,errors=remount-ro,data=ordered
[    0.992723] scsi 0:0:0:1: Direct-Access     Msft     Virtual Disk     1.0  PQ: 0 ANSI: 5
[    0.992999] sd 0:0:0:1: Attached scsi generic sg1 type 0
[    0.993622] sd 0:0:0:1: [sdb] 536870912 512-byte logical blocks: (275 GB/256 GiB)
[    0.993623] sd 0:0:0:1: [sdb] 4096-byte physical blocks
[    0.993704] sd 0:0:0:1: [sdb] Write Protect is off
[    0.993705] sd 0:0:0:1: [sdb] Mode Sense: 0f 00 00 00
[    0.993869] sd 0:0:0:1: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    0.996699] sd 0:0:0:1: [sdb] Attached SCSI disk
[    1.024119] Adding 2097152k swap on /swap/file.  Priority:-2 extents:1 across:2097152k
[    1.105907] hv_pci a72fc80c-88ca-42a1-8819-1a47164887c5: PCI VMBus probing: Using version 0x10002
[    1.106933] hv_pci a72fc80c-88ca-42a1-8819-1a47164887c5: PCI host bridge to bus 8819:00
[    1.106934] pci_bus 8819:00: root bus resource [mem 0xc00000000-0xc00002fff window]
[    1.107544] pci 8819:00:00.0: [1af4:1049] type 00 class 0x010000
[    1.109157] pci 8819:00:00.0: reg 0x10: [mem 0xc00000000-0xc00000fff 64bit]
[    1.109866] pci 8819:00:00.0: reg 0x18: [mem 0xc00001000-0xc00001fff 64bit]
[    1.110745] pci 8819:00:00.0: reg 0x20: [mem 0xc00002000-0xc00002fff 64bit]
[    1.115209] pci 8819:00:00.0: BAR 0: assigned [mem 0xc00000000-0xc00000fff 64bit]
[    1.115726] pci 8819:00:00.0: BAR 2: assigned [mem 0xc00001000-0xc00001fff 64bit]
[    1.116248] pci 8819:00:00.0: BAR 4: assigned [mem 0xc00002000-0xc00002fff 64bit]
[    1.692709] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[    1.699948] EXT4-fs (sdb): recovery complete
[    1.700993] EXT4-fs (sdb): mounted filesystem with ordered data mode. Opts: discard,errors=remount-ro,data=ordered
[    1.726539] FS-Cache: Duplicate cookie detected
[    1.726540] FS-Cache: O-cookie c=00000000bbcdc786 [p=00000000c00584db fl=222 nc=0 na=1]
[    1.726541] FS-Cache: O-cookie d=00000000d63812f8 n=00000000afc9e097
[    1.726541] FS-Cache: O-key=[10] '34323934393337343531'
[    1.726544] FS-Cache: N-cookie c=0000000095cb1df6 [p=00000000c00584db fl=2 nc=0 na=1]
[    1.726544] FS-Cache: N-cookie d=00000000d63812f8 n=00000000d95cbdaa
[    1.726544] FS-Cache: N-key=[10] '34323934393337343531'
[    1.796994] hv_pci 7cca7ab0-7c60-4c3c-b299-bdf609f50c3d: PCI VMBus probing: Using version 0x10002
[    1.797849] hv_pci 7cca7ab0-7c60-4c3c-b299-bdf609f50c3d: PCI host bridge to bus b299:00
[    1.797850] pci_bus b299:00: root bus resource [mem 0xc00004000-0xc00006fff window]
[    1.798223] 9pnet_virtio: no channels available for device drvfs
[    1.798227] init: (1) WARNING: mount: waiting for virtio device...
[    1.798440] pci b299:00:00.0: [1af4:1049] type 00 class 0x010000
[    1.799993] pci b299:00:00.0: reg 0x10: [mem 0xc00004000-0xc00004fff 64bit]
[    1.800679] pci b299:00:00.0: reg 0x18: [mem 0xc00005000-0xc00005fff 64bit]
[    1.801356] pci b299:00:00.0: reg 0x20: [mem 0xc00006000-0xc00006fff 64bit]
[    1.805602] pci b299:00:00.0: BAR 0: assigned [mem 0xc00004000-0xc00004fff 64bit]
[    1.806089] pci b299:00:00.0: BAR 2: assigned [mem 0xc00005000-0xc00005fff 64bit]
[    1.806567] pci b299:00:00.0: BAR 4: assigned [mem 0xc00006000-0xc00006fff 64bit]
[    1.902363] hv_pci 71017744-9917-4fb5-8640-f7c8801e6f16: PCI VMBus probing: Using version 0x10002
[    1.903437] hv_pci 71017744-9917-4fb5-8640-f7c8801e6f16: PCI host bridge to bus 8640:00
[    1.903438] pci_bus 8640:00: root bus resource [mem 0xc00008000-0xc0000afff window]
[    1.903738] 9pnet_virtio: no channels available for device drvfs
[    1.903743] init: (1) WARNING: mount: waiting for virtio device...
[    1.904061] pci 8640:00:00.0: [1af4:1049] type 00 class 0x010000
[    1.905879] pci 8640:00:00.0: reg 0x10: [mem 0xc00008000-0xc00008fff 64bit]
[    1.906596] pci 8640:00:00.0: reg 0x18: [mem 0xc00009000-0xc00009fff 64bit]
[    1.907317] pci 8640:00:00.0: reg 0x20: [mem 0xc0000a000-0xc0000afff 64bit]
[    1.911803] pci 8640:00:00.0: BAR 0: assigned [mem 0xc00008000-0xc00008fff 64bit]
[    1.912330] pci 8640:00:00.0: BAR 2: assigned [mem 0xc00009000-0xc00009fff 64bit]
[    1.912861] pci 8640:00:00.0: BAR 4: assigned [mem 0xc0000a000-0xc0000afff 64bit]
[    2.008856] hv_pci 25bb6ac2-36f0-428a-832e-603cfdd390fa: PCI VMBus probing: Using version 0x10002
[    2.010436] hv_pci 25bb6ac2-36f0-428a-832e-603cfdd390fa: PCI host bridge to bus 832e:00
[    2.010439] pci_bus 832e:00: root bus resource [mem 0xc0000c000-0xc0000efff window]
[    2.011587] pci 832e:00:00.0: [1af4:1049] type 00 class 0x010000
[    2.014702] pci 832e:00:00.0: reg 0x10: [mem 0xc0000c000-0xc0000cfff 64bit]
[    2.016155] pci 832e:00:00.0: reg 0x18: [mem 0xc0000d000-0xc0000dfff 64bit]
[    2.017539] pci 832e:00:00.0: reg 0x20: [mem 0xc0000e000-0xc0000efff 64bit]
[    2.021884] pci 832e:00:00.0: BAR 0: assigned [mem 0xc0000c000-0xc0000cfff 64bit]
[    2.022385] pci 832e:00:00.0: BAR 2: assigned [mem 0xc0000d000-0xc0000dfff 64bit]
[    2.022901] pci 832e:00:00.0: BAR 4: assigned [mem 0xc0000e000-0xc0000efff 64bit]
[   49.585672] hv_balloon: Max. dynamic memory size: 8152 MB
@therealkenc
Copy link
Collaborator

I get the curious hv_balloon message around ~50s in too, although my startup (from --shutdown) is only a couple of seconds. That line appears in dmesg long after I get the shell prompt.

image

Did the long delay begin to happen for you after the 20175 Update, or was it always a thing.

@licanhua
Copy link
Collaborator

I have Ubuntu 20.04 LTS. although hv_balloon takes ~50s on my machine to get hv_balloon: Max. dynamic memory size, but Ubuntu console is immediately ready to use. hv_balloon doesn't block the standup.

@patricknazar
Copy link
Author

patricknazar commented Jul 30, 2020

Perhaps the hv_balloon isn't related to my problem, then? I don't get a console prompt and sometimes it gives me a terminated error. After waiting a while, starting wsl again won't hang and will go straight to prompt.

I believe I had this problem before the update to 20175, although I would get the HYPERVISOR_ERROR GSOD #5288 and my comment before I could do anything about it. This update seems to have stopped that from happening but I still get a big delay on "first boot". Sadly, I can only get the condition to happen like once a day.

Edit: I'll add that I'd only get the GSOD when this problem happened. No hanging (i.e. what would happen on second boot) meant no GSOD

@therealkenc
Copy link
Collaborator

Perhaps the hv_balloon isn't related to my problem, then?

Probably not.

@patricknazar
Copy link
Author

Today it's just not wanting to start at all.

The operation timed out because a response was not received from the virtual machine or container.
Press any key to continue...

or just a never ending black screen.

trying to run dmesg

PS C:\Users\Patrick> wsl "dmesg"
The operation timed out because a response was not received from the virtual machine or container.

I did get it to run once: https://pastebin.com/KGFVDrMJ

@therealkenc
Copy link
Collaborator

The operation timed out because a response was not received from the virtual machine or container.

If you can get wsl.exe to fail, then please submit networking logs via feedback hub. I'm not sure they are much good for identifying problems at boot, but if you can catch wsl.exe failing they might show something. Also might want to disable the Windows Docker WSL backend per #5648 just get the extraneous variable out of the way. You want wsl.exe firing up the VM not Docker.

@patricknazar
Copy link
Author

Thanks yeah I'll try this again tomorrow before/during/after the bug happens so I can make that recording in feedback hub. Because now I've rebooted and all is working normally, as per usual.

@patricknazar
Copy link
Author

This comment may have helped me here, but the pc was on for quite a while before I found/tried it so it might have just done its "work after a while" magic trick. Tomorrow I will try this on boot and see how it goes. In short: wsl --set-default-version 2. I did this on install initially and I shouldn't have to keep doing it but if it helps could be a clue as to what is going on.

@patricknazar
Copy link
Author

I tried it today and it didn't work at first, tried wsl --set-default-version 2 then wsl, same problem. But then I tried wsl --shutdown then wsl and it worked. Tomorrow I'll try just wsl --shutdown then wsl and see how we go.

@patricknazar
Copy link
Author

Today it just doesn't start, no matter if I put any of those commands.

@patricknazar
Copy link
Author

No problems from me in regards to this anymore, closing.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants