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