Bug 154148 – Enhance logging

• Component: Web Template Framework
• Status: RESOLVED WONTFIX

[Keith Rollin]

Enhance logging in order to help diagnose in-the-field issues.

cf:
rdar://problem/23836456
rdar://problem/22870338

[Keith Rollin]

Created attachment 271438 [details]
Patch

[Keith Rollin]

Created attachment 271684 [details]
Patch

[WebKit Commit Bot]

Attachment 271684 [details] did not pass style-queue:


ERROR: Source/WTF/wtf/Assertions.h:458:  Multi line control clauses should use braces.  [whitespace/braces] [4]
ERROR: Source/WTF/wtf/Assertions.h:464:  Multi line control clauses should use braces.  [whitespace/braces] [4]
Total errors found: 2 in 71 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Keith Rollin]

Created attachment 271712 [details]
Patch

[WebKit Commit Bot]

Attachment 271712 [details] did not pass style-queue:


ERROR: Source/WTF/wtf/Assertions.h:458:  Multi line control clauses should use braces.  [whitespace/braces] [4]
ERROR: Source/WTF/wtf/Assertions.h:464:  Multi line control clauses should use braces.  [whitespace/braces] [4]
Total errors found: 2 in 71 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Chris Dumez]

Comment on attachment 271712 [details]
Patch

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

Some initial comments. I'll review more deeply later.

> Source/WTF/ChangeLog:12
> +        Always-on logging is implemented in the form of some new macros.

Please don't duplicate the changelog entries. they should refer to specific project changes.

> Source/WTF/wtf/Assertions.cpp:503
> +    ASSERT(timer);

We normally don't take raw pointers in if they are expected to be non-null. This probably should take a WTFTimer& instead.

> Source/WTF/wtf/Assertions.cpp:510
> +bool WTFTimerExceededThreshold(WTFTimer* timer)

We normally don't take raw pointers in if they are expected to be non-null. This probably should take a WTFTimer& instead.

> Source/WTF/wtf/Assertions.cpp:513
> +    if (timer->m_end < 0.0) {

Seems kind of unexpected that this function (given its name) would update timer->m_end, isn't it?

> Source/WTF/wtf/Assertions.cpp:520
> +bool WTFIsSimpleFormat(const char* format)

Can you document with a comment what a "simple" format is?

> Source/WTF/wtf/Assertions.h:43
> +#if USE(OS_LOG)

The ifdefed includes should come after the regular includes, not in the middle of other includes.

> Source/WTF/wtf/Assertions.h:139
> +typedef struct {

isn't the typedef struct a C thing?

> Source/WTF/wtf/Assertions.h:168
> +WTF_EXPORT_PRIVATE void WTFTimerInit(WTFTimer*, double threshold);

We try to use std:chrono these days instead of double to represent times or durations.

> Source/WebCore/html/parser/HTMLDocumentParser.cpp:252
> +    LOG_ALWAYS_TIMER_START(pumpTimer, 0.100);

this 0.100 is not very readable. This is why we use std::chrono for these things.

Also, for theses things we tend to use scope and local variables with "Scope" in the name. e.g.
{
  LogIfSlowerThan logger("blah blah", 100_ms);
  // ...
}

> Tools/TestWebKitAPI/Tests/WTF/Assertions.cpp:35
> +// <samples> * (<samples> + 1), we end up with 146,325,312 tests. If we were to

This seems like a lot. How long does it take to run all these tests. I am working about the extra testing time on the slower bots and possible timeouts.

[Keith Rollin]

(In reply to comment #6)
> Comment on attachment 271712 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=271712&action=review
> 
> Some initial comments. I'll review more deeply later.
> 
> > Source/WTF/ChangeLog:12
> > +        Always-on logging is implemented in the form of some new macros.
> 
> Please don't duplicate the changelog entries. they should refer to specific
> project changes.

OK. I'll rewrite the changelog entries.

> > Source/WTF/wtf/Assertions.cpp:503
> > +    ASSERT(timer);
> 
> We normally don't take raw pointers in if they are expected to be non-null.
> This probably should take a WTFTimer& instead.

There's a comment in Assertions.h saying that the file should be compatible with C. That's why this whole timing facility uses pointers, "typedef struct", and non-member functions. However, as we discussed offline, the utility of the timing functions is questionable, so I'll be taking those out for this check-in.

> > Source/WTF/wtf/Assertions.cpp:510
> > +bool WTFTimerExceededThreshold(WTFTimer* timer)
> 
> We normally don't take raw pointers in if they are expected to be non-null.
> This probably should take a WTFTimer& instead.
> 
> > Source/WTF/wtf/Assertions.cpp:513
> > +    if (timer->m_end < 0.0) {
> 
> Seems kind of unexpected that this function (given its name) would update
> timer->m_end, isn't it?

Taking this out, per above.

> > Source/WTF/wtf/Assertions.cpp:520
> > +bool WTFIsSimpleFormat(const char* format)
> 
> Can you document with a comment what a "simple" format is?

OK.

> > Source/WTF/wtf/Assertions.h:43
> > +#if USE(OS_LOG)
> 
> The ifdefed includes should come after the regular includes, not in the
> middle of other includes.

OK.

> > Source/WTF/wtf/Assertions.h:139
> > +typedef struct {
> 
> isn't the typedef struct a C thing?

Yes, per above. Also, taking out per above.

> > Source/WTF/wtf/Assertions.h:168
> > +WTF_EXPORT_PRIVATE void WTFTimerInit(WTFTimer*, double threshold);
> 
> We try to use std:chrono these days instead of double to represent times or
> durations.

OK. But taking this out, per above.

> > Source/WebCore/html/parser/HTMLDocumentParser.cpp:252
> > +    LOG_ALWAYS_TIMER_START(pumpTimer, 0.100);
> 
> this 0.100 is not very readable. This is why we use std::chrono for these
> things.

OK. But taking this out, per above.

> Also, for theses things we tend to use scope and local variables with
> "Scope" in the name. e.g.
> {
>   LogIfSlowerThan logger("blah blah", 100_ms);
>   // ...
> }

OK. But taking this out, per above.

> > Tools/TestWebKitAPI/Tests/WTF/Assertions.cpp:35
> > +// <samples> * (<samples> + 1), we end up with 146,325,312 tests. If we were to
> 
> This seems like a lot. How long does it take to run all these tests. I am
> working about the extra testing time on the slower bots and possible
> timeouts.

I've toned this down to about 180,000 tests, or about 1% of what it used to be. The tests used to take about 120 second to run, so we should be running in 1-2 seconds now.

[Sam Weinig]

Comment on attachment 271712 [details]
Patch

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

> Source/WebKit2/NetworkProcess/NetworkProcess.cpp:128
> +#if !LOG_ALWAYS_DISABLED
> +    reportResourceUsage();
> +#endif

It seems like it would be better to have this called by the callers of didReceiveMessage, since there are fewer of those.

> Source/WebKit2/Platform/IPC/Connection.h:102
> +#if !LOG_ALWAYS_DISABLED
> +        void reportResourceUsage();
> +
> +    private:
> +        double m_lastReportTime = 0;
> +        struct rusage m_usage = {{0, 0}, {0, 0}, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0};
> +#endif

It seems really odd for this to be on the client.  Client's usually are just used for delegation and notification.  It seems like this should be on the Connection itself and probably abstracted out a bit.  Also, it should be using std::chrono instead of doubles.

[Keith Rollin]

Thanks, Sam. I'll look at refactoring.

[Lucas Forschler]

The content of attachment 271438 [details] has been deleted by
    Lucas Forschler <[e-mail]>
who provided the following reason:

yes

The token used to delete this attachment was generated at 2016-02-24 16:51:00 PST.

[Lucas Forschler]

The content of attachment 271712 [details] has been deleted by
    Lucas Forschler <[e-mail]>
who provided the following reason:

yes

The token used to delete this attachment was generated at 2016-02-24 16:51:20 PST.

[Lucas Forschler]

The content of attachment 271684 [details] has been deleted by
    Lucas Forschler <[e-mail]>
who provided the following reason:

yes

The token used to delete this attachment was generated at 2016-02-24 16:51:52 PST.

[Keith Rollin]

I don't remember what this was about. I don't have any local work towards this.