drive: Add some event logging in DriveScheduler

This should be helpful to understand interaction with the server.
Example:

2013-04-25T13:00:46.217: Drive mount point is added
2013-04-25T13:00:51.476: Queue job: TYPE_GET_APP_LIST [1]
2013-04-25T13:00:51.476: Start job: TYPE_GET_APP_LIST [1]
2013-04-25T13:00:51.476: Queue job: TYPE_GET_ABOUT_RESOURCE [2]
2013-04-25T13:00:51.476: Start job: TYPE_GET_ABOUT_RESOURCE [2]
2013-04-25T13:00:51.512: Queue job: TYPE_GET_ABOUT_RESOURCE [3]
2013-04-25T13:00:51.512: Start job: TYPE_GET_ABOUT_RESOURCE [3]
2013-04-25T13:00:51.593: Queue job: TYPE_GET_ABOUT_RESOURCE [4]
2013-04-25T13:00:51.593: Start job: TYPE_GET_ABOUT_RESOURCE [4]
2013-04-25T13:00:52.056: Job done: TYPE_GET_ABOUT_RESOURCE [2] => FILE_ERROR_OK (elapsed time: 580ms)
2013-04-25T13:00:52.066: Job done: TYPE_GET_APP_LIST [1] => FILE_ERROR_OK (elapsed time: 590ms)
2013-04-25T13:00:52.072: Job done: TYPE_GET_ABOUT_RESOURCE [3] => FILE_ERROR_OK (elapsed time: 560ms)
2013-04-25T13:00:52.074: Job done: TYPE_GET_ABOUT_RESOURCE [4] => FILE_ERROR_OK (elapsed time: 481ms)
2013-04-25T13:00:54.172: Queue job: TYPE_GET_ABOUT_RESOURCE [5]
2013-04-25T13:00:54.172: Start job: TYPE_GET_ABOUT_RESOURCE [5]
2013-04-25T13:00:54.515: Job done: TYPE_GET_ABOUT_RESOURCE [5] => FILE_ERROR_OK (elapsed time: 342ms)

BUG=233448
TEST=open Drive in Files.app; go to chrome:drive-internals; confirm that lots of messages are shown in "Event Log" section.

Review URL: https://codereview.chromium.org/14416004

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@196334 0039d316-1c4b-4281-b951-d872f2087c98

4 files changed, 31 insertions, 9 deletions

diff --git a/chrome/browser/chromeos/drive/drive_scheduler.cc b/chrome/browser/chromeos/drive/drive_scheduler.cc
index ec5b5a8..61e9659 100644
--- a/chrome/browser/chromeos/drive/drive_scheduler.cc
+++ b/chrome/browser/chromeos/drive/drive_scheduler.cc
@@ -10,7 +10,9 @@
 #include "base/prefs/pref_service.h"
 #include "base/rand_util.h"
 #include "base/stl_util.h"
+#include "base/strings/string_number_conversions.h"
 #include "chrome/browser/chromeos/drive/drive_file_system_util.h"
+#include "chrome/browser/chromeos/drive/logging.h"
 #include "chrome/browser/google_apis/drive_api_parser.h"
 #include "chrome/browser/google_apis/gdata_wapi_parser.h"
 #include "chrome/browser/profiles/profile.h"
@@ -394,6 +396,9 @@ void DriveScheduler::QueueJob(scoped_ptr<QueueEntry> job) {
 
   JobInfo* job_info = job_map_.Lookup(job->job_id);
   DCHECK(job_info);
+  util::Log("Queue job: %s [%d]",
+            JobTypeToString(job_info->job_type).c_str(),
+            job_info->job_id);
 
   QueueType queue_type = GetJobQueueType(job_info->job_type);
   std::list<QueueEntry*>& queue = queue_[queue_type];
@@ -431,11 +436,15 @@ void DriveScheduler::DoJobLoop(QueueType queue_type) {
   JobInfo* job_info = job_map_.Lookup(queue_entry->job_id);
   DCHECK(job_info);
   job_info->state = STATE_RUNNING;
+  job_info->start_time = base::Time::Now();
   NotifyJobUpdated(*job_info);
 
   // The some arguments are evaluated after bind, so we copy the pointer to the
   // QueueEntry
   QueueEntry* entry = queue_entry.get();
+  util::Log("Start job: %s [%d]",
+            JobTypeToString(job_info->job_type).c_str(),
+            job_info->job_id);
 
   switch (job_info->job_type) {
     case TYPE_GET_ABOUT_RESOURCE: {
@@ -709,6 +718,13 @@ scoped_ptr<DriveScheduler::QueueEntry> DriveScheduler::OnJobDone(
   DCHECK(job_info);
   QueueType queue_type = GetJobQueueType(job_info->job_type);
 
+  const base::TimeDelta elapsed = base::Time::Now() - job_info->start_time;
+  util::Log("Job done: %s [%d] => %s (elapsed time: %sms)",
+            JobTypeToString(job_info->job_type).c_str(),
+            job_info->job_id,
+            FileErrorToString(error).c_str(),
+            base::Int64ToString(elapsed.InMilliseconds()).c_str());
+
   // Decrement the number of jobs for this queue.
   --jobs_running_[queue_type];
 
diff --git a/chrome/browser/chromeos/drive/drive_system_service.cc b/chrome/browser/chromeos/drive/drive_system_service.cc
index 4faf5f6..ca0e9f6 100644
--- a/chrome/browser/chromeos/drive/drive_system_service.cc
+++ b/chrome/browser/chromeos/drive/drive_system_service.cc
@@ -314,7 +314,7 @@ void DriveSystemService::AddDriveMountPoint() {
       drive_mount_point);
 
   if (success) {
-    util::Log("AddDriveMountPoint");
+    util::Log("Drive mount point is added");
     FOR_EACH_OBSERVER(DriveSystemServiceObserver, observers_,
                       OnFileSystemMounted());
   }
@@ -338,7 +338,7 @@ void DriveSystemService::RemoveDriveMountPoint() {
     file_system_proxy_->DetachFromFileSystem();
     file_system_proxy_ = NULL;
   }
-  util::Log("RemoveDriveMountPoint");
+  util::Log("Drive mount point is removed");
 }
 
 void DriveSystemService::InitializeAfterCacheInitialized(bool success) {
diff --git a/chrome/browser/chromeos/drive/job_list.cc b/chrome/browser/chromeos/drive/job_list.cc
index 3eda377..b06c47e 100644
--- a/chrome/browser/chromeos/drive/job_list.cc
+++ b/chrome/browser/chromeos/drive/job_list.cc
@@ -64,4 +64,13 @@ std::string JobStateToString(JobState state) {
   return "(unknown job state)";
 }
 
+
+JobInfo::JobInfo(JobType in_job_type)
+    : job_type(in_job_type),
+      job_id(-1),
+      state(STATE_NONE),
+      num_completed_bytes(0),
+      num_total_bytes(0) {
+}
+
 }  // namespace drive
diff --git a/chrome/browser/chromeos/drive/job_list.h b/chrome/browser/chromeos/drive/job_list.h
index 9805e5d..e8698ce 100644
--- a/chrome/browser/chromeos/drive/job_list.h
+++ b/chrome/browser/chromeos/drive/job_list.h
@@ -58,13 +58,7 @@ typedef int32 JobID;
 
 // Information about a specific job that is visible to other systems.
 struct JobInfo {
-  explicit JobInfo(JobType in_job_type)
-      : job_type(in_job_type),
-        job_id(-1),
-        state(STATE_NONE),
-        num_completed_bytes(0),
-        num_total_bytes(0) {
-  }
+  explicit JobInfo(JobType job_type);
 
   // Type of the job.
   JobType job_type;
@@ -86,6 +80,9 @@ struct JobInfo {
 
   // Drive path of the file that this job acts on.
   base::FilePath file_path;
+
+  // Time when the job is started (i.e. the request is sent to the server).
+  base::Time start_time;
 };
 
 // The interface for observing JobListInterface.