Home | History | Annotate | Download | only in tracing 
      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 #include "content/browser/tracing/trace_controller_impl.h"
      6 
      7 #include "base/bind.h"
      8 #include "base/command_line.h"
      9 #include "base/debug/trace_event.h"
     10 #include "base/strings/string_number_conversions.h"
     11 #include "content/browser/tracing/trace_message_filter.h"
     12 #include "content/browser/tracing/trace_subscriber_stdio.h"
     13 #include "content/common/child_process_messages.h"
     14 #include "content/public/browser/browser_message_filter.h"
     15 #include "content/public/common/content_switches.h"
     16 
     17 using base::debug::TraceLog;
     18 
     19 namespace content {
     20 
     21 namespace {
     22 
     23 base::LazyInstance<TraceControllerImpl>::Leaky g_controller =
     24     LAZY_INSTANCE_INITIALIZER;
     25 
     26 class AutoStopTraceSubscriberStdio : public TraceSubscriberStdio {
     27  public:
     28   AutoStopTraceSubscriberStdio(const base::FilePath& file_path)
     29       : TraceSubscriberStdio(file_path) {}
     30 
     31   static void EndStartupTrace(TraceSubscriberStdio* subscriber) {
     32     if (!TraceControllerImpl::GetInstance()->EndTracingAsync(subscriber))
     33       delete subscriber;
     34     // else, the tracing will end asynchronously in OnEndTracingComplete().
     35   }
     36 
     37   virtual void OnEndTracingComplete() OVERRIDE {
     38     TraceSubscriberStdio::OnEndTracingComplete();
     39     delete this;
     40     // TODO(joth): this would be the time to automatically open up
     41     // chrome://tracing/ and load up the trace data collected.
     42   }
     43 };
     44 
     45 }  // namespace
     46 
     47 TraceController* TraceController::GetInstance() {
     48   return TraceControllerImpl::GetInstance();
     49 }
     50 
     51 TraceControllerImpl::TraceControllerImpl() :
     52     subscriber_(NULL),
     53     pending_end_ack_count_(0),
     54     pending_bpf_ack_count_(0),
     55     maximum_bpf_(0.0f),
     56     is_tracing_(false),
     57     is_get_category_groups_(false),
     58     category_filter_(
     59         base::debug::CategoryFilter::kDefaultCategoryFilterString) {
     60   TraceLog::GetInstance()->SetNotificationCallback(
     61       base::Bind(&TraceControllerImpl::OnTraceNotification,
     62                  base::Unretained(this)));
     63 }
     64 
     65 TraceControllerImpl::~TraceControllerImpl() {
     66   // No need to SetNotificationCallback(nil) on the TraceLog since this is a
     67   // Leaky instance.
     68   NOTREACHED();
     69 }
     70 
     71 TraceControllerImpl* TraceControllerImpl::GetInstance() {
     72   return g_controller.Pointer();
     73 }
     74 
     75 void TraceControllerImpl::InitStartupTracing(const CommandLine& command_line) {
     76   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
     77   base::FilePath trace_file = command_line.GetSwitchValuePath(
     78       switches::kTraceStartupFile);
     79   // trace_file = "none" means that startup events will show up for the next
     80   // begin/end tracing (via about:tracing or AutomationProxy::BeginTracing/
     81   // EndTracing, for example).
     82   if (trace_file == base::FilePath().AppendASCII("none"))
     83     return;
     84 
     85   if (trace_file.empty()) {
     86     // Default to saving the startup trace into the current dir.
     87     trace_file = base::FilePath().AppendASCII("chrometrace.log");
     88   }
     89   scoped_ptr<AutoStopTraceSubscriberStdio> subscriber(
     90       new AutoStopTraceSubscriberStdio(trace_file));
     91   DCHECK(can_begin_tracing(subscriber.get()));
     92 
     93   std::string delay_str = command_line.GetSwitchValueASCII(
     94       switches::kTraceStartupDuration);
     95   int delay_secs = 5;
     96   if (!delay_str.empty() && !base::StringToInt(delay_str, &delay_secs)) {
     97     DLOG(WARNING) << "Could not parse --" << switches::kTraceStartupDuration
     98         << "=" << delay_str << " defaulting to 5 (secs)";
     99     delay_secs = 5;
    100   }
    101 
    102   OnTracingBegan(subscriber.get());
    103   BrowserThread::PostDelayedTask(
    104       BrowserThread::UI,
    105       FROM_HERE,
    106       base::Bind(&AutoStopTraceSubscriberStdio::EndStartupTrace,
    107                  base::Unretained(subscriber.release())),
    108       base::TimeDelta::FromSeconds(delay_secs));
    109 }
    110 
    111 bool TraceControllerImpl::GetKnownCategoryGroupsAsync(
    112     TraceSubscriber* subscriber) {
    113   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
    114 
    115   // Known categories come back from child processes with the EndTracingAck
    116   // message. So to get known categories, just begin and end tracing immediately
    117   // afterwards. This will ping all the child processes for categories.
    118   is_get_category_groups_ = true;
    119   bool success = BeginTracing(subscriber, "*",
    120                               TraceLog::GetInstance()->trace_options()) &&
    121                  EndTracingAsync(subscriber);
    122   is_get_category_groups_ = success;
    123   return success;
    124 }
    125 
    126 bool TraceControllerImpl::BeginTracing(TraceSubscriber* subscriber,
    127                                        const std::string& category_patterns,
    128                                        base::debug::TraceLog::Options options) {
    129   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
    130 
    131   if (!can_begin_tracing(subscriber))
    132     return false;
    133 
    134   // Enable tracing
    135   TraceLog::GetInstance()->SetEnabled(
    136       base::debug::CategoryFilter(category_patterns), options);
    137 
    138   OnTracingBegan(subscriber);
    139 
    140   return true;
    141 }
    142 
    143 bool TraceControllerImpl::EndTracingAsync(TraceSubscriber* subscriber) {
    144   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
    145 
    146   if (!can_end_tracing() || subscriber != subscriber_)
    147     return false;
    148 
    149   // There could be a case where there are no child processes and filters_
    150   // is empty. In that case we can immediately tell the subscriber that tracing
    151   // has ended. To avoid recursive calls back to the subscriber, we will just
    152   // use the existing asynchronous OnEndTracingAck code.
    153   // Count myself (local trace) in pending_end_ack_count_, acked below.
    154   pending_end_ack_count_ = filters_.size() + 1;
    155 
    156   // Handle special case of zero child processes.
    157   if (pending_end_ack_count_ == 1) {
    158     // Ack asynchronously now, because we don't have any children to wait for.
    159     std::vector<std::string> category_groups;
    160     TraceLog::GetInstance()->GetKnownCategoryGroups(&category_groups);
    161     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    162         base::Bind(&TraceControllerImpl::OnEndTracingAck,
    163                    base::Unretained(this), category_groups));
    164   }
    165 
    166   // Notify all child processes.
    167   for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it) {
    168     it->get()->SendEndTracing();
    169   }
    170 
    171   return true;
    172 }
    173 
    174 bool TraceControllerImpl::GetTraceBufferPercentFullAsync(
    175     TraceSubscriber* subscriber) {
    176   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
    177 
    178   if (!can_get_buffer_percent_full() || subscriber != subscriber_)
    179     return false;
    180 
    181   maximum_bpf_ = 0.0f;
    182   pending_bpf_ack_count_ = filters_.size() + 1;
    183 
    184   // Handle special case of zero child processes.
    185   if (pending_bpf_ack_count_ == 1) {
    186     // Ack asynchronously now, because we don't have any children to wait for.
    187     float bpf = TraceLog::GetInstance()->GetBufferPercentFull();
    188     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    189         base::Bind(&TraceControllerImpl::OnTraceBufferPercentFullReply,
    190                    base::Unretained(this), bpf));
    191   }
    192 
    193   // Message all child processes.
    194   for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it) {
    195     it->get()->SendGetTraceBufferPercentFull();
    196   }
    197 
    198   return true;
    199 }
    200 
    201 bool TraceControllerImpl::SetWatchEvent(TraceSubscriber* subscriber,
    202                                         const std::string& category_name,
    203                                         const std::string& event_name) {
    204   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
    205   if (subscriber != subscriber_)
    206     return false;
    207 
    208   watch_category_ = category_name;
    209   watch_name_ = event_name;
    210 
    211   TraceLog::GetInstance()->SetWatchEvent(category_name, event_name);
    212   for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it)
    213     it->get()->SendSetWatchEvent(category_name, event_name);
    214 
    215   return true;
    216 }
    217 
    218 bool TraceControllerImpl::CancelWatchEvent(TraceSubscriber* subscriber) {
    219   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
    220   if (subscriber != subscriber_)
    221     return false;
    222 
    223   watch_category_.clear();
    224   watch_name_.clear();
    225 
    226   TraceLog::GetInstance()->CancelWatchEvent();
    227   for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it)
    228     it->get()->SendCancelWatchEvent();
    229 
    230   return true;
    231 }
    232 
    233 void TraceControllerImpl::CancelSubscriber(TraceSubscriber* subscriber) {
    234   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
    235 
    236   if (subscriber == subscriber_) {
    237     subscriber_ = NULL;
    238     // End tracing if necessary.
    239     if (is_tracing_ && pending_end_ack_count_ == 0)
    240       EndTracingAsync(NULL);
    241   }
    242 }
    243 
    244 void TraceControllerImpl::AddFilter(TraceMessageFilter* filter) {
    245   if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) {
    246     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    247         base::Bind(&TraceControllerImpl::AddFilter, base::Unretained(this),
    248                    make_scoped_refptr(filter)));
    249     return;
    250   }
    251 
    252   filters_.insert(filter);
    253   if (is_tracing_enabled()) {
    254     std::string cf_str = category_filter_.ToString();
    255     filter->SendBeginTracing(cf_str, trace_options_);
    256     if (!watch_category_.empty())
    257       filter->SendSetWatchEvent(watch_category_, watch_name_);
    258   }
    259 }
    260 
    261 void TraceControllerImpl::RemoveFilter(TraceMessageFilter* filter) {
    262   if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) {
    263     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    264         base::Bind(&TraceControllerImpl::RemoveFilter, base::Unretained(this),
    265                    make_scoped_refptr(filter)));
    266     return;
    267   }
    268 
    269   filters_.erase(filter);
    270 }
    271 
    272 void TraceControllerImpl::OnTracingBegan(TraceSubscriber* subscriber) {
    273   is_tracing_ = true;
    274 
    275   subscriber_ = subscriber;
    276 
    277   category_filter_ = TraceLog::GetInstance()->GetCurrentCategoryFilter();
    278   trace_options_ = TraceLog::GetInstance()->trace_options();
    279 
    280   // Notify all child processes.
    281   for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it) {
    282     it->get()->SendBeginTracing(category_filter_.ToString(), trace_options_);
    283   }
    284 }
    285 
    286 void TraceControllerImpl::OnEndTracingAck(
    287     const std::vector<std::string>& known_category_groups) {
    288   if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) {
    289     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    290         base::Bind(&TraceControllerImpl::OnEndTracingAck,
    291                    base::Unretained(this), known_category_groups));
    292     return;
    293   }
    294 
    295   // Merge known_category_groups with known_category_groups_
    296   known_category_groups_.insert(known_category_groups.begin(),
    297                                 known_category_groups.end());
    298 
    299   if (pending_end_ack_count_ == 0)
    300     return;
    301 
    302   if (--pending_end_ack_count_ == 0) {
    303     // All acks have been received.
    304     is_tracing_ = false;
    305 
    306     // Disable local trace.
    307     TraceLog::GetInstance()->SetDisabled();
    308 
    309     // During this call, our OnTraceDataCollected will be
    310     // called with the last of the local trace data. Since we are on the UI
    311     // thread, the call to OnTraceDataCollected will be synchronous, so we can
    312     // immediately call OnEndTracingComplete below.
    313     TraceLog::GetInstance()->Flush(
    314         base::Bind(&TraceControllerImpl::OnTraceDataCollected,
    315                    base::Unretained(this)));
    316 
    317     // Trigger callback if one is set.
    318     if (subscriber_) {
    319       if (is_get_category_groups_)
    320         subscriber_->OnKnownCategoriesCollected(known_category_groups_);
    321       else
    322         subscriber_->OnEndTracingComplete();
    323       // Clear subscriber so that others can use TraceController.
    324       subscriber_ = NULL;
    325     }
    326 
    327     is_get_category_groups_ = false;
    328   }
    329 
    330   if (pending_end_ack_count_ == 1) {
    331     // The last ack represents local trace, so we need to ack it now. Note that
    332     // this code only executes if there were child processes.
    333     std::vector<std::string> category_groups;
    334     TraceLog::GetInstance()->GetKnownCategoryGroups(&category_groups);
    335     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    336         base::Bind(&TraceControllerImpl::OnEndTracingAck,
    337                    base::Unretained(this), category_groups));
    338   }
    339 }
    340 
    341 void TraceControllerImpl::OnTraceDataCollected(
    342     const scoped_refptr<base::RefCountedString>& events_str_ptr) {
    343   // OnTraceDataCollected may be called from any browser thread, either by the
    344   // local event trace system or from child processes via TraceMessageFilter.
    345   if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) {
    346     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    347         base::Bind(&TraceControllerImpl::OnTraceDataCollected,
    348                    base::Unretained(this), events_str_ptr));
    349     return;
    350   }
    351 
    352   // Drop trace events if we are just getting categories.
    353   if (subscriber_ && !is_get_category_groups_)
    354     subscriber_->OnTraceDataCollected(events_str_ptr);
    355 }
    356 
    357 void TraceControllerImpl::OnTraceNotification(int notification) {
    358   // OnTraceNotification may be called from any browser thread, either by the
    359   // local event trace system or from child processes via TraceMessageFilter.
    360   if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) {
    361     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    362         base::Bind(&TraceControllerImpl::OnTraceNotification,
    363                    base::Unretained(this), notification));
    364     return;
    365   }
    366 
    367   if (notification & base::debug::TraceLog::TRACE_BUFFER_FULL) {
    368     // EndTracingAsync may return false if tracing is already in the process
    369     // of being ended. That is ok.
    370     EndTracingAsync(subscriber_);
    371   }
    372   if (notification & base::debug::TraceLog::EVENT_WATCH_NOTIFICATION) {
    373     if (subscriber_)
    374       subscriber_->OnEventWatchNotification();
    375   }
    376 }
    377 
    378 void TraceControllerImpl::OnTraceBufferPercentFullReply(float percent_full) {
    379   if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) {
    380     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    381         base::Bind(&TraceControllerImpl::OnTraceBufferPercentFullReply,
    382                    base::Unretained(this), percent_full));
    383     return;
    384   }
    385 
    386   if (pending_bpf_ack_count_ == 0)
    387     return;
    388 
    389   maximum_bpf_ = (maximum_bpf_ > percent_full)? maximum_bpf_ : percent_full;
    390 
    391   if (--pending_bpf_ack_count_ == 0) {
    392     // Trigger callback if one is set.
    393     if (subscriber_)
    394       subscriber_->OnTraceBufferPercentFullReply(maximum_bpf_);
    395   }
    396 
    397   if (pending_bpf_ack_count_ == 1) {
    398     // The last ack represents local trace, so we need to ack it now. Note that
    399     // this code only executes if there were child processes.
    400     float bpf = TraceLog::GetInstance()->GetBufferPercentFull();
    401     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
    402         base::Bind(&TraceControllerImpl::OnTraceBufferPercentFullReply,
    403                    base::Unretained(this), bpf));
    404   }
    405 }
    406 
    407 }  // namespace content
    408