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