* [Qemu-devel] [Bug 1826393] [NEW] QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-04-25 11:37 Waldemar Kozaczuk
2019-04-29 15:47 ` Stefan Hajnoczi
` (2 more replies)
0 siblings, 3 replies; 13+ messages in thread
From: Waldemar Kozaczuk @ 2019-04-25 11:37 UTC (permalink / raw)
To: qemu-devel
Public bug reported:
Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and that
way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have noticed
that everytime I start QEMU to run OSv, QEMU seems to hand noticably
longer (~1 second) before showing SeaBIOS output. I have tried all kind
of combinations to get rid of that pause and nothing helped.
Here is my start command:
time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
-enable-kvm \
-cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
It looks like qemu process starts, waits almost a second for something
and then print SeaBIOS splashscreen and continues boot:
--> waits here
SeaBIOS (version 1.12.0-1)
Booting from Hard Disk..OSv v0.53.0-6-gc8395118
disk read (real mode): 27.25ms, (+27.25ms)
uncompress lzloader.elf: 46.22ms, (+18.97ms)
TLS initialization: 46.79ms, (+0.57ms)
.init functions: 47.82ms, (+1.03ms)
SMP launched: 48.08ms, (+0.26ms)
VFS initialized: 49.25ms, (+1.17ms)
Network initialized: 49.48ms, (+0.24ms)
pvpanic done: 49.57ms, (+0.08ms)
pci enumerated: 52.42ms, (+2.85ms)
drivers probe: 52.42ms, (+0.00ms)
drivers loaded: 55.33ms, (+2.90ms)
ROFS mounted: 56.37ms, (+1.04ms)
Total time: 56.37ms, (+0.00ms)
Found optarg
dev etc hello libenviron.so libvdso.so proc tmp tools usr
real 0m0.935s
user 0m0.426s
sys 0m0.490s
With version 2.12.0 I used to see real below 200ms. So it seems qemu
slowed down 5 times.
I ran strace -tt against it and I have noticed a pause here:
...
07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848747 getpid() = 5162
07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848837 getpid() = 5162
07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
})
07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
v_nsec=190532609})
--> waits for almost 800ms
07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
LIN}], left {tv_sec=0, tv_nsec=189909632})
07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
...
when I run same command using qemu 3.0.5 that I still happen to have on
the same machine that I built directly from source I see total boot time
at around 200ms. It seems like a regression.
** Affects: qemu
Importance: Undecided
Status: New
--
You received this bug notification because you are a member of qemu-
devel-ml, which is subscribed to QEMU.
https://bugs.launchpad.net/bugs/1826393
Title:
QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
Status in QEMU:
New
Bug description:
Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
noticed that everytime I start QEMU to run OSv, QEMU seems to hand
noticably longer (~1 second) before showing SeaBIOS output. I have
tried all kind of combinations to get rid of that pause and nothing
helped.
Here is my start command:
time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
-enable-kvm \
-cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
It looks like qemu process starts, waits almost a second for something
and then print SeaBIOS splashscreen and continues boot:
--> waits here
SeaBIOS (version 1.12.0-1)
Booting from Hard Disk..OSv v0.53.0-6-gc8395118
disk read (real mode): 27.25ms, (+27.25ms)
uncompress lzloader.elf: 46.22ms, (+18.97ms)
TLS initialization: 46.79ms, (+0.57ms)
.init functions: 47.82ms, (+1.03ms)
SMP launched: 48.08ms, (+0.26ms)
VFS initialized: 49.25ms, (+1.17ms)
Network initialized: 49.48ms, (+0.24ms)
pvpanic done: 49.57ms, (+0.08ms)
pci enumerated: 52.42ms, (+2.85ms)
drivers probe: 52.42ms, (+0.00ms)
drivers loaded: 55.33ms, (+2.90ms)
ROFS mounted: 56.37ms, (+1.04ms)
Total time: 56.37ms, (+0.00ms)
Found optarg
dev etc hello libenviron.so libvdso.so proc tmp tools usr
real 0m0.935s
user 0m0.426s
sys 0m0.490s
With version 2.12.0 I used to see real below 200ms. So it seems qemu
slowed down 5 times.
I ran strace -tt against it and I have noticed a pause here:
...
07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848747 getpid() = 5162
07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848837 getpid() = 5162
07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
})
07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
v_nsec=190532609})
--> waits for almost 800ms
07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
LIN}], left {tv_sec=0, tv_nsec=189909632})
07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
...
when I run same command using qemu 3.0.5 that I still happen to have
on the same machine that I built directly from source I see total boot
time at around 200ms. It seems like a regression.
To manage notifications about this bug go to:
https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] [NEW] QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-04-29 15:47 ` Stefan Hajnoczi
0 siblings, 0 replies; 13+ messages in thread
From: Stefan Hajnoczi @ 2019-04-29 15:47 UTC (permalink / raw)
To: Bug 1826393; +Cc: qemu-devel, kraxel, sgarzare
[-- Attachment #1: Type: text/plain, Size: 9714 bytes --]
On Thu, Apr 25, 2019 at 11:37:02AM -0000, Waldemar Kozaczuk wrote:
> Public bug reported:
>
> Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and that
> way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have noticed
> that everytime I start QEMU to run OSv, QEMU seems to hand noticably
> longer (~1 second) before showing SeaBIOS output. I have tried all kind
> of combinations to get rid of that pause and nothing helped.
>
> Here is my start command:
> time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> -enable-kvm \
> -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
>
> It looks like qemu process starts, waits almost a second for something
> and then print SeaBIOS splashscreen and continues boot:
>
> --> waits here
> SeaBIOS (version 1.12.0-1)
> Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> disk read (real mode): 27.25ms, (+27.25ms)
> uncompress lzloader.elf: 46.22ms, (+18.97ms)
> TLS initialization: 46.79ms, (+0.57ms)
> .init functions: 47.82ms, (+1.03ms)
> SMP launched: 48.08ms, (+0.26ms)
> VFS initialized: 49.25ms, (+1.17ms)
> Network initialized: 49.48ms, (+0.24ms)
> pvpanic done: 49.57ms, (+0.08ms)
> pci enumerated: 52.42ms, (+2.85ms)
> drivers probe: 52.42ms, (+0.00ms)
> drivers loaded: 55.33ms, (+2.90ms)
> ROFS mounted: 56.37ms, (+1.04ms)
> Total time: 56.37ms, (+0.00ms)
> Found optarg
> dev etc hello libenviron.so libvdso.so proc tmp tools usr
>
> real 0m0.935s
> user 0m0.426s
> sys 0m0.490s
>
> With version 2.12.0 I used to see real below 200ms. So it seems qemu
> slowed down 5 times.
>
> I ran strace -tt against it and I have noticed a pause here:
> ...
> 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848747 getpid() = 5162
> 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848837 getpid() = 5162
> 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> })
> 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> v_nsec=190532609})
>
> --> waits for almost 800ms
>
> 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> LIN}], left {tv_sec=0, tv_nsec=189909632})
> 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
>
> ...
>
> when I run same command using qemu 3.0.5 that I still happen to have on
> the same machine that I built directly from source I see total boot time
> at around 200ms. It seems like a regression.
Please try building QEMU 4.0.0 from source:
https://download.qemu.org/qemu-4.0.0.tar.xz
> ** Affects: qemu
> Importance: Undecided
> Status: New
>
> --
> You received this bug notification because you are a member of qemu-
> devel-ml, which is subscribed to QEMU.
> https://bugs.launchpad.net/bugs/1826393
>
> Title:
> QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
>
> Status in QEMU:
> New
>
> Bug description:
> Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
> that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
> noticed that everytime I start QEMU to run OSv, QEMU seems to hand
> noticably longer (~1 second) before showing SeaBIOS output. I have
> tried all kind of combinations to get rid of that pause and nothing
> helped.
>
> Here is my start command:
> time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> -enable-kvm \
> -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
>
> It looks like qemu process starts, waits almost a second for something
> and then print SeaBIOS splashscreen and continues boot:
>
> --> waits here
> SeaBIOS (version 1.12.0-1)
> Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> disk read (real mode): 27.25ms, (+27.25ms)
> uncompress lzloader.elf: 46.22ms, (+18.97ms)
> TLS initialization: 46.79ms, (+0.57ms)
> .init functions: 47.82ms, (+1.03ms)
> SMP launched: 48.08ms, (+0.26ms)
> VFS initialized: 49.25ms, (+1.17ms)
> Network initialized: 49.48ms, (+0.24ms)
> pvpanic done: 49.57ms, (+0.08ms)
> pci enumerated: 52.42ms, (+2.85ms)
> drivers probe: 52.42ms, (+0.00ms)
> drivers loaded: 55.33ms, (+2.90ms)
> ROFS mounted: 56.37ms, (+1.04ms)
> Total time: 56.37ms, (+0.00ms)
> Found optarg
> dev etc hello libenviron.so libvdso.so proc tmp tools usr
>
> real 0m0.935s
> user 0m0.426s
> sys 0m0.490s
>
> With version 2.12.0 I used to see real below 200ms. So it seems qemu
> slowed down 5 times.
>
> I ran strace -tt against it and I have noticed a pause here:
> ...
> 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848747 getpid() = 5162
> 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848837 getpid() = 5162
> 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> })
> 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> v_nsec=190532609})
>
> --> waits for almost 800ms
>
> 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> LIN}], left {tv_sec=0, tv_nsec=189909632})
> 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
>
> ...
>
> when I run same command using qemu 3.0.5 that I still happen to have
> on the same machine that I built directly from source I see total boot
> time at around 200ms. It seems like a regression.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
>
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 455 bytes --]
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] [NEW] QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-04-29 15:47 ` Stefan Hajnoczi
0 siblings, 0 replies; 13+ messages in thread
From: Stefan Hajnoczi @ 2019-04-29 15:47 UTC (permalink / raw)
To: Bug 1826393; +Cc: sgarzare, qemu-devel, kraxel
[-- Attachment #1: Type: text/plain, Size: 9714 bytes --]
On Thu, Apr 25, 2019 at 11:37:02AM -0000, Waldemar Kozaczuk wrote:
> Public bug reported:
>
> Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and that
> way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have noticed
> that everytime I start QEMU to run OSv, QEMU seems to hand noticably
> longer (~1 second) before showing SeaBIOS output. I have tried all kind
> of combinations to get rid of that pause and nothing helped.
>
> Here is my start command:
> time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> -enable-kvm \
> -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
>
> It looks like qemu process starts, waits almost a second for something
> and then print SeaBIOS splashscreen and continues boot:
>
> --> waits here
> SeaBIOS (version 1.12.0-1)
> Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> disk read (real mode): 27.25ms, (+27.25ms)
> uncompress lzloader.elf: 46.22ms, (+18.97ms)
> TLS initialization: 46.79ms, (+0.57ms)
> .init functions: 47.82ms, (+1.03ms)
> SMP launched: 48.08ms, (+0.26ms)
> VFS initialized: 49.25ms, (+1.17ms)
> Network initialized: 49.48ms, (+0.24ms)
> pvpanic done: 49.57ms, (+0.08ms)
> pci enumerated: 52.42ms, (+2.85ms)
> drivers probe: 52.42ms, (+0.00ms)
> drivers loaded: 55.33ms, (+2.90ms)
> ROFS mounted: 56.37ms, (+1.04ms)
> Total time: 56.37ms, (+0.00ms)
> Found optarg
> dev etc hello libenviron.so libvdso.so proc tmp tools usr
>
> real 0m0.935s
> user 0m0.426s
> sys 0m0.490s
>
> With version 2.12.0 I used to see real below 200ms. So it seems qemu
> slowed down 5 times.
>
> I ran strace -tt against it and I have noticed a pause here:
> ...
> 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848747 getpid() = 5162
> 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848837 getpid() = 5162
> 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> })
> 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> v_nsec=190532609})
>
> --> waits for almost 800ms
>
> 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> LIN}], left {tv_sec=0, tv_nsec=189909632})
> 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
>
> ...
>
> when I run same command using qemu 3.0.5 that I still happen to have on
> the same machine that I built directly from source I see total boot time
> at around 200ms. It seems like a regression.
Please try building QEMU 4.0.0 from source:
https://download.qemu.org/qemu-4.0.0.tar.xz
> ** Affects: qemu
> Importance: Undecided
> Status: New
>
> --
> You received this bug notification because you are a member of qemu-
> devel-ml, which is subscribed to QEMU.
> https://bugs.launchpad.net/bugs/1826393
>
> Title:
> QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
>
> Status in QEMU:
> New
>
> Bug description:
> Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
> that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
> noticed that everytime I start QEMU to run OSv, QEMU seems to hand
> noticably longer (~1 second) before showing SeaBIOS output. I have
> tried all kind of combinations to get rid of that pause and nothing
> helped.
>
> Here is my start command:
> time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> -enable-kvm \
> -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
>
> It looks like qemu process starts, waits almost a second for something
> and then print SeaBIOS splashscreen and continues boot:
>
> --> waits here
> SeaBIOS (version 1.12.0-1)
> Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> disk read (real mode): 27.25ms, (+27.25ms)
> uncompress lzloader.elf: 46.22ms, (+18.97ms)
> TLS initialization: 46.79ms, (+0.57ms)
> .init functions: 47.82ms, (+1.03ms)
> SMP launched: 48.08ms, (+0.26ms)
> VFS initialized: 49.25ms, (+1.17ms)
> Network initialized: 49.48ms, (+0.24ms)
> pvpanic done: 49.57ms, (+0.08ms)
> pci enumerated: 52.42ms, (+2.85ms)
> drivers probe: 52.42ms, (+0.00ms)
> drivers loaded: 55.33ms, (+2.90ms)
> ROFS mounted: 56.37ms, (+1.04ms)
> Total time: 56.37ms, (+0.00ms)
> Found optarg
> dev etc hello libenviron.so libvdso.so proc tmp tools usr
>
> real 0m0.935s
> user 0m0.426s
> sys 0m0.490s
>
> With version 2.12.0 I used to see real below 200ms. So it seems qemu
> slowed down 5 times.
>
> I ran strace -tt against it and I have noticed a pause here:
> ...
> 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848747 getpid() = 5162
> 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848837 getpid() = 5162
> 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> })
> 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> v_nsec=190532609})
>
> --> waits for almost 800ms
>
> 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> LIN}], left {tv_sec=0, tv_nsec=189909632})
> 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
>
> ...
>
> when I run same command using qemu 3.0.5 that I still happen to have
> on the same machine that I built directly from source I see total boot
> time at around 200ms. It seems like a regression.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
>
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 455 bytes --]
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] [NEW] QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-04-29 15:47 ` Stefan Hajnoczi
0 siblings, 0 replies; 13+ messages in thread
From: Stefan Hajnoczi @ 2019-04-29 15:47 UTC (permalink / raw)
To: qemu-devel
On Thu, Apr 25, 2019 at 11:37:02AM -0000, Waldemar Kozaczuk wrote:
> Public bug reported:
>
> Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and that
> way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have noticed
> that everytime I start QEMU to run OSv, QEMU seems to hand noticably
> longer (~1 second) before showing SeaBIOS output. I have tried all kind
> of combinations to get rid of that pause and nothing helped.
>
> Here is my start command:
> time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> -enable-kvm \
> -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
>
> It looks like qemu process starts, waits almost a second for something
> and then print SeaBIOS splashscreen and continues boot:
>
> --> waits here
> SeaBIOS (version 1.12.0-1)
> Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> disk read (real mode): 27.25ms, (+27.25ms)
> uncompress lzloader.elf: 46.22ms, (+18.97ms)
> TLS initialization: 46.79ms, (+0.57ms)
> .init functions: 47.82ms, (+1.03ms)
> SMP launched: 48.08ms, (+0.26ms)
> VFS initialized: 49.25ms, (+1.17ms)
> Network initialized: 49.48ms, (+0.24ms)
> pvpanic done: 49.57ms, (+0.08ms)
> pci enumerated: 52.42ms, (+2.85ms)
> drivers probe: 52.42ms, (+0.00ms)
> drivers loaded: 55.33ms, (+2.90ms)
> ROFS mounted: 56.37ms, (+1.04ms)
> Total time: 56.37ms, (+0.00ms)
> Found optarg
> dev etc hello libenviron.so libvdso.so proc tmp tools usr
>
> real 0m0.935s
> user 0m0.426s
> sys 0m0.490s
>
> With version 2.12.0 I used to see real below 200ms. So it seems qemu
> slowed down 5 times.
>
> I ran strace -tt against it and I have noticed a pause here:
> ...
> 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848747 getpid() = 5162
> 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848837 getpid() = 5162
> 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> })
> 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> v_nsec=190532609})
>
> --> waits for almost 800ms
>
> 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> LIN}], left {tv_sec=0, tv_nsec=189909632})
> 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
>
> ...
>
> when I run same command using qemu 3.0.5 that I still happen to have on
> the same machine that I built directly from source I see total boot time
> at around 200ms. It seems like a regression.
Please try building QEMU 4.0.0 from source:
https://download.qemu.org/qemu-4.0.0.tar.xz
> ** Affects: qemu
> Importance: Undecided
> Status: New
>
> --
> You received this bug notification because you are a member of qemu-
> devel-ml, which is subscribed to QEMU.
> https://bugs.launchpad.net/bugs/1826393
>
> Title:
> QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
>
> Status in QEMU:
> New
>
> Bug description:
> Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
> that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
> noticed that everytime I start QEMU to run OSv, QEMU seems to hand
> noticably longer (~1 second) before showing SeaBIOS output. I have
> tried all kind of combinations to get rid of that pause and nothing
> helped.
>
> Here is my start command:
> time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> -enable-kvm \
> -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
>
> It looks like qemu process starts, waits almost a second for something
> and then print SeaBIOS splashscreen and continues boot:
>
> --> waits here
> SeaBIOS (version 1.12.0-1)
> Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> disk read (real mode): 27.25ms, (+27.25ms)
> uncompress lzloader.elf: 46.22ms, (+18.97ms)
> TLS initialization: 46.79ms, (+0.57ms)
> .init functions: 47.82ms, (+1.03ms)
> SMP launched: 48.08ms, (+0.26ms)
> VFS initialized: 49.25ms, (+1.17ms)
> Network initialized: 49.48ms, (+0.24ms)
> pvpanic done: 49.57ms, (+0.08ms)
> pci enumerated: 52.42ms, (+2.85ms)
> drivers probe: 52.42ms, (+0.00ms)
> drivers loaded: 55.33ms, (+2.90ms)
> ROFS mounted: 56.37ms, (+1.04ms)
> Total time: 56.37ms, (+0.00ms)
> Found optarg
> dev etc hello libenviron.so libvdso.so proc tmp tools usr
>
> real 0m0.935s
> user 0m0.426s
> sys 0m0.490s
>
> With version 2.12.0 I used to see real below 200ms. So it seems qemu
> slowed down 5 times.
>
> I ran strace -tt against it and I have noticed a pause here:
> ...
> 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848747 getpid() = 5162
> 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848837 getpid() = 5162
> 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> })
> 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> v_nsec=190532609})
>
> --> waits for almost 800ms
>
> 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> LIN}], left {tv_sec=0, tv_nsec=189909632})
> 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
>
> ...
>
> when I run same command using qemu 3.0.5 that I still happen to have
> on the same machine that I built directly from source I see total boot
> time at around 200ms. It seems like a regression.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
>
--
You received this bug notification because you are a member of qemu-
devel-ml, which is subscribed to QEMU.
https://bugs.launchpad.net/bugs/1826393
Title:
QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
Status in QEMU:
New
Bug description:
Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
noticed that everytime I start QEMU to run OSv, QEMU seems to hand
noticably longer (~1 second) before showing SeaBIOS output. I have
tried all kind of combinations to get rid of that pause and nothing
helped.
Here is my start command:
time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
-enable-kvm \
-cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
It looks like qemu process starts, waits almost a second for something
and then print SeaBIOS splashscreen and continues boot:
--> waits here
SeaBIOS (version 1.12.0-1)
Booting from Hard Disk..OSv v0.53.0-6-gc8395118
disk read (real mode): 27.25ms, (+27.25ms)
uncompress lzloader.elf: 46.22ms, (+18.97ms)
TLS initialization: 46.79ms, (+0.57ms)
.init functions: 47.82ms, (+1.03ms)
SMP launched: 48.08ms, (+0.26ms)
VFS initialized: 49.25ms, (+1.17ms)
Network initialized: 49.48ms, (+0.24ms)
pvpanic done: 49.57ms, (+0.08ms)
pci enumerated: 52.42ms, (+2.85ms)
drivers probe: 52.42ms, (+0.00ms)
drivers loaded: 55.33ms, (+2.90ms)
ROFS mounted: 56.37ms, (+1.04ms)
Total time: 56.37ms, (+0.00ms)
Found optarg
dev etc hello libenviron.so libvdso.so proc tmp tools usr
real 0m0.935s
user 0m0.426s
sys 0m0.490s
With version 2.12.0 I used to see real below 200ms. So it seems qemu
slowed down 5 times.
I ran strace -tt against it and I have noticed a pause here:
...
07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848747 getpid() = 5162
07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848837 getpid() = 5162
07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
})
07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
v_nsec=190532609})
--> waits for almost 800ms
07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
LIN}], left {tv_sec=0, tv_nsec=189909632})
07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
...
when I run same command using qemu 3.0.5 that I still happen to have
on the same machine that I built directly from source I see total boot
time at around 200ms. It seems like a regression.
To manage notifications about this bug go to:
https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] [NEW] QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-04-29 16:25 ` Stefano Garzarella
0 siblings, 0 replies; 13+ messages in thread
From: Stefano Garzarella @ 2019-04-29 16:25 UTC (permalink / raw)
To: Bug 1826393; +Cc: Stefan Hajnoczi, qemu-devel, kraxel
On Mon, Apr 29, 2019 at 11:47:33AM -0400, Stefan Hajnoczi wrote:
> On Thu, Apr 25, 2019 at 11:37:02AM -0000, Waldemar Kozaczuk wrote:
>
> Please try building QEMU 4.0.0 from source:
>
> https://download.qemu.org/qemu-4.0.0.tar.xz
>
It seems that is related to an issue with some TPM timeouts found in
SeaBIOS 1.12.0:
https://www.mail-archive.com/qemu-devel@nongnu.org/msg575060.html
As Stefan suggested the new QEMU 4.0.0 should not have this issue since
it is shipped with SeaBIOS 1.12.1 (where the fix is applied).
If you want to use QEMU 3.1.0 with the new SeaBIOS, you can download it
and use the '-bios' parameter:
$ wget https://github.com/qemu/qemu/blob/v4.0.0/pc-bios/bios-256k.bin
$ qemu-system-x86_64 -bios /path/to/bios-256k.bin ...
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] [NEW] QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-04-29 16:25 ` Stefano Garzarella
0 siblings, 0 replies; 13+ messages in thread
From: Stefano Garzarella @ 2019-04-29 16:25 UTC (permalink / raw)
To: qemu-devel
On Mon, Apr 29, 2019 at 11:47:33AM -0400, Stefan Hajnoczi wrote:
> On Thu, Apr 25, 2019 at 11:37:02AM -0000, Waldemar Kozaczuk wrote:
>
> Please try building QEMU 4.0.0 from source:
>
> https://download.qemu.org/qemu-4.0.0.tar.xz
>
It seems that is related to an issue with some TPM timeouts found in
SeaBIOS 1.12.0:
https://www.mail-archive.com/qemu-devel@nongnu.org/msg575060.html
As Stefan suggested the new QEMU 4.0.0 should not have this issue since
it is shipped with SeaBIOS 1.12.1 (where the fix is applied).
If you want to use QEMU 3.1.0 with the new SeaBIOS, you can download it
and use the '-bios' parameter:
$ wget https://github.com/qemu/qemu/blob/v4.0.0/pc-bios/bios-256k.bin
$ qemu-system-x86_64 -bios /path/to/bios-256k.bin ...
--
You received this bug notification because you are a member of qemu-
devel-ml, which is subscribed to QEMU.
https://bugs.launchpad.net/bugs/1826393
Title:
QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
Status in QEMU:
New
Bug description:
Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
noticed that everytime I start QEMU to run OSv, QEMU seems to hand
noticably longer (~1 second) before showing SeaBIOS output. I have
tried all kind of combinations to get rid of that pause and nothing
helped.
Here is my start command:
time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
-enable-kvm \
-cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
It looks like qemu process starts, waits almost a second for something
and then print SeaBIOS splashscreen and continues boot:
--> waits here
SeaBIOS (version 1.12.0-1)
Booting from Hard Disk..OSv v0.53.0-6-gc8395118
disk read (real mode): 27.25ms, (+27.25ms)
uncompress lzloader.elf: 46.22ms, (+18.97ms)
TLS initialization: 46.79ms, (+0.57ms)
.init functions: 47.82ms, (+1.03ms)
SMP launched: 48.08ms, (+0.26ms)
VFS initialized: 49.25ms, (+1.17ms)
Network initialized: 49.48ms, (+0.24ms)
pvpanic done: 49.57ms, (+0.08ms)
pci enumerated: 52.42ms, (+2.85ms)
drivers probe: 52.42ms, (+0.00ms)
drivers loaded: 55.33ms, (+2.90ms)
ROFS mounted: 56.37ms, (+1.04ms)
Total time: 56.37ms, (+0.00ms)
Found optarg
dev etc hello libenviron.so libvdso.so proc tmp tools usr
real 0m0.935s
user 0m0.426s
sys 0m0.490s
With version 2.12.0 I used to see real below 200ms. So it seems qemu
slowed down 5 times.
I ran strace -tt against it and I have noticed a pause here:
...
07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848747 getpid() = 5162
07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848837 getpid() = 5162
07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
})
07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
v_nsec=190532609})
--> waits for almost 800ms
07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
LIN}], left {tv_sec=0, tv_nsec=189909632})
07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
...
when I run same command using qemu 3.0.5 that I still happen to have
on the same machine that I built directly from source I see total boot
time at around 200ms. It seems like a regression.
To manage notifications about this bug go to:
https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
^ permalink raw reply [flat|nested] 13+ messages in thread
* [Qemu-devel] [Bug 1826393] Re: QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
2019-04-25 11:37 [Qemu-devel] [Bug 1826393] [NEW] QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase Waldemar Kozaczuk
2019-04-29 15:47 ` Stefan Hajnoczi
@ 2019-05-01 4:13 ` Waldemar Kozaczuk
2019-05-02 7:57 ` Stefano Garzarella
2 siblings, 0 replies; 13+ messages in thread
From: Waldemar Kozaczuk @ 2019-05-01 4:13 UTC (permalink / raw)
To: qemu-devel
I tried with the bios https://github.com/qemu/qemu/blob/v4.0.0/pc-bios/bios-256k.bin and it failed like so:
```
qemu: could not load PC BIOS 'bios-256k.bin'
qemu failed.
```
Have not had chance to try with QEMU 4 yet.
--
You received this bug notification because you are a member of qemu-
devel-ml, which is subscribed to QEMU.
https://bugs.launchpad.net/bugs/1826393
Title:
QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
Status in QEMU:
New
Bug description:
Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
noticed that everytime I start QEMU to run OSv, QEMU seems to hand
noticably longer (~1 second) before showing SeaBIOS output. I have
tried all kind of combinations to get rid of that pause and nothing
helped.
Here is my start command:
time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
-enable-kvm \
-cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
It looks like qemu process starts, waits almost a second for something
and then print SeaBIOS splashscreen and continues boot:
--> waits here
SeaBIOS (version 1.12.0-1)
Booting from Hard Disk..OSv v0.53.0-6-gc8395118
disk read (real mode): 27.25ms, (+27.25ms)
uncompress lzloader.elf: 46.22ms, (+18.97ms)
TLS initialization: 46.79ms, (+0.57ms)
.init functions: 47.82ms, (+1.03ms)
SMP launched: 48.08ms, (+0.26ms)
VFS initialized: 49.25ms, (+1.17ms)
Network initialized: 49.48ms, (+0.24ms)
pvpanic done: 49.57ms, (+0.08ms)
pci enumerated: 52.42ms, (+2.85ms)
drivers probe: 52.42ms, (+0.00ms)
drivers loaded: 55.33ms, (+2.90ms)
ROFS mounted: 56.37ms, (+1.04ms)
Total time: 56.37ms, (+0.00ms)
Found optarg
dev etc hello libenviron.so libvdso.so proc tmp tools usr
real 0m0.935s
user 0m0.426s
sys 0m0.490s
With version 2.12.0 I used to see real below 200ms. So it seems qemu
slowed down 5 times.
I ran strace -tt against it and I have noticed a pause here:
...
07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848747 getpid() = 5162
07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848837 getpid() = 5162
07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
})
07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
v_nsec=190532609})
--> waits for almost 800ms
07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
LIN}], left {tv_sec=0, tv_nsec=189909632})
07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
...
when I run same command using qemu 3.0.5 that I still happen to have
on the same machine that I built directly from source I see total boot
time at around 200ms. It seems like a regression.
To manage notifications about this bug go to:
https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
^ permalink raw reply [flat|nested] 13+ messages in thread
* [Qemu-devel] [Bug 1826393] Re: QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
2019-04-25 11:37 [Qemu-devel] [Bug 1826393] [NEW] QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase Waldemar Kozaczuk
2019-04-29 15:47 ` Stefan Hajnoczi
2019-05-01 4:13 ` [Qemu-devel] [Bug 1826393] " Waldemar Kozaczuk
@ 2019-05-02 7:57 ` Stefano Garzarella
2019-05-06 17:40 ` Waldemar Kozaczuk
2 siblings, 1 reply; 13+ messages in thread
From: Stefano Garzarella @ 2019-05-02 7:57 UTC (permalink / raw)
To: qemu-devel
Oh sorry, you're using the 'pc' machine, so please try this bios:
https://github.com/qemu/qemu/blob/v4.0.0/pc-bios/bios.bin
--
You received this bug notification because you are a member of qemu-
devel-ml, which is subscribed to QEMU.
https://bugs.launchpad.net/bugs/1826393
Title:
QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
Status in QEMU:
New
Bug description:
Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
noticed that everytime I start QEMU to run OSv, QEMU seems to hand
noticably longer (~1 second) before showing SeaBIOS output. I have
tried all kind of combinations to get rid of that pause and nothing
helped.
Here is my start command:
time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
-enable-kvm \
-cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
It looks like qemu process starts, waits almost a second for something
and then print SeaBIOS splashscreen and continues boot:
--> waits here
SeaBIOS (version 1.12.0-1)
Booting from Hard Disk..OSv v0.53.0-6-gc8395118
disk read (real mode): 27.25ms, (+27.25ms)
uncompress lzloader.elf: 46.22ms, (+18.97ms)
TLS initialization: 46.79ms, (+0.57ms)
.init functions: 47.82ms, (+1.03ms)
SMP launched: 48.08ms, (+0.26ms)
VFS initialized: 49.25ms, (+1.17ms)
Network initialized: 49.48ms, (+0.24ms)
pvpanic done: 49.57ms, (+0.08ms)
pci enumerated: 52.42ms, (+2.85ms)
drivers probe: 52.42ms, (+0.00ms)
drivers loaded: 55.33ms, (+2.90ms)
ROFS mounted: 56.37ms, (+1.04ms)
Total time: 56.37ms, (+0.00ms)
Found optarg
dev etc hello libenviron.so libvdso.so proc tmp tools usr
real 0m0.935s
user 0m0.426s
sys 0m0.490s
With version 2.12.0 I used to see real below 200ms. So it seems qemu
slowed down 5 times.
I ran strace -tt against it and I have noticed a pause here:
...
07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848747 getpid() = 5162
07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848837 getpid() = 5162
07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
})
07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
v_nsec=190532609})
--> waits for almost 800ms
07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
LIN}], left {tv_sec=0, tv_nsec=189909632})
07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
...
when I run same command using qemu 3.0.5 that I still happen to have
on the same machine that I built directly from source I see total boot
time at around 200ms. It seems like a regression.
To manage notifications about this bug go to:
https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] Re: QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
2019-05-02 7:57 ` Stefano Garzarella
@ 2019-05-06 17:40 ` Waldemar Kozaczuk
2019-05-14 8:04 ` Stefano Garzarella
0 siblings, 1 reply; 13+ messages in thread
From: Waldemar Kozaczuk @ 2019-05-06 17:40 UTC (permalink / raw)
To: qemu-devel
The last bios indeed helped. It knows runs under 200ms.
Do you anticipate doing minor release of 3.1.0 with updated bios to address
this issue? Or users are expected to upgrade to QEMU 4.0.0?
Regards,
Waldek
On Thu, May 2, 2019 at 4:05 AM Stefano Garzarella <
1826393@bugs.launchpad.net> wrote:
> Oh sorry, you're using the 'pc' machine, so please try this bios:
> https://github.com/qemu/qemu/blob/v4.0.0/pc-bios/bios.bin
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1826393
>
> Title:
> QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
>
> Status in QEMU:
> New
>
> Bug description:
> Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
> that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
> noticed that everytime I start QEMU to run OSv, QEMU seems to hand
> noticably longer (~1 second) before showing SeaBIOS output. I have
> tried all kind of combinations to get rid of that pause and nothing
> helped.
>
> Here is my start command:
> time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> -enable-kvm \
> -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
>
> It looks like qemu process starts, waits almost a second for something
> and then print SeaBIOS splashscreen and continues boot:
>
> --> waits here
> SeaBIOS (version 1.12.0-1)
> Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> disk read (real mode): 27.25ms, (+27.25ms)
> uncompress lzloader.elf: 46.22ms, (+18.97ms)
> TLS initialization: 46.79ms, (+0.57ms)
> .init functions: 47.82ms, (+1.03ms)
> SMP launched: 48.08ms, (+0.26ms)
> VFS initialized: 49.25ms, (+1.17ms)
> Network initialized: 49.48ms, (+0.24ms)
> pvpanic done: 49.57ms, (+0.08ms)
> pci enumerated: 52.42ms, (+2.85ms)
> drivers probe: 52.42ms, (+0.00ms)
> drivers loaded: 55.33ms, (+2.90ms)
> ROFS mounted: 56.37ms, (+1.04ms)
> Total time: 56.37ms, (+0.00ms)
> Found optarg
> dev etc hello libenviron.so libvdso.so proc tmp tools usr
>
> real 0m0.935s
> user 0m0.426s
> sys 0m0.490s
>
> With version 2.12.0 I used to see real below 200ms. So it seems qemu
> slowed down 5 times.
>
> I ran strace -tt against it and I have noticed a pause here:
> ...
> 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848747 getpid() = 5162
> 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848837 getpid() = 5162
> 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN},
> {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8,
> revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> })
> 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1
> EAGAIN (Resource temporarily unavailable)
> 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN},
> {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1
> ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> v_nsec=190532609})
>
> --> waits for almost 800ms
>
> 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN},
> {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2
> ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> LIN}], left {tv_sec=0, tv_nsec=189909632})
> 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1
> EAGAIN (Resource temporarily unavailable)
> 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
>
> ...
>
> when I run same command using qemu 3.0.5 that I still happen to have
> on the same machine that I built directly from source I see total boot
> time at around 200ms. It seems like a regression.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
>
--
You received this bug notification because you are a member of qemu-
devel-ml, which is subscribed to QEMU.
https://bugs.launchpad.net/bugs/1826393
Title:
QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
Status in QEMU:
New
Bug description:
Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
noticed that everytime I start QEMU to run OSv, QEMU seems to hand
noticably longer (~1 second) before showing SeaBIOS output. I have
tried all kind of combinations to get rid of that pause and nothing
helped.
Here is my start command:
time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
-enable-kvm \
-cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
It looks like qemu process starts, waits almost a second for something
and then print SeaBIOS splashscreen and continues boot:
--> waits here
SeaBIOS (version 1.12.0-1)
Booting from Hard Disk..OSv v0.53.0-6-gc8395118
disk read (real mode): 27.25ms, (+27.25ms)
uncompress lzloader.elf: 46.22ms, (+18.97ms)
TLS initialization: 46.79ms, (+0.57ms)
.init functions: 47.82ms, (+1.03ms)
SMP launched: 48.08ms, (+0.26ms)
VFS initialized: 49.25ms, (+1.17ms)
Network initialized: 49.48ms, (+0.24ms)
pvpanic done: 49.57ms, (+0.08ms)
pci enumerated: 52.42ms, (+2.85ms)
drivers probe: 52.42ms, (+0.00ms)
drivers loaded: 55.33ms, (+2.90ms)
ROFS mounted: 56.37ms, (+1.04ms)
Total time: 56.37ms, (+0.00ms)
Found optarg
dev etc hello libenviron.so libvdso.so proc tmp tools usr
real 0m0.935s
user 0m0.426s
sys 0m0.490s
With version 2.12.0 I used to see real below 200ms. So it seems qemu
slowed down 5 times.
I ran strace -tt against it and I have noticed a pause here:
...
07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848747 getpid() = 5162
07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848837 getpid() = 5162
07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
})
07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
v_nsec=190532609})
--> waits for almost 800ms
07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
LIN}], left {tv_sec=0, tv_nsec=189909632})
07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
...
when I run same command using qemu 3.0.5 that I still happen to have
on the same machine that I built directly from source I see total boot
time at around 200ms. It seems like a regression.
To manage notifications about this bug go to:
https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] Re: QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-05-14 8:04 ` Stefano Garzarella
0 siblings, 0 replies; 13+ messages in thread
From: Stefano Garzarella @ 2019-05-14 8:04 UTC (permalink / raw)
To: Bug 1826393; +Cc: qemu devel list, Gerd Hoffmann
On Mon, May 06, 2019 at 05:40:05PM -0000, Waldemar Kozaczuk wrote:
> The last bios indeed helped. It knows runs under 200ms.
>
> Do you anticipate doing minor release of 3.1.0 with updated bios to address
> this issue? Or users are expected to upgrade to QEMU 4.0.0?
CCing Gerd
I'm not sure we will release SeaBIOS 1.12.1 with a minor release of QEMU
3.1.0, so upgrading to QEMU 4.0 should be the way to address this issue.
Regards,
Stefano
>
> Regards,
> Waldek
>
> On Thu, May 2, 2019 at 4:05 AM Stefano Garzarella <
> 1826393@bugs.launchpad.net> wrote:
>
> > Oh sorry, you're using the 'pc' machine, so please try this bios:
> > https://github.com/qemu/qemu/blob/v4.0.0/pc-bios/bios.bin
> >
> > --
> > You received this bug notification because you are subscribed to the bug
> > report.
> > https://bugs.launchpad.net/bugs/1826393
> >
> > Title:
> > QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
> >
> > Status in QEMU:
> > New
> >
> > Bug description:
> > Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
> > that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
> > noticed that everytime I start QEMU to run OSv, QEMU seems to hand
> > noticably longer (~1 second) before showing SeaBIOS output. I have
> > tried all kind of combinations to get rid of that pause and nothing
> > helped.
> >
> > Here is my start command:
> > time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> > -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> > -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> > -enable-kvm \
> > -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> > -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
> >
> > It looks like qemu process starts, waits almost a second for something
> > and then print SeaBIOS splashscreen and continues boot:
> >
> > --> waits here
> > SeaBIOS (version 1.12.0-1)
> > Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> > disk read (real mode): 27.25ms, (+27.25ms)
> > uncompress lzloader.elf: 46.22ms, (+18.97ms)
> > TLS initialization: 46.79ms, (+0.57ms)
> > .init functions: 47.82ms, (+1.03ms)
> > SMP launched: 48.08ms, (+0.26ms)
> > VFS initialized: 49.25ms, (+1.17ms)
> > Network initialized: 49.48ms, (+0.24ms)
> > pvpanic done: 49.57ms, (+0.08ms)
> > pci enumerated: 52.42ms, (+2.85ms)
> > drivers probe: 52.42ms, (+0.00ms)
> > drivers loaded: 55.33ms, (+2.90ms)
> > ROFS mounted: 56.37ms, (+1.04ms)
> > Total time: 56.37ms, (+0.00ms)
> > Found optarg
> > dev etc hello libenviron.so libvdso.so proc tmp tools usr
> >
> > real 0m0.935s
> > user 0m0.426s
> > sys 0m0.490s
> >
> > With version 2.12.0 I used to see real below 200ms. So it seems qemu
> > slowed down 5 times.
> >
> > I ran strace -tt against it and I have noticed a pause here:
> > ...
> > 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> > 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> > 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> > 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> > 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> > 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> > 07:31:41.848747 getpid() = 5162
> > 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> > 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> > 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> > 07:31:41.848837 getpid() = 5162
> > 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> > 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> > 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> > 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN},
> > {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> > {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8,
> > revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> > })
> > 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1
> > EAGAIN (Resource temporarily unavailable)
> > 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> > 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> > 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN},
> > {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> > {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1
> > ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> > v_nsec=190532609})
> >
> > --> waits for almost 800ms
> >
> > 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> > 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> > 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> > 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN},
> > {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> > {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2
> > ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> > LIN}], left {tv_sec=0, tv_nsec=189909632})
> > 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1
> > EAGAIN (Resource temporarily unavailable)
> > 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> > 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> >
> > ...
> >
> > when I run same command using qemu 3.0.5 that I still happen to have
> > on the same machine that I built directly from source I see total boot
> > time at around 200ms. It seems like a regression.
> >
> > To manage notifications about this bug go to:
> > https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
> >
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1826393
>
> Title:
> QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
>
> Status in QEMU:
> New
>
> Bug description:
> Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
> that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
> noticed that everytime I start QEMU to run OSv, QEMU seems to hand
> noticably longer (~1 second) before showing SeaBIOS output. I have
> tried all kind of combinations to get rid of that pause and nothing
> helped.
>
> Here is my start command:
> time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> -enable-kvm \
> -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
>
> It looks like qemu process starts, waits almost a second for something
> and then print SeaBIOS splashscreen and continues boot:
>
> --> waits here
> SeaBIOS (version 1.12.0-1)
> Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> disk read (real mode): 27.25ms, (+27.25ms)
> uncompress lzloader.elf: 46.22ms, (+18.97ms)
> TLS initialization: 46.79ms, (+0.57ms)
> .init functions: 47.82ms, (+1.03ms)
> SMP launched: 48.08ms, (+0.26ms)
> VFS initialized: 49.25ms, (+1.17ms)
> Network initialized: 49.48ms, (+0.24ms)
> pvpanic done: 49.57ms, (+0.08ms)
> pci enumerated: 52.42ms, (+2.85ms)
> drivers probe: 52.42ms, (+0.00ms)
> drivers loaded: 55.33ms, (+2.90ms)
> ROFS mounted: 56.37ms, (+1.04ms)
> Total time: 56.37ms, (+0.00ms)
> Found optarg
> dev etc hello libenviron.so libvdso.so proc tmp tools usr
>
> real 0m0.935s
> user 0m0.426s
> sys 0m0.490s
>
> With version 2.12.0 I used to see real below 200ms. So it seems qemu
> slowed down 5 times.
>
> I ran strace -tt against it and I have noticed a pause here:
> ...
> 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848747 getpid() = 5162
> 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848837 getpid() = 5162
> 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> })
> 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> v_nsec=190532609})
>
> --> waits for almost 800ms
>
> 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> LIN}], left {tv_sec=0, tv_nsec=189909632})
> 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
>
> ...
>
> when I run same command using qemu 3.0.5 that I still happen to have
> on the same machine that I built directly from source I see total boot
> time at around 200ms. It seems like a regression.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
--
Stefano Garzarella
Software Engineer @ Red Hat
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] Re: QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-05-14 8:04 ` Stefano Garzarella
0 siblings, 0 replies; 13+ messages in thread
From: Stefano Garzarella @ 2019-05-14 8:04 UTC (permalink / raw)
To: qemu-devel
On Mon, May 06, 2019 at 05:40:05PM -0000, Waldemar Kozaczuk wrote:
> The last bios indeed helped. It knows runs under 200ms.
>
> Do you anticipate doing minor release of 3.1.0 with updated bios to address
> this issue? Or users are expected to upgrade to QEMU 4.0.0?
CCing Gerd
I'm not sure we will release SeaBIOS 1.12.1 with a minor release of QEMU
3.1.0, so upgrading to QEMU 4.0 should be the way to address this issue.
Regards,
Stefano
>
> Regards,
> Waldek
>
> On Thu, May 2, 2019 at 4:05 AM Stefano Garzarella <
> 1826393@bugs.launchpad.net> wrote:
>
> > Oh sorry, you're using the 'pc' machine, so please try this bios:
> > https://github.com/qemu/qemu/blob/v4.0.0/pc-bios/bios.bin
> >
> > --
> > You received this bug notification because you are subscribed to the bug
> > report.
> > https://bugs.launchpad.net/bugs/1826393
> >
> > Title:
> > QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
> >
> > Status in QEMU:
> > New
> >
> > Bug description:
> > Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
> > that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
> > noticed that everytime I start QEMU to run OSv, QEMU seems to hand
> > noticably longer (~1 second) before showing SeaBIOS output. I have
> > tried all kind of combinations to get rid of that pause and nothing
> > helped.
> >
> > Here is my start command:
> > time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> > -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> > -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> > -enable-kvm \
> > -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> > -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
> >
> > It looks like qemu process starts, waits almost a second for something
> > and then print SeaBIOS splashscreen and continues boot:
> >
> > --> waits here
> > SeaBIOS (version 1.12.0-1)
> > Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> > disk read (real mode): 27.25ms, (+27.25ms)
> > uncompress lzloader.elf: 46.22ms, (+18.97ms)
> > TLS initialization: 46.79ms, (+0.57ms)
> > .init functions: 47.82ms, (+1.03ms)
> > SMP launched: 48.08ms, (+0.26ms)
> > VFS initialized: 49.25ms, (+1.17ms)
> > Network initialized: 49.48ms, (+0.24ms)
> > pvpanic done: 49.57ms, (+0.08ms)
> > pci enumerated: 52.42ms, (+2.85ms)
> > drivers probe: 52.42ms, (+0.00ms)
> > drivers loaded: 55.33ms, (+2.90ms)
> > ROFS mounted: 56.37ms, (+1.04ms)
> > Total time: 56.37ms, (+0.00ms)
> > Found optarg
> > dev etc hello libenviron.so libvdso.so proc tmp tools usr
> >
> > real 0m0.935s
> > user 0m0.426s
> > sys 0m0.490s
> >
> > With version 2.12.0 I used to see real below 200ms. So it seems qemu
> > slowed down 5 times.
> >
> > I ran strace -tt against it and I have noticed a pause here:
> > ...
> > 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> > 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> > 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> > 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> > 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> > 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> > 07:31:41.848747 getpid() = 5162
> > 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> > 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> > 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> > 07:31:41.848837 getpid() = 5162
> > 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> > 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> > 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> > 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN},
> > {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> > {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8,
> > revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> > })
> > 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1
> > EAGAIN (Resource temporarily unavailable)
> > 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> > 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> > 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN},
> > {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> > {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1
> > ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> > v_nsec=190532609})
> >
> > --> waits for almost 800ms
> >
> > 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> > 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> > 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> > 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN},
> > {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> > {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2
> > ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> > LIN}], left {tv_sec=0, tv_nsec=189909632})
> > 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1
> > EAGAIN (Resource temporarily unavailable)
> > 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> > 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> >
> > ...
> >
> > when I run same command using qemu 3.0.5 that I still happen to have
> > on the same machine that I built directly from source I see total boot
> > time at around 200ms. It seems like a regression.
> >
> > To manage notifications about this bug go to:
> > https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
> >
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1826393
>
> Title:
> QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
>
> Status in QEMU:
> New
>
> Bug description:
> Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
> that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
> noticed that everytime I start QEMU to run OSv, QEMU seems to hand
> noticably longer (~1 second) before showing SeaBIOS output. I have
> tried all kind of combinations to get rid of that pause and nothing
> helped.
>
> Here is my start command:
> time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
> -device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
> -drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
> -enable-kvm \
> -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
> -mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
>
> It looks like qemu process starts, waits almost a second for something
> and then print SeaBIOS splashscreen and continues boot:
>
> --> waits here
> SeaBIOS (version 1.12.0-1)
> Booting from Hard Disk..OSv v0.53.0-6-gc8395118
> disk read (real mode): 27.25ms, (+27.25ms)
> uncompress lzloader.elf: 46.22ms, (+18.97ms)
> TLS initialization: 46.79ms, (+0.57ms)
> .init functions: 47.82ms, (+1.03ms)
> SMP launched: 48.08ms, (+0.26ms)
> VFS initialized: 49.25ms, (+1.17ms)
> Network initialized: 49.48ms, (+0.24ms)
> pvpanic done: 49.57ms, (+0.08ms)
> pci enumerated: 52.42ms, (+2.85ms)
> drivers probe: 52.42ms, (+0.00ms)
> drivers loaded: 55.33ms, (+2.90ms)
> ROFS mounted: 56.37ms, (+1.04ms)
> Total time: 56.37ms, (+0.00ms)
> Found optarg
> dev etc hello libenviron.so libvdso.so proc tmp tools usr
>
> real 0m0.935s
> user 0m0.426s
> sys 0m0.490s
>
> With version 2.12.0 I used to see real below 200ms. So it seems qemu
> slowed down 5 times.
>
> I ran strace -tt against it and I have noticed a pause here:
> ...
> 07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
> 07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
> 07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
> 07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
> 07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848747 getpid() = 5162
> 07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
> 07:31:41.848837 getpid() = 5162
> 07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
> 07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
> 07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
> })
> 07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
> 07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
> 07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
> v_nsec=190532609})
>
> --> waits for almost 800ms
>
> 07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
> 07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
> 07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
> {fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
> LIN}], left {tv_sec=0, tv_nsec=189909632})
> 07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
> 07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
>
> ...
>
> when I run same command using qemu 3.0.5 that I still happen to have
> on the same machine that I built directly from source I see total boot
> time at around 200ms. It seems like a regression.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
--
Stefano Garzarella
Software Engineer @ Red Hat
** Changed in: qemu
Status: New => Fix Released
--
You received this bug notification because you are a member of qemu-
devel-ml, which is subscribed to QEMU.
https://bugs.launchpad.net/bugs/1826393
Title:
QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
Status in QEMU:
Fix Released
Bug description:
Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
noticed that everytime I start QEMU to run OSv, QEMU seems to hand
noticably longer (~1 second) before showing SeaBIOS output. I have
tried all kind of combinations to get rid of that pause and nothing
helped.
Here is my start command:
time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
-enable-kvm \
-cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
It looks like qemu process starts, waits almost a second for something
and then print SeaBIOS splashscreen and continues boot:
--> waits here
SeaBIOS (version 1.12.0-1)
Booting from Hard Disk..OSv v0.53.0-6-gc8395118
disk read (real mode): 27.25ms, (+27.25ms)
uncompress lzloader.elf: 46.22ms, (+18.97ms)
TLS initialization: 46.79ms, (+0.57ms)
.init functions: 47.82ms, (+1.03ms)
SMP launched: 48.08ms, (+0.26ms)
VFS initialized: 49.25ms, (+1.17ms)
Network initialized: 49.48ms, (+0.24ms)
pvpanic done: 49.57ms, (+0.08ms)
pci enumerated: 52.42ms, (+2.85ms)
drivers probe: 52.42ms, (+0.00ms)
drivers loaded: 55.33ms, (+2.90ms)
ROFS mounted: 56.37ms, (+1.04ms)
Total time: 56.37ms, (+0.00ms)
Found optarg
dev etc hello libenviron.so libvdso.so proc tmp tools usr
real 0m0.935s
user 0m0.426s
sys 0m0.490s
With version 2.12.0 I used to see real below 200ms. So it seems qemu
slowed down 5 times.
I ran strace -tt against it and I have noticed a pause here:
...
07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848747 getpid() = 5162
07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848837 getpid() = 5162
07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
})
07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
v_nsec=190532609})
--> waits for almost 800ms
07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
LIN}], left {tv_sec=0, tv_nsec=189909632})
07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
...
when I run same command using qemu 3.0.5 that I still happen to have
on the same machine that I built directly from source I see total boot
time at around 200ms. It seems like a regression.
To manage notifications about this bug go to:
https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] Re: QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-05-14 8:52 ` Gerd Hoffmann
0 siblings, 0 replies; 13+ messages in thread
From: Gerd Hoffmann @ 2019-05-14 8:52 UTC (permalink / raw)
To: Stefano Garzarella; +Cc: Bug 1826393, qemu devel list
On Tue, May 14, 2019 at 10:04:14AM +0200, Stefano Garzarella wrote:
> On Mon, May 06, 2019 at 05:40:05PM -0000, Waldemar Kozaczuk wrote:
> > The last bios indeed helped. It knows runs under 200ms.
> >
> > Do you anticipate doing minor release of 3.1.0 with updated bios to address
> > this issue? Or users are expected to upgrade to QEMU 4.0.0?
>
> CCing Gerd
>
> I'm not sure we will release SeaBIOS 1.12.1 with a minor release of QEMU
> 3.1.0, so upgrading to QEMU 4.0 should be the way to address this issue.
I think with the 4.0 release 3.1 is EOL and there will be no more 3.1.x
stable releases ...
cheers,
Gerd
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [Qemu-devel] [Bug 1826393] Re: QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
@ 2019-05-14 8:52 ` Gerd Hoffmann
0 siblings, 0 replies; 13+ messages in thread
From: Gerd Hoffmann @ 2019-05-14 8:52 UTC (permalink / raw)
To: qemu-devel
On Tue, May 14, 2019 at 10:04:14AM +0200, Stefano Garzarella wrote:
> On Mon, May 06, 2019 at 05:40:05PM -0000, Waldemar Kozaczuk wrote:
> > The last bios indeed helped. It knows runs under 200ms.
> >
> > Do you anticipate doing minor release of 3.1.0 with updated bios to address
> > this issue? Or users are expected to upgrade to QEMU 4.0.0?
>
> CCing Gerd
>
> I'm not sure we will release SeaBIOS 1.12.1 with a minor release of QEMU
> 3.1.0, so upgrading to QEMU 4.0 should be the way to address this issue.
I think with the 4.0 release 3.1 is EOL and there will be no more 3.1.x
stable releases ...
cheers,
Gerd
--
You received this bug notification because you are a member of qemu-
devel-ml, which is subscribed to QEMU.
https://bugs.launchpad.net/bugs/1826393
Title:
QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase
Status in QEMU:
Fix Released
Bug description:
Yesterday I have upgraded my laptop from Ubuntu 18.10 to 19.04 and
that way got newer QEMU 3.1.0 along vs QEMU 2.12.0 before. I have
noticed that everytime I start QEMU to run OSv, QEMU seems to hand
noticably longer (~1 second) before showing SeaBIOS output. I have
tried all kind of combinations to get rid of that pause and nothing
helped.
Here is my start command:
time qemu-system-x86_64 -m 256M -smp 1 -nographic -nodefaults \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=usr.img,if=none,id=hd0,cache=none,aio=thre\
-enable-kvm \
-cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio
It looks like qemu process starts, waits almost a second for something
and then print SeaBIOS splashscreen and continues boot:
--> waits here
SeaBIOS (version 1.12.0-1)
Booting from Hard Disk..OSv v0.53.0-6-gc8395118
disk read (real mode): 27.25ms, (+27.25ms)
uncompress lzloader.elf: 46.22ms, (+18.97ms)
TLS initialization: 46.79ms, (+0.57ms)
.init functions: 47.82ms, (+1.03ms)
SMP launched: 48.08ms, (+0.26ms)
VFS initialized: 49.25ms, (+1.17ms)
Network initialized: 49.48ms, (+0.24ms)
pvpanic done: 49.57ms, (+0.08ms)
pci enumerated: 52.42ms, (+2.85ms)
drivers probe: 52.42ms, (+0.00ms)
drivers loaded: 55.33ms, (+2.90ms)
ROFS mounted: 56.37ms, (+1.04ms)
Total time: 56.37ms, (+0.00ms)
Found optarg
dev etc hello libenviron.so libvdso.so proc tmp tools usr
real 0m0.935s
user 0m0.426s
sys 0m0.490s
With version 2.12.0 I used to see real below 200ms. So it seems qemu
slowed down 5 times.
I ran strace -tt against it and I have noticed a pause here:
...
07:31:41.848579 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848604 futex(0x55c4a2ff6308, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
07:31:41.848649 ioctl(10, KVM_SET_PIT2, 0x7ffdd272d1f0) = 0
07:31:41.848674 ioctl(9, KVM_CHECK_EXTENSION, KVM_CAP_KVMCLOCK_CTRL) = 1
07:31:41.848699 ioctl(10, KVM_SET_CLOCK, 0x7ffdd272d230) = 0
07:31:41.848724 futex(0x55c4a49a9a9c, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848747 getpid() = 5162
07:31:41.848769 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848791 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.848814 futex(0x55c4a49a9a98, FUTEX_WAKE_PRIVATE, 2147483647) = 1
07:31:41.848837 getpid() = 5162
07:31:41.848858 tgkill(5162, 5166, SIGUSR1) = 0
07:31:41.848889 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
07:31:41.848919 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:41.848943 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=8, revents=POLLIN}], left {tv_sec=0, tv_nsec=0
})
07:31:41.849003 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:41.849031 read(8, "\5\0\0\0\0\0\0\0", 16) = 8
07:31:41.849064 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 0
07:31:41.849086 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=984624000}, NULL, 8) = 1 ([{fd=7, revents=POLLIN}], left {tv_sec=0, t
v_nsec=190532609})
--> waits for almost 800ms
07:31:42.643272 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
07:31:42.643522 read(7, "\1\0\0\0\0\0\0\0", 512) = 8
07:31:42.643625 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
07:31:42.643646 ppoll([{fd=0, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=7, events=POLLIN},
{fd=8, events=POLLIN}], 5, {tv_sec=0, tv_nsec=190066000}, NULL, 8) = 2 ([{fd=4, revents=POLLIN}, {fd=8, revents=POL
LIN}], left {tv_sec=0, tv_nsec=189909632})
07:31:42.643836 futex(0x55c4a2fd34c0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
07:31:42.643859 read(8, "\2\0\0\0\0\0\0\0", 16) = 8
07:31:42.643880 futex(0x55c4a2fd34c0, FUTEX_WAKE_PRIVATE, 1) = 1
...
when I run same command using qemu 3.0.5 that I still happen to have
on the same machine that I built directly from source I see total boot
time at around 200ms. It seems like a regression.
To manage notifications about this bug go to:
https://bugs.launchpad.net/qemu/+bug/1826393/+subscriptions
^ permalink raw reply [flat|nested] 13+ messages in thread
end of thread, other threads:[~2019-05-14 9:02 UTC | newest]
Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-04-25 11:37 [Qemu-devel] [Bug 1826393] [NEW] QEMU 3.1.0 stuck waiting for 800ms (5 times slower) in pre-bios phase Waldemar Kozaczuk
2019-04-29 15:47 ` Stefan Hajnoczi
2019-04-29 15:47 ` Stefan Hajnoczi
2019-04-29 15:47 ` Stefan Hajnoczi
2019-04-29 16:25 ` Stefano Garzarella
2019-04-29 16:25 ` Stefano Garzarella
2019-05-01 4:13 ` [Qemu-devel] [Bug 1826393] " Waldemar Kozaczuk
2019-05-02 7:57 ` Stefano Garzarella
2019-05-06 17:40 ` Waldemar Kozaczuk
2019-05-14 8:04 ` Stefano Garzarella
2019-05-14 8:04 ` Stefano Garzarella
2019-05-14 8:52 ` Gerd Hoffmann
2019-05-14 8:52 ` Gerd Hoffmann
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.