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