Undefined trace event when calling from inside Blink

[Carlos Knippschild]

Hello.

I'm trying to call one of the tracing macros from third_party/WebKit/Source/core/frame/FrameSerializer.cpp but I'm getting an error due to the internal macro being undefined:

In file included from ../../third_party/WebKit/Source/platform/TraceEvent.h:34:0,

                 from ../../third_party/WebKit/Source/core/inspector/InspectorTraceEvents.h:11,

                 from ../../third_party/WebKit/Source/core/layout/SubtreeLayoutScope.h:34,

                 from ../../third_party/WebKit/Source/core/layout/LayoutObject.h:37,

                 from ../../third_party/WebKit/Source/core/layout/LayoutBoxModelObject.h:30,

                 from ../../third_party/WebKit/Source/core/layout/LayoutBox.h:27,

                 from ../../third_party/WebKit/Source/core/layout/LayoutReplaced.h:26,

                 from ../../third_party/WebKit/Source/core/layout/LayoutPart.h:27,

                 from ../../third_party/WebKit/Source/core/layout/api/LayoutPartItem.h:8,

                 from ../../third_party/WebKit/Source/core/frame/Frame.h:33,

                 from ../../third_party/WebKit/Source/core/frame/LocalFrame.h:33,

                 from ../../third_party/WebKit/Source/core/frame/FrameSerializer.cpp:56:

../../third_party/WebKit/Source/core/frame/FrameSerializer.cpp: In member function 'void blink::FrameSerializer::serializeFrame(const blink::LocalFrame&)':

../../third_party/WebKit/Source/platform/TraceEventCommon.h:378:15: error: 'INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP' was not declared in this scope

       arg2_val)

               ^

../../third_party/WebKit/Source/core/frame/FrameSerializer.cpp:321:13: note: in expansion of macro 'TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP2'

             TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP2(

             ^

Searching for definitions of that macro I can see it is defined for Skia and V8, for which the base tracing macros were also made available (through a copy of trace_event_common.h). So I'm guessing this specific implementation is missing for Blink? How should I proceed to get this fixed/working?

Note: other tracing macros do work correctly inside Blink.

Thanks!

[Primiano Tucci]

Looks like the INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP definition is missing in the shadow-copy of the macros in third_party/WebKit/Source/platform/TraceEvent.h.

Long reasons for the presence of that file , mostly due to the legacy of blink being a separate project back then + the fact that base cannot be directly included everywhere in blink.

The reason why you are hitting this is because you are the first one trying to use a macro with copy + id + tid override + timestamp override in blink. You just found out that it has never been plumbed through.

What is the trace macro you are trying to use (a link to the CL would help)?

My question here is: do you *really* need an event with ID, TID and timestamp? (read: do you really need to override the TID and the timestamp?) If not might be just easier to use a simpler macro.

If yes, let's fix platform/TraceEvent.h.

--
--
Chromium Developers mailing list: chromi...@chromium.org
View archives, change email options, or unsubscribe:
http://groups.google.com/a/chromium.org/group/chromium-dev

[Carlos Knippschild]

What I needed was a call for a single scope (no async) that allowed me to set the begin timestamp. This combination was not available so I chose the closer to that I could find.

No CL uploaded yet. I'm adding tracing to the iterations of the for loop in FrameSerializer::serializeFrame but I'd like to only create a trace if the element was actually serialized (only known at the iteration end). So I would store the timestamp at the beginning and call a timestamp-enabled macro only if a serialization occurred. 

[Carlos Knippschild]

Side question: given the increasing number of tracing options and parameters, is there another way of doing things that does not rely on creating new macros for each combination?

[Primiano Tucci]

+oysteine who knows more than anybody else about the tracing macros.

> Side question: given the increasing number of tracing options and parameters, is there another way of doing things that does not rely on creating new macros for each combination?

You mean in blink or in general?

Not sure what is the state in blink about allowing including //base, I think that might not happen too soon.

Unfortunately without that we have to do these hops.

> Side question: given the increasing number of tracing options and parameters, is there another way of doing things that does not rely on creating new macros for each combination?

I think the short answer is: not easily. Eventually it's something we can reconsider after bit.ly/TracingV2, which is absorbing most of the tracing-refactoring bandwidth right now.

Probably we can come up with something smarter now that we have variadic templates and blink is merged. But can't want to avoid moving too many pieces at the same time.

Going back to the original question, I think one option is backporting TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 taking inspiration from the already-backported TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0

It seems that INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP  is already there in platform/TraceEvent.h so you are just missing the wrapper macro. 

[Xianzhu Wang]

On Thu, Sep 15, 2016 at 12:12 PM, Primiano Tucci <prim...@chromium.org> wrote:

+oysteine who knows more than anybody else about the tracing macros.

> Side question: given the increasing number of tracing options and parameters, is there another way of doing things that does not rely on creating new macros for each combination?

You mean in blink or in general?

Not sure what is the state in blink about allowing including //base, I think that might not happen too soon.

Unfortunately without that we have to do these hops.

We already allow including base/trace_event.h from Source/platform (https://cs.chromium.org/chromium/src/third_party/WebKit/Source/platform/DEPS?l=24), so I think we can include base/trace_event.h from TraceEvent.h and remove most of the code in it as well as EventTracer.

[Xianzhu Wang]

On Thu, Sep 15, 2016 at 12:23 PM, Xianzhu Wang <wangx...@chromium.org> wrote:

On Thu, Sep 15, 2016 at 12:12 PM, Primiano Tucci <prim...@chromium.org> wrote:

+oysteine who knows more than anybody else about the tracing macros.

> Side question: given the increasing number of tracing options and parameters, is there another way of doing things that does not rely on creating new macros for each combination?

You mean in blink or in general?

Not sure what is the state in blink about allowing including //base, I think that might not happen too soon.

Unfortunately without that we have to do these hops.

We already allow including base/trace_event.h from Source/platform (https://cs.chromium.org/chromium/src/third_party/WebKit/Source/platform/DEPS?l=24), so I think we can include base/trace_event.h from TraceEvent.h and remove most of the code in it as well as EventTracer.

 

I'm working on this.

[Oystein Eftevaag]

That's great, thank you!

Yes, there's definitely elements of combinatorial explosion with the current trace macros. We kicked around a prototype CL for addressing those issues within the existing macros at some point, but TracingV2 with protos supersedes it and is what we should wait for to get a proper solution in place.

[Carlos Knippschild]

Great to know an improvement is coming. And thanks Xianzhu for getting on solving the immediate issue. 

[Jeremy Roman]

On Thu, Sep 15, 2016 at 4:29 PM, Xianzhu Wang <wangx...@chromium.org> wrote:

On Thu, Sep 15, 2016 at 12:23 PM, Xianzhu Wang <wangx...@chromium.org> wrote:

On Thu, Sep 15, 2016 at 12:12 PM, Primiano Tucci <prim...@chromium.org> wrote:

+oysteine who knows more than anybody else about the tracing macros.

> Side question: given the increasing number of tracing options and parameters, is there another way of doing things that does not rely on creating new macros for each combination?

You mean in blink or in general?

Not sure what is the state in blink about allowing including //base, I think that might not happen too soon.

Unfortunately without that we have to do these hops.

We already allow including base/trace_event.h from Source/platform (https://cs.chromium.org/chromium/src/third_party/WebKit/Source/platform/DEPS?l=24),

FWIW, that's there to allow access to the non-macro bits, like TracedValue and ConvertableToTraceFormat. For the moment, you shouldn't include base/trace_event/trace_event.h in Blink, because you will get compile errors arising from conflicts between it and the platform/TraceEvent.h.

(At least until platform/TraceEvent.h ceases to exist.)

[Xianzhu Wang]

Currently, TraceEvent.h defines public and internal trace event macros and defines underlying api macros (supporting the public and internal macros) which call EventTracer functions which then call base::trace_event functions.

My plan is to remove the redefined macros and include trace_event.h directly from TraceEvent.h so that the chromium macros can be used by blink code. I also need to: 1. let blink::TracedValue implement ConvertableToTraceFormat; and 2. define the WTF::CString variation of SetTraceValue().

[Carlos Knippschild]

A few more trace related questions:

• What is the "correct" include when I want to add trace calls to a file I'm working with?
• Are there any guidelines for creating new categories and naming them?
• What's the rule of thumb for choosing if a new tracing category I'm creating should be "disabled-by-default"?

Thanks!

[Primiano Tucci]

On Fri, Sep 16, 2016 at 10:00 PM, Carlos Knippschild <car...@chromium.org> wrote:

• What is the "correct" include when I want to add trace calls to a file I'm working with?

base/trace_event/trace_event.h in chrome/content whatever can use base (% blink)

platform/TraceEvent.h for blink

• Are there any guidelines for creating new categories and naming them?

Hmm not that I am aware of. Be reasonable and if possible reuse an existing one? 

• What's the rule of thumb for choosing if a new tracing category I'm creating should be "disabled-by-default"?

It's a tradeoff between how much useful that category will be to debug general perf issues vs how much that's a more specific drill-down feature.

Another important factor is the spamminess: if your category is spammy is very likely a no-go for the enabled-by-default section. If you want some reference data you can take a look to the "tracing.tracing_with_debug_overhead" benchmark in chromeperf.appspot.com (example). That benchmark keeps track of the tracing spammyness on some popular website and will generate an alert if you add a category which is too spammy. Also is a good way to get an impression of the current state of things.

[Carlos Knippschild]

I included platform/TraceEvent.h into third_party/WebKit/Source/web/WebFrameSerializer.cpp and got this error when building for some platforms but not for others (while building for Android locally it did work):

../../third_party/WebKit/Source/platform/TraceEvent.h:498:5: error: call to 'setTraceValue' is ambiguous

    setTraceValue(arg1Val, &argTypes[0], &argValues[0]);

    ^~~~~~~~~~~~~

../../third_party/WebKit/Source/platform/TraceEvent.h:571:12: note: in instantiation of function template specialization 'blink::TraceEvent::addTraceEvent<unsigned long>' requested here

    return addTraceEvent(phase, categoryEnabled, name, scope, id,

           ^

../../third_party/WebKit/Source/web/WebFrameSerializer.cpp:225:5: note: in instantiation of function template specialization 'blink::TraceEvent::addTraceEvent<unsigned long>' requested here

    TRACE_EVENT_END1("page-serialization", "WebFrameSerializer::generateMHTMLParts serializing",

    ^

(...)

This happened because I was adding the value of Vector::size() as an argument to that TRACE_EVENT_END1 call, which is of the standard type size_t. Switching to include base/trace_event/trace_event.h made it build successfully but that is still a forbidden import. For now my fix is to static cast to unsigned long long which is the type finally accepted by the setTraceValue functions defined in TraceEvent.h.

Xianzhu, I'm guessing your patch would fix this as well?

[Xianzhu Wang]

On Fri, Sep 16, 2016 at 5:46 PM, Carlos Knippschild <car...@chromium.org> wrote:

I included platform/TraceEvent.h into third_party/WebKit/Source/web/WebFrameSerializer.cpp and got this error when building for some platforms but not for others (while building for Android locally it did work):

../../third_party/WebKit/Source/platform/TraceEvent.h:498:5: error: call to 'setTraceValue' is ambiguous

    setTraceValue(arg1Val, &argTypes[0], &argValues[0]);

    ^~~~~~~~~~~~~

../../third_party/WebKit/Source/platform/TraceEvent.h:571:12: note: in instantiation of function template specialization 'blink::TraceEvent::addTraceEvent<unsigned long>' requested here

    return addTraceEvent(phase, categoryEnabled, name, scope, id,

           ^

../../third_party/WebKit/Source/web/WebFrameSerializer.cpp:225:5: note: in instantiation of function template specialization 'blink::TraceEvent::addTraceEvent<unsigned long>' requested here

    TRACE_EVENT_END1("page-serialization", "WebFrameSerializer::generateMHTMLParts serializing",

    ^

(...)

This happened because I was adding the value of Vector::size() as an argument to that TRACE_EVENT_END1 call, which is of the standard type size_t. Switching to include base/trace_event/trace_event.h made it build successfully but that is still a forbidden import. For now my fix is to static cast to unsigned long long which is the type finally accepted by the setTraceValue functions defined in TraceEvent.h.

Xianzhu, I'm guessing your patch would fix this as well?

Yes. The blink version of setTraceValue will go away.

[Xianzhu Wang]

https://codereview.chromium.org/2341333003/ is almost working, except one thing: an inspector layout test fails with the CL.

After investigation, I found that it's because we pass different types of timestamps to TRACE_EVENT_XXX_WITH_TIMESTAMP macros in chromium and blink. In chromium, timestamps are int64_t in microseconds passed to base::TimeTicks::fromIntervalValue(). In blink, timestamps are double in seconds passed to base::TimeTicks::fromSecondsD(). With the CL which doesn't handle the difference, blink timestamps passed to chromium trace event macros are implicitly converted to int64_t and are incorrectly interpreted as microseconds.

I thought of the following methods:

1. Modify each callsite of TRACE_EVENT_XXX_WITH_TIMESTAMP in blink to convert the blink timestamp into int64_t in microseconds (maybe with a helper function in TraceEvent.h). This method is the simplest but can't ensure the modification is complete, and can't prevent future errors.

2. Do 1, and add the following in base::TimeTicks and base::TimeDelta:

   static TimeTicks|TimeDelta FromInternalValue(double) = delete;

to forbid implicit conversion from double to int64_t. This adds extra restrictions to the original base::TimeTicks and base::TimeDelta API, and requires explicit type modifier or cast when passing a literal integral number to the constructors to avoid ambiguity.

3. Let TRACE_EVENT_XXX_WITH_TIMESTAMP macros accept only base::TimeTicks for timestamps, and add a helper function in blink's TraceEvent.h for blink code to convert double timestamps into base::TimeTicks. This seems clean, but requires modification of all usages of TRACE_EVENT_XXX_WITH_TIMESTAMP macros in chromium and blink.

For now I'm inclined to choose 3. Wdyt?

[Carlos Knippschild]

3. seems a cleaner solution for me too but IDK if we want to tie tracing with our time classes. It will require changes to many files that use those functions but less than 30 (some of them are just the trace base files themselves).

Wouldn't another option be to do 1. and also add a trace macro/function (I'm not sure) specific to handle double timestamp values but make it generate a compilation error? This would avoid future wrong usage in Blink and would not require explicit casts when creating TimeTicks|TimeDelta from integers. Is this even possible?

[Xianzhu Wang]

https://codereview.chromium.org/2359503002/ is the CL for 3, after 1 is first implemented in https://codereview.chromium.org/2341333003/. The changed files are not too many (though there will be more unittest files to fix the complication errors). The CL also simplifies call sites because TimeTicks is already used everywhere in chromium. Blink code needs TraceEvent::toTraceTimestamp() to convert a blink timestamp to TimeTicks. A 'void toTraceTimestamp(int64_t)' function prototype is declared to avoid wrong usages in blink.

[Oystein Eftevaag]

+1 for option 3. Tracing is already internally tied to base::TimeTickets and as long as trace_event_common.h doesn't include anything else from base/, we should be good.