Initializing VGA console is very slow

[wkozaczuk]

Initializing VGA console takes almost 60 ms as you see below it. It turns out that this particular code is the culprit - https://github.com/cloudius-systems/osv/blob/master/drivers/vga.cc#L70-L84.

./scripts/build fs=rofs image=native-example

qemu-system-x86_64 -m 2G -smp 1 -vnc :1 -gdb tcp::1234,server,nowait \
-device virtio-blk-pci,id=blk0,bootindex=0,drive=hd0,scsi=off \
-drive file=/home/wkozaczuk/projects/osv/build/last/usr.img,if=none,id=hd0,cache=none,aio=threads \
-netdev user,id=un0,net=192.168.122.0/24,host=192.168.122.1 \
-device virtio-net-pci,netdev=un0 -device virtio-rng-pci \
-enable-kvm -cpu host,+x2apic -chardev stdio,mux=on,id=stdio,signal=off \
-mon chardev=stdio,mode=readline -device isa-serial,chardev=stdio

OSv v0.51.0-5-ga3cd022f
1 CPUs detected
Firmware vendor: SeaBIOS
bsd: initializing - done
VFS: mounting ramfs at /
VFS: mounting devfs at /dev
net: initializing - done
vga: Add VGA device instance
Probed driver: VGAConsole
eth0: ethernet address: 52:54:00:12:34:56
Probed driver: virtio-net
virtio-blk: Add blk device instances 0 as vblk0, devsize=8520192
Probed driver: virtio-blk
random: virtio-rng registered as a source.
Probed driver: virtio-rng
random: intel drng, rdrand registered as a source.
random: <Software, Yarrow> initialized
VFS: unmounting /dev
VFS: mounting rofs at /rofs
VFS: mounting devfs at /dev
VFS: mounting procfs at /proc
VFS: mounting ramfs at /tmp
[I/27 dhcp]: Broadcasting DHCPDISCOVER message with xid: [1165270835]
[I/27 dhcp]: Waiting for IP...
[I/35 dhcp]: Received DHCPOFFER message from DHCP server: 192.168.122.1 regarding offerred IP address: 192.168.122.15
[I/35 dhcp]: Broadcasting DHCPREQUEST message with xid: [1165270835] to SELECT offered IP: 192.168.122.15
[I/35 dhcp]: Received DHCPACK message from DHCP server: 192.168.122.1 regarding offerred IP address: 192.168.122.15
[I/35 dhcp]: Server acknowledged IP 192.168.122.15 for interface eth0 with time to lease in seconds: 86400
eth0: 192.168.122.15
[I/35 dhcp]: Configuring eth0: ip 192.168.122.15 subnet mask 255.255.255.0 gateway 192.168.122.1 MTU 1500
	disk read (real mode): 38.40ms, (+38.40ms)
	uncompress lzloader.elf: 60.00ms, (+21.61ms)
	TLS initialization: 60.49ms, (+0.48ms)
	.init functions: 62.21ms, (+1.72ms)
	SMP launched: 63.02ms, (+0.81ms)
	VFS initialized: 65.12ms, (+2.10ms)
	Network initialized: 65.42ms, (+0.30ms)
	pvpanic done: 65.53ms, (+0.11ms)
	pci enumerated: 75.86ms, (+10.33ms)
	drivers probe: 75.86ms, (+0.00ms)
	VGAConsole probed: 75.86ms, (+0.00ms)
	VGAConsole instantiated: 133.33ms, (+57.47ms)
	drivers loaded: 139.99ms, (+6.66ms)
	arch init: 139.99ms, (+0.00ms)
	drivers loaded: 141.53ms, (+1.54ms)
	ROFS mounted: 143.63ms, (+2.09ms)
	Total time: 151.41ms, (+7.78ms)
Hello from C code
[I/0 dhcp]: Unicasting DHCPRELEASE message with xid: [1958559405] from client: 192.168.122.15 to server: 192.168.122.1
VFS: unmounting /dev
VFS: unmounting /proc
VFS: unmounting /
ROFS: spent 1.07 ms reading from disk
ROFS: read 27 512-byte blocks from disk
ROFS: allocated 24 512-byte blocks of cache memory
ROFS: hit ratio is 90.32%
Powering off.

real	0m0.277s
user	0m0.119s
sys	0m0.141s

Simple workaround is to disable VGA console by passing "--console=serial" in OSv command line which means serial console will be initialized and use only. On some hypervisors the serial console is not available however.

Most likely slowness has to do how efficiently specific hypervisor handles reads from video memory. Corresponding discussion and details can be found here - https://groups.google.com/forum/#!topic/osv-dev/40xeAkbUyw8.