Added reporting of CPU time consumed while running the test

agent/wpthook/results.cc

@@ -650,6 +650,21 @@ void Results::SavePageData(OptimizationChecks& checks){
     // Peak number of running browser processes
     buff.Format("%d\t", peak_process_count_);
     result += buff;
+    // Doc Complete CPU time
+    double doc_cpu_time = 0;
+    double full_cpu_time = 0;
+    _test_state.GetElapsedCPUTimes(doc_cpu_time, full_cpu_time);
+    if (doc_cpu_time > 0.0) {
+      buff.Format("%0.3f\t", doc_cpu_time);
+      result += buff;
+    } else
+      result += "\t";
+    // Fully Loaded CPU time
+    if (full_cpu_time > 0.0) {
+      buff.Format("%0.3f\t", full_cpu_time);
+      result += buff;
+    } else
+      result += "\t";
 
     result += "\r\n";
 

agent/wpthook/test_state.cc

@@ -154,6 +154,9 @@ void TestState::Reset(bool cascade) {
     _last_cpu_idle.QuadPart = 0;
     _last_cpu_kernel.QuadPart = 0;
     _last_cpu_user.QuadPart = 0;
+    _start_cpu_time.dwHighDateTime = _start_cpu_time.dwLowDateTime = 0;
+    _doc_cpu_time.dwHighDateTime = _doc_cpu_time.dwLowDateTime = 0;
+    _end_cpu_time.dwHighDateTime = _end_cpu_time.dwLowDateTime = 0;
     _progress_data.RemoveAll();
     _test_result = 0;
     _title_time.QuadPart = 0;
@@ -197,6 +200,7 @@ void TestState::Start() {
   GetSystemTime(&_start_time);
   if (!_start.QuadPart)
     _start.QuadPart = _step_start.QuadPart;
+  GetCPUTime(_start_cpu_time);
   _active = true;
   UpdateBrowserWindow();  // the document window may not be available yet
   if (!_started) {
@@ -317,6 +321,7 @@ void TestState::OnLoad() {
     navigated_ = true;
     navigating_ = false;
     QueryPerformanceCounter(&_on_load);
+    GetCPUTime(_doc_cpu_time);
     ActivityDetected();
     _screen_capture.Capture(_document_window,
                             CapturedImage::DOCUMENT_COMPLETE);
@@ -395,6 +400,7 @@ bool TestState::IsDone() {
 void TestState::Done(bool force) {
   WptTrace(loglevel::kFunction, _T("[wpthook] - **** TestState::Done()\n"));
   if (_active) {
+    GetCPUTime(_end_cpu_time);
     _screen_capture.Capture(_document_window, CapturedImage::FULLY_LOADED);
 
     if (force || !_test._combine_steps) {
@@ -998,3 +1004,48 @@ void TestState::ProcessStopped(DWORD process_id) {
   _browser_processes.RemoveKey(process_id);
   LeaveCriticalSection(&_cs_browser_processes);
 }
+
+/*-----------------------------------------------------------------------------
+-----------------------------------------------------------------------------*/
+void TestState::GetCPUTime(FILETIME &cpu_time) {
+  FILETIME idle_time, kernel_time, user_time;
+  if (GetSystemTimes(&idle_time, &kernel_time, &user_time)) {
+    ULARGE_INTEGER k, u, i, combined;
+    k.LowPart = kernel_time.dwLowDateTime;
+    k.HighPart = kernel_time.dwHighDateTime;
+    u.LowPart = user_time.dwLowDateTime;
+    u.HighPart = user_time.dwHighDateTime;
+    i.LowPart = idle_time.dwLowDateTime;
+    i.HighPart = idle_time.dwHighDateTime;
+    combined.QuadPart = (k.QuadPart + u.QuadPart) - i.QuadPart;
+    cpu_time.dwHighDateTime = combined.HighPart;
+    cpu_time.dwLowDateTime = combined.LowPart;
+  }
+}
+
+/*-----------------------------------------------------------------------------
+-----------------------------------------------------------------------------*/
+double TestState::GetElapsedMilliseconds(FILETIME &start, FILETIME &end) {
+  double elapsed = 0;
+  ULARGE_INTEGER s, e;
+  s.LowPart = start.dwLowDateTime;
+  s.HighPart = start.dwHighDateTime;
+  e.LowPart = end.dwLowDateTime;
+  e.HighPart = end.dwHighDateTime;
+  if (e.QuadPart > s.QuadPart)
+    elapsed = (double)(e.QuadPart - s.QuadPart) / 10000.0;
+
+  return elapsed;
+}
+
+/*-----------------------------------------------------------------------------
+-----------------------------------------------------------------------------*/
+bool TestState::GetElapsedCPUTimes(double &doc, double &end) {
+  bool ret = false;
+  doc = GetElapsedMilliseconds(_start_cpu_time, _doc_cpu_time);
+  end = GetElapsedMilliseconds(_start_cpu_time, _end_cpu_time);
+  if (doc > 0.0 || end > 0.0)
+    ret = true;
+
+  return ret;
+}

agent/wpthook/test_state.h

@@ -113,6 +113,7 @@ class TestState {
   CString GetTimedEventsJSON();
   void ProcessStarted(DWORD process_id);
   void ProcessStopped(DWORD process_id);
+  bool GetElapsedCPUTimes(double &doc, double &end);
 
   // times
   LARGE_INTEGER _start;
@@ -193,6 +194,9 @@ class TestState {
   DWORD _video_capture_count;
   LARGE_INTEGER  _last_video_time;
   CAtlList<RECT> _pre_render_paints;
+  FILETIME      _start_cpu_time;
+  FILETIME      _doc_cpu_time;
+  FILETIME      _end_cpu_time;
 
   CRITICAL_SECTION  _data_cs;
 
@@ -201,4 +205,6 @@ class TestState {
   void FindViewport(bool force = false);
   void RecordTime(CString time_name, DWORD time, LARGE_INTEGER * out_time);
   DWORD ElapsedMs(LARGE_INTEGER start, LARGE_INTEGER end) const;
+  void GetCPUTime(FILETIME &cpu_time);
+  double GetElapsedMilliseconds(FILETIME &start, FILETIME &end);
 };

www/page_data.inc

@@ -235,6 +235,8 @@ function loadPageData($file, $options = null)
                 $ret['firstPaint'] = (array_key_exists(90, $fields) && strlen(trim($fields[90]))) ? (int)trim($fields[90]) : 0;
                 $ret['peakMem'] = (array_key_exists(91, $fields) && strlen(trim($fields[91]))) ? (int)trim($fields[91]) : 0;
                 $ret['processCount'] = (array_key_exists(92, $fields) && strlen(trim($fields[92]))) ? (int)trim($fields[92]) : 0;
+                $ret['docCPUms'] = (array_key_exists(93, $fields) && strlen(trim($fields[93]))) ? floatval(trim($fields[93])) : 0.0;
+                $ret['fullyLoadedCPUms'] = (array_key_exists(94, $fields) && strlen(trim($fields[94]))) ? floatval(trim($fields[94])) : 0.0;
 
                 $ret['date'] = strtotime(trim($fields[0]) . ' ' . trim($fields[1]));
                 if (!strlen($ret['pageSpeedVersion']))