1967238 - Print preview dialog shows nothing but a spinner for about 50 seconds on first use

Status: NEW

(Toolkit :: Printing, defect)

Description

[:Gijs (he/him)]

[Tracking Requested - why for this release]:

Seeing this on my own local nightly and on shipped nightlies. Doesn't repro on beta 139b9. No obvious errors in the browser console. Don't see any dupes suggested by bugzilla.

Comment 1

[:Gijs (he/him)]

On mozregression nightly builds I can repro this at least 10 releases back, so there must be some other difference between my beta build and what's happening on the (clean) nightly profiles. Still seems very bad (we don't even show a cancel button! esc works but most users won't know that) but I guess not a recent regression...

Comment 2

[:Gijs (he/him)]

Attachment: Profile markers

I have a debug settings fx profiler profile for this behaviour but am still not sure where the time is going - the browser is not hanging, so most samples in the parent process are in the event loop code and ZwUserMsgWaitForMultipleObjectsEx et al.

Subsequent openings of the dialog are fast.

My suspicion is that we're fetching information about the default printer. In my case, that's a network printer, and it isn't turned on. So I assume that some of this fetching of information tries for a while to reach the printer and then gives up. This is bad; we have a "Save to PDF" printer setting; if this is the first time the dialog is being opened and it takes more than <some threshold> to fetch printer settings we should just default to that, IMO.

Comment 3

[Emilio Cobos Álvarez [:emilio]]

The printer information is queried off the main thread, do you have a whole profile? That may show more stuff around here.

Comment 4

[:Gijs (he/him)]

Looks like practically all the time is spent in:

NtWaitForMultipleObjects [ntdll.dll]
WaitForMultipleObjectsEx [KERNELBASE.dll]
DefaultWaitForHandles(unsigned long, unsigned long, unsigned long, void**, unsigned long*) [onecore\com\combase\dcomrem\sync.cxx]
CoWaitForMultipleHandles(unsigned long, unsigned long, unsigned long, void**, unsigned long*) [onecore\com\combase\dcomrem\sync.cxx]
PdcRegenerationHandler::WaitForPdcCompletionOrTimeout(Windows::Foundation::IAsyncAction*, unsigned long, tagCOWAIT_FLAGS) [WINSPOOL.DRV]
PdcRegenerationHandler::WaitforPdcCompletion(Windows::Foundation::IAsyncAction*) [WINSPOOL.DRV]
PdcRegenerationHandler::RegeneratePdcForPrinter(void*, int) [WINSPOOL.DRV]
RegeneratePrintDeviceCapabilities [WINSPOOL.DRV]
fun_11df44 [PrintConfig.dll]
fun_1048d0 [PrintConfig.dll]
fun_2ae10 [PrintConfig.dll]
PTOpenProviderExImp(unsigned short const*, unsigned long, unsigned long, HPTPROVIDER__**, unsigned long*) [prntvpt.dll]
CPrintTicketServerBase::BindEx(unsigned short*, unsigned long, unsigned long, unsigned long*) [prntvpt.dll]
PTOpenProviderEx [prntvpt.dll]
fun_ae040 [PrintConfig.dll]
fun_ae010 [PrintConfig.dll]
fun_d695c [PrintConfig.dll]
fun_d6ec0 [PrintConfig.dll]
fun_da238 [PrintConfig.dll]
fun_da12c [PrintConfig.dll]
fun_daec0 [PrintConfig.dll]
fun_3054c [PrintConfig.dll]
fun_3c428 [PrintConfig.dll]
MxdcGetPDEVAdjustment [PrintConfig.dll]
edocs::PDev::InvokeMxdcGetPDEVAdjustment(long (*)(void*, unsigned long, _devicemodeW const*, unsigned long, void const*, unsigned long, PrintPropertiesCollection*), edocs::PDEVAdjustmentInfo&) [mxdwdrv.dll]
edocs::PDev::ValidateForm(void) [mxdwdrv.dll]
DrvEnablePDEV [mxdwdrv.dll]
GdiPrinterThunk [gdi32full.dll]
_ClientPrinterThunk [user32.dll]
KiUserCallbackDispatch [ntdll.dll]
ZwGdiOpenDCW [win32u.dll]
hdcCreateDCW(_UNICODE_STRING*, _UNICODE_STRING*, _devicemodeW const*, int, int, int) [gdi32full.dll]
bCreateDCW [GDI32.dll]
CreateICW [GDI32.dll]
DevmodeToSettingsInitializer(nsTString<char16_t> const&, _devicemodeW const*, mozilla::Mutex&, mozilla::PrintSettingsInitializer&) [widget/windows/nsPrinterWin.cpp]
nsPrinterWin::DefaultSettings() const [widget/windows/nsPrinterWin.cpp]
nsPrinterWin::CreatePrinterInfo() const [widget/windows/nsPrinterWin.cpp]
mozilla::SpawnPrintBackgroundTask<nsPrinterBase,nsPrinterBase::PrinterInfo>::<lambda_1>::operator()::<lambda_1>::operator()() const [widget/PrintBackgroundTask.h]
std::invoke(mozilla::SpawnPrintBackgroundTask<nsPrinterBase,nsPrinterBase::PrinterInfo>::<lambda_1>::operator()::<lambda_1>&&) [/builds/worker/fetches/vs/VC/Tools/MSVC/14.39.33519/include/type_traits]
std::_Apply_impl(mozilla::SpawnPrintBackgroundTask<nsPrinterBase,nsPrinterBase::PrinterInfo>::<lambda_1>::operator()::<lambda_1>&&, std::tuple<> const&&, std::integer_sequence<unsigned long long>) [/builds/worker/fetches/vs/VC/Tools/MSVC/14.39.33519/include/tuple]
std::apply(mozilla::SpawnPrintBackgroundTask<nsPrinterBase,nsPrinterBase::PrinterInfo>::<lambda_1>::operator()::<lambda_1>&&, std::tuple<> const&&) [/builds/worker/fetches/vs/VC/Tools/MSVC/14.39.33519/include/tuple]
mozilla::SpawnPrintBackgroundTask<nsPrinterBase,nsPrinterBase::PrinterInfo>::<lambda_1>::operator()() const [widget/PrintBackgroundTask.h]

Comment 5

[Emilio Cobos Álvarez [:emilio]]

So this would be the timing out promise: https://searchfox.org/mozilla-central/rev/578d9c83f046d8c361ac6b98b297c27990d468fd/toolkit/components/printing/content/print.js#1205

It seems having some timeout there or at least not blocking initialization on it would be good...

Comment 6

[:Gijs (he/him)]

Attachment: WIP: Bug 1967238 - avoid blocking print dialog initialization on slow/unavailable network printers, r?emilio

Comment 7

[:Gijs (he/him)]

So I've poked at this a bit given I can reproduce and bug 1821588 makes it seem like this can be intermittent / depends on Windows' vagaries.

I have a patch that:

• adds telemetry so we gain insight into how long this process really takes
• caps it during dialog initialization at a (currently fixed, open to other suggestions) timeout and tries the next printer if initialization takes a long time

This works well.

However, it creates 2, maybe 3, different problems:

• we end up having this timeout every time the dialog opens (if you cancel it), because we don't seem to persist the selected printer once we have skipped the "default" printer. I don't know how that logic works and if I'm missing in the patch. I started with a 5s timeout so this is easily noticeable.
• if I open the dialog once, wait for it to figure itself out, then close it, then reopen it, then select the network printer "on purpose", the dialog gets "stuck" and doesn't recover. I've tried adding some logging, as far as I can tell we just end up stuck in native code somewhere but it's not clear to me why or how I'd debug it. I'm hoping someone more familiar with printing can advise.
• with the steps above, assuming a subsequent call will continue to be slow, we probably need some state (other than purely the controls being disabled) to indicate to the user that we're waiting on the OS to give us printer information. I haven't written that yet but wanted to write down that I think we need it.

I'm also curious if there is some way for us to detect that this is a disconnected/unavailable network printer and avoid the slowness entirely.

Comment 8

[Daniel Holbert [:dholbert]]

[Answering for just the part where I think I recall a good answer...]

(In reply to :Gijs (he/him) from comment #7)

• we end up having this timeout every time the dialog opens (if you cancel it), because we don't seem to persist the selected printer once we have skipped the "default" printer. I don't know how that logic works and if I'm missing in the patch. I started with a 5s timeout so this is easily noticeable.

IIRC, when the user completes a print job, we save the printer that was used to the about:config pref named "print_printer". And when the print dialog opens, we check that pref first, and we default to selecting that printer. If that pref is empty or unrecognized, then I think we instead use the system default printer.

In your case, you've probably got the "bad" printer either set as the system default or saved in the print_printer pref. Either way: if you want to make the print dialog start out with a different printer from the one that it chose last time, you'll want to adjust the print_printer value. "Mozilla Save to PDF" might be a good (or at least likely-safe) fallback print-target if we detect that the current print target is hanging.

Comment 9

[Tony Davis]

Attachment: ABOUT SUPPORT showing old printer not changed

Please remove this if irrelevant or gets in the way of your processing for this bug.

Comment 10

[Tony Davis]

Hope you don't mind me adding a bit to this, as I was the originator of the original linked BUG (sorry cannot find that now).
Anyway, I had a similar test case to some of the others, where a printer (or in this case a printer Driver) had to change.
We have a new Brother HL-L3230CDW that is now used for most day to day printing, but ALSO an old HP 7350, that is used for labels or the odd shopping list page. It was originally using the D7200 driver (the only was to get it working in Windows 11), and that is what you see in my attached ABOUT_SUPPORT text file.

NOTE: I had to change that driver from a D7200 to a D7400 driver, that was more reliable. However, I had NOT printed from this Laptop to that desktop, where that shared printer is connected.

I have NOW tested the print preview from my FF 139 on the laptop, and that was successful (as it WAS selectable, and printed fine).
HOWEVER: the OLD D7200 printer properties details are STILL in the ABOUT:SUPPORT page attached, they have NOT CHANGED, even after a good print. I even restarted the browser to recheck, still the same values. Hope this is useful, as those configs don't seem to get refreshed.

Comment 11

[Daniel Holbert [:dholbert]]

(In reply to Tony Davis from comment #10)

I have NOW tested the print preview from my FF 139 on the laptop, and that was successful (as it WAS selectable, and printed fine).

Hooray!

HOWEVER: the OLD D7200 printer properties details are STILL in the ABOUT:SUPPORT page attached, they have NOT CHANGED, even after a good print. I even restarted the browser to recheck, still the same values. Hope this is useful, as those configs don't seem to get refreshed.

If I'm understanding you correctly, I think this observation is in fact expected behavior. Firefox remembers print settings on a per-printer basis (storing settings for all printers you've previously used), so that e.g. Firefox will remember that you chose to print with larger margins on Printer A without imposing those as the new default for all other printers, for example. (This does mean that about:config might accumulate entries for printers that you've long since discarded (or haven't used in a while), which is perhaps a bit cluttery, but doesn't really cause trouble.)

Comment 12

[Daniel Holbert [:dholbert]]

(In reply to Tony Davis from comment #10)

Hope you don't mind me adding a bit to this, as I was the originator of the original linked BUG (sorry cannot find that now).

(For reference, Tony's bug here was bug 1821588, I think.)

Comment 13

[Mark Striemer [:mstriemer]]

The approach in the patch seems reasonable to me

we end up having this timeout every time the dialog opens (if you cancel it)

This seems like it might be the preferred handling of this situation to me. Perhaps you are wanting to print to a network printer, but it is off so you cancel the dialog and turn it on. Opening the dialog should likely go back to the now-available network printer rather than Save to PDF (If I'm understanding this correctly)

if I open the dialog once, wait for it to figure itself out, then close it, then reopen it, then select the network printer "on purpose", the dialog gets "stuck" and doesn't recover

changedSettings = await this.refreshSettings(printerName, "user-change")

I wonder if that line is throwing and then we never re-enable the form. Likely we'd want to put an error message on the printer input, and leave the form disabled but allow the user to switch to a connected printer still. Seems like a different bug though?

assuming a subsequent call will continue to be slow, we probably need some state to indicate to the user that we're waiting on the OS to give us printer information

I agree here too. Could be nice to show a throbber that we're connecting to a printer after 5 seconds in the non-initializing state. This also makes me wonder if we should add a warning if we've fallen back to the non-default printer in the initialization step

Comment 14

[Tony Davis]

Is it worth retesting this issue under Windows 11 after update KB5066835 is applied, in case it subtly changes your testing results?
Although this is supposed to fix some hanging printing issues with Chrome Based browsers, could there be some common FF coding that comes into play, and might have been fixed or improved with this Microsoft update?
[Browser] Fixed: This update [KB5066835] addresses an issue that caused the print preview screen to stop responding in Chromium-based browsers.