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
33namespace v8 {
34namespace internal {
35
36#define DECLARE_EVENT(ignore1, name) name,
37static const char* kLogEventsNames[CodeEventListener::NUMBER_OF_LOG_EVENTS] = {
38    LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)};
39#undef DECLARE_EVENT
40
41static 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
55class 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
153CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { }
154
155CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }
156
157void 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
164void 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
171void 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
180void 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
200void 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
207void 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
216class 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
236const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
237// Extra space for the PID in the filename
238const int PerfBasicLogger::kFilenameBufferPadding = 16;
239
240PerfBasicLogger::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
257PerfBasicLogger::~PerfBasicLogger() {
258  fclose(perf_output_handle_);
259  perf_output_handle_ = NULL;
260}
261
262void 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
285class 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
337const char LowLevelLogger::kLogExt[] = ".ll";
338
339LowLevelLogger::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
354LowLevelLogger::~LowLevelLogger() {
355  fclose(ll_output_handle_);
356  ll_output_handle_ = NULL;
357}
358
359
360void 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
385void 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
398void 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
407void 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
414void LowLevelLogger::CodeMovingGCEvent() {
415  const char tag = kCodeMovingGCTag;
416
417  LogWriteBytes(&tag, sizeof(tag));
418}
419
420class 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
443JitLogger::JitLogger(JitCodeEventHandler code_event_handler)
444    : code_event_handler_(code_event_handler) {
445}
446
447void 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
465void 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
482void 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
499void* 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
508void 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.
523class 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//
550class 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//
617class 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//
661Profiler::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
674void 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
698void 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
718void 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
732Logger::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
746Logger::~Logger() {
747  delete log_;
748}
749
750void Logger::addCodeEventListener(CodeEventListener* listener) {
751  bool result = isolate_->code_event_dispatcher()->AddListener(listener);
752  USE(result);
753  DCHECK(result);
754}
755
756void Logger::removeCodeEventListener(CodeEventListener* listener) {
757  isolate_->code_event_dispatcher()->RemoveListener(listener);
758}
759
760void 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
768void Logger::StringEvent(const char* name, const char* value) {
769  if (FLAG_log) UncheckedStringEvent(name, value);
770}
771
772
773void 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
781void Logger::IntEvent(const char* name, int value) {
782  if (FLAG_log) UncheckedIntEvent(name, value);
783}
784
785
786void Logger::IntPtrTEvent(const char* name, intptr_t value) {
787  if (FLAG_log) UncheckedIntPtrTEvent(name, value);
788}
789
790
791void 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
799void 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
807void 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.
818void 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
829void Logger::ApiSecurityCheck() {
830  if (!log_->IsEnabled() || !FLAG_log_api) return;
831  ApiEvent("api,check-security");
832}
833
834void 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
846void 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
855void 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
865void 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
877void 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
884void 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);
894TIMER_EVENTS_LIST(V)
895#undef V
896
897void 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
925void 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
936void 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
945void Logger::ApiEntryCall(const char* name) {
946  if (!log_->IsEnabled() || !FLAG_log_api) return;
947  ApiEvent("api,%s", name);
948}
949
950
951void 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
959void 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
967void 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
995void Logger::CallbackEvent(Name* name, Address entry_point) {
996  CallbackEventInternal("", name, entry_point);
997}
998
999
1000void Logger::GetterCallbackEvent(Name* name, Address entry_point) {
1001  CallbackEventInternal("get ", name, entry_point);
1002}
1003
1004
1005void Logger::SetterCallbackEvent(Name* name, Address entry_point) {
1006  CallbackEventInternal("set ", name, entry_point);
1007}
1008
1009static 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
1020void 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
1030void 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
1046void 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.
1075void 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
1098void 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
1108void 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
1122void Logger::CodeMovingGCEvent() {
1123  if (!is_logging_code_events()) return;
1124  if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1125  base::OS::SignalCodeMovingGC();
1126}
1127
1128void 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
1139void Logger::CodeMoveEvent(AbstractCode* from, Address to) {
1140  if (!is_logging_code_events()) return;
1141  MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(), to);
1142}
1143
1144void 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
1164void 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
1174void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1175  if (!is_logging_code_events()) return;
1176  MoveEventInternal(CodeEventListener::SHARED_FUNC_MOVE_EVENT, from, to);
1177}
1178
1179void 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
1191void 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
1205void 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
1225void 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
1236void 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
1244void 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
1252void Logger::DebugTag(const char* call_site_tag) {
1253  if (!log_->IsEnabled() || !FLAG_log) return;
1254  Log::MessageBuilder msg(log_);
1255  msg.Append("debug-tag,%s", call_site_tag);
1256  msg.WriteToLogFile();
1257}
1258
1259
1260void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1261  if (!log_->IsEnabled() || !FLAG_log) return;
1262  StringBuilder s(parameter.length() + 1);
1263  for (int i = 0; i < parameter.length(); ++i) {
1264    s.AddCharacter(static_cast<char>(parameter[i]));
1265  }
1266  char* parameter_string = s.Finalize();
1267  Log::MessageBuilder msg(log_);
1268  msg.Append("debug-queue-event,%s,%15.3f,%s", event_type,
1269             base::OS::TimeCurrentMillis(), parameter_string);
1270  DeleteArray(parameter_string);
1271  msg.WriteToLogFile();
1272}
1273
1274void Logger::RuntimeCallTimerEvent() {
1275  RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats();
1276  RuntimeCallTimer* timer = stats->current_timer();
1277  if (timer == nullptr) return;
1278  RuntimeCallCounter* counter = timer->counter();
1279  if (counter == nullptr) return;
1280  Log::MessageBuilder msg(log_);
1281  msg.Append("active-runtime-timer,");
1282  msg.AppendDoubleQuotedString(counter->name);
1283  msg.WriteToLogFile();
1284}
1285
1286void Logger::TickEvent(v8::TickSample* sample, bool overflow) {
1287  if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
1288  if (V8_UNLIKELY(FLAG_runtime_stats ==
1289                  v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE)) {
1290    RuntimeCallTimerEvent();
1291  }
1292  Log::MessageBuilder msg(log_);
1293  msg.Append("%s,", kLogEventsNames[CodeEventListener::TICK_EVENT]);
1294  msg.AppendAddress(reinterpret_cast<Address>(sample->pc));
1295  msg.Append(",%d", static_cast<int>(timer_.Elapsed().InMicroseconds()));
1296  if (sample->has_external_callback) {
1297    msg.Append(",1,");
1298    msg.AppendAddress(
1299        reinterpret_cast<Address>(sample->external_callback_entry));
1300  } else {
1301    msg.Append(",0,");
1302    msg.AppendAddress(reinterpret_cast<Address>(sample->tos));
1303  }
1304  msg.Append(",%d", static_cast<int>(sample->state));
1305  if (overflow) {
1306    msg.Append(",overflow");
1307  }
1308  for (unsigned i = 0; i < sample->frames_count; ++i) {
1309    msg.Append(',');
1310    msg.AppendAddress(reinterpret_cast<Address>(sample->stack[i]));
1311  }
1312  msg.WriteToLogFile();
1313}
1314
1315
1316void Logger::StopProfiler() {
1317  if (!log_->IsEnabled()) return;
1318  if (profiler_ != NULL) {
1319    profiler_->pause();
1320    is_logging_ = false;
1321    removeCodeEventListener(this);
1322  }
1323}
1324
1325
1326// This function can be called when Log's mutex is acquired,
1327// either from main or Profiler's thread.
1328void Logger::LogFailure() {
1329  StopProfiler();
1330}
1331
1332
1333class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1334 public:
1335  EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1336                                     Handle<AbstractCode>* code_objects,
1337                                     int* count)
1338      : sfis_(sfis), code_objects_(code_objects), count_(count) {}
1339
1340  virtual void EnterContext(Context* context) {}
1341  virtual void LeaveContext(Context* context) {}
1342
1343  virtual void VisitFunction(JSFunction* function) {
1344    SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
1345    Object* maybe_script = sfi->script();
1346    if (maybe_script->IsScript()
1347        && !Script::cast(maybe_script)->HasValidSource()) return;
1348    if (sfis_ != NULL) {
1349      sfis_[*count_] = Handle<SharedFunctionInfo>(sfi);
1350    }
1351    if (code_objects_ != NULL) {
1352      DCHECK(function->abstract_code()->kind() ==
1353             AbstractCode::OPTIMIZED_FUNCTION);
1354      code_objects_[*count_] = Handle<AbstractCode>(function->abstract_code());
1355    }
1356    *count_ = *count_ + 1;
1357  }
1358
1359 private:
1360  Handle<SharedFunctionInfo>* sfis_;
1361  Handle<AbstractCode>* code_objects_;
1362  int* count_;
1363};
1364
1365static int EnumerateCompiledFunctions(Heap* heap,
1366                                      Handle<SharedFunctionInfo>* sfis,
1367                                      Handle<AbstractCode>* code_objects) {
1368  HeapIterator iterator(heap);
1369  DisallowHeapAllocation no_gc;
1370  int compiled_funcs_count = 0;
1371
1372  // Iterate the heap to find shared function info objects and record
1373  // the unoptimized code for them.
1374  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1375    if (!obj->IsSharedFunctionInfo()) continue;
1376    SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1377    if (sfi->is_compiled()
1378        && (!sfi->script()->IsScript()
1379            || Script::cast(sfi->script())->HasValidSource())) {
1380      if (sfis != NULL) {
1381        sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1382      }
1383      if (code_objects != NULL) {
1384        code_objects[compiled_funcs_count] =
1385            Handle<AbstractCode>(sfi->abstract_code());
1386      }
1387      ++compiled_funcs_count;
1388    }
1389  }
1390
1391  // Iterate all optimized functions in all contexts.
1392  EnumerateOptimizedFunctionsVisitor visitor(sfis,
1393                                             code_objects,
1394                                             &compiled_funcs_count);
1395  Deoptimizer::VisitAllOptimizedFunctions(heap->isolate(), &visitor);
1396
1397  return compiled_funcs_count;
1398}
1399
1400
1401void Logger::LogCodeObject(Object* object) {
1402  AbstractCode* code_object = AbstractCode::cast(object);
1403  CodeEventListener::LogEventsAndTags tag = CodeEventListener::STUB_TAG;
1404  const char* description = "Unknown code from the snapshot";
1405  switch (code_object->kind()) {
1406    case AbstractCode::FUNCTION:
1407    case AbstractCode::INTERPRETED_FUNCTION:
1408    case AbstractCode::OPTIMIZED_FUNCTION:
1409      return;  // We log this later using LogCompiledFunctions.
1410    case AbstractCode::BYTECODE_HANDLER:
1411      return;  // We log it later by walking the dispatch table.
1412    case AbstractCode::BINARY_OP_IC:    // fall through
1413    case AbstractCode::COMPARE_IC:      // fall through
1414    case AbstractCode::TO_BOOLEAN_IC:   // fall through
1415
1416    case AbstractCode::STUB:
1417      description =
1418          CodeStub::MajorName(CodeStub::GetMajorKey(code_object->GetCode()));
1419      if (description == NULL)
1420        description = "A stub from the snapshot";
1421      tag = CodeEventListener::STUB_TAG;
1422      break;
1423    case AbstractCode::REGEXP:
1424      description = "Regular expression code";
1425      tag = CodeEventListener::REG_EXP_TAG;
1426      break;
1427    case AbstractCode::BUILTIN:
1428      description =
1429          isolate_->builtins()->name(code_object->GetCode()->builtin_index());
1430      tag = CodeEventListener::BUILTIN_TAG;
1431      break;
1432    case AbstractCode::HANDLER:
1433      description = "An IC handler from the snapshot";
1434      tag = CodeEventListener::HANDLER_TAG;
1435      break;
1436    case AbstractCode::KEYED_LOAD_IC:
1437      description = "A keyed load IC from the snapshot";
1438      tag = CodeEventListener::KEYED_LOAD_IC_TAG;
1439      break;
1440    case AbstractCode::LOAD_IC:
1441      description = "A load IC from the snapshot";
1442      tag = CodeEventListener::LOAD_IC_TAG;
1443      break;
1444    case AbstractCode::LOAD_GLOBAL_IC:
1445      description = "A load global IC from the snapshot";
1446      tag = Logger::LOAD_GLOBAL_IC_TAG;
1447      break;
1448    case AbstractCode::CALL_IC:
1449      description = "A call IC from the snapshot";
1450      tag = CodeEventListener::CALL_IC_TAG;
1451      break;
1452    case AbstractCode::STORE_IC:
1453      description = "A store IC from the snapshot";
1454      tag = CodeEventListener::STORE_IC_TAG;
1455      break;
1456    case AbstractCode::KEYED_STORE_IC:
1457      description = "A keyed store IC from the snapshot";
1458      tag = CodeEventListener::KEYED_STORE_IC_TAG;
1459      break;
1460    case AbstractCode::WASM_FUNCTION:
1461      description = "A Wasm function";
1462      tag = CodeEventListener::STUB_TAG;
1463      break;
1464    case AbstractCode::JS_TO_WASM_FUNCTION:
1465      description = "A JavaScript to Wasm adapter";
1466      tag = CodeEventListener::STUB_TAG;
1467      break;
1468    case AbstractCode::WASM_TO_JS_FUNCTION:
1469      description = "A Wasm to JavaScript adapter";
1470      tag = CodeEventListener::STUB_TAG;
1471      break;
1472    case AbstractCode::NUMBER_OF_KINDS:
1473      UNIMPLEMENTED();
1474  }
1475  PROFILE(isolate_, CodeCreateEvent(tag, code_object, description));
1476}
1477
1478
1479void Logger::LogCodeObjects() {
1480  Heap* heap = isolate_->heap();
1481  HeapIterator iterator(heap);
1482  DisallowHeapAllocation no_gc;
1483  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1484    if (obj->IsCode()) LogCodeObject(obj);
1485    if (obj->IsBytecodeArray()) LogCodeObject(obj);
1486  }
1487}
1488
1489void Logger::LogBytecodeHandlers() {
1490  const interpreter::OperandScale kOperandScales[] = {
1491#define VALUE(Name, _) interpreter::OperandScale::k##Name,
1492      OPERAND_SCALE_LIST(VALUE)
1493#undef VALUE
1494  };
1495
1496  const int last_index = static_cast<int>(interpreter::Bytecode::kLast);
1497  interpreter::Interpreter* interpreter = isolate_->interpreter();
1498  for (auto operand_scale : kOperandScales) {
1499    for (int index = 0; index <= last_index; ++index) {
1500      interpreter::Bytecode bytecode = interpreter::Bytecodes::FromByte(index);
1501      if (interpreter::Bytecodes::BytecodeHasHandler(bytecode, operand_scale)) {
1502        Code* code = interpreter->GetBytecodeHandler(bytecode, operand_scale);
1503        std::string bytecode_name =
1504            interpreter::Bytecodes::ToString(bytecode, operand_scale);
1505        PROFILE(isolate_, CodeCreateEvent(
1506                              CodeEventListener::BYTECODE_HANDLER_TAG,
1507                              AbstractCode::cast(code), bytecode_name.c_str()));
1508      }
1509    }
1510  }
1511}
1512
1513void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
1514                                 Handle<AbstractCode> code) {
1515  Handle<String> func_name(shared->DebugName());
1516  if (shared->script()->IsScript()) {
1517    Handle<Script> script(Script::cast(shared->script()));
1518    int line_num = Script::GetLineNumber(script, shared->start_position()) + 1;
1519    int column_num =
1520        Script::GetColumnNumber(script, shared->start_position()) + 1;
1521    if (script->name()->IsString()) {
1522      Handle<String> script_name(String::cast(script->name()));
1523      if (line_num > 0) {
1524        PROFILE(isolate_,
1525                CodeCreateEvent(
1526                    Logger::ToNativeByScript(
1527                        CodeEventListener::LAZY_COMPILE_TAG, *script),
1528                    *code, *shared, *script_name, line_num, column_num));
1529      } else {
1530        // Can't distinguish eval and script here, so always use Script.
1531        PROFILE(isolate_,
1532                CodeCreateEvent(Logger::ToNativeByScript(
1533                                    CodeEventListener::SCRIPT_TAG, *script),
1534                                *code, *shared, *script_name));
1535      }
1536    } else {
1537      PROFILE(isolate_,
1538              CodeCreateEvent(Logger::ToNativeByScript(
1539                                  CodeEventListener::LAZY_COMPILE_TAG, *script),
1540                              *code, *shared, isolate_->heap()->empty_string(),
1541                              line_num, column_num));
1542    }
1543  } else if (shared->IsApiFunction()) {
1544    // API function.
1545    FunctionTemplateInfo* fun_data = shared->get_api_func_data();
1546    Object* raw_call_data = fun_data->call_code();
1547    if (!raw_call_data->IsUndefined(isolate_)) {
1548      CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1549      Object* callback_obj = call_data->callback();
1550      Address entry_point = v8::ToCData<Address>(callback_obj);
1551#if USES_FUNCTION_DESCRIPTORS
1552      entry_point = *FUNCTION_ENTRYPOINT_ADDRESS(entry_point);
1553#endif
1554      PROFILE(isolate_, CallbackEvent(*func_name, entry_point));
1555    }
1556  } else {
1557    PROFILE(isolate_, CodeCreateEvent(CodeEventListener::LAZY_COMPILE_TAG,
1558                                      *code, *shared, *func_name));
1559  }
1560}
1561
1562
1563void Logger::LogCompiledFunctions() {
1564  Heap* heap = isolate_->heap();
1565  HandleScope scope(isolate_);
1566  const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL);
1567  ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
1568  ScopedVector<Handle<AbstractCode> > code_objects(compiled_funcs_count);
1569  EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start());
1570
1571  // During iteration, there can be heap allocation due to
1572  // GetScriptLineNumber call.
1573  for (int i = 0; i < compiled_funcs_count; ++i) {
1574    if (code_objects[i].is_identical_to(isolate_->builtins()->CompileLazy()))
1575      continue;
1576    LogExistingFunction(sfis[i], code_objects[i]);
1577  }
1578}
1579
1580
1581void Logger::LogAccessorCallbacks() {
1582  Heap* heap = isolate_->heap();
1583  HeapIterator iterator(heap);
1584  DisallowHeapAllocation no_gc;
1585  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1586    if (!obj->IsAccessorInfo()) continue;
1587    AccessorInfo* ai = AccessorInfo::cast(obj);
1588    if (!ai->name()->IsName()) continue;
1589    Address getter_entry = v8::ToCData<Address>(ai->getter());
1590    Name* name = Name::cast(ai->name());
1591    if (getter_entry != 0) {
1592#if USES_FUNCTION_DESCRIPTORS
1593      getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(getter_entry);
1594#endif
1595      PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
1596    }
1597    Address setter_entry = v8::ToCData<Address>(ai->setter());
1598    if (setter_entry != 0) {
1599#if USES_FUNCTION_DESCRIPTORS
1600      setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(setter_entry);
1601#endif
1602      PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
1603    }
1604  }
1605}
1606
1607
1608static void AddIsolateIdIfNeeded(std::ostream& os,  // NOLINT
1609                                 Isolate* isolate) {
1610  if (FLAG_logfile_per_isolate) os << "isolate-" << isolate << "-";
1611}
1612
1613
1614static void PrepareLogFileName(std::ostream& os,  // NOLINT
1615                               Isolate* isolate, const char* file_name) {
1616  int dir_separator_count = 0;
1617  for (const char* p = file_name; *p; p++) {
1618    if (base::OS::isDirectorySeparator(*p)) dir_separator_count++;
1619  }
1620
1621  for (const char* p = file_name; *p; p++) {
1622    if (dir_separator_count == 0) {
1623      AddIsolateIdIfNeeded(os, isolate);
1624      dir_separator_count--;
1625    }
1626    if (*p == '%') {
1627      p++;
1628      switch (*p) {
1629        case '\0':
1630          // If there's a % at the end of the string we back up
1631          // one character so we can escape the loop properly.
1632          p--;
1633          break;
1634        case 'p':
1635          os << base::OS::GetCurrentProcessId();
1636          break;
1637        case 't':
1638          // %t expands to the current time in milliseconds.
1639          os << static_cast<int64_t>(base::OS::TimeCurrentMillis());
1640          break;
1641        case '%':
1642          // %% expands (contracts really) to %.
1643          os << '%';
1644          break;
1645        default:
1646          // All other %'s expand to themselves.
1647          os << '%' << *p;
1648          break;
1649      }
1650    } else {
1651      if (base::OS::isDirectorySeparator(*p)) dir_separator_count--;
1652      os << *p;
1653    }
1654  }
1655}
1656
1657
1658bool Logger::SetUp(Isolate* isolate) {
1659  // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
1660  if (is_initialized_) return true;
1661  is_initialized_ = true;
1662
1663  std::ostringstream log_file_name;
1664  PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
1665  log_->Initialize(log_file_name.str().c_str());
1666
1667  if (FLAG_perf_basic_prof) {
1668    perf_basic_logger_ = new PerfBasicLogger();
1669    addCodeEventListener(perf_basic_logger_);
1670  }
1671
1672  if (FLAG_perf_prof) {
1673    perf_jit_logger_ = new PerfJitLogger();
1674    addCodeEventListener(perf_jit_logger_);
1675  }
1676
1677  if (FLAG_ll_prof) {
1678    ll_logger_ = new LowLevelLogger(log_file_name.str().c_str());
1679    addCodeEventListener(ll_logger_);
1680  }
1681
1682  ticker_ = new Ticker(isolate, kSamplingIntervalMs);
1683
1684  if (Log::InitLogAtStart()) {
1685    is_logging_ = true;
1686  }
1687
1688  if (FLAG_log_internal_timer_events || FLAG_prof_cpp) timer_.Start();
1689
1690  if (FLAG_prof_cpp) {
1691    profiler_ = new Profiler(isolate);
1692    is_logging_ = true;
1693    profiler_->Engage();
1694  }
1695
1696  profiler_listener_.reset();
1697
1698  if (is_logging_) {
1699    addCodeEventListener(this);
1700  }
1701
1702  return true;
1703}
1704
1705
1706void Logger::SetCodeEventHandler(uint32_t options,
1707                                 JitCodeEventHandler event_handler) {
1708  if (jit_logger_) {
1709      removeCodeEventListener(jit_logger_);
1710      delete jit_logger_;
1711      jit_logger_ = NULL;
1712  }
1713
1714  if (event_handler) {
1715    jit_logger_ = new JitLogger(event_handler);
1716    addCodeEventListener(jit_logger_);
1717    if (options & kJitCodeEventEnumExisting) {
1718      HandleScope scope(isolate_);
1719      LogCodeObjects();
1720      LogCompiledFunctions();
1721    }
1722  }
1723}
1724
1725void Logger::SetUpProfilerListener() {
1726  if (!is_initialized_) return;
1727  if (profiler_listener_.get() == nullptr) {
1728    profiler_listener_.reset(new ProfilerListener(isolate_));
1729  }
1730  addCodeEventListener(profiler_listener_.get());
1731}
1732
1733void Logger::TearDownProfilerListener() {
1734  if (profiler_listener_->HasObservers()) return;
1735  removeCodeEventListener(profiler_listener_.get());
1736}
1737
1738sampler::Sampler* Logger::sampler() {
1739  return ticker_;
1740}
1741
1742
1743FILE* Logger::TearDown() {
1744  if (!is_initialized_) return NULL;
1745  is_initialized_ = false;
1746
1747  // Stop the profiler before closing the file.
1748  if (profiler_ != NULL) {
1749    profiler_->Disengage();
1750    delete profiler_;
1751    profiler_ = NULL;
1752  }
1753
1754  delete ticker_;
1755  ticker_ = NULL;
1756
1757  if (perf_basic_logger_) {
1758    removeCodeEventListener(perf_basic_logger_);
1759    delete perf_basic_logger_;
1760    perf_basic_logger_ = NULL;
1761  }
1762
1763  if (perf_jit_logger_) {
1764    removeCodeEventListener(perf_jit_logger_);
1765    delete perf_jit_logger_;
1766    perf_jit_logger_ = NULL;
1767  }
1768
1769  if (ll_logger_) {
1770    removeCodeEventListener(ll_logger_);
1771    delete ll_logger_;
1772    ll_logger_ = NULL;
1773  }
1774
1775  if (jit_logger_) {
1776    removeCodeEventListener(jit_logger_);
1777    delete jit_logger_;
1778    jit_logger_ = NULL;
1779  }
1780
1781  if (profiler_listener_.get() != nullptr) {
1782    removeCodeEventListener(profiler_listener_.get());
1783  }
1784
1785  return log_->Close();
1786}
1787
1788}  // namespace internal
1789}  // namespace v8
1790