src/v8/src/log.cc

   1 // Copyright 2011 the V8 project authors. All rights reserved.
   2 // Redistribution and use in source and binary forms, with or without
   3 // modification, are permitted provided that the following conditions are
   4 // met:
   5 //
   6 //     * Redistributions of source code must retain the above copyright
   7 //       notice, this list of conditions and the following disclaimer.
   8 //     * Redistributions in binary form must reproduce the above
   9 //       copyright notice, this list of conditions and the following
  10 //       disclaimer in the documentation and/or other materials provided
  11 //       with the distribution.
  12 //     * Neither the name of Google Inc. nor the names of its
  13 //       contributors may be used to endorse or promote products derived
  14 //       from this software without specific prior written permission.
  15 //
  16 // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
  17 // "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
  18 // LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
  19 // A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
  20 // OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
  21 // SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
  22 // LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
  23 // DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
  24 // THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
  25 // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
  26 // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
  27
  28 #include <stdarg.h>
  29
  30 #include "v8.h"
  31
  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 namespace v8 {
  47 namespace internal {
  48
  49
  50 #define DECLARE_EVENT(ignore1, name) name,
  51 static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
  52   LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
  53 };
  54 #undef DECLARE_EVENT
  55
  56
  57 #define CALL_LISTENERS(Call)                    \
  58 for (int i = 0; i < listeners_.length(); ++i) { \
  59   listeners_[i]->Call;                          \
  60 }
  61
  62 #define PROFILER_LOG(Call)                                \
  63   do {                                                    \
  64     CpuProfiler* cpu_profiler = isolate_->cpu_profiler(); \
  65     if (cpu_profiler->is_profiling()) {                   \
  66       cpu_profiler->Call;                                 \
  67     }                                                     \
  68   } while (false);
  69
  70 // ComputeMarker must only be used when SharedFunctionInfo is known.
  71 static const char* ComputeMarker(Code* code) {
  72   switch (code->kind()) {
  73     case Code::FUNCTION: return code->optimizable() ? "~" : "";
  74     case Code::OPTIMIZED_FUNCTION: return "*";
  75     default: return "";
  76   }
  77 }
  78
  79
  80 class CodeEventLogger::NameBuffer {
  81  public:
  82   NameBuffer() { Reset(); }
  83
  84   void Reset() {
  85     utf8_pos_ = 0;
  86   }
  87
  88   void Init(Logger::LogEventsAndTags tag) {
  89     Reset();
  90     AppendBytes(kLogEventsNames[tag]);
  91     AppendByte(':');
  92   }
  93
  94   void AppendName(Name* name) {
  95     if (name->IsString()) {
  96       AppendString(String::cast(name));
  97     } else {
  98       Symbol* symbol = Symbol::cast(name);
  99       AppendBytes("symbol(");
 100       if (!symbol->name()->IsUndefined()) {
 101         AppendBytes("\"");
 102         AppendString(String::cast(symbol->name()));
 103         AppendBytes("\" ");
 104       }
 105       AppendBytes("hash ");
 106       AppendHex(symbol->Hash());
 107       AppendByte(')');
 108     }
 109   }
 110
 111   void AppendString(String* str) {
 112     if (str == NULL) return;
 113     int uc16_length = Min(str->length(), kUtf16BufferSize);
 114     String::WriteToFlat(str, utf16_buffer, 0, uc16_length);
 115     int previous = unibrow::Utf16::kNoPreviousCharacter;
 116     for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
 117       uc16 c = utf16_buffer[i];
 118       if (c <= unibrow::Utf8::kMaxOneByteChar) {
 119         utf8_buffer_[utf8_pos_++] = static_cast<char>(c);
 120       } else {
 121         int char_length = unibrow::Utf8::Length(c, previous);
 122         if (utf8_pos_ + char_length > kUtf8BufferSize) break;
 123         unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous);
 124         utf8_pos_ += char_length;
 125       }
 126       previous = c;
 127     }
 128   }
 129
 130   void AppendBytes(const char* bytes, int size) {
 131     size = Min(size, kUtf8BufferSize - utf8_pos_);
 132     OS::MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
 133     utf8_pos_ += size;
 134   }
 135
 136   void AppendBytes(const char* bytes) {
 137     AppendBytes(bytes, StrLength(bytes));
 138   }
 139
 140   void AppendByte(char c) {
 141     if (utf8_pos_ >= kUtf8BufferSize) return;
 142     utf8_buffer_[utf8_pos_++] = c;
 143   }
 144
 145   void AppendInt(int n) {
 146     Vector<char> buffer(utf8_buffer_ + utf8_pos_,
 147                         kUtf8BufferSize - utf8_pos_);
 148     int size = OS::SNPrintF(buffer, "%d", n);
 149     if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
 150       utf8_pos_ += size;
 151     }
 152   }
 153
 154   void AppendHex(uint32_t n) {
 155     Vector<char> buffer(utf8_buffer_ + utf8_pos_,
 156                         kUtf8BufferSize - utf8_pos_);
 157     int size = OS::SNPrintF(buffer, "%x", n);
 158     if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
 159       utf8_pos_ += size;
 160     }
 161   }
 162
 163   const char* get() { return utf8_buffer_; }
 164   int size() const { return utf8_pos_; }
 165
 166  private:
 167   static const int kUtf8BufferSize = 512;
 168   static const int kUtf16BufferSize = 128;
 169
 170   int utf8_pos_;
 171   char utf8_buffer_[kUtf8BufferSize];
 172   uc16 utf16_buffer[kUtf16BufferSize];
 173 };
 174
 175
 176 CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { }
 177
 178 CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }
 179
 180
 181 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
 182                                       Code* code,
 183                                       const char* comment) {
 184   name_buffer_->Init(tag);
 185   name_buffer_->AppendBytes(comment);
 186   LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
 187 }
 188
 189
 190 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
 191                                       Code* code,
 192                                       Name* name) {
 193   name_buffer_->Init(tag);
 194   name_buffer_->AppendName(name);
 195   LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
 196 }
 197
 198
 199 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
 200                                       Code* code,
 201                                       SharedFunctionInfo* shared,
 202                                       CompilationInfo* info,
 203                                       Name* name) {
 204   name_buffer_->Init(tag);
 205   name_buffer_->AppendBytes(ComputeMarker(code));
 206   name_buffer_->AppendName(name);
 207   LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
 208 }
 209
 210
 211 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
 212                                       Code* code,
 213                                       SharedFunctionInfo* shared,
 214                                       CompilationInfo* info,
 215                                       Name* source, int line, int column) {
 216   name_buffer_->Init(tag);
 217   name_buffer_->AppendBytes(ComputeMarker(code));
 218   name_buffer_->AppendString(shared->DebugName());
 219   name_buffer_->AppendByte(' ');
 220   if (source->IsString()) {
 221     name_buffer_->AppendString(String::cast(source));
 222   } else {
 223     name_buffer_->AppendBytes("symbol(hash ");
 224     name_buffer_->AppendHex(Name::cast(source)->Hash());
 225     name_buffer_->AppendByte(')');
 226   }
 227   name_buffer_->AppendByte(':');
 228   name_buffer_->AppendInt(line);
 229   LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
 230 }
 231
 232
 233 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
 234                                       Code* code,
 235                                       int args_count) {
 236   name_buffer_->Init(tag);
 237   name_buffer_->AppendInt(args_count);
 238   LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
 239 }
 240
 241
 242 void CodeEventLogger::RegExpCodeCreateEvent(Code* code, String* source) {
 243   name_buffer_->Init(Logger::REG_EXP_TAG);
 244   name_buffer_->AppendString(source);
 245   LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
 246 }
 247
 248
 249 // Linux perf tool logging support
 250 class PerfBasicLogger : public CodeEventLogger {
 251  public:
 252   PerfBasicLogger();
 253   virtual ~PerfBasicLogger();
 254
 255   virtual void CodeMoveEvent(Address from, Address to) { }
 256   virtual void CodeDeleteEvent(Address from) { }
 257
 258  private:
 259   virtual void LogRecordedBuffer(Code* code,
 260                                  SharedFunctionInfo* shared,
 261                                  const char* name,
 262                                  int length);
 263
 264   // Extension added to V8 log file name to get the low-level log name.
 265   static const char kFilenameFormatString[];
 266   static const int kFilenameBufferPadding;
 267
 268   // File buffer size of the low-level log. We don't use the default to
 269   // minimize the associated overhead.
 270   static const int kLogBufferSize = 2 * MB;
 271
 272   FILE* perf_output_handle_;
 273 };
 274
 275 const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
 276 // Extra space for the PID in the filename
 277 const int PerfBasicLogger::kFilenameBufferPadding = 16;
 278
 279 PerfBasicLogger::PerfBasicLogger()
 280     : perf_output_handle_(NULL) {
 281   // Open the perf JIT dump file.
 282   int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
 283   ScopedVector<char> perf_dump_name(bufferSize);
 284   int size = OS::SNPrintF(
 285       perf_dump_name,
 286       kFilenameFormatString,
 287       OS::GetCurrentProcessId());
 288   CHECK_NE(size, -1);
 289   perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);
 290   CHECK_NE(perf_output_handle_, NULL);
 291   setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);
 292 }
 293
 294
 295 PerfBasicLogger::~PerfBasicLogger() {
 296   fclose(perf_output_handle_);
 297   perf_output_handle_ = NULL;
 298 }
 299
 300
 301 void PerfBasicLogger::LogRecordedBuffer(Code* code,
 302                                        SharedFunctionInfo*,
 303                                        const char* name,
 304                                        int length) {
 305   ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);
 306
 307   OS::FPrint(perf_output_handle_, "%llx %x %.*s\n",
 308       reinterpret_cast<uint64_t>(code->instruction_start()),
 309       code->instruction_size(),
 310       length, name);
 311 }
 312
 313
 314 // Linux perf tool logging support
 315 class PerfJitLogger : public CodeEventLogger {
 316  public:
 317   PerfJitLogger();
 318   virtual ~PerfJitLogger();
 319
 320   virtual void CodeMoveEvent(Address from, Address to) { }
 321   virtual void CodeDeleteEvent(Address from) { }
 322
 323  private:
 324   virtual void LogRecordedBuffer(Code* code,
 325                                  SharedFunctionInfo* shared,
 326                                  const char* name,
 327                                  int length);
 328
 329   // Extension added to V8 log file name to get the low-level log name.
 330   static const char kFilenameFormatString[];
 331   static const int kFilenameBufferPadding;
 332
 333   // File buffer size of the low-level log. We don't use the default to
 334   // minimize the associated overhead.
 335   static const int kLogBufferSize = 2 * MB;
 336
 337   void LogWriteBytes(const char* bytes, int size);
 338   void LogWriteHeader();
 339
 340   static const uint32_t kJitHeaderMagic = 0x4F74496A;
 341   static const uint32_t kJitHeaderVersion = 0x2;
 342   static const uint32_t kElfMachIA32 = 3;
 343   static const uint32_t kElfMachX64 = 62;
 344   static const uint32_t kElfMachARM = 40;
 345   static const uint32_t kElfMachMIPS = 10;
 346
 347   struct jitheader {
 348     uint32_t magic;
 349     uint32_t version;
 350     uint32_t total_size;
 351     uint32_t elf_mach;
 352     uint32_t pad1;
 353     uint32_t pid;
 354     uint64_t timestamp;
 355   };
 356
 357   enum jit_record_type {
 358     JIT_CODE_LOAD = 0
 359     // JIT_CODE_UNLOAD = 1,
 360     // JIT_CODE_CLOSE = 2,
 361     // JIT_CODE_DEBUG_INFO = 3,
 362     // JIT_CODE_PAGE_MAP = 4,
 363     // JIT_CODE_MAX = 5
 364   };
 365
 366   struct jr_code_load {
 367     uint32_t id;
 368     uint32_t total_size;
 369     uint64_t timestamp;
 370     uint64_t vma;
 371     uint64_t code_addr;
 372     uint32_t code_size;
 373     uint32_t align;
 374   };
 375
 376   uint32_t GetElfMach() {
 377 #if V8_TARGET_ARCH_IA32
 378     return kElfMachIA32;
 379 #elif V8_TARGET_ARCH_X64
 380     return kElfMachX64;
 381 #elif V8_TARGET_ARCH_ARM
 382     return kElfMachARM;
 383 #elif V8_TARGET_ARCH_MIPS
 384     return kElfMachMIPS;
 385 #else
 386     UNIMPLEMENTED();
 387     return 0;
 388 #endif
 389   }
 390
 391   FILE* perf_output_handle_;
 392 };
 393
 394 const char PerfJitLogger::kFilenameFormatString[] = "/tmp/jit-%d.dump";
 395
 396 // Extra padding for the PID in the filename
 397 const int PerfJitLogger::kFilenameBufferPadding = 16;
 398
 399 PerfJitLogger::PerfJitLogger()
 400     : perf_output_handle_(NULL) {
 401   // Open the perf JIT dump file.
 402   int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
 403   ScopedVector<char> perf_dump_name(bufferSize);
 404   int size = OS::SNPrintF(
 405       perf_dump_name,
 406       kFilenameFormatString,
 407       OS::GetCurrentProcessId());
 408   CHECK_NE(size, -1);
 409   perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);
 410   CHECK_NE(perf_output_handle_, NULL);
 411   setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);
 412
 413   LogWriteHeader();
 414 }
 415
 416
 417 PerfJitLogger::~PerfJitLogger() {
 418   fclose(perf_output_handle_);
 419   perf_output_handle_ = NULL;
 420 }
 421
 422
 423 void PerfJitLogger::LogRecordedBuffer(Code* code,
 424                                       SharedFunctionInfo*,
 425                                       const char* name,
 426                                       int length) {
 427   ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);
 428   ASSERT(perf_output_handle_ != NULL);
 429
 430   const char* code_name = name;
 431   uint8_t* code_pointer = reinterpret_cast<uint8_t*>(code->instruction_start());
 432   uint32_t code_size = code->instruction_size();
 433
 434   static const char string_terminator[] = "\0";
 435
 436   jr_code_load code_load;
 437   code_load.id = JIT_CODE_LOAD;
 438   code_load.total_size = sizeof(code_load) + length + 1 + code_size;
 439   code_load.timestamp =
 440       static_cast<uint64_t>(OS::TimeCurrentMillis() * 1000.0);
 441   code_load.vma = 0x0;  //  Our addresses are absolute.
 442   code_load.code_addr = reinterpret_cast<uint64_t>(code->instruction_start());
 443   code_load.code_size = code_size;
 444   code_load.align = 0;
 445
 446   LogWriteBytes(reinterpret_cast<const char*>(&code_load), sizeof(code_load));
 447   LogWriteBytes(code_name, length);
 448   LogWriteBytes(string_terminator, 1);
 449   LogWriteBytes(reinterpret_cast<const char*>(code_pointer), code_size);
 450 }
 451
 452
 453 void PerfJitLogger::LogWriteBytes(const char* bytes, int size) {
 454   size_t rv = fwrite(bytes, 1, size, perf_output_handle_);
 455   ASSERT(static_cast<size_t>(size) == rv);
 456   USE(rv);
 457 }
 458
 459
 460 void PerfJitLogger::LogWriteHeader() {
 461   ASSERT(perf_output_handle_ != NULL);
 462   jitheader header;
 463   header.magic = kJitHeaderMagic;
 464   header.version = kJitHeaderVersion;
 465   header.total_size = sizeof(jitheader);
 466   header.pad1 = 0xdeadbeef;
 467   header.elf_mach = GetElfMach();
 468   header.pid = OS::GetCurrentProcessId();
 469   header.timestamp = static_cast<uint64_t>(OS::TimeCurrentMillis() * 1000.0);
 470   LogWriteBytes(reinterpret_cast<const char*>(&header), sizeof(header));
 471 }
 472
 473
 474 // Low-level logging support.
 475 #define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;
 476
 477 class LowLevelLogger : public CodeEventLogger {
 478  public:
 479   explicit LowLevelLogger(const char* file_name);
 480   virtual ~LowLevelLogger();
 481
 482   virtual void CodeMoveEvent(Address from, Address to);
 483   virtual void CodeDeleteEvent(Address from);
 484   virtual void SnapshotPositionEvent(Address addr, int pos);
 485   virtual void CodeMovingGCEvent();
 486
 487  private:
 488   virtual void LogRecordedBuffer(Code* code,
 489                                  SharedFunctionInfo* shared,
 490                                  const char* name,
 491                                  int length);
 492
 493   // Low-level profiling event structures.
 494   struct CodeCreateStruct {
 495     static const char kTag = 'C';
 496
 497     int32_t name_size;
 498     Address code_address;
 499     int32_t code_size;
 500   };
 501
 502
 503   struct CodeMoveStruct {
 504     static const char kTag = 'M';
 505
 506     Address from_address;
 507     Address to_address;
 508   };
 509
 510
 511   struct CodeDeleteStruct {
 512     static const char kTag = 'D';
 513
 514     Address address;
 515   };
 516
 517
 518   struct SnapshotPositionStruct {
 519     static const char kTag = 'P';
 520
 521     Address address;
 522     int32_t position;
 523   };
 524
 525
 526   static const char kCodeMovingGCTag = 'G';
 527
 528
 529   // Extension added to V8 log file name to get the low-level log name.
 530   static const char kLogExt[];
 531
 532   // File buffer size of the low-level log. We don't use the default to
 533   // minimize the associated overhead.
 534   static const int kLogBufferSize = 2 * MB;
 535
 536   void LogCodeInfo();
 537   void LogWriteBytes(const char* bytes, int size);
 538
 539   template <typename T>
 540   void LogWriteStruct(const T& s) {
 541     char tag = T::kTag;
 542     LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag));
 543     LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
 544   }
 545
 546   FILE* ll_output_handle_;
 547 };
 548
 549 const char LowLevelLogger::kLogExt[] = ".ll";
 550
 551 LowLevelLogger::LowLevelLogger(const char* name)
 552     : ll_output_handle_(NULL) {
 553   // Open the low-level log file.
 554   size_t len = strlen(name);
 555   ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt)));
 556   OS::MemCopy(ll_name.start(), name, len);
 557   OS::MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
 558   ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode);
 559   setvbuf(ll_output_handle_, NULL, _IOFBF, kLogBufferSize);
 560
 561   LogCodeInfo();
 562 }
 563
 564
 565 LowLevelLogger::~LowLevelLogger() {
 566   fclose(ll_output_handle_);
 567   ll_output_handle_ = NULL;
 568 }
 569
 570
 571 void LowLevelLogger::LogCodeInfo() {
 572 #if V8_TARGET_ARCH_IA32
 573   const char arch[] = "ia32";
 574 #elif V8_TARGET_ARCH_X64
 575   const char arch[] = "x64";
 576 #elif V8_TARGET_ARCH_ARM
 577   const char arch[] = "arm";
 578 #elif V8_TARGET_ARCH_MIPS
 579   const char arch[] = "mips";
 580 #else
 581   const char arch[] = "unknown";
 582 #endif
 583   LogWriteBytes(arch, sizeof(arch));
 584 }
 585
 586
 587 void LowLevelLogger::LogRecordedBuffer(Code* code,
 588                                        SharedFunctionInfo*,
 589                                        const char* name,
 590                                        int length) {
 591   CodeCreateStruct event;
 592   event.name_size = length;
 593   event.code_address = code->instruction_start();
 594   ASSERT(event.code_address == code->address() + Code::kHeaderSize);
 595   event.code_size = code->instruction_size();
 596   LogWriteStruct(event);
 597   LogWriteBytes(name, length);
 598   LogWriteBytes(
 599       reinterpret_cast<const char*>(code->instruction_start()),
 600       code->instruction_size());
 601 }
 602
 603
 604 void LowLevelLogger::CodeMoveEvent(Address from, Address to) {
 605   CodeMoveStruct event;
 606   event.from_address = from + Code::kHeaderSize;
 607   event.to_address = to + Code::kHeaderSize;
 608   LogWriteStruct(event);
 609 }
 610
 611
 612 void LowLevelLogger::CodeDeleteEvent(Address from) {
 613   CodeDeleteStruct event;
 614   event.address = from + Code::kHeaderSize;
 615   LogWriteStruct(event);
 616 }
 617
 618
 619 void LowLevelLogger::SnapshotPositionEvent(Address addr, int pos) {
 620   SnapshotPositionStruct event;
 621   event.address = addr + Code::kHeaderSize;
 622   event.position = pos;
 623   LogWriteStruct(event);
 624 }
 625
 626
 627 void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
 628   size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
 629   ASSERT(static_cast<size_t>(size) == rv);
 630   USE(rv);
 631 }
 632
 633
 634 void LowLevelLogger::CodeMovingGCEvent() {
 635   const char tag = kCodeMovingGCTag;
 636
 637   LogWriteBytes(&tag, sizeof(tag));
 638 }
 639
 640
 641 #define JIT_LOG(Call) if (jit_logger_) jit_logger_->Call;
 642
 643
 644 class JitLogger : public CodeEventLogger {
 645  public:
 646   explicit JitLogger(JitCodeEventHandler code_event_handler);
 647
 648   virtual void CodeMoveEvent(Address from, Address to);
 649   virtual void CodeDeleteEvent(Address from);
 650   virtual void AddCodeLinePosInfoEvent(
 651       void* jit_handler_data,
 652       int pc_offset,
 653       int position,
 654       JitCodeEvent::PositionType position_type);
 655
 656   void* StartCodePosInfoEvent();
 657   void EndCodePosInfoEvent(Code* code, void* jit_handler_data);
 658
 659  private:
 660   virtual void LogRecordedBuffer(Code* code,
 661                                  SharedFunctionInfo* shared,
 662                                  const char* name,
 663                                  int length);
 664
 665   JitCodeEventHandler code_event_handler_;
 666 };
 667
 668
 669 JitLogger::JitLogger(JitCodeEventHandler code_event_handler)
 670     : code_event_handler_(code_event_handler) {
 671 }
 672
 673
 674 void JitLogger::LogRecordedBuffer(Code* code,
 675                                   SharedFunctionInfo* shared,
 676                                   const char* name,
 677                                   int length) {
 678   JitCodeEvent event;
 679   memset(&event, 0, sizeof(event));
 680   event.type = JitCodeEvent::CODE_ADDED;
 681   event.code_start = code->instruction_start();
 682   event.code_len = code->instruction_size();
 683   Handle<Script> script_handle;
 684   if (shared && shared->script()->IsScript()) {
 685     script_handle = Handle<Script>(Script::cast(shared->script()));
 686   }
 687   event.script = ToApiHandle<v8::Script>(script_handle);
 688   event.name.str = name;
 689   event.name.len = length;
 690   code_event_handler_(&event);
 691 }
 692
 693
 694 void JitLogger::CodeMoveEvent(Address from, Address to) {
 695   Code* from_code = Code::cast(HeapObject::FromAddress(from));
 696
 697   JitCodeEvent event;
 698   event.type = JitCodeEvent::CODE_MOVED;
 699   event.code_start = from_code->instruction_start();
 700   event.code_len = from_code->instruction_size();
 701
 702   // Calculate the header size.
 703   const size_t header_size =
 704       from_code->instruction_start() - reinterpret_cast<byte*>(from_code);
 705
 706   // Calculate the new start address of the instructions.
 707   event.new_code_start =
 708       reinterpret_cast<byte*>(HeapObject::FromAddress(to)) + header_size;
 709
 710   code_event_handler_(&event);
 711 }
 712
 713
 714 void JitLogger::CodeDeleteEvent(Address from) {
 715   Code* from_code = Code::cast(HeapObject::FromAddress(from));
 716
 717   JitCodeEvent event;
 718   event.type = JitCodeEvent::CODE_REMOVED;
 719   event.code_start = from_code->instruction_start();
 720   event.code_len = from_code->instruction_size();
 721
 722   code_event_handler_(&event);
 723 }
 724
 725 void JitLogger::AddCodeLinePosInfoEvent(
 726     void* jit_handler_data,
 727     int pc_offset,
 728     int position,
 729     JitCodeEvent::PositionType position_type) {
 730   JitCodeEvent event;
 731   memset(&event, 0, sizeof(event));
 732   event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO;
 733   event.user_data = jit_handler_data;
 734   event.line_info.offset = pc_offset;
 735   event.line_info.pos = position;
 736   event.line_info.position_type = position_type;
 737
 738   code_event_handler_(&event);
 739 }
 740
 741
 742 void* JitLogger::StartCodePosInfoEvent() {
 743   JitCodeEvent event;
 744   memset(&event, 0, sizeof(event));
 745   event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING;
 746
 747   code_event_handler_(&event);
 748   return event.user_data;
 749 }
 750
 751
 752 void JitLogger::EndCodePosInfoEvent(Code* code, void* jit_handler_data) {
 753   JitCodeEvent event;
 754   memset(&event, 0, sizeof(event));
 755   event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING;
 756   event.code_start = code->instruction_start();
 757   event.user_data = jit_handler_data;
 758
 759   code_event_handler_(&event);
 760 }
 761
 762
 763 // The Profiler samples pc and sp values for the main thread.
 764 // Each sample is appended to a circular buffer.
 765 // An independent thread removes data and writes it to the log.
 766 // This design minimizes the time spent in the sampler.
 767 //
 768 class Profiler: public Thread {
 769  public:
 770   explicit Profiler(Isolate* isolate);
 771   void Engage();
 772   void Disengage();
 773
 774   // Inserts collected profiling data into buffer.
 775   void Insert(TickSample* sample) {
 776     if (paused_)
 777       return;
 778
 779     if (Succ(head_) == tail_) {
 780       overflow_ = true;
 781     } else {
 782       buffer_[head_] = *sample;
 783       head_ = Succ(head_);
 784       buffer_semaphore_.Signal();  // Tell we have an element.
 785     }
 786   }
 787
 788   virtual void Run();
 789
 790   // Pause and Resume TickSample data collection.
 791   void pause() { paused_ = true; }
 792   void resume() { paused_ = false; }
 793
 794  private:
 795   // Waits for a signal and removes profiling data.
 796   bool Remove(TickSample* sample) {
 797     buffer_semaphore_.Wait();  // Wait for an element.
 798     *sample = buffer_[tail_];
 799     bool result = overflow_;
 800     tail_ = Succ(tail_);
 801     overflow_ = false;
 802     return result;
 803   }
 804
 805   // Returns the next index in the cyclic buffer.
 806   int Succ(int index) { return (index + 1) % kBufferSize; }
 807
 808   Isolate* isolate_;
 809   // Cyclic buffer for communicating profiling samples
 810   // between the signal handler and the worker thread.
 811   static const int kBufferSize = 128;
 812   TickSample buffer_[kBufferSize];  // Buffer storage.
 813   int head_;  // Index to the buffer head.
 814   int tail_;  // Index to the buffer tail.
 815   bool overflow_;  // Tell whether a buffer overflow has occurred.
 816   // Sempahore used for buffer synchronization.
 817   Semaphore buffer_semaphore_;
 818
 819   // Tells whether profiler is engaged, that is, processing thread is stated.
 820   bool engaged_;
 821
 822   // Tells whether worker thread should continue running.
 823   bool running_;
 824
 825   // Tells whether we are currently recording tick samples.
 826   bool paused_;
 827 };
 828
 829
 830 //
 831 // Ticker used to provide ticks to the profiler and the sliding state
 832 // window.
 833 //
 834 class Ticker: public Sampler {
 835  public:
 836   Ticker(Isolate* isolate, int interval):
 837       Sampler(isolate, interval),
 838       profiler_(NULL) {}
 839
 840   ~Ticker() { if (IsActive()) Stop(); }
 841
 842   virtual void Tick(TickSample* sample) {
 843     if (profiler_) profiler_->Insert(sample);
 844   }
 845
 846   void SetProfiler(Profiler* profiler) {
 847     ASSERT(profiler_ == NULL);
 848     profiler_ = profiler;
 849     IncreaseProfilingDepth();
 850     if (!IsActive()) Start();
 851   }
 852
 853   void ClearProfiler() {
 854     profiler_ = NULL;
 855     if (IsActive()) Stop();
 856     DecreaseProfilingDepth();
 857   }
 858
 859  private:
 860   Profiler* profiler_;
 861 };
 862
 863
 864 //
 865 // Profiler implementation.
 866 //
 867 Profiler::Profiler(Isolate* isolate)
 868     : Thread("v8:Profiler"),
 869       isolate_(isolate),
 870       head_(0),
 871       tail_(0),
 872       overflow_(false),
 873       buffer_semaphore_(0),
 874       engaged_(false),
 875       running_(false),
 876       paused_(false) {
 877 }
 878
 879
 880 void Profiler::Engage() {
 881   if (engaged_) return;
 882   engaged_ = true;
 883
 884   OS::LogSharedLibraryAddresses(isolate_);
 885
 886   // Start thread processing the profiler buffer.
 887   running_ = true;
 888   Start();
 889
 890   // Register to get ticks.
 891   Logger* logger = isolate_->logger();
 892   logger->ticker_->SetProfiler(this);
 893
 894   logger->ProfilerBeginEvent();
 895 }
 896
 897
 898 void Profiler::Disengage() {
 899   if (!engaged_) return;
 900
 901   // Stop receiving ticks.
 902   isolate_->logger()->ticker_->ClearProfiler();
 903
 904   // Terminate the worker thread by setting running_ to false,
 905   // inserting a fake element in the queue and then wait for
 906   // the thread to terminate.
 907   running_ = false;
 908   TickSample sample;
 909   // Reset 'paused_' flag, otherwise semaphore may not be signalled.
 910   resume();
 911   Insert(&sample);
 912   Join();
 913
 914   LOG(isolate_, UncheckedStringEvent("profiler", "end"));
 915 }
 916
 917
 918 void Profiler::Run() {
 919   TickSample sample;
 920   bool overflow = Remove(&sample);
 921   while (running_) {
 922     LOG(isolate_, TickEvent(&sample, overflow));
 923     overflow = Remove(&sample);
 924   }
 925 }
 926
 927
 928 //
 929 // Logger class implementation.
 930 //
 931
 932 Logger::Logger(Isolate* isolate)
 933   : isolate_(isolate),
 934     ticker_(NULL),
 935     profiler_(NULL),
 936     log_events_(NULL),
 937     is_logging_(false),
 938     log_(new Log(this)),
 939     perf_basic_logger_(NULL),
 940     perf_jit_logger_(NULL),
 941     ll_logger_(NULL),
 942     jit_logger_(NULL),
 943     listeners_(5),
 944     is_initialized_(false) {
 945 }
 946
 947
 948 Logger::~Logger() {
 949   delete log_;
 950 }
 951
 952
 953 void Logger::addCodeEventListener(CodeEventListener* listener) {
 954   ASSERT(!hasCodeEventListener(listener));
 955   listeners_.Add(listener);
 956 }
 957
 958
 959 void Logger::removeCodeEventListener(CodeEventListener* listener) {
 960   ASSERT(hasCodeEventListener(listener));
 961   listeners_.RemoveElement(listener);
 962 }
 963
 964
 965 bool Logger::hasCodeEventListener(CodeEventListener* listener) {
 966   return listeners_.Contains(listener);
 967 }
 968
 969
 970 void Logger::ProfilerBeginEvent() {
 971   if (!log_->IsEnabled()) return;
 972   Log::MessageBuilder msg(log_);
 973   msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
 974   msg.WriteToLogFile();
 975 }
 976
 977
 978 void Logger::StringEvent(const char* name, const char* value) {
 979   if (FLAG_log) UncheckedStringEvent(name, value);
 980 }
 981
 982
 983 void Logger::UncheckedStringEvent(const char* name, const char* value) {
 984   if (!log_->IsEnabled()) return;
 985   Log::MessageBuilder msg(log_);
 986   msg.Append("%s,\"%s\"\n", name, value);
 987   msg.WriteToLogFile();
 988 }
 989
 990
 991 void Logger::IntEvent(const char* name, int value) {
 992   if (FLAG_log) UncheckedIntEvent(name, value);
 993 }
 994
 995
 996 void Logger::IntPtrTEvent(const char* name, intptr_t value) {
 997   if (FLAG_log) UncheckedIntPtrTEvent(name, value);
 998 }
 999
1000
1001 void Logger::UncheckedIntEvent(const char* name, int value) {
1002   if (!log_->IsEnabled()) return;
1003   Log::MessageBuilder msg(log_);
1004   msg.Append("%s,%d\n", name, value);
1005   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   msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
1013   msg.WriteToLogFile();
1014 }
1015
1016
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 // FLAG_log_api is true.
1028 void Logger::ApiEvent(const char* format, ...) {
1029   ASSERT(log_->IsEnabled() && FLAG_log_api);
1030   Log::MessageBuilder msg(log_);
1031   va_list ap;
1032   va_start(ap, format);
1033   msg.AppendVA(format, ap);
1034   va_end(ap);
1035   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     Symbol* symbol = Symbol::cast(key);
1047     if (symbol->name()->IsUndefined()) {
1048       ApiEvent("api,check-security,symbol(hash %x)\n",
1049                Symbol::cast(key)->Hash());
1050     } else {
1051       SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
1052           DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1053       ApiEvent("api,check-security,symbol(\"%s\" hash %x)\n",
1054                str.get(),
1055                Symbol::cast(key)->Hash());
1056     }
1057   } else if (key->IsUndefined()) {
1058     ApiEvent("api,check-security,undefined\n");
1059   } else {
1060     ApiEvent("api,check-security,['no-name']\n");
1061   }
1062 }
1063
1064
1065 void Logger::SharedLibraryEvent(const char* library_path,
1066                                 uintptr_t start,
1067                                 uintptr_t end) {
1068   if (!log_->IsEnabled() || !FLAG_prof) return;
1069   Log::MessageBuilder msg(log_);
1070   msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
1071              library_path,
1072              start,
1073              end);
1074   msg.WriteToLogFile();
1075 }
1076
1077
1078 void Logger::SharedLibraryEvent(const wchar_t* library_path,
1079                                 uintptr_t start,
1080                                 uintptr_t end) {
1081   if (!log_->IsEnabled() || !FLAG_prof) return;
1082   Log::MessageBuilder msg(log_);
1083   msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
1084              library_path,
1085              start,
1086              end);
1087   msg.WriteToLogFile();
1088 }
1089
1090
1091 void Logger::CodeDeoptEvent(Code* code) {
1092   if (!log_->IsEnabled()) return;
1093   ASSERT(FLAG_log_internal_timer_events);
1094   Log::MessageBuilder msg(log_);
1095   int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
1096   msg.Append("code-deopt,%ld,%d\n", since_epoch, code->CodeSize());
1097   msg.WriteToLogFile();
1098 }
1099
1100
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   const char* format = (se == START) ? "timer-event-start,\"%s\",%ld\n"
1107                                      : "timer-event-end,\"%s\",%ld\n";
1108   msg.Append(format, name, since_epoch);
1109   msg.WriteToLogFile();
1110 }
1111
1112
1113 void Logger::EnterExternal(Isolate* isolate) {
1114   LOG(isolate, TimerEvent(START, TimerEventScope::v8_external));
1115   ASSERT(isolate->current_vm_state() == JS);
1116   isolate->set_current_vm_state(EXTERNAL);
1117 }
1118
1119
1120 void Logger::LeaveExternal(Isolate* isolate) {
1121   LOG(isolate, TimerEvent(END, TimerEventScope::v8_external));
1122   ASSERT(isolate->current_vm_state() == EXTERNAL);
1123   isolate->set_current_vm_state(JS);
1124 }
1125
1126
1127 void Logger::LogInternalEvents(const char* name, int se) {
1128   Isolate* isolate = Isolate::Current();
1129   LOG(isolate, TimerEvent(static_cast<StartEnd>(se), name));
1130 }
1131
1132
1133 void Logger::TimerEventScope::LogTimerEvent(StartEnd se) {
1134   isolate_->event_logger()(name_, se);
1135 }
1136
1137
1138 const char* Logger::TimerEventScope::v8_recompile_synchronous =
1139     "V8.RecompileSynchronous";
1140 const char* Logger::TimerEventScope::v8_recompile_concurrent =
1141     "V8.RecompileConcurrent";
1142 const char* Logger::TimerEventScope::v8_compile_full_code =
1143     "V8.CompileFullCode";
1144 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   Handle<Object> source = GetProperty(regexp, "source");
1154   if (!source->IsString()) {
1155     msg.Append("no source");
1156     return;
1157   }
1158
1159   switch (regexp->TypeTag()) {
1160     case JSRegExp::ATOM:
1161       msg.Append('a');
1162       break;
1163     default:
1164       break;
1165   }
1166   msg.Append('/');
1167   msg.AppendDetailed(*Handle<String>::cast(source), false);
1168   msg.Append('/');
1169
1170   // global flag
1171   Handle<Object> global = GetProperty(regexp, "global");
1172   if (global->IsTrue()) {
1173     msg.Append('g');
1174   }
1175   // ignorecase flag
1176   Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
1177   if (ignorecase->IsTrue()) {
1178     msg.Append('i');
1179   }
1180   // multiline flag
1181   Handle<Object> multiline = GetProperty(regexp, "multiline");
1182   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   msg.Append(in_cache ? ",hit\n" : ",miss\n");
1196   msg.WriteToLogFile();
1197 }
1198
1199
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   for (int i = 0; i < format.length(); i++) {
1205     char c = format[i];
1206     if (c == '%' && i <= format.length() - 2) {
1207       i++;
1208       ASSERT('0' <= format[i] && format[i] <= '9');
1209       // No exception expected when getting an element from an array literal.
1210       Handle<Object> obj =
1211           Object::GetElementNoExceptionThrown(isolate_, args, format[i] - '0');
1212       i++;
1213       switch (format[i]) {
1214         case 's':
1215           msg.AppendDetailed(String::cast(*obj), false);
1216           break;
1217         case 'S':
1218           msg.AppendDetailed(String::cast(*obj), true);
1219           break;
1220         case 'r':
1221           Logger::LogRegExpSource(Handle<JSRegExp>::cast(obj));
1222           break;
1223         case 'x':
1224           msg.Append("0x%x", Smi::cast(*obj)->value());
1225           break;
1226         case 'i':
1227           msg.Append("%i", Smi::cast(*obj)->value());
1228           break;
1229         default:
1230           UNREACHABLE();
1231       }
1232     } else {
1233       msg.Append(c);
1234     }
1235   }
1236   msg.Append('\n');
1237   msg.WriteToLogFile();
1238 }
1239
1240
1241 void Logger::ApiIndexedSecurityCheck(uint32_t index) {
1242   if (!log_->IsEnabled() || !FLAG_log_api) return;
1243   ApiEvent("api,check-security,%u\n", index);
1244 }
1245
1246
1247 void Logger::ApiNamedPropertyAccess(const char* tag,
1248                                     JSObject* holder,
1249                                     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   if (name->IsString()) {
1256     SmartArrayPointer<char> property_name =
1257         String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1258     ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, class_name.get(),
1259              property_name.get());
1260   } else {
1261     Symbol* symbol = Symbol::cast(name);
1262     uint32_t hash = symbol->Hash();
1263     if (symbol->name()->IsUndefined()) {
1264       ApiEvent("api,%s,\"%s\",symbol(hash %x)\n", tag, class_name.get(), hash);
1265     } else {
1266       SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
1267           DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1268       ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)\n",
1269                tag, class_name.get(), str.get(), hash);
1270     }
1271   }
1272 }
1273
1274 void Logger::ApiIndexedPropertyAccess(const char* tag,
1275                                       JSObject* holder,
1276                                       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              static_cast<unsigned int>(size));
1305   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) {
1318   Isolate::Current()->logger()->NewEvent(name, object, size);
1319 }
1320
1321
1322 void Logger::DeleteEventStatic(const char* name, void* object) {
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              kLogEventsNames[CODE_CREATION_EVENT],
1333              kLogEventsNames[CALLBACK_TAG]);
1334   msg.AppendAddress(entry_point);
1335   if (name->IsString()) {
1336     SmartArrayPointer<char> str =
1337         String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1338     msg.Append(",1,\"%s%s\"", prefix, str.get());
1339   } else {
1340     Symbol* symbol = Symbol::cast(name);
1341     if (symbol->name()->IsUndefined()) {
1342       msg.Append(",1,symbol(hash %x)", prefix, symbol->Hash());
1343     } else {
1344       SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
1345           DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1346       msg.Append(",1,symbol(\"%s\" hash %x)", prefix, str.get(),
1347                  symbol->Hash());
1348     }
1349   }
1350   msg.Append('\n');
1351   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 static void AppendCodeCreateHeader(Log::MessageBuilder* msg,
1374                                    Logger::LogEventsAndTags tag,
1375                                    Code* code) {
1376   ASSERT(msg);
1377   msg->Append("%s,%s,%d,",
1378               kLogEventsNames[Logger::CODE_CREATION_EVENT],
1379               kLogEventsNames[tag],
1380               code->kind());
1381   msg->AppendAddress(code->address());
1382   msg->Append(",%d,", code->ExecutableSize());
1383 }
1384
1385
1386 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1387                              Code* code,
1388                              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   AppendCodeCreateHeader(&msg, tag, code);
1397   msg.AppendDoubleQuotedString(comment);
1398   msg.Append('\n');
1399   msg.WriteToLogFile();
1400 }
1401
1402
1403 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1404                              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   if (name->IsString()) {
1415     msg.Append('"');
1416     msg.AppendDetailed(String::cast(name), false);
1417     msg.Append('"');
1418   } else {
1419     msg.AppendSymbolName(Symbol::cast(name));
1420   }
1421   msg.Append('\n');
1422   msg.WriteToLogFile();
1423 }
1424
1425
1426 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1427                              Code* code,
1428                              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     return;
1439
1440   Log::MessageBuilder msg(log_);
1441   AppendCodeCreateHeader(&msg, tag, code);
1442   if (name->IsString()) {
1443     SmartArrayPointer<char> str =
1444         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   msg.AppendAddress(shared->address());
1451   msg.Append(",%s", ComputeMarker(code));
1452   msg.Append('\n');
1453   msg.WriteToLogFile();
1454 }
1455
1456
1457 // Although, it is possible to extract source and line from
1458 // the SharedFunctionInfo object, we left it to caller
1459 // to leave logging functions free from heap allocations.
1460 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1461                              Code* code,
1462                              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   CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, source, line,
1469                                  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   if (source->IsString()) {
1478     SmartArrayPointer<char> sourcestr =
1479        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   msg.AppendAddress(shared->address());
1486   msg.Append(",%s", ComputeMarker(code));
1487   msg.Append('\n');
1488   msg.WriteToLogFile();
1489 }
1490
1491
1492 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1493                              Code* code,
1494                              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   AppendCodeCreateHeader(&msg, tag, code);
1503   msg.Append("\"args_count: %d\"", args_count);
1504   msg.Append('\n');
1505   msg.WriteToLogFile();
1506 }
1507
1508
1509 void Logger::CodeMovingGCEvent() {
1510   PROFILER_LOG(CodeMovingGCEvent());
1511
1512   if (!is_logging_code_events()) return;
1513   if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1514   CALL_LISTENERS(CodeMovingGCEvent());
1515   OS::SignalCodeMovingGC();
1516 }
1517
1518
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   AppendCodeCreateHeader(&msg, REG_EXP_TAG, code);
1528   msg.Append('"');
1529   msg.AppendDetailed(source, false);
1530   msg.Append('"');
1531   msg.Append('\n');
1532   msg.WriteToLogFile();
1533 }
1534
1535
1536 void Logger::CodeMoveEvent(Address from, Address to) {
1537   PROFILER_LOG(CodeMoveEvent(from, to));
1538
1539   if (!is_logging_code_events()) return;
1540   CALL_LISTENERS(CodeMoveEvent(from, to));
1541   MoveEventInternal(CODE_MOVE_EVENT, from, to);
1542 }
1543
1544
1545 void Logger::CodeDeleteEvent(Address from) {
1546   PROFILER_LOG(CodeDeleteEvent(from));
1547
1548   if (!is_logging_code_events()) return;
1549   CALL_LISTENERS(CodeDeleteEvent(from));
1550
1551   if (!FLAG_log_code || !log_->IsEnabled()) return;
1552   Log::MessageBuilder msg(log_);
1553   msg.Append("%s,", kLogEventsNames[CODE_DELETE_EVENT]);
1554   msg.AppendAddress(from);
1555   msg.Append('\n');
1556   msg.WriteToLogFile();
1557 }
1558
1559
1560 void Logger::CodeLinePosInfoAddPositionEvent(void* jit_handler_data,
1561                                      int pc_offset,
1562                                      int position) {
1563   JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
1564                                   pc_offset,
1565                                   position,
1566                                   JitCodeEvent::POSITION));
1567 }
1568
1569
1570 void Logger::CodeLinePosInfoAddStatementPositionEvent(void* jit_handler_data,
1571                                                       int pc_offset,
1572                                                       int position) {
1573   JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
1574                                   pc_offset,
1575                                   position,
1576                                   JitCodeEvent::STATEMENT_POSITION));
1577 }
1578
1579
1580 void Logger::CodeStartLinePosInfoRecordEvent(PositionsRecorder* pos_recorder) {
1581   if (jit_logger_ != NULL) {
1582       pos_recorder->AttachJITHandlerData(jit_logger_->StartCodePosInfoEvent());
1583   }
1584 }
1585
1586
1587 void Logger::CodeEndLinePosInfoRecordEvent(Code* code,
1588                                            void* jit_handler_data) {
1589   JIT_LOG(EndCodePosInfoEvent(code, jit_handler_data));
1590 }
1591
1592
1593 void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
1594   if (code_name == NULL) return;  // Not a code object.
1595   Log::MessageBuilder msg(log_);
1596   msg.Append("%s,%d,", kLogEventsNames[SNAPSHOT_CODE_NAME_EVENT], pos);
1597   msg.AppendDoubleQuotedString(code_name);
1598   msg.Append("\n");
1599   msg.WriteToLogFile();
1600 }
1601
1602
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   msg.AppendAddress(addr);
1610   msg.Append(",%d", pos);
1611   msg.Append('\n');
1612   msg.WriteToLogFile();
1613 }
1614
1615
1616 void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1617   PROFILER_LOG(SharedFunctionInfoMoveEvent(from, to));
1618
1619   if (!is_logging_code_events()) return;
1620   MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to);
1621 }
1622
1623
1624 void Logger::MoveEventInternal(LogEventsAndTags event,
1625                                Address from,
1626                                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   uint32_t sec, usec;
1644   if (OS::GetUserTime(&sec, &usec) != -1) {
1645     msg.Append("%d,%d,", sec, usec);
1646   }
1647   msg.Append("%.0f", OS::TimeCurrentMillis());
1648
1649   msg.Append('\n');
1650   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   String* class_name = obj->IsJSObject()
1658                        ? JSObject::cast(obj)->class_name()
1659                        : isolate_->heap()->empty_string();
1660   msg.Append("suspect-read,");
1661   msg.Append(class_name);
1662   msg.Append(',');
1663   if (name->IsString()) {
1664     msg.Append('"');
1665     msg.Append(String::cast(name));
1666     msg.Append('"');
1667   } else {
1668     msg.AppendSymbolName(Symbol::cast(name));
1669   }
1670   msg.Append('\n');
1671   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   // Using non-relative system time in order to be able to synchronize with
1679   // external memory profiling events (e.g. DOM memory size).
1680   msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
1681              space, kind, OS::TimeCurrentMillis());
1682   msg.WriteToLogFile();
1683 }
1684
1685
1686 void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1687   if (!log_->IsEnabled() || !FLAG_log_gc) return;
1688   Log::MessageBuilder msg(log_);
1689   msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1690   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   msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1698   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   msg.Append("debug-tag,%s\n", call_site_tag);
1706   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   StringBuilder s(parameter.length() + 1);
1713   for (int i = 0; i < parameter.length(); ++i) {
1714     s.AddCharacter(static_cast<char>(parameter[i]));
1715   }
1716   char* parameter_string = s.Finalize();
1717   Log::MessageBuilder msg(log_);
1718   msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1719              event_type,
1720              OS::TimeCurrentMillis(),
1721              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   msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
1731   msg.AppendAddress(sample->pc);
1732   msg.Append(",%ld", static_cast<int>(timer_.Elapsed().InMicroseconds()));
1733   if (sample->has_external_callback) {
1734     msg.Append(",1,");
1735     msg.AppendAddress(sample->external_callback);
1736   } else {
1737     msg.Append(",0,");
1738     msg.AppendAddress(sample->tos);
1739   }
1740   msg.Append(",%d", static_cast<int>(sample->state));
1741   if (overflow) {
1742     msg.Append(",overflow");
1743   }
1744   for (int i = 0; i < sample->frames_count; ++i) {
1745     msg.Append(',');
1746     msg.AppendAddress(sample->stack[i]);
1747   }
1748   msg.Append('\n');
1749   msg.WriteToLogFile();
1750 }
1751
1752
1753 void Logger::StopProfiler() {
1754   if (!log_->IsEnabled()) return;
1755   if (profiler_ != NULL) {
1756     profiler_->pause();
1757     is_logging_ = false;
1758   }
1759 }
1760
1761
1762 // This function can be called when Log's mutex is acquired,
1763 // either from main or Profiler's thread.
1764 void Logger::LogFailure() {
1765   StopProfiler();
1766 }
1767
1768
1769 class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1770  public:
1771   EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1772                                      Handle<Code>* code_objects,
1773                                      int* count)
1774       : sfis_(sfis), code_objects_(code_objects), count_(count) { }
1775
1776   virtual void EnterContext(Context* context) {}
1777   virtual void LeaveContext(Context* context) {}
1778
1779   virtual void VisitFunction(JSFunction* function) {
1780     SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
1781     Object* maybe_script = sfi->script();
1782     if (maybe_script->IsScript()
1783         && !Script::cast(maybe_script)->HasValidSource()) return;
1784     if (sfis_ != NULL) {
1785       sfis_[*count_] = Handle<SharedFunctionInfo>(sfi);
1786     }
1787     if (code_objects_ != NULL) {
1788       ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
1789       code_objects_[*count_] = Handle<Code>(function->code());
1790     }
1791     *count_ = *count_ + 1;
1792   }
1793
1794  private:
1795   Handle<SharedFunctionInfo>* sfis_;
1796   Handle<Code>* code_objects_;
1797   int* count_;
1798 };
1799
1800
1801 static int EnumerateCompiledFunctions(Heap* heap,
1802                                       Handle<SharedFunctionInfo>* sfis,
1803                                       Handle<Code>* code_objects) {
1804   HeapIterator iterator(heap);
1805   DisallowHeapAllocation no_gc;
1806   int compiled_funcs_count = 0;
1807
1808   // Iterate the heap to find shared function info objects and record
1809   // the unoptimized code for them.
1810   for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1811     if (!obj->IsSharedFunctionInfo()) continue;
1812     SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1813     if (sfi->is_compiled()
1814         && (!sfi->script()->IsScript()
1815             || Script::cast(sfi->script())->HasValidSource())) {
1816       if (sfis != NULL) {
1817         sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1818       }
1819       if (code_objects != NULL) {
1820         code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
1821       }
1822       ++compiled_funcs_count;
1823     }
1824   }
1825
1826   // Iterate all optimized functions in all contexts.
1827   EnumerateOptimizedFunctionsVisitor visitor(sfis,
1828                                              code_objects,
1829                                              &compiled_funcs_count);
1830   Deoptimizer::VisitAllOptimizedFunctions(heap->isolate(), &visitor);
1831
1832   return compiled_funcs_count;
1833 }
1834
1835
1836 void Logger::LogCodeObject(Object* object) {
1837   Code* code_object = Code::cast(object);
1838   LogEventsAndTags tag = Logger::STUB_TAG;
1839   const char* description = "Unknown code from the snapshot";
1840   switch (code_object->kind()) {
1841     case Code::FUNCTION:
1842     case Code::OPTIMIZED_FUNCTION:
1843       return;  // We log this later using LogCompiledFunctions.
1844     case Code::BINARY_OP_IC:
1845     case Code::COMPARE_IC:  // fall through
1846     case Code::COMPARE_NIL_IC:   // fall through
1847     case Code::TO_BOOLEAN_IC:  // fall through
1848     case Code::STUB:
1849       description =
1850           CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
1851       if (description == NULL)
1852         description = "A stub from the snapshot";
1853       tag = Logger::STUB_TAG;
1854       break;
1855     case Code::REGEXP:
1856       description = "Regular expression code";
1857       tag = Logger::REG_EXP_TAG;
1858       break;
1859     case Code::BUILTIN:
1860       description = "A builtin from the snapshot";
1861       tag = Logger::BUILTIN_TAG;
1862       break;
1863     case Code::HANDLER:
1864       description = "An IC handler from the snapshot";
1865       tag = Logger::HANDLER_TAG;
1866       break;
1867     case Code::KEYED_LOAD_IC:
1868       description = "A keyed load IC from the snapshot";
1869       tag = Logger::KEYED_LOAD_IC_TAG;
1870       break;
1871     case Code::LOAD_IC:
1872       description = "A load IC from the snapshot";
1873       tag = Logger::LOAD_IC_TAG;
1874       break;
1875     case Code::STORE_IC:
1876       description = "A store IC from the snapshot";
1877       tag = Logger::STORE_IC_TAG;
1878       break;
1879     case Code::KEYED_STORE_IC:
1880       description = "A keyed store IC from the snapshot";
1881       tag = Logger::KEYED_STORE_IC_TAG;
1882       break;
1883     case Code::NUMBER_OF_KINDS:
1884       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   for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1897     if (obj->IsCode()) LogCodeObject(obj);
1898   }
1899 }
1900
1901
1902 void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
1903                                  Handle<Code> code) {
1904   Handle<String> func_name(shared->DebugName());
1905   if (shared->script()->IsScript()) {
1906     Handle<Script> script(Script::cast(shared->script()));
1907     int line_num = GetScriptLineNumber(script, shared->start_position()) + 1;
1908     int column_num =
1909         GetScriptColumnNumber(script, shared->start_position()) + 1;
1910     if (script->name()->IsString()) {
1911       Handle<String> script_name(String::cast(script->name()));
1912       if (line_num > 0) {
1913         PROFILE(isolate_,
1914                 CodeCreateEvent(
1915                     Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1916                     *code, *shared, NULL,
1917                     *script_name, line_num, column_num));
1918       } else {
1919         // Can't distinguish eval and script here, so always use Script.
1920         PROFILE(isolate_,
1921                 CodeCreateEvent(
1922                     Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1923                     *code, *shared, NULL, *script_name));
1924       }
1925     } else {
1926       PROFILE(isolate_,
1927               CodeCreateEvent(
1928                   Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1929                   *code, *shared, NULL,
1930                   isolate_->heap()->empty_string(), line_num, column_num));
1931     }
1932   } else if (shared->IsApiFunction()) {
1933     // API function.
1934     FunctionTemplateInfo* fun_data = shared->get_api_func_data();
1935     Object* raw_call_data = fun_data->call_code();
1936     if (!raw_call_data->IsUndefined()) {
1937       CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1938       Object* callback_obj = call_data->callback();
1939       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   // During iteration, there can be heap allocation due to
1961   // GetScriptLineNumber call.
1962   for (int i = 0; i < compiled_funcs_count; ++i) {
1963     if (code_objects[i].is_identical_to(
1964             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     if (!obj->IsExecutableAccessorInfo()) continue;
1979     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     Address setter_entry = v8::ToCData<Address>(ai->setter());
1987     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   stream->Add("isolate-%p-", isolate);
1997 }
1998
1999
2000 static SmartArrayPointer<const char> PrepareLogFileName(
2001     Isolate* isolate, const char* file_name) {
2002   if (strchr(file_name, '%') != NULL || !isolate->IsDefaultIsolate()) {
2003     // If there's a '%' in the log file name we have to expand
2004     // placeholders.
2005     HeapStringAllocator allocator;
2006     StringStream stream(&allocator);
2007     AddIsolateIdIfNeeded(isolate, &stream);
2008     for (const char* p = file_name; *p; p++) {
2009       if (*p == '%') {
2010         p++;
2011         switch (*p) {
2012           case '\0':
2013             // If there's a % at the end of the string we back up
2014             // one character so we can escape the loop properly.
2015             p--;
2016             break;
2017           case 'p':
2018             stream.Add("%d", OS::GetCurrentProcessId());
2019             break;
2020           case 't': {
2021             // %t expands to the current time in milliseconds.
2022             double time = OS::TimeCurrentMillis();
2023             stream.Add("%.0f", FmtElm(time));
2024             break;
2025           }
2026           case '%':
2027             // %% expands (contracts really) to %.
2028             stream.Put('%');
2029             break;
2030           default:
2031             // All other %'s expand to themselves.
2032             stream.Put('%');
2033             stream.Put(*p);
2034             break;
2035         }
2036       } else {
2037         stream.Put(*p);
2038       }
2039     }
2040     return SmartArrayPointer<const char>(stream.ToCString());
2041   }
2042   int length = StrLength(file_name);
2043   char* str = NewArray<char>(length + 1);
2044   OS::MemCopy(str, file_name, length);
2045   str[length] = '\0';
2046   return SmartArrayPointer<const char>(str);
2047 }
2048
2049
2050 bool Logger::SetUp(Isolate* isolate) {
2051   // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
2052   if (is_initialized_) return true;
2053   is_initialized_ = true;
2054
2055   // --ll-prof implies --log-code and --log-snapshot-positions.
2056   if (FLAG_ll_prof) {
2057     FLAG_log_snapshot_positions = true;
2058   }
2059
2060   SmartArrayPointer<const char> log_file_name =
2061       PrepareLogFileName(isolate, FLAG_logfile);
2062   log_->Initialize(log_file_name.get());
2063
2064
2065   if (FLAG_perf_basic_prof) {
2066     perf_basic_logger_ = new PerfBasicLogger();
2067     addCodeEventListener(perf_basic_logger_);
2068   }
2069
2070   if (FLAG_perf_jit_prof) {
2071     perf_jit_logger_ = new PerfJitLogger();
2072     addCodeEventListener(perf_jit_logger_);
2073   }
2074
2075   if (FLAG_ll_prof) {
2076     ll_logger_ = new LowLevelLogger(log_file_name.get());
2077     addCodeEventListener(ll_logger_);
2078   }
2079
2080   ticker_ = new Ticker(isolate, kSamplingIntervalMs);
2081
2082   if (Log::InitLogAtStart()) {
2083     is_logging_ = true;
2084   }
2085
2086   if (FLAG_prof) {
2087     profiler_ = new Profiler(isolate);
2088     is_logging_ = true;
2089     profiler_->Engage();
2090   }
2091
2092   if (FLAG_log_internal_timer_events || FLAG_prof) timer_.Start();
2093
2094   return true;
2095 }
2096
2097
2098 void Logger::SetCodeEventHandler(uint32_t options,
2099                                  JitCodeEventHandler event_handler) {
2100   if (jit_logger_) {
2101       removeCodeEventListener(jit_logger_);
2102       delete jit_logger_;
2103       jit_logger_ = NULL;
2104   }
2105
2106   if (event_handler) {
2107     jit_logger_ = new JitLogger(event_handler);
2108     addCodeEventListener(jit_logger_);
2109     if (options & kJitCodeEventEnumExisting) {
2110       HandleScope scope(isolate_);
2111       LogCodeObjects();
2112       LogCompiledFunctions();
2113     }
2114   }
2115 }
2116
2117
2118 Sampler* Logger::sampler() {
2119   return ticker_;
2120 }
2121
2122
2123 FILE* Logger::TearDown() {
2124   if (!is_initialized_) return NULL;
2125   is_initialized_ = false;
2126
2127   // Stop the profiler before closing the file.
2128   if (profiler_ != NULL) {
2129     profiler_->Disengage();
2130     delete profiler_;
2131     profiler_ = NULL;
2132   }
2133
2134   delete ticker_;
2135   ticker_ = NULL;
2136
2137   if (perf_basic_logger_) {
2138     removeCodeEventListener(perf_basic_logger_);
2139     delete perf_basic_logger_;
2140     perf_basic_logger_ = NULL;
2141   }
2142
2143   if (perf_jit_logger_) {
2144     removeCodeEventListener(perf_jit_logger_);
2145     delete perf_jit_logger_;
2146     perf_jit_logger_ = NULL;
2147   }
2148
2149   if (ll_logger_) {
2150     removeCodeEventListener(ll_logger_);
2151     delete ll_logger_;
2152     ll_logger_ = NULL;
2153   }
2154
2155   if (jit_logger_) {
2156     removeCodeEventListener(jit_logger_);
2157     delete jit_logger_;
2158     jit_logger_ = NULL;
2159   }
2160
2161   return log_->Close();
2162 }
2163
2164 } }  // namespace v8::internal