Skip to content

Installer's syslog reader holds setupapi.dev.log open, adding ~37s to every SetupAPI call during install #369

Description

@bideco

Summary

The installer runs syslog_reader_thread(), which opens %WINDIR%\inf\setupapi.dev.log with GENERIC_READ and holds the handle for the installer's entire lifetime in order to tail it and relay lines back as IC_SYSLOG_MESSAGE.

Windows file-sharing conflicts are bidirectional, so that lingering read handle collides with SetupAPI's own writes to the same log from the same process. Every SetupAPI call that closes a text-log section then sleep-retries until an internal timeout expires, roughly 37 seconds per call.

During a driver install this happens at least twice per device interface (once in SetupCopyOEMInf, once in the DIF_INSTALLDEVICE class-installer call), so a three-interface composite device takes about 170 seconds instead of about 10.

In short: the installer's debug-log tailing stalls the installer's own driver install.

Root cause

libwdi/installer.c, in syslog_reader_thread():

char* syslog_name[NB_SYSLOGS] = { "\inf\setupapi.dev.log", "\setupapi.log", "\setupact.log" };
...
log_handle = CreateFileA(log_path, GENERIC_READ, FILE_SHARE_READ|FILE_SHARE_WRITE,
    NULL, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, NULL);

The share mode permits other writers, but the conflict runs the other way. When SetupAPI opens the log for its own write, through its internal text-log path:

SetupCopyOEMInfW -> pSetupCloseTextLogSection -> TextLogMapFile
                 -> pSetupOpenFileForWrite -> _pSpUtilsCreateFile -> SleepEx

with a share mode that excludes readers, the still-open GENERIC_READ handle causes a sharing violation. _pSpUtilsCreateFile then retries with SleepEx until its retry budget is exhausted, and only then proceeds.

That retry budget is what produces the eerily constant timing: it is a timeout, not work.

Evidence

SetupCopyOEMInfW timed standalone on Windows 11, same package, same device, varying only whether libwdi's handle is held:

Conditions Time
log handle free 0.20 - 0.28 s
holding libwdi's exact handle (GENERIC_READ, FILE_SHARE_READ|FILE_SHARE_WRITE) 37.38 s

This matches what the installer measures internally (GetTickCount brackets around the calls), before and after removing the reader:

Call Before After
SetupCopyOEMInf 37,532 ms 453 ms
DIF_INSTALLDEVICE 37,172 ms 94 ms

Sysinternals handle.exe, polled every 400 ms during a real install, shows the installer process holding C:\Windows\INF\setupapi.dev.log continuously for the whole ~52 s of the operation. Nothing else on the system ever holds it.

Two SetupCopyOEMInfW calls made inside a single held window each pay the cost independently (37,387 ms and 37,406 ms), so the retry budget is per log-section-close rather than once per process. That is why both call sites are affected rather than just the first.

Ruled out along the way, with direct evidence: Windows Defender (fully disabled, including real-time and behaviour monitoring, verified by the absence of Antimalware scan events in an ETW trace), network paths, the setupapi LogLevel registry value, DriverStore size, device presence, CopyStyle, and holding an open HDEVINFO on the target device. None of them change the timing. Only the log handle does.

Reproduction

No libwdi build required, and nothing needs to be installed on a real device:

  1. Generate any WinUSB package for a VID/PID that no present device matches, so nothing can bind:
    wdi-simple.exe --vid 0xF00D --pid 0xBEEF --extract --dest out
  2. Time SetupCopyOEMInfW on out\...\*.inf. Expect roughly 0.2 s.
  3. In the same process, open the log and hold it:
    CreateFileW(L"C:\Windows\INF\setupapi.dev.log", GENERIC_READ, FILE_SHARE_READ|FILE_SHARE_WRITE, NULL, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, NULL)
  4. Time the same SetupCopyOEMInfW call again. Expect roughly 37 s.

Delete the staged package afterwards (pnputil /delete-driver oemNN.inf).

Impact

Any libwdi-based tool (Zadig, QMK Toolbox, and others) pays roughly 37 s per SetupAPI text-log section close during a driver install on machines where this reproduces. It presents as "driver installation is extremely slow" with no CPU and no disk activity, which makes it very easy to misattribute to the DriverStore, to antivirus, or to the machine itself. I spent a long time chasing exactly those false leads before measuring the API in isolation.

Suggested fix

The reader does not need to hold the handle across the install. Options, roughly in order of preference:

  1. Open, read, and close per poll, instead of holding the handle for the thread's lifetime. This keeps the feature and removes the conflict.
  2. Close the handle before the install operations and reopen afterwards.
  3. Make the syslog reader opt-in.

I took the blunt route downstream and compiled the reader out, since I do not need the relay, but option 1 should preserve the feature for everyone else.

Environment

  • Windows 11, build 10.0.22631
  • libwdi at commit 30df0c0 (2025-07-17)
  • Reproduced with both a stock installer and a locally patched one; the patch does not touch the syslog reader or the call sites involved.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions