[d8] Support more console functions

- console.assert now fails properly
- console.trace dumps a low-level stack trace
- console.time/End dumps a timer event to the log file
- console.timeStamp dumps a timer event to the log

Drive-by-fixes:
- simplify test-log.cc
- fix test-log.cc log parser JS helper
- always start the default timer int the logger

Change-Id: I0bb26b9410a4e0d1d5bc8621d8b2243922fe3f29
Reviewed-on: https://chromium-review.googlesource.com/702459Reviewed-by: Yang Guo <yangguo@chromium.org>
Reviewed-by: Jakob Kummerow <jkummerow@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/master@{#48531}

src/builtins/builtins-console.cc

@@ -35,10 +35,7 @@ namespace internal {
   V(Profile, profile)               \
   V(ProfileEnd, profileEnd)         \
   V(Timeline, timeline)             \
-  V(TimelineEnd, timelineEnd)       \
-  V(Time, time)                     \
-  V(TimeEnd, timeEnd)               \
-  V(TimeStamp, timeStamp)
+  V(TimelineEnd, timelineEnd)
 
 namespace {
 void ConsoleCall(
@@ -63,6 +60,20 @@ void ConsoleCall(
       wrapper,
       v8::debug::ConsoleContext(context_id, Utils::ToLocal(context_name)));
 }
+
+void LogTimerEvent(Isolate* isolate, BuiltinArguments args,
+                   Logger::StartEnd se) {
+  if (!isolate->logger()->is_logging()) return;
+  HandleScope scope(isolate);
+  std::unique_ptr<char[]> name;
+  const char* raw_name = "default";
+  if (args.length() > 1 && args[1]->IsString()) {
+    // Try converting the first argument to a string.
+    name = args.at<String>(1)->ToCString();
+    raw_name = name.get();
+  }
+  LOG(isolate, TimerEvent(se, raw_name));
+}
 }  // namespace
 
 #define CONSOLE_BUILTIN_IMPLEMENTATION(call, name)             \
@@ -74,6 +85,27 @@ void ConsoleCall(
 CONSOLE_METHOD_LIST(CONSOLE_BUILTIN_IMPLEMENTATION)
 #undef CONSOLE_BUILTIN_IMPLEMENTATION
 
+BUILTIN(ConsoleTime) {
+  LogTimerEvent(isolate, args, Logger::START);
+  ConsoleCall(isolate, args, &debug::ConsoleDelegate::Time);
+  RETURN_FAILURE_IF_SCHEDULED_EXCEPTION(isolate);
+  return isolate->heap()->undefined_value();
+}
+
+BUILTIN(ConsoleTimeEnd) {
+  LogTimerEvent(isolate, args, Logger::END);
+  ConsoleCall(isolate, args, &debug::ConsoleDelegate::TimeEnd);
+  RETURN_FAILURE_IF_SCHEDULED_EXCEPTION(isolate);
+  return isolate->heap()->undefined_value();
+}
+
+BUILTIN(ConsoleTimeStamp) {
+  LogTimerEvent(isolate, args, Logger::STAMP);
+  ConsoleCall(isolate, args, &debug::ConsoleDelegate::TimeStamp);
+  RETURN_FAILURE_IF_SCHEDULED_EXCEPTION(isolate);
+  return isolate->heap()->undefined_value();
+}
+
 namespace {
 void InstallContextFunction(Handle<JSObject> target, const char* name,
                             Builtins::Name call, int context_id,
@@ -120,6 +152,12 @@ BUILTIN(ConsoleContext) {
                          args.at(1));
   CONSOLE_METHOD_LIST(CONSOLE_BUILTIN_SETUP)
 #undef CONSOLE_BUILTIN_SETUP
+  InstallContextFunction(context, "time", Builtins::kConsoleTime, id,
+                         args.at(1));
+  InstallContextFunction(context, "timeEnd", Builtins::kConsoleTimeEnd, id,
+                         args.at(1));
+  InstallContextFunction(context, "timeStamp", Builtins::kConsoleTimeStamp, id,
+                         args.at(1));
 
   return *context;
 }

src/d8-console.cc

@@ -4,15 +4,17 @@
 
 #include "src/d8-console.h"
 #include "src/d8.h"
+#include "src/isolate.h"
 
 namespace v8 {
 
 namespace {
-void WriteToFile(FILE* file, Isolate* isolate,
+void WriteToFile(const char* action, FILE* file, Isolate* isolate,
                  const debug::ConsoleCallArguments& args) {
+  fprintf(file, "console.%s: ", action);
   for (int i = 0; i < args.Length(); i++) {
     HandleScope handle_scope(isolate);
-    if (i != 0) fprintf(file, " ");
+    if (i > 0) fprintf(file, " ");
 
     Local<Value> arg = args[i];
     Local<String> str_obj;
@@ -35,29 +37,48 @@ D8Console::D8Console(Isolate* isolate) : isolate_(isolate) {
   default_timer_ = base::TimeTicks::HighResolutionNow();
 }
 
+void D8Console::Assert(const debug::ConsoleCallArguments& args,
+                       const v8::debug::ConsoleContext&) {
+  Local<Boolean> arg;
+  if (args.Length() > 0) {
+    if (!args[0]->ToBoolean(isolate_->GetCurrentContext()).ToLocal(&arg)) {
+      return;
+    }
+  } else {
+    // No arguments given, the "first" argument is undefined which is false-ish.
+    arg = v8::False(isolate_);
+  }
+  if (arg->IsTrue()) return;
+  WriteToFile("assert", stdout, isolate_, args);
+  isolate_->ThrowException(v8::Exception::Error(
+      v8::String::NewFromUtf8(isolate_, "console.assert failed",
+                              v8::NewStringType::kNormal)
+          .ToLocalChecked()));
+}
+
 void D8Console::Log(const debug::ConsoleCallArguments& args,
                     const v8::debug::ConsoleContext&) {
-  WriteToFile(stdout, isolate_, args);
+  WriteToFile("log", stdout, isolate_, args);
 }
 
 void D8Console::Error(const debug::ConsoleCallArguments& args,
                       const v8::debug::ConsoleContext&) {
-  WriteToFile(stderr, isolate_, args);
+  WriteToFile("error", stderr, isolate_, args);
 }
 
 void D8Console::Warn(const debug::ConsoleCallArguments& args,
                      const v8::debug::ConsoleContext&) {
-  WriteToFile(stdout, isolate_, args);
+  WriteToFile("warn", stdout, isolate_, args);
 }
 
 void D8Console::Info(const debug::ConsoleCallArguments& args,
                      const v8::debug::ConsoleContext&) {
-  WriteToFile(stdout, isolate_, args);
+  WriteToFile("info", stdout, isolate_, args);
 }
 
 void D8Console::Debug(const debug::ConsoleCallArguments& args,
                       const v8::debug::ConsoleContext&) {
-  WriteToFile(stdout, isolate_, args);
+  WriteToFile("debug", stdout, isolate_, args);
 }
 
 void D8Console::Time(const debug::ConsoleCallArguments& args,
@@ -84,11 +105,11 @@ void D8Console::Time(const debug::ConsoleCallArguments& args,
 void D8Console::TimeEnd(const debug::ConsoleCallArguments& args,
                         const v8::debug::ConsoleContext&) {
   base::TimeDelta delta;
-  base::TimeTicks now = base::TimeTicks::HighResolutionNow();
   if (args.Length() == 0) {
     delta = base::TimeTicks::HighResolutionNow() - default_timer_;
-    printf("default: ");
+    printf("console.timeEnd: default, %f\n", delta.InMillisecondsF());
   } else {
+    base::TimeTicks now = base::TimeTicks::HighResolutionNow();
     Local<Value> arg = args[0];
     Local<String> label;
     v8::TryCatch try_catch(isolate_);
@@ -99,9 +120,30 @@ void D8Console::TimeEnd(const debug::ConsoleCallArguments& args,
     if (find != timers_.end()) {
       delta = now - find->second;
     }
-    printf("%s: ", *utf8);
+    printf("console.timeEnd: %s, %f\n", *utf8, delta.InMillisecondsF());
   }
-  printf("%f\n", delta.InMillisecondsF());
+}
+
+void D8Console::TimeStamp(const debug::ConsoleCallArguments& args,
+                          const v8::debug::ConsoleContext&) {
+  base::TimeDelta delta = base::TimeTicks::HighResolutionNow() - default_timer_;
+  if (args.Length() == 0) {
+    printf("console.timeStamp: default, %f\n", delta.InMillisecondsF());
+  } else {
+    Local<Value> arg = args[0];
+    Local<String> label;
+    v8::TryCatch try_catch(isolate_);
+    if (!arg->ToString(isolate_->GetCurrentContext()).ToLocal(&label)) return;
+    v8::String::Utf8Value utf8(isolate_, label);
+    std::string string(*utf8);
+    printf("console.timeStamp: %s, %f\n", *utf8, delta.InMillisecondsF());
+  }
+}
+
+void D8Console::Trace(const debug::ConsoleCallArguments& args,
+                      const v8::debug::ConsoleContext&) {
+  i::Isolate* i_isolate = reinterpret_cast<i::Isolate*>(isolate_);
+  i_isolate->PrintStack(stderr, i::Isolate::kPrintStackConcise);
 }
 
 }  // namespace v8

src/d8-console.h

@@ -16,6 +16,8 @@ class D8Console : public debug::ConsoleDelegate {
   explicit D8Console(Isolate* isolate);
 
  private:
+  void Assert(const debug::ConsoleCallArguments& args,
+              const v8::debug::ConsoleContext&) override;
   void Log(const debug::ConsoleCallArguments& args,
            const v8::debug::ConsoleContext&) override;
   void Error(const debug::ConsoleCallArguments& args,
@@ -30,6 +32,10 @@ class D8Console : public debug::ConsoleDelegate {
             const v8::debug::ConsoleContext&) override;
   void TimeEnd(const debug::ConsoleCallArguments& args,
                const v8::debug::ConsoleContext&) override;
+  void TimeStamp(const debug::ConsoleCallArguments& args,
+                 const v8::debug::ConsoleContext&) override;
+  void Trace(const debug::ConsoleCallArguments& args,
+             const v8::debug::ConsoleContext&) override;
 
   Isolate* isolate_;
   std::map<std::string, base::TimeTicks> timers_;

src/isolate.h

@@ -722,7 +722,8 @@ class Isolate {
   void PrintCurrentStackTrace(FILE* out);
   void PrintStack(StringStream* accumulator,
                   PrintStackMode mode = kPrintStackVerbose);
-  void PrintStack(FILE* out, PrintStackMode mode = kPrintStackVerbose);
+  V8_EXPORT_PRIVATE void PrintStack(FILE* out,
+                                    PrintStackMode mode = kPrintStackVerbose);
   Handle<String> StackTraceString();
   // Stores a stack trace in a stack-allocated temporary buffer which will
   // end up in the minidump for debugging purposes.

src/log.cc

@@ -845,9 +845,7 @@ void Logger::CodeDeoptEvent(Code* code, DeoptKind kind, Address pc,
   if (!log_->IsEnabled()) return;
   Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc);
   Log::MessageBuilder msg(log_);
-  int since_epoch = timer_.IsStarted()
-                        ? static_cast<int>(timer_.Elapsed().InMicroseconds())
-                        : -1;
+  int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
   msg.Append("code-deopt,%d,%d,", since_epoch, code->CodeSize());
   msg.AppendAddress(code->instruction_start());
 
@@ -893,24 +891,27 @@ void Logger::CurrentTimeEvent() {
 
 void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
   if (!log_->IsEnabled()) return;
-  DCHECK(FLAG_log_internal_timer_events);
   Log::MessageBuilder msg(log_);
   int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
-  const char* format = (se == START) ? "timer-event-start,\"%s\",%ld"
-                                     : "timer-event-end,\"%s\",%ld";
+  const char* format = (se == START)
+                           ? "timer-event-start,\"%s\",%ld"
+                           : (se == END) ? "timer-event-end,\"%s\",%ld"
+                                         : "timer-event,\"%s\",%ld";
   msg.Append(format, name, since_epoch);
   msg.WriteToLogFile();
 }
 
-
+// static
 void Logger::EnterExternal(Isolate* isolate) {
+  DCHECK(FLAG_log_internal_timer_events);
   LOG(isolate, TimerEvent(START, TimerEventExternal::name()));
   DCHECK(isolate->current_vm_state() == JS);
   isolate->set_current_vm_state(EXTERNAL);
 }
 
-
+// static
 void Logger::LeaveExternal(Isolate* isolate) {
+  DCHECK(FLAG_log_internal_timer_events);
   LOG(isolate, TimerEvent(END, TimerEventExternal::name()));
   DCHECK(isolate->current_vm_state() == EXTERNAL);
   isolate->set_current_vm_state(JS);
@@ -1000,9 +1001,7 @@ void Logger::CallbackEventInternal(const char* prefix, Name* name,
   msg.Append("%s,%s,-2,",
              kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT],
              kLogEventsNames[CodeEventListener::CALLBACK_TAG]);
-  int timestamp = timer_.IsStarted()
-                      ? static_cast<int>(timer_.Elapsed().InMicroseconds())
-                      : -1;
+  int timestamp = static_cast<int>(timer_.Elapsed().InMicroseconds());
   msg.Append("%d,", timestamp);
   msg.AppendAddress(entry_point);
   if (name->IsString()) {
@@ -1048,9 +1047,7 @@ void AppendCodeCreateHeader(Log::MessageBuilder* msg,
   msg->Append("%s,%s,%d,",
               kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT],
               kLogEventsNames[tag], code->kind());
-  int timestamp = timer->IsStarted()
-                      ? static_cast<int>(timer->Elapsed().InMicroseconds())
-                      : -1;
+  int timestamp = static_cast<int>(timer->Elapsed().InMicroseconds());
   msg->Append("%d,", timestamp);
   msg->AppendAddress(code->instruction_start());
   msg->Append(",%d,", code->instruction_size());
@@ -1825,7 +1822,7 @@ bool Logger::SetUp(Isolate* isolate) {
     is_logging_ = true;
   }
 
-  if (FLAG_log_internal_timer_events || FLAG_prof_cpp) timer_.Start();
+  timer_.Start();
 
   if (FLAG_prof_cpp) {
     profiler_ = new Profiler(isolate);

src/log.h

@@ -93,7 +93,7 @@ class Ticker;
 
 class Logger : public CodeEventListener {
  public:
-  enum StartEnd { START = 0, END = 1 };
+  enum StartEnd { START = 0, END = 1, STAMP = 2 };
 
   // Acquires resources for logging if the right flags are set.
   bool SetUp(Isolate* isolate);
@@ -213,7 +213,7 @@ class Logger : public CodeEventListener {
 
   void CurrentTimeEvent();
 
-  void TimerEvent(StartEnd se, const char* name);
+  V8_EXPORT_PRIVATE void TimerEvent(StartEnd se, const char* name);
 
   static void EnterExternal(Isolate* isolate);
   static void LeaveExternal(Isolate* isolate);

test/cctest/log-eq-of-logging-and-traversal.js

@@ -39,7 +39,8 @@ function parseState(s) {
 function LogProcessor() {
   LogReader.call(this, {
       'code-creation': {
-          parsers: [null, parseInt, parseInt, parseInt, null, 'var-args'],
+          parsers: [null, parseInt, parseInt, parseInt, parseInt,
+                    null, 'var-args'],
           processor: this.processCodeCreation },
       'code-move': { parsers: [parseInt, parseInt],
           processor: this.processCodeMove },
@@ -55,8 +56,10 @@ function LogProcessor() {
 LogProcessor.prototype.__proto__ = LogReader.prototype;
 
 LogProcessor.prototype.processCodeCreation = function(
-    type, kind, start, size, name, maybe_func) {
-  if (type != "LazyCompile" && type != "Script" && type != "Function") return;
+    type, kind, timestamp, start, size, name, maybe_func) {
+  if (type != "LazyCompile" && type != "Script" && type != "Function") {
+    return;
+  }
   // Scripts will compile into anonymous functions starting at 1:1. Adjust the
   // name here so that it matches corrsponding function's name during the heap
   // traversal.
@@ -66,9 +69,9 @@ LogProcessor.prototype.processCodeCreation = function(
   if (maybe_func.length) {
     var funcAddr = parseInt(maybe_func[0]);
     var state = parseState(maybe_func[1]);
-    this.profile.addFuncCode(type, name, start, size, funcAddr, state);
+    this.profile.addFuncCode(type, name, timestamp, start, size, funcAddr, state);
   } else {
-    this.profile.addCode(type, name, start, size);
+    this.profile.addCode(type, name, timestamp, start, size);
   }
 };
 
@@ -100,6 +103,7 @@ function RunTest() {
     logging_processor.profile.codeMap_.getAllDynamicEntriesWithAddresses();
   if (logging_entries.length === 0)
     return "logging_entries.length === 0";
+
   var traversal_processor = new LogProcessor();
   for ( ; pos < log_lines_length; ++pos) {
     line = log_lines[pos];
@@ -170,6 +174,7 @@ function RunTest() {
   return [equal, comparison];
 }
 
+
 var result = RunTest();
 if (typeof result !== "string") {
   var out = [];

test/message/console.js

@@ -18,7 +18,6 @@ console.timeEnd("a", "b");
 
 console.log("log", "more");
 console.warn("warn", { toString: () => 2 });
-console.error("error");
 console.debug("debug");
 console.info("info");
 

test/message/console.out

-default: {NUMBER}
-abcd: {NUMBER}
-b: 0.000000
-a: {NUMBER}
-log more
-warn 2
-debug
-info
-*%(basename)s:25: Error: exception
+console.timeEnd: default, {NUMBER}
+console.timeEnd: abcd, {NUMBER}
+console.timeEnd: b, {NUMBER}
+console.timeEnd: a, {NUMBER}
+console.log: log more
+console.warn: warn 2
+console.debug: debug
+console.info: info
+console.info: *%(basename)s:24: Error: exception
 console.info({ toString: () => {throw new Error("exception");} })
                                 ^
 Error: exception
-    at Object.toString (*%(basename)s:25:39)
+    at Object.toString (*%(basename)s:24:39)
     at console.info (<anonymous>)
-    at *%(basename)s:25:9
+    at *%(basename)s:24:9
+

test/message/settimeout.out

-state: 0
-state: 0
-increment state
-current state: 1
-increment state
-current state: 2
-increment state
-current state: 3
+console.log: state: 0
+console.log: state: 0
+console.log: increment state
+console.log: current state: 1
+console.log: increment state
+console.log: current state: 2
+console.log: increment state
+console.log: current state: 3
 *%(basename)s:19: Error
     setTimeout(function() { throw new Error(); });
                             ^

test/mjsunit/console.js

+// Copyright 2016 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.
+
+console.assert(true);
+console.assert("yes");
+assertThrows(() => console.assert(false), Error);
+assertThrows(() => console.assert(""), Error);
+assertThrows(() => console.assert(0), Error);
+
+let args = ["", {}, [], this, Array, 1, 1.4, true, false];
+
+console.log(...args);
+console.error(...args);
+console.warn(...args);
+console.info(...args);
+console.debug(...args);
+
+console.time();
+console.timeEnd();
+
+console.time("a");
+console.timeEnd("a");
+
+console.timeStamp();
+args.forEach(each => console.timeStamp(each));
+
+console.trace();