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 <sstream> 9 10 #include "src/bailout-reason.h" 11 #include "src/base/platform/platform.h" 12 #include "src/bootstrapper.h" 13 #include "src/code-stubs.h" 14 #include "src/deoptimizer.h" 15 #include "src/global-handles.h" 16 #include "src/log-inl.h" 17 #include "src/log-utils.h" 18 #include "src/macro-assembler.h" 19 #include "src/profiler/cpu-profiler.h" 20 #include "src/runtime-profiler.h" 21 #include "src/string-stream.h" 22 #include "src/vm-state-inl.h" 23 24 namespace v8 { 25 namespace internal { 26 27 28 #define DECLARE_EVENT(ignore1, name) name, 29 static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = { 30 LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT) 31 }; 32 #undef DECLARE_EVENT 33 34 35 #define CALL_LISTENERS(Call) \ 36 for (int i = 0; i < listeners_.length(); ++i) { \ 37 listeners_[i]->Call; \ 38 } 39 40 #define PROFILER_LOG(Call) \ 41 do { \ 42 CpuProfiler* cpu_profiler = isolate_->cpu_profiler(); \ 43 if (cpu_profiler->is_profiling()) { \ 44 cpu_profiler->Call; \ 45 } \ 46 } while (false); 47 48 static const char* ComputeMarker(SharedFunctionInfo* shared, Code* code) { 49 switch (code->kind()) { 50 case Code::FUNCTION: 51 return shared->optimization_disabled() ? "" : "~"; 52 case Code::OPTIMIZED_FUNCTION: 53 return "*"; 54 default: 55 return ""; 56 } 57 } 58 59 60 class CodeEventLogger::NameBuffer { 61 public: 62 NameBuffer() { Reset(); } 63 64 void Reset() { 65 utf8_pos_ = 0; 66 } 67 68 void Init(Logger::LogEventsAndTags tag) { 69 Reset(); 70 AppendBytes(kLogEventsNames[tag]); 71 AppendByte(':'); 72 } 73 74 void AppendName(Name* name) { 75 if (name->IsString()) { 76 AppendString(String::cast(name)); 77 } else { 78 Symbol* symbol = Symbol::cast(name); 79 AppendBytes("symbol("); 80 if (!symbol->name()->IsUndefined()) { 81 AppendBytes("\""); 82 AppendString(String::cast(symbol->name())); 83 AppendBytes("\" "); 84 } 85 AppendBytes("hash "); 86 AppendHex(symbol->Hash()); 87 AppendByte(')'); 88 } 89 } 90 91 void AppendString(String* str) { 92 if (str == NULL) return; 93 int uc16_length = Min(str->length(), kUtf16BufferSize); 94 String::WriteToFlat(str, utf16_buffer, 0, uc16_length); 95 int previous = unibrow::Utf16::kNoPreviousCharacter; 96 for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) { 97 uc16 c = utf16_buffer[i]; 98 if (c <= unibrow::Utf8::kMaxOneByteChar) { 99 utf8_buffer_[utf8_pos_++] = static_cast<char>(c); 100 } else { 101 int char_length = unibrow::Utf8::Length(c, previous); 102 if (utf8_pos_ + char_length > kUtf8BufferSize) break; 103 unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous); 104 utf8_pos_ += char_length; 105 } 106 previous = c; 107 } 108 } 109 110 void AppendBytes(const char* bytes, int size) { 111 size = Min(size, kUtf8BufferSize - utf8_pos_); 112 MemCopy(utf8_buffer_ + utf8_pos_, bytes, size); 113 utf8_pos_ += size; 114 } 115 116 void AppendBytes(const char* bytes) { 117 AppendBytes(bytes, StrLength(bytes)); 118 } 119 120 void AppendByte(char c) { 121 if (utf8_pos_ >= kUtf8BufferSize) return; 122 utf8_buffer_[utf8_pos_++] = c; 123 } 124 125 void AppendInt(int n) { 126 int space = kUtf8BufferSize - utf8_pos_; 127 if (space <= 0) return; 128 Vector<char> buffer(utf8_buffer_ + utf8_pos_, space); 129 int size = SNPrintF(buffer, "%d", n); 130 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) { 131 utf8_pos_ += size; 132 } 133 } 134 135 void AppendHex(uint32_t n) { 136 int space = kUtf8BufferSize - utf8_pos_; 137 if (space <= 0) return; 138 Vector<char> buffer(utf8_buffer_ + utf8_pos_, space); 139 int size = SNPrintF(buffer, "%x", n); 140 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) { 141 utf8_pos_ += size; 142 } 143 } 144 145 const char* get() { return utf8_buffer_; } 146 int size() const { return utf8_pos_; } 147 148 private: 149 static const int kUtf8BufferSize = 512; 150 static const int kUtf16BufferSize = kUtf8BufferSize; 151 152 int utf8_pos_; 153 char utf8_buffer_[kUtf8BufferSize]; 154 uc16 utf16_buffer[kUtf16BufferSize]; 155 }; 156 157 158 CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { } 159 160 CodeEventLogger::~CodeEventLogger() { delete name_buffer_; } 161 162 163 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, 164 Code* code, 165 const char* comment) { 166 name_buffer_->Init(tag); 167 name_buffer_->AppendBytes(comment); 168 LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size()); 169 } 170 171 172 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, 173 Code* code, 174 Name* name) { 175 name_buffer_->Init(tag); 176 name_buffer_->AppendName(name); 177 LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size()); 178 } 179 180 181 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, 182 Code* code, 183 SharedFunctionInfo* shared, 184 CompilationInfo* info, 185 Name* name) { 186 name_buffer_->Init(tag); 187 name_buffer_->AppendBytes(ComputeMarker(shared, code)); 188 name_buffer_->AppendName(name); 189 LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); 190 } 191 192 193 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, 194 Code* code, 195 SharedFunctionInfo* shared, 196 CompilationInfo* info, 197 Name* source, int line, int column) { 198 name_buffer_->Init(tag); 199 name_buffer_->AppendBytes(ComputeMarker(shared, code)); 200 name_buffer_->AppendString(shared->DebugName()); 201 name_buffer_->AppendByte(' '); 202 if (source->IsString()) { 203 name_buffer_->AppendString(String::cast(source)); 204 } else { 205 name_buffer_->AppendBytes("symbol(hash "); 206 name_buffer_->AppendHex(Name::cast(source)->Hash()); 207 name_buffer_->AppendByte(')'); 208 } 209 name_buffer_->AppendByte(':'); 210 name_buffer_->AppendInt(line); 211 LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); 212 } 213 214 215 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, 216 Code* code, 217 int args_count) { 218 name_buffer_->Init(tag); 219 name_buffer_->AppendInt(args_count); 220 LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size()); 221 } 222 223 224 void CodeEventLogger::RegExpCodeCreateEvent(Code* code, String* source) { 225 name_buffer_->Init(Logger::REG_EXP_TAG); 226 name_buffer_->AppendString(source); 227 LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size()); 228 } 229 230 231 // Linux perf tool logging support 232 class PerfBasicLogger : public CodeEventLogger { 233 public: 234 PerfBasicLogger(); 235 virtual ~PerfBasicLogger(); 236 237 virtual void CodeMoveEvent(Address from, Address to) { } 238 virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { } 239 virtual void CodeDeleteEvent(Address from) { } 240 241 private: 242 virtual void LogRecordedBuffer(Code* code, 243 SharedFunctionInfo* shared, 244 const char* name, 245 int length); 246 247 // Extension added to V8 log file name to get the low-level log name. 248 static const char kFilenameFormatString[]; 249 static const int kFilenameBufferPadding; 250 251 // File buffer size of the low-level log. We don't use the default to 252 // minimize the associated overhead. 253 static const int kLogBufferSize = 2 * MB; 254 255 FILE* perf_output_handle_; 256 }; 257 258 const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map"; 259 // Extra space for the PID in the filename 260 const int PerfBasicLogger::kFilenameBufferPadding = 16; 261 262 PerfBasicLogger::PerfBasicLogger() 263 : perf_output_handle_(NULL) { 264 // Open the perf JIT dump file. 265 int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding; 266 ScopedVector<char> perf_dump_name(bufferSize); 267 int size = SNPrintF( 268 perf_dump_name, 269 kFilenameFormatString, 270 base::OS::GetCurrentProcessId()); 271 CHECK_NE(size, -1); 272 perf_output_handle_ = 273 base::OS::FOpen(perf_dump_name.start(), base::OS::LogFileOpenMode); 274 CHECK_NOT_NULL(perf_output_handle_); 275 setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize); 276 } 277 278 279 PerfBasicLogger::~PerfBasicLogger() { 280 fclose(perf_output_handle_); 281 perf_output_handle_ = NULL; 282 } 283 284 285 void PerfBasicLogger::LogRecordedBuffer(Code* code, 286 SharedFunctionInfo*, 287 const char* name, 288 int length) { 289 DCHECK(code->instruction_start() == code->address() + Code::kHeaderSize); 290 291 if (FLAG_perf_basic_prof_only_functions && 292 (code->kind() != Code::FUNCTION && 293 code->kind() != Code::OPTIMIZED_FUNCTION)) { 294 return; 295 } 296 297 base::OS::FPrint(perf_output_handle_, "%llx %x %.*s\n", 298 reinterpret_cast<uint64_t>(code->instruction_start()), 299 code->instruction_size(), length, name); 300 } 301 302 303 // Low-level logging support. 304 #define LL_LOG(Call) if (ll_logger_) ll_logger_->Call; 305 306 class LowLevelLogger : public CodeEventLogger { 307 public: 308 explicit LowLevelLogger(const char* file_name); 309 virtual ~LowLevelLogger(); 310 311 virtual void CodeMoveEvent(Address from, Address to); 312 virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { } 313 virtual void CodeDeleteEvent(Address from); 314 virtual void SnapshotPositionEvent(Address addr, int pos); 315 virtual void CodeMovingGCEvent(); 316 317 private: 318 virtual void LogRecordedBuffer(Code* code, 319 SharedFunctionInfo* shared, 320 const char* name, 321 int length); 322 323 // Low-level profiling event structures. 324 struct CodeCreateStruct { 325 static const char kTag = 'C'; 326 327 int32_t name_size; 328 Address code_address; 329 int32_t code_size; 330 }; 331 332 333 struct CodeMoveStruct { 334 static const char kTag = 'M'; 335 336 Address from_address; 337 Address to_address; 338 }; 339 340 341 struct CodeDeleteStruct { 342 static const char kTag = 'D'; 343 344 Address address; 345 }; 346 347 348 struct SnapshotPositionStruct { 349 static const char kTag = 'P'; 350 351 Address address; 352 int32_t position; 353 }; 354 355 356 static const char kCodeMovingGCTag = 'G'; 357 358 359 // Extension added to V8 log file name to get the low-level log name. 360 static const char kLogExt[]; 361 362 // File buffer size of the low-level log. We don't use the default to 363 // minimize the associated overhead. 364 static const int kLogBufferSize = 2 * MB; 365 366 void LogCodeInfo(); 367 void LogWriteBytes(const char* bytes, int size); 368 369 template <typename T> 370 void LogWriteStruct(const T& s) { 371 char tag = T::kTag; 372 LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag)); 373 LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s)); 374 } 375 376 FILE* ll_output_handle_; 377 }; 378 379 const char LowLevelLogger::kLogExt[] = ".ll"; 380 381 LowLevelLogger::LowLevelLogger(const char* name) 382 : ll_output_handle_(NULL) { 383 // Open the low-level log file. 384 size_t len = strlen(name); 385 ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt))); 386 MemCopy(ll_name.start(), name, len); 387 MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt)); 388 ll_output_handle_ = 389 base::OS::FOpen(ll_name.start(), base::OS::LogFileOpenMode); 390 setvbuf(ll_output_handle_, NULL, _IOFBF, kLogBufferSize); 391 392 LogCodeInfo(); 393 } 394 395 396 LowLevelLogger::~LowLevelLogger() { 397 fclose(ll_output_handle_); 398 ll_output_handle_ = NULL; 399 } 400 401 402 void LowLevelLogger::LogCodeInfo() { 403 #if V8_TARGET_ARCH_IA32 404 const char arch[] = "ia32"; 405 #elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_64_BIT 406 const char arch[] = "x64"; 407 #elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_32_BIT 408 const char arch[] = "x32"; 409 #elif V8_TARGET_ARCH_ARM 410 const char arch[] = "arm"; 411 #elif V8_TARGET_ARCH_PPC 412 const char arch[] = "ppc"; 413 #elif V8_TARGET_ARCH_MIPS 414 const char arch[] = "mips"; 415 #elif V8_TARGET_ARCH_X87 416 const char arch[] = "x87"; 417 #elif V8_TARGET_ARCH_ARM64 418 const char arch[] = "arm64"; 419 #else 420 const char arch[] = "unknown"; 421 #endif 422 LogWriteBytes(arch, sizeof(arch)); 423 } 424 425 426 void LowLevelLogger::LogRecordedBuffer(Code* code, 427 SharedFunctionInfo*, 428 const char* name, 429 int length) { 430 CodeCreateStruct event; 431 event.name_size = length; 432 event.code_address = code->instruction_start(); 433 DCHECK(event.code_address == code->address() + Code::kHeaderSize); 434 event.code_size = code->instruction_size(); 435 LogWriteStruct(event); 436 LogWriteBytes(name, length); 437 LogWriteBytes( 438 reinterpret_cast<const char*>(code->instruction_start()), 439 code->instruction_size()); 440 } 441 442 443 void LowLevelLogger::CodeMoveEvent(Address from, Address to) { 444 CodeMoveStruct event; 445 event.from_address = from + Code::kHeaderSize; 446 event.to_address = to + Code::kHeaderSize; 447 LogWriteStruct(event); 448 } 449 450 451 void LowLevelLogger::CodeDeleteEvent(Address from) { 452 CodeDeleteStruct event; 453 event.address = from + Code::kHeaderSize; 454 LogWriteStruct(event); 455 } 456 457 458 void LowLevelLogger::SnapshotPositionEvent(Address addr, int pos) { 459 SnapshotPositionStruct event; 460 event.address = addr + Code::kHeaderSize; 461 event.position = pos; 462 LogWriteStruct(event); 463 } 464 465 466 void LowLevelLogger::LogWriteBytes(const char* bytes, int size) { 467 size_t rv = fwrite(bytes, 1, size, ll_output_handle_); 468 DCHECK(static_cast<size_t>(size) == rv); 469 USE(rv); 470 } 471 472 473 void LowLevelLogger::CodeMovingGCEvent() { 474 const char tag = kCodeMovingGCTag; 475 476 LogWriteBytes(&tag, sizeof(tag)); 477 } 478 479 480 #define JIT_LOG(Call) if (jit_logger_) jit_logger_->Call; 481 482 483 class JitLogger : public CodeEventLogger { 484 public: 485 explicit JitLogger(JitCodeEventHandler code_event_handler); 486 487 virtual void CodeMoveEvent(Address from, Address to); 488 virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { } 489 virtual void CodeDeleteEvent(Address from); 490 virtual void AddCodeLinePosInfoEvent( 491 void* jit_handler_data, 492 int pc_offset, 493 int position, 494 JitCodeEvent::PositionType position_type); 495 496 void* StartCodePosInfoEvent(); 497 void EndCodePosInfoEvent(Code* code, void* jit_handler_data); 498 499 private: 500 virtual void LogRecordedBuffer(Code* code, 501 SharedFunctionInfo* shared, 502 const char* name, 503 int length); 504 505 JitCodeEventHandler code_event_handler_; 506 base::Mutex logger_mutex_; 507 }; 508 509 510 JitLogger::JitLogger(JitCodeEventHandler code_event_handler) 511 : code_event_handler_(code_event_handler) { 512 } 513 514 515 void JitLogger::LogRecordedBuffer(Code* code, 516 SharedFunctionInfo* shared, 517 const char* name, 518 int length) { 519 JitCodeEvent event; 520 memset(&event, 0, sizeof(event)); 521 event.type = JitCodeEvent::CODE_ADDED; 522 event.code_start = code->instruction_start(); 523 event.code_len = code->instruction_size(); 524 Handle<SharedFunctionInfo> shared_function_handle; 525 if (shared && shared->script()->IsScript()) { 526 shared_function_handle = Handle<SharedFunctionInfo>(shared); 527 } 528 event.script = ToApiHandle<v8::UnboundScript>(shared_function_handle); 529 event.name.str = name; 530 event.name.len = length; 531 code_event_handler_(&event); 532 } 533 534 535 void JitLogger::CodeMoveEvent(Address from, Address to) { 536 base::LockGuard<base::Mutex> guard(&logger_mutex_); 537 Code* from_code = Code::cast(HeapObject::FromAddress(from)); 538 539 JitCodeEvent event; 540 event.type = JitCodeEvent::CODE_MOVED; 541 event.code_start = from_code->instruction_start(); 542 event.code_len = from_code->instruction_size(); 543 544 // Calculate the header size. 545 const size_t header_size = 546 from_code->instruction_start() - reinterpret_cast<byte*>(from_code); 547 548 // Calculate the new start address of the instructions. 549 event.new_code_start = 550 reinterpret_cast<byte*>(HeapObject::FromAddress(to)) + header_size; 551 552 code_event_handler_(&event); 553 } 554 555 556 void JitLogger::CodeDeleteEvent(Address from) { 557 Code* from_code = Code::cast(HeapObject::FromAddress(from)); 558 559 JitCodeEvent event; 560 event.type = JitCodeEvent::CODE_REMOVED; 561 event.code_start = from_code->instruction_start(); 562 event.code_len = from_code->instruction_size(); 563 564 code_event_handler_(&event); 565 } 566 567 void JitLogger::AddCodeLinePosInfoEvent( 568 void* jit_handler_data, 569 int pc_offset, 570 int position, 571 JitCodeEvent::PositionType position_type) { 572 JitCodeEvent event; 573 memset(&event, 0, sizeof(event)); 574 event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO; 575 event.user_data = jit_handler_data; 576 event.line_info.offset = pc_offset; 577 event.line_info.pos = position; 578 event.line_info.position_type = position_type; 579 580 code_event_handler_(&event); 581 } 582 583 584 void* JitLogger::StartCodePosInfoEvent() { 585 JitCodeEvent event; 586 memset(&event, 0, sizeof(event)); 587 event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING; 588 589 code_event_handler_(&event); 590 return event.user_data; 591 } 592 593 594 void JitLogger::EndCodePosInfoEvent(Code* code, void* jit_handler_data) { 595 JitCodeEvent event; 596 memset(&event, 0, sizeof(event)); 597 event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING; 598 event.code_start = code->instruction_start(); 599 event.user_data = jit_handler_data; 600 601 code_event_handler_(&event); 602 } 603 604 605 // The Profiler samples pc and sp values for the main thread. 606 // Each sample is appended to a circular buffer. 607 // An independent thread removes data and writes it to the log. 608 // This design minimizes the time spent in the sampler. 609 // 610 class Profiler: public base::Thread { 611 public: 612 explicit Profiler(Isolate* isolate); 613 void Engage(); 614 void Disengage(); 615 616 // Inserts collected profiling data into buffer. 617 void Insert(TickSample* sample) { 618 if (paused_) 619 return; 620 621 if (Succ(head_) == static_cast<int>(base::NoBarrier_Load(&tail_))) { 622 overflow_ = true; 623 } else { 624 buffer_[head_] = *sample; 625 head_ = Succ(head_); 626 buffer_semaphore_.Signal(); // Tell we have an element. 627 } 628 } 629 630 virtual void Run(); 631 632 // Pause and Resume TickSample data collection. 633 void pause() { paused_ = true; } 634 void resume() { paused_ = false; } 635 636 private: 637 // Waits for a signal and removes profiling data. 638 bool Remove(TickSample* sample) { 639 buffer_semaphore_.Wait(); // Wait for an element. 640 *sample = buffer_[base::NoBarrier_Load(&tail_)]; 641 bool result = overflow_; 642 base::NoBarrier_Store(&tail_, static_cast<base::Atomic32>( 643 Succ(base::NoBarrier_Load(&tail_)))); 644 overflow_ = false; 645 return result; 646 } 647 648 // Returns the next index in the cyclic buffer. 649 int Succ(int index) { return (index + 1) % kBufferSize; } 650 651 Isolate* isolate_; 652 // Cyclic buffer for communicating profiling samples 653 // between the signal handler and the worker thread. 654 static const int kBufferSize = 128; 655 TickSample buffer_[kBufferSize]; // Buffer storage. 656 int head_; // Index to the buffer head. 657 base::Atomic32 tail_; // Index to the buffer tail. 658 bool overflow_; // Tell whether a buffer overflow has occurred. 659 // Sempahore used for buffer synchronization. 660 base::Semaphore buffer_semaphore_; 661 662 // Tells whether profiler is engaged, that is, processing thread is stated. 663 bool engaged_; 664 665 // Tells whether worker thread should continue running. 666 base::Atomic32 running_; 667 668 // Tells whether we are currently recording tick samples. 669 bool paused_; 670 }; 671 672 673 // 674 // Ticker used to provide ticks to the profiler and the sliding state 675 // window. 676 // 677 class Ticker: public Sampler { 678 public: 679 Ticker(Isolate* isolate, int interval): 680 Sampler(isolate, interval), 681 profiler_(NULL) {} 682 683 ~Ticker() { if (IsActive()) Stop(); } 684 685 virtual void Tick(TickSample* sample) { 686 if (profiler_) profiler_->Insert(sample); 687 } 688 689 void SetProfiler(Profiler* profiler) { 690 DCHECK(profiler_ == NULL); 691 profiler_ = profiler; 692 IncreaseProfilingDepth(); 693 if (!IsActive()) Start(); 694 } 695 696 void ClearProfiler() { 697 profiler_ = NULL; 698 if (IsActive()) Stop(); 699 DecreaseProfilingDepth(); 700 } 701 702 private: 703 Profiler* profiler_; 704 }; 705 706 707 // 708 // Profiler implementation. 709 // 710 Profiler::Profiler(Isolate* isolate) 711 : base::Thread(Options("v8:Profiler")), 712 isolate_(isolate), 713 head_(0), 714 overflow_(false), 715 buffer_semaphore_(0), 716 engaged_(false), 717 paused_(false) { 718 base::NoBarrier_Store(&tail_, 0); 719 base::NoBarrier_Store(&running_, 0); 720 } 721 722 723 void Profiler::Engage() { 724 if (engaged_) return; 725 engaged_ = true; 726 727 std::vector<base::OS::SharedLibraryAddress> addresses = 728 base::OS::GetSharedLibraryAddresses(); 729 for (size_t i = 0; i < addresses.size(); ++i) { 730 LOG(isolate_, SharedLibraryEvent( 731 addresses[i].library_path, addresses[i].start, addresses[i].end)); 732 } 733 734 // Start thread processing the profiler buffer. 735 base::NoBarrier_Store(&running_, 1); 736 Start(); 737 738 // Register to get ticks. 739 Logger* logger = isolate_->logger(); 740 logger->ticker_->SetProfiler(this); 741 742 logger->ProfilerBeginEvent(); 743 } 744 745 746 void Profiler::Disengage() { 747 if (!engaged_) return; 748 749 // Stop receiving ticks. 750 isolate_->logger()->ticker_->ClearProfiler(); 751 752 // Terminate the worker thread by setting running_ to false, 753 // inserting a fake element in the queue and then wait for 754 // the thread to terminate. 755 base::NoBarrier_Store(&running_, 0); 756 TickSample sample; 757 // Reset 'paused_' flag, otherwise semaphore may not be signalled. 758 resume(); 759 Insert(&sample); 760 Join(); 761 762 LOG(isolate_, UncheckedStringEvent("profiler", "end")); 763 } 764 765 766 void Profiler::Run() { 767 TickSample sample; 768 bool overflow = Remove(&sample); 769 while (base::NoBarrier_Load(&running_)) { 770 LOG(isolate_, TickEvent(&sample, overflow)); 771 overflow = Remove(&sample); 772 } 773 } 774 775 776 // 777 // Logger class implementation. 778 // 779 780 Logger::Logger(Isolate* isolate) 781 : isolate_(isolate), 782 ticker_(NULL), 783 profiler_(NULL), 784 log_events_(NULL), 785 is_logging_(false), 786 log_(new Log(this)), 787 perf_basic_logger_(NULL), 788 ll_logger_(NULL), 789 jit_logger_(NULL), 790 listeners_(5), 791 is_initialized_(false) { 792 } 793 794 795 Logger::~Logger() { 796 delete log_; 797 } 798 799 800 void Logger::addCodeEventListener(CodeEventListener* listener) { 801 DCHECK(!hasCodeEventListener(listener)); 802 listeners_.Add(listener); 803 } 804 805 806 void Logger::removeCodeEventListener(CodeEventListener* listener) { 807 DCHECK(hasCodeEventListener(listener)); 808 listeners_.RemoveElement(listener); 809 } 810 811 812 bool Logger::hasCodeEventListener(CodeEventListener* listener) { 813 return listeners_.Contains(listener); 814 } 815 816 817 void Logger::ProfilerBeginEvent() { 818 if (!log_->IsEnabled()) return; 819 Log::MessageBuilder msg(log_); 820 msg.Append("profiler,\"begin\",%d", kSamplingIntervalMs); 821 msg.WriteToLogFile(); 822 } 823 824 825 void Logger::StringEvent(const char* name, const char* value) { 826 if (FLAG_log) UncheckedStringEvent(name, value); 827 } 828 829 830 void Logger::UncheckedStringEvent(const char* name, const char* value) { 831 if (!log_->IsEnabled()) return; 832 Log::MessageBuilder msg(log_); 833 msg.Append("%s,\"%s\"", name, value); 834 msg.WriteToLogFile(); 835 } 836 837 838 void Logger::IntEvent(const char* name, int value) { 839 if (FLAG_log) UncheckedIntEvent(name, value); 840 } 841 842 843 void Logger::IntPtrTEvent(const char* name, intptr_t value) { 844 if (FLAG_log) UncheckedIntPtrTEvent(name, value); 845 } 846 847 848 void Logger::UncheckedIntEvent(const char* name, int value) { 849 if (!log_->IsEnabled()) return; 850 Log::MessageBuilder msg(log_); 851 msg.Append("%s,%d", name, value); 852 msg.WriteToLogFile(); 853 } 854 855 856 void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) { 857 if (!log_->IsEnabled()) return; 858 Log::MessageBuilder msg(log_); 859 msg.Append("%s,%" V8_PTR_PREFIX "d", name, value); 860 msg.WriteToLogFile(); 861 } 862 863 864 void Logger::HandleEvent(const char* name, Object** location) { 865 if (!log_->IsEnabled() || !FLAG_log_handles) return; 866 Log::MessageBuilder msg(log_); 867 msg.Append("%s,0x%" V8PRIxPTR, name, location); 868 msg.WriteToLogFile(); 869 } 870 871 872 // ApiEvent is private so all the calls come from the Logger class. It is the 873 // caller's responsibility to ensure that log is enabled and that 874 // FLAG_log_api is true. 875 void Logger::ApiEvent(const char* format, ...) { 876 DCHECK(log_->IsEnabled() && FLAG_log_api); 877 Log::MessageBuilder msg(log_); 878 va_list ap; 879 va_start(ap, format); 880 msg.AppendVA(format, ap); 881 va_end(ap); 882 msg.WriteToLogFile(); 883 } 884 885 886 void Logger::ApiSecurityCheck() { 887 if (!log_->IsEnabled() || !FLAG_log_api) return; 888 ApiEvent("api,check-security"); 889 } 890 891 892 void Logger::SharedLibraryEvent(const std::string& library_path, 893 uintptr_t start, 894 uintptr_t end) { 895 if (!log_->IsEnabled() || !FLAG_prof_cpp) return; 896 Log::MessageBuilder msg(log_); 897 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR, 898 library_path.c_str(), start, end); 899 msg.WriteToLogFile(); 900 } 901 902 903 void Logger::CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) { 904 PROFILER_LOG(CodeDeoptEvent(code, pc, fp_to_sp_delta)); 905 if (!log_->IsEnabled() || !FLAG_log_internal_timer_events) return; 906 Log::MessageBuilder msg(log_); 907 int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); 908 msg.Append("code-deopt,%ld,%d", since_epoch, code->CodeSize()); 909 msg.WriteToLogFile(); 910 } 911 912 913 void Logger::CurrentTimeEvent() { 914 if (!log_->IsEnabled()) return; 915 DCHECK(FLAG_log_timer_events || FLAG_prof_cpp); 916 Log::MessageBuilder msg(log_); 917 int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); 918 msg.Append("current-time,%ld", since_epoch); 919 msg.WriteToLogFile(); 920 } 921 922 923 void Logger::TimerEvent(Logger::StartEnd se, const char* name) { 924 if (!log_->IsEnabled()) return; 925 DCHECK(FLAG_log_internal_timer_events); 926 Log::MessageBuilder msg(log_); 927 int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); 928 const char* format = (se == START) ? "timer-event-start,\"%s\",%ld" 929 : "timer-event-end,\"%s\",%ld"; 930 msg.Append(format, name, since_epoch); 931 msg.WriteToLogFile(); 932 } 933 934 935 void Logger::EnterExternal(Isolate* isolate) { 936 LOG(isolate, TimerEvent(START, TimerEventExternal::name())); 937 DCHECK(isolate->current_vm_state() == JS); 938 isolate->set_current_vm_state(EXTERNAL); 939 } 940 941 942 void Logger::LeaveExternal(Isolate* isolate) { 943 LOG(isolate, TimerEvent(END, TimerEventExternal::name())); 944 DCHECK(isolate->current_vm_state() == EXTERNAL); 945 isolate->set_current_vm_state(JS); 946 } 947 948 949 template <class TimerEvent> 950 void TimerEventScope<TimerEvent>::LogTimerEvent(Logger::StartEnd se) { 951 Logger::CallEventLogger(isolate_, TimerEvent::name(), se, 952 TimerEvent::expose_to_api()); 953 } 954 955 956 // Instantiate template methods. 957 #define V(TimerName, expose) \ 958 template void TimerEventScope<TimerEvent##TimerName>::LogTimerEvent( \ 959 Logger::StartEnd se); 960 TIMER_EVENTS_LIST(V) 961 #undef V 962 963 964 namespace { 965 // Emits the source code of a regexp. Used by regexp events. 966 void LogRegExpSource(Handle<JSRegExp> regexp, Isolate* isolate, 967 Log::MessageBuilder* msg) { 968 // Prints "/" + re.source + "/" + 969 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"") 970 971 Handle<Object> source = 972 Object::GetProperty(isolate, regexp, "source").ToHandleChecked(); 973 if (!source->IsString()) { 974 msg->Append("no source"); 975 return; 976 } 977 978 switch (regexp->TypeTag()) { 979 case JSRegExp::ATOM: 980 msg->Append('a'); 981 break; 982 default: 983 break; 984 } 985 msg->Append('/'); 986 msg->AppendDetailed(*Handle<String>::cast(source), false); 987 msg->Append('/'); 988 989 // global flag 990 Handle<Object> global = 991 Object::GetProperty(isolate, regexp, "global").ToHandleChecked(); 992 if (global->IsTrue()) { 993 msg->Append('g'); 994 } 995 // ignorecase flag 996 Handle<Object> ignorecase = 997 Object::GetProperty(isolate, regexp, "ignoreCase").ToHandleChecked(); 998 if (ignorecase->IsTrue()) { 999 msg->Append('i'); 1000 } 1001 // multiline flag 1002 Handle<Object> multiline = 1003 Object::GetProperty(isolate, regexp, "multiline").ToHandleChecked(); 1004 if (multiline->IsTrue()) { 1005 msg->Append('m'); 1006 } 1007 } 1008 } // namespace 1009 1010 1011 void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) { 1012 if (!log_->IsEnabled() || !FLAG_log_regexp) return; 1013 Log::MessageBuilder msg(log_); 1014 msg.Append("regexp-compile,"); 1015 LogRegExpSource(regexp, isolate_, &msg); 1016 msg.Append(in_cache ? ",hit" : ",miss"); 1017 msg.WriteToLogFile(); 1018 } 1019 1020 1021 void Logger::ApiNamedPropertyAccess(const char* tag, 1022 JSObject* holder, 1023 Object* name) { 1024 DCHECK(name->IsName()); 1025 if (!log_->IsEnabled() || !FLAG_log_api) return; 1026 String* class_name_obj = holder->class_name(); 1027 base::SmartArrayPointer<char> class_name = 1028 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1029 if (name->IsString()) { 1030 base::SmartArrayPointer<char> property_name = 1031 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1032 ApiEvent("api,%s,\"%s\",\"%s\"", tag, class_name.get(), 1033 property_name.get()); 1034 } else { 1035 Symbol* symbol = Symbol::cast(name); 1036 uint32_t hash = symbol->Hash(); 1037 if (symbol->name()->IsUndefined()) { 1038 ApiEvent("api,%s,\"%s\",symbol(hash %x)", tag, class_name.get(), hash); 1039 } else { 1040 base::SmartArrayPointer<char> str = 1041 String::cast(symbol->name()) 1042 ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1043 ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)", tag, class_name.get(), 1044 str.get(), hash); 1045 } 1046 } 1047 } 1048 1049 void Logger::ApiIndexedPropertyAccess(const char* tag, 1050 JSObject* holder, 1051 uint32_t index) { 1052 if (!log_->IsEnabled() || !FLAG_log_api) return; 1053 String* class_name_obj = holder->class_name(); 1054 base::SmartArrayPointer<char> class_name = 1055 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1056 ApiEvent("api,%s,\"%s\",%u", tag, class_name.get(), index); 1057 } 1058 1059 1060 void Logger::ApiObjectAccess(const char* tag, JSObject* object) { 1061 if (!log_->IsEnabled() || !FLAG_log_api) return; 1062 String* class_name_obj = object->class_name(); 1063 base::SmartArrayPointer<char> class_name = 1064 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1065 ApiEvent("api,%s,\"%s\"", tag, class_name.get()); 1066 } 1067 1068 1069 void Logger::ApiEntryCall(const char* name) { 1070 if (!log_->IsEnabled() || !FLAG_log_api) return; 1071 ApiEvent("api,%s", name); 1072 } 1073 1074 1075 void Logger::NewEvent(const char* name, void* object, size_t size) { 1076 if (!log_->IsEnabled() || !FLAG_log) return; 1077 Log::MessageBuilder msg(log_); 1078 msg.Append("new,%s,0x%" V8PRIxPTR ",%u", name, object, 1079 static_cast<unsigned int>(size)); 1080 msg.WriteToLogFile(); 1081 } 1082 1083 1084 void Logger::DeleteEvent(const char* name, void* object) { 1085 if (!log_->IsEnabled() || !FLAG_log) return; 1086 Log::MessageBuilder msg(log_); 1087 msg.Append("delete,%s,0x%" V8PRIxPTR, name, object); 1088 msg.WriteToLogFile(); 1089 } 1090 1091 1092 void Logger::CallbackEventInternal(const char* prefix, Name* name, 1093 Address entry_point) { 1094 if (!FLAG_log_code || !log_->IsEnabled()) return; 1095 Log::MessageBuilder msg(log_); 1096 msg.Append("%s,%s,-2,", 1097 kLogEventsNames[CODE_CREATION_EVENT], 1098 kLogEventsNames[CALLBACK_TAG]); 1099 msg.AppendAddress(entry_point); 1100 if (name->IsString()) { 1101 base::SmartArrayPointer<char> str = 1102 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1103 msg.Append(",1,\"%s%s\"", prefix, str.get()); 1104 } else { 1105 Symbol* symbol = Symbol::cast(name); 1106 if (symbol->name()->IsUndefined()) { 1107 msg.Append(",1,symbol(hash %x)", prefix, symbol->Hash()); 1108 } else { 1109 base::SmartArrayPointer<char> str = 1110 String::cast(symbol->name()) 1111 ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1112 msg.Append(",1,symbol(\"%s\" hash %x)", prefix, str.get(), 1113 symbol->Hash()); 1114 } 1115 } 1116 msg.WriteToLogFile(); 1117 } 1118 1119 1120 void Logger::CallbackEvent(Name* name, Address entry_point) { 1121 PROFILER_LOG(CallbackEvent(name, entry_point)); 1122 CallbackEventInternal("", name, entry_point); 1123 } 1124 1125 1126 void Logger::GetterCallbackEvent(Name* name, Address entry_point) { 1127 PROFILER_LOG(GetterCallbackEvent(name, entry_point)); 1128 CallbackEventInternal("get ", name, entry_point); 1129 } 1130 1131 1132 void Logger::SetterCallbackEvent(Name* name, Address entry_point) { 1133 PROFILER_LOG(SetterCallbackEvent(name, entry_point)); 1134 CallbackEventInternal("set ", name, entry_point); 1135 } 1136 1137 1138 static void AppendCodeCreateHeader(Log::MessageBuilder* msg, 1139 Logger::LogEventsAndTags tag, 1140 Code* code) { 1141 DCHECK(msg); 1142 msg->Append("%s,%s,%d,", 1143 kLogEventsNames[Logger::CODE_CREATION_EVENT], 1144 kLogEventsNames[tag], 1145 code->kind()); 1146 msg->AppendAddress(code->address()); 1147 msg->Append(",%d,", code->ExecutableSize()); 1148 } 1149 1150 1151 void Logger::CodeCreateEvent(LogEventsAndTags tag, 1152 Code* code, 1153 const char* comment) { 1154 PROFILER_LOG(CodeCreateEvent(tag, code, comment)); 1155 1156 if (!is_logging_code_events()) return; 1157 CALL_LISTENERS(CodeCreateEvent(tag, code, comment)); 1158 1159 if (!FLAG_log_code || !log_->IsEnabled()) return; 1160 Log::MessageBuilder msg(log_); 1161 AppendCodeCreateHeader(&msg, tag, code); 1162 msg.AppendDoubleQuotedString(comment); 1163 msg.WriteToLogFile(); 1164 } 1165 1166 1167 void Logger::CodeCreateEvent(LogEventsAndTags tag, 1168 Code* code, 1169 Name* name) { 1170 PROFILER_LOG(CodeCreateEvent(tag, code, name)); 1171 1172 if (!is_logging_code_events()) return; 1173 CALL_LISTENERS(CodeCreateEvent(tag, code, name)); 1174 1175 if (!FLAG_log_code || !log_->IsEnabled()) return; 1176 Log::MessageBuilder msg(log_); 1177 AppendCodeCreateHeader(&msg, tag, code); 1178 if (name->IsString()) { 1179 msg.Append('"'); 1180 msg.AppendDetailed(String::cast(name), false); 1181 msg.Append('"'); 1182 } else { 1183 msg.AppendSymbolName(Symbol::cast(name)); 1184 } 1185 msg.WriteToLogFile(); 1186 } 1187 1188 1189 void Logger::CodeCreateEvent(LogEventsAndTags tag, 1190 Code* code, 1191 SharedFunctionInfo* shared, 1192 CompilationInfo* info, 1193 Name* name) { 1194 PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, name)); 1195 1196 if (!is_logging_code_events()) return; 1197 CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, name)); 1198 1199 if (!FLAG_log_code || !log_->IsEnabled()) return; 1200 if (code == isolate_->builtins()->builtin(Builtins::kCompileLazy)) return; 1201 1202 Log::MessageBuilder msg(log_); 1203 AppendCodeCreateHeader(&msg, tag, code); 1204 if (name->IsString()) { 1205 base::SmartArrayPointer<char> str = 1206 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1207 msg.Append("\"%s\"", str.get()); 1208 } else { 1209 msg.AppendSymbolName(Symbol::cast(name)); 1210 } 1211 msg.Append(','); 1212 msg.AppendAddress(shared->address()); 1213 msg.Append(",%s", ComputeMarker(shared, code)); 1214 msg.WriteToLogFile(); 1215 } 1216 1217 1218 // Although, it is possible to extract source and line from 1219 // the SharedFunctionInfo object, we left it to caller 1220 // to leave logging functions free from heap allocations. 1221 void Logger::CodeCreateEvent(LogEventsAndTags tag, 1222 Code* code, 1223 SharedFunctionInfo* shared, 1224 CompilationInfo* info, 1225 Name* source, int line, int column) { 1226 PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, source, line, column)); 1227 1228 if (!is_logging_code_events()) return; 1229 CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, source, line, 1230 column)); 1231 1232 if (!FLAG_log_code || !log_->IsEnabled()) return; 1233 Log::MessageBuilder msg(log_); 1234 AppendCodeCreateHeader(&msg, tag, code); 1235 base::SmartArrayPointer<char> name = 1236 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1237 msg.Append("\"%s ", name.get()); 1238 if (source->IsString()) { 1239 base::SmartArrayPointer<char> sourcestr = String::cast(source)->ToCString( 1240 DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1241 msg.Append("%s", sourcestr.get()); 1242 } else { 1243 msg.AppendSymbolName(Symbol::cast(source)); 1244 } 1245 msg.Append(":%d:%d\",", line, column); 1246 msg.AppendAddress(shared->address()); 1247 msg.Append(",%s", ComputeMarker(shared, code)); 1248 msg.WriteToLogFile(); 1249 } 1250 1251 1252 void Logger::CodeCreateEvent(LogEventsAndTags tag, 1253 Code* code, 1254 int args_count) { 1255 PROFILER_LOG(CodeCreateEvent(tag, code, args_count)); 1256 1257 if (!is_logging_code_events()) return; 1258 CALL_LISTENERS(CodeCreateEvent(tag, code, args_count)); 1259 1260 if (!FLAG_log_code || !log_->IsEnabled()) return; 1261 Log::MessageBuilder msg(log_); 1262 AppendCodeCreateHeader(&msg, tag, code); 1263 msg.Append("\"args_count: %d\"", args_count); 1264 msg.WriteToLogFile(); 1265 } 1266 1267 1268 void Logger::CodeDisableOptEvent(Code* code, 1269 SharedFunctionInfo* shared) { 1270 PROFILER_LOG(CodeDisableOptEvent(code, shared)); 1271 1272 if (!is_logging_code_events()) return; 1273 CALL_LISTENERS(CodeDisableOptEvent(code, shared)); 1274 1275 if (!FLAG_log_code || !log_->IsEnabled()) return; 1276 Log::MessageBuilder msg(log_); 1277 msg.Append("%s,", kLogEventsNames[CODE_DISABLE_OPT_EVENT]); 1278 base::SmartArrayPointer<char> name = 1279 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); 1280 msg.Append("\"%s\",", name.get()); 1281 msg.Append("\"%s\"", GetBailoutReason(shared->disable_optimization_reason())); 1282 msg.WriteToLogFile(); 1283 } 1284 1285 1286 void Logger::CodeMovingGCEvent() { 1287 PROFILER_LOG(CodeMovingGCEvent()); 1288 1289 if (!is_logging_code_events()) return; 1290 if (!log_->IsEnabled() || !FLAG_ll_prof) return; 1291 CALL_LISTENERS(CodeMovingGCEvent()); 1292 base::OS::SignalCodeMovingGC(); 1293 } 1294 1295 1296 void Logger::RegExpCodeCreateEvent(Code* code, String* source) { 1297 PROFILER_LOG(RegExpCodeCreateEvent(code, source)); 1298 1299 if (!is_logging_code_events()) return; 1300 CALL_LISTENERS(RegExpCodeCreateEvent(code, source)); 1301 1302 if (!FLAG_log_code || !log_->IsEnabled()) return; 1303 Log::MessageBuilder msg(log_); 1304 AppendCodeCreateHeader(&msg, REG_EXP_TAG, code); 1305 msg.Append('"'); 1306 msg.AppendDetailed(source, false); 1307 msg.Append('"'); 1308 msg.WriteToLogFile(); 1309 } 1310 1311 1312 void Logger::CodeMoveEvent(Address from, Address to) { 1313 PROFILER_LOG(CodeMoveEvent(from, to)); 1314 1315 if (!is_logging_code_events()) return; 1316 CALL_LISTENERS(CodeMoveEvent(from, to)); 1317 MoveEventInternal(CODE_MOVE_EVENT, from, to); 1318 } 1319 1320 1321 void Logger::CodeDeleteEvent(Address from) { 1322 PROFILER_LOG(CodeDeleteEvent(from)); 1323 1324 if (!is_logging_code_events()) return; 1325 CALL_LISTENERS(CodeDeleteEvent(from)); 1326 1327 if (!FLAG_log_code || !log_->IsEnabled()) return; 1328 Log::MessageBuilder msg(log_); 1329 msg.Append("%s,", kLogEventsNames[CODE_DELETE_EVENT]); 1330 msg.AppendAddress(from); 1331 msg.WriteToLogFile(); 1332 } 1333 1334 1335 void Logger::CodeLinePosInfoAddPositionEvent(void* jit_handler_data, 1336 int pc_offset, 1337 int position) { 1338 JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data, 1339 pc_offset, 1340 position, 1341 JitCodeEvent::POSITION)); 1342 } 1343 1344 1345 void Logger::CodeLinePosInfoAddStatementPositionEvent(void* jit_handler_data, 1346 int pc_offset, 1347 int position) { 1348 JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data, 1349 pc_offset, 1350 position, 1351 JitCodeEvent::STATEMENT_POSITION)); 1352 } 1353 1354 1355 void Logger::CodeStartLinePosInfoRecordEvent(PositionsRecorder* pos_recorder) { 1356 if (jit_logger_ != NULL) { 1357 pos_recorder->AttachJITHandlerData(jit_logger_->StartCodePosInfoEvent()); 1358 } 1359 } 1360 1361 1362 void Logger::CodeEndLinePosInfoRecordEvent(Code* code, 1363 void* jit_handler_data) { 1364 JIT_LOG(EndCodePosInfoEvent(code, jit_handler_data)); 1365 } 1366 1367 1368 void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) { 1369 if (code_name == NULL) return; // Not a code object. 1370 Log::MessageBuilder msg(log_); 1371 msg.Append("%s,%d,", kLogEventsNames[SNAPSHOT_CODE_NAME_EVENT], pos); 1372 msg.AppendDoubleQuotedString(code_name); 1373 msg.WriteToLogFile(); 1374 } 1375 1376 1377 void Logger::SnapshotPositionEvent(Address addr, int pos) { 1378 if (!log_->IsEnabled()) return; 1379 LL_LOG(SnapshotPositionEvent(addr, pos)); 1380 if (!FLAG_log_snapshot_positions) return; 1381 Log::MessageBuilder msg(log_); 1382 msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]); 1383 msg.AppendAddress(addr); 1384 msg.Append(",%d", pos); 1385 msg.WriteToLogFile(); 1386 } 1387 1388 1389 void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) { 1390 if (!is_logging_code_events()) return; 1391 MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to); 1392 } 1393 1394 1395 void Logger::MoveEventInternal(LogEventsAndTags event, 1396 Address from, 1397 Address to) { 1398 if (!FLAG_log_code || !log_->IsEnabled()) return; 1399 Log::MessageBuilder msg(log_); 1400 msg.Append("%s,", kLogEventsNames[event]); 1401 msg.AppendAddress(from); 1402 msg.Append(','); 1403 msg.AppendAddress(to); 1404 msg.WriteToLogFile(); 1405 } 1406 1407 1408 void Logger::ResourceEvent(const char* name, const char* tag) { 1409 if (!log_->IsEnabled() || !FLAG_log) return; 1410 Log::MessageBuilder msg(log_); 1411 msg.Append("%s,%s,", name, tag); 1412 1413 uint32_t sec, usec; 1414 if (base::OS::GetUserTime(&sec, &usec) != -1) { 1415 msg.Append("%d,%d,", sec, usec); 1416 } 1417 msg.Append("%.0f", base::OS::TimeCurrentMillis()); 1418 msg.WriteToLogFile(); 1419 } 1420 1421 1422 void Logger::SuspectReadEvent(Name* name, Object* obj) { 1423 if (!log_->IsEnabled() || !FLAG_log_suspect) return; 1424 Log::MessageBuilder msg(log_); 1425 String* class_name = obj->IsJSObject() 1426 ? JSObject::cast(obj)->class_name() 1427 : isolate_->heap()->empty_string(); 1428 msg.Append("suspect-read,"); 1429 msg.Append(class_name); 1430 msg.Append(','); 1431 if (name->IsString()) { 1432 msg.Append('"'); 1433 msg.Append(String::cast(name)); 1434 msg.Append('"'); 1435 } else { 1436 msg.AppendSymbolName(Symbol::cast(name)); 1437 } 1438 msg.WriteToLogFile(); 1439 } 1440 1441 1442 void Logger::HeapSampleBeginEvent(const char* space, const char* kind) { 1443 if (!log_->IsEnabled() || !FLAG_log_gc) return; 1444 Log::MessageBuilder msg(log_); 1445 // Using non-relative system time in order to be able to synchronize with 1446 // external memory profiling events (e.g. DOM memory size). 1447 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f", space, kind, 1448 base::OS::TimeCurrentMillis()); 1449 msg.WriteToLogFile(); 1450 } 1451 1452 1453 void Logger::HeapSampleEndEvent(const char* space, const char* kind) { 1454 if (!log_->IsEnabled() || !FLAG_log_gc) return; 1455 Log::MessageBuilder msg(log_); 1456 msg.Append("heap-sample-end,\"%s\",\"%s\"", space, kind); 1457 msg.WriteToLogFile(); 1458 } 1459 1460 1461 void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) { 1462 if (!log_->IsEnabled() || !FLAG_log_gc) return; 1463 Log::MessageBuilder msg(log_); 1464 msg.Append("heap-sample-item,%s,%d,%d", type, number, bytes); 1465 msg.WriteToLogFile(); 1466 } 1467 1468 1469 void Logger::DebugTag(const char* call_site_tag) { 1470 if (!log_->IsEnabled() || !FLAG_log) return; 1471 Log::MessageBuilder msg(log_); 1472 msg.Append("debug-tag,%s", call_site_tag); 1473 msg.WriteToLogFile(); 1474 } 1475 1476 1477 void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) { 1478 if (!log_->IsEnabled() || !FLAG_log) return; 1479 StringBuilder s(parameter.length() + 1); 1480 for (int i = 0; i < parameter.length(); ++i) { 1481 s.AddCharacter(static_cast<char>(parameter[i])); 1482 } 1483 char* parameter_string = s.Finalize(); 1484 Log::MessageBuilder msg(log_); 1485 msg.Append("debug-queue-event,%s,%15.3f,%s", event_type, 1486 base::OS::TimeCurrentMillis(), parameter_string); 1487 DeleteArray(parameter_string); 1488 msg.WriteToLogFile(); 1489 } 1490 1491 1492 void Logger::TickEvent(TickSample* sample, bool overflow) { 1493 if (!log_->IsEnabled() || !FLAG_prof_cpp) return; 1494 Log::MessageBuilder msg(log_); 1495 msg.Append("%s,", kLogEventsNames[TICK_EVENT]); 1496 msg.AppendAddress(sample->pc); 1497 msg.Append(",%ld", static_cast<int>(timer_.Elapsed().InMicroseconds())); 1498 if (sample->has_external_callback) { 1499 msg.Append(",1,"); 1500 #if USES_FUNCTION_DESCRIPTORS 1501 msg.AppendAddress(*FUNCTION_ENTRYPOINT_ADDRESS(sample->external_callback)); 1502 #else 1503 msg.AppendAddress(sample->external_callback); 1504 #endif 1505 } else { 1506 msg.Append(",0,"); 1507 msg.AppendAddress(sample->tos); 1508 } 1509 msg.Append(",%d", static_cast<int>(sample->state)); 1510 if (overflow) { 1511 msg.Append(",overflow"); 1512 } 1513 for (unsigned i = 0; i < sample->frames_count; ++i) { 1514 msg.Append(','); 1515 msg.AppendAddress(sample->stack[i]); 1516 } 1517 msg.WriteToLogFile(); 1518 } 1519 1520 1521 void Logger::StopProfiler() { 1522 if (!log_->IsEnabled()) return; 1523 if (profiler_ != NULL) { 1524 profiler_->pause(); 1525 is_logging_ = false; 1526 } 1527 } 1528 1529 1530 // This function can be called when Log's mutex is acquired, 1531 // either from main or Profiler's thread. 1532 void Logger::LogFailure() { 1533 StopProfiler(); 1534 } 1535 1536 1537 class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor { 1538 public: 1539 EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis, 1540 Handle<Code>* code_objects, 1541 int* count) 1542 : sfis_(sfis), code_objects_(code_objects), count_(count) { } 1543 1544 virtual void EnterContext(Context* context) {} 1545 virtual void LeaveContext(Context* context) {} 1546 1547 virtual void VisitFunction(JSFunction* function) { 1548 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared()); 1549 Object* maybe_script = sfi->script(); 1550 if (maybe_script->IsScript() 1551 && !Script::cast(maybe_script)->HasValidSource()) return; 1552 if (sfis_ != NULL) { 1553 sfis_[*count_] = Handle<SharedFunctionInfo>(sfi); 1554 } 1555 if (code_objects_ != NULL) { 1556 DCHECK(function->code()->kind() == Code::OPTIMIZED_FUNCTION); 1557 code_objects_[*count_] = Handle<Code>(function->code()); 1558 } 1559 *count_ = *count_ + 1; 1560 } 1561 1562 private: 1563 Handle<SharedFunctionInfo>* sfis_; 1564 Handle<Code>* code_objects_; 1565 int* count_; 1566 }; 1567 1568 1569 static int EnumerateCompiledFunctions(Heap* heap, 1570 Handle<SharedFunctionInfo>* sfis, 1571 Handle<Code>* code_objects) { 1572 HeapIterator iterator(heap); 1573 DisallowHeapAllocation no_gc; 1574 int compiled_funcs_count = 0; 1575 1576 // Iterate the heap to find shared function info objects and record 1577 // the unoptimized code for them. 1578 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { 1579 if (!obj->IsSharedFunctionInfo()) continue; 1580 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj); 1581 if (sfi->is_compiled() 1582 && (!sfi->script()->IsScript() 1583 || Script::cast(sfi->script())->HasValidSource())) { 1584 if (sfis != NULL) { 1585 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi); 1586 } 1587 if (code_objects != NULL) { 1588 code_objects[compiled_funcs_count] = Handle<Code>(sfi->code()); 1589 } 1590 ++compiled_funcs_count; 1591 } 1592 } 1593 1594 // Iterate all optimized functions in all contexts. 1595 EnumerateOptimizedFunctionsVisitor visitor(sfis, 1596 code_objects, 1597 &compiled_funcs_count); 1598 Deoptimizer::VisitAllOptimizedFunctions(heap->isolate(), &visitor); 1599 1600 return compiled_funcs_count; 1601 } 1602 1603 1604 void Logger::LogCodeObject(Object* object) { 1605 Code* code_object = Code::cast(object); 1606 LogEventsAndTags tag = Logger::STUB_TAG; 1607 const char* description = "Unknown code from the snapshot"; 1608 switch (code_object->kind()) { 1609 case Code::FUNCTION: 1610 case Code::OPTIMIZED_FUNCTION: 1611 return; // We log this later using LogCompiledFunctions. 1612 case Code::BINARY_OP_IC: 1613 case Code::COMPARE_IC: // fall through 1614 case Code::COMPARE_NIL_IC: // fall through 1615 case Code::TO_BOOLEAN_IC: // fall through 1616 case Code::STUB: 1617 description = CodeStub::MajorName(CodeStub::GetMajorKey(code_object)); 1618 if (description == NULL) 1619 description = "A stub from the snapshot"; 1620 tag = Logger::STUB_TAG; 1621 break; 1622 case Code::REGEXP: 1623 description = "Regular expression code"; 1624 tag = Logger::REG_EXP_TAG; 1625 break; 1626 case Code::BUILTIN: 1627 description = isolate_->builtins()->name(code_object->builtin_index()); 1628 tag = Logger::BUILTIN_TAG; 1629 break; 1630 case Code::HANDLER: 1631 description = "An IC handler from the snapshot"; 1632 tag = Logger::HANDLER_TAG; 1633 break; 1634 case Code::KEYED_LOAD_IC: 1635 description = "A keyed load IC from the snapshot"; 1636 tag = Logger::KEYED_LOAD_IC_TAG; 1637 break; 1638 case Code::LOAD_IC: 1639 description = "A load IC from the snapshot"; 1640 tag = Logger::LOAD_IC_TAG; 1641 break; 1642 case Code::CALL_IC: 1643 description = "A call IC from the snapshot"; 1644 tag = Logger::CALL_IC_TAG; 1645 break; 1646 case Code::STORE_IC: 1647 description = "A store IC from the snapshot"; 1648 tag = Logger::STORE_IC_TAG; 1649 break; 1650 case Code::KEYED_STORE_IC: 1651 description = "A keyed store IC from the snapshot"; 1652 tag = Logger::KEYED_STORE_IC_TAG; 1653 break; 1654 case Code::WASM_FUNCTION: 1655 description = "A wasm function"; 1656 tag = Logger::STUB_TAG; 1657 break; 1658 case Code::NUMBER_OF_KINDS: 1659 break; 1660 } 1661 PROFILE(isolate_, CodeCreateEvent(tag, code_object, description)); 1662 } 1663 1664 1665 void Logger::LogCodeObjects() { 1666 Heap* heap = isolate_->heap(); 1667 heap->CollectAllGarbage(Heap::kMakeHeapIterableMask, 1668 "Logger::LogCodeObjects"); 1669 HeapIterator iterator(heap); 1670 DisallowHeapAllocation no_gc; 1671 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { 1672 if (obj->IsCode()) LogCodeObject(obj); 1673 } 1674 } 1675 1676 1677 void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared, 1678 Handle<Code> code) { 1679 Handle<String> func_name(shared->DebugName()); 1680 if (shared->script()->IsScript()) { 1681 Handle<Script> script(Script::cast(shared->script())); 1682 int line_num = Script::GetLineNumber(script, shared->start_position()) + 1; 1683 int column_num = 1684 Script::GetColumnNumber(script, shared->start_position()) + 1; 1685 if (script->name()->IsString()) { 1686 Handle<String> script_name(String::cast(script->name())); 1687 if (line_num > 0) { 1688 PROFILE(isolate_, 1689 CodeCreateEvent( 1690 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script), 1691 *code, *shared, NULL, 1692 *script_name, line_num, column_num)); 1693 } else { 1694 // Can't distinguish eval and script here, so always use Script. 1695 PROFILE(isolate_, 1696 CodeCreateEvent( 1697 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script), 1698 *code, *shared, NULL, *script_name)); 1699 } 1700 } else { 1701 PROFILE(isolate_, 1702 CodeCreateEvent( 1703 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script), 1704 *code, *shared, NULL, 1705 isolate_->heap()->empty_string(), line_num, column_num)); 1706 } 1707 } else if (shared->IsApiFunction()) { 1708 // API function. 1709 FunctionTemplateInfo* fun_data = shared->get_api_func_data(); 1710 Object* raw_call_data = fun_data->call_code(); 1711 if (!raw_call_data->IsUndefined()) { 1712 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data); 1713 Object* callback_obj = call_data->callback(); 1714 Address entry_point = v8::ToCData<Address>(callback_obj); 1715 PROFILE(isolate_, CallbackEvent(*func_name, entry_point)); 1716 } 1717 } else { 1718 PROFILE(isolate_, 1719 CodeCreateEvent( 1720 Logger::LAZY_COMPILE_TAG, *code, *shared, NULL, *func_name)); 1721 } 1722 } 1723 1724 1725 void Logger::LogCompiledFunctions() { 1726 Heap* heap = isolate_->heap(); 1727 heap->CollectAllGarbage(Heap::kMakeHeapIterableMask, 1728 "Logger::LogCompiledFunctions"); 1729 HandleScope scope(isolate_); 1730 const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL); 1731 ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count); 1732 ScopedVector< Handle<Code> > code_objects(compiled_funcs_count); 1733 EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start()); 1734 1735 // During iteration, there can be heap allocation due to 1736 // GetScriptLineNumber call. 1737 for (int i = 0; i < compiled_funcs_count; ++i) { 1738 if (code_objects[i].is_identical_to(isolate_->builtins()->CompileLazy())) 1739 continue; 1740 LogExistingFunction(sfis[i], code_objects[i]); 1741 } 1742 } 1743 1744 1745 void Logger::LogAccessorCallbacks() { 1746 Heap* heap = isolate_->heap(); 1747 heap->CollectAllGarbage(Heap::kMakeHeapIterableMask, 1748 "Logger::LogAccessorCallbacks"); 1749 HeapIterator iterator(heap); 1750 DisallowHeapAllocation no_gc; 1751 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { 1752 if (!obj->IsExecutableAccessorInfo()) continue; 1753 ExecutableAccessorInfo* ai = ExecutableAccessorInfo::cast(obj); 1754 if (!ai->name()->IsName()) continue; 1755 Address getter_entry = v8::ToCData<Address>(ai->getter()); 1756 Name* name = Name::cast(ai->name()); 1757 if (getter_entry != 0) { 1758 PROFILE(isolate_, GetterCallbackEvent(name, getter_entry)); 1759 } 1760 Address setter_entry = v8::ToCData<Address>(ai->setter()); 1761 if (setter_entry != 0) { 1762 PROFILE(isolate_, SetterCallbackEvent(name, setter_entry)); 1763 } 1764 } 1765 } 1766 1767 1768 static void AddIsolateIdIfNeeded(std::ostream& os, // NOLINT 1769 Isolate* isolate) { 1770 if (FLAG_logfile_per_isolate) os << "isolate-" << isolate << "-"; 1771 } 1772 1773 1774 static void PrepareLogFileName(std::ostream& os, // NOLINT 1775 Isolate* isolate, const char* file_name) { 1776 int dir_separator_count = 0; 1777 for (const char* p = file_name; *p; p++) { 1778 if (base::OS::isDirectorySeparator(*p)) dir_separator_count++; 1779 } 1780 1781 for (const char* p = file_name; *p; p++) { 1782 if (dir_separator_count == 0) { 1783 AddIsolateIdIfNeeded(os, isolate); 1784 dir_separator_count--; 1785 } 1786 if (*p == '%') { 1787 p++; 1788 switch (*p) { 1789 case '\0': 1790 // If there's a % at the end of the string we back up 1791 // one character so we can escape the loop properly. 1792 p--; 1793 break; 1794 case 'p': 1795 os << base::OS::GetCurrentProcessId(); 1796 break; 1797 case 't': 1798 // %t expands to the current time in milliseconds. 1799 os << static_cast<int64_t>(base::OS::TimeCurrentMillis()); 1800 break; 1801 case '%': 1802 // %% expands (contracts really) to %. 1803 os << '%'; 1804 break; 1805 default: 1806 // All other %'s expand to themselves. 1807 os << '%' << *p; 1808 break; 1809 } 1810 } else { 1811 if (base::OS::isDirectorySeparator(*p)) dir_separator_count--; 1812 os << *p; 1813 } 1814 } 1815 } 1816 1817 1818 bool Logger::SetUp(Isolate* isolate) { 1819 // Tests and EnsureInitialize() can call this twice in a row. It's harmless. 1820 if (is_initialized_) return true; 1821 is_initialized_ = true; 1822 1823 // --ll-prof implies --log-code and --log-snapshot-positions. 1824 if (FLAG_ll_prof) { 1825 FLAG_log_snapshot_positions = true; 1826 } 1827 1828 std::ostringstream log_file_name; 1829 PrepareLogFileName(log_file_name, isolate, FLAG_logfile); 1830 log_->Initialize(log_file_name.str().c_str()); 1831 1832 1833 if (FLAG_perf_basic_prof) { 1834 perf_basic_logger_ = new PerfBasicLogger(); 1835 addCodeEventListener(perf_basic_logger_); 1836 } 1837 1838 if (FLAG_ll_prof) { 1839 ll_logger_ = new LowLevelLogger(log_file_name.str().c_str()); 1840 addCodeEventListener(ll_logger_); 1841 } 1842 1843 ticker_ = new Ticker(isolate, kSamplingIntervalMs); 1844 1845 if (Log::InitLogAtStart()) { 1846 is_logging_ = true; 1847 } 1848 1849 if (FLAG_log_internal_timer_events || FLAG_prof_cpp) timer_.Start(); 1850 1851 if (FLAG_prof_cpp) { 1852 profiler_ = new Profiler(isolate); 1853 is_logging_ = true; 1854 profiler_->Engage(); 1855 } 1856 1857 return true; 1858 } 1859 1860 1861 void Logger::SetCodeEventHandler(uint32_t options, 1862 JitCodeEventHandler event_handler) { 1863 if (jit_logger_) { 1864 removeCodeEventListener(jit_logger_); 1865 delete jit_logger_; 1866 jit_logger_ = NULL; 1867 } 1868 1869 if (event_handler) { 1870 jit_logger_ = new JitLogger(event_handler); 1871 addCodeEventListener(jit_logger_); 1872 if (options & kJitCodeEventEnumExisting) { 1873 HandleScope scope(isolate_); 1874 LogCodeObjects(); 1875 LogCompiledFunctions(); 1876 } 1877 } 1878 } 1879 1880 1881 Sampler* Logger::sampler() { 1882 return ticker_; 1883 } 1884 1885 1886 FILE* Logger::TearDown() { 1887 if (!is_initialized_) return NULL; 1888 is_initialized_ = false; 1889 1890 // Stop the profiler before closing the file. 1891 if (profiler_ != NULL) { 1892 profiler_->Disengage(); 1893 delete profiler_; 1894 profiler_ = NULL; 1895 } 1896 1897 delete ticker_; 1898 ticker_ = NULL; 1899 1900 if (perf_basic_logger_) { 1901 removeCodeEventListener(perf_basic_logger_); 1902 delete perf_basic_logger_; 1903 perf_basic_logger_ = NULL; 1904 } 1905 1906 if (ll_logger_) { 1907 removeCodeEventListener(ll_logger_); 1908 delete ll_logger_; 1909 ll_logger_ = NULL; 1910 } 1911 1912 if (jit_logger_) { 1913 removeCodeEventListener(jit_logger_); 1914 delete jit_logger_; 1915 jit_logger_ = NULL; 1916 } 1917 1918 return log_->Close(); 1919 } 1920 1921 } // namespace internal 1922 } // namespace v8 1923