New issue
Advanced search Search tips

Issue 914067 link

Starred by 2 users

Issue metadata

Status: Assigned
Owner:
Cc:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

Potential jank caused by third party block

Project Member Reported by etienneb@chromium.org, Dec 11

Issue description

From this slow-report: e982f244369dfc4b

There is a 40 seconds jank on the main thread.

1) The main thread is receiving an user input. [normal priority]
2) The background thread is running third party blocking code [lower priority]

They are aligned. Which is telling us 2) is probably blocking 1)

The sampling profiler is telling us that the main thread is block here:

NtWaitForSingleObject
 RtlpWaitOnCriticalSection
 RtlpEnterCriticalSectionContended
 LdrResolveDelayLoadedAPI
 _delayLoadHelper2
 _tailMerge_OLEAUT32_dll
 NdrpUserMarshalUnmarshall(_MIDL_STUB_MESSAGE *,unsigned char *,unsigned char const *)
 NdrUserMarshalUnmarshall
 NdrpServerUnMarshal
 NdrStubCall2
 NdrStubCall3
 CreateForwardProcBuffer
 NdrDcomAsyncStubCall
 CCtxComChnl::ContextInvoke(tagRPCOLEMESSAGE *,IRpcStubBuffer *,tagIPIDEntry *,unsigned long *)
 NdrpSetupBeginStubCall
 NdrpBeginDcomAsyncClientCall
 ThreadWndProc(HWND__ *,unsigned int,unsigned __int64,__int64)
 UserCallWinProcCheckWow
 DispatchMessageWorker
 base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &)
 base::MessagePumpForUI::DoRunLoop()
 base::MessagePumpWin::Run(base::MessagePump::Delegate *)
 base::RunLoop::Run()
 ChromeBrowserMainParts::MainMessageLoopRun(int *)
 content::BrowserMainLoop::RunMainMessageLoopParts()
 content::BrowserMainRunnerImpl::Run()
 content::BrowserMain(content::MainFunctionParams const &)
 content::RunBrowserProcessMain(content::MainFunctionParams const &,content::ContentMainDelegate *)
 content::ContentMainRunnerImpl::RunServiceManager(content::MainFunctionParams &,bool)
 content::ContentMainRunnerImpl::Run(bool)
 service_manager::Main(service_manager::MainParams const &)
 content::ContentMain(content::ContentMainParams const &)
 ChromeMain
 MainDllLoader::Launch(HINSTANCE__ *,base::TimeTicks)
 wWinMain
 __scrt_common_main_seh
 BaseThreadInitThunk
 RtlUserThreadStart
 
third_party1.png
50.3 KB View Download
third_party2.png
34.8 KB View Download
third_party3.png
68.7 KB View Download
The task that seems to be blocking the main thread is CreateExeCertificateInfo(), which uses Windows' Crypto API to check the certificate of chrome.exe
crash/212164b4cdaac644 shows a similar problem. The main thread is stuck in a delay load while a background worker is running this task:
  src_file "../../chrome/browser/conflicts/third_party_conflicts_manager_win.cc"
  src_func "ThirdPartyConflictsManager"
This confirms what we suspected: it's possible for the background priority thread to end up grabbing the loader lock at the same time that a higher priority thread wants it. In this case, the first module being inspected wants to delay load crypt32.dll, and the foreground thread wants to do something that also needs to load a module.

I think the best thing here is to move module inspection out to a utility process.
See the attached plot for a breakdown of time spent in LdrResolveDelayLoadedAPI at startup across the population in canary.

Summary:
~250ms @ 99th percentile
2.1s @ 99.9th percentile
11s @ 99.99th percentile
LdrResolveDelayLoadedAPI.png
75.4 KB View Download
Cc: etienneb@chromium.org
Owner: fdoray@chromium.org
Status: Assigned (was: Untriaged)
@fdoray is going to add instrumentation to try to estimate the number of callsites where this is problematic (where a DLL Load is happening on a background thread).
The initial analysis mentions two threads and their priorities:

1) The main thread is receiving an user input. [normal priority]
2) The background thread is running third party blocking code [lower priority]

However it's not clear that the priorities are relevant. Since the main thread is blocked it is not using any CPU time so its priority is not relevant. The priority of the background thread is only relevant if some third (and fourth, assuming a two-core system) thread is consuming lots of CPU time. We don't know if that is happening or if the background DLL load is just inherently time consuming.

Isn't this the real problem? This seems like too heavy-weight an operation to be doing on the main thread.
> The task that seems to be blocking the main thread is CreateExeCertificateInfo()

And isn't this the real solution?
> I think the best thing here is to move module inspection out to a utility process.

Given that a DLL load implies disk I/O don't we want to see how often we are doing a DLL load on the *main* thread?
> (where a DLL Load is happening on a background thread).

Sign in to add a comment