Bug 183065 - Introduce ITP debug logging as an opt-in developer feature
Summary: Introduce ITP debug logging as an opt-in developer feature
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: WebKit Misc. (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: John Wilander
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2018-02-22 15:07 PST by John Wilander
Modified: 2018-02-23 15:26 PST (History)
8 users (show)

See Also:


Attachments
Patch (9.44 KB, patch)
2018-02-22 15:15 PST, John Wilander
no flags Details | Formatted Diff | Diff
Patch (10.30 KB, patch)
2018-02-23 12:54 PST, John Wilander
no flags Details | Formatted Diff | Diff
Patch (9.84 KB, patch)
2018-02-23 14:45 PST, John Wilander
bfulgham: review+
bfulgham: commit-queue-
Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description John Wilander 2018-02-22 15:07:02 PST
We should allow developers to opt in to ITP debug logging on the INFO level.
Comment 1 John Wilander 2018-02-22 15:07:17 PST
<rdar://problem/37803761>
Comment 2 John Wilander 2018-02-22 15:15:28 PST
Created attachment 334481 [details]
Patch
Comment 3 John Wilander 2018-02-23 12:54:36 PST
Created attachment 334543 [details]
Patch
Comment 4 Keith Rollin 2018-02-23 13:08:37 PST
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
Comment 5 John Wilander 2018-02-23 13:48:40 PST
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.
Comment 6 John Wilander 2018-02-23 14:45:09 PST
Created attachment 334548 [details]
Patch
Comment 7 Brent Fulgham 2018-02-23 14:51:47 PST
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;
}
Comment 8 John Wilander 2018-02-23 15:22:21 PST
Thanks, Brent! I will fix the duplicated code.
Comment 9 John Wilander 2018-02-23 15:26:42 PST
Committed r228967: <https://trac.webkit.org/changeset/228967>