1// Copyright 2011 the V8 project authors. All rights reserved. 2// Use of this source code is governed by a BSD-style license that can be 3// found in the LICENSE file. 4 5#include "src/logging/log.h" 6 7#include <atomic> 8#include <cstdarg> 9#include <memory> 10#include <sstream> 11 12#include "include/v8-locker.h" 13#include "src/api/api-inl.h" 14#include "src/base/platform/mutex.h" 15#include "src/base/platform/platform.h" 16#include "src/base/platform/wrappers.h" 17#include "src/builtins/profile-data-reader.h" 18#include "src/codegen/bailout-reason.h" 19#include "src/codegen/macro-assembler.h" 20#include "src/codegen/source-position-table.h" 21#include "src/deoptimizer/deoptimizer.h" 22#include "src/diagnostics/perf-jit.h" 23#include "src/execution/isolate.h" 24#include "src/execution/v8threads.h" 25#include "src/execution/vm-state-inl.h" 26#include "src/handles/global-handles.h" 27#include "src/heap/combined-heap.h" 28#include "src/heap/heap-inl.h" 29#include "src/init/bootstrapper.h" 30#include "src/interpreter/bytecodes.h" 31#include "src/interpreter/interpreter.h" 32#include "src/libsampler/sampler.h" 33#include "src/logging/counters.h" 34#include "src/logging/log-inl.h" 35#include "src/logging/log-utils.h" 36#include "src/objects/api-callbacks.h" 37#include "src/objects/code-kind.h" 38#include "src/objects/code.h" 39#include "src/profiler/tick-sample.h" 40#include "src/snapshot/embedded/embedded-data.h" 41#include "src/strings/string-stream.h" 42#include "src/strings/unicode-inl.h" 43#include "src/tracing/tracing-category-observer.h" 44#include "src/utils/memcopy.h" 45#include "src/utils/version.h" 46 47#ifdef ENABLE_GDB_JIT_INTERFACE 48#include "src/diagnostics/gdb-jit.h" 49#endif // ENABLE_GDB_JIT_INTERFACE 50 51#if V8_ENABLE_WEBASSEMBLY 52#include "src/wasm/wasm-code-manager.h" 53#include "src/wasm/wasm-engine.h" 54#include "src/wasm/wasm-objects-inl.h" 55#endif // V8_ENABLE_WEBASSEMBLY 56 57#if V8_OS_WIN 58#if defined(V8_ENABLE_SYSTEM_INSTRUMENTATION) 59#include "src/diagnostics/system-jit-win.h" 60#endif 61#endif // V8_OS_WIN 62 63namespace v8 { 64namespace internal { 65 66#define DECLARE_EVENT(ignore1, name) #name, 67static const char* kLogEventsNames[CodeEventListener::NUMBER_OF_LOG_EVENTS] = { 68 LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)}; 69#undef DECLARE_EVENT 70 71static v8::CodeEventType GetCodeEventTypeForTag( 72 CodeEventListener::LogEventsAndTags tag) { 73 switch (tag) { 74 case CodeEventListener::NUMBER_OF_LOG_EVENTS: 75#define V(Event, _) case CodeEventListener::Event: 76 LOG_EVENTS_LIST(V) 77#undef V 78 return v8::CodeEventType::kUnknownType; 79#define V(From, To) \ 80 case CodeEventListener::From: \ 81 return v8::CodeEventType::k##To##Type; 82 TAGS_LIST(V) 83#undef V 84 } 85 // The execution should never pass here 86 UNREACHABLE(); 87} 88#define CALL_CODE_EVENT_HANDLER(Call) \ 89 if (listener_) { \ 90 listener_->Call; \ 91 } else { \ 92 PROFILE(isolate_, Call); \ 93 } 94 95static const char* ComputeMarker(SharedFunctionInfo shared, AbstractCode code) { 96 CodeKind kind = code.kind(); 97 // We record interpreter trampoline builtin copies as having the 98 // "interpreted" marker. 99 if (FLAG_interpreted_frames_native_stack && kind == CodeKind::BUILTIN && 100 code.GetCode().is_interpreter_trampoline_builtin() && 101 ToCodeT(code.GetCode()) != 102 *BUILTIN_CODE(shared.GetIsolate(), InterpreterEntryTrampoline)) { 103 kind = CodeKind::INTERPRETED_FUNCTION; 104 } 105 if (shared.optimization_disabled() && 106 kind == CodeKind::INTERPRETED_FUNCTION) { 107 return ""; 108 } 109 return CodeKindToMarker(kind); 110} 111 112#if V8_ENABLE_WEBASSEMBLY 113static const char* ComputeMarker(const wasm::WasmCode* code) { 114 switch (code->kind()) { 115 case wasm::WasmCode::kWasmFunction: 116 return code->is_liftoff() ? "" : "*"; 117 default: 118 return ""; 119 } 120} 121#endif // V8_ENABLE_WEBASSEMBLY 122 123class CodeEventLogger::NameBuffer { 124 public: 125 NameBuffer() { Reset(); } 126 127 void Reset() { utf8_pos_ = 0; } 128 129 void Init(LogEventsAndTags tag) { 130 Reset(); 131 AppendBytes(kLogEventsNames[tag]); 132 AppendByte(':'); 133 } 134 135 void AppendName(Name name) { 136 if (name.IsString()) { 137 AppendString(String::cast(name)); 138 } else { 139 Symbol symbol = Symbol::cast(name); 140 AppendBytes("symbol("); 141 if (!symbol.description().IsUndefined()) { 142 AppendBytes("\""); 143 AppendString(String::cast(symbol.description())); 144 AppendBytes("\" "); 145 } 146 AppendBytes("hash "); 147 AppendHex(symbol.hash()); 148 AppendByte(')'); 149 } 150 } 151 152 void AppendString(String str) { 153 if (str.is_null()) return; 154 int length = 0; 155 std::unique_ptr<char[]> c_str = 156 str.ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL, &length); 157 AppendBytes(c_str.get(), length); 158 } 159 160 void AppendBytes(const char* bytes, int size) { 161 size = std::min(size, kUtf8BufferSize - utf8_pos_); 162 MemCopy(utf8_buffer_ + utf8_pos_, bytes, size); 163 utf8_pos_ += size; 164 } 165 166 void AppendBytes(const char* bytes) { 167 size_t len = strlen(bytes); 168 DCHECK_GE(kMaxInt, len); 169 AppendBytes(bytes, static_cast<int>(len)); 170 } 171 172 void AppendByte(char c) { 173 if (utf8_pos_ >= kUtf8BufferSize) return; 174 utf8_buffer_[utf8_pos_++] = c; 175 } 176 177 void AppendInt(int n) { 178 int space = kUtf8BufferSize - utf8_pos_; 179 if (space <= 0) return; 180 base::Vector<char> buffer(utf8_buffer_ + utf8_pos_, space); 181 int size = SNPrintF(buffer, "%d", n); 182 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) { 183 utf8_pos_ += size; 184 } 185 } 186 187 void AppendHex(uint32_t n) { 188 int space = kUtf8BufferSize - utf8_pos_; 189 if (space <= 0) return; 190 base::Vector<char> buffer(utf8_buffer_ + utf8_pos_, space); 191 int size = SNPrintF(buffer, "%x", n); 192 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) { 193 utf8_pos_ += size; 194 } 195 } 196 197 const char* get() { return utf8_buffer_; } 198 int size() const { return utf8_pos_; } 199 200 private: 201 static const int kUtf8BufferSize = 512; 202 static const int kUtf16BufferSize = kUtf8BufferSize; 203 204 int utf8_pos_; 205 char utf8_buffer_[kUtf8BufferSize]; 206}; 207 208CodeEventLogger::CodeEventLogger(Isolate* isolate) 209 : isolate_(isolate), name_buffer_(std::make_unique<NameBuffer>()) {} 210 211CodeEventLogger::~CodeEventLogger() = default; 212 213void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag, 214 Handle<AbstractCode> code, 215 const char* comment) { 216 DCHECK(is_listening_to_code_events()); 217 name_buffer_->Init(tag); 218 name_buffer_->AppendBytes(comment); 219 LogRecordedBuffer(code, MaybeHandle<SharedFunctionInfo>(), 220 name_buffer_->get(), name_buffer_->size()); 221} 222 223void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag, 224 Handle<AbstractCode> code, 225 Handle<Name> name) { 226 DCHECK(is_listening_to_code_events()); 227 name_buffer_->Init(tag); 228 name_buffer_->AppendName(*name); 229 LogRecordedBuffer(code, MaybeHandle<SharedFunctionInfo>(), 230 name_buffer_->get(), name_buffer_->size()); 231} 232 233void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag, 234 Handle<AbstractCode> code, 235 Handle<SharedFunctionInfo> shared, 236 Handle<Name> script_name) { 237 DCHECK(is_listening_to_code_events()); 238 name_buffer_->Init(tag); 239 name_buffer_->AppendBytes(ComputeMarker(*shared, *code)); 240 name_buffer_->AppendByte(' '); 241 name_buffer_->AppendName(*script_name); 242 LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); 243} 244 245void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag, 246 Handle<AbstractCode> code, 247 Handle<SharedFunctionInfo> shared, 248 Handle<Name> script_name, int line, 249 int column) { 250 DCHECK(is_listening_to_code_events()); 251 name_buffer_->Init(tag); 252 name_buffer_->AppendBytes(ComputeMarker(*shared, *code)); 253 name_buffer_->AppendBytes(shared->DebugNameCStr().get()); 254 name_buffer_->AppendByte(' '); 255 if (script_name->IsString()) { 256 name_buffer_->AppendString(String::cast(*script_name)); 257 } else { 258 name_buffer_->AppendBytes("symbol(hash "); 259 name_buffer_->AppendHex(Name::cast(*script_name).hash()); 260 name_buffer_->AppendByte(')'); 261 } 262 name_buffer_->AppendByte(':'); 263 name_buffer_->AppendInt(line); 264 LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); 265} 266 267#if V8_ENABLE_WEBASSEMBLY 268void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag, 269 const wasm::WasmCode* code, 270 wasm::WasmName name, 271 const char* source_url, 272 int /*code_offset*/, int /*script_id*/) { 273 DCHECK(is_listening_to_code_events()); 274 name_buffer_->Init(tag); 275 DCHECK(!name.empty()); 276 name_buffer_->AppendBytes(name.begin(), name.length()); 277 name_buffer_->AppendByte('-'); 278 if (code->IsAnonymous()) { 279 name_buffer_->AppendBytes("<anonymous>"); 280 } else { 281 name_buffer_->AppendInt(code->index()); 282 } 283 name_buffer_->AppendByte('-'); 284 name_buffer_->AppendBytes(ExecutionTierToString(code->tier())); 285 LogRecordedBuffer(code, name_buffer_->get(), name_buffer_->size()); 286} 287#endif // V8_ENABLE_WEBASSEMBLY 288 289void CodeEventLogger::RegExpCodeCreateEvent(Handle<AbstractCode> code, 290 Handle<String> source) { 291 DCHECK(is_listening_to_code_events()); 292 name_buffer_->Init(CodeEventListener::REG_EXP_TAG); 293 name_buffer_->AppendString(*source); 294 LogRecordedBuffer(code, MaybeHandle<SharedFunctionInfo>(), 295 name_buffer_->get(), name_buffer_->size()); 296} 297 298// Linux perf tool logging support. 299#if V8_OS_LINUX 300class PerfBasicLogger : public CodeEventLogger { 301 public: 302 explicit PerfBasicLogger(Isolate* isolate); 303 ~PerfBasicLogger() override; 304 305 void CodeMoveEvent(AbstractCode from, AbstractCode to) override {} 306 void CodeDisableOptEvent(Handle<AbstractCode> code, 307 Handle<SharedFunctionInfo> shared) override {} 308 309 private: 310 void LogRecordedBuffer(Handle<AbstractCode> code, 311 MaybeHandle<SharedFunctionInfo> maybe_shared, 312 const char* name, int length) override; 313#if V8_ENABLE_WEBASSEMBLY 314 void LogRecordedBuffer(const wasm::WasmCode* code, const char* name, 315 int length) override; 316#endif // V8_ENABLE_WEBASSEMBLY 317 void WriteLogRecordedBuffer(uintptr_t address, int size, const char* name, 318 int name_length); 319 320 // Extension added to V8 log file name to get the low-level log name. 321 static const char kFilenameFormatString[]; 322 static const int kFilenameBufferPadding; 323 324 FILE* perf_output_handle_; 325}; 326 327const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map"; 328// Extra space for the PID in the filename 329const int PerfBasicLogger::kFilenameBufferPadding = 16; 330 331PerfBasicLogger::PerfBasicLogger(Isolate* isolate) 332 : CodeEventLogger(isolate), perf_output_handle_(nullptr) { 333 // Open the perf JIT dump file. 334 int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding; 335 base::ScopedVector<char> perf_dump_name(bufferSize); 336 int size = SNPrintF(perf_dump_name, kFilenameFormatString, 337 base::OS::GetCurrentProcessId()); 338 CHECK_NE(size, -1); 339 perf_output_handle_ = 340 base::OS::FOpen(perf_dump_name.begin(), base::OS::LogFileOpenMode); 341 CHECK_NOT_NULL(perf_output_handle_); 342 setvbuf(perf_output_handle_, nullptr, _IOLBF, 0); 343} 344 345PerfBasicLogger::~PerfBasicLogger() { 346 base::Fclose(perf_output_handle_); 347 perf_output_handle_ = nullptr; 348} 349 350void PerfBasicLogger::WriteLogRecordedBuffer(uintptr_t address, int size, 351 const char* name, 352 int name_length) { 353 // Linux perf expects hex literals without a leading 0x, while some 354 // implementations of printf might prepend one when using the %p format 355 // for pointers, leading to wrongly formatted JIT symbols maps. 356 // 357 // Instead, we use V8PRIxPTR format string and cast pointer to uintpr_t, 358 // so that we have control over the exact output format. 359 base::OS::FPrint(perf_output_handle_, "%" V8PRIxPTR " %x %.*s\n", address, 360 size, name_length, name); 361} 362 363void PerfBasicLogger::LogRecordedBuffer(Handle<AbstractCode> code, 364 MaybeHandle<SharedFunctionInfo>, 365 const char* name, int length) { 366 if (FLAG_perf_basic_prof_only_functions && 367 !CodeKindIsBuiltinOrJSFunction(code->kind())) { 368 return; 369 } 370 371 WriteLogRecordedBuffer(static_cast<uintptr_t>(code->InstructionStart()), 372 code->InstructionSize(), name, length); 373} 374 375#if V8_ENABLE_WEBASSEMBLY 376void PerfBasicLogger::LogRecordedBuffer(const wasm::WasmCode* code, 377 const char* name, int length) { 378 WriteLogRecordedBuffer(static_cast<uintptr_t>(code->instruction_start()), 379 code->instructions().length(), name, length); 380} 381#endif // V8_ENABLE_WEBASSEMBLY 382#endif // V8_OS_LINUX 383 384// External CodeEventListener 385ExternalCodeEventListener::ExternalCodeEventListener(Isolate* isolate) 386 : is_listening_(false), isolate_(isolate), code_event_handler_(nullptr) {} 387 388ExternalCodeEventListener::~ExternalCodeEventListener() { 389 if (is_listening_) { 390 StopListening(); 391 } 392} 393 394void ExternalCodeEventListener::LogExistingCode() { 395 HandleScope scope(isolate_); 396 ExistingCodeLogger logger(isolate_, this); 397 logger.LogCodeObjects(); 398 logger.LogCompiledFunctions(); 399} 400 401void ExternalCodeEventListener::StartListening( 402 CodeEventHandler* code_event_handler) { 403 if (is_listening_ || code_event_handler == nullptr) { 404 return; 405 } 406 code_event_handler_ = code_event_handler; 407 is_listening_ = isolate_->code_event_dispatcher()->AddListener(this); 408 if (is_listening_) { 409 LogExistingCode(); 410 } 411} 412 413void ExternalCodeEventListener::StopListening() { 414 if (!is_listening_) { 415 return; 416 } 417 418 isolate_->code_event_dispatcher()->RemoveListener(this); 419 is_listening_ = false; 420} 421 422void ExternalCodeEventListener::CodeCreateEvent(LogEventsAndTags tag, 423 Handle<AbstractCode> code, 424 const char* comment) { 425 CodeEvent code_event; 426 code_event.code_start_address = 427 static_cast<uintptr_t>(code->InstructionStart()); 428 code_event.code_size = static_cast<size_t>(code->InstructionSize()); 429 code_event.function_name = isolate_->factory()->empty_string(); 430 code_event.script_name = isolate_->factory()->empty_string(); 431 code_event.script_line = 0; 432 code_event.script_column = 0; 433 code_event.code_type = GetCodeEventTypeForTag(tag); 434 code_event.comment = comment; 435 436 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event)); 437} 438 439void ExternalCodeEventListener::CodeCreateEvent(LogEventsAndTags tag, 440 Handle<AbstractCode> code, 441 Handle<Name> name) { 442 Handle<String> name_string = 443 Name::ToFunctionName(isolate_, name).ToHandleChecked(); 444 445 CodeEvent code_event; 446 code_event.code_start_address = 447 static_cast<uintptr_t>(code->InstructionStart()); 448 code_event.code_size = static_cast<size_t>(code->InstructionSize()); 449 code_event.function_name = name_string; 450 code_event.script_name = isolate_->factory()->empty_string(); 451 code_event.script_line = 0; 452 code_event.script_column = 0; 453 code_event.code_type = GetCodeEventTypeForTag(tag); 454 code_event.comment = ""; 455 456 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event)); 457} 458 459void ExternalCodeEventListener::CodeCreateEvent( 460 LogEventsAndTags tag, Handle<AbstractCode> code, 461 Handle<SharedFunctionInfo> shared, Handle<Name> name) { 462 Handle<String> name_string = 463 Name::ToFunctionName(isolate_, name).ToHandleChecked(); 464 465 CodeEvent code_event; 466 code_event.code_start_address = 467 static_cast<uintptr_t>(code->InstructionStart()); 468 code_event.code_size = static_cast<size_t>(code->InstructionSize()); 469 code_event.function_name = name_string; 470 code_event.script_name = isolate_->factory()->empty_string(); 471 code_event.script_line = 0; 472 code_event.script_column = 0; 473 code_event.code_type = GetCodeEventTypeForTag(tag); 474 code_event.comment = ""; 475 476 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event)); 477} 478 479void ExternalCodeEventListener::CodeCreateEvent( 480 LogEventsAndTags tag, Handle<AbstractCode> code, 481 Handle<SharedFunctionInfo> shared, Handle<Name> source, int line, 482 int column) { 483 Handle<String> name_string = 484 Name::ToFunctionName(isolate_, handle(shared->Name(), isolate_)) 485 .ToHandleChecked(); 486 Handle<String> source_string = 487 Name::ToFunctionName(isolate_, source).ToHandleChecked(); 488 489 CodeEvent code_event; 490 code_event.code_start_address = 491 static_cast<uintptr_t>(code->InstructionStart()); 492 code_event.code_size = static_cast<size_t>(code->InstructionSize()); 493 code_event.function_name = name_string; 494 code_event.script_name = source_string; 495 code_event.script_line = line; 496 code_event.script_column = column; 497 code_event.code_type = GetCodeEventTypeForTag(tag); 498 code_event.comment = ""; 499 500 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event)); 501} 502 503#if V8_ENABLE_WEBASSEMBLY 504void ExternalCodeEventListener::CodeCreateEvent( 505 LogEventsAndTags tag, const wasm::WasmCode* code, wasm::WasmName name, 506 const char* source_url, int code_offset, int script_id) { 507 // TODO(mmarchini): handle later 508} 509#endif // V8_ENABLE_WEBASSEMBLY 510 511void ExternalCodeEventListener::RegExpCodeCreateEvent(Handle<AbstractCode> code, 512 Handle<String> source) { 513 CodeEvent code_event; 514 code_event.code_start_address = 515 static_cast<uintptr_t>(code->InstructionStart()); 516 code_event.code_size = static_cast<size_t>(code->InstructionSize()); 517 code_event.function_name = source; 518 code_event.script_name = isolate_->factory()->empty_string(); 519 code_event.script_line = 0; 520 code_event.script_column = 0; 521 code_event.code_type = GetCodeEventTypeForTag(CodeEventListener::REG_EXP_TAG); 522 code_event.comment = ""; 523 524 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event)); 525} 526 527void ExternalCodeEventListener::CodeMoveEvent(AbstractCode from, 528 AbstractCode to) { 529 CodeEvent code_event; 530 code_event.previous_code_start_address = 531 static_cast<uintptr_t>(from.InstructionStart()); 532 code_event.code_start_address = static_cast<uintptr_t>(to.InstructionStart()); 533 code_event.code_size = static_cast<size_t>(to.InstructionSize()); 534 code_event.function_name = isolate_->factory()->empty_string(); 535 code_event.script_name = isolate_->factory()->empty_string(); 536 code_event.script_line = 0; 537 code_event.script_column = 0; 538 code_event.code_type = v8::CodeEventType::kRelocationType; 539 code_event.comment = ""; 540 541 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event)); 542} 543 544// Low-level logging support. 545class LowLevelLogger : public CodeEventLogger { 546 public: 547 LowLevelLogger(Isolate* isolate, const char* file_name); 548 ~LowLevelLogger() override; 549 550 void CodeMoveEvent(AbstractCode from, AbstractCode to) override; 551 void CodeDisableOptEvent(Handle<AbstractCode> code, 552 Handle<SharedFunctionInfo> shared) override {} 553 void SnapshotPositionEvent(HeapObject obj, int pos); 554 void CodeMovingGCEvent() override; 555 556 private: 557 void LogRecordedBuffer(Handle<AbstractCode> code, 558 MaybeHandle<SharedFunctionInfo> maybe_shared, 559 const char* name, int length) override; 560#if V8_ENABLE_WEBASSEMBLY 561 void LogRecordedBuffer(const wasm::WasmCode* code, const char* name, 562 int length) override; 563#endif // V8_ENABLE_WEBASSEMBLY 564 565 // Low-level profiling event structures. 566 struct CodeCreateStruct { 567 static const char kTag = 'C'; 568 569 int32_t name_size; 570 Address code_address; 571 int32_t code_size; 572 }; 573 574 struct CodeMoveStruct { 575 static const char kTag = 'M'; 576 577 Address from_address; 578 Address to_address; 579 }; 580 581 static const char kCodeMovingGCTag = 'G'; 582 583 // Extension added to V8 log file name to get the low-level log name. 584 static const char kLogExt[]; 585 586 void LogCodeInfo(); 587 void LogWriteBytes(const char* bytes, int size); 588 589 template <typename T> 590 void LogWriteStruct(const T& s) { 591 char tag = T::kTag; 592 LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag)); 593 LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s)); 594 } 595 596 FILE* ll_output_handle_; 597}; 598 599const char LowLevelLogger::kLogExt[] = ".ll"; 600 601LowLevelLogger::LowLevelLogger(Isolate* isolate, const char* name) 602 : CodeEventLogger(isolate), ll_output_handle_(nullptr) { 603 // Open the low-level log file. 604 size_t len = strlen(name); 605 base::ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt))); 606 MemCopy(ll_name.begin(), name, len); 607 MemCopy(ll_name.begin() + len, kLogExt, sizeof(kLogExt)); 608 ll_output_handle_ = 609 base::OS::FOpen(ll_name.begin(), base::OS::LogFileOpenMode); 610 setvbuf(ll_output_handle_, nullptr, _IOLBF, 0); 611 612 LogCodeInfo(); 613} 614 615LowLevelLogger::~LowLevelLogger() { 616 base::Fclose(ll_output_handle_); 617 ll_output_handle_ = nullptr; 618} 619 620void LowLevelLogger::LogCodeInfo() { 621#if V8_TARGET_ARCH_IA32 622 const char arch[] = "ia32"; 623#elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_64_BIT 624 const char arch[] = "x64"; 625#elif V8_TARGET_ARCH_ARM 626 const char arch[] = "arm"; 627#elif V8_TARGET_ARCH_PPC 628 const char arch[] = "ppc"; 629#elif V8_TARGET_ARCH_PPC64 630 const char arch[] = "ppc64"; 631#elif V8_TARGET_ARCH_MIPS 632 const char arch[] = "mips"; 633#elif V8_TARGET_ARCH_LOONG64 634 const char arch[] = "loong64"; 635#elif V8_TARGET_ARCH_ARM64 636 const char arch[] = "arm64"; 637#elif V8_TARGET_ARCH_S390 638 const char arch[] = "s390"; 639#elif V8_TARGET_ARCH_RISCV64 640 const char arch[] = "riscv64"; 641#else 642 const char arch[] = "unknown"; 643#endif 644 LogWriteBytes(arch, sizeof(arch)); 645} 646 647void LowLevelLogger::LogRecordedBuffer(Handle<AbstractCode> code, 648 MaybeHandle<SharedFunctionInfo>, 649 const char* name, int length) { 650 CodeCreateStruct event; 651 event.name_size = length; 652 event.code_address = code->InstructionStart(); 653 event.code_size = code->InstructionSize(); 654 LogWriteStruct(event); 655 LogWriteBytes(name, length); 656 LogWriteBytes(reinterpret_cast<const char*>(code->InstructionStart()), 657 code->InstructionSize()); 658} 659 660#if V8_ENABLE_WEBASSEMBLY 661void LowLevelLogger::LogRecordedBuffer(const wasm::WasmCode* code, 662 const char* name, int length) { 663 CodeCreateStruct event; 664 event.name_size = length; 665 event.code_address = code->instruction_start(); 666 event.code_size = code->instructions().length(); 667 LogWriteStruct(event); 668 LogWriteBytes(name, length); 669 LogWriteBytes(reinterpret_cast<const char*>(code->instruction_start()), 670 code->instructions().length()); 671} 672#endif // V8_ENABLE_WEBASSEMBLY 673 674void LowLevelLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) { 675 CodeMoveStruct event; 676 event.from_address = from.InstructionStart(); 677 event.to_address = to.InstructionStart(); 678 LogWriteStruct(event); 679} 680 681void LowLevelLogger::LogWriteBytes(const char* bytes, int size) { 682 size_t rv = fwrite(bytes, 1, size, ll_output_handle_); 683 DCHECK(static_cast<size_t>(size) == rv); 684 USE(rv); 685} 686 687void LowLevelLogger::CodeMovingGCEvent() { 688 const char tag = kCodeMovingGCTag; 689 690 LogWriteBytes(&tag, sizeof(tag)); 691} 692 693class JitLogger : public CodeEventLogger { 694 public: 695 JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler); 696 697 void CodeMoveEvent(AbstractCode from, AbstractCode to) override; 698 void CodeDisableOptEvent(Handle<AbstractCode> code, 699 Handle<SharedFunctionInfo> shared) override {} 700 void AddCodeLinePosInfoEvent(void* jit_handler_data, int pc_offset, 701 int position, 702 JitCodeEvent::PositionType position_type, 703 JitCodeEvent::CodeType code_type); 704 705 void* StartCodePosInfoEvent(JitCodeEvent::CodeType code_type); 706 void EndCodePosInfoEvent(Address start_address, void* jit_handler_data, 707 JitCodeEvent::CodeType code_type); 708 709 private: 710 void LogRecordedBuffer(Handle<AbstractCode> code, 711 MaybeHandle<SharedFunctionInfo> maybe_shared, 712 const char* name, int length) override; 713#if V8_ENABLE_WEBASSEMBLY 714 void LogRecordedBuffer(const wasm::WasmCode* code, const char* name, 715 int length) override; 716#endif // V8_ENABLE_WEBASSEMBLY 717 718 JitCodeEventHandler code_event_handler_; 719 base::Mutex logger_mutex_; 720}; 721 722JitLogger::JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler) 723 : CodeEventLogger(isolate), code_event_handler_(code_event_handler) {} 724 725void JitLogger::LogRecordedBuffer(Handle<AbstractCode> code, 726 MaybeHandle<SharedFunctionInfo> maybe_shared, 727 const char* name, int length) { 728 JitCodeEvent event = {}; 729 event.type = JitCodeEvent::CODE_ADDED; 730 event.code_start = reinterpret_cast<void*>(code->InstructionStart()); 731 event.code_type = 732 code->IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE; 733 event.code_len = code->InstructionSize(); 734 Handle<SharedFunctionInfo> shared; 735 if (maybe_shared.ToHandle(&shared) && shared->script().IsScript()) { 736 event.script = ToApiHandle<v8::UnboundScript>(shared); 737 } else { 738 event.script = Local<v8::UnboundScript>(); 739 } 740 event.name.str = name; 741 event.name.len = length; 742 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_); 743 code_event_handler_(&event); 744} 745 746#if V8_ENABLE_WEBASSEMBLY 747void JitLogger::LogRecordedBuffer(const wasm::WasmCode* code, const char* name, 748 int length) { 749 JitCodeEvent event = {}; 750 event.type = JitCodeEvent::CODE_ADDED; 751 event.code_type = JitCodeEvent::WASM_CODE; 752 event.code_start = code->instructions().begin(); 753 event.code_len = code->instructions().length(); 754 event.name.str = name; 755 event.name.len = length; 756 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_); 757 758 wasm::WasmModuleSourceMap* source_map = 759 code->native_module()->GetWasmSourceMap(); 760 wasm::WireBytesRef code_ref = 761 code->native_module()->module()->functions[code->index()].code; 762 uint32_t code_offset = code_ref.offset(); 763 uint32_t code_end_offset = code_ref.end_offset(); 764 765 std::vector<v8::JitCodeEvent::line_info_t> mapping_info; 766 std::string filename; 767 std::unique_ptr<JitCodeEvent::wasm_source_info_t> wasm_source_info; 768 769 if (source_map && source_map->IsValid() && 770 source_map->HasSource(code_offset, code_end_offset)) { 771 size_t last_line_number = 0; 772 773 for (SourcePositionTableIterator iterator(code->source_positions()); 774 !iterator.done(); iterator.Advance()) { 775 uint32_t offset = iterator.source_position().ScriptOffset() + code_offset; 776 if (!source_map->HasValidEntry(code_offset, offset)) continue; 777 if (filename.empty()) { 778 filename = source_map->GetFilename(offset); 779 } 780 mapping_info.push_back({static_cast<size_t>(iterator.code_offset()), 781 last_line_number, JitCodeEvent::POSITION}); 782 last_line_number = source_map->GetSourceLine(offset) + 1; 783 } 784 785 wasm_source_info = std::make_unique<JitCodeEvent::wasm_source_info_t>(); 786 wasm_source_info->filename = filename.c_str(); 787 wasm_source_info->filename_size = filename.size(); 788 wasm_source_info->line_number_table_size = mapping_info.size(); 789 wasm_source_info->line_number_table = mapping_info.data(); 790 791 event.wasm_source_info = wasm_source_info.get(); 792 } 793 code_event_handler_(&event); 794} 795#endif // V8_ENABLE_WEBASSEMBLY 796 797void JitLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) { 798 base::MutexGuard guard(&logger_mutex_); 799 800 JitCodeEvent event; 801 event.type = JitCodeEvent::CODE_MOVED; 802 event.code_type = 803 from.IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE; 804 event.code_start = reinterpret_cast<void*>(from.InstructionStart()); 805 event.code_len = from.InstructionSize(); 806 event.new_code_start = reinterpret_cast<void*>(to.InstructionStart()); 807 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_); 808 809 code_event_handler_(&event); 810} 811 812void JitLogger::AddCodeLinePosInfoEvent( 813 void* jit_handler_data, int pc_offset, int position, 814 JitCodeEvent::PositionType position_type, 815 JitCodeEvent::CodeType code_type) { 816 JitCodeEvent event = {}; 817 event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO; 818 event.code_type = code_type; 819 event.user_data = jit_handler_data; 820 event.line_info.offset = pc_offset; 821 event.line_info.pos = position; 822 event.line_info.position_type = position_type; 823 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_); 824 825 code_event_handler_(&event); 826} 827 828void* JitLogger::StartCodePosInfoEvent(JitCodeEvent::CodeType code_type) { 829 JitCodeEvent event = {}; 830 event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING; 831 event.code_type = code_type; 832 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_); 833 834 code_event_handler_(&event); 835 return event.user_data; 836} 837 838void JitLogger::EndCodePosInfoEvent(Address start_address, 839 void* jit_handler_data, 840 JitCodeEvent::CodeType code_type) { 841 JitCodeEvent event = {}; 842 event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING; 843 event.code_type = code_type; 844 event.code_start = reinterpret_cast<void*>(start_address); 845 event.user_data = jit_handler_data; 846 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_); 847 848 code_event_handler_(&event); 849} 850 851// TODO(lpy): Keeping sampling thread inside V8 is a workaround currently, 852// the reason is to reduce code duplication during migration to sampler library, 853// sampling thread, as well as the sampler, will be moved to D8 eventually. 854class SamplingThread : public base::Thread { 855 public: 856 static const int kSamplingThreadStackSize = 64 * KB; 857 858 SamplingThread(sampler::Sampler* sampler, int interval_microseconds) 859 : base::Thread( 860 base::Thread::Options("SamplingThread", kSamplingThreadStackSize)), 861 sampler_(sampler), 862 interval_microseconds_(interval_microseconds) {} 863 void Run() override { 864 while (sampler_->IsActive()) { 865 sampler_->DoSample(); 866 base::OS::Sleep( 867 base::TimeDelta::FromMicroseconds(interval_microseconds_)); 868 } 869 } 870 871 private: 872 sampler::Sampler* sampler_; 873 const int interval_microseconds_; 874}; 875 876// The Profiler samples pc and sp values for the main thread. 877// Each sample is appended to a circular buffer. 878// An independent thread removes data and writes it to the log. 879// This design minimizes the time spent in the sampler. 880// 881class Profiler : public base::Thread { 882 public: 883 explicit Profiler(Isolate* isolate); 884 void Engage(); 885 void Disengage(); 886 887 // Inserts collected profiling data into buffer. 888 void Insert(TickSample* sample) { 889 if (Succ(head_) == static_cast<int>(base::Relaxed_Load(&tail_))) { 890 overflow_ = true; 891 } else { 892 buffer_[head_] = *sample; 893 head_ = Succ(head_); 894 buffer_semaphore_.Signal(); // Tell we have an element. 895 } 896 } 897 898 void Run() override; 899 900 private: 901 // Waits for a signal and removes profiling data. 902 bool Remove(TickSample* sample) { 903 buffer_semaphore_.Wait(); // Wait for an element. 904 *sample = buffer_[base::Relaxed_Load(&tail_)]; 905 bool result = overflow_; 906 base::Relaxed_Store( 907 &tail_, static_cast<base::Atomic32>(Succ(base::Relaxed_Load(&tail_)))); 908 overflow_ = false; 909 return result; 910 } 911 912 // Returns the next index in the cyclic buffer. 913 int Succ(int index) { return (index + 1) % kBufferSize; } 914 915 Isolate* isolate_; 916 // Cyclic buffer for communicating profiling samples 917 // between the signal handler and the worker thread. 918 static const int kBufferSize = 128; 919 TickSample buffer_[kBufferSize]; // Buffer storage. 920 int head_; // Index to the buffer head. 921 base::Atomic32 tail_; // Index to the buffer tail. 922 bool overflow_; // Tell whether a buffer overflow has occurred. 923 // Semaphore used for buffer synchronization. 924 base::Semaphore buffer_semaphore_; 925 926 // Tells whether worker thread should continue running. 927 base::Atomic32 running_; 928}; 929 930// 931// Ticker used to provide ticks to the profiler and the sliding state 932// window. 933// 934class Ticker : public sampler::Sampler { 935 public: 936 Ticker(Isolate* isolate, int interval_microseconds) 937 : sampler::Sampler(reinterpret_cast<v8::Isolate*>(isolate)), 938 sampling_thread_( 939 std::make_unique<SamplingThread>(this, interval_microseconds)), 940 perThreadData_(isolate->FindPerThreadDataForThisThread()) {} 941 942 ~Ticker() override { 943 if (IsActive()) Stop(); 944 } 945 946 void SetProfiler(Profiler* profiler) { 947 DCHECK_NULL(profiler_); 948 profiler_ = profiler; 949 if (!IsActive()) Start(); 950 sampling_thread_->StartSynchronously(); 951 } 952 953 void ClearProfiler() { 954 profiler_ = nullptr; 955 if (IsActive()) Stop(); 956 sampling_thread_->Join(); 957 } 958 959 void SampleStack(const v8::RegisterState& state) override { 960 if (!profiler_) return; 961 Isolate* isolate = reinterpret_cast<Isolate*>(this->isolate()); 962 if (isolate->was_locker_ever_used() && 963 (!isolate->thread_manager()->IsLockedByThread( 964 perThreadData_->thread_id()) || 965 perThreadData_->thread_state() != nullptr)) 966 return; 967 TickSample sample; 968 sample.Init(isolate, state, TickSample::kIncludeCEntryFrame, true); 969 profiler_->Insert(&sample); 970 } 971 972 private: 973 Profiler* profiler_ = nullptr; 974 std::unique_ptr<SamplingThread> sampling_thread_; 975 Isolate::PerIsolateThreadData* perThreadData_; 976}; 977 978// 979// Profiler implementation when invoking with --prof. 980// 981Profiler::Profiler(Isolate* isolate) 982 : base::Thread(Options("v8:Profiler")), 983 isolate_(isolate), 984 head_(0), 985 overflow_(false), 986 buffer_semaphore_(0) { 987 base::Relaxed_Store(&tail_, 0); 988 base::Relaxed_Store(&running_, 0); 989} 990 991void Profiler::Engage() { 992 std::vector<base::OS::SharedLibraryAddress> addresses = 993 base::OS::GetSharedLibraryAddresses(); 994 for (const auto& address : addresses) { 995 LOG(isolate_, SharedLibraryEvent(address.library_path, address.start, 996 address.end, address.aslr_slide)); 997 } 998 LOG(isolate_, SharedLibraryEnd()); 999 1000 // Start thread processing the profiler buffer. 1001 base::Relaxed_Store(&running_, 1); 1002 CHECK(Start()); 1003 1004 // Register to get ticks. 1005 Logger* logger = isolate_->logger(); 1006 logger->ticker_->SetProfiler(this); 1007 1008 LOG(isolate_, ProfilerBeginEvent()); 1009} 1010 1011void Profiler::Disengage() { 1012 // Stop receiving ticks. 1013 isolate_->logger()->ticker_->ClearProfiler(); 1014 1015 // Terminate the worker thread by setting running_ to false, 1016 // inserting a fake element in the queue and then wait for 1017 // the thread to terminate. 1018 base::Relaxed_Store(&running_, 0); 1019 TickSample sample; 1020 Insert(&sample); 1021 Join(); 1022 1023 LOG(isolate_, UncheckedStringEvent("profiler", "end")); 1024} 1025 1026void Profiler::Run() { 1027 TickSample sample; 1028 bool overflow = Remove(&sample); 1029 while (base::Relaxed_Load(&running_)) { 1030 LOG(isolate_, TickEvent(&sample, overflow)); 1031 overflow = Remove(&sample); 1032 } 1033} 1034 1035// 1036// Logger class implementation. 1037// 1038#define MSG_BUILDER() \ 1039 std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder(); \ 1040 if (!msg_ptr) return; \ 1041 Log::MessageBuilder& msg = *msg_ptr.get(); 1042 1043Logger::Logger(Isolate* isolate) 1044 : isolate_(isolate), 1045 is_logging_(false), 1046 is_initialized_(false), 1047 existing_code_logger_(isolate) {} 1048 1049Logger::~Logger() = default; 1050 1051const LogSeparator Logger::kNext = LogSeparator::kSeparator; 1052 1053int64_t Logger::Time() { 1054 if (FLAG_verify_predictable) { 1055 return isolate_->heap()->MonotonicallyIncreasingTimeInMs() * 1000; 1056 } 1057 return timer_.Elapsed().InMicroseconds(); 1058} 1059 1060void Logger::AddCodeEventListener(CodeEventListener* listener) { 1061 bool result = isolate_->code_event_dispatcher()->AddListener(listener); 1062 CHECK(result); 1063} 1064 1065void Logger::RemoveCodeEventListener(CodeEventListener* listener) { 1066 isolate_->code_event_dispatcher()->RemoveListener(listener); 1067} 1068 1069void Logger::ProfilerBeginEvent() { 1070 MSG_BUILDER(); 1071 msg << "profiler" << kNext << "begin" << kNext << FLAG_prof_sampling_interval; 1072 msg.WriteToLogFile(); 1073} 1074 1075void Logger::StringEvent(const char* name, const char* value) { 1076 if (FLAG_log) UncheckedStringEvent(name, value); 1077} 1078 1079void Logger::UncheckedStringEvent(const char* name, const char* value) { 1080 MSG_BUILDER(); 1081 msg << name << kNext << value; 1082 msg.WriteToLogFile(); 1083} 1084 1085void Logger::IntPtrTEvent(const char* name, intptr_t value) { 1086 if (!FLAG_log) return; 1087 MSG_BUILDER(); 1088 msg << name << kNext; 1089 msg.AppendFormatString("%" V8PRIdPTR, value); 1090 msg.WriteToLogFile(); 1091} 1092 1093void Logger::SharedLibraryEvent(const std::string& library_path, 1094 uintptr_t start, uintptr_t end, 1095 intptr_t aslr_slide) { 1096 if (!FLAG_prof_cpp) return; 1097 MSG_BUILDER(); 1098 msg << "shared-library" << kNext << library_path.c_str() << kNext 1099 << reinterpret_cast<void*>(start) << kNext << reinterpret_cast<void*>(end) 1100 << kNext << aslr_slide; 1101 msg.WriteToLogFile(); 1102} 1103 1104void Logger::SharedLibraryEnd() { 1105 if (!FLAG_prof_cpp) return; 1106 MSG_BUILDER(); 1107 msg << "shared-library-end"; 1108 msg.WriteToLogFile(); 1109} 1110 1111void Logger::CurrentTimeEvent() { 1112 DCHECK(FLAG_log_internal_timer_events); 1113 MSG_BUILDER(); 1114 msg << "current-time" << kNext << Time(); 1115 msg.WriteToLogFile(); 1116} 1117 1118void Logger::TimerEvent(v8::LogEventStatus se, const char* name) { 1119 MSG_BUILDER(); 1120 switch (se) { 1121 case kStart: 1122 msg << "timer-event-start"; 1123 break; 1124 case kEnd: 1125 msg << "timer-event-end"; 1126 break; 1127 case kStamp: 1128 msg << "timer-event"; 1129 } 1130 msg << kNext << name << kNext << Time(); 1131 msg.WriteToLogFile(); 1132} 1133 1134void Logger::BasicBlockCounterEvent(const char* name, int block_id, 1135 uint32_t count) { 1136 if (!FLAG_turbo_profiling_log_builtins) return; 1137 MSG_BUILDER(); 1138 msg << ProfileDataFromFileConstants::kBlockCounterMarker << kNext << name 1139 << kNext << block_id << kNext << count; 1140 msg.WriteToLogFile(); 1141} 1142 1143void Logger::BuiltinHashEvent(const char* name, int hash) { 1144 if (!FLAG_turbo_profiling_log_builtins) return; 1145 MSG_BUILDER(); 1146 msg << ProfileDataFromFileConstants::kBuiltinHashMarker << kNext << name 1147 << kNext << hash; 1148 msg.WriteToLogFile(); 1149} 1150 1151bool Logger::is_logging() { 1152 // Disable logging while the CPU profiler is running. 1153 if (isolate_->is_profiling()) return false; 1154 return is_logging_.load(std::memory_order_relaxed); 1155} 1156 1157// Instantiate template methods. 1158#define V(TimerName, expose) \ 1159 template void TimerEventScope<TimerEvent##TimerName>::LogTimerEvent( \ 1160 v8::LogEventStatus se); 1161TIMER_EVENTS_LIST(V) 1162#undef V 1163 1164void Logger::NewEvent(const char* name, void* object, size_t size) { 1165 if (!FLAG_log) return; 1166 MSG_BUILDER(); 1167 msg << "new" << kNext << name << kNext << object << kNext 1168 << static_cast<unsigned int>(size); 1169 msg.WriteToLogFile(); 1170} 1171 1172void Logger::DeleteEvent(const char* name, void* object) { 1173 if (!FLAG_log) return; 1174 MSG_BUILDER(); 1175 msg << "delete" << kNext << name << kNext << object; 1176 msg.WriteToLogFile(); 1177} 1178 1179namespace { 1180 1181void AppendCodeCreateHeader(Log::MessageBuilder& msg, 1182 CodeEventListener::LogEventsAndTags tag, 1183 CodeKind kind, uint8_t* address, int size, 1184 uint64_t time) { 1185 msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] 1186 << Logger::kNext << kLogEventsNames[tag] << Logger::kNext 1187 << static_cast<int>(kind) << Logger::kNext << time << Logger::kNext 1188 << reinterpret_cast<void*>(address) << Logger::kNext << size 1189 << Logger::kNext; 1190} 1191 1192void AppendCodeCreateHeader(Log::MessageBuilder& msg, 1193 CodeEventListener::LogEventsAndTags tag, 1194 AbstractCode code, uint64_t time) { 1195 AppendCodeCreateHeader(msg, tag, code.kind(), 1196 reinterpret_cast<uint8_t*>(code.InstructionStart()), 1197 code.InstructionSize(), time); 1198} 1199 1200} // namespace 1201// We log source code information in the form: 1202// 1203// code-source-info <addr>,<script>,<start>,<end>,<pos>,<inline-pos>,<fns> 1204// 1205// where 1206// <addr> is code object address 1207// <script> is script id 1208// <start> is the starting position inside the script 1209// <end> is the end position inside the script 1210// <pos> is source position table encoded in the string, 1211// it is a sequence of C<code-offset>O<script-offset>[I<inlining-id>] 1212// where 1213// <code-offset> is the offset within the code object 1214// <script-offset> is the position within the script 1215// <inlining-id> is the offset in the <inlining> table 1216// <inlining> table is a sequence of strings of the form 1217// F<function-id>O<script-offset>[I<inlining-id>] 1218// where 1219// <function-id> is an index into the <fns> function table 1220// <fns> is the function table encoded as a sequence of strings 1221// S<shared-function-info-address> 1222 1223void Logger::LogSourceCodeInformation(Handle<AbstractCode> code, 1224 Handle<SharedFunctionInfo> shared) { 1225 Object script_object = shared->script(); 1226 if (!script_object.IsScript()) return; 1227 Script script = Script::cast(script_object); 1228 EnsureLogScriptSource(script); 1229 1230 MSG_BUILDER(); 1231 msg << "code-source-info" << Logger::kNext 1232 << reinterpret_cast<void*>(code->InstructionStart()) << Logger::kNext 1233 << script.id() << Logger::kNext << shared->StartPosition() 1234 << Logger::kNext << shared->EndPosition() << Logger::kNext; 1235 // TODO(v8:11429): Clean-up baseline-replated code in source position 1236 // iteration. 1237 bool hasInlined = false; 1238 if (code->kind() != CodeKind::BASELINE) { 1239 SourcePositionTableIterator iterator(code->SourcePositionTable(*shared)); 1240 for (; !iterator.done(); iterator.Advance()) { 1241 SourcePosition pos = iterator.source_position(); 1242 msg << "C" << iterator.code_offset() << "O" << pos.ScriptOffset(); 1243 if (pos.isInlined()) { 1244 msg << "I" << pos.InliningId(); 1245 hasInlined = true; 1246 } 1247 } 1248 } 1249 msg << Logger::kNext; 1250 int maxInlinedId = -1; 1251 if (hasInlined) { 1252 PodArray<InliningPosition> inlining_positions = 1253 DeoptimizationData::cast( 1254 Handle<Code>::cast(code)->deoptimization_data()) 1255 .InliningPositions(); 1256 for (int i = 0; i < inlining_positions.length(); i++) { 1257 InliningPosition inlining_pos = inlining_positions.get(i); 1258 msg << "F"; 1259 if (inlining_pos.inlined_function_id != -1) { 1260 msg << inlining_pos.inlined_function_id; 1261 if (inlining_pos.inlined_function_id > maxInlinedId) { 1262 maxInlinedId = inlining_pos.inlined_function_id; 1263 } 1264 } 1265 SourcePosition pos = inlining_pos.position; 1266 msg << "O" << pos.ScriptOffset(); 1267 if (pos.isInlined()) { 1268 msg << "I" << pos.InliningId(); 1269 } 1270 } 1271 } 1272 msg << Logger::kNext; 1273 if (hasInlined) { 1274 DeoptimizationData deopt_data = DeoptimizationData::cast( 1275 Handle<Code>::cast(code)->deoptimization_data()); 1276 msg << std::hex; 1277 for (int i = 0; i <= maxInlinedId; i++) { 1278 msg << "S" 1279 << reinterpret_cast<void*>( 1280 deopt_data.GetInlinedFunction(i).address()); 1281 } 1282 msg << std::dec; 1283 } 1284 msg.WriteToLogFile(); 1285} 1286 1287void Logger::LogCodeDisassemble(Handle<AbstractCode> code) { 1288 if (!FLAG_log_code_disassemble) return; 1289 MSG_BUILDER(); 1290 msg << "code-disassemble" << Logger::kNext 1291 << reinterpret_cast<void*>(code->InstructionStart()) << Logger::kNext 1292 << CodeKindToString(code->kind()) << Logger::kNext; 1293 { 1294 std::ostringstream stream; 1295 if (code->IsCode()) { 1296#ifdef ENABLE_DISASSEMBLER 1297 Code::cast(*code).Disassemble(nullptr, stream, isolate_); 1298#endif 1299 } else { 1300 BytecodeArray::cast(*code).Disassemble(stream); 1301 } 1302 std::string string = stream.str(); 1303 msg.AppendString(string.c_str(), string.length()); 1304 } 1305 msg.WriteToLogFile(); 1306} 1307 1308// Builtins and Bytecode handlers 1309void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code, 1310 const char* name) { 1311 if (!is_listening_to_code_events()) return; 1312 if (!FLAG_log_code) return; 1313 { 1314 MSG_BUILDER(); 1315 AppendCodeCreateHeader(msg, tag, *code, Time()); 1316 msg << name; 1317 msg.WriteToLogFile(); 1318 } 1319 LogCodeDisassemble(code); 1320} 1321 1322void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code, 1323 Handle<Name> name) { 1324 if (!is_listening_to_code_events()) return; 1325 if (!FLAG_log_code) return; 1326 { 1327 MSG_BUILDER(); 1328 AppendCodeCreateHeader(msg, tag, *code, Time()); 1329 msg << *name; 1330 msg.WriteToLogFile(); 1331 } 1332 LogCodeDisassemble(code); 1333} 1334 1335// Scripts 1336void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code, 1337 Handle<SharedFunctionInfo> shared, 1338 Handle<Name> script_name) { 1339 if (!is_listening_to_code_events()) return; 1340 if (!FLAG_log_code) return; 1341 if (*code == 1342 AbstractCode::cast(isolate_->builtins()->code(Builtin::kCompileLazy))) { 1343 return; 1344 } 1345 { 1346 MSG_BUILDER(); 1347 AppendCodeCreateHeader(msg, tag, *code, Time()); 1348 msg << *script_name << kNext << reinterpret_cast<void*>(shared->address()) 1349 << kNext << ComputeMarker(*shared, *code); 1350 msg.WriteToLogFile(); 1351 } 1352 LogSourceCodeInformation(code, shared); 1353 LogCodeDisassemble(code); 1354} 1355 1356void Logger::FeedbackVectorEvent(FeedbackVector vector, AbstractCode code) { 1357 DisallowGarbageCollection no_gc; 1358 if (!FLAG_log_code) return; 1359 MSG_BUILDER(); 1360 msg << "feedback-vector" << kNext << Time(); 1361 msg << kNext << reinterpret_cast<void*>(vector.address()) << kNext 1362 << vector.length(); 1363 msg << kNext << reinterpret_cast<void*>(code.InstructionStart()); 1364 msg << kNext << vector.tiering_state(); 1365 msg << kNext << vector.maybe_has_optimized_code(); 1366 msg << kNext << vector.invocation_count(); 1367 msg << kNext << vector.profiler_ticks() << kNext; 1368 1369#ifdef OBJECT_PRINT 1370 std::ostringstream buffer; 1371 vector.FeedbackVectorPrint(buffer); 1372 std::string contents = buffer.str(); 1373 msg.AppendString(contents.c_str(), contents.length()); 1374#else 1375 msg << "object-printing-disabled"; 1376#endif 1377 msg.WriteToLogFile(); 1378} 1379 1380// Functions 1381// Although, it is possible to extract source and line from 1382// the SharedFunctionInfo object, we left it to caller 1383// to leave logging functions free from heap allocations. 1384void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code, 1385 Handle<SharedFunctionInfo> shared, 1386 Handle<Name> script_name, int line, int column) { 1387 if (!is_listening_to_code_events()) return; 1388 if (!FLAG_log_code) return; 1389 { 1390 MSG_BUILDER(); 1391 AppendCodeCreateHeader(msg, tag, *code, Time()); 1392 msg << shared->DebugNameCStr().get() << " " << *script_name << ":" << line 1393 << ":" << column << kNext << reinterpret_cast<void*>(shared->address()) 1394 << kNext << ComputeMarker(*shared, *code); 1395 1396 msg.WriteToLogFile(); 1397 } 1398 LogSourceCodeInformation(code, shared); 1399 LogCodeDisassemble(code); 1400} 1401 1402#if V8_ENABLE_WEBASSEMBLY 1403void Logger::CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code, 1404 wasm::WasmName name, const char* /*source_url*/, 1405 int /*code_offset*/, int /*script_id*/) { 1406 if (!is_listening_to_code_events()) return; 1407 if (!FLAG_log_code) return; 1408 MSG_BUILDER(); 1409 AppendCodeCreateHeader(msg, tag, CodeKind::WASM_FUNCTION, 1410 code->instructions().begin(), 1411 code->instructions().length(), Time()); 1412 DCHECK(!name.empty()); 1413 msg.AppendString(name); 1414 1415 // We have to add two extra fields that allow the tick processor to group 1416 // events for the same wasm function, even if it gets compiled again. For 1417 // normal JS functions, we use the shared function info. For wasm, the pointer 1418 // to the native module + function index works well enough. 1419 // TODO(herhut) Clean up the tick processor code instead. 1420 void* tag_ptr = 1421 reinterpret_cast<byte*>(code->native_module()) + code->index(); 1422 msg << kNext << tag_ptr << kNext << ComputeMarker(code); 1423 msg.WriteToLogFile(); 1424} 1425#endif // V8_ENABLE_WEBASSEMBLY 1426 1427void Logger::CallbackEventInternal(const char* prefix, Handle<Name> name, 1428 Address entry_point) { 1429 if (!FLAG_log_code) return; 1430 MSG_BUILDER(); 1431 msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << kNext 1432 << kLogEventsNames[CodeEventListener::CALLBACK_TAG] << kNext << -2 1433 << kNext << Time() << kNext << reinterpret_cast<void*>(entry_point) 1434 << kNext << 1 << kNext << prefix << *name; 1435 msg.WriteToLogFile(); 1436} 1437 1438void Logger::CallbackEvent(Handle<Name> name, Address entry_point) { 1439 CallbackEventInternal("", name, entry_point); 1440} 1441 1442void Logger::GetterCallbackEvent(Handle<Name> name, Address entry_point) { 1443 CallbackEventInternal("get ", name, entry_point); 1444} 1445 1446void Logger::SetterCallbackEvent(Handle<Name> name, Address entry_point) { 1447 CallbackEventInternal("set ", name, entry_point); 1448} 1449 1450void Logger::RegExpCodeCreateEvent(Handle<AbstractCode> code, 1451 Handle<String> source) { 1452 if (!is_listening_to_code_events()) return; 1453 if (!FLAG_log_code) return; 1454 MSG_BUILDER(); 1455 AppendCodeCreateHeader(msg, CodeEventListener::REG_EXP_TAG, *code, Time()); 1456 msg << *source; 1457 msg.WriteToLogFile(); 1458} 1459 1460void Logger::CodeMoveEvent(AbstractCode from, AbstractCode to) { 1461 if (!is_listening_to_code_events()) return; 1462 MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from.InstructionStart(), 1463 to.InstructionStart()); 1464} 1465 1466void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) { 1467 if (!is_listening_to_code_events()) return; 1468 MoveEventInternal(CodeEventListener::SHARED_FUNC_MOVE_EVENT, from, to); 1469} 1470 1471void Logger::CodeMovingGCEvent() { 1472 if (!is_listening_to_code_events()) return; 1473 if (!FLAG_ll_prof) return; 1474 base::OS::SignalCodeMovingGC(); 1475} 1476 1477void Logger::CodeDisableOptEvent(Handle<AbstractCode> code, 1478 Handle<SharedFunctionInfo> shared) { 1479 if (!is_listening_to_code_events()) return; 1480 if (!FLAG_log_code) return; 1481 MSG_BUILDER(); 1482 msg << kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT] << kNext 1483 << shared->DebugNameCStr().get() << kNext 1484 << GetBailoutReason(shared->disabled_optimization_reason()); 1485 msg.WriteToLogFile(); 1486} 1487 1488void Logger::ProcessDeoptEvent(Handle<Code> code, SourcePosition position, 1489 const char* kind, const char* reason) { 1490 MSG_BUILDER(); 1491 msg << "code-deopt" << kNext << Time() << kNext << code->CodeSize() << kNext 1492 << reinterpret_cast<void*>(code->InstructionStart()); 1493 1494 std::ostringstream deopt_location; 1495 int inlining_id = -1; 1496 int script_offset = -1; 1497 if (position.IsKnown()) { 1498 position.Print(deopt_location, *code); 1499 inlining_id = position.InliningId(); 1500 script_offset = position.ScriptOffset(); 1501 } else { 1502 deopt_location << "<unknown>"; 1503 } 1504 msg << kNext << inlining_id << kNext << script_offset << kNext; 1505 msg << kind << kNext; 1506 msg << deopt_location.str().c_str() << kNext << reason; 1507 msg.WriteToLogFile(); 1508} 1509 1510void Logger::CodeDeoptEvent(Handle<Code> code, DeoptimizeKind kind, Address pc, 1511 int fp_to_sp_delta) { 1512 if (!is_logging() || !FLAG_log_deopt) return; 1513 Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(*code, pc); 1514 ProcessDeoptEvent(code, info.position, Deoptimizer::MessageFor(kind), 1515 DeoptimizeReasonToString(info.deopt_reason)); 1516} 1517 1518void Logger::CodeDependencyChangeEvent(Handle<Code> code, 1519 Handle<SharedFunctionInfo> sfi, 1520 const char* reason) { 1521 if (!is_logging() || !FLAG_log_deopt) return; 1522 SourcePosition position(sfi->StartPosition(), -1); 1523 ProcessDeoptEvent(code, position, "dependency-change", reason); 1524} 1525 1526namespace { 1527 1528void CodeLinePosEvent(JitLogger& jit_logger, Address code_start, 1529 SourcePositionTableIterator& iter, 1530 JitCodeEvent::CodeType code_type) { 1531 void* jit_handler_data = jit_logger.StartCodePosInfoEvent(code_type); 1532 for (; !iter.done(); iter.Advance()) { 1533 if (iter.is_statement()) { 1534 jit_logger.AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(), 1535 iter.source_position().ScriptOffset(), 1536 JitCodeEvent::STATEMENT_POSITION, 1537 code_type); 1538 } 1539 jit_logger.AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(), 1540 iter.source_position().ScriptOffset(), 1541 JitCodeEvent::POSITION, code_type); 1542 } 1543 jit_logger.EndCodePosInfoEvent(code_start, jit_handler_data, code_type); 1544} 1545 1546} // namespace 1547 1548void Logger::CodeLinePosInfoRecordEvent(Address code_start, 1549 ByteArray source_position_table, 1550 JitCodeEvent::CodeType code_type) { 1551 if (!jit_logger_) return; 1552 SourcePositionTableIterator iter(source_position_table); 1553 CodeLinePosEvent(*jit_logger_, code_start, iter, code_type); 1554} 1555 1556#if V8_ENABLE_WEBASSEMBLY 1557void Logger::WasmCodeLinePosInfoRecordEvent( 1558 Address code_start, base::Vector<const byte> source_position_table) { 1559 if (!jit_logger_) return; 1560 SourcePositionTableIterator iter(source_position_table); 1561 CodeLinePosEvent(*jit_logger_, code_start, iter, JitCodeEvent::WASM_CODE); 1562} 1563#endif // V8_ENABLE_WEBASSEMBLY 1564 1565void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) { 1566 if (code_name == nullptr) return; // Not a code object. 1567 if (!is_listening_to_code_events()) return; 1568 MSG_BUILDER(); 1569 msg << kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT] << kNext 1570 << pos << kNext << code_name; 1571 msg.WriteToLogFile(); 1572} 1573 1574void Logger::MoveEventInternal(LogEventsAndTags event, Address from, 1575 Address to) { 1576 if (!FLAG_log_code) return; 1577 MSG_BUILDER(); 1578 msg << kLogEventsNames[event] << kNext << reinterpret_cast<void*>(from) 1579 << kNext << reinterpret_cast<void*>(to); 1580 msg.WriteToLogFile(); 1581} 1582 1583namespace { 1584void AppendFunctionMessage(Log::MessageBuilder& msg, const char* reason, 1585 int script_id, double time_delta, int start_position, 1586 int end_position, uint64_t time) { 1587 msg << "function" << Logger::kNext << reason << Logger::kNext << script_id 1588 << Logger::kNext << start_position << Logger::kNext << end_position 1589 << Logger::kNext; 1590 if (V8_UNLIKELY(FLAG_predictable)) { 1591 msg << 0.1; 1592 } else { 1593 msg << time_delta; 1594 } 1595 msg << Logger::kNext << time << Logger::kNext; 1596} 1597} // namespace 1598 1599void Logger::FunctionEvent(const char* reason, int script_id, double time_delta, 1600 int start_position, int end_position, 1601 String function_name) { 1602 if (!FLAG_log_function_events) return; 1603 MSG_BUILDER(); 1604 AppendFunctionMessage(msg, reason, script_id, time_delta, start_position, 1605 end_position, Time()); 1606 if (!function_name.is_null()) msg << function_name; 1607 msg.WriteToLogFile(); 1608} 1609 1610void Logger::FunctionEvent(const char* reason, int script_id, double time_delta, 1611 int start_position, int end_position, 1612 const char* function_name, 1613 size_t function_name_length, bool is_one_byte) { 1614 if (!FLAG_log_function_events) return; 1615 MSG_BUILDER(); 1616 AppendFunctionMessage(msg, reason, script_id, time_delta, start_position, 1617 end_position, Time()); 1618 if (function_name_length > 0) { 1619 msg.AppendString(function_name, function_name_length, is_one_byte); 1620 } 1621 msg.WriteToLogFile(); 1622} 1623 1624void Logger::CompilationCacheEvent(const char* action, const char* cache_type, 1625 SharedFunctionInfo sfi) { 1626 if (!FLAG_log_function_events) return; 1627 MSG_BUILDER(); 1628 int script_id = -1; 1629 if (sfi.script().IsScript()) { 1630 script_id = Script::cast(sfi.script()).id(); 1631 } 1632 msg << "compilation-cache" << Logger::kNext << action << Logger::kNext 1633 << cache_type << Logger::kNext << script_id << Logger::kNext 1634 << sfi.StartPosition() << Logger::kNext << sfi.EndPosition() 1635 << Logger::kNext << Time(); 1636 msg.WriteToLogFile(); 1637} 1638 1639void Logger::ScriptEvent(ScriptEventType type, int script_id) { 1640 if (!FLAG_log_function_events) return; 1641 MSG_BUILDER(); 1642 msg << "script" << Logger::kNext; 1643 switch (type) { 1644 case ScriptEventType::kReserveId: 1645 msg << "reserve-id"; 1646 break; 1647 case ScriptEventType::kCreate: 1648 msg << "create"; 1649 break; 1650 case ScriptEventType::kDeserialize: 1651 msg << "deserialize"; 1652 break; 1653 case ScriptEventType::kBackgroundCompile: 1654 msg << "background-compile"; 1655 break; 1656 case ScriptEventType::kStreamingCompile: 1657 msg << "streaming-compile"; 1658 break; 1659 } 1660 msg << Logger::kNext << script_id << Logger::kNext << Time(); 1661 msg.WriteToLogFile(); 1662} 1663 1664void Logger::ScriptDetails(Script script) { 1665 if (!FLAG_log_function_events) return; 1666 { 1667 MSG_BUILDER(); 1668 msg << "script-details" << Logger::kNext << script.id() << Logger::kNext; 1669 if (script.name().IsString()) { 1670 msg << String::cast(script.name()); 1671 } 1672 msg << Logger::kNext << script.line_offset() << Logger::kNext 1673 << script.column_offset() << Logger::kNext; 1674 if (script.source_mapping_url().IsString()) { 1675 msg << String::cast(script.source_mapping_url()); 1676 } 1677 msg.WriteToLogFile(); 1678 } 1679 EnsureLogScriptSource(script); 1680} 1681 1682bool Logger::EnsureLogScriptSource(Script script) { 1683 // Make sure the script is written to the log file. 1684 int script_id = script.id(); 1685 if (logged_source_code_.find(script_id) != logged_source_code_.end()) { 1686 return true; 1687 } 1688 // This script has not been logged yet. 1689 logged_source_code_.insert(script_id); 1690 Object source_object = script.source(); 1691 if (!source_object.IsString()) return false; 1692 1693 std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder(); 1694 if (!msg_ptr) return false; 1695 Log::MessageBuilder& msg = *msg_ptr.get(); 1696 1697 String source_code = String::cast(source_object); 1698 msg << "script-source" << kNext << script_id << kNext; 1699 1700 // Log the script name. 1701 if (script.name().IsString()) { 1702 msg << String::cast(script.name()) << kNext; 1703 } else { 1704 msg << "<unknown>" << kNext; 1705 } 1706 1707 // Log the source code. 1708 msg << source_code; 1709 msg.WriteToLogFile(); 1710 return true; 1711} 1712 1713void Logger::RuntimeCallTimerEvent() { 1714#ifdef V8_RUNTIME_CALL_STATS 1715 RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats(); 1716 RuntimeCallCounter* counter = stats->current_counter(); 1717 if (counter == nullptr) return; 1718 MSG_BUILDER(); 1719 msg << "active-runtime-timer" << kNext << counter->name(); 1720 msg.WriteToLogFile(); 1721#endif // V8_RUNTIME_CALL_STATS 1722} 1723 1724void Logger::TickEvent(TickSample* sample, bool overflow) { 1725 if (!FLAG_prof_cpp) return; 1726 if (V8_UNLIKELY(TracingFlags::runtime_stats.load(std::memory_order_relaxed) == 1727 v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE)) { 1728 RuntimeCallTimerEvent(); 1729 } 1730 MSG_BUILDER(); 1731 msg << kLogEventsNames[CodeEventListener::TICK_EVENT] << kNext 1732 << reinterpret_cast<void*>(sample->pc) << kNext << Time(); 1733 if (sample->has_external_callback) { 1734 msg << kNext << 1 << kNext 1735 << reinterpret_cast<void*>(sample->external_callback_entry); 1736 } else { 1737 msg << kNext << 0 << kNext << reinterpret_cast<void*>(sample->tos); 1738 } 1739 msg << kNext << static_cast<int>(sample->state); 1740 if (overflow) msg << kNext << "overflow"; 1741 for (unsigned i = 0; i < sample->frames_count; ++i) { 1742 msg << kNext << reinterpret_cast<void*>(sample->stack[i]); 1743 } 1744 msg.WriteToLogFile(); 1745} 1746 1747void Logger::ICEvent(const char* type, bool keyed, Handle<Map> map, 1748 Handle<Object> key, char old_state, char new_state, 1749 const char* modifier, const char* slow_stub_reason) { 1750 if (!FLAG_log_ic) return; 1751 int line; 1752 int column; 1753 // GetAbstractPC must come before MSG_BUILDER(), as it can GC, which might 1754 // attempt to get the log lock again and result in a deadlock. 1755 Address pc = isolate_->GetAbstractPC(&line, &column); 1756 MSG_BUILDER(); 1757 if (keyed) msg << "Keyed"; 1758 msg << type << kNext << reinterpret_cast<void*>(pc) << kNext << Time() 1759 << kNext << line << kNext << column << kNext << old_state << kNext 1760 << new_state << kNext 1761 << AsHex::Address(map.is_null() ? kNullAddress : map->ptr()) << kNext; 1762 if (key->IsSmi()) { 1763 msg << Smi::ToInt(*key); 1764 } else if (key->IsNumber()) { 1765 msg << key->Number(); 1766 } else if (key->IsName()) { 1767 msg << Name::cast(*key); 1768 } 1769 msg << kNext << modifier << kNext; 1770 if (slow_stub_reason != nullptr) { 1771 msg << slow_stub_reason; 1772 } 1773 msg.WriteToLogFile(); 1774} 1775 1776void Logger::MapEvent(const char* type, Handle<Map> from, Handle<Map> to, 1777 const char* reason, Handle<HeapObject> name_or_sfi) { 1778 if (!FLAG_log_maps) return; 1779 if (!to.is_null()) MapDetails(*to); 1780 int line = -1; 1781 int column = -1; 1782 Address pc = 0; 1783 1784 if (!isolate_->bootstrapper()->IsActive()) { 1785 pc = isolate_->GetAbstractPC(&line, &column); 1786 } 1787 MSG_BUILDER(); 1788 msg << "map" << kNext << type << kNext << Time() << kNext 1789 << AsHex::Address(from.is_null() ? kNullAddress : from->ptr()) << kNext 1790 << AsHex::Address(to.is_null() ? kNullAddress : to->ptr()) << kNext 1791 << AsHex::Address(pc) << kNext << line << kNext << column << kNext 1792 << reason << kNext; 1793 1794 if (!name_or_sfi.is_null()) { 1795 if (name_or_sfi->IsName()) { 1796 msg << Name::cast(*name_or_sfi); 1797 } else if (name_or_sfi->IsSharedFunctionInfo()) { 1798 SharedFunctionInfo sfi = SharedFunctionInfo::cast(*name_or_sfi); 1799 msg << sfi.DebugNameCStr().get(); 1800#if V8_SFI_HAS_UNIQUE_ID 1801 msg << " " << sfi.unique_id(); 1802#endif // V8_SFI_HAS_UNIQUE_ID 1803 } 1804 } 1805 msg.WriteToLogFile(); 1806} 1807 1808void Logger::MapCreate(Map map) { 1809 if (!FLAG_log_maps) return; 1810 DisallowGarbageCollection no_gc; 1811 MSG_BUILDER(); 1812 msg << "map-create" << kNext << Time() << kNext << AsHex::Address(map.ptr()); 1813 msg.WriteToLogFile(); 1814} 1815 1816void Logger::MapDetails(Map map) { 1817 if (!FLAG_log_maps) return; 1818 DisallowGarbageCollection no_gc; 1819 MSG_BUILDER(); 1820 msg << "map-details" << kNext << Time() << kNext << AsHex::Address(map.ptr()) 1821 << kNext; 1822 if (FLAG_log_maps_details) { 1823 std::ostringstream buffer; 1824 map.PrintMapDetails(buffer); 1825 msg << buffer.str().c_str(); 1826 } 1827 msg.WriteToLogFile(); 1828} 1829 1830static std::vector<std::pair<Handle<SharedFunctionInfo>, Handle<AbstractCode>>> 1831EnumerateCompiledFunctions(Heap* heap) { 1832 HeapObjectIterator iterator(heap); 1833 DisallowGarbageCollection no_gc; 1834 std::vector<std::pair<Handle<SharedFunctionInfo>, Handle<AbstractCode>>> 1835 compiled_funcs; 1836 Isolate* isolate = heap->isolate(); 1837 1838 // Iterate the heap to find JSFunctions and record their optimized code. 1839 for (HeapObject obj = iterator.Next(); !obj.is_null(); 1840 obj = iterator.Next()) { 1841 if (obj.IsSharedFunctionInfo()) { 1842 SharedFunctionInfo sfi = SharedFunctionInfo::cast(obj); 1843 if (sfi.is_compiled() && !sfi.HasBytecodeArray()) { 1844 compiled_funcs.emplace_back( 1845 handle(sfi, isolate), 1846 handle(AbstractCode::cast(sfi.abstract_code(isolate)), isolate)); 1847 } 1848 } else if (obj.IsJSFunction()) { 1849 // Given that we no longer iterate over all optimized JSFunctions, we need 1850 // to take care of this here. 1851 JSFunction function = JSFunction::cast(obj); 1852 // TODO(jarin) This leaves out deoptimized code that might still be on the 1853 // stack. Also note that we will not log optimized code objects that are 1854 // only on a type feedback vector. We should make this mroe precise. 1855 if (function.HasAttachedOptimizedCode() && 1856 Script::cast(function.shared().script()).HasValidSource()) { 1857 compiled_funcs.emplace_back( 1858 handle(function.shared(), isolate), 1859 handle(AbstractCode::cast(FromCodeT(function.code())), isolate)); 1860 } 1861 } 1862 } 1863 1864 Script::Iterator script_iterator(heap->isolate()); 1865 for (Script script = script_iterator.Next(); !script.is_null(); 1866 script = script_iterator.Next()) { 1867 if (!script.HasValidSource()) continue; 1868 1869 SharedFunctionInfo::ScriptIterator sfi_iterator(heap->isolate(), script); 1870 for (SharedFunctionInfo sfi = sfi_iterator.Next(); !sfi.is_null(); 1871 sfi = sfi_iterator.Next()) { 1872 if (sfi.is_compiled()) { 1873 compiled_funcs.emplace_back( 1874 handle(sfi, isolate), 1875 handle(AbstractCode::cast(sfi.abstract_code(isolate)), isolate)); 1876 } 1877 } 1878 } 1879 1880 return compiled_funcs; 1881} 1882 1883void Logger::LogCodeObjects() { existing_code_logger_.LogCodeObjects(); } 1884 1885void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared, 1886 Handle<AbstractCode> code) { 1887 existing_code_logger_.LogExistingFunction(shared, code); 1888} 1889 1890void Logger::LogCompiledFunctions() { 1891 existing_code_logger_.LogCompiledFunctions(); 1892} 1893 1894void Logger::LogBuiltins() { existing_code_logger_.LogBuiltins(); } 1895 1896void Logger::LogAccessorCallbacks() { 1897 Heap* heap = isolate_->heap(); 1898 HeapObjectIterator iterator(heap); 1899 DisallowGarbageCollection no_gc; 1900 for (HeapObject obj = iterator.Next(); !obj.is_null(); 1901 obj = iterator.Next()) { 1902 if (!obj.IsAccessorInfo()) continue; 1903 AccessorInfo ai = AccessorInfo::cast(obj); 1904 if (!ai.name().IsName()) continue; 1905 Address getter_entry = v8::ToCData<Address>(ai.getter()); 1906 HandleScope scope(isolate_); 1907 Handle<Name> name(Name::cast(ai.name()), isolate_); 1908 if (getter_entry != 0) { 1909#if USES_FUNCTION_DESCRIPTORS 1910 getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(getter_entry); 1911#endif 1912 PROFILE(isolate_, GetterCallbackEvent(name, getter_entry)); 1913 } 1914 Address setter_entry = v8::ToCData<Address>(ai.setter()); 1915 if (setter_entry != 0) { 1916#if USES_FUNCTION_DESCRIPTORS 1917 setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(setter_entry); 1918#endif 1919 PROFILE(isolate_, SetterCallbackEvent(name, setter_entry)); 1920 } 1921 } 1922} 1923 1924void Logger::LogAllMaps() { 1925 Heap* heap = isolate_->heap(); 1926 CombinedHeapObjectIterator iterator(heap); 1927 for (HeapObject obj = iterator.Next(); !obj.is_null(); 1928 obj = iterator.Next()) { 1929 if (!obj.IsMap()) continue; 1930 Map map = Map::cast(obj); 1931 MapCreate(map); 1932 MapDetails(map); 1933 } 1934} 1935 1936static void AddIsolateIdIfNeeded(std::ostream& os, Isolate* isolate) { 1937 if (!FLAG_logfile_per_isolate) return; 1938 os << "isolate-" << isolate << "-" << base::OS::GetCurrentProcessId() << "-"; 1939} 1940 1941static void PrepareLogFileName(std::ostream& os, Isolate* isolate, 1942 const char* file_name) { 1943 int dir_separator_count = 0; 1944 for (const char* p = file_name; *p; p++) { 1945 if (base::OS::isDirectorySeparator(*p)) dir_separator_count++; 1946 } 1947 1948 for (const char* p = file_name; *p; p++) { 1949 if (dir_separator_count == 0) { 1950 AddIsolateIdIfNeeded(os, isolate); 1951 dir_separator_count--; 1952 } 1953 if (*p == '%') { 1954 p++; 1955 switch (*p) { 1956 case '\0': 1957 // If there's a % at the end of the string we back up 1958 // one character so we can escape the loop properly. 1959 p--; 1960 break; 1961 case 'p': 1962 os << base::OS::GetCurrentProcessId(); 1963 break; 1964 case 't': 1965 // %t expands to the current time in milliseconds. 1966 os << static_cast<int64_t>( 1967 V8::GetCurrentPlatform()->CurrentClockTimeMillis()); 1968 break; 1969 case '%': 1970 // %% expands (contracts really) to %. 1971 os << '%'; 1972 break; 1973 default: 1974 // All other %'s expand to themselves. 1975 os << '%' << *p; 1976 break; 1977 } 1978 } else { 1979 if (base::OS::isDirectorySeparator(*p)) dir_separator_count--; 1980 os << *p; 1981 } 1982 } 1983} 1984 1985bool Logger::SetUp(Isolate* isolate) { 1986 // Tests and EnsureInitialize() can call this twice in a row. It's harmless. 1987 if (is_initialized_) return true; 1988 is_initialized_ = true; 1989 1990 std::ostringstream log_file_name; 1991 PrepareLogFileName(log_file_name, isolate, FLAG_logfile); 1992 log_ = std::make_unique<Log>(this, log_file_name.str()); 1993 1994#if V8_OS_LINUX 1995 if (FLAG_perf_basic_prof) { 1996 perf_basic_logger_ = std::make_unique<PerfBasicLogger>(isolate); 1997 AddCodeEventListener(perf_basic_logger_.get()); 1998 } 1999 2000 if (FLAG_perf_prof) { 2001 perf_jit_logger_ = std::make_unique<PerfJitLogger>(isolate); 2002 AddCodeEventListener(perf_jit_logger_.get()); 2003 } 2004#else 2005 static_assert( 2006 !FLAG_perf_prof, 2007 "--perf-prof should be statically disabled on non-Linux platforms"); 2008 static_assert( 2009 !FLAG_perf_basic_prof, 2010 "--perf-basic-prof should be statically disabled on non-Linux platforms"); 2011#endif 2012 2013#ifdef ENABLE_GDB_JIT_INTERFACE 2014 if (i::FLAG_gdbjit) { 2015 auto code_event_handler = i::GDBJITInterface::EventHandler; 2016 DCHECK_NOT_NULL(code_event_handler); 2017 gdb_jit_logger_ = std::make_unique<JitLogger>(isolate, code_event_handler); 2018 AddCodeEventListener(gdb_jit_logger_.get()); 2019 CHECK(isolate->code_event_dispatcher()->IsListeningToCodeEvents()); 2020 } 2021#endif // ENABLE_GDB_JIT_INTERFACE 2022 2023#if defined(V8_OS_WIN) && defined(V8_ENABLE_SYSTEM_INSTRUMENTATION) 2024 if (i::FLAG_enable_system_instrumentation) { 2025 auto code_event_handler = i::ETWJITInterface::EventHandler; 2026 DCHECK_NOT_NULL(code_event_handler); 2027 etw_jit_logger_ = std::make_unique<JitLogger>(isolate, code_event_handler); 2028 AddCodeEventListener(etw_jit_logger_.get()); 2029 CHECK(isolate->code_event_dispatcher()->IsListeningToCodeEvents()); 2030 } 2031#endif // defined(V8_OS_WIN) 2032 2033 if (FLAG_ll_prof) { 2034 ll_logger_ = 2035 std::make_unique<LowLevelLogger>(isolate, log_file_name.str().c_str()); 2036 AddCodeEventListener(ll_logger_.get()); 2037 } 2038 ticker_ = std::make_unique<Ticker>(isolate, FLAG_prof_sampling_interval); 2039 if (FLAG_log) UpdateIsLogging(true); 2040 timer_.Start(); 2041 if (FLAG_prof_cpp) { 2042 CHECK(FLAG_log); 2043 CHECK(is_logging()); 2044 profiler_ = std::make_unique<Profiler>(isolate); 2045 profiler_->Engage(); 2046 } 2047 if (is_logging_) AddCodeEventListener(this); 2048 return true; 2049} 2050 2051void Logger::LateSetup(Isolate* isolate) { 2052 if (!isolate->code_event_dispatcher()->IsListeningToCodeEvents()) return; 2053 Builtins::EmitCodeCreateEvents(isolate); 2054#if V8_ENABLE_WEBASSEMBLY 2055 wasm::GetWasmEngine()->EnableCodeLogging(isolate); 2056#endif 2057} 2058 2059void Logger::SetCodeEventHandler(uint32_t options, 2060 JitCodeEventHandler event_handler) { 2061 if (jit_logger_) { 2062 RemoveCodeEventListener(jit_logger_.get()); 2063 jit_logger_.reset(); 2064 } 2065 2066 if (event_handler) { 2067#if V8_ENABLE_WEBASSEMBLY 2068 wasm::GetWasmEngine()->EnableCodeLogging(isolate_); 2069#endif // V8_ENABLE_WEBASSEMBLY 2070 jit_logger_ = std::make_unique<JitLogger>(isolate_, event_handler); 2071 AddCodeEventListener(jit_logger_.get()); 2072 if (options & kJitCodeEventEnumExisting) { 2073 HandleScope scope(isolate_); 2074 LogCodeObjects(); 2075 LogBuiltins(); 2076 LogCompiledFunctions(); 2077 } 2078 } 2079} 2080 2081sampler::Sampler* Logger::sampler() { return ticker_.get(); } 2082std::string Logger::file_name() const { return log_.get()->file_name(); } 2083 2084void Logger::StopProfilerThread() { 2085 if (profiler_ != nullptr) { 2086 profiler_->Disengage(); 2087 profiler_.reset(); 2088 } 2089} 2090 2091FILE* Logger::TearDownAndGetLogFile() { 2092 if (!is_initialized_) return nullptr; 2093 is_initialized_ = false; 2094 UpdateIsLogging(false); 2095 2096 // Stop the profiler thread before closing the file. 2097 StopProfilerThread(); 2098 2099 ticker_.reset(); 2100 timer_.Stop(); 2101 2102#if V8_OS_LINUX 2103 if (perf_basic_logger_) { 2104 RemoveCodeEventListener(perf_basic_logger_.get()); 2105 perf_basic_logger_.reset(); 2106 } 2107 2108 if (perf_jit_logger_) { 2109 RemoveCodeEventListener(perf_jit_logger_.get()); 2110 perf_jit_logger_.reset(); 2111 } 2112#endif 2113 2114 if (ll_logger_) { 2115 RemoveCodeEventListener(ll_logger_.get()); 2116 ll_logger_.reset(); 2117 } 2118 2119 if (jit_logger_) { 2120 RemoveCodeEventListener(jit_logger_.get()); 2121 jit_logger_.reset(); 2122 } 2123 2124 return log_->Close(); 2125} 2126 2127void Logger::UpdateIsLogging(bool value) { 2128 base::MutexGuard guard(log_->mutex()); 2129 if (value) { 2130 isolate_->CollectSourcePositionsForAllBytecodeArrays(); 2131 } 2132 // Relaxed atomic to avoid locking the mutex for the most common case: when 2133 // logging is disabled. 2134 is_logging_.store(value, std::memory_order_relaxed); 2135} 2136 2137void ExistingCodeLogger::LogCodeObject(Object object) { 2138 HandleScope scope(isolate_); 2139 Handle<AbstractCode> abstract_code(AbstractCode::cast(object), isolate_); 2140 CodeEventListener::LogEventsAndTags tag = CodeEventListener::STUB_TAG; 2141 const char* description = "Unknown code from before profiling"; 2142 switch (abstract_code->kind()) { 2143 case CodeKind::INTERPRETED_FUNCTION: 2144 case CodeKind::TURBOFAN: 2145 case CodeKind::BASELINE: 2146 case CodeKind::MAGLEV: 2147 return; // We log this later using LogCompiledFunctions. 2148 case CodeKind::FOR_TESTING: 2149 description = "STUB code"; 2150 tag = CodeEventListener::STUB_TAG; 2151 break; 2152 case CodeKind::REGEXP: 2153 description = "Regular expression code"; 2154 tag = CodeEventListener::REG_EXP_TAG; 2155 break; 2156 case CodeKind::BYTECODE_HANDLER: 2157 description = 2158 isolate_->builtins()->name(abstract_code->GetCode().builtin_id()); 2159 tag = CodeEventListener::BYTECODE_HANDLER_TAG; 2160 break; 2161 case CodeKind::BUILTIN: 2162 if (Code::cast(object).is_interpreter_trampoline_builtin() && 2163 ToCodeT(Code::cast(object)) != 2164 *BUILTIN_CODE(isolate_, InterpreterEntryTrampoline)) { 2165 return; 2166 } 2167 description = 2168 isolate_->builtins()->name(abstract_code->GetCode().builtin_id()); 2169 tag = CodeEventListener::BUILTIN_TAG; 2170 break; 2171 case CodeKind::WASM_FUNCTION: 2172 description = "A Wasm function"; 2173 tag = CodeEventListener::FUNCTION_TAG; 2174 break; 2175 case CodeKind::JS_TO_WASM_FUNCTION: 2176 description = "A JavaScript to Wasm adapter"; 2177 tag = CodeEventListener::STUB_TAG; 2178 break; 2179 case CodeKind::JS_TO_JS_FUNCTION: 2180 description = "A WebAssembly.Function adapter"; 2181 tag = CodeEventListener::STUB_TAG; 2182 break; 2183 case CodeKind::WASM_TO_CAPI_FUNCTION: 2184 description = "A Wasm to C-API adapter"; 2185 tag = CodeEventListener::STUB_TAG; 2186 break; 2187 case CodeKind::WASM_TO_JS_FUNCTION: 2188 description = "A Wasm to JavaScript adapter"; 2189 tag = CodeEventListener::STUB_TAG; 2190 break; 2191 case CodeKind::C_WASM_ENTRY: 2192 description = "A C to Wasm entry stub"; 2193 tag = CodeEventListener::STUB_TAG; 2194 break; 2195 } 2196 CALL_CODE_EVENT_HANDLER(CodeCreateEvent(tag, abstract_code, description)) 2197} 2198 2199void ExistingCodeLogger::LogCodeObjects() { 2200 Heap* heap = isolate_->heap(); 2201 HeapObjectIterator iterator(heap); 2202 DisallowGarbageCollection no_gc; 2203 for (HeapObject obj = iterator.Next(); !obj.is_null(); 2204 obj = iterator.Next()) { 2205 if (obj.IsCode()) LogCodeObject(obj); 2206 if (obj.IsBytecodeArray()) LogCodeObject(obj); 2207 } 2208} 2209 2210void ExistingCodeLogger::LogBuiltins() { 2211 Builtins* builtins = isolate_->builtins(); 2212 DCHECK(builtins->is_initialized()); 2213 for (Builtin builtin = Builtins::kFirst; builtin <= Builtins::kLast; 2214 ++builtin) { 2215 Code code = FromCodeT(builtins->code(builtin)); 2216 LogCodeObject(code); 2217 } 2218} 2219 2220void ExistingCodeLogger::LogCompiledFunctions() { 2221 Heap* heap = isolate_->heap(); 2222 HandleScope scope(isolate_); 2223 std::vector<std::pair<Handle<SharedFunctionInfo>, Handle<AbstractCode>>> 2224 compiled_funcs = EnumerateCompiledFunctions(heap); 2225 2226 // During iteration, there can be heap allocation due to 2227 // GetScriptLineNumber call. 2228 for (auto& pair : compiled_funcs) { 2229 Handle<SharedFunctionInfo> shared = pair.first; 2230 SharedFunctionInfo::EnsureSourcePositionsAvailable(isolate_, shared); 2231 if (shared->HasInterpreterData()) { 2232 LogExistingFunction( 2233 shared, 2234 Handle<AbstractCode>( 2235 AbstractCode::cast(FromCodeT(shared->InterpreterTrampoline())), 2236 isolate_)); 2237 } 2238 if (shared->HasBaselineCode()) { 2239 LogExistingFunction(shared, Handle<AbstractCode>( 2240 AbstractCode::cast(FromCodeT( 2241 shared->baseline_code(kAcquireLoad))), 2242 isolate_)); 2243 } 2244 if (pair.second.is_identical_to(BUILTIN_CODE(isolate_, CompileLazy))) 2245 continue; 2246 LogExistingFunction(pair.first, pair.second); 2247 } 2248 2249#if V8_ENABLE_WEBASSEMBLY 2250 HeapObjectIterator iterator(heap); 2251 DisallowGarbageCollection no_gc; 2252 2253 for (HeapObject obj = iterator.Next(); !obj.is_null(); 2254 obj = iterator.Next()) { 2255 if (!obj.IsWasmModuleObject()) continue; 2256 auto module_object = WasmModuleObject::cast(obj); 2257 module_object.native_module()->LogWasmCodes(isolate_, 2258 module_object.script()); 2259 } 2260#endif // V8_ENABLE_WEBASSEMBLY 2261} 2262 2263void ExistingCodeLogger::LogExistingFunction( 2264 Handle<SharedFunctionInfo> shared, Handle<AbstractCode> code, 2265 CodeEventListener::LogEventsAndTags tag) { 2266 if (shared->script().IsScript()) { 2267 Handle<Script> script(Script::cast(shared->script()), isolate_); 2268 int line_num = Script::GetLineNumber(script, shared->StartPosition()) + 1; 2269 int column_num = 2270 Script::GetColumnNumber(script, shared->StartPosition()) + 1; 2271 if (script->name().IsString()) { 2272 Handle<String> script_name(String::cast(script->name()), isolate_); 2273 if (!shared->is_toplevel()) { 2274 CALL_CODE_EVENT_HANDLER( 2275 CodeCreateEvent(Logger::ToNativeByScript(tag, *script), code, 2276 shared, script_name, line_num, column_num)) 2277 } else { 2278 // Can't distinguish eval and script here, so always use Script. 2279 CALL_CODE_EVENT_HANDLER(CodeCreateEvent( 2280 Logger::ToNativeByScript(CodeEventListener::SCRIPT_TAG, *script), 2281 code, shared, script_name)) 2282 } 2283 } else { 2284 CALL_CODE_EVENT_HANDLER(CodeCreateEvent( 2285 Logger::ToNativeByScript(tag, *script), code, shared, 2286 ReadOnlyRoots(isolate_).empty_string_handle(), line_num, column_num)) 2287 } 2288 } else if (shared->IsApiFunction()) { 2289 // API function. 2290 Handle<FunctionTemplateInfo> fun_data = 2291 handle(shared->get_api_func_data(), isolate_); 2292 Object raw_call_data = fun_data->call_code(kAcquireLoad); 2293 if (!raw_call_data.IsUndefined(isolate_)) { 2294 CallHandlerInfo call_data = CallHandlerInfo::cast(raw_call_data); 2295 Object callback_obj = call_data.callback(); 2296 Address entry_point = v8::ToCData<Address>(callback_obj); 2297#if USES_FUNCTION_DESCRIPTORS 2298 entry_point = *FUNCTION_ENTRYPOINT_ADDRESS(entry_point); 2299#endif 2300 Handle<String> fun_name = SharedFunctionInfo::DebugName(shared); 2301 CALL_CODE_EVENT_HANDLER(CallbackEvent(fun_name, entry_point)) 2302 2303 // Fast API function. 2304 int c_functions_count = fun_data->GetCFunctionsCount(); 2305 for (int i = 0; i < c_functions_count; i++) { 2306 CALL_CODE_EVENT_HANDLER( 2307 CallbackEvent(fun_name, fun_data->GetCFunction(i))) 2308 } 2309 } 2310 } 2311} 2312 2313#undef CALL_CODE_EVENT_HANDLER 2314#undef MSG_BUILDER 2315 2316} // namespace internal 2317} // namespace v8 2318