Add events with custom timestamps and thread id to PPAPI dev tracing interface.

Add events with custom timestamps and thread id to PPAPI dev tracing interface.

This exposes the AddTraceEventWithThreadIdAndTimestamp function, which may be
helpful for in-module profiling of NaCl applications.

BUG=none
NOTRY=true

Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=208738

[grosse, 2013-06-21 21:21:37]

dmichael as ppapi OWNER
dsinclair as base/debug OWNER

I am working on profiling in NaCl, and we wanted to integrate this with the dev
tracing interface. Unfortunately, there were worries that calling out on every
event would be too slow, so we were planning to experiment with recording our
own timestamps and batching the calls. This patch exposes the version of the dev
tracing api that allows a timestamp to be provided.

[bradn, 2013-06-21 21:49:17]

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
File ppapi/shared_impl/ppb_trace_event_impl.cc (right):

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.cc:32: const void* category_enabled,
Fix the identation

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.cc:52: const void* category_enabled,
indentation

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.cc:63: ticks +=
base::TimeDelta::FromMicroseconds(timestamp);
I think we're going to need to string through TimeTicks::NowFromSystemTraceTime
as well, because we'll need a way to have access to a matching clock.

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
File ppapi/shared_impl/ppb_trace_event_impl.h (right):

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.h:29: uint8_t flags);
Fix the indentation here.

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.h:30: static void
AddTraceEventWithThreadIdAndTimestamp(int8_t phase,
And here.
See the style guide, you probably wan to wrap these.

https://codereview.chromium.org/17555005/diff/2001/ppapi/tests/test_dev_trace...
File ppapi/tests/test_dev_trace_event.cc (right):

https://codereview.chromium.org/17555005/diff/2001/ppapi/tests/test_dev_trace...
ppapi/tests/test_dev_trace_event.cc:32: const void* cat_enabled =
interface_->GetCategoryEnabled("");
Maybe pass a non-empty?

https://codereview.chromium.org/17555005/diff/2001/ppapi/tests/test_dev_trace...
ppapi/tests/test_dev_trace_event.cc:43:
interface_->AddTraceEventWithThreadIdAndTimestamp('B', cat_enabled, "foo", 0,
Maybe use different name pair (foo, bar)?

[dsinclair, 2013-06-22 01:29:55]

On 2013/06/21 21:21:37, grosse wrote:
> dmichael as ppapi OWNER
> dsinclair as base/debug OWNER
> 
> I am working on profiling in NaCl, and we wanted to integrate this with the
dev
> tracing interface. Unfortunately, there were worries that calling out on every
> event would be too slow, so we were planning to experiment with recording our
> own timestamps and batching the calls. This patch exposes the version of the
dev
> tracing api that allows a timestamp to be provided.

lgtm

[bradn, 2013-06-22 16:09:24]

LGTM

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
File ppapi/tests/test_dev_trace_event.cc (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
ppapi/tests/test_dev_trace_event.cc:44:
interface_->AddTraceEventWithThreadIdAndTimestamp('B', cat_enabled, "foo", 0,
Nit, maybe wrap these from the paren down, so they fit on the following line.

[dmichael (off chromium), 2013-06-24 17:43:42]

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
File ppapi/api/dev/ppb_trace_event_dev.idl (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
ppapi/api/dev/ppb_trace_event_dev.idl:60: [in] int64_t timestamp,
Do you plan to ever pass anything other than Now() here? If not, maybe we should
just omit that param, leave out the Now() function, and have the proxy-side
implementation apply it instead.

[It's a little confusing/weird to have a Now() function on this interface; we
already provide time ticks in another way on PPB_Core. I'd like to avoid adding
a new way.]

https://codereview.chromium.org/17555005/diff/21001/ppapi/ppapi_sources.gypi
File ppapi/ppapi_sources.gypi (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/ppapi_sources.gypi#...
ppapi/ppapi_sources.gypi:406: 'tests/test_dev_trace_event.h',
nit: We don't put "dev" in the name of the test, even for Dev interfaces.

https://codereview.chromium.org/17555005/diff/21001/ppapi/shared_impl/ppb_tra...
File ppapi/shared_impl/ppb_trace_event_impl.cc (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/shared_impl/ppb_tra...
ppapi/shared_impl/ppb_trace_event_impl.cc:48: reinterpret_cast<const unsigned
long long*>(arg_values), NULL, flags);
maybe overkill, but you could COMPILE_ASSERT(sizeof(unsigned long long) ==
sizeof(uint64_t));

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
File ppapi/tests/test_dev_trace_event.cc (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
ppapi/tests/test_dev_trace_event.cc:1: // Copyright (c) 2012 The Chromium
Authors. All rights reserved.
ditto, 2013

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
File ppapi/tests/test_dev_trace_event.h (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
ppapi/tests/test_dev_trace_event.h:1: // Copyright (c) 2012 The Chromium
Authors. All rights reserved.
nit: 2013 on new files

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
ppapi/tests/test_dev_trace_event.h:17: // TestCase implementation.
I slightly prefer making everything from here down private.

[elijahtaylor1, 2013-06-24 21:04:17]

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
File ppapi/api/dev/ppb_trace_event_dev.idl (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
ppapi/api/dev/ppb_trace_event_dev.idl:47: * Adds a trace event to the platform
tracing system. This function call is
This comment is identical to the previous one.  Can you elaborate on why this is
different and why it might be used on the backend of trace_events.h macros
instead of the vanilla one above?

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
ppapi/api/dev/ppb_trace_event_dev.idl:68: * Get the current clock value,
suitable for adding trace events.
It isn't clear from this comment why it is useful to include this in the trace
event API.  Can you elaborate here why it is useful over ordinary time functions
you might have access to?  Or why you need to pass in a timestamp in the first
place?

https://codereview.chromium.org/17555005/diff/21001/ppapi/thunk/interfaces_pp...
File ppapi/thunk/interfaces_ppb_public_dev.h (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/thunk/interfaces_pp...
ppapi/thunk/interfaces_ppb_public_dev.h:52: PROXIED_IFACE(PPB_Instance,
PPB_TRACE_EVENT_DEV_INTERFACE_0_2,
does this mean once you land this change we can no longer query the 0.1
interface?  Would prefer to leave it available in the meantime so everyone
doesn't have to move to the new interface right away when this is submitted.

[grosse, 2013-06-24 23:16:46]

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
File ppapi/shared_impl/ppb_trace_event_impl.cc (right):

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.cc:32: const void* category_enabled,
On 2013/06/21 21:49:18, bradn wrote:
> Fix the identation

Done.

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.cc:52: const void* category_enabled,
On 2013/06/21 21:49:18, bradn wrote:
> indentation

Done.

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.cc:63: ticks +=
base::TimeDelta::FromMicroseconds(timestamp);
On 2013/06/21 21:49:18, bradn wrote:
> I think we're going to need to string through
TimeTicks::NowFromSystemTraceTime
> as well, because we'll need a way to have access to a matching clock.

Added Now() method.

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
File ppapi/shared_impl/ppb_trace_event_impl.h (right):

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.h:29: uint8_t flags);
On 2013/06/21 21:49:18, bradn wrote:
> Fix the indentation here.

Done

https://codereview.chromium.org/17555005/diff/2001/ppapi/shared_impl/ppb_trac...
ppapi/shared_impl/ppb_trace_event_impl.h:30: static void
AddTraceEventWithThreadIdAndTimestamp(int8_t phase,
On 2013/06/21 21:49:18, bradn wrote:
> And here.
> See the style guide, you probably wan to wrap these.

Done

https://codereview.chromium.org/17555005/diff/2001/ppapi/tests/test_dev_trace...
File ppapi/tests/test_dev_trace_event.cc (right):

https://codereview.chromium.org/17555005/diff/2001/ppapi/tests/test_dev_trace...
ppapi/tests/test_dev_trace_event.cc:32: const void* cat_enabled =
interface_->GetCategoryEnabled("");
On 2013/06/21 21:49:18, bradn wrote:
> Maybe pass a non-empty?

Done.

https://codereview.chromium.org/17555005/diff/2001/ppapi/tests/test_dev_trace...
ppapi/tests/test_dev_trace_event.cc:43:
interface_->AddTraceEventWithThreadIdAndTimestamp('B', cat_enabled, "foo", 0,
On 2013/06/21 21:49:18, bradn wrote:
> Maybe use different name pair (foo, bar)?

Ignored

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
File ppapi/api/dev/ppb_trace_event_dev.idl (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
ppapi/api/dev/ppb_trace_event_dev.idl:47: * Adds a trace event to the platform
tracing system. This function call is
On 2013/06/24 21:04:18, elijahtaylor1 wrote:
> This comment is identical to the previous one.  Can you elaborate on why this
is
> different and why it might be used on the backend of trace_events.h macros
> instead of the vanilla one above?

Done.

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
ppapi/api/dev/ppb_trace_event_dev.idl:60: [in] int64_t timestamp,
On 2013/06/24 17:43:42, dmichael wrote:
> Do you plan to ever pass anything other than Now() here? If not, maybe we
should
> just omit that param, leave out the Now() function, and have the proxy-side
> implementation apply it instead.
> 
> [It's a little confusing/weird to have a Now() function on this interface; we
> already provide time ticks in another way on PPB_Core. I'd like to avoid
adding
> a new way.]

We want to make sure that we're using the same clock as the event tracing
interface.

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
ppapi/api/dev/ppb_trace_event_dev.idl:68: * Get the current clock value,
suitable for adding trace events.
On 2013/06/24 21:04:18, elijahtaylor1 wrote:
> It isn't clear from this comment why it is useful to include this in the trace
> event API.  Can you elaborate here why it is useful over ordinary time
functions
> you might have access to?  Or why you need to pass in a timestamp in the first
> place?

Done.

https://codereview.chromium.org/17555005/diff/21001/ppapi/ppapi_sources.gypi
File ppapi/ppapi_sources.gypi (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/ppapi_sources.gypi#...
ppapi/ppapi_sources.gypi:406: 'tests/test_dev_trace_event.h',
On 2013/06/24 17:43:42, dmichael wrote:
> nit: We don't put "dev" in the name of the test, even for Dev interfaces.

Done.

https://codereview.chromium.org/17555005/diff/21001/ppapi/shared_impl/ppb_tra...
File ppapi/shared_impl/ppb_trace_event_impl.cc (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/shared_impl/ppb_tra...
ppapi/shared_impl/ppb_trace_event_impl.cc:48: reinterpret_cast<const unsigned
long long*>(arg_values), NULL, flags);
On 2013/06/24 17:43:42, dmichael wrote:
> maybe overkill, but you could COMPILE_ASSERT(sizeof(unsigned long long) ==
> sizeof(uint64_t));

Done.

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
File ppapi/tests/test_dev_trace_event.cc (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
ppapi/tests/test_dev_trace_event.cc:1: // Copyright (c) 2012 The Chromium
Authors. All rights reserved.
On 2013/06/24 17:43:42, dmichael wrote:
> ditto, 2013

Done.

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
ppapi/tests/test_dev_trace_event.cc:44:
interface_->AddTraceEventWithThreadIdAndTimestamp('B', cat_enabled, "foo", 0,
On 2013/06/22 16:09:25, bradn wrote:
> Nit, maybe wrap these from the paren down, so they fit on the following line.

Done.

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
File ppapi/tests/test_dev_trace_event.h (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
ppapi/tests/test_dev_trace_event.h:1: // Copyright (c) 2012 The Chromium
Authors. All rights reserved.
On 2013/06/24 17:43:42, dmichael wrote:
> nit: 2013 on new files

Done.

https://codereview.chromium.org/17555005/diff/21001/ppapi/tests/test_dev_trac...
ppapi/tests/test_dev_trace_event.h:17: // TestCase implementation.
On 2013/06/24 17:43:42, dmichael wrote:
> I slightly prefer making everything from here down private.

Done.

https://codereview.chromium.org/17555005/diff/21001/ppapi/thunk/interfaces_pp...
File ppapi/thunk/interfaces_ppb_public_dev.h (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/thunk/interfaces_pp...
ppapi/thunk/interfaces_ppb_public_dev.h:52: PROXIED_IFACE(PPB_Instance,
PPB_TRACE_EVENT_DEV_INTERFACE_0_2,
On 2013/06/24 21:04:18, elijahtaylor1 wrote:
> does this mean once you land this change we can no longer query the 0.1
> interface?  Would prefer to leave it available in the meantime so everyone
> doesn't have to move to the new interface right away when this is submitted.

Done.

[nduca, 2013-06-25 07:43:39]

dsinclair can review in my place. this is exciting work, folks. :)

[dmichael (off chromium), 2013-06-25 21:01:56]

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
File ppapi/api/dev/ppb_trace_event_dev.idl (right):

https://codereview.chromium.org/17555005/diff/21001/ppapi/api/dev/ppb_trace_e...
ppapi/api/dev/ppb_trace_event_dev.idl:60: [in] int64_t timestamp,
On 2013/06/24 23:16:46, grosse wrote:
> On 2013/06/24 17:43:42, dmichael wrote:
> > Do you plan to ever pass anything other than Now() here? If not, maybe we
> should
> > just omit that param, leave out the Now() function, and have the proxy-side
> > implementation apply it instead.
> > 
> > [It's a little confusing/weird to have a Now() function on this interface;
we
> > already provide time ticks in another way on PPB_Core. I'd like to avoid
> adding
> > a new way.]
> 
> We want to make sure that we're using the same clock as the event tracing
> interface.
> 
PPB_Core::GetTimeTicks also uses base::TimeTicks::Now(). The only difference is
it converts to PP_TimeTicks (which is a double). Any precision loss will be
minor and won't really matter for trace events. You should just use
PPB_Core::GetTimeTicks and get rid of Now().

[bradn, 2013-06-25 21:21:51]

Robert's actually got the wrong timer function here (which I managed to miss).

The timer I'd intended was:
base::TimeTicks::NowFromSystemTraceTime()

Which returns a very different timer which I don't believe we expose elsewhere?
He's revising the CL to reflect that.

Here's some broader context.

nfullagar has a very low impact profiling tool that we're trying to use data
from (xray). 
The goal is to match up its timing (done using RDTSC) with the chrome://tracing
timer which is different.

Calling the current interface adds at least a factor of 4 slow down whereas nick
just sent us these number for xray:

So single threaded 64-bit voronoi benchmark clocks in as:

no optimizations, debug       --> 11.27sec
-finstrument-functions (i-f)  --> 11.85s
i-f + -O3                     -->  4.23s
just -O3, no i-f ('release')  -->  3.95s
i-f + -O3 while tracing       -->  5.67s

So for this example, -f-f -O3 w/ trace capture (5.67s) falls right between
'debug' (11.27s) and 'release' (3.95s)

Trace buffer up to 16M entries + 2000 frame captures seems good so far.

[grosse, 2013-06-25 21:57:58]

On 2013/06/25 21:21:51, bradn wrote:
> Robert's actually got the wrong timer function here (which I managed to miss).
> 
> The timer I'd intended was:
> base::TimeTicks::NowFromSystemTraceTime()
> 
> Which returns a very different timer which I don't believe we expose
elsewhere?
> He's revising the CL to reflect that.

The CL has now been fixed.

[dmichael (off chromium), 2013-06-25 22:19:27]

lgtm

https://codereview.chromium.org/17555005/diff/93001/ppapi/api/dev/ppb_trace_e...
File ppapi/api/dev/ppb_trace_event_dev.idl (right):

https://codereview.chromium.org/17555005/diff/93001/ppapi/api/dev/ppb_trace_e...
ppapi/api/dev/ppb_trace_event_dev.idl:59: [in] int64_t timestamp,
What do you think of a typedef or struct for the timestamp, to make the
connection between Now and this function more obvious and discourage providing
an int64_t some other way or doing arithmetic on the time.

e.g.
typedef int64_t PP_TraceEventTime;

https://codereview.chromium.org/17555005/diff/93001/ppapi/shared_impl/ppb_tra...
File ppapi/shared_impl/ppb_trace_event_impl.cc (right):

https://codereview.chromium.org/17555005/diff/93001/ppapi/shared_impl/ppb_tra...
ppapi/shared_impl/ppb_trace_event_impl.cc:99: const PPB_Trace_Event_Dev
g_ppb_trace_event_thunk = {
Please use the versioned struct (PPB_Trace_Event_Dev_0_2)

[grosse, 2013-06-25 23:16:38]

https://codereview.chromium.org/17555005/diff/93001/ppapi/api/dev/ppb_trace_e...
File ppapi/api/dev/ppb_trace_event_dev.idl (right):

https://codereview.chromium.org/17555005/diff/93001/ppapi/api/dev/ppb_trace_e...
ppapi/api/dev/ppb_trace_event_dev.idl:59: [in] int64_t timestamp,
On 2013/06/25 22:19:27, dmichael wrote:
> What do you think of a typedef or struct for the timestamp, to make the
> connection between Now and this function more obvious and discourage providing
> an int64_t some other way or doing arithmetic on the time.
> 
> e.g.
> typedef int64_t PP_TraceEventTime;

Done.

https://codereview.chromium.org/17555005/diff/93001/ppapi/shared_impl/ppb_tra...
File ppapi/shared_impl/ppb_trace_event_impl.cc (right):

https://codereview.chromium.org/17555005/diff/93001/ppapi/shared_impl/ppb_tra...
ppapi/shared_impl/ppb_trace_event_impl.cc:99: const PPB_Trace_Event_Dev
g_ppb_trace_event_thunk = {
On 2013/06/25 22:19:27, dmichael wrote:
> Please use the versioned struct (PPB_Trace_Event_Dev_0_2)

Done.

[commit-bot: I haz the power, 2013-06-25 23:19:48]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/grosse@chromium.org/17555005/109001

[commit-bot: I haz the power, 2013-06-26 00:48:33]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

[commit-bot: I haz the power, 2013-06-26 02:20:52]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/grosse@chromium.org/17555005/109001

[commit-bot: I haz the power, 2013-06-26 02:31:00]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

[commit-bot: I haz the power, 2013-06-26 16:16:59]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/grosse@chromium.org/17555005/109001

[commit-bot: I haz the power, 2013-06-26 16:27:01]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

[commit-bot: I haz the power, 2013-06-26 16:43:35]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/grosse@chromium.org/17555005/134001

[commit-bot: I haz the power, 2013-06-26 16:54:49]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

[commit-bot: I haz the power, 2013-06-26 18:05:57]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/grosse@chromium.org/17555005/134001

[commit-bot: I haz the power, 2013-06-26 18:16:24]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

[commit-bot: I haz the power, 2013-06-26 18:21:25]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/grosse@chromium.org/17555005/134001

[commit-bot: I haz the power, 2013-06-26 18:22:00]

Change committed as 208738