Bug 183065 – Introduce ITP debug logging as an opt-in developer feature

• Status: RESOLVED
• Resolution: FIXED
• Component: WebKit Misc.

[John Wilander]

We should allow developers to opt in to ITP debug logging on the INFO level.

[John Wilander]

<rdar://problem/37803761>

[John Wilander]

Created attachment 334481 [details]
Patch

[John Wilander]

Created attachment 334543 [details]
Patch

[Keith Rollin]

Comment on attachment 334543 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=334543&action=review

> Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:223
> +        StringBuilder domainsToRemoveDataRecordsForBuilder;
> +        domainsToRemoveDataRecordsForBuilder.appendLiteral("About to remove data records for ");
> +        bool firstDomain = true;
> +        for (auto& domain : prevalentResourceDomains) {
> +            if (firstDomain)
> +                firstDomain = false;
> +            else
> +                domainsToRemoveDataRecordsForBuilder.appendLiteral(", ");
> +            domainsToRemoveDataRecordsForBuilder.append(domain);
> +        }
> +        domainsToRemoveDataRecordsForBuilder.appendLiteral(".");
> +        RELEASE_LOG_INFO(ResourceLoadStatisticsDebug, "%s", domainsToRemoveDataRecordsForBuilder.toString().utf8().data());

It's probably not an issue in little-used debugging code, but it's better to put as much as possible in the format string, as it takes up less room in the logarchive file. That is specify "About to remove data records for %s" instead of just "%s".

Also, if you want to collect these strings on external devices, you should specify "%{public}s". Otherwise, the "%s" collects the string only on internal builds. On external builds, "%s" is replaced with "<PRIVATE>" or some such.

> Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:239
> +                RELEASE_LOG_INFO_IF(m_debugLoggingEnabled, ResourceLoadStatisticsDebug, "Done removing data records.");

I don't know if it's relevant in this context, but it's sometimes a good idea to include some kind of token in the logging so that you can tie together related logging that occurs at different times. Especially if there could be multiple threads logging at the same time and interleaving their output. For instance, provide the address of the object doing the logging, or something like the page/frame/resource IDs used in resource loading.

> Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:967
> +            RELEASE_LOG_INFO(ResourceLoadStatisticsDebug, "%s", domainsToPartitionBuilder.toString().utf8().data());

Ditto as for the previous block of logging under m_debugLoggingEnabled.

> Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:982
> +            RELEASE_LOG_INFO(ResourceLoadStatisticsDebug, "%s", domainsToBlockBuilder.toString().utf8().data());

Ditto

> Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:997
> +            RELEASE_LOG_INFO(ResourceLoadStatisticsDebug, "%s", domainsToNeitherPartitionNorBlockBuilder.toString().utf8().data());

Ditto

[John Wilander]

Thanks, Keith! See inline below.

(In reply to Keith Rollin from comment #4)
> Comment on attachment 334543 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=334543&action=review
> 
> > Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:223
> > +        StringBuilder domainsToRemoveDataRecordsForBuilder;
> > +        domainsToRemoveDataRecordsForBuilder.appendLiteral("About to remove data records for ");
> > +        bool firstDomain = true;
> > +        for (auto& domain : prevalentResourceDomains) {
> > +            if (firstDomain)
> > +                firstDomain = false;
> > +            else
> > +                domainsToRemoveDataRecordsForBuilder.appendLiteral(", ");
> > +            domainsToRemoveDataRecordsForBuilder.append(domain);
> > +        }
> > +        domainsToRemoveDataRecordsForBuilder.appendLiteral(".");
> > +        RELEASE_LOG_INFO(ResourceLoadStatisticsDebug, "%s", domainsToRemoveDataRecordsForBuilder.toString().utf8().data());
> 
> It's probably not an issue in little-used debugging code, but it's better to
> put as much as possible in the format string, as it takes up less room in
> the logarchive file. That is specify "About to remove data records for %s"
> instead of just "%s".

Will fix.

> Also, if you want to collect these strings on external devices, you should
> specify "%{public}s". Otherwise, the "%s" collects the string only on
> internal builds. On external builds, "%s" is replaced with "<PRIVATE>" or
> some such.

Oh, that makes sense. Will fix.

> > Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:239
> > +                RELEASE_LOG_INFO_IF(m_debugLoggingEnabled, ResourceLoadStatisticsDebug, "Done removing data records.");
> 
> I don't know if it's relevant in this context, but it's sometimes a good
> idea to include some kind of token in the logging so that you can tie
> together related logging that occurs at different times. Especially if there
> could be multiple threads logging at the same time and interleaving their
> output. For instance, provide the address of the object doing the logging,
> or something like the page/frame/resource IDs used in resource loading.

I have come across such issues in previous jobs. However, these log statements are all from the central Resource Load Statistics Store in the UI process so they should not be confusing. Maybe across SafariViewController and Safari on iOS, or across Safari Technology Preview and Safari on macOS.

> > Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:967
> > +            RELEASE_LOG_INFO(ResourceLoadStatisticsDebug, "%s", domainsToPartitionBuilder.toString().utf8().data());
> 
> Ditto as for the previous block of logging under m_debugLoggingEnabled.

Will fix.

> > Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:982
> > +            RELEASE_LOG_INFO(ResourceLoadStatisticsDebug, "%s", domainsToBlockBuilder.toString().utf8().data());
> 
> Ditto

Will fix.

> > Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:997
> > +            RELEASE_LOG_INFO(ResourceLoadStatisticsDebug, "%s", domainsToNeitherPartitionNorBlockBuilder.toString().utf8().data());
> 
> Ditto

Will fix.

[John Wilander]

Created attachment 334548 [details]
Patch

[Brent Fulgham]

Comment on attachment 334548 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=334548&action=review

Looks good, but please reduce the duplicated code as I suggested.

> Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:43
>  #include <wtf/NeverDestroyed.h>

You could #if !RELEASE_LOG_DISABLED this header include, which might help build perf for non-logging builds.

> Source/WebKit/UIProcess/WebResourceLoadStatisticsStore.cpp:219
> +            domainsToRemoveDataRecordsForBuilder.append(domain);

You repeat this pattern a bunch of times. I suggest making it a static function:

static void appendWithDelimiter(StringBuilder& builder, const String& domain, bool firstItem)
{
    if (!firstItem)
        builder.appendLiteral(", ");
    builder.append(domain);
}

Then this code would be:

StringBuilder domainsToRemoveDataRecordsForBuilder;
bool firstDomain = true;
for (auto& domain : prevalentResourceDomains) {
    appendWithDelimiter(domainsToRemoveDataRecordsForBuilder, domain, firstDomain);
    firstDomain = false;
}

[John Wilander]

Thanks, Brent! I will fix the duplicated code.

[John Wilander]

Committed r228967: <https://trac.webkit.org/changeset/228967>