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