inspector: implement console.timeLog

New method was added to console spec [1].
This CL implements it.

[1] https://console.spec.whatwg.org/#timelog

R=dgozman@chromium.org,yangguo@chromium.org

Bug: chromium:854474
Cq-Include-Trybots: luci.chromium.try:linux_chromium_headless_rel;master.tryserver.blink:linux_trusty_blink_rel
Change-Id: Ie5f249795979bb886cf824ae9f950c5ef78ce04d
Reviewed-on: https://chromium-review.googlesource.com/1247641
Commit-Queue: Aleksey Kozyatinskiy <kozyatinskiy@chromium.org>
Reviewed-by: Dmitry Gozman <dgozman@chromium.org>
Reviewed-by: Yang Guo <yangguo@chromium.org>
Cr-Commit-Position: refs/heads/master@{#56294}

src/bootstrapper.cc

@@ -2883,6 +2883,8 @@ void Genesis::InitializeGlobal(Handle<JSGlobalObject> global_object,
                           Builtins::kConsoleProfileEnd, 1, false, NONE);
     SimpleInstallFunction(isolate_, console, "time", Builtins::kConsoleTime, 1,
                           false, NONE);
+    SimpleInstallFunction(isolate_, console, "timeLog",
+                          Builtins::kConsoleTimeLog, 1, false, NONE);
     SimpleInstallFunction(isolate_, console, "timeEnd",
                           Builtins::kConsoleTimeEnd, 1, false, NONE);
     SimpleInstallFunction(isolate_, console, "timeStamp",

src/builtins/builtins-console.cc

@@ -32,7 +32,8 @@ namespace internal {
   V(CountReset, countReset)         \
   V(Assert, assert)                 \
   V(Profile, profile)               \
-  V(ProfileEnd, profileEnd)
+  V(ProfileEnd, profileEnd)         \
+  V(TimeLog, timeLog)
 
 namespace {
 void ConsoleCall(

src/builtins/builtins-definitions.h

@@ -495,6 +495,7 @@ namespace internal {
   CPP(ConsoleProfile)                                                          \
   CPP(ConsoleProfileEnd)                                                       \
   CPP(ConsoleTime)                                                             \
+  CPP(ConsoleTimeLog)                                                          \
   CPP(ConsoleTimeEnd)                                                          \
   CPP(ConsoleTimeStamp)                                                        \
   CPP(ConsoleContext)                                                          \

src/debug/interface-types.h

@@ -161,6 +161,8 @@ class ConsoleDelegate {
                           const ConsoleContext& context) {}
   virtual void Time(const ConsoleCallArguments& args,
                     const ConsoleContext& context) {}
+  virtual void TimeLog(const ConsoleCallArguments& args,
+                       const ConsoleContext& context) {}
   virtual void TimeEnd(const ConsoleCallArguments& args,
                        const ConsoleContext& context) {}
   virtual void TimeStamp(const ConsoleCallArguments& args,

src/inspector/v8-console-message.cc

@@ -565,6 +565,13 @@ bool V8ConsoleMessageStorage::countReset(int contextId, const String16& id) {
   return true;
 }
 
+double V8ConsoleMessageStorage::timeLog(int contextId, const String16& id) {
+  std::map<String16, double>& time = m_data[contextId].m_time;
+  auto it = time.find(id);
+  if (it == time.end()) return 0.0;
+  return m_inspector->client()->currentTimeMS() - it->second;
+}
+
 double V8ConsoleMessageStorage::timeEnd(int contextId, const String16& id) {
   std::map<String16, double>& time = m_data[contextId].m_time;
   auto it = time.find(id);

src/inspector/v8-console-message.h

@@ -120,6 +120,7 @@ class V8ConsoleMessageStorage {
   int count(int contextId, const String16& id);
   bool countReset(int contextId, const String16& id);
   void time(int contextId, const String16& id);
+  double timeLog(int contextId, const String16& id);
   double timeEnd(int contextId, const String16& id);
   bool hasTimer(int contextId, const String16& id);
 

src/inspector/v8-console.cc

@@ -76,6 +76,14 @@ class ConsoleHelper {
     reportCall(type, arguments);
   }
 
+  void reportCallAndReplaceFirstArgument(ConsoleAPIType type,
+                                         const String16& message) {
+    std::vector<v8::Local<v8::Value>> arguments;
+    arguments.push_back(toV8String(m_isolate, message));
+    for (int i = 1; i < m_info.Length(); ++i) arguments.push_back(m_info[i]);
+    reportCall(type, arguments);
+  }
+
   void reportCallWithArgument(ConsoleAPIType type, const String16& message) {
     std::vector<v8::Local<v8::Value>> arguments(1,
                                                 toV8String(m_isolate, message));
@@ -386,10 +394,9 @@ static void timeFunction(const v8::debug::ConsoleCallArguments& info,
 
 static void timeEndFunction(const v8::debug::ConsoleCallArguments& info,
                             const v8::debug::ConsoleContext& consoleContext,
-                            bool timelinePrefix, V8InspectorImpl* inspector) {
+                            bool timeLog, V8InspectorImpl* inspector) {
   ConsoleHelper helper(info, consoleContext, inspector);
   String16 protocolTitle = helper.firstArgToString("default", false);
-  if (timelinePrefix) protocolTitle = "Timeline '" + protocolTitle + "'";
   const String16& timerId =
       protocolTitle + "@" +
       consoleContextToString(inspector->isolate(), consoleContext);
@@ -400,12 +407,21 @@ static void timeEndFunction(const v8::debug::ConsoleCallArguments& info,
     return;
   }
   inspector->client()->consoleTimeEnd(toStringView(protocolTitle));
-  double elapsed = helper.consoleMessageStorage()->timeEnd(
-      helper.contextId(),
-      protocolTitle + "@" +
-          consoleContextToString(inspector->isolate(), consoleContext));
+  String16 title = protocolTitle + "@" +
+                   consoleContextToString(inspector->isolate(), consoleContext);
+  double elapsed;
+  if (timeLog) {
+    elapsed =
+        helper.consoleMessageStorage()->timeLog(helper.contextId(), title);
+  } else {
+    elapsed =
+        helper.consoleMessageStorage()->timeEnd(helper.contextId(), title);
+  }
   String16 message =
       protocolTitle + ": " + String16::fromDouble(elapsed) + "ms";
+  if (timeLog)
+    helper.reportCallAndReplaceFirstArgument(ConsoleAPIType::kLog, message);
+  else
     helper.reportCallWithArgument(ConsoleAPIType::kTimeEnd, message);
 }
 
@@ -414,6 +430,11 @@ void V8Console::Time(const v8::debug::ConsoleCallArguments& info,
   timeFunction(info, consoleContext, false, m_inspector);
 }
 
+void V8Console::TimeLog(const v8::debug::ConsoleCallArguments& info,
+                        const v8::debug::ConsoleContext& consoleContext) {
+  timeEndFunction(info, consoleContext, true, m_inspector);
+}
+
 void V8Console::TimeEnd(const v8::debug::ConsoleCallArguments& info,
                         const v8::debug::ConsoleContext& consoleContext) {
   timeEndFunction(info, consoleContext, false, m_inspector);

src/inspector/v8-console.h

@@ -88,6 +88,8 @@ class V8Console : public v8::debug::ConsoleDelegate {
                   const v8::debug::ConsoleContext& consoleContext) override;
   void Time(const v8::debug::ConsoleCallArguments&,
             const v8::debug::ConsoleContext& consoleContext) override;
+  void TimeLog(const v8::debug::ConsoleCallArguments&,
+               const v8::debug::ConsoleContext& consoleContext) override;
   void TimeEnd(const v8::debug::ConsoleCallArguments&,
                const v8::debug::ConsoleContext& consoleContext) override;
   void TimeStamp(const v8::debug::ConsoleCallArguments&,

test/inspector/runtime/console-context-expected.txt

@@ -28,9 +28,10 @@ console.context() methods:
     [15] : assert
     [16] : profile
     [17] : profileEnd
-    [18] : time
-    [19] : timeEnd
-    [20] : timeStamp
+    [18] : timeLog
+    [19] : time
+    [20] : timeEnd
+    [21] : timeStamp
 ]
 
 Running test: testDefaultConsoleContext

test/inspector/runtime/console-time-log-expected.txt

+Test for console.timeLog
+[
+    [0] : {
+        type : string
+        value : 42: 1ms
+    }
+    [1] : {
+        type : string
+        value : a
+    }
+]
+[
+    [0] : {
+        type : string
+        value : 42: 2ms
+    }
+    [1] : {
+        type : string
+        value : a
+    }
+    [2] : {
+        type : string
+        value : b
+    }
+]
+[
+    [0] : {
+        type : string
+        value : 42: 3ms
+    }
+]
+[
+    [0] : {
+        type : string
+        value : Timer '42' does not exist
+    }
+]

test/inspector/runtime/console-time-log.js

+// Copyright 2018 the V8 project authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+const {session, contextGroup, Protocol} =
+    InspectorTest.start('Test for console.timeLog');
+
+(async function test() {
+  Protocol.Runtime.enable();
+  utils.setCurrentTimeMSForTest(0.0);
+  await Protocol.Runtime.evaluate({expression: `console.time('42')`});
+  utils.setCurrentTimeMSForTest(1.0);
+  Protocol.Runtime.evaluate({expression: `console.timeLog('42', 'a')`});
+  logArgs(await Protocol.Runtime.onceConsoleAPICalled());
+  utils.setCurrentTimeMSForTest(2.0);
+  Protocol.Runtime.evaluate({expression: `console.timeLog('42', 'a', 'b')`});
+  logArgs(await Protocol.Runtime.onceConsoleAPICalled());
+  utils.setCurrentTimeMSForTest(3.0);
+  Protocol.Runtime.evaluate({expression: `console.timeEnd('42')`});
+  logArgs(await Protocol.Runtime.onceConsoleAPICalled());
+  utils.setCurrentTimeMSForTest(4.0);
+  Protocol.Runtime.evaluate({expression: `console.timeLog('42', 'text')`});
+  logArgs(await Protocol.Runtime.onceConsoleAPICalled());
+  InspectorTest.completeTest();
+})()
+
+function logArgs(message) {
+  InspectorTest.logMessage(message.params.args);
+}