blob: 0ff96dc34b993b3d55275ccff59b23819c3fda86 [file] [log] [blame]
* Copyright 2015 Google Inc. All Rights Reserved.
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* See the License for the specific language governing permissions and
* limitations under the License.
#include <set>
#include <vector>
#include "base/debug/trace_event.h"
#include "base/debug/trace_event_impl.h"
#include "base/memory/ref_counted.h"
#include "base/optional.h"
#include "base/time.h"
namespace cobalt {
namespace trace_event {
// EventParser is a class responsible for parsing raw base::debug::TraceLog
// trace events generated by calls to tracing functions found in trace_event.h.
// Example tracing calls include TRACE_EVENT0 and TRACE_EVENT_FLOW_BEGIN0.
// It parses raw sequences of base::debug::TraceEvent structures into
// high level event trees.
// This class will interpret the incoming log data and, as it becomes able to,
// will in turn fire its own higher level events such as when an event flow
// has ended. This is useful because it compiles all data for flow structures
// as it reads the individual raw trace events and only provides it to the
// client when entire flows have completed and all relevant information about
// them is available and nicely organized.
// Using this trace log parse to re-create the program flow structure
// makes it much easier to write code that analyzes timing and execution results
// available in the trace log.
// EventParser can link TRACE_EVENTs across TRACE_EVENT_FLOWs, allowing entire
// processing pipelines that span multiple thread boundaries to be linked
// together automatically.
class EventParser {
// A ScopedEvent represents some Chromium tracing event that has a duration.
// This includes standard TRACE_EVENTs which are scoped and thus have a
// beginning and end. It also includes TRACE_EVENT_FLOWs, which necessarily
// have an associated beginning and end.
class ScopedEvent : public base::RefCountedThreadSafe<ScopedEvent> {
ScopedEvent(const scoped_refptr<ScopedEvent>& parent,
const base::debug::TraceEvent& begin_event,
EventParser* event_parser);
// Shortcut method to retrieve the event name. This should be the same
// amongst begin_event(), end_event() and all instant_events().
const std::string name() const { return begin_event().name(); }
// Convenience method for returning the duration of this event's entire
// flow. This value may not exist if the trace was terminated before the
// end of the scoped event's flow occurs.
base::optional<base::TimeDelta> flow_duration() const {
if (end_flow_time()) {
return *end_flow_time() - begin_event().timestamp();
} else {
return base::nullopt;
// Convenience method for returning the duration of this event's scope.
// This value may not exist if the trace was terminated before the
// scoped event's end occurs.
base::optional<base::TimeDelta> in_scope_duration() const {
if (end_event()) {
return end_event()->timestamp() - begin_event().timestamp();
} else {
return base::nullopt;
// Returns the event's parent scope. Informally, this is the scope that
// was responsible for producing this scope.
const scoped_refptr<ScopedEvent>& parent() const { return parent_; }
// Return a list of the event's child events. Informally, these are the
// events that were produced by this event.
const std::vector<scoped_refptr<ScopedEvent> > children() const {
return children_;
// Returns the Chromium TraceEvent structure associated with the beginning
// of this scoped event (e.g. since the event is scoped, it has a beginning
// and end).
const base::debug::TraceEvent& begin_event() const { return begin_event_; }
// Returns the Chromium TraceEvent structure associated with the end of this
// scoped event. If the scoped event has not finished yet, this will return
// nullopt.
const base::optional<base::debug::TraceEvent>& end_event() const {
return end_event_;
// Return a list of instant events that are effectively children of this
// scoped event. For example, all TRACE_EVENT_FLOW_STEP calls will attach
// the generated TraceEvent structure as an instant event to the
// corresponding flow ScopedEvent.
const std::vector<base::debug::TraceEvent> instant_events() const {
return instant_events_;
// The end flow time is the time when the last of this ScopedEvent's
// descendants has ended. This can be much later than the ScopedEvent's
// local end time. An example where the end flow time is different from
// the end time is if within a TRACE_EVENT, a TRACE_EVENT_FLOW is started
// and the TRACE_EVENT_FLOW ends *after* the TRACE_EVENT ends. In this
// case, the TRACE_EVENT's end flow time is equal to the TRACE_EVENT_FLOW's
// end time, assuming the TRACE_EVENT_FLOW did not spawn any children of its
// own that could extend the TRACE_EVENT's end flow time even longer.
const base::optional<base::TimeTicks>& end_flow_time() const {
return end_flow_time_;
// Returns the latest generated Chromium TraceEvent we've seen so far.
// This will return end_event if it exists, otherwise the latest
// instant_event, otherwise the begin_event.
const base::debug::TraceEvent& LastTraceEvent() const;
// The state is used to keep track of what state the ScopedEvent is in.
// ScopedEvents may persist for much longer after they have been ended.
// Newly started event scopes will begin life in the kState_Active state.
enum State {
// kState_Active means that the ScopedEvent has not yet received a
// end signal (e.g. TRACE_EVENT_FLOW_BEGIN is not yet matched with
// kState_Ended means that the ScopedEvent has received an end signal,
// but it still has descendants that have not received their end signal
// and thus the end flow time for this ScopedEvent is not currently
// available.
// kState_EndedAndLastTouched exists to handle a bit of a special case
// where a TRACE_EVENT_FLOW is ended, and it has no children, but
// since it can potentially be linked as a parent to a subsequent
// TRACE_EVENT call (e.g. as is done in MessageLoop::RunTask), it should
// not be marked as having its flow ended yet. Being "last touched"
// means that this event was last on a thread to be modified on any
// thread (e.g. started, stepped or ended).
// kState_FlowEnded indicates that this ScopedEvent and all its
// descendants have ended their flows, and the state of the event will
// no longer be changing.
// kState_Aborted indicates that the ScopedEvent did not end properly
// and was instead aborted prematurely. Not all fields (like end_event)
// may be available, but the object will no longer be changing.
State state() const { return state_; }
virtual ~ScopedEvent();
friend class base::RefCountedThreadSafe<ScopedEvent>;
// Many of these methods will be called by EventParser in response to event
// processing.
void OnEnd(const base::debug::TraceEvent& end_event);
void OnEndFlow(const base::TimeTicks& timestamp);
bool AreEndFlowConditionsMet() const;
void AddInstantEvent(const base::debug::TraceEvent& event);
void OnNotLastTouched();
void Abort();
// Returns a set of all leaf nodes in the event tree rooted at this
// ScopedEvent node. If this node is a leaf node, the returned set
// will contain this node as the single item.
std::set<scoped_refptr<ScopedEvent> > GetLeafEvents();
scoped_refptr<ScopedEvent> parent_;
std::vector<scoped_refptr<ScopedEvent> > children_;
base::debug::TraceEvent begin_event_;
base::optional<base::debug::TraceEvent> end_event_;
base::optional<base::TimeTicks> end_flow_time_;
std::vector<base::debug::TraceEvent> instant_events_;
// How many of our children have flows that have not ended yet? If this
// is non-zero, then our flow cannot yet be ended.
int flow_active_children_;
State state_;
// The parent event parser this ScopedEvent is apart of.
EventParser* event_parser_;
friend class EventParser;
typedef base::Callback<void(const scoped_refptr<ScopedEvent>& event)>
// The passed in scoped_event_flow_end_callback will be run every time we
// encounter a ScopedEvent whose flow has ended (e.g. the event is over and
// so are all its descendants). It is important to realize that an event's
// "flow end" is different from the end of the event's scope. For example,
// if a TRACE_EVENT posts a message to a message loop, and then the
// TRACE_EVENT goes out of scope, the event's scope has ended but its flow
// has not. The flow will only end when the posted message is processed
// and that message did not post any messages of its own to extend the flow
// farther.
explicit EventParser(
const ScopedEventFlowEndCallback& scoped_event_flow_end_callback);
// This is the function that drives the event parser. As raw events are fed
// to EventParser from base::debug::TraceLog, the event parser is updated and
// may produce its own higher level events.
void ParseEvent(const base::debug::TraceEvent& event);
// Used to keep track of information local to specific threads, such as
// which events are currently on the stack for that thread, and what the last
// event touched on that thread was.
struct ThreadInfo {
std::vector<scoped_refptr<ScopedEvent> > event_stack_;
scoped_refptr<ScopedEvent> last_touched_event_;
void UpdateLastTouchedEvent(ThreadInfo* thread_info,
const scoped_refptr<ScopedEvent>& event);
std::set<scoped_refptr<ScopedEvent> > GetLeafEvents();
friend class ScopedEvent;
ScopedEventFlowEndCallback scoped_event_flow_end_callback_;
typedef base::hash_map<int, ThreadInfo> ThreadMap;
ThreadMap thread_id_to_info_map_;
// Keep a mapping of all active flow events (which may span multiple threads)
// for easy lookup if we need to process a flow event.
typedef base::hash_map<uint64_t, scoped_refptr<ScopedEvent> > FlowEventMap;
FlowEventMap flow_id_to_event_map_;
} // namespace trace_event
} // namespace cobalt