log.cc 56.5 KB
Newer Older
danno@chromium.org's avatar
danno@chromium.org committed
1
// Copyright 2011 the V8 project authors. All rights reserved.
2 3
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
4

5 6 7 8
#include "src/log.h"

#include <cstdarg>
#include <sstream>
9

10
#include "src/bailout-reason.h"
11
#include "src/base/platform/platform.h"
12 13 14 15
#include "src/bootstrapper.h"
#include "src/code-stubs.h"
#include "src/deoptimizer.h"
#include "src/global-handles.h"
16
#include "src/log-inl.h"
17 18
#include "src/log-utils.h"
#include "src/macro-assembler.h"
19
#include "src/profiler/cpu-profiler.h"
20 21 22
#include "src/runtime-profiler.h"
#include "src/string-stream.h"
#include "src/vm-state-inl.h"
23

24 25
namespace v8 {
namespace internal {
26

27

28 29 30 31 32 33 34
#define DECLARE_EVENT(ignore1, name) name,
static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
  LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
};
#undef DECLARE_EVENT


35 36 37 38 39
#define CALL_LISTENERS(Call)                    \
for (int i = 0; i < listeners_.length(); ++i) { \
  listeners_[i]->Call;                          \
}

40 41 42 43 44 45 46 47
#define PROFILER_LOG(Call)                                \
  do {                                                    \
    CpuProfiler* cpu_profiler = isolate_->cpu_profiler(); \
    if (cpu_profiler->is_profiling()) {                   \
      cpu_profiler->Call;                                 \
    }                                                     \
  } while (false);

48
static const char* ComputeMarker(SharedFunctionInfo* shared, Code* code) {
49
  switch (code->kind()) {
50 51 52 53 54 55
    case Code::FUNCTION:
      return shared->optimization_disabled() ? "" : "~";
    case Code::OPTIMIZED_FUNCTION:
      return "*";
    default:
      return "";
56 57 58 59
  }
}


60
class CodeEventLogger::NameBuffer {
61
 public:
62
  NameBuffer() { Reset(); }
63

64 65 66
  void Reset() {
    utf8_pos_ = 0;
  }
67

68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83
  void Init(Logger::LogEventsAndTags tag) {
    Reset();
    AppendBytes(kLogEventsNames[tag]);
    AppendByte(':');
  }

  void AppendName(Name* name) {
    if (name->IsString()) {
      AppendString(String::cast(name));
    } else {
      Symbol* symbol = Symbol::cast(name);
      AppendBytes("symbol(");
      if (!symbol->name()->IsUndefined()) {
        AppendBytes("\"");
        AppendString(String::cast(symbol->name()));
        AppendBytes("\" ");
84
      }
85 86 87
      AppendBytes("hash ");
      AppendHex(symbol->Hash());
      AppendByte(')');
88
    }
89
  }
90

91 92 93 94 95 96 97 98 99 100 101 102 103 104
  void AppendString(String* str) {
    if (str == NULL) return;
    int uc16_length = Min(str->length(), kUtf16BufferSize);
    String::WriteToFlat(str, utf16_buffer, 0, uc16_length);
    int previous = unibrow::Utf16::kNoPreviousCharacter;
    for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
      uc16 c = utf16_buffer[i];
      if (c <= unibrow::Utf8::kMaxOneByteChar) {
        utf8_buffer_[utf8_pos_++] = static_cast<char>(c);
      } else {
        int char_length = unibrow::Utf8::Length(c, previous);
        if (utf8_pos_ + char_length > kUtf8BufferSize) break;
        unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous);
        utf8_pos_ += char_length;
105
      }
106
      previous = c;
107
    }
108
  }
109

110 111
  void AppendBytes(const char* bytes, int size) {
    size = Min(size, kUtf8BufferSize - utf8_pos_);
112
    MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
113 114
    utf8_pos_ += size;
  }
115

116 117 118
  void AppendBytes(const char* bytes) {
    AppendBytes(bytes, StrLength(bytes));
  }
119

120 121 122 123
  void AppendByte(char c) {
    if (utf8_pos_ >= kUtf8BufferSize) return;
    utf8_buffer_[utf8_pos_++] = c;
  }
124

125
  void AppendInt(int n) {
126 127 128
    int space = kUtf8BufferSize - utf8_pos_;
    if (space <= 0) return;
    Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
129
    int size = SNPrintF(buffer, "%d", n);
130 131
    if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
      utf8_pos_ += size;
132
    }
133
  }
134

135
  void AppendHex(uint32_t n) {
136 137 138
    int space = kUtf8BufferSize - utf8_pos_;
    if (space <= 0) return;
    Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
139
    int size = SNPrintF(buffer, "%x", n);
140 141
    if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
      utf8_pos_ += size;
142
    }
143
  }
144

145 146
  const char* get() { return utf8_buffer_; }
  int size() const { return utf8_pos_; }
147 148

 private:
149
  static const int kUtf8BufferSize = 512;
150
  static const int kUtf16BufferSize = kUtf8BufferSize;
151

152 153 154
  int utf8_pos_;
  char utf8_buffer_[kUtf8BufferSize];
  uc16 utf16_buffer[kUtf16BufferSize];
155 156 157
};


158 159 160 161 162
CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { }

CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }


163 164 165
void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
                                      Code* code,
                                      const char* comment) {
166 167 168
  name_buffer_->Init(tag);
  name_buffer_->AppendBytes(comment);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
169 170 171 172 173 174
}


void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
                                      Code* code,
                                      Name* name) {
175 176 177
  name_buffer_->Init(tag);
  name_buffer_->AppendName(name);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
178 179 180 181
}


void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
182 183 184 185 186
                                      Code* code,
                                      SharedFunctionInfo* shared,
                                      CompilationInfo* info,
                                      Name* name) {
  name_buffer_->Init(tag);
187
  name_buffer_->AppendBytes(ComputeMarker(shared, code));
188 189
  name_buffer_->AppendName(name);
  LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
190 191 192 193
}


void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
194 195 196
                                      Code* code,
                                      SharedFunctionInfo* shared,
                                      CompilationInfo* info,
197
                                      Name* source, int line, int column) {
198
  name_buffer_->Init(tag);
199
  name_buffer_->AppendBytes(ComputeMarker(shared, code));
200 201
  name_buffer_->AppendString(shared->DebugName());
  name_buffer_->AppendByte(' ');
202
  if (source->IsString()) {
203
    name_buffer_->AppendString(String::cast(source));
204
  } else {
205 206 207
    name_buffer_->AppendBytes("symbol(hash ");
    name_buffer_->AppendHex(Name::cast(source)->Hash());
    name_buffer_->AppendByte(')');
208
  }
209 210 211
  name_buffer_->AppendByte(':');
  name_buffer_->AppendInt(line);
  LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
212 213 214 215 216 217
}


void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
                                      Code* code,
                                      int args_count) {
218 219 220
  name_buffer_->Init(tag);
  name_buffer_->AppendInt(args_count);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
221 222 223 224
}


void CodeEventLogger::RegExpCodeCreateEvent(Code* code, String* source) {
225 226 227
  name_buffer_->Init(Logger::REG_EXP_TAG);
  name_buffer_->AppendString(source);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
228 229 230
}


231 232 233 234 235 236 237
// Linux perf tool logging support
class PerfBasicLogger : public CodeEventLogger {
 public:
  PerfBasicLogger();
  virtual ~PerfBasicLogger();

  virtual void CodeMoveEvent(Address from, Address to) { }
238
  virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { }
239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266
  virtual void CodeDeleteEvent(Address from) { }

 private:
  virtual void LogRecordedBuffer(Code* code,
                                 SharedFunctionInfo* shared,
                                 const char* name,
                                 int length);

  // Extension added to V8 log file name to get the low-level log name.
  static const char kFilenameFormatString[];
  static const int kFilenameBufferPadding;

  // File buffer size of the low-level log. We don't use the default to
  // minimize the associated overhead.
  static const int kLogBufferSize = 2 * MB;

  FILE* perf_output_handle_;
};

const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
// Extra space for the PID in the filename
const int PerfBasicLogger::kFilenameBufferPadding = 16;

PerfBasicLogger::PerfBasicLogger()
    : perf_output_handle_(NULL) {
  // Open the perf JIT dump file.
  int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
  ScopedVector<char> perf_dump_name(bufferSize);
267
  int size = SNPrintF(
268 269
      perf_dump_name,
      kFilenameFormatString,
270
      base::OS::GetCurrentProcessId());
271
  CHECK_NE(size, -1);
272 273
  perf_output_handle_ =
      base::OS::FOpen(perf_dump_name.start(), base::OS::LogFileOpenMode);
274
  CHECK_NOT_NULL(perf_output_handle_);
275 276 277 278 279 280 281 282 283 284 285 286 287 288
  setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);
}


PerfBasicLogger::~PerfBasicLogger() {
  fclose(perf_output_handle_);
  perf_output_handle_ = NULL;
}


void PerfBasicLogger::LogRecordedBuffer(Code* code,
                                       SharedFunctionInfo*,
                                       const char* name,
                                       int length) {
289
  DCHECK(code->instruction_start() == code->address() + Code::kHeaderSize);
290

291 292 293 294 295 296
  if (FLAG_perf_basic_prof_only_functions &&
      (code->kind() != Code::FUNCTION &&
       code->kind() != Code::OPTIMIZED_FUNCTION)) {
    return;
  }

297 298 299
  base::OS::FPrint(perf_output_handle_, "%llx %x %.*s\n",
                   reinterpret_cast<uint64_t>(code->instruction_start()),
                   code->instruction_size(), length, name);
300 301 302
}


303
// Low-level logging support.
304 305
#define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;

306
class LowLevelLogger : public CodeEventLogger {
307 308
 public:
  explicit LowLevelLogger(const char* file_name);
309
  virtual ~LowLevelLogger();
310

311
  virtual void CodeMoveEvent(Address from, Address to);
312
  virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { }
313 314 315
  virtual void CodeDeleteEvent(Address from);
  virtual void SnapshotPositionEvent(Address addr, int pos);
  virtual void CodeMovingGCEvent();
316 317

 private:
318 319
  virtual void LogRecordedBuffer(Code* code,
                                 SharedFunctionInfo* shared,
320 321
                                 const char* name,
                                 int length);
322

323
  // Low-level profiling event structures.
324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380
  struct CodeCreateStruct {
    static const char kTag = 'C';

    int32_t name_size;
    Address code_address;
    int32_t code_size;
  };


  struct CodeMoveStruct {
    static const char kTag = 'M';

    Address from_address;
    Address to_address;
  };


  struct CodeDeleteStruct {
    static const char kTag = 'D';

    Address address;
  };


  struct SnapshotPositionStruct {
    static const char kTag = 'P';

    Address address;
    int32_t position;
  };


  static const char kCodeMovingGCTag = 'G';


  // Extension added to V8 log file name to get the low-level log name.
  static const char kLogExt[];

  // File buffer size of the low-level log. We don't use the default to
  // minimize the associated overhead.
  static const int kLogBufferSize = 2 * MB;

  void LogCodeInfo();
  void LogWriteBytes(const char* bytes, int size);

  template <typename T>
  void LogWriteStruct(const T& s) {
    char tag = T::kTag;
    LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag));
    LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
  }

  FILE* ll_output_handle_;
};

const char LowLevelLogger::kLogExt[] = ".ll";

381 382 383 384 385
LowLevelLogger::LowLevelLogger(const char* name)
    : ll_output_handle_(NULL) {
  // Open the low-level log file.
  size_t len = strlen(name);
  ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt)));
386 387
  MemCopy(ll_name.start(), name, len);
  MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
388 389
  ll_output_handle_ =
      base::OS::FOpen(ll_name.start(), base::OS::LogFileOpenMode);
390 391 392 393 394 395 396 397 398 399 400 401 402 403 404
  setvbuf(ll_output_handle_, NULL, _IOFBF, kLogBufferSize);

  LogCodeInfo();
}


LowLevelLogger::~LowLevelLogger() {
  fclose(ll_output_handle_);
  ll_output_handle_ = NULL;
}


void LowLevelLogger::LogCodeInfo() {
#if V8_TARGET_ARCH_IA32
  const char arch[] = "ia32";
405
#elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_64_BIT
406
  const char arch[] = "x64";
407 408
#elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_32_BIT
  const char arch[] = "x32";
409 410
#elif V8_TARGET_ARCH_ARM
  const char arch[] = "arm";
411 412
#elif V8_TARGET_ARCH_PPC
  const char arch[] = "ppc";
413 414
#elif V8_TARGET_ARCH_MIPS
  const char arch[] = "mips";
danno@chromium.org's avatar
danno@chromium.org committed
415 416
#elif V8_TARGET_ARCH_X87
  const char arch[] = "x87";
417 418
#elif V8_TARGET_ARCH_ARM64
  const char arch[] = "arm64";
419 420 421 422 423 424 425 426 427
#else
  const char arch[] = "unknown";
#endif
  LogWriteBytes(arch, sizeof(arch));
}


void LowLevelLogger::LogRecordedBuffer(Code* code,
                                       SharedFunctionInfo*,
428 429
                                       const char* name,
                                       int length) {
430
  CodeCreateStruct event;
431
  event.name_size = length;
432
  event.code_address = code->instruction_start();
433
  DCHECK(event.code_address == code->address() + Code::kHeaderSize);
434 435
  event.code_size = code->instruction_size();
  LogWriteStruct(event);
436
  LogWriteBytes(name, length);
437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467
  LogWriteBytes(
      reinterpret_cast<const char*>(code->instruction_start()),
      code->instruction_size());
}


void LowLevelLogger::CodeMoveEvent(Address from, Address to) {
  CodeMoveStruct event;
  event.from_address = from + Code::kHeaderSize;
  event.to_address = to + Code::kHeaderSize;
  LogWriteStruct(event);
}


void LowLevelLogger::CodeDeleteEvent(Address from) {
  CodeDeleteStruct event;
  event.address = from + Code::kHeaderSize;
  LogWriteStruct(event);
}


void LowLevelLogger::SnapshotPositionEvent(Address addr, int pos) {
  SnapshotPositionStruct event;
  event.address = addr + Code::kHeaderSize;
  event.position = pos;
  LogWriteStruct(event);
}


void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
  size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
468
  DCHECK(static_cast<size_t>(size) == rv);
469 470 471 472 473 474 475 476 477 478 479
  USE(rv);
}


void LowLevelLogger::CodeMovingGCEvent() {
  const char tag = kCodeMovingGCTag;

  LogWriteBytes(&tag, sizeof(tag));
}


480
#define JIT_LOG(Call) if (jit_logger_) jit_logger_->Call;
481 482


483 484 485 486
class JitLogger : public CodeEventLogger {
 public:
  explicit JitLogger(JitCodeEventHandler code_event_handler);

487
  virtual void CodeMoveEvent(Address from, Address to);
488
  virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) { }
489 490
  virtual void CodeDeleteEvent(Address from);
  virtual void AddCodeLinePosInfoEvent(
491 492 493 494
      void* jit_handler_data,
      int pc_offset,
      int position,
      JitCodeEvent::PositionType position_type);
495

496 497 498 499 500 501
  void* StartCodePosInfoEvent();
  void EndCodePosInfoEvent(Code* code, void* jit_handler_data);

 private:
  virtual void LogRecordedBuffer(Code* code,
                                 SharedFunctionInfo* shared,
502 503
                                 const char* name,
                                 int length);
504 505

  JitCodeEventHandler code_event_handler_;
506
  base::Mutex logger_mutex_;
507 508 509 510 511 512 513 514 515 516
};


JitLogger::JitLogger(JitCodeEventHandler code_event_handler)
    : code_event_handler_(code_event_handler) {
}


void JitLogger::LogRecordedBuffer(Code* code,
                                  SharedFunctionInfo* shared,
517 518
                                  const char* name,
                                  int length) {
519 520 521 522 523
  JitCodeEvent event;
  memset(&event, 0, sizeof(event));
  event.type = JitCodeEvent::CODE_ADDED;
  event.code_start = code->instruction_start();
  event.code_len = code->instruction_size();
524
  Handle<SharedFunctionInfo> shared_function_handle;
525
  if (shared && shared->script()->IsScript()) {
526
    shared_function_handle = Handle<SharedFunctionInfo>(shared);
527
  }
528
  event.script = ToApiHandle<v8::UnboundScript>(shared_function_handle);
529 530
  event.name.str = name;
  event.name.len = length;
531 532 533 534
  code_event_handler_(&event);
}


535
void JitLogger::CodeMoveEvent(Address from, Address to) {
536
  base::LockGuard<base::Mutex> guard(&logger_mutex_);
537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561 562 563 564 565 566 567 568 569 570 571 572 573 574 575 576 577 578 579 580 581 582 583 584 585 586 587 588 589 590 591 592 593 594 595 596 597 598 599 600 601 602 603 604
  Code* from_code = Code::cast(HeapObject::FromAddress(from));

  JitCodeEvent event;
  event.type = JitCodeEvent::CODE_MOVED;
  event.code_start = from_code->instruction_start();
  event.code_len = from_code->instruction_size();

  // Calculate the header size.
  const size_t header_size =
      from_code->instruction_start() - reinterpret_cast<byte*>(from_code);

  // Calculate the new start address of the instructions.
  event.new_code_start =
      reinterpret_cast<byte*>(HeapObject::FromAddress(to)) + header_size;

  code_event_handler_(&event);
}


void JitLogger::CodeDeleteEvent(Address from) {
  Code* from_code = Code::cast(HeapObject::FromAddress(from));

  JitCodeEvent event;
  event.type = JitCodeEvent::CODE_REMOVED;
  event.code_start = from_code->instruction_start();
  event.code_len = from_code->instruction_size();

  code_event_handler_(&event);
}

void JitLogger::AddCodeLinePosInfoEvent(
    void* jit_handler_data,
    int pc_offset,
    int position,
    JitCodeEvent::PositionType position_type) {
  JitCodeEvent event;
  memset(&event, 0, sizeof(event));
  event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO;
  event.user_data = jit_handler_data;
  event.line_info.offset = pc_offset;
  event.line_info.pos = position;
  event.line_info.position_type = position_type;

  code_event_handler_(&event);
}


void* JitLogger::StartCodePosInfoEvent() {
  JitCodeEvent event;
  memset(&event, 0, sizeof(event));
  event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING;

  code_event_handler_(&event);
  return event.user_data;
}


void JitLogger::EndCodePosInfoEvent(Code* code, void* jit_handler_data) {
  JitCodeEvent event;
  memset(&event, 0, sizeof(event));
  event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING;
  event.code_start = code->instruction_start();
  event.user_data = jit_handler_data;

  code_event_handler_(&event);
}


605 606 607 608 609
// The Profiler samples pc and sp values for the main thread.
// Each sample is appended to a circular buffer.
// An independent thread removes data and writes it to the log.
// This design minimizes the time spent in the sampler.
//
610
class Profiler: public base::Thread {
611
 public:
612
  explicit Profiler(Isolate* isolate);
613 614 615 616 617
  void Engage();
  void Disengage();

  // Inserts collected profiling data into buffer.
  void Insert(TickSample* sample) {
618 619 620
    if (paused_)
      return;

621
    if (Succ(head_) == static_cast<int>(base::NoBarrier_Load(&tail_))) {
622 623 624 625
      overflow_ = true;
    } else {
      buffer_[head_] = *sample;
      head_ = Succ(head_);
626
      buffer_semaphore_.Signal();  // Tell we have an element.
627 628 629
    }
  }

630 631 632 633 634 635 636
  virtual void Run();

  // Pause and Resume TickSample data collection.
  void pause() { paused_ = true; }
  void resume() { paused_ = false; }

 private:
637 638
  // Waits for a signal and removes profiling data.
  bool Remove(TickSample* sample) {
639
    buffer_semaphore_.Wait();  // Wait for an element.
640
    *sample = buffer_[base::NoBarrier_Load(&tail_)];
641
    bool result = overflow_;
642 643
    base::NoBarrier_Store(&tail_, static_cast<base::Atomic32>(
                                      Succ(base::NoBarrier_Load(&tail_))));
644 645 646 647 648 649 650
    overflow_ = false;
    return result;
  }

  // Returns the next index in the cyclic buffer.
  int Succ(int index) { return (index + 1) % kBufferSize; }

651
  Isolate* isolate_;
652 653 654 655 656
  // Cyclic buffer for communicating profiling samples
  // between the signal handler and the worker thread.
  static const int kBufferSize = 128;
  TickSample buffer_[kBufferSize];  // Buffer storage.
  int head_;  // Index to the buffer head.
657
  base::Atomic32 tail_;             // Index to the buffer tail.
658
  bool overflow_;  // Tell whether a buffer overflow has occurred.
659
  // Sempahore used for buffer synchronization.
660
  base::Semaphore buffer_semaphore_;
661

662 663 664
  // Tells whether profiler is engaged, that is, processing thread is stated.
  bool engaged_;

665
  // Tells whether worker thread should continue running.
666
  base::Atomic32 running_;
667 668

  // Tells whether we are currently recording tick samples.
669
  bool paused_;
670 671 672 673 674 675 676
};


//
// Ticker used to provide ticks to the profiler and the sliding state
// window.
//
677
class Ticker: public Sampler {
678
 public:
679
  Ticker(Isolate* isolate, int interval):
680
      Sampler(isolate, interval),
681
      profiler_(NULL) {}
682 683 684

  ~Ticker() { if (IsActive()) Stop(); }

685
  virtual void Tick(TickSample* sample) {
686 687 688 689
    if (profiler_) profiler_->Insert(sample);
  }

  void SetProfiler(Profiler* profiler) {
690
    DCHECK(profiler_ == NULL);
691
    profiler_ = profiler;
692
    IncreaseProfilingDepth();
693
    if (!IsActive()) Start();
694 695 696 697
  }

  void ClearProfiler() {
    profiler_ = NULL;
698
    if (IsActive()) Stop();
699
    DecreaseProfilingDepth();
700 701 702 703 704 705 706 707 708 709
  }

 private:
  Profiler* profiler_;
};


//
// Profiler implementation.
//
710
Profiler::Profiler(Isolate* isolate)
711
    : base::Thread(Options("v8:Profiler")),
712
      isolate_(isolate),
713
      head_(0),
714
      overflow_(false),
715
      buffer_semaphore_(0),
716
      engaged_(false),
717 718
      paused_(false) {
  base::NoBarrier_Store(&tail_, 0);
719
  base::NoBarrier_Store(&running_, 0);
720
}
721 722 723


void Profiler::Engage() {
724 725 726
  if (engaged_) return;
  engaged_ = true;

727 728
  std::vector<base::OS::SharedLibraryAddress> addresses =
      base::OS::GetSharedLibraryAddresses();
729 730 731 732
  for (size_t i = 0; i < addresses.size(); ++i) {
    LOG(isolate_, SharedLibraryEvent(
        addresses[i].library_path, addresses[i].start, addresses[i].end));
  }
733 734

  // Start thread processing the profiler buffer.
735
  base::NoBarrier_Store(&running_, 1);
736 737 738
  Start();

  // Register to get ticks.
yurys@chromium.org's avatar
yurys@chromium.org committed
739 740
  Logger* logger = isolate_->logger();
  logger->ticker_->SetProfiler(this);
741

yurys@chromium.org's avatar
yurys@chromium.org committed
742
  logger->ProfilerBeginEvent();
743 744 745 746
}


void Profiler::Disengage() {
747 748
  if (!engaged_) return;

749
  // Stop receiving ticks.
750
  isolate_->logger()->ticker_->ClearProfiler();
751

752 753 754
  // Terminate the worker thread by setting running_ to false,
  // inserting a fake element in the queue and then wait for
  // the thread to terminate.
755
  base::NoBarrier_Store(&running_, 0);
756 757 758 759 760
  TickSample sample;
  // Reset 'paused_' flag, otherwise semaphore may not be signalled.
  resume();
  Insert(&sample);
  Join();
761

dcarney@chromium.org's avatar
dcarney@chromium.org committed
762
  LOG(isolate_, UncheckedStringEvent("profiler", "end"));
763 764
}

765

766 767 768
void Profiler::Run() {
  TickSample sample;
  bool overflow = Remove(&sample);
769
  while (base::NoBarrier_Load(&running_)) {
770 771 772
    LOG(isolate_, TickEvent(&sample, overflow));
    overflow = Remove(&sample);
  }
773 774
}

775

776 777 778
//
// Logger class implementation.
//
779

780 781 782 783 784
Logger::Logger(Isolate* isolate)
  : isolate_(isolate),
    ticker_(NULL),
    profiler_(NULL),
    log_events_(NULL),
785
    is_logging_(false),
786
    log_(new Log(this)),
787
    perf_basic_logger_(NULL),
788 789
    ll_logger_(NULL),
    jit_logger_(NULL),
790
    listeners_(5),
791
    is_initialized_(false) {
792 793
}

794

795 796
Logger::~Logger() {
  delete log_;
797
}
798

799

800
void Logger::addCodeEventListener(CodeEventListener* listener) {
801
  DCHECK(!hasCodeEventListener(listener));
802 803 804 805 806
  listeners_.Add(listener);
}


void Logger::removeCodeEventListener(CodeEventListener* listener) {
807
  DCHECK(hasCodeEventListener(listener));
808 809 810 811 812 813 814 815 816
  listeners_.RemoveElement(listener);
}


bool Logger::hasCodeEventListener(CodeEventListener* listener) {
  return listeners_.Contains(listener);
}


817
void Logger::ProfilerBeginEvent() {
818
  if (!log_->IsEnabled()) return;
819
  Log::MessageBuilder msg(log_);
820
  msg.Append("profiler,\"begin\",%d", kSamplingIntervalMs);
821 822 823
  msg.WriteToLogFile();
}

824

825
void Logger::StringEvent(const char* name, const char* value) {
826 827 828 829 830
  if (FLAG_log) UncheckedStringEvent(name, value);
}


void Logger::UncheckedStringEvent(const char* name, const char* value) {
831
  if (!log_->IsEnabled()) return;
832
  Log::MessageBuilder msg(log_);
833
  msg.Append("%s,\"%s\"", name, value);
834
  msg.WriteToLogFile();
835 836 837 838
}


void Logger::IntEvent(const char* name, int value) {
839 840 841 842
  if (FLAG_log) UncheckedIntEvent(name, value);
}


843 844 845 846 847
void Logger::IntPtrTEvent(const char* name, intptr_t value) {
  if (FLAG_log) UncheckedIntPtrTEvent(name, value);
}


848
void Logger::UncheckedIntEvent(const char* name, int value) {
849
  if (!log_->IsEnabled()) return;
850
  Log::MessageBuilder msg(log_);
851
  msg.Append("%s,%d", name, value);
852
  msg.WriteToLogFile();
853 854 855
}


856
void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
857
  if (!log_->IsEnabled()) return;
858
  Log::MessageBuilder msg(log_);
859
  msg.Append("%s,%" V8_PTR_PREFIX "d", name, value);
860 861 862 863
  msg.WriteToLogFile();
}


864
void Logger::HandleEvent(const char* name, Object** location) {
865
  if (!log_->IsEnabled() || !FLAG_log_handles) return;
866
  Log::MessageBuilder msg(log_);
867
  msg.Append("%s,0x%" V8PRIxPTR, name, location);
868
  msg.WriteToLogFile();
869 870 871 872
}


// ApiEvent is private so all the calls come from the Logger class.  It is the
873
// caller's responsibility to ensure that log is enabled and that
874 875
// FLAG_log_api is true.
void Logger::ApiEvent(const char* format, ...) {
876
  DCHECK(log_->IsEnabled() && FLAG_log_api);
877
  Log::MessageBuilder msg(log_);
878 879
  va_list ap;
  va_start(ap, format);
880
  msg.AppendVA(format, ap);
881 882
  va_end(ap);
  msg.WriteToLogFile();
883 884 885
}


886
void Logger::ApiSecurityCheck() {
887
  if (!log_->IsEnabled() || !FLAG_log_api) return;
888
  ApiEvent("api,check-security");
889 890 891
}


892
void Logger::SharedLibraryEvent(const std::string& library_path,
893 894
                                uintptr_t start,
                                uintptr_t end) {
jkummerow's avatar
jkummerow committed
895
  if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
896
  Log::MessageBuilder msg(log_);
897 898
  msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR,
             library_path.c_str(), start, end);
899
  msg.WriteToLogFile();
900 901
}

902

903 904
void Logger::CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) {
  PROFILER_LOG(CodeDeoptEvent(code, pc, fp_to_sp_delta));
905
  if (!log_->IsEnabled() || !FLAG_log_internal_timer_events) return;
906
  Log::MessageBuilder msg(log_);
907
  int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
908
  msg.Append("code-deopt,%ld,%d", since_epoch, code->CodeSize());
909 910 911 912
  msg.WriteToLogFile();
}


913 914
void Logger::CurrentTimeEvent() {
  if (!log_->IsEnabled()) return;
915
  DCHECK(FLAG_log_timer_events || FLAG_prof_cpp);
916 917
  Log::MessageBuilder msg(log_);
  int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
918
  msg.Append("current-time,%ld", since_epoch);
919 920 921 922
  msg.WriteToLogFile();
}


923
void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
924
  if (!log_->IsEnabled()) return;
925
  DCHECK(FLAG_log_internal_timer_events);
926
  Log::MessageBuilder msg(log_);
927
  int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
928 929
  const char* format = (se == START) ? "timer-event-start,\"%s\",%ld"
                                     : "timer-event-end,\"%s\",%ld";
930
  msg.Append(format, name, since_epoch);
931 932 933 934
  msg.WriteToLogFile();
}


935
void Logger::EnterExternal(Isolate* isolate) {
936
  LOG(isolate, TimerEvent(START, TimerEventExternal::name()));
937
  TRACE_EVENT_BEGIN0(TRACE_DISABLED_BY_DEFAULT("v8"), "V8.External");
938
  DCHECK(isolate->current_vm_state() == JS);
939
  isolate->set_current_vm_state(EXTERNAL);
940 941 942
}


943
void Logger::LeaveExternal(Isolate* isolate) {
944
  LOG(isolate, TimerEvent(END, TimerEventExternal::name()));
945
  TRACE_EVENT_END0(TRACE_DISABLED_BY_DEFAULT("v8"), "V8.External");
946
  DCHECK(isolate->current_vm_state() == EXTERNAL);
947
  isolate->set_current_vm_state(JS);
948 949 950
}


951 952
template <class TimerEvent>
void TimerEventScope<TimerEvent>::LogTimerEvent(Logger::StartEnd se) {
953 954
  Logger::CallEventLogger(isolate_, TimerEvent::name(), se,
                          TimerEvent::expose_to_api());
955 956 957
}


958 959 960 961 962 963
// Instantiate template methods.
#define V(TimerName, expose)                                           \
  template void TimerEventScope<TimerEvent##TimerName>::LogTimerEvent( \
      Logger::StartEnd se);
TIMER_EVENTS_LIST(V)
#undef V
964 965


966 967 968 969
namespace {
// Emits the source code of a regexp. Used by regexp events.
void LogRegExpSource(Handle<JSRegExp> regexp, Isolate* isolate,
                     Log::MessageBuilder* msg) {
970
  // Prints "/" + re.source + "/" +
971 972
  //      (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")

973 974
  Handle<Object> source =
      Object::GetProperty(isolate, regexp, "source").ToHandleChecked();
975
  if (!source->IsString()) {
976
    msg->Append("no source");
977 978 979
    return;
  }

980
  switch (regexp->TypeTag()) {
981
    case JSRegExp::ATOM:
982
      msg->Append('a');
983 984 985 986
      break;
    default:
      break;
  }
987 988 989
  msg->Append('/');
  msg->AppendDetailed(*Handle<String>::cast(source), false);
  msg->Append('/');
990 991

  // global flag
992 993
  Handle<Object> global =
      Object::GetProperty(isolate, regexp, "global").ToHandleChecked();
994
  if (global->IsTrue()) {
995
    msg->Append('g');
996 997
  }
  // ignorecase flag
998 999
  Handle<Object> ignorecase =
      Object::GetProperty(isolate, regexp, "ignoreCase").ToHandleChecked();
1000
  if (ignorecase->IsTrue()) {
1001
    msg->Append('i');
1002 1003
  }
  // multiline flag
1004 1005
  Handle<Object> multiline =
      Object::GetProperty(isolate, regexp, "multiline").ToHandleChecked();
1006
  if (multiline->IsTrue()) {
1007
    msg->Append('m');
1008 1009
  }
}
1010
}  // namespace
1011 1012


1013
void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
1014
  if (!log_->IsEnabled() || !FLAG_log_regexp) return;
1015
  Log::MessageBuilder msg(log_);
1016
  msg.Append("regexp-compile,");
1017
  LogRegExpSource(regexp, isolate_, &msg);
1018
  msg.Append(in_cache ? ",hit" : ",miss");
1019
  msg.WriteToLogFile();
1020 1021 1022
}


1023 1024 1025
void Logger::ApiNamedPropertyAccess(const char* tag,
                                    JSObject* holder,
                                    Object* name) {
1026
  DCHECK(name->IsName());
1027
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1028
  String* class_name_obj = holder->class_name();
rmcilroy's avatar
rmcilroy committed
1029
  base::SmartArrayPointer<char> class_name =
1030
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1031
  if (name->IsString()) {
rmcilroy's avatar
rmcilroy committed
1032
    base::SmartArrayPointer<char> property_name =
1033
        String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1034
    ApiEvent("api,%s,\"%s\",\"%s\"", tag, class_name.get(),
1035
             property_name.get());
1036
  } else {
1037 1038 1039
    Symbol* symbol = Symbol::cast(name);
    uint32_t hash = symbol->Hash();
    if (symbol->name()->IsUndefined()) {
1040
      ApiEvent("api,%s,\"%s\",symbol(hash %x)", tag, class_name.get(), hash);
1041
    } else {
rmcilroy's avatar
rmcilroy committed
1042 1043 1044
      base::SmartArrayPointer<char> str =
          String::cast(symbol->name())
              ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1045 1046
      ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)", tag, class_name.get(),
               str.get(), hash);
1047
    }
1048
  }
1049 1050 1051 1052 1053
}

void Logger::ApiIndexedPropertyAccess(const char* tag,
                                      JSObject* holder,
                                      uint32_t index) {
1054
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1055
  String* class_name_obj = holder->class_name();
rmcilroy's avatar
rmcilroy committed
1056
  base::SmartArrayPointer<char> class_name =
1057
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1058
  ApiEvent("api,%s,\"%s\",%u", tag, class_name.get(), index);
1059 1060
}

1061

1062
void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
1063
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1064
  String* class_name_obj = object->class_name();
rmcilroy's avatar
rmcilroy committed
1065
  base::SmartArrayPointer<char> class_name =
1066
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1067
  ApiEvent("api,%s,\"%s\"", tag, class_name.get());
1068 1069 1070 1071
}


void Logger::ApiEntryCall(const char* name) {
1072
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1073
  ApiEvent("api,%s", name);
1074 1075 1076 1077
}


void Logger::NewEvent(const char* name, void* object, size_t size) {
1078
  if (!log_->IsEnabled() || !FLAG_log) return;
1079
  Log::MessageBuilder msg(log_);
1080
  msg.Append("new,%s,0x%" V8PRIxPTR ",%u", name, object,
1081 1082
             static_cast<unsigned int>(size));
  msg.WriteToLogFile();
1083 1084 1085 1086
}


void Logger::DeleteEvent(const char* name, void* object) {
1087
  if (!log_->IsEnabled() || !FLAG_log) return;
1088
  Log::MessageBuilder msg(log_);
1089
  msg.Append("delete,%s,0x%" V8PRIxPTR, name, object);
1090
  msg.WriteToLogFile();
1091 1092 1093
}


1094
void Logger::CallbackEventInternal(const char* prefix, Name* name,
1095
                                   Address entry_point) {
1096
  if (!FLAG_log_code || !log_->IsEnabled()) return;
1097
  Log::MessageBuilder msg(log_);
1098
  msg.Append("%s,%s,-2,",
1099 1100
             kLogEventsNames[CODE_CREATION_EVENT],
             kLogEventsNames[CALLBACK_TAG]);
1101
  msg.AppendAddress(entry_point);
1102
  if (name->IsString()) {
rmcilroy's avatar
rmcilroy committed
1103
    base::SmartArrayPointer<char> str =
1104
        String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1105
    msg.Append(",1,\"%s%s\"", prefix, str.get());
1106
  } else {
1107 1108 1109 1110
    Symbol* symbol = Symbol::cast(name);
    if (symbol->name()->IsUndefined()) {
      msg.Append(",1,symbol(hash %x)", prefix, symbol->Hash());
    } else {
rmcilroy's avatar
rmcilroy committed
1111 1112 1113
      base::SmartArrayPointer<char> str =
          String::cast(symbol->name())
              ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1114 1115
      msg.Append(",1,symbol(\"%s\" hash %x)", prefix, str.get(),
                 symbol->Hash());
1116
    }
1117
  }
1118
  msg.WriteToLogFile();
1119 1120 1121
}


1122
void Logger::CallbackEvent(Name* name, Address entry_point) {
1123
  PROFILER_LOG(CallbackEvent(name, entry_point));
1124
  CallbackEventInternal("", name, entry_point);
1125 1126 1127
}


1128
void Logger::GetterCallbackEvent(Name* name, Address entry_point) {
1129
  PROFILER_LOG(GetterCallbackEvent(name, entry_point));
1130
  CallbackEventInternal("get ", name, entry_point);
1131 1132 1133
}


1134
void Logger::SetterCallbackEvent(Name* name, Address entry_point) {
1135
  PROFILER_LOG(SetterCallbackEvent(name, entry_point));
1136
  CallbackEventInternal("set ", name, entry_point);
1137 1138 1139
}


1140 1141 1142
static void AppendCodeCreateHeader(Log::MessageBuilder* msg,
                                   Logger::LogEventsAndTags tag,
                                   Code* code) {
1143
  DCHECK(msg);
1144
  msg->Append("%s,%s,%d,",
1145
              kLogEventsNames[Logger::CODE_CREATION_EVENT],
1146 1147 1148 1149 1150 1151 1152
              kLogEventsNames[tag],
              code->kind());
  msg->AppendAddress(code->address());
  msg->Append(",%d,", code->ExecutableSize());
}


1153 1154 1155
void Logger::CodeCreateEvent(LogEventsAndTags tag,
                             Code* code,
                             const char* comment) {
1156
  PROFILER_LOG(CodeCreateEvent(tag, code, comment));
1157

1158
  if (!is_logging_code_events()) return;
1159
  CALL_LISTENERS(CodeCreateEvent(tag, code, comment));
1160 1161

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1162
  Log::MessageBuilder msg(log_);
1163 1164
  AppendCodeCreateHeader(&msg, tag, code);
  msg.AppendDoubleQuotedString(comment);
1165
  msg.WriteToLogFile();
1166 1167 1168
}


1169 1170
void Logger::CodeCreateEvent(LogEventsAndTags tag,
                             Code* code,
1171
                             Name* name) {
1172
  PROFILER_LOG(CodeCreateEvent(tag, code, name));
1173

1174
  if (!is_logging_code_events()) return;
1175
  CALL_LISTENERS(CodeCreateEvent(tag, code, name));
1176 1177

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1178
  Log::MessageBuilder msg(log_);
1179
  AppendCodeCreateHeader(&msg, tag, code);
1180 1181 1182 1183 1184
  if (name->IsString()) {
    msg.Append('"');
    msg.AppendDetailed(String::cast(name), false);
    msg.Append('"');
  } else {
1185
    msg.AppendSymbolName(Symbol::cast(name));
1186
  }
1187
  msg.WriteToLogFile();
1188 1189 1190 1191 1192 1193
}


void Logger::CodeCreateEvent(LogEventsAndTags tag,
                             Code* code,
                             SharedFunctionInfo* shared,
1194
                             CompilationInfo* info,
1195
                             Name* name) {
1196
  PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, name));
1197

1198
  if (!is_logging_code_events()) return;
1199
  CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, name));
1200 1201

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1202
  if (code == isolate_->builtins()->builtin(Builtins::kCompileLazy)) return;
1203

1204
  Log::MessageBuilder msg(log_);
1205
  AppendCodeCreateHeader(&msg, tag, code);
1206
  if (name->IsString()) {
rmcilroy's avatar
rmcilroy committed
1207
    base::SmartArrayPointer<char> str =
1208
        String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1209
    msg.Append("\"%s\"", str.get());
1210
  } else {
1211
    msg.AppendSymbolName(Symbol::cast(name));
1212 1213
  }
  msg.Append(',');
1214
  msg.AppendAddress(shared->address());
1215
  msg.Append(",%s", ComputeMarker(shared, code));
1216
  msg.WriteToLogFile();
1217 1218 1219
}


1220 1221 1222
// Although, it is possible to extract source and line from
// the SharedFunctionInfo object, we left it to caller
// to leave logging functions free from heap allocations.
1223
void Logger::CodeCreateEvent(LogEventsAndTags tag,
1224 1225
                             Code* code,
                             SharedFunctionInfo* shared,
1226
                             CompilationInfo* info,
1227
                             Name* source, int line, int column) {
1228
  PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, source, line, column));
1229

1230
  if (!is_logging_code_events()) return;
1231 1232
  CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, source, line,
                                 column));
1233 1234

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1235
  Log::MessageBuilder msg(log_);
1236
  AppendCodeCreateHeader(&msg, tag, code);
rmcilroy's avatar
rmcilroy committed
1237
  base::SmartArrayPointer<char> name =
1238
      shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1239
  msg.Append("\"%s ", name.get());
1240
  if (source->IsString()) {
rmcilroy's avatar
rmcilroy committed
1241 1242
    base::SmartArrayPointer<char> sourcestr = String::cast(source)->ToCString(
        DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1243
    msg.Append("%s", sourcestr.get());
1244
  } else {
1245
    msg.AppendSymbolName(Symbol::cast(source));
1246
  }
1247
  msg.Append(":%d:%d\",", line, column);
1248
  msg.AppendAddress(shared->address());
1249
  msg.Append(",%s", ComputeMarker(shared, code));
1250
  msg.WriteToLogFile();
1251 1252 1253
}


1254 1255 1256
void Logger::CodeCreateEvent(LogEventsAndTags tag,
                             Code* code,
                             int args_count) {
1257
  PROFILER_LOG(CodeCreateEvent(tag, code, args_count));
1258

1259
  if (!is_logging_code_events()) return;
1260
  CALL_LISTENERS(CodeCreateEvent(tag, code, args_count));
1261 1262

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1263
  Log::MessageBuilder msg(log_);
1264 1265
  AppendCodeCreateHeader(&msg, tag, code);
  msg.Append("\"args_count: %d\"", args_count);
1266
  msg.WriteToLogFile();
1267 1268 1269
}


1270 1271 1272 1273 1274 1275 1276 1277 1278 1279
void Logger::CodeDisableOptEvent(Code* code,
                                 SharedFunctionInfo* shared) {
  PROFILER_LOG(CodeDisableOptEvent(code, shared));

  if (!is_logging_code_events()) return;
  CALL_LISTENERS(CodeDisableOptEvent(code, shared));

  if (!FLAG_log_code || !log_->IsEnabled()) return;
  Log::MessageBuilder msg(log_);
  msg.Append("%s,", kLogEventsNames[CODE_DISABLE_OPT_EVENT]);
rmcilroy's avatar
rmcilroy committed
1280
  base::SmartArrayPointer<char> name =
1281 1282
      shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
  msg.Append("\"%s\",", name.get());
1283
  msg.Append("\"%s\"", GetBailoutReason(shared->disable_optimization_reason()));
1284 1285 1286 1287
  msg.WriteToLogFile();
}


1288
void Logger::CodeMovingGCEvent() {
1289 1290 1291
  PROFILER_LOG(CodeMovingGCEvent());

  if (!is_logging_code_events()) return;
1292
  if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1293
  CALL_LISTENERS(CodeMovingGCEvent());
1294
  base::OS::SignalCodeMovingGC();
1295 1296 1297
}


1298
void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
1299
  PROFILER_LOG(RegExpCodeCreateEvent(code, source));
1300

1301
  if (!is_logging_code_events()) return;
1302
  CALL_LISTENERS(RegExpCodeCreateEvent(code, source));
1303 1304

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1305
  Log::MessageBuilder msg(log_);
1306 1307
  AppendCodeCreateHeader(&msg, REG_EXP_TAG, code);
  msg.Append('"');
1308
  msg.AppendDetailed(source, false);
1309
  msg.Append('"');
1310 1311 1312 1313
  msg.WriteToLogFile();
}


1314
void Logger::CodeMoveEvent(Address from, Address to) {
1315 1316 1317
  PROFILER_LOG(CodeMoveEvent(from, to));

  if (!is_logging_code_events()) return;
1318
  CALL_LISTENERS(CodeMoveEvent(from, to));
1319 1320 1321 1322 1323
  MoveEventInternal(CODE_MOVE_EVENT, from, to);
}


void Logger::CodeDeleteEvent(Address from) {
1324 1325 1326
  PROFILER_LOG(CodeDeleteEvent(from));

  if (!is_logging_code_events()) return;
1327
  CALL_LISTENERS(CodeDeleteEvent(from));
1328

1329
  if (!FLAG_log_code || !log_->IsEnabled()) return;
1330 1331 1332 1333
  Log::MessageBuilder msg(log_);
  msg.Append("%s,", kLogEventsNames[CODE_DELETE_EVENT]);
  msg.AppendAddress(from);
  msg.WriteToLogFile();
1334 1335
}

1336

1337 1338 1339
void Logger::CodeLinePosInfoAddPositionEvent(void* jit_handler_data,
                                     int pc_offset,
                                     int position) {
1340 1341 1342 1343
  JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
                                  pc_offset,
                                  position,
                                  JitCodeEvent::POSITION));
1344 1345
}

1346

1347 1348 1349
void Logger::CodeLinePosInfoAddStatementPositionEvent(void* jit_handler_data,
                                                      int pc_offset,
                                                      int position) {
1350 1351 1352 1353
  JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
                                  pc_offset,
                                  position,
                                  JitCodeEvent::STATEMENT_POSITION));
1354 1355
}

1356

1357
void Logger::CodeStartLinePosInfoRecordEvent(PositionsRecorder* pos_recorder) {
1358 1359
  if (jit_logger_ != NULL) {
      pos_recorder->AttachJITHandlerData(jit_logger_->StartCodePosInfoEvent());
1360 1361 1362
  }
}

1363

1364 1365
void Logger::CodeEndLinePosInfoRecordEvent(Code* code,
                                           void* jit_handler_data) {
1366
  JIT_LOG(EndCodePosInfoEvent(code, jit_handler_data));
1367
}
1368

1369

1370 1371 1372 1373 1374 1375 1376 1377 1378
void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
  if (code_name == NULL) return;  // Not a code object.
  Log::MessageBuilder msg(log_);
  msg.Append("%s,%d,", kLogEventsNames[SNAPSHOT_CODE_NAME_EVENT], pos);
  msg.AppendDoubleQuotedString(code_name);
  msg.WriteToLogFile();
}


1379
void Logger::SnapshotPositionEvent(Address addr, int pos) {
1380
  if (!log_->IsEnabled()) return;
1381
  LL_LOG(SnapshotPositionEvent(addr, pos));
1382
  if (!FLAG_log_snapshot_positions) return;
1383
  Log::MessageBuilder msg(log_);
1384
  msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
1385 1386 1387 1388 1389 1390
  msg.AppendAddress(addr);
  msg.Append(",%d", pos);
  msg.WriteToLogFile();
}


1391
void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1392
  if (!is_logging_code_events()) return;
1393
  MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to);
1394 1395 1396 1397 1398 1399
}


void Logger::MoveEventInternal(LogEventsAndTags event,
                               Address from,
                               Address to) {
1400
  if (!FLAG_log_code || !log_->IsEnabled()) return;
1401
  Log::MessageBuilder msg(log_);
1402
  msg.Append("%s,", kLogEventsNames[event]);
1403
  msg.AppendAddress(from);
1404
  msg.Append(',');
1405
  msg.AppendAddress(to);
1406
  msg.WriteToLogFile();
1407 1408 1409
}


1410
void Logger::ResourceEvent(const char* name, const char* tag) {
1411
  if (!log_->IsEnabled() || !FLAG_log) return;
1412
  Log::MessageBuilder msg(log_);
1413
  msg.Append("%s,%s,", name, tag);
1414 1415

  uint32_t sec, usec;
1416
  if (base::OS::GetUserTime(&sec, &usec) != -1) {
1417
    msg.Append("%d,%d,", sec, usec);
1418
  }
1419
  msg.Append("%.0f", base::OS::TimeCurrentMillis());
1420
  msg.WriteToLogFile();
1421 1422 1423
}


1424
void Logger::SuspectReadEvent(Name* name, Object* obj) {
1425
  if (!log_->IsEnabled() || !FLAG_log_suspect) return;
1426
  Log::MessageBuilder msg(log_);
1427 1428
  String* class_name = obj->IsJSObject()
                       ? JSObject::cast(obj)->class_name()
1429
                       : isolate_->heap()->empty_string();
1430 1431 1432
  msg.Append("suspect-read,");
  msg.Append(class_name);
  msg.Append(',');
1433 1434 1435 1436 1437
  if (name->IsString()) {
    msg.Append('"');
    msg.Append(String::cast(name));
    msg.Append('"');
  } else {
1438
    msg.AppendSymbolName(Symbol::cast(name));
1439
  }
1440
  msg.WriteToLogFile();
1441 1442 1443 1444
}


void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
1445
  if (!log_->IsEnabled() || !FLAG_log_gc) return;
1446
  Log::MessageBuilder msg(log_);
1447 1448
  // Using non-relative system time in order to be able to synchronize with
  // external memory profiling events (e.g. DOM memory size).
1449 1450
  msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f", space, kind,
             base::OS::TimeCurrentMillis());
1451 1452 1453 1454
  msg.WriteToLogFile();
}


1455
void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1456
  if (!log_->IsEnabled() || !FLAG_log_gc) return;
1457
  Log::MessageBuilder msg(log_);
1458
  msg.Append("heap-sample-end,\"%s\",\"%s\"", space, kind);
1459
  msg.WriteToLogFile();
1460 1461 1462 1463
}


void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1464
  if (!log_->IsEnabled() || !FLAG_log_gc) return;
1465
  Log::MessageBuilder msg(log_);
1466
  msg.Append("heap-sample-item,%s,%d,%d", type, number, bytes);
1467
  msg.WriteToLogFile();
1468 1469 1470
}


1471
void Logger::DebugTag(const char* call_site_tag) {
1472
  if (!log_->IsEnabled() || !FLAG_log) return;
1473
  Log::MessageBuilder msg(log_);
1474
  msg.Append("debug-tag,%s", call_site_tag);
1475
  msg.WriteToLogFile();
1476 1477 1478 1479
}


void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1480
  if (!log_->IsEnabled() || !FLAG_log) return;
1481 1482 1483 1484 1485
  StringBuilder s(parameter.length() + 1);
  for (int i = 0; i < parameter.length(); ++i) {
    s.AddCharacter(static_cast<char>(parameter[i]));
  }
  char* parameter_string = s.Finalize();
1486
  Log::MessageBuilder msg(log_);
1487 1488
  msg.Append("debug-queue-event,%s,%15.3f,%s", event_type,
             base::OS::TimeCurrentMillis(), parameter_string);
1489
  DeleteArray(parameter_string);
1490
  msg.WriteToLogFile();
1491 1492 1493
}


1494
void Logger::TickEvent(TickSample* sample, bool overflow) {
jkummerow's avatar
jkummerow committed
1495
  if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
1496
  Log::MessageBuilder msg(log_);
1497 1498
  msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
  msg.AppendAddress(sample->pc);
1499
  msg.Append(",%ld", static_cast<int>(timer_.Elapsed().InMicroseconds()));
1500 1501
  if (sample->has_external_callback) {
    msg.Append(",1,");
1502 1503 1504
#if USES_FUNCTION_DESCRIPTORS
    msg.AppendAddress(*FUNCTION_ENTRYPOINT_ADDRESS(sample->external_callback));
#else
1505
    msg.AppendAddress(sample->external_callback);
1506
#endif
1507 1508 1509 1510
  } else {
    msg.Append(",0,");
    msg.AppendAddress(sample->tos);
  }
1511
  msg.Append(",%d", static_cast<int>(sample->state));
1512 1513 1514
  if (overflow) {
    msg.Append(",overflow");
  }
1515
  for (unsigned i = 0; i < sample->frames_count; ++i) {
1516
    msg.Append(',');
1517
    msg.AppendAddress(sample->stack[i]);
1518
  }
1519
  msg.WriteToLogFile();
1520
}
1521 1522


1523
void Logger::StopProfiler() {
1524
  if (!log_->IsEnabled()) return;
1525
  if (profiler_ != NULL) {
1526 1527
    profiler_->pause();
    is_logging_ = false;
1528
  }
1529
}
1530 1531


1532 1533
// This function can be called when Log's mutex is acquired,
// either from main or Profiler's thread.
1534
void Logger::LogFailure() {
1535
  StopProfiler();
1536 1537 1538
}


1539 1540 1541 1542 1543 1544 1545 1546 1547 1548 1549
class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
 public:
  EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
                                     Handle<Code>* code_objects,
                                     int* count)
      : sfis_(sfis), code_objects_(code_objects), count_(count) { }

  virtual void EnterContext(Context* context) {}
  virtual void LeaveContext(Context* context) {}

  virtual void VisitFunction(JSFunction* function) {
1550 1551 1552 1553
    SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
    Object* maybe_script = sfi->script();
    if (maybe_script->IsScript()
        && !Script::cast(maybe_script)->HasValidSource()) return;
1554
    if (sfis_ != NULL) {
1555
      sfis_[*count_] = Handle<SharedFunctionInfo>(sfi);
1556 1557
    }
    if (code_objects_ != NULL) {
1558
      DCHECK(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
1559 1560 1561 1562 1563 1564 1565 1566 1567 1568 1569 1570
      code_objects_[*count_] = Handle<Code>(function->code());
    }
    *count_ = *count_ + 1;
  }

 private:
  Handle<SharedFunctionInfo>* sfis_;
  Handle<Code>* code_objects_;
  int* count_;
};


1571 1572
static int EnumerateCompiledFunctions(Heap* heap,
                                      Handle<SharedFunctionInfo>* sfis,
1573
                                      Handle<Code>* code_objects) {
1574
  HeapIterator iterator(heap);
1575
  DisallowHeapAllocation no_gc;
1576
  int compiled_funcs_count = 0;
1577 1578 1579

  // Iterate the heap to find shared function info objects and record
  // the unoptimized code for them.
1580
  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1581 1582 1583 1584 1585
    if (!obj->IsSharedFunctionInfo()) continue;
    SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
    if (sfi->is_compiled()
        && (!sfi->script()->IsScript()
            || Script::cast(sfi->script())->HasValidSource())) {
1586
      if (sfis != NULL) {
1587
        sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1588 1589 1590 1591
      }
      if (code_objects != NULL) {
        code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
      }
1592
      ++compiled_funcs_count;
1593
    }
1594
  }
1595 1596 1597 1598 1599

  // Iterate all optimized functions in all contexts.
  EnumerateOptimizedFunctionsVisitor visitor(sfis,
                                             code_objects,
                                             &compiled_funcs_count);
1600
  Deoptimizer::VisitAllOptimizedFunctions(heap->isolate(), &visitor);
1601

1602 1603
  return compiled_funcs_count;
}
1604 1605


1606
void Logger::LogCodeObject(Object* object) {
1607 1608 1609 1610 1611 1612 1613
  Code* code_object = Code::cast(object);
  LogEventsAndTags tag = Logger::STUB_TAG;
  const char* description = "Unknown code from the snapshot";
  switch (code_object->kind()) {
    case Code::FUNCTION:
    case Code::OPTIMIZED_FUNCTION:
      return;  // We log this later using LogCompiledFunctions.
1614
    case Code::BINARY_OP_IC:
1615 1616 1617 1618
    case Code::COMPARE_IC:  // fall through
    case Code::COMPARE_NIL_IC:   // fall through
    case Code::TO_BOOLEAN_IC:  // fall through
    case Code::STUB:
1619
      description = CodeStub::MajorName(CodeStub::GetMajorKey(code_object));
1620 1621 1622 1623
      if (description == NULL)
        description = "A stub from the snapshot";
      tag = Logger::STUB_TAG;
      break;
1624 1625 1626 1627
    case Code::REGEXP:
      description = "Regular expression code";
      tag = Logger::REG_EXP_TAG;
      break;
1628
    case Code::BUILTIN:
1629
      description = isolate_->builtins()->name(code_object->builtin_index());
1630 1631
      tag = Logger::BUILTIN_TAG;
      break;
1632 1633 1634 1635
    case Code::HANDLER:
      description = "An IC handler from the snapshot";
      tag = Logger::HANDLER_TAG;
      break;
1636 1637 1638 1639 1640 1641 1642 1643
    case Code::KEYED_LOAD_IC:
      description = "A keyed load IC from the snapshot";
      tag = Logger::KEYED_LOAD_IC_TAG;
      break;
    case Code::LOAD_IC:
      description = "A load IC from the snapshot";
      tag = Logger::LOAD_IC_TAG;
      break;
1644 1645 1646 1647
    case Code::CALL_IC:
      description = "A call IC from the snapshot";
      tag = Logger::CALL_IC_TAG;
      break;
1648 1649 1650 1651 1652 1653 1654 1655
    case Code::STORE_IC:
      description = "A store IC from the snapshot";
      tag = Logger::STORE_IC_TAG;
      break;
    case Code::KEYED_STORE_IC:
      description = "A keyed store IC from the snapshot";
      tag = Logger::KEYED_STORE_IC_TAG;
      break;
1656 1657
    case Code::WASM_FUNCTION:
      description = "A wasm function";
titzer's avatar
titzer committed
1658 1659
      tag = Logger::STUB_TAG;
      break;
1660 1661
    case Code::NUMBER_OF_KINDS:
      break;
1662
  }
1663
  PROFILE(isolate_, CodeCreateEvent(tag, code_object, description));
1664 1665 1666
}


1667
void Logger::LogCodeObjects() {
1668
  Heap* heap = isolate_->heap();
1669 1670
  heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
                          "Logger::LogCodeObjects");
1671
  HeapIterator iterator(heap);
1672
  DisallowHeapAllocation no_gc;
1673 1674 1675 1676 1677 1678
  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
    if (obj->IsCode()) LogCodeObject(obj);
  }
}


1679 1680 1681 1682 1683
void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
                                 Handle<Code> code) {
  Handle<String> func_name(shared->DebugName());
  if (shared->script()->IsScript()) {
    Handle<Script> script(Script::cast(shared->script()));
1684
    int line_num = Script::GetLineNumber(script, shared->start_position()) + 1;
1685
    int column_num =
1686
        Script::GetColumnNumber(script, shared->start_position()) + 1;
1687
    if (script->name()->IsString()) {
1688 1689
      Handle<String> script_name(String::cast(script->name()));
      if (line_num > 0) {
1690
        PROFILE(isolate_,
1691 1692
                CodeCreateEvent(
                    Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1693
                    *code, *shared, NULL,
1694
                    *script_name, line_num, column_num));
1695 1696
      } else {
        // Can't distinguish eval and script here, so always use Script.
1697
        PROFILE(isolate_,
1698 1699
                CodeCreateEvent(
                    Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1700
                    *code, *shared, NULL, *script_name));
1701 1702
      }
    } else {
1703
      PROFILE(isolate_,
1704 1705
              CodeCreateEvent(
                  Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1706
                  *code, *shared, NULL,
1707
                  isolate_->heap()->empty_string(), line_num, column_num));
1708 1709 1710 1711 1712 1713 1714 1715 1716
    }
  } else if (shared->IsApiFunction()) {
    // API function.
    FunctionTemplateInfo* fun_data = shared->get_api_func_data();
    Object* raw_call_data = fun_data->call_code();
    if (!raw_call_data->IsUndefined()) {
      CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
      Object* callback_obj = call_data->callback();
      Address entry_point = v8::ToCData<Address>(callback_obj);
1717
      PROFILE(isolate_, CallbackEvent(*func_name, entry_point));
1718 1719
    }
  } else {
1720
    PROFILE(isolate_,
1721
            CodeCreateEvent(
1722
                Logger::LAZY_COMPILE_TAG, *code, *shared, NULL, *func_name));
1723 1724 1725 1726
  }
}


1727
void Logger::LogCompiledFunctions() {
1728
  Heap* heap = isolate_->heap();
1729 1730
  heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
                          "Logger::LogCompiledFunctions");
1731
  HandleScope scope(isolate_);
1732
  const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL);
1733
  ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
1734
  ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
1735
  EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start());
1736 1737 1738 1739

  // During iteration, there can be heap allocation due to
  // GetScriptLineNumber call.
  for (int i = 0; i < compiled_funcs_count; ++i) {
1740
    if (code_objects[i].is_identical_to(isolate_->builtins()->CompileLazy()))
1741
      continue;
1742
    LogExistingFunction(sfis[i], code_objects[i]);
1743 1744 1745
  }
}

1746 1747

void Logger::LogAccessorCallbacks() {
1748
  Heap* heap = isolate_->heap();
1749 1750
  heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
                          "Logger::LogAccessorCallbacks");
1751
  HeapIterator iterator(heap);
1752
  DisallowHeapAllocation no_gc;
1753
  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1754 1755
    if (!obj->IsAccessorInfo()) continue;
    AccessorInfo* ai = AccessorInfo::cast(obj);
1756
    if (!ai->name()->IsName()) continue;
1757
    Address getter_entry = v8::ToCData<Address>(ai->getter());
1758
    Name* name = Name::cast(ai->name());
1759
    if (getter_entry != 0) {
1760
      PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
1761 1762 1763
    }
    Address setter_entry = v8::ToCData<Address>(ai->setter());
    if (setter_entry != 0) {
1764
      PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
1765 1766 1767 1768
    }
  }
}

1769

1770
static void AddIsolateIdIfNeeded(std::ostream& os,  // NOLINT
1771 1772
                                 Isolate* isolate) {
  if (FLAG_logfile_per_isolate) os << "isolate-" << isolate << "-";
1773 1774 1775
}


1776
static void PrepareLogFileName(std::ostream& os,  // NOLINT
1777
                               Isolate* isolate, const char* file_name) {
sejunho's avatar
sejunho committed
1778
  int dir_separator_count = 0;
1779
  for (const char* p = file_name; *p; p++) {
sejunho's avatar
sejunho committed
1780 1781 1782 1783 1784 1785 1786 1787
    if (base::OS::isDirectorySeparator(*p)) dir_separator_count++;
  }

  for (const char* p = file_name; *p; p++) {
    if (dir_separator_count == 0) {
      AddIsolateIdIfNeeded(os, isolate);
      dir_separator_count--;
    }
1788 1789 1790 1791 1792 1793 1794 1795 1796
    if (*p == '%') {
      p++;
      switch (*p) {
        case '\0':
          // If there's a % at the end of the string we back up
          // one character so we can escape the loop properly.
          p--;
          break;
        case 'p':
1797
          os << base::OS::GetCurrentProcessId();
1798
          break;
1799
        case 't':
1800
          // %t expands to the current time in milliseconds.
1801
          os << static_cast<int64_t>(base::OS::TimeCurrentMillis());
1802 1803 1804
          break;
        case '%':
          // %% expands (contracts really) to %.
1805
          os << '%';
1806 1807 1808
          break;
        default:
          // All other %'s expand to themselves.
1809
          os << '%' << *p;
1810
          break;
1811
      }
1812
    } else {
sejunho's avatar
sejunho committed
1813
      if (base::OS::isDirectorySeparator(*p)) dir_separator_count--;
1814
      os << *p;
1815 1816 1817 1818 1819
    }
  }
}


1820
bool Logger::SetUp(Isolate* isolate) {
1821 1822 1823
  // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
  if (is_initialized_) return true;
  is_initialized_ = true;
1824

1825 1826 1827 1828 1829
  // --ll-prof implies --log-code and --log-snapshot-positions.
  if (FLAG_ll_prof) {
    FLAG_log_snapshot_positions = true;
  }

1830
  std::ostringstream log_file_name;
1831
  PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
1832
  log_->Initialize(log_file_name.str().c_str());
1833

1834 1835 1836 1837 1838 1839

  if (FLAG_perf_basic_prof) {
    perf_basic_logger_ = new PerfBasicLogger();
    addCodeEventListener(perf_basic_logger_);
  }

1840
  if (FLAG_ll_prof) {
1841
    ll_logger_ = new LowLevelLogger(log_file_name.str().c_str());
1842
    addCodeEventListener(ll_logger_);
1843
  }
1844

1845 1846
  ticker_ = new Ticker(isolate, kSamplingIntervalMs);

1847
  if (Log::InitLogAtStart()) {
1848
    is_logging_ = true;
1849
  }
1850

jkummerow's avatar
jkummerow committed
1851
  if (FLAG_log_internal_timer_events || FLAG_prof_cpp) timer_.Start();
1852

jkummerow's avatar
jkummerow committed
1853
  if (FLAG_prof_cpp) {
1854
    profiler_ = new Profiler(isolate);
1855 1856
    is_logging_ = true;
    profiler_->Engage();
1857 1858 1859 1860 1861 1862
  }

  return true;
}


1863 1864
void Logger::SetCodeEventHandler(uint32_t options,
                                 JitCodeEventHandler event_handler) {
1865
  if (jit_logger_) {
1866
      removeCodeEventListener(jit_logger_);
1867 1868 1869
      delete jit_logger_;
      jit_logger_ = NULL;
  }
1870

1871 1872
  if (event_handler) {
    jit_logger_ = new JitLogger(event_handler);
1873 1874 1875 1876 1877 1878
    addCodeEventListener(jit_logger_);
    if (options & kJitCodeEventEnumExisting) {
      HandleScope scope(isolate_);
      LogCodeObjects();
      LogCompiledFunctions();
    }
1879 1880 1881 1882
  }
}


1883 1884 1885 1886 1887
Sampler* Logger::sampler() {
  return ticker_;
}


1888 1889
FILE* Logger::TearDown() {
  if (!is_initialized_) return NULL;
1890
  is_initialized_ = false;
1891

1892 1893 1894 1895 1896 1897 1898 1899
  // Stop the profiler before closing the file.
  if (profiler_ != NULL) {
    profiler_->Disengage();
    delete profiler_;
    profiler_ = NULL;
  }

  delete ticker_;
1900
  ticker_ = NULL;
1901

1902 1903 1904 1905 1906 1907
  if (perf_basic_logger_) {
    removeCodeEventListener(perf_basic_logger_);
    delete perf_basic_logger_;
    perf_basic_logger_ = NULL;
  }

1908
  if (ll_logger_) {
1909
    removeCodeEventListener(ll_logger_);
1910 1911 1912 1913
    delete ll_logger_;
    ll_logger_ = NULL;
  }

1914
  if (jit_logger_) {
1915
    removeCodeEventListener(jit_logger_);
1916 1917 1918 1919
    delete jit_logger_;
    jit_logger_ = NULL;
  }

1920
  return log_->Close();
1921 1922
}

1923 1924
}  // namespace internal
}  // namespace v8