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