The virtual machine takes 4 minutes to start up.

[Meteor Cai]

I used the Ubuntu 22.04 image to create the VMI. It took over 4 minutes from the creation process until the virtual machine could be connected via IP.  

After logging into the virtual machine via SSH, and then using the "system-analyze" command to view the results, it was found that the system startup only took 24 seconds. The first timestamp in the dmesg log is: 09:22:30, and the last one is: 09:22:53. It seems to be consistent.

The log related to virt-handler is as follows: 

2025-11-28T09:18:25.589552135+08:00 stderr F {"component":"virt-handler","level":"info","msg":"Generic Allocate: resourceName: vhost-net","pos":"generic_device.go:240","timestamp":"2025-11-28T01:18:25.589467Z"}
2025-11-28T09:18:25.589565936+08:00 stderr F {"component":"virt-handler","level":"info","msg":"Generic Allocate: request: [&ContainerAllocateRequest{DevicesIDs:[vhost-net771],}]","pos":"generic_device.go:241","timestamp":"2025-11-28T01:18:25.589500Z"}
2025-11-28T09:18:25.590035433+08:00 stderr F {"component":"virt-handler","level":"info","msg":"Generic Allocate: resourceName: kvm","pos":"generic_device.go:240","timestamp":"2025-11-28T01:18:25.589991Z"}
2025-11-28T09:18:25.590041828+08:00 stderr F {"component":"virt-handler","level":"info","msg":"Generic Allocate: request: [&ContainerAllocateRequest{DevicesIDs:[kvm454],}]","pos":"generic_device.go:241","timestamp":"2025-11-28T01:18:25.590008Z"}
2025-11-28T09:18:25.590693343+08:00 stderr F {"component":"virt-handler","level":"info","msg":"Generic Allocate: resourceName: tun","pos":"generic_device.go:240","timestamp":"2025-11-28T01:18:25.590660Z"}
2025-11-28T09:18:25.590707347+08:00 stderr F {"component":"virt-handler","level":"info","msg":"Generic Allocate: request: [&ContainerAllocateRequest{DevicesIDs:[tun936],}]","pos":"generic_device.go:241","timestamp":"2025-11-28T01:18:25.590679Z"}
2025-11-28T09:18:31.711162849+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Scheduled | Domain does not exist","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:1901","timestamp":"2025-11-28T01:18:31.710851Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:31.714720898+08:00 stderr F {"component":"virt-handler","level":"info","msg":"initialized a new cgroup v1 manager successfully. controllerPaths: map[:/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope blkio:/blkio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpu:/cpu/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuacct:/cpuacct/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuset:/cpuset/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope devices:/devices/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope freezer:/freezer/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope hugetlb:/hugetlb/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope memory:/memory/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope name=systemd:/name=systemd/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_cls:/net_cls/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_prio:/net_prio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope perf_event:/perf_event/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope pids:/pids/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope rdma:/rdma/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope], procCgroupBasePath: /proc/774138/cgroup","pos":"cgroup.go:135","timestamp":"2025-11-28T01:18:31.714536Z"}
2025-11-28T09:18:31.71812217+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"Bind mounting container disk at root: /proc/1/root, relative: /run/containerd/io.containerd.runtime.v2.task/k8s.io/6e9e8036abc4a1a3bf537b18949b70f8a1203d5bd2574e21fbd92599d52c857e/rootfs/disk/ubuntu-22.04-compressed-0711.qcow2 to root: /var/lib/kubelet/pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/container-disks, relative: /disk_0.img","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"mount.go:289","timestamp":"2025-11-28T01:18:31.717972Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:31.795459859+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"mounting kernel artifacts","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"mount.go:407","timestamp":"2025-11-28T01:18:31.795093Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:31.79552187+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"kernel boot not defined - nothing to mount","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"mount.go:410","timestamp":"2025-11-28T01:18:31.795212Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:31.800237404+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"Current pod network: {\"interfaces\":[{\"name\":\"lo\",\"index\":1,\"type\":\"device\",\"state\":\"unknown\",\"mtu\":65536,\"ethtool\":{\"feature\":{\"tx-checksum\":true}},\"IPv4\":{\"enabled\":true,\"address\":[{\"IP\":\"127.0.0.1\",\"prefix-length\":8}]},\"IPv6\":{\"enabled\":true,\"address\":[{\"IP\":\"::1\",\"prefix-length\":128}]},\"linux-stack\":{\"ip4-route-local-net\":false,\"port-learning\":false},\"Metadata\":null},{\"name\":\"tunl0\",\"index\":2,\"type\":\"ipip\",\"state\":\"down\",\"mtu\":1480,\"ethtool\":{\"feature\":{\"tx-checksum\":true}},\"IPv4\":{\"enabled\":false},\"IPv6\":{\"enabled\":false},\"linux-stack\":{\"ip4-route-local-net\":false,\"port-learning\":false},\"Metadata\":null},{\"name\":\"eth0\",\"index\":4,\"type\":\"veth\",\"state\":\"up\",\"mac-address\":\"2a:ab:d7:32:60:d9\",\"mtu\":1480,\"ethtool\":{\"feature\":{\"tx-checksum\":true}},\"IPv4\":{\"enabled\":true,\"address\":[{\"IP\":\"172.22.59.198\",\"prefix-length\":32}]},\"IPv6\":{\"enabled\":true,\"address\":[{\"IP\":\"fe80::28ab:d7ff:fe32:60d9\",\"prefix-length\":64}]},\"linux-stack\":{\"ip4-route-local-net\":false,\"port-learning\":false},\"Metadata\":null}],\"routes\":{\"running\":[{\"destination\":\"0.0.0.0/0\",\"next-hop-interface\":\"eth0\",\"next-hop-address\":\"169.254.1.1\",\"table-id\":254},{\"destination\":\"169.254.1.1/32\",\"next-hop-interface\":\"eth0\",\"table-id\":254},{\"destination\":\"fe80::/64\",\"next-hop-interface\":\"eth0\",\"table-id\":254}]},\"linux-stack\":{\"ipv4\":{\"arp-ignore\":0,\"forwarding\":false,\"ping-group-range\":[1,0],\"unprivileged-port-start\":1024},\"ipv6\":{\"forwarding\":false}}}","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"netpod.go:185","timestamp":"2025-11-28T01:18:31.799935Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:31.801683521+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"Desired pod network: {\"interfaces\":[{\"name\":\"k6t-eth0\",\"type\":\"bridge\",\"state\":\"up\",\"ethtool\":{\"feature\":{\"tx-checksum\":false}},\"IPv4\":{\"enabled\":true,\"address\":[{\"IP\":\"169.254.75.10\",\"prefix-length\":32}]},\"IPv6\":{},\"linux-stack\":{},\"Metadata\":{\"Pid\":0,\"NetworkName\":\"default\"}},{\"name\":\"eth0-nic\",\"index\":4,\"state\":\"up\",\"copy-mac-from\":\"k6t-eth0\",\"controller\":\"k6t-eth0\",\"ethtool\":{\"feature\":{}},\"IPv4\":{\"enabled\":false},\"IPv6\":{\"enabled\":false},\"linux-stack\":{\"port-learning\":false},\"Metadata\":{\"Pid\":0,\"NetworkName\":\"default\"}},{\"name\":\"tap0\",\"type\":\"tap\",\"state\":\"up\",\"mtu\":1480,\"controller\":\"k6t-eth0\",\"ethtool\":{\"feature\":{}},\"tap\":{\"UID\":107,\"GID\":107},\"IPv4\":{},\"IPv6\":{},\"linux-stack\":{},\"Metadata\":{\"Pid\":774138,\"NetworkName\":\"default\"}},{\"name\":\"eth0\",\"type\":\"dummy\",\"mac-address\":\"2a:ab:d7:32:60:d9\",\"mtu\":1480,\"ethtool\":{\"feature\":{}},\"IPv4\":{\"enabled\":true,\"address\":[{\"IP\":\"172.22.59.198\",\"prefix-length\":32}]},\"IPv6\":{\"enabled\":true,\"address\":[{\"IP\":\"fe80::28ab:d7ff:fe32:60d9\",\"prefix-length\":64}]},\"linux-stack\":{},\"Metadata\":{\"Pid\":0,\"NetworkName\":\"default\"}}],\"linux-stack\":{\"ipv4\":{\"arp-ignore\":1},\"ipv6\":{}}}","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"netpod.go:242","timestamp":"2025-11-28T01:18:31.801442Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:31.841444473+08:00 stderr F {"component":"virt-handler","level":"info","msg":"[ContextExecutor]: Executing... Switching from original () to desired () context","pos":"context_executor.go:75","timestamp":"2025-11-28T01:18:31.841166Z"}
2025-11-28T09:18:31.856964988+08:00 stderr F {"component":"virt-handler","level":"info","msg":"[ContextExecutor]: Execution ended successfully","pos":"context_executor.go:90","timestamp":"2025-11-28T01:18:31.856722Z"}
2025-11-28T09:18:33.115536231+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"Accepted new notify pipe connection for vmi","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:398","timestamp":"2025-11-28T01:18:33.115445Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:33.116839001+08:00 stderr F {"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain is in state Shutoff reason Unknown","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:3362","timestamp":"2025-11-28T01:18:33.116773Z","uid":""}
2025-11-28T09:18:42.58306798+08:00 stderr F {"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain is in state Paused reason StartingUp","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:3392","timestamp":"2025-11-28T01:18:42.582935Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:42.825164066+08:00 stderr F {"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain is in state Running reason Unknown","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:3392","timestamp":"2025-11-28T01:18:42.825111Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:42.826718019+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"migration is block migration because of containerdisk volume","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:2545","timestamp":"2025-11-28T01:18:42.826669Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:42.82672705+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"migration is block migration because of cloudinitdisk volume","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:2545","timestamp":"2025-11-28T01:18:42.826700Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:42.826728263+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"migration is block migration because of kubeconfig volume","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:2545","timestamp":"2025-11-28T01:18:42.826712Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:43.785110344+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Scheduled | Domain status: Running, reason: Unknown","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:1899","timestamp":"2025-11-28T01:18:43.785007Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:43.80899226+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running | Domain status: Running, reason: Unknown","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:1899","timestamp":"2025-11-28T01:18:43.808953Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:43.809123187+08:00 stderr F {"component":"virt-handler","level":"info","msg":"initialized a new cgroup v1 manager successfully. controllerPaths: map[:/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope blkio:/blkio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpu:/cpu/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuacct:/cpuacct/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuset:/cpuset/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope devices:/devices/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope freezer:/freezer/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope hugetlb:/hugetlb/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope memory:/memory/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope name=systemd:/name=systemd/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_cls:/net_cls/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_prio:/net_prio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope perf_event:/perf_event/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope pids:/pids/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope rdma:/rdma/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope], procCgroupBasePath: /proc/774138/cgroup","pos":"cgroup.go:135","timestamp":"2025-11-28T01:18:43.809100Z"}
2025-11-28T09:18:43.839658631+08:00 stderr F {"component":"virt-handler","kind":"","level":"error","msg":"Updating the VirtualMachineInstance status failed.","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:2059","reason":"Operation cannot be fulfilled on virtualmachineinstances.kubevirt.io \"kubevirt-1l600-test\": the object has been modified; please apply your changes to the latest version and try again","timestamp":"2025-11-28T01:18:43.839547Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:43.839670422+08:00 stderr F {"component":"virt-handler","level":"info","msg":"re-enqueuing VirtualMachineInstance cideploy/kubevirt-1l600-test","pos":"vm.go:1714","reason":"Operation cannot be fulfilled on virtualmachineinstances.kubevirt.io \"kubevirt-1l600-test\": the object has been modified; please apply your changes to the latest version and try again","timestamp":"2025-11-28T01:18:43.839570Z"}
2025-11-28T09:18:43.83967229+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running | Domain status: Running, reason: Unknown","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:1899","timestamp":"2025-11-28T01:18:43.839583Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:43.839768021+08:00 stderr F {"component":"virt-handler","level":"info","msg":"initialized a new cgroup v1 manager successfully. controllerPaths: map[:/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope blkio:/blkio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpu:/cpu/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuacct:/cpuacct/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuset:/cpuset/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope devices:/devices/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope freezer:/freezer/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope hugetlb:/hugetlb/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope memory:/memory/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope name=systemd:/name=systemd/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_cls:/net_cls/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_prio:/net_prio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope perf_event:/perf_event/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope pids:/pids/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope rdma:/rdma/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope], procCgroupBasePath: /proc/774138/cgroup","pos":"cgroup.go:135","timestamp":"2025-11-28T01:18:43.839711Z"}
2025-11-28T09:18:43.884322075+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running | Domain status: Running, reason: Unknown","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:1899","timestamp":"2025-11-28T01:18:43.884161Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:18:43.884441368+08:00 stderr F {"component":"virt-handler","level":"info","msg":"initialized a new cgroup v1 manager successfully. controllerPaths: map[:/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope blkio:/blkio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpu:/cpu/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuacct:/cpuacct/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuset:/cpuset/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope devices:/devices/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope freezer:/freezer/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope hugetlb:/hugetlb/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope memory:/memory/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope name=systemd:/name=systemd/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_cls:/net_cls/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_prio:/net_prio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope perf_event:/perf_event/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope pids:/pids/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope rdma:/rdma/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope], procCgroupBasePath: /proc/774138/cgroup","pos":"cgroup.go:135","timestamp":"2025-11-28T01:18:43.884380Z"}
2025-11-28T09:18:51.782970328+08:00 stderr F {"component":"virt-handler","level":"info","msg":"refreshed device plugins for permitted/forbidden host devices","pos":"device_controller.go:350","timestamp":"2025-11-28T01:18:51.782856Z"}
2025-11-28T09:18:51.782992174+08:00 stderr F {"component":"virt-handler","level":"info","msg":"enabled device-plugins for: []","pos":"device_controller.go:351","timestamp":"2025-11-28T01:18:51.782896Z"}
2025-11-28T09:18:51.782995501+08:00 stderr F {"component":"virt-handler","level":"info","msg":"disabled device-plugins for: []","pos":"device_controller.go:352","timestamp":"2025-11-28T01:18:51.782903Z"}
2025-11-28T09:19:24.607698455+08:00 stderr F {"component":"virt-handler","level":"error","msg":"failed to scrape metrics from //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock","pos":"scrapper.go:48","reason":"failed to update domain stats from socket //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock: unknown error encountered sending command GetDomainStats: rpc error: code = DeadlineExceeded desc = context deadline exceeded","timestamp":"2025-11-28T01:19:24.607543Z"}
2025-11-28T09:19:52.607567217+08:00 stderr F {"component":"virt-handler","level":"info","msg":"refreshed device plugins for permitted/forbidden host devices","pos":"device_controller.go:350","timestamp":"2025-11-28T01:19:52.607436Z"}
2025-11-28T09:19:52.607588988+08:00 stderr F {"component":"virt-handler","level":"info","msg":"enabled device-plugins for: []","pos":"device_controller.go:351","timestamp":"2025-11-28T01:19:52.607476Z"}
2025-11-28T09:19:52.607591793+08:00 stderr F {"component":"virt-handler","level":"info","msg":"disabled device-plugins for: []","pos":"device_controller.go:352","timestamp":"2025-11-28T01:19:52.607484Z"}
2025-11-28T09:20:14.163688943+08:00 stderr F {"component":"virt-handler","level":"error","msg":"failed to scrape metrics from //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock","pos":"scrapper.go:48","reason":"failed to update domain stats from socket //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock: unknown error encountered sending command GetDomainStats: rpc error: code = DeadlineExceeded desc = context deadline exceeded","timestamp":"2025-11-28T01:20:14.163519Z"}
2025-11-28T09:20:25.060088908+08:00 stderr F {"component":"virt-handler","level":"error","msg":"failed to scrape metrics from //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock","pos":"scrapper.go:48","reason":"failed to update domain stats from socket //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock: unknown error encountered sending command GetDomainStats: rpc error: code = DeadlineExceeded desc = context deadline exceeded","timestamp":"2025-11-28T01:20:25.059863Z"}
2025-11-28T09:20:44.391725229+08:00 stderr F {"component":"virt-handler","level":"error","msg":"failed to scrape metrics from //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock","pos":"scrapper.go:48","reason":"failed to update domain stats from socket //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock: unknown error encountered sending command GetDomainStats: rpc error: code = DeadlineExceeded desc = context deadline exceeded","timestamp":"2025-11-28T01:20:44.391507Z"}
2025-11-28T09:21:07.054223327+08:00 stderr F {"component":"virt-handler","level":"info","msg":"refreshed device plugins for permitted/forbidden host devices","pos":"device_controller.go:350","timestamp":"2025-11-28T01:21:07.052037Z"}
2025-11-28T09:21:07.054271095+08:00 stderr F {"component":"virt-handler","level":"info","msg":"enabled device-plugins for: []","pos":"device_controller.go:351","timestamp":"2025-11-28T01:21:07.052077Z"}
2025-11-28T09:21:07.05427637+08:00 stderr F {"component":"virt-handler","level":"info","msg":"disabled device-plugins for: []","pos":"device_controller.go:352","timestamp":"2025-11-28T01:21:07.052087Z"}
2025-11-28T09:21:13.899206395+08:00 stderr F {"component":"virt-handler","level":"error","msg":"failed to scrape metrics from //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock","pos":"scrapper.go:48","reason":"failed to update domain stats from socket //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock: unknown error encountered sending command GetDomainStats: rpc error: code = DeadlineExceeded desc = context deadline exceeded","timestamp":"2025-11-28T01:21:13.899030Z"}
2025-11-28T09:21:44.030209856+08:00 stderr F {"component":"virt-handler","level":"error","msg":"failed to scrape metrics from //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock","pos":"scrapper.go:48","reason":"failed to update domain stats from socket //pods/f8bdfaf2-ddf3-455d-9137-8ca4d718066d/volumes/kubernetes.io~empty-dir/sockets/launcher-sock: unknown error encountered sending command GetDomainStats: rpc error: code = DeadlineExceeded desc = context deadline exceeded","timestamp":"2025-11-28T01:21:44.026665Z"}
2025-11-28T09:22:14.859781152+08:00 stderr F {"component":"virt-handler","level":"info","msg":"refreshed device plugins for permitted/forbidden host devices","pos":"device_controller.go:350","timestamp":"2025-11-28T01:22:14.859684Z"}
2025-11-28T09:22:14.859793066+08:00 stderr F {"component":"virt-handler","level":"info","msg":"enabled device-plugins for: []","pos":"device_controller.go:351","timestamp":"2025-11-28T01:22:14.859710Z"}
2025-11-28T09:22:14.859794394+08:00 stderr F {"component":"virt-handler","level":"info","msg":"disabled device-plugins for: []","pos":"device_controller.go:352","timestamp":"2025-11-28T01:22:14.859719Z"}
2025-11-28T09:22:58.335157643+08:00 stderr F {"component":"virt-handler","level":"info","msg":"resyncing virt-launcher domains","pos":"domain-watcher.go:137","timestamp":"2025-11-28T01:22:58.334774Z"}
2025-11-28T09:22:58.344709361+08:00 stderr F {"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running | Domain status: Running, reason: Unknown","name":"kubevirt-1l600-test","namespace":"cideploy","pos":"vm.go:1899","timestamp":"2025-11-28T01:22:58.344477Z","uid":"a4368497-7943-444c-927b-176415bc8861"}
2025-11-28T09:22:58.345529092+08:00 stderr F {"component":"virt-handler","level":"info","msg":"initialized a new cgroup v1 manager successfully. controllerPaths: map[:/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope blkio:/blkio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpu:/cpu/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuacct:/cpuacct/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope cpuset:/cpuset/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope devices:/devices/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope freezer:/freezer/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope hugetlb:/hugetlb/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope memory:/memory/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope name=systemd:/name=systemd/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_cls:/net_cls/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope net_prio:/net_prio/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope perf_event:/perf_event/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope pids:/pids/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope rdma:/rdma/kubepods.slice/kubepods-podf8bdfaf2_ddf3_455d_9137_8ca4d718066d.slice/cri-containerd-a65252916ba6f418efebb9ff28d76f3b73a6a920ff6c72431a34fbfc1f6fbcf5.scope], procCgroupBasePath: /proc/774138/cgroup","pos":"cgroup.go:135","timestamp":"2025-11-28T01:22:58.345267Z"}
2025-11-28T09:23:44.857601992+08:00 stderr F {"component":"virt-handler","level":"info","msg":"refreshed device plugins for permitted/forbidden host devices","pos":"device_controller.go:350","timestamp":"2025-11-28T01:23:44.857303Z"}
2025-11-28T09:23:44.857650682+08:00 stderr F {"component":"virt-handler","level":"info","msg":"enabled device-plugins for: []","pos":"device_controller.go:351","timestamp":"2025-11-28T01:23:44.857392Z"}
2025-11-28T09:23:44.857658643+08:00 stderr F {"component":"virt-handler","level":"info","msg":"disabled device-plugins for: []","pos":"device_controller.go:352","timestamp":"2025-11-28T01:23:44.857430Z"}

Could anyone help me figure out where the problem lies?

[Or Mergi]

Is there a chance most of the time went on pulling the OS image?

Could you share the VM/VMI/pod events?

--
You received this message because you are subscribed to the Google Groups "kubevirt-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to kubevirt-dev...@googlegroups.com.
To view this discussion visit https://groups.google.com/d/msgid/kubevirt-dev/35e151fb-4804-4e0f-a83f-49bc77776d5bn%40googlegroups.com.

--

Or Mergi

[Meteor Cai]

From the status perspective, after 40 seconds, it would be in the "Running" state. Therefore, the action of pulling the image did not take up much time. Running "kubectl get event" did not reveal any events related to this VMI.