V8中的日志
Posted Jtag特工
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了V8中的日志相关的知识，希望对你有一定的参考价值。
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)V8中的日志
Google Apps Script V8 vs Rhino 的“日志”非常慢？
用于 Visual Studio 分析的节点工具：v8 日志文件未保存，无数据