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