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