log.cc 63 KB
Newer Older
danno@chromium.org's avatar
danno@chromium.org committed
1
// Copyright 2011 the V8 project authors. All rights reserved.
2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31
// Redistribution and use in source and binary forms, with or without
// modification, are permitted provided that the following conditions are
// met:
//
//     * Redistributions of source code must retain the above copyright
//       notice, this list of conditions and the following disclaimer.
//     * Redistributions in binary form must reproduce the above
//       copyright notice, this list of conditions and the following
//       disclaimer in the documentation and/or other materials provided
//       with the distribution.
//     * Neither the name of Google Inc. nor the names of its
//       contributors may be used to endorse or promote products derived
//       from this software without specific prior written permission.
//
// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.

#include <stdarg.h>

#include "v8.h"

32
#include "bootstrapper.h"
33
#include "code-stubs.h"
34
#include "cpu-profiler.h"
35
#include "deoptimizer.h"
36
#include "global-handles.h"
37
#include "log.h"
38
#include "log-utils.h"
39
#include "macro-assembler.h"
40
#include "platform.h"
41
#include "runtime-profiler.h"
42
#include "serialize.h"
43
#include "string-stream.h"
44
#include "vm-state-inl.h"
45

46 47
namespace v8 {
namespace internal {
48

49

50 51 52 53 54 55 56
#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


57 58 59 60 61
#define CALL_LISTENERS(Call)                    \
for (int i = 0; i < listeners_.length(); ++i) { \
  listeners_[i]->Call;                          \
}

62 63 64 65 66 67 68 69
#define PROFILER_LOG(Call)                                \
  do {                                                    \
    CpuProfiler* cpu_profiler = isolate_->cpu_profiler(); \
    if (cpu_profiler->is_profiling()) {                   \
      cpu_profiler->Call;                                 \
    }                                                     \
  } while (false);

70 71 72 73 74 75 76 77 78 79
// ComputeMarker must only be used when SharedFunctionInfo is known.
static const char* ComputeMarker(Code* code) {
  switch (code->kind()) {
    case Code::FUNCTION: return code->optimizable() ? "~" : "";
    case Code::OPTIMIZED_FUNCTION: return "*";
    default: return "";
  }
}


80
class CodeEventLogger::NameBuffer {
81
 public:
82
  NameBuffer() { Reset(); }
83

84 85 86
  void Reset() {
    utf8_pos_ = 0;
  }
87

88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103
  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("\" ");
104
      }
105 106 107
      AppendBytes("hash ");
      AppendHex(symbol->Hash());
      AppendByte(')');
108
    }
109
  }
110

111 112 113 114 115 116 117 118 119 120 121 122 123 124
  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;
125
      }
126
      previous = c;
127
    }
128
  }
129

130 131 132 133 134
  void AppendBytes(const char* bytes, int size) {
    size = Min(size, kUtf8BufferSize - utf8_pos_);
    OS::MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
    utf8_pos_ += size;
  }
135

136 137 138
  void AppendBytes(const char* bytes) {
    AppendBytes(bytes, StrLength(bytes));
  }
139

140 141 142 143
  void AppendByte(char c) {
    if (utf8_pos_ >= kUtf8BufferSize) return;
    utf8_buffer_[utf8_pos_++] = c;
  }
144

145 146 147 148 149 150
  void AppendInt(int n) {
    Vector<char> buffer(utf8_buffer_ + utf8_pos_,
                        kUtf8BufferSize - utf8_pos_);
    int size = OS::SNPrintF(buffer, "%d", n);
    if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
      utf8_pos_ += size;
151
    }
152
  }
153

154 155 156 157 158 159
  void AppendHex(uint32_t n) {
    Vector<char> buffer(utf8_buffer_ + utf8_pos_,
                        kUtf8BufferSize - utf8_pos_);
    int size = OS::SNPrintF(buffer, "%x", n);
    if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
      utf8_pos_ += size;
160
    }
161
  }
162

163 164
  const char* get() { return utf8_buffer_; }
  int size() const { return utf8_pos_; }
165 166

 private:
167 168
  static const int kUtf8BufferSize = 512;
  static const int kUtf16BufferSize = 128;
169

170 171 172
  int utf8_pos_;
  char utf8_buffer_[kUtf8BufferSize];
  uc16 utf16_buffer[kUtf16BufferSize];
173 174 175
};


176 177 178 179 180
CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { }

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


181 182 183
void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
                                      Code* code,
                                      const char* comment) {
184 185 186
  name_buffer_->Init(tag);
  name_buffer_->AppendBytes(comment);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
187 188 189 190 191 192
}


void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
                                      Code* code,
                                      Name* name) {
193 194 195
  name_buffer_->Init(tag);
  name_buffer_->AppendName(name);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
196 197 198 199
}


void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
200 201 202 203 204 205 206 207
                                      Code* code,
                                      SharedFunctionInfo* shared,
                                      CompilationInfo* info,
                                      Name* name) {
  name_buffer_->Init(tag);
  name_buffer_->AppendBytes(ComputeMarker(code));
  name_buffer_->AppendName(name);
  LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
208 209 210 211
}


void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
212 213 214
                                      Code* code,
                                      SharedFunctionInfo* shared,
                                      CompilationInfo* info,
215
                                      Name* source, int line, int column) {
216 217 218 219
  name_buffer_->Init(tag);
  name_buffer_->AppendBytes(ComputeMarker(code));
  name_buffer_->AppendString(shared->DebugName());
  name_buffer_->AppendByte(' ');
220
  if (source->IsString()) {
221
    name_buffer_->AppendString(String::cast(source));
222
  } else {
223 224 225
    name_buffer_->AppendBytes("symbol(hash ");
    name_buffer_->AppendHex(Name::cast(source)->Hash());
    name_buffer_->AppendByte(')');
226
  }
227 228 229
  name_buffer_->AppendByte(':');
  name_buffer_->AppendInt(line);
  LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
230 231 232 233 234 235
}


void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
                                      Code* code,
                                      int args_count) {
236 237 238
  name_buffer_->Init(tag);
  name_buffer_->AppendInt(args_count);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
239 240 241 242
}


void CodeEventLogger::RegExpCodeCreateEvent(Code* code, String* source) {
243 244 245
  name_buffer_->Init(Logger::REG_EXP_TAG);
  name_buffer_->AppendString(source);
  LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
246 247 248
}


249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 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 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 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 468 469 470 471 472 473
// Linux perf tool logging support
class PerfBasicLogger : public CodeEventLogger {
 public:
  PerfBasicLogger();
  virtual ~PerfBasicLogger();

  virtual void CodeMoveEvent(Address from, Address to) { }
  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);
  int size = OS::SNPrintF(
      perf_dump_name,
      kFilenameFormatString,
      OS::GetCurrentProcessId());
  CHECK_NE(size, -1);
  perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);
  CHECK_NE(perf_output_handle_, NULL);
  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) {
  ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);

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


// Linux perf tool logging support
class PerfJitLogger : public CodeEventLogger {
 public:
  PerfJitLogger();
  virtual ~PerfJitLogger();

  virtual void CodeMoveEvent(Address from, Address to) { }
  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;

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

  static const uint32_t kJitHeaderMagic = 0x4F74496A;
  static const uint32_t kJitHeaderVersion = 0x2;
  static const uint32_t kElfMachIA32 = 3;
  static const uint32_t kElfMachX64 = 62;
  static const uint32_t kElfMachARM = 40;
  static const uint32_t kElfMachMIPS = 10;

  struct jitheader {
    uint32_t magic;
    uint32_t version;
    uint32_t total_size;
    uint32_t elf_mach;
    uint32_t pad1;
    uint32_t pid;
    uint64_t timestamp;
  };

  enum jit_record_type {
    JIT_CODE_LOAD = 0
    // JIT_CODE_UNLOAD = 1,
    // JIT_CODE_CLOSE = 2,
    // JIT_CODE_DEBUG_INFO = 3,
    // JIT_CODE_PAGE_MAP = 4,
    // JIT_CODE_MAX = 5
  };

  struct jr_code_load {
    uint32_t id;
    uint32_t total_size;
    uint64_t timestamp;
    uint64_t vma;
    uint64_t code_addr;
    uint32_t code_size;
    uint32_t align;
  };

  uint32_t GetElfMach() {
#if V8_TARGET_ARCH_IA32
    return kElfMachIA32;
#elif V8_TARGET_ARCH_X64
    return kElfMachX64;
#elif V8_TARGET_ARCH_ARM
    return kElfMachARM;
#elif V8_TARGET_ARCH_MIPS
    return kElfMachMIPS;
#else
    UNIMPLEMENTED();
    return 0;
#endif
  }

  FILE* perf_output_handle_;
};

const char PerfJitLogger::kFilenameFormatString[] = "/tmp/jit-%d.dump";

// Extra padding for the PID in the filename
const int PerfJitLogger::kFilenameBufferPadding = 16;

PerfJitLogger::PerfJitLogger()
    : perf_output_handle_(NULL) {
  // Open the perf JIT dump file.
  int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
  ScopedVector<char> perf_dump_name(bufferSize);
  int size = OS::SNPrintF(
      perf_dump_name,
      kFilenameFormatString,
      OS::GetCurrentProcessId());
  CHECK_NE(size, -1);
  perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);
  CHECK_NE(perf_output_handle_, NULL);
  setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);

  LogWriteHeader();
}


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


void PerfJitLogger::LogRecordedBuffer(Code* code,
                                      SharedFunctionInfo*,
                                      const char* name,
                                      int length) {
  ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);
  ASSERT(perf_output_handle_ != NULL);

  const char* code_name = name;
  uint8_t* code_pointer = reinterpret_cast<uint8_t*>(code->instruction_start());
  uint32_t code_size = code->instruction_size();

  static const char string_terminator[] = "\0";

  jr_code_load code_load;
  code_load.id = JIT_CODE_LOAD;
  code_load.total_size = sizeof(code_load) + length + 1 + code_size;
  code_load.timestamp =
      static_cast<uint64_t>(OS::TimeCurrentMillis() * 1000.0);
  code_load.vma = 0x0;  //  Our addresses are absolute.
  code_load.code_addr = reinterpret_cast<uint64_t>(code->instruction_start());
  code_load.code_size = code_size;
  code_load.align = 0;

  LogWriteBytes(reinterpret_cast<const char*>(&code_load), sizeof(code_load));
  LogWriteBytes(code_name, length);
  LogWriteBytes(string_terminator, 1);
  LogWriteBytes(reinterpret_cast<const char*>(code_pointer), code_size);
}


void PerfJitLogger::LogWriteBytes(const char* bytes, int size) {
  size_t rv = fwrite(bytes, 1, size, perf_output_handle_);
  ASSERT(static_cast<size_t>(size) == rv);
  USE(rv);
}


void PerfJitLogger::LogWriteHeader() {
  ASSERT(perf_output_handle_ != NULL);
  jitheader header;
  header.magic = kJitHeaderMagic;
  header.version = kJitHeaderVersion;
  header.total_size = sizeof(jitheader);
  header.pad1 = 0xdeadbeef;
  header.elf_mach = GetElfMach();
  header.pid = OS::GetCurrentProcessId();
  header.timestamp = static_cast<uint64_t>(OS::TimeCurrentMillis() * 1000.0);
  LogWriteBytes(reinterpret_cast<const char*>(&header), sizeof(header));
}


474
// Low-level logging support.
475 476
#define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;

477
class LowLevelLogger : public CodeEventLogger {
478 479
 public:
  explicit LowLevelLogger(const char* file_name);
480
  virtual ~LowLevelLogger();
481

482 483 484 485
  virtual void CodeMoveEvent(Address from, Address to);
  virtual void CodeDeleteEvent(Address from);
  virtual void SnapshotPositionEvent(Address addr, int pos);
  virtual void CodeMovingGCEvent();
486 487

 private:
488 489
  virtual void LogRecordedBuffer(Code* code,
                                 SharedFunctionInfo* shared,
490 491
                                 const char* name,
                                 int length);
492

493
  // Low-level profiling event structures.
494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550
  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";

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
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)));
  OS::MemCopy(ll_name.start(), name, len);
  OS::MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
  ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode);
  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";
#elif V8_TARGET_ARCH_X64
  const char arch[] = "x64";
#elif V8_TARGET_ARCH_ARM
  const char arch[] = "arm";
#elif V8_TARGET_ARCH_MIPS
  const char arch[] = "mips";
#else
  const char arch[] = "unknown";
#endif
  LogWriteBytes(arch, sizeof(arch));
}


void LowLevelLogger::LogRecordedBuffer(Code* code,
                                       SharedFunctionInfo*,
589 590
                                       const char* name,
                                       int length) {
591
  CodeCreateStruct event;
592
  event.name_size = length;
593 594 595 596
  event.code_address = code->instruction_start();
  ASSERT(event.code_address == code->address() + Code::kHeaderSize);
  event.code_size = code->instruction_size();
  LogWriteStruct(event);
597
  LogWriteBytes(name, length);
598 599 600 601 602 603 604 605 606 607 608 609 610 611 612 613 614 615 616 617 618 619 620 621 622 623 624 625 626 627 628 629 630 631 632 633 634 635 636 637 638 639 640
  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_);
  ASSERT(static_cast<size_t>(size) == rv);
  USE(rv);
}


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

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


641
#define JIT_LOG(Call) if (jit_logger_) jit_logger_->Call;
642 643


644 645 646 647
class JitLogger : public CodeEventLogger {
 public:
  explicit JitLogger(JitCodeEventHandler code_event_handler);

648 649 650
  virtual void CodeMoveEvent(Address from, Address to);
  virtual void CodeDeleteEvent(Address from);
  virtual void AddCodeLinePosInfoEvent(
651 652 653 654
      void* jit_handler_data,
      int pc_offset,
      int position,
      JitCodeEvent::PositionType position_type);
655

656 657 658 659 660 661
  void* StartCodePosInfoEvent();
  void EndCodePosInfoEvent(Code* code, void* jit_handler_data);

 private:
  virtual void LogRecordedBuffer(Code* code,
                                 SharedFunctionInfo* shared,
662 663
                                 const char* name,
                                 int length);
664 665 666 667 668 669 670 671 672 673 674 675

  JitCodeEventHandler code_event_handler_;
};


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


void JitLogger::LogRecordedBuffer(Code* code,
                                  SharedFunctionInfo* shared,
676 677
                                  const char* name,
                                  int length) {
678 679 680 681 682 683 684 685 686 687
  JitCodeEvent event;
  memset(&event, 0, sizeof(event));
  event.type = JitCodeEvent::CODE_ADDED;
  event.code_start = code->instruction_start();
  event.code_len = code->instruction_size();
  Handle<Script> script_handle;
  if (shared && shared->script()->IsScript()) {
    script_handle = Handle<Script>(Script::cast(shared->script()));
  }
  event.script = ToApiHandle<v8::Script>(script_handle);
688 689
  event.name.str = name;
  event.name.len = length;
690 691 692 693
  code_event_handler_(&event);
}


694
void JitLogger::CodeMoveEvent(Address from, Address to) {
695 696 697 698 699 700 701 702 703 704 705 706 707 708 709 710 711 712 713 714 715 716 717 718 719 720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741 742 743 744 745 746 747 748 749 750 751 752 753 754 755 756 757 758 759 760 761 762
  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);
}


763 764 765 766 767 768 769
// 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.
//
class Profiler: public Thread {
 public:
770
  explicit Profiler(Isolate* isolate);
771 772 773 774 775
  void Engage();
  void Disengage();

  // Inserts collected profiling data into buffer.
  void Insert(TickSample* sample) {
776 777 778
    if (paused_)
      return;

779 780 781 782 783
    if (Succ(head_) == tail_) {
      overflow_ = true;
    } else {
      buffer_[head_] = *sample;
      head_ = Succ(head_);
784
      buffer_semaphore_.Signal();  // Tell we have an element.
785 786 787
    }
  }

788 789 790 791 792 793 794
  virtual void Run();

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

 private:
795 796
  // Waits for a signal and removes profiling data.
  bool Remove(TickSample* sample) {
797
    buffer_semaphore_.Wait();  // Wait for an element.
798 799 800 801 802 803 804 805 806 807
    *sample = buffer_[tail_];
    bool result = overflow_;
    tail_ = Succ(tail_);
    overflow_ = false;
    return result;
  }

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

808
  Isolate* isolate_;
809 810 811 812 813 814 815
  // 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.
  int tail_;  // Index to the buffer tail.
  bool overflow_;  // Tell whether a buffer overflow has occurred.
816
  // Sempahore used for buffer synchronization.
817
  Semaphore buffer_semaphore_;
818

819 820 821
  // Tells whether profiler is engaged, that is, processing thread is stated.
  bool engaged_;

822 823
  // Tells whether worker thread should continue running.
  bool running_;
824 825

  // Tells whether we are currently recording tick samples.
826
  bool paused_;
827 828 829 830 831 832 833
};


//
// Ticker used to provide ticks to the profiler and the sliding state
// window.
//
834
class Ticker: public Sampler {
835
 public:
836
  Ticker(Isolate* isolate, int interval):
837
      Sampler(isolate, interval),
838
      profiler_(NULL) {}
839 840 841

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

842
  virtual void Tick(TickSample* sample) {
843 844 845 846
    if (profiler_) profiler_->Insert(sample);
  }

  void SetProfiler(Profiler* profiler) {
847
    ASSERT(profiler_ == NULL);
848
    profiler_ = profiler;
849
    IncreaseProfilingDepth();
850
    if (!IsActive()) Start();
851 852 853 854
  }

  void ClearProfiler() {
    profiler_ = NULL;
855
    if (IsActive()) Stop();
856
    DecreaseProfilingDepth();
857 858 859 860 861 862 863 864 865 866
  }

 private:
  Profiler* profiler_;
};


//
// Profiler implementation.
//
867
Profiler::Profiler(Isolate* isolate)
868 869
    : Thread("v8:Profiler"),
      isolate_(isolate),
870
      head_(0),
871 872
      tail_(0),
      overflow_(false),
873
      buffer_semaphore_(0),
874
      engaged_(false),
875 876
      running_(false),
      paused_(false) {
877 878 879 880
}


void Profiler::Engage() {
881 882 883
  if (engaged_) return;
  engaged_ = true;

884
  OS::LogSharedLibraryAddresses(isolate_);
885 886 887 888 889 890

  // Start thread processing the profiler buffer.
  running_ = true;
  Start();

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

yurys@chromium.org's avatar
yurys@chromium.org committed
894
  logger->ProfilerBeginEvent();
895 896 897 898
}


void Profiler::Disengage() {
899 900
  if (!engaged_) return;

901
  // Stop receiving ticks.
902
  isolate_->logger()->ticker_->ClearProfiler();
903

904 905 906 907 908 909 910 911 912
  // Terminate the worker thread by setting running_ to false,
  // inserting a fake element in the queue and then wait for
  // the thread to terminate.
  running_ = false;
  TickSample sample;
  // Reset 'paused_' flag, otherwise semaphore may not be signalled.
  resume();
  Insert(&sample);
  Join();
913

dcarney@chromium.org's avatar
dcarney@chromium.org committed
914
  LOG(isolate_, UncheckedStringEvent("profiler", "end"));
915 916
}

917

918 919 920 921 922 923 924
void Profiler::Run() {
  TickSample sample;
  bool overflow = Remove(&sample);
  while (running_) {
    LOG(isolate_, TickEvent(&sample, overflow));
    overflow = Remove(&sample);
  }
925 926
}

927

928 929 930
//
// Logger class implementation.
//
931

932 933 934 935 936
Logger::Logger(Isolate* isolate)
  : isolate_(isolate),
    ticker_(NULL),
    profiler_(NULL),
    log_events_(NULL),
937
    is_logging_(false),
938
    log_(new Log(this)),
939 940
    perf_basic_logger_(NULL),
    perf_jit_logger_(NULL),
941 942
    ll_logger_(NULL),
    jit_logger_(NULL),
943
    listeners_(5),
944
    is_initialized_(false) {
945 946
}

947

948 949
Logger::~Logger() {
  delete log_;
950
}
951

952

953 954 955 956 957 958 959 960 961 962 963 964 965 966 967 968 969
void Logger::addCodeEventListener(CodeEventListener* listener) {
  ASSERT(!hasCodeEventListener(listener));
  listeners_.Add(listener);
}


void Logger::removeCodeEventListener(CodeEventListener* listener) {
  ASSERT(hasCodeEventListener(listener));
  listeners_.RemoveElement(listener);
}


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


970
void Logger::ProfilerBeginEvent() {
971
  if (!log_->IsEnabled()) return;
972
  Log::MessageBuilder msg(log_);
973
  msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
974 975 976
  msg.WriteToLogFile();
}

977

978
void Logger::StringEvent(const char* name, const char* value) {
979 980 981 982 983
  if (FLAG_log) UncheckedStringEvent(name, value);
}


void Logger::UncheckedStringEvent(const char* name, const char* value) {
984
  if (!log_->IsEnabled()) return;
985
  Log::MessageBuilder msg(log_);
986 987
  msg.Append("%s,\"%s\"\n", name, value);
  msg.WriteToLogFile();
988 989 990 991
}


void Logger::IntEvent(const char* name, int value) {
992 993 994 995
  if (FLAG_log) UncheckedIntEvent(name, value);
}


996 997 998 999 1000
void Logger::IntPtrTEvent(const char* name, intptr_t value) {
  if (FLAG_log) UncheckedIntPtrTEvent(name, value);
}


1001
void Logger::UncheckedIntEvent(const char* name, int value) {
1002
  if (!log_->IsEnabled()) return;
1003
  Log::MessageBuilder msg(log_);
1004 1005
  msg.Append("%s,%d\n", name, value);
  msg.WriteToLogFile();
1006 1007 1008
}


1009
void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
1010
  if (!log_->IsEnabled()) return;
1011
  Log::MessageBuilder msg(log_);
1012 1013 1014 1015 1016
  msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
  msg.WriteToLogFile();
}


1017
void Logger::HandleEvent(const char* name, Object** location) {
1018
  if (!log_->IsEnabled() || !FLAG_log_handles) return;
1019
  Log::MessageBuilder msg(log_);
1020
  msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
1021
  msg.WriteToLogFile();
1022 1023 1024 1025
}


// ApiEvent is private so all the calls come from the Logger class.  It is the
1026
// caller's responsibility to ensure that log is enabled and that
1027 1028
// FLAG_log_api is true.
void Logger::ApiEvent(const char* format, ...) {
1029
  ASSERT(log_->IsEnabled() && FLAG_log_api);
1030
  Log::MessageBuilder msg(log_);
1031 1032
  va_list ap;
  va_start(ap, format);
1033
  msg.AppendVA(format, ap);
1034 1035
  va_end(ap);
  msg.WriteToLogFile();
1036 1037 1038 1039
}


void Logger::ApiNamedSecurityCheck(Object* key) {
1040
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1041
  if (key->IsString()) {
1042
    SmartArrayPointer<char> str =
1043
        String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1044
    ApiEvent("api,check-security,\"%s\"\n", str.get());
1045
  } else if (key->IsSymbol()) {
1046 1047 1048 1049 1050 1051 1052 1053
    Symbol* symbol = Symbol::cast(key);
    if (symbol->name()->IsUndefined()) {
      ApiEvent("api,check-security,symbol(hash %x)\n",
               Symbol::cast(key)->Hash());
    } else {
      SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
          DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
      ApiEvent("api,check-security,symbol(\"%s\" hash %x)\n",
1054
               str.get(),
1055 1056
               Symbol::cast(key)->Hash());
    }
1057 1058 1059 1060 1061 1062 1063 1064 1065
  } else if (key->IsUndefined()) {
    ApiEvent("api,check-security,undefined\n");
  } else {
    ApiEvent("api,check-security,['no-name']\n");
  }
}


void Logger::SharedLibraryEvent(const char* library_path,
1066 1067
                                uintptr_t start,
                                uintptr_t end) {
1068
  if (!log_->IsEnabled() || !FLAG_prof) return;
1069
  Log::MessageBuilder msg(log_);
1070 1071 1072 1073
  msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
             library_path,
             start,
             end);
1074
  msg.WriteToLogFile();
1075 1076 1077 1078
}


void Logger::SharedLibraryEvent(const wchar_t* library_path,
1079 1080
                                uintptr_t start,
                                uintptr_t end) {
1081
  if (!log_->IsEnabled() || !FLAG_prof) return;
1082
  Log::MessageBuilder msg(log_);
1083 1084 1085 1086
  msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
             library_path,
             start,
             end);
1087
  msg.WriteToLogFile();
1088 1089
}

1090

1091 1092 1093
void Logger::CodeDeoptEvent(Code* code) {
  if (!log_->IsEnabled()) return;
  ASSERT(FLAG_log_internal_timer_events);
1094
  Log::MessageBuilder msg(log_);
1095
  int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
1096 1097 1098 1099 1100
  msg.Append("code-deopt,%ld,%d\n", since_epoch, code->CodeSize());
  msg.WriteToLogFile();
}


1101
void Logger::TimerEvent(StartEnd se, const char* name) {
1102
  if (!log_->IsEnabled()) return;
1103
  ASSERT(FLAG_log_internal_timer_events);
1104
  Log::MessageBuilder msg(log_);
1105
  int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
1106 1107 1108
  const char* format = (se == START) ? "timer-event-start,\"%s\",%ld\n"
                                     : "timer-event-end,\"%s\",%ld\n";
  msg.Append(format, name, since_epoch);
1109 1110 1111 1112
  msg.WriteToLogFile();
}


1113 1114 1115 1116
void Logger::EnterExternal(Isolate* isolate) {
  LOG(isolate, TimerEvent(START, TimerEventScope::v8_external));
  ASSERT(isolate->current_vm_state() == JS);
  isolate->set_current_vm_state(EXTERNAL);
1117 1118 1119
}


1120 1121 1122 1123
void Logger::LeaveExternal(Isolate* isolate) {
  LOG(isolate, TimerEvent(END, TimerEventScope::v8_external));
  ASSERT(isolate->current_vm_state() == EXTERNAL);
  isolate->set_current_vm_state(JS);
1124 1125 1126
}


1127 1128 1129 1130 1131 1132
void Logger::LogInternalEvents(const char* name, int se) {
  Isolate* isolate = Isolate::Current();
  LOG(isolate, TimerEvent(static_cast<StartEnd>(se), name));
}


1133
void Logger::TimerEventScope::LogTimerEvent(StartEnd se) {
1134
  isolate_->event_logger()(name_, se);
1135 1136 1137
}


1138 1139
const char* Logger::TimerEventScope::v8_recompile_synchronous =
    "V8.RecompileSynchronous";
1140 1141
const char* Logger::TimerEventScope::v8_recompile_concurrent =
    "V8.RecompileConcurrent";
1142 1143 1144
const char* Logger::TimerEventScope::v8_compile_full_code =
    "V8.CompileFullCode";
const char* Logger::TimerEventScope::v8_execute = "V8.Execute";
1145
const char* Logger::TimerEventScope::v8_external = "V8.External";
1146 1147


1148
void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
1149
  // Prints "/" + re.source + "/" +
1150
  //      (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
1151
  Log::MessageBuilder msg(log_);
1152 1153 1154

  Handle<Object> source = GetProperty(regexp, "source");
  if (!source->IsString()) {
1155
    msg.Append("no source");
1156 1157 1158
    return;
  }

1159
  switch (regexp->TypeTag()) {
1160
    case JSRegExp::ATOM:
1161
      msg.Append('a');
1162 1163 1164 1165
      break;
    default:
      break;
  }
1166 1167 1168
  msg.Append('/');
  msg.AppendDetailed(*Handle<String>::cast(source), false);
  msg.Append('/');
1169 1170 1171 1172

  // global flag
  Handle<Object> global = GetProperty(regexp, "global");
  if (global->IsTrue()) {
1173
    msg.Append('g');
1174 1175 1176 1177
  }
  // ignorecase flag
  Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
  if (ignorecase->IsTrue()) {
1178
    msg.Append('i');
1179 1180 1181 1182
  }
  // multiline flag
  Handle<Object> multiline = GetProperty(regexp, "multiline");
  if (multiline->IsTrue()) {
1183
    msg.Append('m');
1184
  }
1185 1186

  msg.WriteToLogFile();
1187 1188 1189
}


1190
void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
1191
  if (!log_->IsEnabled() || !FLAG_log_regexp) return;
1192
  Log::MessageBuilder msg(log_);
1193
  msg.Append("regexp-compile,");
1194
  LogRegExpSource(regexp);
1195 1196
  msg.Append(in_cache ? ",hit\n" : ",miss\n");
  msg.WriteToLogFile();
1197 1198 1199
}


yurys@chromium.org's avatar
yurys@chromium.org committed
1200
void Logger::LogRuntime(Vector<const char> format,
1201
                        Handle<JSArray> args) {
1202
  if (!log_->IsEnabled() || !FLAG_log_runtime) return;
1203
  Log::MessageBuilder msg(log_);
1204 1205 1206 1207 1208
  for (int i = 0; i < format.length(); i++) {
    char c = format[i];
    if (c == '%' && i <= format.length() - 2) {
      i++;
      ASSERT('0' <= format[i] && format[i] <= '9');
1209
      // No exception expected when getting an element from an array literal.
1210 1211
      Handle<Object> obj =
          Object::GetElementNoExceptionThrown(isolate_, args, format[i] - '0');
1212 1213 1214
      i++;
      switch (format[i]) {
        case 's':
1215
          msg.AppendDetailed(String::cast(*obj), false);
1216 1217
          break;
        case 'S':
1218
          msg.AppendDetailed(String::cast(*obj), true);
1219 1220
          break;
        case 'r':
1221
          Logger::LogRegExpSource(Handle<JSRegExp>::cast(obj));
1222 1223
          break;
        case 'x':
1224
          msg.Append("0x%x", Smi::cast(*obj)->value());
1225 1226
          break;
        case 'i':
1227
          msg.Append("%i", Smi::cast(*obj)->value());
1228 1229 1230 1231 1232
          break;
        default:
          UNREACHABLE();
      }
    } else {
1233
      msg.Append(c);
1234 1235
    }
  }
1236 1237
  msg.Append('\n');
  msg.WriteToLogFile();
1238 1239 1240
}


1241
void Logger::ApiIndexedSecurityCheck(uint32_t index) {
1242
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1243 1244 1245 1246 1247 1248 1249
  ApiEvent("api,check-security,%u\n", index);
}


void Logger::ApiNamedPropertyAccess(const char* tag,
                                    JSObject* holder,
                                    Object* name) {
1250
  ASSERT(name->IsName());
1251
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1252
  String* class_name_obj = holder->class_name();
1253
  SmartArrayPointer<char> class_name =
1254
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1255 1256 1257
  if (name->IsString()) {
    SmartArrayPointer<char> property_name =
        String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1258 1259
    ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, class_name.get(),
             property_name.get());
1260
  } else {
1261 1262 1263
    Symbol* symbol = Symbol::cast(name);
    uint32_t hash = symbol->Hash();
    if (symbol->name()->IsUndefined()) {
1264
      ApiEvent("api,%s,\"%s\",symbol(hash %x)\n", tag, class_name.get(), hash);
1265 1266 1267 1268
    } else {
      SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
          DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
      ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)\n",
1269
               tag, class_name.get(), str.get(), hash);
1270
    }
1271
  }
1272 1273 1274 1275 1276
}

void Logger::ApiIndexedPropertyAccess(const char* tag,
                                      JSObject* holder,
                                      uint32_t index) {
1277
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1278
  String* class_name_obj = holder->class_name();
1279
  SmartArrayPointer<char> class_name =
1280
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1281
  ApiEvent("api,%s,\"%s\",%u\n", tag, class_name.get(), index);
1282 1283
}

1284

1285
void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
1286
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1287
  String* class_name_obj = object->class_name();
1288
  SmartArrayPointer<char> class_name =
1289
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1290
  ApiEvent("api,%s,\"%s\"\n", tag, class_name.get());
1291 1292 1293 1294
}


void Logger::ApiEntryCall(const char* name) {
1295
  if (!log_->IsEnabled() || !FLAG_log_api) return;
1296
  ApiEvent("api,%s\n", name);
1297 1298 1299 1300
}


void Logger::NewEvent(const char* name, void* object, size_t size) {
1301
  if (!log_->IsEnabled() || !FLAG_log) return;
1302
  Log::MessageBuilder msg(log_);
1303
  msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
1304 1305
             static_cast<unsigned int>(size));
  msg.WriteToLogFile();
1306 1307 1308 1309
}


void Logger::DeleteEvent(const char* name, void* object) {
1310
  if (!log_->IsEnabled() || !FLAG_log) return;
1311
  Log::MessageBuilder msg(log_);
1312
  msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
1313
  msg.WriteToLogFile();
1314 1315 1316
}


1317
void Logger::NewEventStatic(const char* name, void* object, size_t size) {
yurys@chromium.org's avatar
yurys@chromium.org committed
1318
  Isolate::Current()->logger()->NewEvent(name, object, size);
1319 1320 1321 1322
}


void Logger::DeleteEventStatic(const char* name, void* object) {
yurys@chromium.org's avatar
yurys@chromium.org committed
1323
  Isolate::Current()->logger()->DeleteEvent(name, object);
1324 1325
}

1326

1327
void Logger::CallbackEventInternal(const char* prefix, Name* name,
1328
                                   Address entry_point) {
1329
  if (!FLAG_log_code || !log_->IsEnabled()) return;
1330
  Log::MessageBuilder msg(log_);
1331
  msg.Append("%s,%s,-2,",
1332 1333
             kLogEventsNames[CODE_CREATION_EVENT],
             kLogEventsNames[CALLBACK_TAG]);
1334
  msg.AppendAddress(entry_point);
1335 1336 1337
  if (name->IsString()) {
    SmartArrayPointer<char> str =
        String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1338
    msg.Append(",1,\"%s%s\"", prefix, str.get());
1339
  } else {
1340 1341 1342 1343 1344 1345
    Symbol* symbol = Symbol::cast(name);
    if (symbol->name()->IsUndefined()) {
      msg.Append(",1,symbol(hash %x)", prefix, symbol->Hash());
    } else {
      SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
          DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1346 1347
      msg.Append(",1,symbol(\"%s\" hash %x)", prefix, str.get(),
                 symbol->Hash());
1348
    }
1349
  }
1350 1351
  msg.Append('\n');
  msg.WriteToLogFile();
1352 1353 1354
}


1355
void Logger::CallbackEvent(Name* name, Address entry_point) {
1356
  PROFILER_LOG(CallbackEvent(name, entry_point));
1357
  CallbackEventInternal("", name, entry_point);
1358 1359 1360
}


1361
void Logger::GetterCallbackEvent(Name* name, Address entry_point) {
1362
  PROFILER_LOG(GetterCallbackEvent(name, entry_point));
1363
  CallbackEventInternal("get ", name, entry_point);
1364 1365 1366
}


1367
void Logger::SetterCallbackEvent(Name* name, Address entry_point) {
1368
  PROFILER_LOG(SetterCallbackEvent(name, entry_point));
1369
  CallbackEventInternal("set ", name, entry_point);
1370 1371 1372
}


1373 1374 1375
static void AppendCodeCreateHeader(Log::MessageBuilder* msg,
                                   Logger::LogEventsAndTags tag,
                                   Code* code) {
1376 1377
  ASSERT(msg);
  msg->Append("%s,%s,%d,",
1378
              kLogEventsNames[Logger::CODE_CREATION_EVENT],
1379 1380 1381 1382 1383 1384 1385
              kLogEventsNames[tag],
              code->kind());
  msg->AppendAddress(code->address());
  msg->Append(",%d,", code->ExecutableSize());
}


1386 1387 1388
void Logger::CodeCreateEvent(LogEventsAndTags tag,
                             Code* code,
                             const char* comment) {
1389
  PROFILER_LOG(CodeCreateEvent(tag, code, comment));
1390

1391
  if (!is_logging_code_events()) return;
1392
  CALL_LISTENERS(CodeCreateEvent(tag, code, comment));
1393 1394

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1395
  Log::MessageBuilder msg(log_);
1396 1397
  AppendCodeCreateHeader(&msg, tag, code);
  msg.AppendDoubleQuotedString(comment);
1398 1399
  msg.Append('\n');
  msg.WriteToLogFile();
1400 1401 1402
}


1403 1404
void Logger::CodeCreateEvent(LogEventsAndTags tag,
                             Code* code,
1405
                             Name* name) {
1406
  PROFILER_LOG(CodeCreateEvent(tag, code, name));
1407

1408
  if (!is_logging_code_events()) return;
1409
  CALL_LISTENERS(CodeCreateEvent(tag, code, name));
1410 1411

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1412
  Log::MessageBuilder msg(log_);
1413
  AppendCodeCreateHeader(&msg, tag, code);
1414 1415 1416 1417 1418
  if (name->IsString()) {
    msg.Append('"');
    msg.AppendDetailed(String::cast(name), false);
    msg.Append('"');
  } else {
1419
    msg.AppendSymbolName(Symbol::cast(name));
1420
  }
1421 1422
  msg.Append('\n');
  msg.WriteToLogFile();
1423 1424 1425 1426 1427 1428
}


void Logger::CodeCreateEvent(LogEventsAndTags tag,
                             Code* code,
                             SharedFunctionInfo* shared,
1429
                             CompilationInfo* info,
1430
                             Name* name) {
1431
  PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, name));
1432

1433
  if (!is_logging_code_events()) return;
1434
  CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, name));
1435 1436

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1437
  if (code == isolate_->builtins()->builtin(Builtins::kCompileUnoptimized))
1438 1439
    return;

1440
  Log::MessageBuilder msg(log_);
1441
  AppendCodeCreateHeader(&msg, tag, code);
1442 1443 1444
  if (name->IsString()) {
    SmartArrayPointer<char> str =
        String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1445
    msg.Append("\"%s\"", str.get());
1446
  } else {
1447
    msg.AppendSymbolName(Symbol::cast(name));
1448 1449
  }
  msg.Append(',');
1450 1451
  msg.AppendAddress(shared->address());
  msg.Append(",%s", ComputeMarker(code));
1452
  msg.Append('\n');
1453
  msg.WriteToLogFile();
1454 1455 1456
}


1457 1458 1459
// 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.
1460
void Logger::CodeCreateEvent(LogEventsAndTags tag,
1461 1462
                             Code* code,
                             SharedFunctionInfo* shared,
1463
                             CompilationInfo* info,
1464
                             Name* source, int line, int column) {
1465
  PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, source, line, column));
1466

1467
  if (!is_logging_code_events()) return;
1468 1469
  CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, source, line,
                                 column));
1470 1471

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1472
  Log::MessageBuilder msg(log_);
1473
  AppendCodeCreateHeader(&msg, tag, code);
1474
  SmartArrayPointer<char> name =
1475
      shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1476
  msg.Append("\"%s ", name.get());
1477 1478 1479
  if (source->IsString()) {
    SmartArrayPointer<char> sourcestr =
       String::cast(source)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1480
    msg.Append("%s", sourcestr.get());
1481
  } else {
1482
    msg.AppendSymbolName(Symbol::cast(source));
1483
  }
1484
  msg.Append(":%d:%d\",", line, column);
1485 1486
  msg.AppendAddress(shared->address());
  msg.Append(",%s", ComputeMarker(code));
1487
  msg.Append('\n');
1488
  msg.WriteToLogFile();
1489 1490 1491
}


1492 1493 1494
void Logger::CodeCreateEvent(LogEventsAndTags tag,
                             Code* code,
                             int args_count) {
1495
  PROFILER_LOG(CodeCreateEvent(tag, code, args_count));
1496

1497
  if (!is_logging_code_events()) return;
1498
  CALL_LISTENERS(CodeCreateEvent(tag, code, args_count));
1499 1500

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1501
  Log::MessageBuilder msg(log_);
1502 1503
  AppendCodeCreateHeader(&msg, tag, code);
  msg.Append("\"args_count: %d\"", args_count);
1504
  msg.Append('\n');
1505
  msg.WriteToLogFile();
1506 1507 1508
}


1509
void Logger::CodeMovingGCEvent() {
1510 1511 1512
  PROFILER_LOG(CodeMovingGCEvent());

  if (!is_logging_code_events()) return;
1513
  if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1514
  CALL_LISTENERS(CodeMovingGCEvent());
1515 1516 1517 1518
  OS::SignalCodeMovingGC();
}


1519
void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
1520
  PROFILER_LOG(RegExpCodeCreateEvent(code, source));
1521

1522
  if (!is_logging_code_events()) return;
1523
  CALL_LISTENERS(RegExpCodeCreateEvent(code, source));
1524 1525

  if (!FLAG_log_code || !log_->IsEnabled()) return;
1526
  Log::MessageBuilder msg(log_);
1527 1528
  AppendCodeCreateHeader(&msg, REG_EXP_TAG, code);
  msg.Append('"');
1529
  msg.AppendDetailed(source, false);
1530
  msg.Append('"');
1531
  msg.Append('\n');
1532 1533 1534 1535
  msg.WriteToLogFile();
}


1536
void Logger::CodeMoveEvent(Address from, Address to) {
1537 1538 1539
  PROFILER_LOG(CodeMoveEvent(from, to));

  if (!is_logging_code_events()) return;
1540
  CALL_LISTENERS(CodeMoveEvent(from, to));
1541 1542 1543 1544 1545
  MoveEventInternal(CODE_MOVE_EVENT, from, to);
}


void Logger::CodeDeleteEvent(Address from) {
1546 1547 1548
  PROFILER_LOG(CodeDeleteEvent(from));

  if (!is_logging_code_events()) return;
1549
  CALL_LISTENERS(CodeDeleteEvent(from));
1550

1551
  if (!FLAG_log_code || !log_->IsEnabled()) return;
1552 1553 1554 1555 1556
  Log::MessageBuilder msg(log_);
  msg.Append("%s,", kLogEventsNames[CODE_DELETE_EVENT]);
  msg.AppendAddress(from);
  msg.Append('\n');
  msg.WriteToLogFile();
1557 1558
}

1559

1560 1561 1562
void Logger::CodeLinePosInfoAddPositionEvent(void* jit_handler_data,
                                     int pc_offset,
                                     int position) {
1563 1564 1565 1566
  JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
                                  pc_offset,
                                  position,
                                  JitCodeEvent::POSITION));
1567 1568
}

1569

1570 1571 1572
void Logger::CodeLinePosInfoAddStatementPositionEvent(void* jit_handler_data,
                                                      int pc_offset,
                                                      int position) {
1573 1574 1575 1576
  JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
                                  pc_offset,
                                  position,
                                  JitCodeEvent::STATEMENT_POSITION));
1577 1578
}

1579

1580
void Logger::CodeStartLinePosInfoRecordEvent(PositionsRecorder* pos_recorder) {
1581 1582
  if (jit_logger_ != NULL) {
      pos_recorder->AttachJITHandlerData(jit_logger_->StartCodePosInfoEvent());
1583 1584 1585
  }
}

1586

1587 1588
void Logger::CodeEndLinePosInfoRecordEvent(Code* code,
                                           void* jit_handler_data) {
1589
  JIT_LOG(EndCodePosInfoEvent(code, jit_handler_data));
1590
}
1591

1592

1593 1594 1595 1596 1597 1598 1599 1600 1601 1602
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.Append("\n");
  msg.WriteToLogFile();
}


1603
void Logger::SnapshotPositionEvent(Address addr, int pos) {
1604
  if (!log_->IsEnabled()) return;
1605
  LL_LOG(SnapshotPositionEvent(addr, pos));
1606
  if (!FLAG_log_snapshot_positions) return;
1607
  Log::MessageBuilder msg(log_);
1608
  msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
1609 1610 1611 1612 1613 1614 1615
  msg.AppendAddress(addr);
  msg.Append(",%d", pos);
  msg.Append('\n');
  msg.WriteToLogFile();
}


1616
void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1617 1618 1619
  PROFILER_LOG(SharedFunctionInfoMoveEvent(from, to));

  if (!is_logging_code_events()) return;
1620
  MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to);
1621 1622 1623 1624 1625 1626
}


void Logger::MoveEventInternal(LogEventsAndTags event,
                               Address from,
                               Address to) {
1627
  if (!FLAG_log_code || !log_->IsEnabled()) return;
1628
  Log::MessageBuilder msg(log_);
1629
  msg.Append("%s,", kLogEventsNames[event]);
1630
  msg.AppendAddress(from);
1631
  msg.Append(',');
1632
  msg.AppendAddress(to);
1633
  msg.Append('\n');
1634
  msg.WriteToLogFile();
1635 1636 1637
}


1638
void Logger::ResourceEvent(const char* name, const char* tag) {
1639
  if (!log_->IsEnabled() || !FLAG_log) return;
1640
  Log::MessageBuilder msg(log_);
1641
  msg.Append("%s,%s,", name, tag);
1642 1643 1644

  uint32_t sec, usec;
  if (OS::GetUserTime(&sec, &usec) != -1) {
1645
    msg.Append("%d,%d,", sec, usec);
1646
  }
1647
  msg.Append("%.0f", OS::TimeCurrentMillis());
1648

1649 1650
  msg.Append('\n');
  msg.WriteToLogFile();
1651 1652 1653
}


1654
void Logger::SuspectReadEvent(Name* name, Object* obj) {
1655
  if (!log_->IsEnabled() || !FLAG_log_suspect) return;
1656
  Log::MessageBuilder msg(log_);
1657 1658
  String* class_name = obj->IsJSObject()
                       ? JSObject::cast(obj)->class_name()
1659
                       : isolate_->heap()->empty_string();
1660 1661 1662
  msg.Append("suspect-read,");
  msg.Append(class_name);
  msg.Append(',');
1663 1664 1665 1666 1667
  if (name->IsString()) {
    msg.Append('"');
    msg.Append(String::cast(name));
    msg.Append('"');
  } else {
1668
    msg.AppendSymbolName(Symbol::cast(name));
1669
  }
1670 1671
  msg.Append('\n');
  msg.WriteToLogFile();
1672 1673 1674 1675
}


void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
1676
  if (!log_->IsEnabled() || !FLAG_log_gc) return;
1677
  Log::MessageBuilder msg(log_);
1678 1679 1680 1681 1682 1683 1684 1685
  // Using non-relative system time in order to be able to synchronize with
  // external memory profiling events (e.g. DOM memory size).
  msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
             space, kind, OS::TimeCurrentMillis());
  msg.WriteToLogFile();
}


1686
void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1687
  if (!log_->IsEnabled() || !FLAG_log_gc) return;
1688
  Log::MessageBuilder msg(log_);
1689 1690
  msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
  msg.WriteToLogFile();
1691 1692 1693 1694
}


void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1695
  if (!log_->IsEnabled() || !FLAG_log_gc) return;
1696
  Log::MessageBuilder msg(log_);
1697 1698
  msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
  msg.WriteToLogFile();
1699 1700 1701
}


1702
void Logger::DebugTag(const char* call_site_tag) {
1703
  if (!log_->IsEnabled() || !FLAG_log) return;
1704
  Log::MessageBuilder msg(log_);
1705 1706
  msg.Append("debug-tag,%s\n", call_site_tag);
  msg.WriteToLogFile();
1707 1708 1709 1710
}


void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1711
  if (!log_->IsEnabled() || !FLAG_log) return;
1712 1713 1714 1715 1716
  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();
1717
  Log::MessageBuilder msg(log_);
1718 1719 1720 1721
  msg.Append("debug-queue-event,%s,%15.3f,%s\n",
             event_type,
             OS::TimeCurrentMillis(),
             parameter_string);
1722
  DeleteArray(parameter_string);
1723
  msg.WriteToLogFile();
1724 1725 1726
}


1727
void Logger::TickEvent(TickSample* sample, bool overflow) {
1728
  if (!log_->IsEnabled() || !FLAG_prof) return;
1729
  Log::MessageBuilder msg(log_);
1730 1731
  msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
  msg.AppendAddress(sample->pc);
1732
  msg.Append(",%ld", static_cast<int>(timer_.Elapsed().InMicroseconds()));
1733 1734 1735 1736 1737 1738 1739
  if (sample->has_external_callback) {
    msg.Append(",1,");
    msg.AppendAddress(sample->external_callback);
  } else {
    msg.Append(",0,");
    msg.AppendAddress(sample->tos);
  }
1740
  msg.Append(",%d", static_cast<int>(sample->state));
1741 1742 1743
  if (overflow) {
    msg.Append(",overflow");
  }
1744
  for (int i = 0; i < sample->frames_count; ++i) {
1745
    msg.Append(',');
1746
    msg.AppendAddress(sample->stack[i]);
1747
  }
1748 1749
  msg.Append('\n');
  msg.WriteToLogFile();
1750
}
1751 1752


1753
void Logger::StopProfiler() {
1754
  if (!log_->IsEnabled()) return;
1755
  if (profiler_ != NULL) {
1756 1757
    profiler_->pause();
    is_logging_ = false;
1758
  }
1759
}
1760 1761


1762 1763
// This function can be called when Log's mutex is acquired,
// either from main or Profiler's thread.
1764
void Logger::LogFailure() {
1765
  StopProfiler();
1766 1767 1768
}


1769 1770 1771 1772 1773 1774 1775 1776 1777 1778 1779
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) {
1780 1781 1782 1783
    SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
    Object* maybe_script = sfi->script();
    if (maybe_script->IsScript()
        && !Script::cast(maybe_script)->HasValidSource()) return;
1784
    if (sfis_ != NULL) {
1785
      sfis_[*count_] = Handle<SharedFunctionInfo>(sfi);
1786 1787 1788 1789 1790 1791 1792 1793 1794 1795 1796 1797 1798 1799 1800
    }
    if (code_objects_ != NULL) {
      ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
      code_objects_[*count_] = Handle<Code>(function->code());
    }
    *count_ = *count_ + 1;
  }

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


1801 1802
static int EnumerateCompiledFunctions(Heap* heap,
                                      Handle<SharedFunctionInfo>* sfis,
1803
                                      Handle<Code>* code_objects) {
1804
  HeapIterator iterator(heap);
1805
  DisallowHeapAllocation no_gc;
1806
  int compiled_funcs_count = 0;
1807 1808 1809

  // Iterate the heap to find shared function info objects and record
  // the unoptimized code for them.
1810
  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1811 1812 1813 1814 1815
    if (!obj->IsSharedFunctionInfo()) continue;
    SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
    if (sfi->is_compiled()
        && (!sfi->script()->IsScript()
            || Script::cast(sfi->script())->HasValidSource())) {
1816
      if (sfis != NULL) {
1817
        sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1818 1819 1820 1821
      }
      if (code_objects != NULL) {
        code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
      }
1822
      ++compiled_funcs_count;
1823
    }
1824
  }
1825 1826 1827 1828 1829

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

1832 1833
  return compiled_funcs_count;
}
1834 1835


1836
void Logger::LogCodeObject(Object* object) {
1837 1838 1839 1840 1841 1842 1843
  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.
1844
    case Code::BINARY_OP_IC:
1845 1846 1847 1848 1849 1850 1851 1852 1853 1854
    case Code::COMPARE_IC:  // fall through
    case Code::COMPARE_NIL_IC:   // fall through
    case Code::TO_BOOLEAN_IC:  // fall through
    case Code::STUB:
      description =
          CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
      if (description == NULL)
        description = "A stub from the snapshot";
      tag = Logger::STUB_TAG;
      break;
1855 1856 1857 1858
    case Code::REGEXP:
      description = "Regular expression code";
      tag = Logger::REG_EXP_TAG;
      break;
1859 1860 1861 1862
    case Code::BUILTIN:
      description = "A builtin from the snapshot";
      tag = Logger::BUILTIN_TAG;
      break;
1863 1864 1865 1866
    case Code::HANDLER:
      description = "An IC handler from the snapshot";
      tag = Logger::HANDLER_TAG;
      break;
1867 1868 1869 1870 1871 1872 1873 1874 1875 1876 1877 1878 1879 1880 1881 1882
    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;
    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;
1883 1884
    case Code::NUMBER_OF_KINDS:
      break;
1885
  }
1886
  PROFILE(isolate_, CodeCreateEvent(tag, code_object, description));
1887 1888 1889
}


1890
void Logger::LogCodeObjects() {
1891
  Heap* heap = isolate_->heap();
1892
  heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
1893
                          "Logger::LogCodeObjects");
1894
  HeapIterator iterator(heap);
1895
  DisallowHeapAllocation no_gc;
1896 1897 1898 1899 1900 1901
  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
    if (obj->IsCode()) LogCodeObject(obj);
  }
}


1902 1903 1904 1905 1906
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()));
1907
    int line_num = GetScriptLineNumber(script, shared->start_position()) + 1;
1908 1909
    int column_num =
        GetScriptColumnNumber(script, shared->start_position()) + 1;
1910
    if (script->name()->IsString()) {
1911 1912
      Handle<String> script_name(String::cast(script->name()));
      if (line_num > 0) {
1913
        PROFILE(isolate_,
1914 1915
                CodeCreateEvent(
                    Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1916
                    *code, *shared, NULL,
1917
                    *script_name, line_num, column_num));
1918 1919
      } else {
        // Can't distinguish eval and script here, so always use Script.
1920
        PROFILE(isolate_,
1921 1922
                CodeCreateEvent(
                    Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1923
                    *code, *shared, NULL, *script_name));
1924 1925
      }
    } else {
1926
      PROFILE(isolate_,
1927 1928
              CodeCreateEvent(
                  Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1929
                  *code, *shared, NULL,
1930
                  isolate_->heap()->empty_string(), line_num, column_num));
1931 1932 1933 1934 1935 1936 1937 1938 1939
    }
  } 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);
1940
      PROFILE(isolate_, CallbackEvent(*func_name, entry_point));
1941 1942
    }
  } else {
1943
    PROFILE(isolate_,
1944
            CodeCreateEvent(
1945
                Logger::LAZY_COMPILE_TAG, *code, *shared, NULL, *func_name));
1946 1947 1948 1949
  }
}


1950
void Logger::LogCompiledFunctions() {
1951
  Heap* heap = isolate_->heap();
1952
  heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
1953
                          "Logger::LogCompiledFunctions");
1954
  HandleScope scope(isolate_);
1955
  const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL);
1956
  ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
1957
  ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
1958
  EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start());
1959 1960 1961 1962

  // During iteration, there can be heap allocation due to
  // GetScriptLineNumber call.
  for (int i = 0; i < compiled_funcs_count; ++i) {
1963 1964
    if (code_objects[i].is_identical_to(
            isolate_->builtins()->CompileUnoptimized()))
1965
      continue;
1966
    LogExistingFunction(sfis[i], code_objects[i]);
1967 1968 1969
  }
}

1970 1971

void Logger::LogAccessorCallbacks() {
1972
  Heap* heap = isolate_->heap();
1973
  heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
1974
                          "Logger::LogAccessorCallbacks");
1975
  HeapIterator iterator(heap);
1976
  DisallowHeapAllocation no_gc;
1977
  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1978 1979
    if (!obj->IsExecutableAccessorInfo()) continue;
    ExecutableAccessorInfo* ai = ExecutableAccessorInfo::cast(obj);
1980
    if (!ai->name()->IsName()) continue;
1981
    Address getter_entry = v8::ToCData<Address>(ai->getter());
1982
    Name* name = Name::cast(ai->name());
1983
    if (getter_entry != 0) {
1984
      PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
1985 1986 1987
    }
    Address setter_entry = v8::ToCData<Address>(ai->setter());
    if (setter_entry != 0) {
1988
      PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
1989 1990 1991 1992
    }
  }
}

1993

1994
static void AddIsolateIdIfNeeded(Isolate* isolate, StringStream* stream) {
1995
  if (isolate->IsDefaultIsolate() || !FLAG_logfile_per_isolate) return;
1996 1997 1998 1999
  stream->Add("isolate-%p-", isolate);
}


2000 2001
static SmartArrayPointer<const char> PrepareLogFileName(
    Isolate* isolate, const char* file_name) {
2002
  if (strchr(file_name, '%') != NULL || !isolate->IsDefaultIsolate()) {
2003 2004 2005 2006
    // If there's a '%' in the log file name we have to expand
    // placeholders.
    HeapStringAllocator allocator;
    StringStream stream(&allocator);
2007
    AddIsolateIdIfNeeded(isolate, &stream);
2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 2022 2023 2024 2025 2026 2027 2028 2029 2030 2031 2032 2033 2034 2035 2036 2037 2038 2039 2040 2041 2042 2043 2044 2045 2046 2047 2048 2049
    for (const char* p = file_name; *p; p++) {
      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':
            stream.Add("%d", OS::GetCurrentProcessId());
            break;
          case 't': {
            // %t expands to the current time in milliseconds.
            double time = OS::TimeCurrentMillis();
            stream.Add("%.0f", FmtElm(time));
            break;
          }
          case '%':
            // %% expands (contracts really) to %.
            stream.Put('%');
            break;
          default:
            // All other %'s expand to themselves.
            stream.Put('%');
            stream.Put(*p);
            break;
        }
      } else {
        stream.Put(*p);
      }
    }
    return SmartArrayPointer<const char>(stream.ToCString());
  }
  int length = StrLength(file_name);
  char* str = NewArray<char>(length + 1);
  OS::MemCopy(str, file_name, length);
  str[length] = '\0';
  return SmartArrayPointer<const char>(str);
}


2050
bool Logger::SetUp(Isolate* isolate) {
2051 2052 2053
  // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
  if (is_initialized_) return true;
  is_initialized_ = true;
2054

2055 2056 2057 2058 2059
  // --ll-prof implies --log-code and --log-snapshot-positions.
  if (FLAG_ll_prof) {
    FLAG_log_snapshot_positions = true;
  }

2060
  SmartArrayPointer<const char> log_file_name =
2061
      PrepareLogFileName(isolate, FLAG_logfile);
2062
  log_->Initialize(log_file_name.get());
2063

2064 2065 2066 2067 2068 2069 2070 2071 2072 2073 2074

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

  if (FLAG_perf_jit_prof) {
    perf_jit_logger_ = new PerfJitLogger();
    addCodeEventListener(perf_jit_logger_);
  }

2075
  if (FLAG_ll_prof) {
2076
    ll_logger_ = new LowLevelLogger(log_file_name.get());
2077
    addCodeEventListener(ll_logger_);
2078
  }
2079

2080 2081
  ticker_ = new Ticker(isolate, kSamplingIntervalMs);

2082
  if (Log::InitLogAtStart()) {
2083
    is_logging_ = true;
2084
  }
2085

2086
  if (FLAG_prof) {
2087
    profiler_ = new Profiler(isolate);
2088 2089
    is_logging_ = true;
    profiler_->Engage();
2090 2091
  }

2092
  if (FLAG_log_internal_timer_events || FLAG_prof) timer_.Start();
2093

2094 2095 2096 2097
  return true;
}


2098 2099
void Logger::SetCodeEventHandler(uint32_t options,
                                 JitCodeEventHandler event_handler) {
2100
  if (jit_logger_) {
2101
      removeCodeEventListener(jit_logger_);
2102 2103 2104
      delete jit_logger_;
      jit_logger_ = NULL;
  }
2105

2106 2107
  if (event_handler) {
    jit_logger_ = new JitLogger(event_handler);
2108 2109 2110 2111 2112 2113
    addCodeEventListener(jit_logger_);
    if (options & kJitCodeEventEnumExisting) {
      HandleScope scope(isolate_);
      LogCodeObjects();
      LogCompiledFunctions();
    }
2114 2115 2116 2117
  }
}


2118 2119 2120 2121 2122
Sampler* Logger::sampler() {
  return ticker_;
}


2123 2124
FILE* Logger::TearDown() {
  if (!is_initialized_) return NULL;
2125
  is_initialized_ = false;
2126

2127 2128 2129 2130 2131 2132 2133 2134
  // Stop the profiler before closing the file.
  if (profiler_ != NULL) {
    profiler_->Disengage();
    delete profiler_;
    profiler_ = NULL;
  }

  delete ticker_;
2135
  ticker_ = NULL;
2136

2137 2138 2139 2140 2141 2142 2143 2144 2145 2146 2147 2148
  if (perf_basic_logger_) {
    removeCodeEventListener(perf_basic_logger_);
    delete perf_basic_logger_;
    perf_basic_logger_ = NULL;
  }

  if (perf_jit_logger_) {
    removeCodeEventListener(perf_jit_logger_);
    delete perf_jit_logger_;
    perf_jit_logger_ = NULL;
  }

2149
  if (ll_logger_) {
2150
    removeCodeEventListener(ll_logger_);
2151 2152 2153 2154
    delete ll_logger_;
    ll_logger_ = NULL;
  }

2155
  if (jit_logger_) {
2156
    removeCodeEventListener(jit_logger_);
2157 2158 2159 2160
    delete jit_logger_;
    jit_logger_ = NULL;
  }

2161
  return log_->Close();
2162 2163 2164
}

} }  // namespace v8::internal