[Storage] Added tracing for blob creation

storage/browser/blob/blob_url_request_job.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "storage/browser/blob/blob_url_request_job.h"
 
 #include <algorithm>
 #include <limits>
 #include <string>
 #include <vector>
 
 #include "base/basictypes.h"
 #include "base/bind.h"
 #include "base/compiler_specific.h"
 #include "base/files/file_util_proxy.h"
 #include "base/format_macros.h"
 #include "base/message_loop/message_loop.h"
 #include "base/message_loop/message_loop_proxy.h"
 #include "base/numerics/safe_conversions.h"
 #include "base/profiler/scoped_tracker.h"
 #include "base/stl_util.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/stringprintf.h"
+#include "base/trace_event/trace_event.h"
 #include "net/base/io_buffer.h"
 #include "net/base/net_errors.h"
 #include "net/http/http_request_headers.h"
 #include "net/http/http_response_headers.h"
 #include "net/http/http_response_info.h"
 #include "net/http/http_util.h"
 #include "net/url_request/url_request.h"
 #include "net/url_request/url_request_context.h"
 #include "net/url_request/url_request_error_job.h"
 #include "net/url_request/url_request_status.h"
@@ skipping 29 matching lines @@
       file_system_context_(file_system_context),
       file_thread_proxy_(file_thread_proxy),
       total_size_(0),
       remaining_bytes_(0),
       pending_get_file_info_count_(0),
       current_item_index_(0),
       current_item_offset_(0),
       error_(false),
       byte_range_set_(false),
       weak_factory_(this) {
+  TRACE_EVENT_ASYNC_BEGIN1("Blob", "BlobRequest", this, "uuid",
+                           blob_data_->uuid());
   DCHECK(file_thread_proxy_.get());
 }
 
 void BlobURLRequestJob::Start() {
   // Continue asynchronously.
   base::MessageLoop::current()->PostTask(
       FROM_HERE,
       base::Bind(&BlobURLRequestJob::DidStart, weak_factory_.GetWeakPtr()));
 }
 
@@ skipping 73 matching lines @@
         // because we need to do multipart encoding here.
         // TODO(jianli): Support multipart byte range requests.
         NotifyFailure(net::ERR_REQUEST_RANGE_NOT_SATISFIABLE);
       }
     }
   }
 }
 
 BlobURLRequestJob::~BlobURLRequestJob() {
   STLDeleteValues(&index_to_reader_);
+  TRACE_EVENT_ASYNC_END1("Blob", "Request", this, "uuid", blob_data_->uuid());
 }
 
 void BlobURLRequestJob::DidStart() {
+  current_file_chunk_number_ = 0;
   error_ = false;
 
   // We only support GET request per the spec.
   if (request()->method() != "GET") {
     NotifyFailure(net::ERR_METHOD_NOT_SUPPORTED);
     return;
   }
 
   // If the blob data is not present, bail out.
   if (!blob_data_) {
     NotifyFailure(net::ERR_FILE_NOT_FOUND);
     return;
   }
 
   CountSize();
 }
 
 bool BlobURLRequestJob::AddItemLength(size_t index, int64 item_length) {
   if (item_length > kint64max - total_size_) {
+    TRACE_EVENT_ASYNC_END1("Blob", "BlobRequest::CountSize", this->request_,

[michaeln, 2015/03/11 23:45:08]

Why use 'this->request_' here and only 'this' elsewhere? Oh, to create a unique
trace id for each callsite?

[dmurph, 2015/03/12 18:16:21]

I thought it would solve something, but I forgot to remove it.  Using 'this' is
just fine.

+                           "uuid", blob_data_->uuid());
     NotifyFailure(net::ERR_FAILED);
     return false;
   }
 
   // Cache the size and add it to the total size.
   DCHECK_LT(index, item_length_list_.size());
   item_length_list_[index] = item_length;
   total_size_ += item_length;
   return true;
 }
 
 void BlobURLRequestJob::CountSize() {
+  TRACE_EVENT_ASYNC_BEGIN1("Blob", "BlobRequest::CountSize", this->request_,
+                           "uuid", blob_data_->uuid());
   pending_get_file_info_count_ = 0;
   total_size_ = 0;
   const auto& items = blob_data_->items();
   item_length_list_.resize(items.size());
 
   for (size_t i = 0; i < items.size(); ++i) {
     const BlobDataItem& item = *items.at(i);
     if (IsFileType(item.type())) {
       ++pending_get_file_info_count_;
       GetFileStreamReader(i)->GetLength(
           base::Bind(&BlobURLRequestJob::DidGetFileItemLength,
                      weak_factory_.GetWeakPtr(), i));
       continue;
     }
 
     if (!AddItemLength(i, item.length()))
       return;
   }
 
   if (pending_get_file_info_count_ == 0)
     DidCountSize(net::OK);
 }
 
 void BlobURLRequestJob::DidCountSize(int error) {
   DCHECK(!error_);
+  TRACE_EVENT_ASYNC_END1("Blob", "BlobRequest::CountSize", this->request_,
+                         "uuid", blob_data_->uuid());
 
   // If an error occured, bail out.
   if (error != net::OK) {
     NotifyFailure(error);
     return;
   }
 
   // Apply the range requirement.
   if (!byte_range_.ComputeBounds(total_size_)) {
     NotifyFailure(net::ERR_REQUEST_RANGE_NOT_SATISFIABLE);
@@ skipping 135 matching lines @@
   remaining_bytes_ -= result;
   DCHECK_GE(remaining_bytes_, 0);
 
   // Adjust the read buffer.
   read_buf_->DidConsume(result);
   DCHECK_GE(read_buf_->BytesRemaining(), 0);
 }
 
 bool BlobURLRequestJob::ReadBytesItem(const BlobDataItem& item,
                                       int bytes_to_read) {
+  TRACE_EVENT1("Blob", "BlobRequest::ReadBytesItem", "uuid",
+               blob_data_->uuid());
   DCHECK_GE(read_buf_->BytesRemaining(), bytes_to_read);
 
   memcpy(read_buf_->data(),
          item.bytes() + item.offset() + current_item_offset_,
          bytes_to_read);
 
   AdvanceBytesRead(bytes_to_read);
   return true;
 }
 
 bool BlobURLRequestJob::ReadFileItem(FileStreamReader* reader,
                                      int bytes_to_read) {
   DCHECK_GE(read_buf_->BytesRemaining(), bytes_to_read);
   DCHECK(reader);
-  const int result = reader->Read(
-      read_buf_.get(),
-      bytes_to_read,
-      base::Bind(&BlobURLRequestJob::DidReadFile, base::Unretained(this)));
+  int chunk_number = current_file_chunk_number_++;

[michaeln, 2015/03/11 23:45:08]

Do we need the chunk_number? I think there can only be one reader->Read() call
inflight at a given time.

For the 0th chunk, i think the id here collides with the larger "BlobRequest"
event scoped to the life of 'this'.

Maybe have an inline helper to form traceid(this, 1) and traceid(this, 2).

[dmurph, 2015/03/12 18:16:21]

It's a unique id combining the id and the category+name.  So they won't overlap.
 See here:
http://www.chromium.org/developers/how-tos/trace-event-profiling-tool/tracing...

[michaeln, 2015/03/12 20:17:32]

But if no two "BlobRequest::ReadFileItem" events for 'this' can be happening
concurrently, do we need chunkid to disambiguate current events from previously
completed events? That seems unlikely?

Just checking because we should avoid the extra data member unless its really
needed.

+  TRACE_EVENT_ASYNC_BEGIN1("Blob", "BlobRequest::ReadFileItem",
+                           this + chunk_number, "uuid", blob_data_->uuid());
+  const int result =
+      reader->Read(read_buf_.get(), bytes_to_read,
+                   base::Bind(&BlobURLRequestJob::DidReadFile,
+                              base::Unretained(this), chunk_number));
   if (result >= 0) {
     // Data is immediately available.
     if (GetStatus().is_io_pending())
-      DidReadFile(result);
+      DidReadFile(chunk_number, result);
     else
       AdvanceBytesRead(result);
     return true;
   }
   if (result == net::ERR_IO_PENDING)
     SetStatus(net::URLRequestStatus(net::URLRequestStatus::IO_PENDING, 0));
   else
     NotifyFailure(result);
   return false;
 }
 
-void BlobURLRequestJob::DidReadFile(int result) {
+void BlobURLRequestJob::DidReadFile(int chunk_number, int result) {
+  TRACE_EVENT_ASYNC_END1("Blob", "BlobRequest::ReadFileItem",
+                         this + chunk_number, "uuid", blob_data_->uuid());
   if (result <= 0) {
     NotifyFailure(net::ERR_FAILED);
     return;
   }
   SetStatus(net::URLRequestStatus());  // Clear the IO_PENDING status
 
   AdvanceBytesRead(result);
 
   // If the read buffer is completely filled, we're done.
   if (!read_buf_->BytesRemaining()) {
@@ skipping 177 matching lines @@
                    .release();
       break;
     default:
       NOTREACHED();
   }
   DCHECK(reader);
   index_to_reader_[index] = reader;
 }
 
 }  // namespace storage