V8中的日志

通过前面的文章，我们知道如何编译v8. 下一步即将开始我们修改v8之旅。

在修改之前，我们看下v8中如何改日志。

为了提升性能，v8默认是不打印日志的，我们可以通过设置d8参数的方式打印日志到文件，默认写到v8.log文件中。

为了达到日志丰富度和性能的平衡，打印日志的参数也有好几种。

最小级别日志

最小的级别是--log.

我的v8打印的内容如下：

v8-version,9,7,37,0,0
v8-platform,macos,macos
new,CodeRange,0x3a8300000000,0
new,MemoryChunk,0x3a8308000000,262144
...
new,MemoryChunk,0x3a83081c0000,262144
heap-capacity,1014688
heap-available,4295685952
new,MemoryChunk,0x3a8308200000,262144
...
new,MemoryChunk,0x3a83082c0000,262144

这段打印的逻辑在log-utils.cc中：

void Log::WriteLogHeader() {
  Log::MessageBuilder msg(this);
  LogSeparator kNext = LogSeparator::kSeparator;
  msg << "v8-version" << kNext << Version::GetMajor() << kNext
      << Version::GetMinor() << kNext << Version::GetBuild() << kNext
      << Version::GetPatch();
  if (strlen(Version::GetEmbedder()) != 0) {
    msg << kNext << Version::GetEmbedder();
  }
  msg << kNext << Version::IsCandidate();
  msg.WriteToLogFile();
  msg << "v8-platform" << kNext << V8_OS_STRING << kNext << V8_TARGET_OS_STRING;
  msg.WriteToLogFile();
}

比如我们想给自己编译的v8上加个标记，就可以加到log-utils.cc中的WriteLogHeader里：

  msg << "[xulun modified v8]";
  msg.WriteToLogFile();

API日志

更进一步地，我们可以记录API调用的事件：--log-api.
在最小log的基础上，会增加对于API事件的日志，比如：

api,v8::ObjectTemplate::New
api,v8::Persistent::New
api,v8::ObjectTemplate::New
api,v8::String::NewFromUtf8Literal
api,v8::FunctionTemplate::New
api,v8::String::NewFromUtf8
...

API中使用LOG_API宏:

#define LOG_API(isolate, class_name, function_name)                        \
  RCS_SCOPE(isolate,                                                       \
            i::RuntimeCallCounterId::kAPI_##class_name##_##function_name); \
  LOG(isolate, ApiEntryCall("v8::" #class_name "::" #function_name))

ApiEntryCall是WriteApiEntryCall的封装：

  void ApiEntryCall(const char* name) {
    if (!FLAG_log_api) return;
    WriteApiEntryCall(name);
  }

WriteApiEntryCall就是加一个"api,"的头：

void Logger::WriteApiEntryCall(const char* name) {
  DCHECK(FLAG_log_api);
  MSG_BUILDER();
  msg << "api" << kNext << name;
  msg.WriteToLogFile();
}

代码生成日志

再进一步，我们可以记录代码生成的事件：--log-code:

...
code-creation,BytecodeHandler,0,292877,0x1af007fd0000,1728,ThrowReferenceErrorIfHole.ExtraWide
code-creation,BytecodeHandler,0,292910,0x1af007fd0700,960,ThrowIfNotSuperConstructor.ExtraWide
code-creation,BytecodeHandler,0,292941,0x1af007fd0b00,2268,SwitchOnGeneratorState.ExtraWide
code-creation,BytecodeHandler,0,292974,0x1af007fd1400,3428,SuspendGenerator.ExtraWide
code-creation,BytecodeHandler,0,293003,0x1af007fd2180,2928,ResumeGenerator.ExtraWide
code-creation,BytecodeHandler,0,293032,0x1af007fd2d00,1360,GetIterator.ExtraWide
code-creation,BytecodeHandler,0,293060,0x1af007fd3280,644,IncBlockCounter.ExtraWide
code-creation,BytecodeHandler,0,293089,0x1af007fd3540,352,Abort.ExtraWide
new,MemoryChunk,0x1af008280000,262144
...

我们刚才输入的代码也可以在日志中看到：

code-creation,Script,10,5014476,0x1af00829341a,5, (d8):1:1,0x1af0082933a8,~
script-source,3,(d8),let a = 0;

这也仍然是使用Log::MessageBuilder来实现的：

void AppendCodeCreateHeader(Log::MessageBuilder& msg,
                            CodeEventListener::LogEventsAndTags tag,
                            CodeKind kind, uint8_t* address, int size,
                            uint64_t time) {
  msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT]
      << Logger::kNext << kLogEventsNames[tag] << Logger::kNext
      << static_cast<int>(kind) << Logger::kNext << time << Logger::kNext
      << reinterpret_cast<void*>(address) << Logger::kNext << size
      << Logger::kNext;
}

头部再和消息体封装在一起构成CodeCreateEvent：

void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                             const char* name) {
  if (!is_listening_to_code_events()) return;
  if (!FLAG_log_code) return;
  {
    MSG_BUILDER();
    AppendCodeCreateHeader(msg, tag, *code, Time());
    msg << name;
    msg.WriteToLogFile();
  }
  LogCodeDisassemble(code);
}

其中MSG_BUILDER宏主要是定义msg对象：

#define MSG_BUILDER()                                                       \
  std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder(); \
  if (!msg_ptr) return;                                                     \
  Log::MessageBuilder& msg = *msg_ptr.get();

函数日志

函数相关的信息可以通过--log-function-events来查看：

script-source,6,(d8),let f1 = () => undefined;
function,preparse-no-resolution,6,9,24,0.035,15902407,arrow function
function,parse-script,6,0,25,0.281,15902570,
function,interpreter,6,0,25,0.293,15903840,
compilation-cache,put,script,6,0,25,15904046
function,first-execution,6,0,25,0,15904916,
script,reserve-id,7,19698314
script,create,7,19698459
script-details,7,(d8),0,0,
script-source,7,(d8),f1();
function,parse-script,7,0,5,0.106,19698826,
function,interpreter,7,0,5,0.149,19699680,
compilation-cache,put,script,7,0,5,19699822
function,first-execution,7,0,5,0,19700315,
function,parse,6,9,24,0.028,19700747,arrow function
function,parse-function,6,9,24,0.179,19700854,f1
function,interpreter-lazy,6,9,24,0.08,19701494,f1
function,first-execution,6,9,24,0,19701810,f1

这其中的日志主要是通过FunctionEvent函数来承载：

void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
                           int start_position, int end_position,
                           String function_name) {
  if (!FLAG_log_function_events) return;
  MSG_BUILDER();
  AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
                        end_position, Time());
  if (!function_name.is_null()) msg << function_name;
  msg.WriteToLogFile();
}

实际中的使用方式是这样的，以Runtime中的FunctionFirstExecution为例：

  LOG(isolate,
      FunctionEvent("first-execution", Script::cast(sfi->script()).id(), 0,
                    sfi->StartPosition(), sfi->EndPosition(), *name));
}

另外，还有来自CompilationCacheEvent的信息：

void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
                                   SharedFunctionInfo sfi) {
  if (!FLAG_log_function_events) return;
  MSG_BUILDER();
  int script_id = -1;
  if (sfi.script().IsScript()) {
    script_id = Script::cast(sfi.script()).id();
  }
  msg << "compilation-cache" << Logger::kNext << action << Logger::kNext
      << cache_type << Logger::kNext << script_id << Logger::kNext
      << sfi.StartPosition() << Logger::kNext << sfi.EndPosition()
      << Logger::kNext << Time();
  msg.WriteToLogFile();
}

内存映射信息

我们可以通过--log-maps来查看内存映射信息。
主要信息分为两类，map-create信息和map-details信息：

map-create,309183,0x36f908002119
map-details,309278,0x36f908002119,0x36f908002119: [Map] in ReadOnlySpace\n - type: MAP_TYPE\n - instance size: 40\n - elements kind: HOLEY_ELEMENTS\n - unused property fields: 0\n - enum length: invalid\n - stable_map\n - non-extensible\n - back pointer: 0x36f9080023b5 <undefined>\n - prototype_validity cell: 0\n - instance descriptors (own) #0: 0x36f9080021c1 <Other heap object (STRONG_DESCRIPTOR_ARRAY_TYPE)>\n - prototype: 0x36f908002235 <null>\n - constructor: 0x36f908002235 <null>\n - dependent code: 0x36f9080021b9 <Other heap object (WEAK_FIXED_ARRAY_TYPE)>\n - construction counter: 0\n\n
map-create,309599,0x36f908002141
map-details,309630,0x36f908002141,0x36f908002141: [Map] in ReadOnlySpace\n - type: ODDBALL_TYPE\n - instance size: 28\n - elements kind: HOLEY_ELEMENTS\n - unused property fields: 0\n - enum length: invalid\n - stable_map\n - undetectable\n - non-extensible\n - back pointer: 0x36f9080023b5 <undefined>\n - prototype_validity cell: 0\n - instance descriptors (own) #0: 0x36f9080021c1 <Other heap object (STRONG_DESCRIPTOR_ARRAY_TYPE)>\n - prototype: 0x36f908002235 <null>\n - constructor: 0x36f908002235 <null>\n - dependent code: 0x36f9080021b9 <Other heap object (WEAK_FIXED_ARRAY_TYPE)>\n - construction counter: 0\n\n

其中map-create就是将地址打印出来，中间的是时间戳：

void Logger::MapCreate(Map map) {
  if (!FLAG_log_maps) return;
  DisallowGarbageCollection no_gc;
  MSG_BUILDER();
  msg << "map-create" << kNext << Time() << kNext << AsHex::Address(map.ptr());
  msg.WriteToLogFile();
}

然后是map-details:

void Logger::MapDetails(Map map) {
  if (!FLAG_log_maps) return;
  DisallowGarbageCollection no_gc;
  MSG_BUILDER();
  msg << "map-details" << kNext << Time() << kNext << AsHex::Address(map.ptr())
      << kNext;
  if (FLAG_log_maps_details) {
    std::ostringstream buffer;
    map.PrintMapDetails(buffer);
    msg << buffer.str().c_str();
  }
  msg.WriteToLogFile();
}

其中，PrintMapDetails是一个简单的封装：

void Map::PrintMapDetails(std::ostream& os) {
  DisallowGarbageCollection no_gc;
  this->MapPrint(os);
  instance_descriptors().PrintDescriptors(os);
}

实际逻辑在MapPrint中，分门别类打印信息，这里节选一部分，大家找找感觉：

void Map::MapPrint(std::ostream& os) {
#ifdef OBJECT_PRINT
  PrintHeader(os, "Map");
#else
  os << "Map=" << reinterpret_cast<void*>(ptr());
#endif
  os << "\n - type: " << instance_type();
  os << "\n - instance size: ";
  if (instance_size() == kVariableSizeSentinel) {
    os << "variable";
  } else {
    os << instance_size();
  }
  if (IsJSObjectMap()) {
    os << "\n - inobject properties: " << GetInObjectProperties();
  }
  os << "\n - elements kind: " << ElementsKindToString(elements_kind());
  os << "\n - unused property fields: " << UnusedPropertyFields();
  os << "\n - enum length: ";
  if (EnumLength() == kInvalidEnumCacheSentinel) {
    os << "invalid";
  } else {
    os << EnumLength();
  }
  if (is_deprecated()) os << "\n - deprecated_map";
  if (is_stable()) os << "\n - stable_map";
  if (is_migration_target()) os << "\n - migration_target";
  if (is_dictionary_map()) os << "\n - dictionary_map";
  if (has_named_interceptor()) os << "\n - named_interceptor";
  if (has_indexed_interceptor()) os << "\n - indexed_interceptor";
  if (may_have_interesting_symbols()) os << "\n - may_have_interesting_symbols";
  if (is_undetectable()) os << "\n - undetectable";
  if (is_callable()) os << "\n - callable";
  if (is_constructor()) os << "\n - constructor";
  if (has_prototype_slot()) {
    os << "\n - has_prototype_slot";
    if (has_non_instance_prototype()) os << " (non-instance prototype)";
  }
  if (is_access_check_needed()) os << "\n - access_check_needed";
  if (!is_extensible()) os << "\n - non-extensible";
  if (IsContextMap()) {
    os << "\n - native context: " << Brief(native_context());
  } else if (is_prototype_map()) {
    os << "\n - prototype_map";
    os << "\n - prototype info: " << Brief(prototype_info());
  } else {
    os << "\n - back pointer: " << Brief(GetBackPointer());
  }
  os << "\n - prototype_validity cell: " << Brief(prototype_validity_cell());
  os << "\n - instance descriptors " << (owns_descriptors() ? "(own) " : "")
     << "#" << NumberOfOwnDescriptors() << ": "
     << Brief(instance_descriptors());
...

性能perf

--perf的日志会打印丰富的tick信息。

首先，我们能多看到d8是调用了哪些库，比如libv8, libv8_libbase, libv8_libplatform等。

shared-library,/Users/xulun/working/github/v8_3/v8/out/x64.debug/d8,0x1086a9a60,0x108755b50,141201408
shared-library,/Users/xulun/working/github/v8_3/v8/out/x64.debug/libv8.dylib,0x113468ac0,0x115fef9a8,4618354688
shared-library,/Users/xulun/working/github/v8_3/v8/out/x64.debug/libv8_libbase.dylib,0x108c388d0,0x108c7f0ba,4441997312
shared-library,/Users/xulun/working/github/v8_3/v8/out/x64.debug/libv8_libplatform.dylib,0x108e96810,0x108ecf0fa,4444479488
shared-library,/Users/xulun/working/github/v8_3/v8/out/x64.debug/libicui18n.dylib,0x1095978a0,0x1097f080b,4451823616
shared-library,/Users/xulun/working/github/v8_3/v8/out/x64.debug/libicuuc.dylib,0x109b57870,0x109cc53c2,4457852928
shared-library,/Users/xulun/working/github/v8_3/v8/out/x64.debug/libc++.dylib,0x109290890,0x10936d5d6,4448649216
shared-library,/Users/xulun/working/github/v8_3/v8/out/x64.debug/libchrome_zlib.dylib,0x108b4d790,0x108b6bad5,4441034752
...

这来自于SharedLibraryEvent方法：

void Logger::SharedLibraryEvent(const std::string& library_path,
                                uintptr_t start, uintptr_t end,
                                intptr_t aslr_slide) {
  if (!FLAG_prof_cpp) return;
  MSG_BUILDER();
  msg << "shared-library" << kNext << library_path.c_str() << kNext
      << reinterpret_cast<void*>(start) << kNext << reinterpret_cast<void*>(end)
      << kNext << aslr_slide;
  msg.WriteToLogFile();
}

SharedLibraryEvent的调用来自Profiler::Engage方法：

void Profiler::Engage() {
  std::vector<base::OS::SharedLibraryAddress> addresses =
      base::OS::GetSharedLibraryAddresses();
  for (const auto& address : addresses) {
    LOG(isolate_, SharedLibraryEvent(address.library_path, address.start,
                                     address.end, address.aslr_slide));
  }
  LOG(isolate_, SharedLibraryEnd());

  // Start thread processing the profiler buffer.
  base::Relaxed_Store(&running_, 1);
  CHECK(Start());

  // Register to get ticks.
  Logger* logger = isolate_->logger();
  logger->ticker_->SetProfiler(this);

  LOG(isolate_, ProfilerBeginEvent());
}

然后，从profiler begin开始，后面就是不断打印tick信息了：

profiler,begin,1000
tick,0x7ff810932af6,2206,0,0x0,6
new,CodeRange,0xbdc00000000,0
tick,0x106032e43,3384,0,0x0,6
new,MemoryChunk,0xbdc08000000,262144
tick,0x105b7f4e7,4646,0,0x0,6
tick,0x119476807,5729,0,0x0,6
tick,0x11948d201,6961,0,0x0,6
tick,0x105bc981b,8236,0,0x0,6
tick,0x11a6e4c87,9496,0,0x0,6
...

其实现在Profiler::Run方法中：

void Profiler::Run() {
  TickSample sample;
  bool overflow = Remove(&sample);
  while (base::Relaxed_Load(&running_)) {
    LOG(isolate_, TickEvent(&sample, overflow));
    overflow = Remove(&sample);
  }
}

终极大招 log-all

如果实在不知道是在哪个分类里的，可以用--log-all。
我们上面看到的，还有没列出的，都会出现.

杂项

指定日志文件名

默认的日志文件名是v8.log，如果要修改的话，可以加--logfile=文件名参数。

为每个isolate打印不同日志

--logfile-per-isolate，这是个默认的选项。

PrintF

v8也有自己的printf功能的函数，叫做PrintF.

void PrintF(const char* format, ...) {
  va_list arguments;
  va_start(arguments, format);
  base::OS::VPrint(format, arguments);
  va_end(arguments);
}

base::OS::VPrint是个跟平台相关的实现，比如在Android上，就是_android_log_vprint，在posix上是vprintf，在Windows上是OutputDebugStringA.

Linux下的实现：

void OS::VPrintError(const char* format, va_list args) {
#if defined(ANDROID) && !defined(V8_ANDROID_LOG_STDOUT)
  __android_log_vprint(ANDROID_LOG_ERROR, LOG_TAG, format, args);
#else
  vfprintf(stderr, format, args);
#endif
}

Win32下的实现：

void OS::VPrint(const char* format, va_list args) {
  VPrintHelper(stdout, format, args);
}

static void VPrintHelper(FILE* stream, const char* format, va_list args) {
  if ((stream == stdout || stream == stderr) && !HasConsole()) {
    char buffer[4096];
    OS::VSNPrintF(buffer, sizeof(buffer), format, args);
    OutputDebugStringA(buffer);
  } else {
    vfprintf(stream, format, args);
  }
}

小结

v8中针对诊断和性能剖析的类相当多，比如logging目录下和diagnostics目录下的各种工具类。
善用这些工具函数，可以为我们分析问题和打印自己的日志信息带来很大帮助。