gpu/command_buffer/service/gpu_tracer.cc

   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 "gpu/command_buffer/service/gpu_tracer.h"
   6
   7 #include <deque>
   8
   9 #include "base/bind.h"
  10 #include "base/debug/trace_event.h"
  11 #include "base/strings/string_util.h"
  12 #include "base/time/time.h"
  13 #include "gpu/command_buffer/common/gles2_cmd_utils.h"
  14
  15 namespace gpu {
  16 namespace gles2 {
  17
  18 static const unsigned int kProcessInterval = 16;
  19 static TraceOutputter* g_outputter_thread = NULL;
  20
  21 TraceMarker::TraceMarker(const std::string& name)
  22     : name_(name),
  23       trace_(NULL) {
  24 }
  25
  26 TraceMarker::~TraceMarker() {
  27 }
  28
  29 scoped_refptr<TraceOutputter> TraceOutputter::Create(const std::string& name) {
  30   if (!g_outputter_thread) {
  31     g_outputter_thread = new TraceOutputter(name);
  32   }
  33   return g_outputter_thread;
  34 }
  35
  36 TraceOutputter::TraceOutputter(const std::string& name)
  37     : named_thread_(name.c_str()), local_trace_id_(0) {
  38   named_thread_.Start();
  39   named_thread_.Stop();
  40 }
  41
  42 TraceOutputter::~TraceOutputter() { g_outputter_thread = NULL; }
  43
  44 void TraceOutputter::Trace(const std::string& name,
  45                            int64 start_time,
  46                            int64 end_time) {
  47   TRACE_EVENT_COPY_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
  48       TRACE_DISABLED_BY_DEFAULT("gpu.device"),
  49       name.c_str(),
  50       local_trace_id_,
  51       named_thread_.thread_id(),
  52       start_time);
  53   TRACE_EVENT_COPY_END_WITH_ID_TID_AND_TIMESTAMP0(
  54       TRACE_DISABLED_BY_DEFAULT("gpu.device"),
  55       name.c_str(),
  56       local_trace_id_,
  57       named_thread_.thread_id(),
  58       end_time);
  59   ++local_trace_id_;
  60 }
  61
  62 GPUTrace::GPUTrace(scoped_refptr<Outputter> outputter,
  63                    const std::string& name,
  64                    int64 offset,
  65                    GpuTracerType tracer_type)
  66     : name_(name),
  67       outputter_(outputter),
  68       offset_(offset),
  69       start_time_(0),
  70       end_time_(0),
  71       tracer_type_(tracer_type),
  72       end_requested_(false) {
  73   memset(queries_, 0, sizeof(queries_));
  74   switch (tracer_type_) {
  75     case kTracerTypeARBTimer:
  76     case kTracerTypeDisjointTimer:
  77       glGenQueriesARB(2, queries_);
  78       break;
  79
  80     default:
  81       tracer_type_ = kTracerTypeInvalid;
  82   }
  83 }
  84
  85 GPUTrace::~GPUTrace() {
  86   switch (tracer_type_) {
  87     case kTracerTypeInvalid:
  88       break;
  89
  90     case kTracerTypeARBTimer:
  91     case kTracerTypeDisjointTimer:
  92       glDeleteQueriesARB(2, queries_);
  93       break;
  94   }
  95 }
  96
  97 void GPUTrace::Start() {
  98   TRACE_EVENT_COPY_ASYNC_BEGIN0(
  99       TRACE_DISABLED_BY_DEFAULT("gpu.service"), name().c_str(), this);
 100
 101   switch (tracer_type_) {
 102     case kTracerTypeInvalid:
 103       break;
 104
 105     case kTracerTypeDisjointTimer:
 106       // For the disjoint timer, GPU idle time does not seem to increment the
 107       // internal counter. We must calculate the offset before any query. The
 108       // good news is any device that supports disjoint timer will also support
 109       // glGetInteger64v, so we can query it directly unlike the ARBTimer case.
 110       // The "offset_" variable will always be 0 during normal use cases, only
 111       // under the unit tests will it be set to specific test values.
 112       if (offset_ == 0) {
 113         GLint64 gl_now = 0;
 114         glGetInteger64v(GL_TIMESTAMP, &gl_now);
 115         offset_ = base::TimeTicks::NowFromSystemTraceTime().ToInternalValue() -
 116                   gl_now / base::Time::kNanosecondsPerMicrosecond;
 117       }
 118       // Intentionally fall through to kTracerTypeARBTimer case.xs
 119     case kTracerTypeARBTimer:
 120       // GL_TIMESTAMP and GL_TIMESTAMP_EXT both have the same value.
 121       glQueryCounter(queries_[0], GL_TIMESTAMP);
 122       break;
 123   }
 124 }
 125
 126 void GPUTrace::End() {
 127   end_requested_ = true;
 128   switch (tracer_type_) {
 129     case kTracerTypeInvalid:
 130       break;
 131
 132     case kTracerTypeARBTimer:
 133     case kTracerTypeDisjointTimer:
 134       // GL_TIMESTAMP and GL_TIMESTAMP_EXT both have the same value.
 135       glQueryCounter(queries_[1], GL_TIMESTAMP);
 136       break;
 137   }
 138
 139   TRACE_EVENT_COPY_ASYNC_END0(
 140       TRACE_DISABLED_BY_DEFAULT("gpu.service"), name().c_str(), this);
 141 }
 142
 143 bool GPUTrace::IsAvailable() {
 144   if (tracer_type_ != kTracerTypeInvalid) {
 145     if (!end_requested_)
 146       return false;
 147
 148     GLint done = 0;
 149     glGetQueryObjectiv(queries_[1], GL_QUERY_RESULT_AVAILABLE, &done);
 150     return !!done;
 151   }
 152
 153   return true;
 154 }
 155
 156 void GPUTrace::Process() {
 157   if (tracer_type_ == kTracerTypeInvalid)
 158     return;
 159
 160   DCHECK(IsAvailable());
 161
 162   GLuint64 begin_stamp = 0;
 163   GLuint64 end_stamp = 0;
 164
 165   // TODO(dsinclair): It's possible for the timer to wrap during the start/end.
 166   // We need to detect if the end is less then the start and correct for the
 167   // wrapping.
 168   glGetQueryObjectui64v(queries_[0], GL_QUERY_RESULT, &begin_stamp);
 169   glGetQueryObjectui64v(queries_[1], GL_QUERY_RESULT, &end_stamp);
 170
 171   start_time_ = (begin_stamp / base::Time::kNanosecondsPerMicrosecond) +
 172                 offset_;
 173   end_time_ = (end_stamp / base::Time::kNanosecondsPerMicrosecond) + offset_;
 174   outputter_->Trace(name(), start_time_, end_time_);
 175 }
 176
 177 GPUTracer::GPUTracer(gles2::GLES2Decoder* decoder)
 178     : gpu_trace_srv_category(TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
 179           TRACE_DISABLED_BY_DEFAULT("gpu.service"))),
 180       gpu_trace_dev_category(TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
 181           TRACE_DISABLED_BY_DEFAULT("gpu.device"))),
 182       decoder_(decoder),
 183       timer_offset_(0),
 184       last_tracer_source_(kTraceGroupInvalid),
 185       tracer_type_(kTracerTypeInvalid),
 186       gpu_timing_synced_(false),
 187       gpu_executing_(false),
 188       process_posted_(false) {
 189   if (gfx::g_driver_gl.ext.b_GL_EXT_disjoint_timer_query) {
 190     tracer_type_ = kTracerTypeDisjointTimer;
 191     outputter_ = TraceOutputter::Create("GL_EXT_disjoint_timer_query");
 192   } else if (gfx::g_driver_gl.ext.b_GL_ARB_timer_query) {
 193     tracer_type_ = kTracerTypeARBTimer;
 194     outputter_ = TraceOutputter::Create("GL_ARB_timer_query");
 195   }
 196 }
 197
 198 GPUTracer::~GPUTracer() {
 199 }
 200
 201 bool GPUTracer::BeginDecoding() {
 202   if (gpu_executing_)
 203     return false;
 204
 205   CalculateTimerOffset();
 206   gpu_executing_ = true;
 207
 208   if (IsTracing()) {
 209     // Reset disjoint bit for the disjoint timer.
 210     if (tracer_type_ == kTracerTypeDisjointTimer) {
 211       GLint disjoint_value = 0;
 212       glGetIntegerv(GL_GPU_DISJOINT_EXT, &disjoint_value);
 213     }
 214
 215     // Begin a Trace for all active markers
 216     for (int n = 0; n < NUM_TRACER_SOURCES; n++) {
 217       for (size_t i = 0; i < markers_[n].size(); i++) {
 218         markers_[n][i].trace_ = CreateTrace(markers_[n][i].name_);
 219         markers_[n][i].trace_->Start();
 220       }
 221     }
 222   }
 223   return true;
 224 }
 225
 226 bool GPUTracer::EndDecoding() {
 227   if (!gpu_executing_)
 228     return false;
 229
 230   // End Trace for all active markers
 231   if (IsTracing()) {
 232     for (int n = 0; n < NUM_TRACER_SOURCES; n++) {
 233       for (size_t i = 0; i < markers_[n].size(); i++) {
 234         if (markers_[n][i].trace_.get()) {
 235           markers_[n][i].trace_->End();
 236           if (markers_[n][i].trace_->IsEnabled())
 237             traces_.push_back(markers_[n][i].trace_);
 238           markers_[n][i].trace_ = 0;
 239         }
 240       }
 241     }
 242     IssueProcessTask();
 243   }
 244
 245   gpu_executing_ = false;
 246
 247   // NOTE(vmiura): glFlush() here can help give better trace results,
 248   // but it distorts the normal device behavior.
 249   return true;
 250 }
 251
 252 bool GPUTracer::Begin(const std::string& name, GpuTracerSource source) {
 253   if (!gpu_executing_)
 254     return false;
 255
 256   DCHECK(source >= 0 && source < NUM_TRACER_SOURCES);
 257
 258   // Push new marker from given 'source'
 259   last_tracer_source_ = source;
 260   markers_[source].push_back(TraceMarker(name));
 261
 262   // Create trace
 263   if (IsTracing()) {
 264     scoped_refptr<GPUTrace> trace = CreateTrace(name);
 265     trace->Start();
 266     markers_[source].back().trace_ = trace;
 267   }
 268
 269   return true;
 270 }
 271
 272 bool GPUTracer::End(GpuTracerSource source) {
 273   if (!gpu_executing_)
 274     return false;
 275
 276   DCHECK(source >= 0 && source < NUM_TRACER_SOURCES);
 277
 278   // Pop last marker with matching 'source'
 279   if (!markers_[source].empty()) {
 280     if (IsTracing()) {
 281       scoped_refptr<GPUTrace> trace = markers_[source].back().trace_;
 282       if (trace.get()) {
 283         trace->End();
 284         if (trace->IsEnabled())
 285           traces_.push_back(trace);
 286         IssueProcessTask();
 287       }
 288     }
 289
 290     markers_[source].pop_back();
 291     return true;
 292   }
 293   return false;
 294 }
 295
 296 bool GPUTracer::IsTracing() {
 297   return (*gpu_trace_srv_category != 0) || (*gpu_trace_dev_category != 0);
 298 }
 299
 300 const std::string& GPUTracer::CurrentName() const {
 301   if (last_tracer_source_ >= 0 &&
 302       last_tracer_source_ < NUM_TRACER_SOURCES &&
 303       !markers_[last_tracer_source_].empty()) {
 304     return markers_[last_tracer_source_].back().name_;
 305   }
 306   return base::EmptyString();
 307 }
 308
 309 scoped_refptr<GPUTrace> GPUTracer::CreateTrace(const std::string& name) {
 310   GpuTracerType tracer_type = *gpu_trace_dev_category ? tracer_type_ :
 311                                                         kTracerTypeInvalid;
 312
 313   return new GPUTrace(outputter_, name, timer_offset_, tracer_type);
 314 }
 315
 316 void GPUTracer::Process() {
 317   process_posted_ = false;
 318   ProcessTraces();
 319   IssueProcessTask();
 320 }
 321
 322 void GPUTracer::ProcessTraces() {
 323   if (tracer_type_ == kTracerTypeInvalid) {
 324     traces_.clear();
 325     return;
 326   }
 327
 328   TRACE_EVENT0("gpu", "GPUTracer::ProcessTraces");
 329
 330   // Make owning decoder's GL context current
 331   if (!decoder_->MakeCurrent()) {
 332     // Skip subsequent GL calls if MakeCurrent fails
 333     traces_.clear();
 334     return;
 335   }
 336
 337   // Check if disjoint operation has occurred, discard ongoing traces if so.
 338   if (tracer_type_ == kTracerTypeDisjointTimer) {
 339     GLint disjoint_value = 0;
 340     glGetIntegerv(GL_GPU_DISJOINT_EXT, &disjoint_value);
 341     if (disjoint_value)
 342       traces_.clear();
 343   }
 344
 345   while (!traces_.empty() && traces_.front()->IsAvailable()) {
 346     traces_.front()->Process();
 347     traces_.pop_front();
 348   }
 349
 350   // Clear pending traces if there were are any errors
 351   GLenum err = glGetError();
 352   if (err != GL_NO_ERROR)
 353     traces_.clear();
 354 }
 355
 356 void GPUTracer::CalculateTimerOffset() {
 357   if (tracer_type_ != kTracerTypeInvalid) {
 358     if (*gpu_trace_dev_category == '\0') {
 359       // If GPU device category is off, invalidate timing sync.
 360       gpu_timing_synced_ = false;
 361       return;
 362     } else if (tracer_type_ == kTracerTypeDisjointTimer) {
 363       // Disjoint timers offsets should be calculated before every query.
 364       gpu_timing_synced_ = true;
 365       timer_offset_ = 0;
 366     }
 367
 368     if (gpu_timing_synced_)
 369       return;
 370
 371     TRACE_EVENT0("gpu", "GPUTracer::CalculateTimerOffset");
 372
 373     // NOTE(vmiura): It would be better to use glGetInteger64v, however
 374     // it's not available everywhere.
 375     GLuint64 gl_now = 0;
 376     GLuint query;
 377
 378     glGenQueriesARB(1, &query);
 379
 380     glFinish();
 381     glQueryCounter(query, GL_TIMESTAMP);
 382     glFinish();
 383
 384     glGetQueryObjectui64v(query, GL_QUERY_RESULT, &gl_now);
 385     glDeleteQueriesARB(1, &query);
 386
 387     base::TimeTicks system_now = base::TimeTicks::NowFromSystemTraceTime();
 388
 389     gl_now /= base::Time::kNanosecondsPerMicrosecond;
 390     timer_offset_ = system_now.ToInternalValue() - gl_now;
 391     gpu_timing_synced_ = true;
 392   }
 393 }
 394
 395 void GPUTracer::IssueProcessTask() {
 396   if (traces_.empty() || process_posted_)
 397     return;
 398
 399   process_posted_ = true;
 400   base::MessageLoop::current()->PostDelayedTask(
 401       FROM_HERE,
 402       base::Bind(&GPUTracer::Process, base::AsWeakPtr(this)),
 403       base::TimeDelta::FromMilliseconds(kProcessInterval));
 404 }
 405
 406 }  // namespace gles2
 407 }  // namespace gpu