Home | History | Annotate | Download | only in debug
      1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
      2 // Use of this source code is governed by a BSD-style license that can be
      3 // found in the LICENSE file.
      4 
      5 
      6 #ifndef BASE_DEBUG_TRACE_EVENT_IMPL_H_
      7 #define BASE_DEBUG_TRACE_EVENT_IMPL_H_
      8 
      9 #include <stack>
     10 #include <string>
     11 #include <vector>
     12 
     13 #include "base/callback.h"
     14 #include "base/containers/hash_tables.h"
     15 #include "base/gtest_prod_util.h"
     16 #include "base/memory/ref_counted_memory.h"
     17 #include "base/memory/scoped_vector.h"
     18 #include "base/observer_list.h"
     19 #include "base/strings/string_util.h"
     20 #include "base/synchronization/condition_variable.h"
     21 #include "base/synchronization/lock.h"
     22 #include "base/threading/thread.h"
     23 #include "base/timer/timer.h"
     24 
     25 // Older style trace macros with explicit id and extra data
     26 // Only these macros result in publishing data to ETW as currently implemented.
     27 #define TRACE_EVENT_BEGIN_ETW(name, id, extra) \
     28     base::debug::TraceLog::AddTraceEventEtw( \
     29         TRACE_EVENT_PHASE_BEGIN, \
     30         name, reinterpret_cast<const void*>(id), extra)
     31 
     32 #define TRACE_EVENT_END_ETW(name, id, extra) \
     33     base::debug::TraceLog::AddTraceEventEtw( \
     34         TRACE_EVENT_PHASE_END, \
     35         name, reinterpret_cast<const void*>(id), extra)
     36 
     37 #define TRACE_EVENT_INSTANT_ETW(name, id, extra) \
     38     base::debug::TraceLog::AddTraceEventEtw( \
     39         TRACE_EVENT_PHASE_INSTANT, \
     40         name, reinterpret_cast<const void*>(id), extra)
     41 
     42 template <typename Type>
     43 struct DefaultSingletonTraits;
     44 
     45 namespace base {
     46 
     47 class WaitableEvent;
     48 
     49 namespace debug {
     50 
     51 // For any argument of type TRACE_VALUE_TYPE_CONVERTABLE the provided
     52 // class must implement this interface.
     53 class ConvertableToTraceFormat {
     54  public:
     55   virtual ~ConvertableToTraceFormat() {}
     56 
     57   // Append the class info to the provided |out| string. The appended
     58   // data must be a valid JSON object. Strings must be properly quoted, and
     59   // escaped. There is no processing applied to the content after it is
     60   // appended.
     61   virtual void AppendAsTraceFormat(std::string* out) const = 0;
     62 };
     63 
     64 const int kTraceMaxNumArgs = 2;
     65 
     66 // Output records are "Events" and can be obtained via the
     67 // OutputCallback whenever the tracing system decides to flush. This
     68 // can happen at any time, on any thread, or you can programmatically
     69 // force it to happen.
     70 class BASE_EXPORT TraceEvent {
     71  public:
     72   union TraceValue {
     73     bool as_bool;
     74     unsigned long long as_uint;
     75     long long as_int;
     76     double as_double;
     77     const void* as_pointer;
     78     const char* as_string;
     79   };
     80 
     81   TraceEvent();
     82   TraceEvent(int thread_id,
     83              TimeTicks timestamp,
     84              char phase,
     85              const unsigned char* category_group_enabled,
     86              const char* name,
     87              unsigned long long id,
     88              int num_args,
     89              const char** arg_names,
     90              const unsigned char* arg_types,
     91              const unsigned long long* arg_values,
     92              scoped_ptr<ConvertableToTraceFormat> convertable_values[],
     93              unsigned char flags);
     94   TraceEvent(const TraceEvent& other);
     95   TraceEvent& operator=(const TraceEvent& other);
     96   ~TraceEvent();
     97 
     98   // Serialize event data to JSON
     99   static void AppendEventsAsJSON(const std::vector<TraceEvent>& events,
    100                                  size_t start,
    101                                  size_t count,
    102                                  std::string* out);
    103   void AppendAsJSON(std::string* out) const;
    104   void AppendPrettyPrinted(std::ostringstream* out) const;
    105 
    106   static void AppendValueAsJSON(unsigned char type,
    107                                 TraceValue value,
    108                                 std::string* out);
    109 
    110   TimeTicks timestamp() const { return timestamp_; }
    111 
    112   // Exposed for unittesting:
    113 
    114   const base::RefCountedString* parameter_copy_storage() const {
    115     return parameter_copy_storage_.get();
    116   }
    117 
    118   const unsigned char* category_group_enabled() const {
    119     return category_group_enabled_;
    120   }
    121 
    122   const char* name() const { return name_; }
    123 
    124  private:
    125   // Note: these are ordered by size (largest first) for optimal packing.
    126   TimeTicks timestamp_;
    127   // id_ can be used to store phase-specific data.
    128   unsigned long long id_;
    129   TraceValue arg_values_[kTraceMaxNumArgs];
    130   const char* arg_names_[kTraceMaxNumArgs];
    131   scoped_ptr<ConvertableToTraceFormat> convertable_values_[kTraceMaxNumArgs];
    132   const unsigned char* category_group_enabled_;
    133   const char* name_;
    134   scoped_refptr<base::RefCountedString> parameter_copy_storage_;
    135   int thread_id_;
    136   char phase_;
    137   unsigned char flags_;
    138   unsigned char arg_types_[kTraceMaxNumArgs];
    139 };
    140 
    141 // TraceBuffer holds the events as they are collected.
    142 class BASE_EXPORT TraceBuffer {
    143  public:
    144   virtual ~TraceBuffer() {}
    145 
    146   virtual void AddEvent(const TraceEvent& event) = 0;
    147   virtual bool HasMoreEvents() const = 0;
    148   virtual const TraceEvent& NextEvent() = 0;
    149   virtual bool IsFull() const = 0;
    150   virtual size_t CountEnabledByName(const unsigned char* category,
    151                                     const std::string& event_name) const = 0;
    152   virtual size_t Size() const = 0;
    153   virtual const TraceEvent& GetEventAt(size_t index) const = 0;
    154 };
    155 
    156 // TraceResultBuffer collects and converts trace fragments returned by TraceLog
    157 // to JSON output.
    158 class BASE_EXPORT TraceResultBuffer {
    159  public:
    160   typedef base::Callback<void(const std::string&)> OutputCallback;
    161 
    162   // If you don't need to stream JSON chunks out efficiently, and just want to
    163   // get a complete JSON string after calling Finish, use this struct to collect
    164   // JSON trace output.
    165   struct BASE_EXPORT SimpleOutput {
    166     OutputCallback GetCallback();
    167     void Append(const std::string& json_string);
    168 
    169     // Do what you want with the json_output_ string after calling
    170     // TraceResultBuffer::Finish.
    171     std::string json_output;
    172   };
    173 
    174   TraceResultBuffer();
    175   ~TraceResultBuffer();
    176 
    177   // Set callback. The callback will be called during Start with the initial
    178   // JSON output and during AddFragment and Finish with following JSON output
    179   // chunks. The callback target must live past the last calls to
    180   // TraceResultBuffer::Start/AddFragment/Finish.
    181   void SetOutputCallback(const OutputCallback& json_chunk_callback);
    182 
    183   // Start JSON output. This resets all internal state, so you can reuse
    184   // the TraceResultBuffer by calling Start.
    185   void Start();
    186 
    187   // Call AddFragment 0 or more times to add trace fragments from TraceLog.
    188   void AddFragment(const std::string& trace_fragment);
    189 
    190   // When all fragments have been added, call Finish to complete the JSON
    191   // formatted output.
    192   void Finish();
    193 
    194  private:
    195   OutputCallback output_callback_;
    196   bool append_comma_;
    197 };
    198 
    199 class BASE_EXPORT CategoryFilter {
    200  public:
    201   // The default category filter, used when none is provided.
    202   // Allows all categories through, except if they end in the suffix 'Debug' or
    203   // 'Test'.
    204   static const char* kDefaultCategoryFilterString;
    205 
    206   // |filter_string| is a comma-delimited list of category wildcards.
    207   // A category can have an optional '-' prefix to make it an excluded category.
    208   // All the same rules apply above, so for example, having both included and
    209   // excluded categories in the same list would not be supported.
    210   //
    211   // Example: CategoryFilter"test_MyTest*");
    212   // Example: CategoryFilter("test_MyTest*,test_OtherStuff");
    213   // Example: CategoryFilter("-excluded_category1,-excluded_category2");
    214   // Example: CategoryFilter("-*,webkit"); would disable everything but webkit.
    215   // Example: CategoryFilter("-webkit"); would enable everything but webkit.
    216   explicit CategoryFilter(const std::string& filter_string);
    217 
    218   CategoryFilter(const CategoryFilter& cf);
    219 
    220   ~CategoryFilter();
    221 
    222   CategoryFilter& operator=(const CategoryFilter& rhs);
    223 
    224   // Writes the string representation of the CategoryFilter. This is a comma
    225   // separated string, similar in nature to the one used to determine
    226   // enabled/disabled category patterns, except here there is an arbitrary
    227   // order, included categories go first, then excluded categories. Excluded
    228   // categories are distinguished from included categories by the prefix '-'.
    229   std::string ToString() const;
    230 
    231   // Determines whether category group would be enabled or
    232   // disabled by this category filter.
    233   bool IsCategoryGroupEnabled(const char* category_group) const;
    234 
    235   // Merges nested_filter with the current CategoryFilter
    236   void Merge(const CategoryFilter& nested_filter);
    237 
    238   // Clears both included/excluded pattern lists. This would be equivalent to
    239   // creating a CategoryFilter with an empty string, through the constructor.
    240   // i.e: CategoryFilter("").
    241   //
    242   // When using an empty filter, all categories are considered included as we
    243   // are not excluding anything.
    244   void Clear();
    245 
    246  private:
    247   FRIEND_TEST_ALL_PREFIXES(TraceEventTestFixture, CategoryFilter);
    248 
    249   static bool IsEmptyOrContainsLeadingOrTrailingWhitespace(
    250       const std::string& str);
    251 
    252   typedef std::vector<std::string> StringList;
    253 
    254   void Initialize(const std::string& filter_string);
    255   void WriteString(const StringList& values,
    256                    std::string* out,
    257                    bool included) const;
    258   bool HasIncludedPatterns() const;
    259 
    260   bool DoesCategoryGroupContainCategory(const char* category_group,
    261                                         const char* category) const;
    262 
    263   StringList included_;
    264   StringList disabled_;
    265   StringList excluded_;
    266 };
    267 
    268 class TraceSamplingThread;
    269 
    270 class BASE_EXPORT TraceLog {
    271  public:
    272   // Notification is a mask of one or more of the following events.
    273   enum Notification {
    274     // The trace buffer does not flush dynamically, so when it fills up,
    275     // subsequent trace events will be dropped. This callback is generated when
    276     // the trace buffer is full. The callback must be thread safe.
    277     TRACE_BUFFER_FULL = 1 << 0,
    278     // A subscribed trace-event occurred.
    279     EVENT_WATCH_NOTIFICATION = 1 << 1
    280   };
    281 
    282   // Options determines how the trace buffer stores data.
    283   enum Options {
    284     // Record until the trace buffer is full.
    285     RECORD_UNTIL_FULL = 1 << 0,
    286 
    287     // Record until the user ends the trace. The trace buffer is a fixed size
    288     // and we use it as a ring buffer during recording.
    289     RECORD_CONTINUOUSLY = 1 << 1,
    290 
    291     // Enable the sampling profiler.
    292     ENABLE_SAMPLING = 1 << 2,
    293 
    294     // Echo to console. Events are discarded.
    295     ECHO_TO_CONSOLE = 1 << 3
    296   };
    297 
    298   static TraceLog* GetInstance();
    299 
    300   // Convert the given string to trace options. Defaults to RECORD_UNTIL_FULL if
    301   // the string does not provide valid options.
    302   static Options TraceOptionsFromString(const std::string& str);
    303 
    304   // Get set of known category groups. This can change as new code paths are
    305   // reached. The known category groups are inserted into |category_groups|.
    306   void GetKnownCategoryGroups(std::vector<std::string>* category_groups);
    307 
    308   // Retrieves the current CategoryFilter.
    309   const CategoryFilter& GetCurrentCategoryFilter();
    310 
    311   Options trace_options() const { return trace_options_; }
    312 
    313   // Enables tracing. See CategoryFilter comments for details
    314   // on how to control what categories will be traced.
    315   void SetEnabled(const CategoryFilter& category_filter, Options options);
    316 
    317   // Disable tracing for all categories.
    318   void SetDisabled();
    319   bool IsEnabled() { return !!enable_count_; }
    320 
    321   // The number of times we have begun recording traces. If tracing is off,
    322   // returns -1. If tracing is on, then it returns the number of times we have
    323   // recorded a trace. By watching for this number to increment, you can
    324   // passively discover when a new trace has begun. This is then used to
    325   // implement the TRACE_EVENT_IS_NEW_TRACE() primitive.
    326   int GetNumTracesRecorded();
    327 
    328 #if defined(OS_ANDROID)
    329   void StartATrace();
    330   void StopATrace();
    331 #endif
    332 
    333   // Enabled state listeners give a callback when tracing is enabled or
    334   // disabled. This can be used to tie into other library's tracing systems
    335   // on-demand.
    336   class EnabledStateObserver {
    337    public:
    338     // Called just after the tracing system becomes enabled, outside of the
    339     // |lock_|.  TraceLog::IsEnabled() is true at this point.
    340     virtual void OnTraceLogEnabled() = 0;
    341 
    342     // Called just after the tracing system disables, outside of the |lock_|.
    343     // TraceLog::IsEnabled() is false at this point.
    344     virtual void OnTraceLogDisabled() = 0;
    345   };
    346   void AddEnabledStateObserver(EnabledStateObserver* listener);
    347   void RemoveEnabledStateObserver(EnabledStateObserver* listener);
    348   bool HasEnabledStateObserver(EnabledStateObserver* listener) const;
    349 
    350   float GetBufferPercentFull() const;
    351 
    352   // Set the thread-safe notification callback. The callback can occur at any
    353   // time and from any thread. WARNING: It is possible for the previously set
    354   // callback to be called during OR AFTER a call to SetNotificationCallback.
    355   // Therefore, the target of the callback must either be a global function,
    356   // ref-counted object or a LazyInstance with Leaky traits (or equivalent).
    357   typedef base::Callback<void(int)> NotificationCallback;
    358   void SetNotificationCallback(const NotificationCallback& cb);
    359 
    360   // Not using base::Callback because of its limited by 7 parameters.
    361   // Also, using primitive type allows directly passing callback from WebCore.
    362   // WARNING: It is possible for the previously set callback to be called
    363   // after a call to SetEventCallback() that replaces or clears the callback.
    364   // This callback may be invoked on any thread.
    365   typedef void (*EventCallback)(char phase,
    366                                 const unsigned char* category_group_enabled,
    367                                 const char* name,
    368                                 unsigned long long id,
    369                                 int num_args,
    370                                 const char* const arg_names[],
    371                                 const unsigned char arg_types[],
    372                                 const unsigned long long arg_values[],
    373                                 unsigned char flags);
    374   void SetEventCallback(EventCallback cb);
    375 
    376   // Flush all collected events to the given output callback. The callback will
    377   // be called one or more times with IPC-bite-size chunks. The string format is
    378   // undefined. Use TraceResultBuffer to convert one or more trace strings to
    379   // JSON.
    380   typedef base::Callback<void(const scoped_refptr<base::RefCountedString>&)>
    381       OutputCallback;
    382   void Flush(const OutputCallback& cb);
    383 
    384   // Called by TRACE_EVENT* macros, don't call this directly.
    385   // The name parameter is a category group for example:
    386   // TRACE_EVENT0("renderer,webkit", "WebViewImpl::HandleInputEvent")
    387   static const unsigned char* GetCategoryGroupEnabled(const char* name);
    388   static const char* GetCategoryGroupName(
    389       const unsigned char* category_group_enabled);
    390 
    391   // Called by TRACE_EVENT* macros, don't call this directly.
    392   // If |copy| is set, |name|, |arg_name1| and |arg_name2| will be deep copied
    393   // into the event; see "Memory scoping note" and TRACE_EVENT_COPY_XXX above.
    394   void AddTraceEvent(char phase,
    395                      const unsigned char* category_group_enabled,
    396                      const char* name,
    397                      unsigned long long id,
    398                      int num_args,
    399                      const char** arg_names,
    400                      const unsigned char* arg_types,
    401                      const unsigned long long* arg_values,
    402                      scoped_ptr<ConvertableToTraceFormat> convertable_values[],
    403                      unsigned char flags);
    404   void AddTraceEventWithThreadIdAndTimestamp(
    405       char phase,
    406       const unsigned char* category_group_enabled,
    407       const char* name,
    408       unsigned long long id,
    409       int thread_id,
    410       const TimeTicks& timestamp,
    411       int num_args,
    412       const char** arg_names,
    413       const unsigned char* arg_types,
    414       const unsigned long long* arg_values,
    415       scoped_ptr<ConvertableToTraceFormat> convertable_values[],
    416       unsigned char flags);
    417   static void AddTraceEventEtw(char phase,
    418                                const char* category_group,
    419                                const void* id,
    420                                const char* extra);
    421   static void AddTraceEventEtw(char phase,
    422                                const char* category_group,
    423                                const void* id,
    424                                const std::string& extra);
    425 
    426   // For every matching event, a notification will be fired. NOTE: the
    427   // notification will fire for each matching event that has already occurred
    428   // since tracing was started (including before tracing if the process was
    429   // started with tracing turned on).
    430   void SetWatchEvent(const std::string& category_name,
    431                      const std::string& event_name);
    432   // Cancel the watch event. If tracing is enabled, this may race with the
    433   // watch event notification firing.
    434   void CancelWatchEvent();
    435 
    436   int process_id() const { return process_id_; }
    437 
    438   // Exposed for unittesting:
    439 
    440   void InstallWaitableEventForSamplingTesting(WaitableEvent* waitable_event);
    441 
    442   // Allows deleting our singleton instance.
    443   static void DeleteForTesting();
    444 
    445   // Allow tests to inspect TraceEvents.
    446   size_t GetEventsSize() const { return logged_events_->Size(); }
    447   const TraceEvent& GetEventAt(size_t index) const {
    448     return logged_events_->GetEventAt(index);
    449   }
    450 
    451   void SetProcessID(int process_id);
    452 
    453   // Process sort indices, if set, override the order of a process will appear
    454   // relative to other processes in the trace viewer. Processes are sorted first
    455   // on their sort index, ascending, then by their name, and then tid.
    456   void SetProcessSortIndex(int sort_index);
    457 
    458   // Sets the name of the process.
    459   void SetProcessName(const std::string& process_name);
    460 
    461   // Processes can have labels in addition to their names. Use labels, for
    462   // instance, to list out the web page titles that a process is handling.
    463   void UpdateProcessLabel(int label_id, const std::string& current_label);
    464   void RemoveProcessLabel(int label_id);
    465 
    466   // Thread sort indices, if set, override the order of a thread will appear
    467   // within its process in the trace viewer. Threads are sorted first on their
    468   // sort index, ascending, then by their name, and then tid.
    469   void SetThreadSortIndex(PlatformThreadId , int sort_index);
    470 
    471   // Allow setting an offset between the current TimeTicks time and the time
    472   // that should be reported.
    473   void SetTimeOffset(TimeDelta offset);
    474 
    475   size_t GetObserverCountForTest() const;
    476 
    477  private:
    478   // This allows constructor and destructor to be private and usable only
    479   // by the Singleton class.
    480   friend struct DefaultSingletonTraits<TraceLog>;
    481 
    482   // Enable/disable each category group based on the current enable_count_
    483   // and category_filter_. Disable the category group if enabled_count_ is 0, or
    484   // if the category group contains a category that matches an included category
    485   // pattern, that category group will be enabled.
    486   // On Android, ATRACE_ENABLED flag will be applied if atrace is started.
    487   void UpdateCategoryGroupEnabledFlags();
    488   void UpdateCategoryGroupEnabledFlag(int category_index);
    489 
    490   static void SetCategoryGroupEnabled(int category_index, bool enabled);
    491   static bool IsCategoryGroupEnabled(
    492       const unsigned char* category_group_enabled);
    493 
    494   // The pointer returned from GetCategoryGroupEnabledInternal() points to a
    495   // value with zero or more of the following bits. Used in this class only.
    496   // The TRACE_EVENT macros should only use the value as a bool.
    497   enum CategoryGroupEnabledFlags {
    498     // Normal enabled flag for category groups enabled with Enable().
    499     CATEGORY_GROUP_ENABLED = 1 << 0,
    500     // On Android if ATrace is enabled, all categories will have this bit.
    501     // Not used on other platforms.
    502     ATRACE_ENABLED = 1 << 1
    503   };
    504 
    505   // Helper class for managing notification_thread_count_ and running
    506   // notification callbacks. This is very similar to a reader-writer lock, but
    507   // shares the lock with TraceLog and manages the notification flags.
    508   class NotificationHelper {
    509    public:
    510     inline explicit NotificationHelper(TraceLog* trace_log);
    511     inline ~NotificationHelper();
    512 
    513     // Called only while TraceLog::lock_ is held. This ORs the given
    514     // notification with any existing notifications.
    515     inline void AddNotificationWhileLocked(int notification);
    516 
    517     // Called only while TraceLog::lock_ is NOT held. If there are any pending
    518     // notifications from previous calls to AddNotificationWhileLocked, this
    519     // will call the NotificationCallback.
    520     inline void SendNotificationIfAny();
    521 
    522    private:
    523     TraceLog* trace_log_;
    524     NotificationCallback callback_copy_;
    525     int notification_;
    526   };
    527 
    528   TraceLog();
    529   ~TraceLog();
    530   const unsigned char* GetCategoryGroupEnabledInternal(const char* name);
    531   void AddMetadataEvents();
    532 
    533 #if defined(OS_ANDROID)
    534   void SendToATrace(char phase,
    535                     const char* category_group,
    536                     const char* name,
    537                     unsigned long long id,
    538                     int num_args,
    539                     const char** arg_names,
    540                     const unsigned char* arg_types,
    541                     const unsigned long long* arg_values,
    542                     scoped_ptr<ConvertableToTraceFormat> convertable_values[],
    543                     unsigned char flags);
    544   static void ApplyATraceEnabledFlag(unsigned char* category_group_enabled);
    545 #endif
    546 
    547   TraceBuffer* GetTraceBuffer();
    548 
    549   // TODO(nduca): switch to per-thread trace buffers to reduce thread
    550   // synchronization.
    551   // This lock protects TraceLog member accesses from arbitrary threads.
    552   Lock lock_;
    553   int enable_count_;
    554   int num_traces_recorded_;
    555   NotificationCallback notification_callback_;
    556   scoped_ptr<TraceBuffer> logged_events_;
    557   EventCallback event_callback_;
    558   bool dispatching_to_observer_list_;
    559   std::vector<EnabledStateObserver*> enabled_state_observer_list_;
    560 
    561   std::string process_name_;
    562   base::hash_map<int, std::string> process_labels_;
    563   int process_sort_index_;
    564   base::hash_map<int, int> thread_sort_indices_;
    565 
    566   base::hash_map<int, std::string> thread_names_;
    567   base::hash_map<int, std::stack<TimeTicks> > thread_event_start_times_;
    568   base::hash_map<std::string, int> thread_colors_;
    569 
    570   // XORed with TraceID to make it unlikely to collide with other processes.
    571   unsigned long long process_id_hash_;
    572 
    573   int process_id_;
    574 
    575   TimeDelta time_offset_;
    576 
    577   // Allow tests to wake up when certain events occur.
    578   const unsigned char* watch_category_;
    579   std::string watch_event_name_;
    580 
    581   Options trace_options_;
    582 
    583   // Sampling thread handles.
    584   scoped_ptr<TraceSamplingThread> sampling_thread_;
    585   PlatformThreadHandle sampling_thread_handle_;
    586 
    587   CategoryFilter category_filter_;
    588 
    589   DISALLOW_COPY_AND_ASSIGN(TraceLog);
    590 };
    591 
    592 }  // namespace debug
    593 }  // namespace base
    594 
    595 #endif  // BASE_DEBUG_TRACE_EVENT_IMPL_H_
    596