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