1838542 - Reduce nsXREDirProvider::GetFile() warning spam

Status: VERIFIED FIXED

(Core :: XPCOM, defect)

Description

[Andrew McCreight [:mccr8] (PTO until 12-2)]

Looking at log-spam-hell report from a recent Linux 64 debug run, by far the most common warning is "WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file toolkit/xre/nsXREDirProvider.cpp:475", with over 800,000 instances. The next most common (bug 1838468, which just had a patch landed) is about 390,000, and the next after that is only around 190,000.

With some debugging, it looks like the major source of this spam is that when looking up a property, nsDirectoryService::Get() spams every provider it has trying to find it, and nsXREDirProvider::GetFile() warns when it can't find something.

There are two kinds of failures that seem to cause most or all of the warnings from these calls in nsDirectoryService::Get():

1. There are a bunch of properties that nsXREDirProvider::GetFile() doesn't know about at all. The most common are "XCurProcD", "CurWorkD", "TmpD", but there are also less frequent things like "indexedDBPDir" and "cachePDir".
2. "ProfLD", "ProfD", "ProfLDS" and "ProfDS" are profile directories. These aren't defined in child processes, so they warn and produce a failure.

I'd say the first case is about 10 times more common than the second, but they are both very frequent, at least from what I'm seeing when running a single Mochitest directory (js/xpconnect/tests/mochitest/) locally.

In my patch, I make the two common cases above fail without warning (when mProfileLocalDir or mProfileDir are null, or when the property is unknown). This eliminates all warnings in this function when I run js/xpconnect/tests/mochitest/ locally. I'll do a try push and see what it looks like across an entire Linux64 debug test run.

More broadly, it seems like a bad idea to funnel most (but not all) of the possible points of failure in nsXREDirProvider::GetFile() into a single warning. If the caller cares about whether the entire GetFile() call fails, they can do the warning themselves. To debug the warning spam, I had to add my own logging, because the sole NS_WARNING was not useful in figuring out what was going on. (The other implementations of nsIDirectoryServiceProvider::GetFile() don't look like they warn any time there is a failure.) I kind of want to change that, but it is a bit of a judgment call and is kind of partially undoing the changes from bug 1799470, so I'll worry about that in a separate bug.

It looks like this function was changed to add a warning in bug 1799470, so technically this is a regression, but it only affects log spam in debug builds.

Comment 1

[Andrew McCreight [:mccr8] (PTO until 12-2)]

Attachment: Bug 1838542 - Eliminate the most common warning spam from nsXREDirProvider::GetFile().

Currently, this function warns any time it fails to return something.
However, this warning happens extremely frequently in two cases:
when the property is unknown or when somebody tries to get a
profile directory in a child process.

This patch eliminates those. It also consolidates some profile
cases. Hopefully an additional 2 strcmps on common cases won't
matter.

Comment 2

[Andrew McCreight [:mccr8] (PTO until 12-2)]

Looking at a try run, this reduces this warning to the point where they are not in the top 100 any more. There are still two different warnings in this file in the top 100, in different places (one from the same function), accounting for around 12,000 instances.

Comment 3

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a0dc8dc759b3
Eliminate the most common warning spam from nsXREDirProvider::GetFile(). r=xpcom-reviewers,jstutte

Comment 4

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/a0dc8dc759b3

Comment 5

[Andrew McCreight [:mccr8] (PTO until 12-2)]

I confirmed that this is mostly gone, aside from the two things mentioned in comment 2. It looks like that's a single issue so I'll file a followup.

Comment 6

[Ryan VanderMeulen [:RyanVM]]

I think this might be worth an ESR115 approval request in the interest of avoiding logspam there for the next year+? :-)

Comment 7

[Andrew McCreight [:mccr8] (PTO until 12-2)]

Comment on attachment 9339187 [details]
Bug 1838542 - Eliminate the most common warning spam from nsXREDirProvider::GetFile().

ESR Uplift Approval Request

• If this is not a sec:{high,crit} bug, please state case for ESR consideration: The most common source of debug log spam (over a million instances of it in a single Linux64 debug run).
• User impact if declined: none
• Fix Landed on Version: 116
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): This tweaks the behavior a bit, but assuming I didn't mess something up it should only affect debug logging.

Comment 8

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9339187 [details]
Bug 1838542 - Eliminate the most common warning spam from nsXREDirProvider::GetFile().

Approved for 115.0esr.

Comment 9

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr115/rev/5c832bfb4d16