Slow logging with max resolution and scrolling

[gz]

It seems that scrolling logging (trace!, debug! etc.) messages can become a bottleneck on bigger screens when it's scrolling and the Output protocol is set to the maximum resolution. But maybe I'm just doing something wrong.

I have the following function:

fn setup_output(st: &SystemTable<Boot>) {
    if let Ok(stdout) = st.boot_services().locate_protocol::<Output>() {
        let stdout = stdout.expect("Warnings encountered while opening Output");
        let stdout = unsafe { &mut *stdout.get() };
        let best_mode = stdout
            .modes()
            .last()
            .unwrap()
            .expect("Warnings encountered while querying text mode");
        stdout
            .set_mode(best_mode)
            .expect_success("Failed to change text mode");
    } else {
        warn!("UEFI Output Protocol is not supported.");
    }
}

When called during initialization, logging/adding new lines is now a bottleneck (but screen resolution is high), and when not called logging/scrolling is fast again (but screen resolution is low). This happens on real hardware.

[HadrienG2]

This does not surprise me much, as I observed very slow UEFI graphics on my machines before. For example, on a high-end laptop of mine with a 2880 x 1440 screen, the GRUB welcome screen takes almost one second to display, during which you can literally see the background color slowly flowing down the screen.

When you consider that a 2880x1440 32-bit bitmap is 16.5 MB of data and that the PCIe link between the CPU and GPU has several GB/s of bandwidth, this is just ridiculously bad.

I suspect that it all boils down a mixture of very poorly optimized firmware code and lack of hardware acceleration. Most likely that poor firmware blitting performance is why the Windows boot screen is so minimalistic ;)

[gz]

Agreed, it's quite terrible. I wasn't sure if there might be some overheads in uefi-rs that slows it down, but if you're not aware of anything I guess we can blame it on the firmware :)

[HadrienG2]

uefi-rs is not very smart about logging, for example it performs one UEFI API call per print() call without any buffering. But the uefi-rs logger does nothing that is resolution-dependent, it just calls the UEFI text output API. So if you observe a resolution-dependent slowdown, it has to be at least partially the firmware's fault...

[HadrienG2]

Okay, it's actually quite a bit more complex than I remembered... but still not resolution dependent ;)

[gz]

According to the UEFI settings my board may be using an Intel GOP driver v13.0.1011 https://www.intel.com/content/www/us/en/embedded/software/emgd/embedded-media-and-graphics-drivers-faq-bios-and-firmware.html

It's fascinating that the whole UEFI Settings GUI stuff renders with reasonable resolution and pretty fast but as soon as a regular UEFI application starts outputting simple text, it seems suddenly no longer possible..

[HadrienG2]

Aha, this is different from my laptop where the UEFI config is run in low-resolution text mode, which suggests to me that the firmware devs were aware of the problem and tried to work around it the ugly way.

It may be that it is only the UEFI text output primitives that are slow in your case. You can check this by rolling out a fill benchmark that hammers the GOP framebuffer with random pixels in a tight loop, and see if you get a reasonable bandwidth.

If it's only the UEFI text output that is slow, then you can work around it by rolling your own text renderer based on raw GOP access... but obviously that's quite a bit of work.

[M1cha]

it's slow because UEFI's GraphicsConsole is really slow. It iterates over every single character, calling Blt for all of them. This also includes allocating temporary memory for every character. And I didn't even look at what the HII protocol does when drawing that character. Scrolling is actually fine because it copies everything one line up at once(not line-by-line).

When using gfxterm, grub does use the GraphicsOutputProtocol directly so it would be fast in theory. The problem is that grubs way of printing characters is worse than UEFIs because they lack an API to output a string. So instead they call grub_gfxterm_putchar character by character, calling blt for every single one of them. If you have a cursor you'll even have two calls per character.

That's also the reason why in BIOS mode, grubs gfxterm is even slower than in UEFI, because there they have to switch between real and protected mode for every single character so they can draw to the screen without implementing their own drivers.

and about the resolution in UEFI: Usually when you have the boot logo enabled rather than the text boot-up mode, it enables the max resolution, also when you enter any setup-menu it'll go to the highest resolution. That means that if you boot directly to grub with uefi booting without a logo, you'll have a lower resolution in grub than when you have the bootlogo enabled or went through the boot selection menu.

References: https://github.com/tianocore/edk2/blob/0a35997643972d3b76a67547cbffeaa8a3d708c3/MdeModulePkg/Universal/Console/GraphicsConsoleDxe/GraphicsConsole.c#L901 https://github.com/tianocore/edk2/blob/0a35997643972d3b76a67547cbffeaa8a3d708c3/MdeModulePkg/Universal/Console/GraphicsConsoleDxe/GraphicsConsole.c#L1756

[HadrienG2]

Many thanks for looking up the explanation !

[GabrielMajeri]

Closing this issue since the original question has been answered, and there's little we can do to improve the overall efficiency of outputting text in UEFI.