diff options
author | jbates@chromium.org <jbates@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2012-09-18 03:41:29 +0000 |
---|---|---|
committer | jbates@chromium.org <jbates@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2012-09-18 03:41:29 +0000 |
commit | 2c391df878dc6187bbb8a26d34260ed46f18d139 (patch) | |
tree | e50370b6faf481726d7b7810f4b89dd55be7d494 | |
parent | 108a0513d108857ba2e943b8f70bd68dc3a98a18 (diff) | |
download | chromium_src-2c391df878dc6187bbb8a26d34260ed46f18d139.zip chromium_src-2c391df878dc6187bbb8a26d34260ed46f18d139.tar.gz chromium_src-2c391df878dc6187bbb8a26d34260ed46f18d139.tar.bz2 |
Trace PostTasks from post to run.
To do this properly, we need a new type of trace event "FLOW" which will be drawn as lines in about:tracing from BEGIN to END.
Also instruments SequencedWorkerPool and ChannelReader::DispatchInputData, which were not currently traced.
BUG=79942
Review URL: https://codereview.chromium.org/10913242
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@157288 0039d316-1c4b-4281-b951-d872f2087c98
-rw-r--r-- | base/debug/trace_event.h | 178 | ||||
-rw-r--r-- | base/message_loop.cc | 27 | ||||
-rw-r--r-- | base/message_loop.h | 3 | ||||
-rw-r--r-- | base/threading/sequenced_worker_pool.cc | 28 | ||||
-rw-r--r-- | ipc/ipc_channel_nacl.cc | 2 | ||||
-rw-r--r-- | ipc/ipc_channel_posix.cc | 2 | ||||
-rw-r--r-- | ipc/ipc_channel_proxy.cc | 1 | ||||
-rw-r--r-- | ipc/ipc_channel_reader.cc | 15 | ||||
-rw-r--r-- | ipc/ipc_channel_win.cc | 2 | ||||
-rw-r--r-- | ipc/ipc_message.h | 10 |
10 files changed, 227 insertions, 41 deletions
diff --git a/base/debug/trace_event.h b/base/debug/trace_event.h index 804b4681..07863ad 100644 --- a/base/debug/trace_event.h +++ b/base/debug/trace_event.h @@ -162,6 +162,11 @@ #define TRACE_STR_COPY(str) \ trace_event_internal::TraceStringWithCopy(str) +// By default, uint64 ID argument values are not mangled with the Process ID in +// TRACE_EVENT_ASYNC macros. Use this macro to force Process ID mangling. +#define TRACE_ID_MANGLE(id) \ + trace_event_internal::TraceID::ForceMangle(id) + // Records a pair of begin and end events called "name" for the current // scope, with 0, 1 or 2 associated arguments. If the category is not // enabled, then this does nothing. @@ -389,8 +394,9 @@ // that the same pointer on two different processes will not collide. // An asynchronous operation can consist of multiple phases. The first phase is // defined by the ASYNC_BEGIN calls. Additional phases can be defined using the -// ASYNC_STEP_BEGIN macros. When the operation completes, call ASYNC_END. -// An async operation can span threads and processes, but all events in that +// ASYNC_STEP macros. When the operation completes, call ASYNC_END. +// An ASYNC trace typically occur on a single thread (if not, they will only be +// drawn on the thread defined in the ASYNC_BEGIN event), but all events in that // operation must use the same |name| and |id|. Each event can have its own // args. #define TRACE_EVENT_ASYNC_BEGIN0(category, name, id) \ @@ -466,6 +472,98 @@ arg1_name, arg1_val, arg2_name, arg2_val) +// Records a single FLOW_BEGIN event called "name" immediately, with 0, 1 or 2 +// associated arguments. If the category is not enabled, then this +// does nothing. +// - category and name strings must have application lifetime (statics or +// literals). They may not include " chars. +// - |id| is used to match the FLOW_BEGIN event with the FLOW_END event. FLOW +// events are considered to match if their category, name and id values all +// match. |id| must either be a pointer or an integer value up to 64 bits. If +// it's a pointer, the bits will be xored with a hash of the process ID so +// that the same pointer on two different processes will not collide. +// FLOW events are different from ASYNC events in how they are drawn by the +// tracing UI. A FLOW defines asynchronous data flow, such as posting a task +// (FLOW_BEGIN) and later executing that task (FLOW_END). Expect FLOWs to be +// drawn as lines or arrows from FLOW_BEGIN scopes to FLOW_END scopes. Similar +// to ASYNC, a FLOW can consist of multiple phases. The first phase is defined +// by the FLOW_BEGIN calls. Additional phases can be defined using the FLOW_STEP +// macros. When the operation completes, call FLOW_END. An async operation can +// span threads and processes, but all events in that operation must use the +// same |name| and |id|. Each event can have its own args. +#define TRACE_EVENT_FLOW_BEGIN0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \ + category, name, id, TRACE_EVENT_FLAG_NONE) +#define TRACE_EVENT_FLOW_BEGIN1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \ + category, name, id, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val) +#define TRACE_EVENT_FLOW_BEGIN2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \ + category, name, id, TRACE_EVENT_FLAG_NONE, \ + arg1_name, arg1_val, arg2_name, arg2_val) +#define TRACE_EVENT_COPY_FLOW_BEGIN0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \ + category, name, id, TRACE_EVENT_FLAG_COPY) +#define TRACE_EVENT_COPY_FLOW_BEGIN1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \ + category, name, id, TRACE_EVENT_FLAG_COPY, \ + arg1_name, arg1_val) +#define TRACE_EVENT_COPY_FLOW_BEGIN2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \ + category, name, id, TRACE_EVENT_FLAG_COPY, \ + arg1_name, arg1_val, arg2_name, arg2_val) + +// Records a single FLOW_STEP event for |step| immediately. If the category +// is not enabled, then this does nothing. The |name| and |id| must match the +// FLOW_BEGIN event above. The |step| param identifies this step within the +// async event. This should be called at the beginning of the next phase of an +// asynchronous operation. +#define TRACE_EVENT_FLOW_STEP0(category, name, id, step) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, \ + category, name, id, TRACE_EVENT_FLAG_NONE, "step", step) +#define TRACE_EVENT_FLOW_STEP1(category, name, id, step, \ + arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, \ + category, name, id, TRACE_EVENT_FLAG_NONE, "step", step, \ + arg1_name, arg1_val) +#define TRACE_EVENT_COPY_FLOW_STEP0(category, name, id, step) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, \ + category, name, id, TRACE_EVENT_FLAG_COPY, "step", step) +#define TRACE_EVENT_COPY_FLOW_STEP1(category, name, id, step, \ + arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, \ + category, name, id, TRACE_EVENT_FLAG_COPY, "step", step, \ + arg1_name, arg1_val) + +// Records a single FLOW_END event for "name" immediately. If the category +// is not enabled, then this does nothing. +#define TRACE_EVENT_FLOW_END0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, \ + category, name, id, TRACE_EVENT_FLAG_NONE) +#define TRACE_EVENT_FLOW_END1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, \ + category, name, id, TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val) +#define TRACE_EVENT_FLOW_END2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, \ + category, name, id, TRACE_EVENT_FLAG_NONE, \ + arg1_name, arg1_val, arg2_name, arg2_val) +#define TRACE_EVENT_COPY_FLOW_END0(category, name, id) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, \ + category, name, id, TRACE_EVENT_FLAG_COPY) +#define TRACE_EVENT_COPY_FLOW_END1(category, name, id, arg1_name, arg1_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, \ + category, name, id, TRACE_EVENT_FLAG_COPY, \ + arg1_name, arg1_val) +#define TRACE_EVENT_COPY_FLOW_END2(category, name, id, arg1_name, arg1_val, \ + arg2_name, arg2_val) \ + INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, \ + category, name, id, TRACE_EVENT_FLAG_COPY, \ + arg1_name, arg1_val, arg2_name, arg2_val) + + //////////////////////////////////////////////////////////////////////////////// // Implementation specific tracing API definitions. @@ -606,6 +704,9 @@ #define TRACE_EVENT_PHASE_ASYNC_BEGIN ('S') #define TRACE_EVENT_PHASE_ASYNC_STEP ('T') #define TRACE_EVENT_PHASE_ASYNC_END ('F') +#define TRACE_EVENT_PHASE_FLOW_BEGIN ('s') +#define TRACE_EVENT_PHASE_FLOW_STEP ('t') +#define TRACE_EVENT_PHASE_FLOW_END ('f') #define TRACE_EVENT_PHASE_METADATA ('M') #define TRACE_EVENT_PHASE_COUNTER ('C') @@ -638,31 +739,58 @@ const unsigned long long kNoEventId = 0; // same pointer is used on different processes. class TraceID { public: - explicit TraceID(const void* id, unsigned char* flags) : - data_(static_cast<unsigned long long>( - reinterpret_cast<unsigned long>(id))) { + class ForceMangle { + public: + explicit ForceMangle(unsigned long long id) : data_(id) {} + explicit ForceMangle(unsigned long id) : data_(id) {} + explicit ForceMangle(unsigned int id) : data_(id) {} + explicit ForceMangle(unsigned short id) : data_(id) {} + explicit ForceMangle(unsigned char id) : data_(id) {} + explicit ForceMangle(long long id) + : data_(static_cast<unsigned long long>(id)) {} + explicit ForceMangle(long id) + : data_(static_cast<unsigned long long>(id)) {} + explicit ForceMangle(int id) + : data_(static_cast<unsigned long long>(id)) {} + explicit ForceMangle(short id) + : data_(static_cast<unsigned long long>(id)) {} + explicit ForceMangle(signed char id) + : data_(static_cast<unsigned long long>(id)) {} + + unsigned long long data() const { return data_; } + + private: + unsigned long long data_; + }; + + explicit TraceID(const void* id, unsigned char* flags) + : data_(static_cast<unsigned long long>( + reinterpret_cast<unsigned long>(id))) { + *flags |= TRACE_EVENT_FLAG_MANGLE_ID; + } + explicit TraceID(ForceMangle id, unsigned char* flags) : data_(id.data()) { *flags |= TRACE_EVENT_FLAG_MANGLE_ID; } - explicit TraceID(unsigned long long id, unsigned char* flags) : - data_(id) { (void)flags; } - explicit TraceID(unsigned long id, unsigned char* flags) : - data_(id) { (void)flags; } - explicit TraceID(unsigned int id, unsigned char* flags) : - data_(id) { (void)flags; } - explicit TraceID(unsigned short id, unsigned char* flags) : - data_(id) { (void)flags; } - explicit TraceID(unsigned char id, unsigned char* flags) : - data_(id) { (void)flags; } - explicit TraceID(long long id, unsigned char* flags) : - data_(static_cast<unsigned long long>(id)) { (void)flags; } - explicit TraceID(long id, unsigned char* flags) : - data_(static_cast<unsigned long long>(id)) { (void)flags; } - explicit TraceID(int id, unsigned char* flags) : - data_(static_cast<unsigned long long>(id)) { (void)flags; } - explicit TraceID(short id, unsigned char* flags) : - data_(static_cast<unsigned long long>(id)) { (void)flags; } - explicit TraceID(signed char id, unsigned char* flags) : - data_(static_cast<unsigned long long>(id)) { (void)flags; } + explicit TraceID(unsigned long long id, unsigned char* flags) + : data_(id) { (void)flags; } + explicit TraceID(unsigned long id, unsigned char* flags) + : data_(id) { (void)flags; } + explicit TraceID(unsigned int id, unsigned char* flags) + : data_(id) { (void)flags; } + explicit TraceID(unsigned short id, unsigned char* flags) + : data_(id) { (void)flags; } + explicit TraceID(unsigned char id, unsigned char* flags) + : data_(id) { (void)flags; } + explicit TraceID(long long id, unsigned char* flags) + : data_(static_cast<unsigned long long>(id)) { (void)flags; } + explicit TraceID(long id, unsigned char* flags) + : data_(static_cast<unsigned long long>(id)) { (void)flags; } + explicit TraceID(int id, unsigned char* flags) + : data_(static_cast<unsigned long long>(id)) { (void)flags; } + explicit TraceID(short id, unsigned char* flags) + : data_(static_cast<unsigned long long>(id)) { (void)flags; } + explicit TraceID(signed char id, unsigned char* flags) + : data_(static_cast<unsigned long long>(id)) { (void)flags; } unsigned long long data() const { return data_; } diff --git a/base/message_loop.cc b/base/message_loop.cc index 32994bf..21108eb 100644 --- a/base/message_loop.cc +++ b/base/message_loop.cc @@ -91,6 +91,14 @@ bool enable_histogrammer_ = false; MessageLoop::MessagePumpFactory* message_pump_for_ui_factory_ = NULL; +// Create a process-wide unique ID to represent this task in trace events. This +// will be mangled with a Process ID hash to reduce the likelyhood of colliding +// with MessageLoop pointers on other processes. +uint64 GetTaskTraceID(const PendingTask& task, MessageLoop* loop) { + return (static_cast<uint64>(task.sequence_num) << 32) | + static_cast<uint64>(reinterpret_cast<intptr_t>(loop)); +} + } // namespace //------------------------------------------------------------------------------ @@ -434,6 +442,8 @@ bool MessageLoop::ProcessNextDelayedNonNestableTask() { } void MessageLoop::RunTask(const PendingTask& pending_task) { + TRACE_EVENT_FLOW_END0("task", "MessageLoop::PostTask", + TRACE_ID_MANGLE(GetTaskTraceID(pending_task, this))); TRACE_EVENT2("task", "MessageLoop::RunTask", "src_file", pending_task.posted_from.file_name(), "src_func", pending_task.posted_from.function_name()); @@ -482,13 +492,8 @@ bool MessageLoop::DeferOrRunPendingTask(const PendingTask& pending_task) { } void MessageLoop::AddToDelayedWorkQueue(const PendingTask& pending_task) { - // Move to the delayed work queue. Initialize the sequence number - // before inserting into the delayed_work_queue_. The sequence number - // is used to faciliate FIFO sorting when two tasks have the same - // delayed_run_time value. - PendingTask new_pending_task(pending_task); - new_pending_task.sequence_num = next_sequence_num_++; - delayed_work_queue_.push(new_pending_task); + // Move to the delayed work queue. + delayed_work_queue_.push(pending_task); } void MessageLoop::ReloadWorkQueue() { @@ -586,6 +591,14 @@ void MessageLoop::AddToIncomingQueue(PendingTask* pending_task) { { base::AutoLock locked(incoming_queue_lock_); + // Initialize the sequence number. The sequence number is used for delayed + // tasks (to faciliate FIFO sorting when two tasks have the same + // delayed_run_time value) and for identifying the task in about:tracing. + pending_task->sequence_num = next_sequence_num_++; + + TRACE_EVENT_FLOW_BEGIN0("task", "MessageLoop::PostTask", + TRACE_ID_MANGLE(GetTaskTraceID(*pending_task, this))); + bool was_empty = incoming_queue_.empty(); incoming_queue_.push(*pending_task); pending_task->task.Reset(); diff --git a/base/message_loop.h b/base/message_loop.h index 39c646e..74dfe65 100644 --- a/base/message_loop.h +++ b/base/message_loop.h @@ -505,7 +505,8 @@ class BASE_EXPORT MessageLoop : public base::MessagePump::Delegate { bool os_modal_loop_; #endif - // The next sequence number to use for delayed tasks. + // The next sequence number to use for delayed tasks. Updating this counter is + // protected by incoming_queue_lock_. int next_sequence_num_; ObserverList<TaskObserver> task_observers_; diff --git a/base/threading/sequenced_worker_pool.cc b/base/threading/sequenced_worker_pool.cc index 68127a5..b9a38c6 100644 --- a/base/threading/sequenced_worker_pool.cc +++ b/base/threading/sequenced_worker_pool.cc @@ -14,6 +14,7 @@ #include "base/callback.h" #include "base/compiler_specific.h" #include "base/critical_closure.h" +#include "base/debug/trace_event.h" #include "base/logging.h" #include "base/memory/linked_ptr.h" #include "base/message_loop_proxy.h" @@ -39,16 +40,19 @@ namespace { struct SequencedTask : public TrackingInfo { SequencedTask() : sequence_token_id(0), + trace_id(0), shutdown_behavior(SequencedWorkerPool::BLOCK_SHUTDOWN) {} explicit SequencedTask(const tracked_objects::Location& from_here) : base::TrackingInfo(from_here, TimeTicks()), sequence_token_id(0), + trace_id(0), shutdown_behavior(SequencedWorkerPool::BLOCK_SHUTDOWN) {} ~SequencedTask() {} int sequence_token_id; + int trace_id; SequencedWorkerPool::WorkerShutdown shutdown_behavior; tracked_objects::Location posted_from; Closure task; @@ -208,6 +212,15 @@ bool SequencedWorkerPoolSequencedTaskRunner::PostDelayedTaskAssertZeroDelay( token_, from_here, task, shutdown_behavior_); } +// Create a process-wide unique ID to represent this task in trace events. This +// will be mangled with a Process ID hash to reduce the likelyhood of colliding +// with MessageLoop pointers on other processes. +uint64 GetTaskTraceID(const SequencedTask& task, + void* pool) { + return (static_cast<uint64>(task.trace_id) << 32) | + static_cast<uint64>(reinterpret_cast<intptr_t>(pool)); +} + } // namespace // Worker --------------------------------------------------------------------- @@ -396,6 +409,9 @@ class SequencedWorkerPool::Inner { // Lists all sequence tokens currently executing. std::set<int> current_sequences_; + // An ID for each posted task to distinguish the task from others in traces. + int trace_id_; + // Set when Shutdown is called and no further tasks should be // allowed, though we may still be running existing tasks. bool shutdown_called_; @@ -451,6 +467,7 @@ SequencedWorkerPool::Inner::Inner( blocking_shutdown_thread_count_(0), pending_task_count_(0), blocking_shutdown_pending_task_count_(0), + trace_id_(0), shutdown_called_(false), testing_observer_(observer) {} @@ -501,6 +518,12 @@ bool SequencedWorkerPool::Inner::PostTask( if (shutdown_called_) return false; + // The trace_id is used for identifying the task in about:tracing. + sequenced.trace_id = trace_id_++; + + TRACE_EVENT_FLOW_BEGIN0("task", "SequencedWorkerPool::PostTask", + TRACE_ID_MANGLE(GetTaskTraceID(sequenced, static_cast<void*>(this)))); + // Now that we have the lock, apply the named token rules. if (optional_token_name) sequenced.sequence_token_id = LockedGetNamedTokenID(*optional_token_name); @@ -605,6 +628,11 @@ void SequencedWorkerPool::Inner::ThreadLoop(Worker* this_worker) { SequencedTask task; std::vector<Closure> delete_these_outside_lock; if (GetWork(&task, &delete_these_outside_lock)) { + TRACE_EVENT_FLOW_END0("task", "SequencedWorkerPool::PostTask", + TRACE_ID_MANGLE(GetTaskTraceID(task, static_cast<void*>(this)))); + TRACE_EVENT2("task", "SequencedWorkerPool::ThreadLoop", + "src_file", task.posted_from.file_name(), + "src_func", task.posted_from.function_name()); int new_thread_id = WillRunWorkerTask(task); { AutoUnlock unlock(lock_); diff --git a/ipc/ipc_channel_nacl.cc b/ipc/ipc_channel_nacl.cc index 0d50a57..4231dd8 100644 --- a/ipc/ipc_channel_nacl.cc +++ b/ipc/ipc_channel_nacl.cc @@ -193,7 +193,7 @@ bool Channel::ChannelImpl::Send(Message* message) { Logging::GetInstance()->OnSendMessage(message_ptr.get(), ""); #endif // IPC_MESSAGE_LOG_ENABLED - message->TraceMessageStep(); + message->TraceMessageBegin(); output_queue_.push_back(linked_ptr<Message>(message_ptr.release())); if (!waiting_connect_) return ProcessOutgoingMessages(); diff --git a/ipc/ipc_channel_posix.cc b/ipc/ipc_channel_posix.cc index 37bc7e4..f5cf8af 100644 --- a/ipc/ipc_channel_posix.cc +++ b/ipc/ipc_channel_posix.cc @@ -631,7 +631,7 @@ bool Channel::ChannelImpl::Send(Message* message) { Logging::GetInstance()->OnSendMessage(message, ""); #endif // IPC_MESSAGE_LOG_ENABLED - message->TraceMessageStep(); + message->TraceMessageBegin(); output_queue_.push(message); if (!is_blocked_on_write_ && !waiting_connect_) { return ProcessOutgoingMessages(); diff --git a/ipc/ipc_channel_proxy.cc b/ipc/ipc_channel_proxy.cc index 630b0cf..0b2338c 100644 --- a/ipc/ipc_channel_proxy.cc +++ b/ipc/ipc_channel_proxy.cc @@ -351,7 +351,6 @@ void ChannelProxy::Close() { bool ChannelProxy::Send(Message* message) { DCHECK(did_init_); - message->TraceMessageStep(); if (outgoing_message_filter()) message = outgoing_message_filter()->Rewrite(message); diff --git a/ipc/ipc_channel_reader.cc b/ipc/ipc_channel_reader.cc index 8e8b6a65..2f291a9 100644 --- a/ipc/ipc_channel_reader.cc +++ b/ipc/ipc_channel_reader.cc @@ -4,6 +4,9 @@ #include "ipc/ipc_channel_reader.h" +#include "ipc/ipc_logging.h" +#include "ipc/ipc_message_macros.h" + namespace IPC { namespace internal { @@ -69,7 +72,17 @@ bool ChannelReader::DispatchInputData(const char* input_data, if (!WillDispatchInputMessage(&m)) return false; - m.TraceMessageStep(); +#ifdef IPC_MESSAGE_LOG_ENABLED + Logging* logger = Logging::GetInstance(); + std::string name; + logger->GetMessageText(m.type(), &name, &m, NULL); + TRACE_EVENT1("ipc", "ChannelReader::DispatchInputData", "name", name); +#else + TRACE_EVENT2("ipc", "ChannelReader::DispatchInputData", + "class", IPC_MESSAGE_ID_CLASS(m.type()), + "line", IPC_MESSAGE_ID_LINE(m.type())); +#endif + m.TraceMessageEnd(); if (IsHelloMessage(m)) HandleHelloMessage(m); else diff --git a/ipc/ipc_channel_win.cc b/ipc/ipc_channel_win.cc index 77ea64c..3cc1c6e 100644 --- a/ipc/ipc_channel_win.cc +++ b/ipc/ipc_channel_win.cc @@ -88,7 +88,7 @@ bool Channel::ChannelImpl::Send(Message* message) { Logging::GetInstance()->OnSendMessage(message, ""); #endif - message->TraceMessageStep(); + message->TraceMessageBegin(); output_queue_.push(message); // ensure waiting to write if (!waiting_connect_) { diff --git a/ipc/ipc_message.h b/ipc/ipc_message.h index 3c62960..1ae9e75 100644 --- a/ipc/ipc_message.h +++ b/ipc/ipc_message.h @@ -224,9 +224,13 @@ class IPC_EXPORT Message : public Pickle { bool dont_log() const { return dont_log_; } #endif - // Called at various points between send and receive to track message. - void TraceMessageStep() { - TRACE_EVENT_ASYNC_STEP0("ipc", "IPC", header()->flags, "step"); + // Called to trace when message is sent. + void TraceMessageBegin() { + TRACE_EVENT_FLOW_BEGIN0("ipc", "IPC", header()->flags); + } + // Called to trace when message is received. + void TraceMessageEnd() { + TRACE_EVENT_FLOW_END0("ipc", "IPC", header()->flags); } protected: |