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