Improve mojo method tracing.

This CL refines TRACE_EVENTs added to generated mojo code:

1. "ns::Class::Method" event is emitted when client calls a mojo interface.

2. "(Impl)ns::Class::Method" event is emitted when mojo calls the
   implementation of an interface.

3. "(Impl)ns::Class::MethodCallback" event is emitted when an implementation
   calls the method's callback.

4. "ns::Class::MethodCallback" event is emitted for async methods when
   the method's callback is called on the client side.

Additionally, this CL removes couple of redundant TRACE_EVENTs that are
either contained in the events above, or are not useful for understanding
mojo call flow.

Bug: 792614
Change-Id: I03ac80729ff0e9d0c4ad9fb7fc98e962110a0518
Reviewed-on: https://chromium-review.googlesource.com/812104Reviewed-by: Ken Rockot <rockot@chromium.org>
Commit-Queue: Dmitry Skiba <dskiba@chromium.org>
Cr-Commit-Position: refs/heads/master@{#523621}

mojo/public/cpp/bindings/lib/connector.cc

@@ -18,6 +18,7 @@
 #include "base/threading/thread_local.h"
 #include "base/trace_event/trace_event.h"
 #include "mojo/public/cpp/bindings/lib/may_auto_lock.h"
+#include "mojo/public/cpp/bindings/mojo_features.h"
 #include "mojo/public/cpp/bindings/sync_handle_watcher.h"
 #include "mojo/public/cpp/system/wait.h"
 
@@ -435,7 +436,11 @@ bool Connector::ReadSingleMessage(MojoResult* read_result) {
                 incoming_serialization_mode_);
     }
 
+#if !BUILDFLAG(MOJO_TRACE_ENABLED)
+    // This emits just full class name, and is inferior to mojo tracing.
     TRACE_EVENT0("mojom", heap_profiler_tag_);
+#endif
+
     receiver_result =
         incoming_receiver_ && incoming_receiver_->Accept(&message);
 

mojo/public/tools/bindings/generators/cpp_templates/interface_definition.tmpl

@@ -122,6 +122,9 @@ class {{class_name}}_{{method.name}}_ForwardToCallback
 {%-   if method.sync %}
 bool {{proxy_name}}::{{method.name}}(
     {{interface_macros.declare_sync_method_params("param_", method)}}) {
+#if BUILDFLAG(MOJO_TRACE_ENABLED)
+  TRACE_EVENT0("mojom", "{{namespace_as_string}}::{{class_name}}::{{method.name}}");
+#endif
   const bool kExpectsResponse = true;
   const bool kIsSync = true;
 {%-   if method|method_supports_lazy_serialization %}
@@ -153,6 +156,9 @@ bool {{proxy_name}}::{{method.name}}(
 
 void {{proxy_name}}::{{method.name}}(
     {{interface_macros.declare_request_params("in_", method, use_once_callback)}}) {
+#if BUILDFLAG(MOJO_TRACE_ENABLED)
+  TRACE_EVENT0("mojom", "{{namespace_as_string}}::{{class_name}}::{{method.name}}");
+#endif
 {%- if method.response_parameters != None %}
   const bool kExpectsResponse = true;
 {%- else %}
@@ -256,7 +262,8 @@ class {{class_name}}_{{method.name}}_ProxyToResponder {
 bool {{class_name}}_{{method.name}}_ForwardToCallback::Accept(
     mojo::Message* message) {
 #if BUILDFLAG(MOJO_TRACE_ENABLED)
-  TRACE_EVENT1("mojom", "{{method.name}}", "message", message->name());
+  TRACE_EVENT1("mojom", "{{namespace_as_string}}::{{class_name}}::{{method.name}}Callback",
+               "message", message->name());
 #endif
   mojo::internal::MessageDispatchContext dispatch_context(message);
 {%-     if method|method_supports_lazy_serialization %}
@@ -305,7 +312,8 @@ void {{class_name}}_{{method.name}}_ProxyToResponder::Run(
 {%-   endif %}
 
 #if BUILDFLAG(MOJO_TRACE_ENABLED)
-  TRACE_EVENT1("mojom", "{{method.name}}", "message", message.name());
+  TRACE_EVENT1("mojom", "(Impl){{namespace_as_string}}::{{class_name}}::{{method.name}}Callback",
+               "message", message.name());
 #endif
   message.set_request_id(request_id_);
   ignore_result(responder_->Accept(&message));
@@ -319,9 +327,6 @@ void {{class_name}}_{{method.name}}_ProxyToResponder::Run(
 {%-   if method.sync %}
 bool {{class_name}}_{{method.name}}_HandleSyncResponse::Accept(
     mojo::Message* message) {
-#if BUILDFLAG(MOJO_TRACE_ENABLED)
-  TRACE_EVENT1("mojom", "{{method.name}}", "message", message->name());
-#endif
 {%-     if method|method_supports_lazy_serialization %}
   if (!message->is_serialized()) {
     auto context =
@@ -376,7 +381,8 @@ bool {{class_name}}StubDispatch::Accept(
 {%-   for method in interface.methods %}
     case internal::k{{class_name}}_{{method.name}}_Name: {
 #if BUILDFLAG(MOJO_TRACE_ENABLED)
-  TRACE_EVENT1("mojom", "{{method.name}}", "message", message->name());
+  TRACE_EVENT1("mojom", "(Impl){{namespace_as_string}}::{{class_name}}::{{method.name}}",
+               "message", message->name());
 #endif
 {%-     if method.response_parameters == None %}
       mojo::internal::MessageDispatchContext context(message);
@@ -428,7 +434,8 @@ bool {{class_name}}StubDispatch::AcceptWithResponder(
 {%-   for method in interface.methods %}
     case internal::k{{class_name}}_{{method.name}}_Name: {
 #if BUILDFLAG(MOJO_TRACE_ENABLED)
-  TRACE_EVENT1("mojom", "{{method.name}}", "message", message->name());
+  TRACE_EVENT1("mojom", "(Impl){{namespace_as_string}}::{{class_name}}::{{method.name}}",
+               "message", message->name());
 #endif
 {%-     if method.response_parameters != None %}
       mojo::internal::MessageDispatchContext context(message);
@@ -495,9 +502,6 @@ bool {{class_name}}RequestValidator::Accept(mojo::Message* message) {
   switch (message->header()->name) {
 {%- for method in interface.methods %}
     case internal::k{{class_name}}_{{method.name}}_Name: {
-#if BUILDFLAG(MOJO_TRACE_ENABLED)
-  TRACE_EVENT1("mojom", "{{method.name}}", "message", message->name());
-#endif
 {%-   if method.response_parameters != None %}
       if (!mojo::internal::ValidateMessageIsRequestExpectingResponse(
               message, &validation_context)) {
@@ -544,9 +548,6 @@ bool {{class_name}}ResponseValidator::Accept(mojo::Message* message) {
   switch (message->header()->name) {
 {%- for method in interface.methods if method.response_parameters != None %}
     case internal::k{{class_name}}_{{method.name}}_Name: {
-#if BUILDFLAG(MOJO_TRACE_ENABLED)
-  TRACE_EVENT1("mojom", "{{method.name}}", "message", message->name());
-#endif
       if (!mojo::internal::ValidateMessagePayload<
                internal::{{class_name}}_{{method.name}}_ResponseParams_Data>(
                     message, &validation_context)) {