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 // XDK support
  47 #include "third_party/xdk/xdk-v8.h"
  48
  49 namespace v8 {
  50 namespace internal {
  51
  52
  53 #define DECLARE_EVENT(ignore1, name) name,
  54 static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
  55   LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
  56 };
  57 #undef DECLARE_EVENT
  58
  59
  60 #define CALL_LISTENERS(Call)                    \
  61 for (int i = 0; i < listeners_.length(); ++i) { \
  62   listeners_[i]->Call;                          \
  63 }
  64
  65 #define PROFILER_LOG(Call)                                \
  66   do {                                                    \
  67     CpuProfiler* cpu_profiler = isolate_->cpu_profiler(); \
  68     if (cpu_profiler->is_profiling()) {                   \
  69       cpu_profiler->Call;                                 \
  70     }                                                     \
  71   } while (false);
  72
  73 // ComputeMarker must only be used when SharedFunctionInfo is known.
  74 static const char* ComputeMarker(Code* code) {
  75   switch (code->kind()) {
  76     case Code::FUNCTION: return code->optimizable() ? "~" : "";
  77     case Code::OPTIMIZED_FUNCTION: return "*";
  78     default: return "";
  79   }
  80 }
  81
  82
  83 class CodeEventLogger::NameBuffer {
  84  public:
  85   NameBuffer() { Reset(); }
  86
  87   void Reset() {
  88     utf8_pos_ = 0;
  89   }
  90
  91   void Init(Logger::LogEventsAndTags tag) {
  92     Reset();
  93     AppendBytes(kLogEventsNames[tag]);
  94     AppendByte(':');
  95   }
  96
  97   void AppendName(Name* name) {
  98     if (name->IsString()) {
  99       AppendString(String::cast(name));
 100     } else {
 101       Symbol* symbol = Symbol::cast(name);
 102       AppendBytes("symbol(");
 103       if (!symbol->name()->IsUndefined()) {
 104         AppendBytes("\"");
 105         AppendString(String::cast(symbol->name()));
 106         AppendBytes("\" ");
 107       }
 108       AppendBytes("hash ");
 109       AppendHex(symbol->Hash());
 110       AppendByte(')');
 111     }
 112   }
 113
 114   void AppendString(String* str) {
 115     if (str == NULL) return;
 116     int uc16_length = Min(str->length(), kUtf16BufferSize);
 117     String::WriteToFlat(str, utf16_buffer, 0, uc16_length);
 118     int previous = unibrow::Utf16::kNoPreviousCharacter;
 119     for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
 120       uc16 c = utf16_buffer[i];
 121       if (c <= unibrow::Utf8::kMaxOneByteChar) {
 122         utf8_buffer_[utf8_pos_++] = static_cast<char>(c);
 123       } else {
 124         int char_length = unibrow::Utf8::Length(c, previous);
 125         if (utf8_pos_ + char_length > kUtf8BufferSize) break;
 126         unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous);
 127         utf8_pos_ += char_length;
 128       }
 129       previous = c;
 130     }
 131   }
 132
 133   void AppendBytes(const char* bytes, int size) {
 134     size = Min(size, kUtf8BufferSize - utf8_pos_);
 135     OS::MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
 136     utf8_pos_ += size;
 137   }
 138
 139   void AppendBytes(const char* bytes) {
 140     AppendBytes(bytes, StrLength(bytes));
 141   }
 142
 143   void AppendByte(char c) {
 144     if (utf8_pos_ >= kUtf8BufferSize) return;
 145     utf8_buffer_[utf8_pos_++] = c;
 146   }
 147
 148   void AppendInt(int n) {
 149     Vector<char> buffer(utf8_buffer_ + utf8_pos_,
 150                         kUtf8BufferSize - utf8_pos_);
 151     int size = OS::SNPrintF(buffer, "%d", n);
 152     if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
 153       utf8_pos_ += size;
 154     }
 155   }
 156
 157   void AppendHex(uint32_t n) {
 158     Vector<char> buffer(utf8_buffer_ + utf8_pos_,
 159                         kUtf8BufferSize - utf8_pos_);
 160     int size = OS::SNPrintF(buffer, "%x", n);
 161     if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
 162       utf8_pos_ += size;
 163     }
 164   }
 165
 166   // XDK needs this function temporarily. It will be removed later.
 167   void AppendAddress(Address address) {
 168     Vector<char> buffer(utf8_buffer_ + utf8_pos_, kUtf8BufferSize - utf8_pos_);
 169     int size = OS::SNPrintF(buffer, "0x%x", address);
 170     if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
 171       utf8_pos_ += size;
 172     }
 173   }
 174
 175   const char* get() { return utf8_buffer_; }
 176   int size() const { return utf8_pos_; }
 177
 178  private:
 179   static const int kUtf8BufferSize = 512;
 180   static const int kUtf16BufferSize = 128;
 181
 182   int utf8_pos_;
 183   char utf8_buffer_[kUtf8BufferSize];
 184   uc16 utf16_buffer[kUtf16BufferSize];
 185 };
 186
 187
 188 CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { }
 189
 190 CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }
 191
 192
 193 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
 194                                       Code* code,
 195                                       const char* comment) {
 196   name_buffer_->Init(tag);
 197   name_buffer_->AppendBytes(comment);
 198   LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
 199 }
 200
 201
 202 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
 203                                       Code* code,
 204                                       Name* name) {
 205   name_buffer_->Init(tag);
 206   name_buffer_->AppendName(name);
 207   LogRecordedBuffer(code, NULL, 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* name) {
 216   name_buffer_->Init(tag);
 217   name_buffer_->AppendBytes(ComputeMarker(code));
 218   name_buffer_->AppendName(name);
 219   LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
 220 }
 221
 222
 223 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
 224                                       Code* code,
 225                                       SharedFunctionInfo* shared,
 226                                       CompilationInfo* info,
 227                                       Name* source, int line, int column) {
 228   name_buffer_->Init(tag);
 229   name_buffer_->AppendBytes(ComputeMarker(code));
 230   name_buffer_->AppendString(shared->DebugName());
 231   name_buffer_->AppendByte(' ');
 232   if (source->IsString()) {
 233     name_buffer_->AppendString(String::cast(source));
 234   } else {
 235     name_buffer_->AppendBytes("symbol(hash ");
 236     name_buffer_->AppendHex(Name::cast(source)->Hash());
 237     name_buffer_->AppendByte(')');
 238   }
 239   name_buffer_->AppendByte(':');
 240   name_buffer_->AppendInt(line);
 241   LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
 242 }
 243
 244
 245 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
 246                                       Code* code,
 247                                       int args_count) {
 248   name_buffer_->Init(tag);
 249   name_buffer_->AppendInt(args_count);
 250   LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
 251 }
 252
 253
 254 void CodeEventLogger::RegExpCodeCreateEvent(Code* code, String* source) {
 255   name_buffer_->Init(Logger::REG_EXP_TAG);
 256   name_buffer_->AppendString(source);
 257   LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
 258 }
 259
 260
 261 // Linux perf tool logging support
 262 class PerfBasicLogger : public CodeEventLogger {
 263  public:
 264   PerfBasicLogger();
 265   virtual ~PerfBasicLogger();
 266
 267   virtual void CodeMoveEvent(Address from, Address to) { }
 268   virtual void CodeDeleteEvent(Address from) { }
 269
 270  private:
 271   virtual void LogRecordedBuffer(Code* code,
 272                                  SharedFunctionInfo* shared,
 273                                  const char* name,
 274                                  int length);
 275
 276   // Extension added to V8 log file name to get the low-level log name.
 277   static const char kFilenameFormatString[];
 278   static const int kFilenameBufferPadding;
 279
 280   // File buffer size of the low-level log. We don't use the default to
 281   // minimize the associated overhead.
 282   static const int kLogBufferSize = 2 * MB;
 283
 284   FILE* perf_output_handle_;
 285 };
 286
 287 const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
 288 // Extra space for the PID in the filename
 289 const int PerfBasicLogger::kFilenameBufferPadding = 16;
 290
 291 PerfBasicLogger::PerfBasicLogger()
 292     : perf_output_handle_(NULL) {
 293   // Open the perf JIT dump file.
 294   int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
 295   ScopedVector<char> perf_dump_name(bufferSize);
 296   int size = OS::SNPrintF(
 297       perf_dump_name,
 298       kFilenameFormatString,
 299       OS::GetCurrentProcessId());
 300   CHECK_NE(size, -1);
 301   perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);
 302   CHECK_NE(perf_output_handle_, NULL);
 303   setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);
 304 }
 305
 306
 307 PerfBasicLogger::~PerfBasicLogger() {
 308   fclose(perf_output_handle_);
 309   perf_output_handle_ = NULL;
 310 }
 311
 312
 313 void PerfBasicLogger::LogRecordedBuffer(Code* code,
 314                                        SharedFunctionInfo*,
 315                                        const char* name,
 316                                        int length) {
 317   ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);
 318
 319   OS::FPrint(perf_output_handle_, "%llx %x %.*s\n",
 320       reinterpret_cast<uint64_t>(code->instruction_start()),
 321       code->instruction_size(),
 322       length, name);
 323 }
 324
 325
 326 // Linux perf tool logging support
 327 class PerfJitLogger : public CodeEventLogger {
 328  public:
 329   PerfJitLogger();
 330   virtual ~PerfJitLogger();
 331
 332   virtual void CodeMoveEvent(Address from, Address to) { }
 333   virtual void CodeDeleteEvent(Address from) { }
 334
 335  private:
 336   virtual void LogRecordedBuffer(Code* code,
 337                                  SharedFunctionInfo* shared,
 338                                  const char* name,
 339                                  int length);
 340
 341   // Extension added to V8 log file name to get the low-level log name.
 342   static const char kFilenameFormatString[];
 343   static const int kFilenameBufferPadding;
 344
 345   // File buffer size of the low-level log. We don't use the default to
 346   // minimize the associated overhead.
 347   static const int kLogBufferSize = 2 * MB;
 348
 349   void LogWriteBytes(const char* bytes, int size);
 350   void LogWriteHeader();
 351
 352   static const uint32_t kJitHeaderMagic = 0x4F74496A;
 353   static const uint32_t kJitHeaderVersion = 0x2;
 354   static const uint32_t kElfMachIA32 = 3;
 355   static const uint32_t kElfMachX64 = 62;
 356   static const uint32_t kElfMachARM = 40;
 357   static const uint32_t kElfMachMIPS = 10;
 358
 359   struct jitheader {
 360     uint32_t magic;
 361     uint32_t version;
 362     uint32_t total_size;
 363     uint32_t elf_mach;
 364     uint32_t pad1;
 365     uint32_t pid;
 366     uint64_t timestamp;
 367   };
 368
 369   enum jit_record_type {
 370     JIT_CODE_LOAD = 0
 371     // JIT_CODE_UNLOAD = 1,
 372     // JIT_CODE_CLOSE = 2,
 373     // JIT_CODE_DEBUG_INFO = 3,
 374     // JIT_CODE_PAGE_MAP = 4,
 375     // JIT_CODE_MAX = 5
 376   };
 377
 378   struct jr_code_load {
 379     uint32_t id;
 380     uint32_t total_size;
 381     uint64_t timestamp;
 382     uint64_t vma;
 383     uint64_t code_addr;
 384     uint32_t code_size;
 385     uint32_t align;
 386   };
 387
 388   uint32_t GetElfMach() {
 389 #if V8_TARGET_ARCH_IA32
 390     return kElfMachIA32;
 391 #elif V8_TARGET_ARCH_X64
 392     return kElfMachX64;
 393 #elif V8_TARGET_ARCH_ARM
 394     return kElfMachARM;
 395 #elif V8_TARGET_ARCH_MIPS
 396     return kElfMachMIPS;
 397 #else
 398     UNIMPLEMENTED();
 399     return 0;
 400 #endif
 401   }
 402
 403   FILE* perf_output_handle_;
 404 };
 405
 406 const char PerfJitLogger::kFilenameFormatString[] = "/tmp/jit-%d.dump";
 407
 408 // Extra padding for the PID in the filename
 409 const int PerfJitLogger::kFilenameBufferPadding = 16;
 410
 411 PerfJitLogger::PerfJitLogger()
 412     : perf_output_handle_(NULL) {
 413   // Open the perf JIT dump file.
 414   int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
 415   ScopedVector<char> perf_dump_name(bufferSize);
 416   int size = OS::SNPrintF(
 417       perf_dump_name,
 418       kFilenameFormatString,
 419       OS::GetCurrentProcessId());
 420   CHECK_NE(size, -1);
 421   perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);
 422   CHECK_NE(perf_output_handle_, NULL);
 423   setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);
 424
 425   LogWriteHeader();
 426 }
 427
 428
 429 PerfJitLogger::~PerfJitLogger() {
 430   fclose(perf_output_handle_);
 431   perf_output_handle_ = NULL;
 432 }
 433
 434
 435 void PerfJitLogger::LogRecordedBuffer(Code* code,
 436                                       SharedFunctionInfo*,
 437                                       const char* name,
 438                                       int length) {
 439   ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);
 440   ASSERT(perf_output_handle_ != NULL);
 441
 442   const char* code_name = name;
 443   uint8_t* code_pointer = reinterpret_cast<uint8_t*>(code->instruction_start());
 444   uint32_t code_size = code->instruction_size();
 445
 446   static const char string_terminator[] = "\0";
 447
 448   jr_code_load code_load;
 449   code_load.id = JIT_CODE_LOAD;
 450   code_load.total_size = sizeof(code_load) + length + 1 + code_size;
 451   code_load.timestamp =
 452       static_cast<uint64_t>(OS::TimeCurrentMillis() * 1000.0);
 453   code_load.vma = 0x0;  //  Our addresses are absolute.
 454   code_load.code_addr = reinterpret_cast<uint64_t>(code->instruction_start());
 455   code_load.code_size = code_size;
 456   code_load.align = 0;
 457
 458   LogWriteBytes(reinterpret_cast<const char*>(&code_load), sizeof(code_load));
 459   LogWriteBytes(code_name, length);
 460   LogWriteBytes(string_terminator, 1);
 461   LogWriteBytes(reinterpret_cast<const char*>(code_pointer), code_size);
 462 }
 463
 464
 465 void PerfJitLogger::LogWriteBytes(const char* bytes, int size) {
 466   size_t rv = fwrite(bytes, 1, size, perf_output_handle_);
 467   ASSERT(static_cast<size_t>(size) == rv);
 468   USE(rv);
 469 }
 470
 471
 472 void PerfJitLogger::LogWriteHeader() {
 473   ASSERT(perf_output_handle_ != NULL);
 474   jitheader header;
 475   header.magic = kJitHeaderMagic;
 476   header.version = kJitHeaderVersion;
 477   header.total_size = sizeof(jitheader);
 478   header.pad1 = 0xdeadbeef;
 479   header.elf_mach = GetElfMach();
 480   header.pid = OS::GetCurrentProcessId();
 481   header.timestamp = static_cast<uint64_t>(OS::TimeCurrentMillis() * 1000.0);
 482   LogWriteBytes(reinterpret_cast<const char*>(&header), sizeof(header));
 483 }
 484
 485
 486 // Low-level logging support.
 487 #define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;
 488
 489 class LowLevelLogger : public CodeEventLogger {
 490  public:
 491   explicit LowLevelLogger(const char* file_name);
 492   virtual ~LowLevelLogger();
 493
 494   virtual void CodeMoveEvent(Address from, Address to);
 495   virtual void CodeDeleteEvent(Address from);
 496   virtual void SnapshotPositionEvent(Address addr, int pos);
 497   virtual void CodeMovingGCEvent();
 498
 499  private:
 500   virtual void LogRecordedBuffer(Code* code,
 501                                  SharedFunctionInfo* shared,
 502                                  const char* name,
 503                                  int length);
 504
 505   // Low-level profiling event structures.
 506   struct CodeCreateStruct {
 507     static const char kTag = 'C';
 508
 509     int32_t name_size;
 510     Address code_address;
 511     int32_t code_size;
 512   };
 513
 514
 515   struct CodeMoveStruct {
 516     static const char kTag = 'M';
 517
 518     Address from_address;
 519     Address to_address;
 520   };
 521
 522
 523   struct CodeDeleteStruct {
 524     static const char kTag = 'D';
 525
 526     Address address;
 527   };
 528
 529
 530   struct SnapshotPositionStruct {
 531     static const char kTag = 'P';
 532
 533     Address address;
 534     int32_t position;
 535   };
 536
 537
 538   static const char kCodeMovingGCTag = 'G';
 539
 540
 541   // Extension added to V8 log file name to get the low-level log name.
 542   static const char kLogExt[];
 543
 544   // File buffer size of the low-level log. We don't use the default to
 545   // minimize the associated overhead.
 546   static const int kLogBufferSize = 2 * MB;
 547
 548   void LogCodeInfo();
 549   void LogWriteBytes(const char* bytes, int size);
 550
 551   template <typename T>
 552   void LogWriteStruct(const T& s) {
 553     char tag = T::kTag;
 554     LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag));
 555     LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
 556   }
 557
 558   FILE* ll_output_handle_;
 559 };
 560
 561 const char LowLevelLogger::kLogExt[] = ".ll";
 562
 563 LowLevelLogger::LowLevelLogger(const char* name)
 564     : ll_output_handle_(NULL) {
 565   // Open the low-level log file.
 566   size_t len = strlen(name);
 567   ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt)));
 568   OS::MemCopy(ll_name.start(), name, len);
 569   OS::MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
 570   ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode);
 571   setvbuf(ll_output_handle_, NULL, _IOFBF, kLogBufferSize);
 572
 573   LogCodeInfo();
 574 }
 575
 576
 577 LowLevelLogger::~LowLevelLogger() {
 578   fclose(ll_output_handle_);
 579   ll_output_handle_ = NULL;
 580 }
 581
 582
 583 void LowLevelLogger::LogCodeInfo() {
 584 #if V8_TARGET_ARCH_IA32
 585   const char arch[] = "ia32";
 586 #elif V8_TARGET_ARCH_X64
 587   const char arch[] = "x64";
 588 #elif V8_TARGET_ARCH_ARM
 589   const char arch[] = "arm";
 590 #elif V8_TARGET_ARCH_MIPS
 591   const char arch[] = "mips";
 592 #else
 593   const char arch[] = "unknown";
 594 #endif
 595   LogWriteBytes(arch, sizeof(arch));
 596 }
 597
 598
 599 void LowLevelLogger::LogRecordedBuffer(Code* code,
 600                                        SharedFunctionInfo*,
 601                                        const char* name,
 602                                        int length) {
 603   CodeCreateStruct event;
 604   event.name_size = length;
 605   event.code_address = code->instruction_start();
 606   ASSERT(event.code_address == code->address() + Code::kHeaderSize);
 607   event.code_size = code->instruction_size();
 608   LogWriteStruct(event);
 609   LogWriteBytes(name, length);
 610   LogWriteBytes(
 611       reinterpret_cast<const char*>(code->instruction_start()),
 612       code->instruction_size());
 613 }
 614
 615
 616 void LowLevelLogger::CodeMoveEvent(Address from, Address to) {
 617   CodeMoveStruct event;
 618   event.from_address = from + Code::kHeaderSize;
 619   event.to_address = to + Code::kHeaderSize;
 620   LogWriteStruct(event);
 621 }
 622
 623
 624 void LowLevelLogger::CodeDeleteEvent(Address from) {
 625   CodeDeleteStruct event;
 626   event.address = from + Code::kHeaderSize;
 627   LogWriteStruct(event);
 628 }
 629
 630
 631 void LowLevelLogger::SnapshotPositionEvent(Address addr, int pos) {
 632   SnapshotPositionStruct event;
 633   event.address = addr + Code::kHeaderSize;
 634   event.position = pos;
 635   LogWriteStruct(event);
 636 }
 637
 638
 639 void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
 640   size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
 641   ASSERT(static_cast<size_t>(size) == rv);
 642   USE(rv);
 643 }
 644
 645
 646 void LowLevelLogger::CodeMovingGCEvent() {
 647   const char tag = kCodeMovingGCTag;
 648
 649   LogWriteBytes(&tag, sizeof(tag));
 650 }
 651
 652
 653 #define JIT_LOG(Call) if (jit_logger_) jit_logger_->Call;
 654
 655
 656 class JitLogger : public CodeEventLogger {
 657  public:
 658   explicit JitLogger(JitCodeEventHandler code_event_handler);
 659
 660   virtual void CodeMoveEvent(Address from, Address to);
 661   virtual void CodeDeleteEvent(Address from);
 662   virtual void AddCodeLinePosInfoEvent(
 663       void* jit_handler_data,
 664       int pc_offset,
 665       int position,
 666       JitCodeEvent::PositionType position_type);
 667
 668   void* StartCodePosInfoEvent();
 669   void EndCodePosInfoEvent(Code* code, void* jit_handler_data);
 670
 671
 672   // >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
 673   // XDK needs all this stuff below to generate the strings like
 674   // "code-creation:..." in the same format as Logger generates.
 675   // This string is sent to XDK by code_event_handler and then used for
 676   // postprocessing. All these CodeCreateEvent(...) functions and helpers
 677   // will be removed before commit.
 678   void AppendCodeCreateHeader(NameBuffer* msg,
 679                               Logger::LogEventsAndTags tag,
 680                               Code* code) {
 681     CHECK(msg);
 682     msg->AppendBytes(kLogEventsNames[Logger::CODE_CREATION_EVENT]);
 683     msg->AppendByte(',');
 684     msg->AppendBytes(kLogEventsNames[tag]);
 685     msg->AppendByte(',');
 686     msg->AppendInt(code->kind());
 687     msg->AppendByte(',');
 688     msg->AppendAddress(code->instruction_start());
 689     msg->AppendByte(',');
 690     msg->AppendInt(code->instruction_size());
 691     msg->AppendByte(',');
 692   }
 693
 694
 695   void AppendDetailed(NameBuffer* msg, String* str, bool show_impl_info) {
 696     CHECK(msg);
 697     if (str == NULL) return;
 698     DisallowHeapAllocation no_gc;  // Ensure string stay valid.
 699     int len = str->length();
 700     if (len > 0x1000)
 701       len = 0x1000;
 702     if (show_impl_info) {
 703       msg->AppendByte(str->IsOneByteRepresentation() ? 'a' : '2');
 704       if (StringShape(str).IsExternal())
 705         msg->AppendByte('e');
 706       if (StringShape(str).IsInternalized())
 707         msg->AppendByte('#');
 708       msg->AppendByte(':');
 709       msg->AppendInt(str->length());
 710       msg->AppendByte(':');
 711     }
 712     for (int i = 0; i < len; i++) {
 713       uc32 c = str->Get(i);
 714       if (c > 0xff) {
 715         msg->AppendBytes("\\u");
 716         msg->AppendHex(c);
 717       } else if (c < 32 || c > 126) {
 718         msg->AppendBytes("\\x");
 719         msg->AppendHex(c);
 720       } else if (c == ',') {
 721         msg->AppendBytes("\\,");
 722       } else if (c == '\\') {
 723         msg->AppendBytes("\\\\");
 724       } else if (c == '\"') {
 725         msg->AppendBytes("\"\"");
 726       } else {
 727         msg->AppendByte(c);
 728       }
 729     }
 730   }
 731
 732
 733   void AppendDoubleQuotedString(NameBuffer* msg, const char* string) {
 734     CHECK(msg);
 735     msg->AppendByte('"');
 736     for (const char* p = string; *p != '\0'; p++) {
 737       if (*p == '"') {
 738         msg->AppendByte('\\');
 739      }
 740       msg->AppendByte(*p);
 741     }
 742     msg->AppendByte('"');
 743   }
 744
 745
 746   void AppendSymbolName(NameBuffer* msg, Symbol* symbol) {
 747     CHECK(msg);
 748     ASSERT(symbol);
 749     msg->AppendBytes("symbol(");
 750     if (!symbol->name()->IsUndefined()) {
 751       msg->AppendByte('"');
 752       AppendDetailed(msg, String::cast(symbol->name()), false);
 753       msg->AppendBytes("\" ");
 754     }
 755     msg->AppendBytes("hash ");
 756     msg->AppendHex(symbol->Hash());
 757     msg->AppendByte(')');
 758   }
 759
 760
 761   virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
 762                                Code* code, const char* comment) {
 763     if (!xdk::XDKIsAgentAlive()) {
 764       CodeEventLogger::CodeCreateEvent(tag, code, comment);
 765       return;
 766     }
 767
 768     name_buffer_->Reset();
 769     AppendCodeCreateHeader(name_buffer_, tag, code);
 770     AppendDoubleQuotedString(name_buffer_, comment);
 771     LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
 772   }
 773
 774
 775   virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
 776                                Code* code, Name* name) {
 777     if (!xdk::XDKIsAgentAlive()) {
 778        CodeEventLogger::CodeCreateEvent(tag, code, name);
 779        return;
 780     }
 781
 782     name_buffer_->Reset();
 783     AppendCodeCreateHeader(name_buffer_, tag, code);
 784     if (name->IsString()) {
 785       name_buffer_->AppendByte('"');
 786       AppendDetailed(name_buffer_, String::cast(name), false);
 787       name_buffer_->AppendByte('"');
 788     } else {
 789       AppendSymbolName(name_buffer_, Symbol::cast(name));
 790     }
 791     LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
 792   }
 793
 794
 795   virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
 796                                Code* code,
 797                                SharedFunctionInfo* shared,
 798                                CompilationInfo* info,
 799                                Name* name) {
 800     if (!xdk::XDKIsAgentAlive()) {
 801       CodeEventLogger::CodeCreateEvent(tag, code, shared, info, name);
 802       return;
 803     }
 804
 805     name_buffer_->Reset();
 806     AppendCodeCreateHeader(name_buffer_, tag, code);
 807     if (name->IsString()) {
 808       SmartArrayPointer<char> str =
 809          String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
 810       name_buffer_->AppendByte('"');
 811       name_buffer_->AppendBytes(str.get());
 812       name_buffer_->AppendByte('"');
 813     } else {
 814       AppendSymbolName(name_buffer_, Symbol::cast(name));
 815     }
 816     name_buffer_->AppendByte(',');
 817     name_buffer_->AppendAddress(shared->address());
 818     name_buffer_->AppendByte(',');
 819     name_buffer_->AppendBytes(ComputeMarker(code));
 820     LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
 821   }
 822
 823   virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
 824                                Code* code,
 825                                SharedFunctionInfo* shared,
 826                                CompilationInfo* info,
 827                                Name* source,
 828                                int line, int column) {
 829     if (!xdk::XDKIsAgentAlive()) {
 830       CodeEventLogger::CodeCreateEvent(tag, code, shared,
 831                                        info, source, line, column);
 832       return;
 833     }
 834
 835     name_buffer_->Reset();
 836     AppendCodeCreateHeader(name_buffer_, tag, code);
 837     SmartArrayPointer<char> name =
 838         shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
 839     name_buffer_->AppendByte('"');
 840     name_buffer_->AppendBytes(name.get());
 841     name_buffer_->AppendByte(' ');
 842     if (source->IsString()) {
 843         SmartArrayPointer<char> sourcestr =
 844            String::cast(source)->ToCString(DISALLOW_NULLS,
 845                                            ROBUST_STRING_TRAVERSAL);
 846         name_buffer_->AppendBytes(sourcestr.get());
 847     } else {
 848         AppendSymbolName(name_buffer_, Symbol::cast(source));
 849     }
 850     name_buffer_->AppendByte(':');
 851     name_buffer_->AppendInt(line);
 852     name_buffer_->AppendByte(':');
 853     name_buffer_->AppendInt(column);
 854     name_buffer_->AppendBytes("\",");
 855     name_buffer_->AppendAddress(shared->address());
 856     name_buffer_->AppendByte(',');
 857     name_buffer_->AppendBytes(ComputeMarker(code));
 858     LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
 859   }
 860
 861
 862   virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
 863                                Code* code,
 864                                int args_count) {
 865     if (!xdk::XDKIsAgentAlive()) {
 866       CodeEventLogger::CodeCreateEvent(tag, code, args_count);
 867       return;
 868     }
 869
 870     name_buffer_->Reset();
 871     AppendCodeCreateHeader(name_buffer_, tag, code);
 872     name_buffer_->AppendBytes("\"args_count: ");
 873     name_buffer_->AppendInt(args_count);
 874     name_buffer_->AppendByte('"');
 875   }
 876
 877
 878   virtual void RegExpCodeCreateEvent(Code* code, String* source) {
 879     if (!xdk::XDKIsAgentAlive()) {
 880       CodeEventLogger::RegExpCodeCreateEvent(code, source);
 881       return;
 882     }
 883
 884     name_buffer_->Reset();
 885     AppendCodeCreateHeader(name_buffer_, Logger::REG_EXP_TAG, code);
 886     name_buffer_->AppendByte('"');
 887     AppendDetailed(name_buffer_, source, false);
 888     name_buffer_->AppendByte('"');
 889   }
 890
 891  private:
 892   virtual void LogRecordedBuffer(Code* code,
 893                                  SharedFunctionInfo* shared,
 894                                  const char* name,
 895                                  int length);
 896
 897   JitCodeEventHandler code_event_handler_;
 898 };
 899
 900
 901 JitLogger::JitLogger(JitCodeEventHandler code_event_handler)
 902     : code_event_handler_(code_event_handler) {
 903 }
 904
 905
 906 void JitLogger::LogRecordedBuffer(Code* code,
 907                                   SharedFunctionInfo* shared,
 908                                   const char* name,
 909                                   int length) {
 910   JitCodeEvent event;
 911   memset(&event, 0, sizeof(event));
 912   event.type = JitCodeEvent::CODE_ADDED;
 913   event.code_start = code->instruction_start();
 914   event.code_len = code->instruction_size();
 915   Handle<Script> script_handle;
 916   if (shared && shared->script()->IsScript()) {
 917     script_handle = Handle<Script>(Script::cast(shared->script()));
 918   }
 919   event.script = ToApiHandle<v8::Script>(script_handle);
 920   event.name.str = name;
 921   event.name.len = length;
 922   code_event_handler_(&event);
 923 }
 924
 925
 926 void JitLogger::CodeMoveEvent(Address from, Address to) {
 927   Code* from_code = Code::cast(HeapObject::FromAddress(from));
 928
 929   JitCodeEvent event;
 930   event.type = JitCodeEvent::CODE_MOVED;
 931   event.code_start = from_code->instruction_start();
 932   event.code_len = from_code->instruction_size();
 933
 934   // Calculate the header size.
 935   const size_t header_size =
 936       from_code->instruction_start() - reinterpret_cast<byte*>(from_code);
 937
 938   // Calculate the new start address of the instructions.
 939   event.new_code_start =
 940       reinterpret_cast<byte*>(HeapObject::FromAddress(to)) + header_size;
 941
 942   code_event_handler_(&event);
 943 }
 944
 945
 946 void JitLogger::CodeDeleteEvent(Address from) {
 947   Code* from_code = Code::cast(HeapObject::FromAddress(from));
 948
 949   JitCodeEvent event;
 950   event.type = JitCodeEvent::CODE_REMOVED;
 951   event.code_start = from_code->instruction_start();
 952   event.code_len = from_code->instruction_size();
 953
 954   code_event_handler_(&event);
 955 }
 956
 957 void JitLogger::AddCodeLinePosInfoEvent(
 958     void* jit_handler_data,
 959     int pc_offset,
 960     int position,
 961     JitCodeEvent::PositionType position_type) {
 962   JitCodeEvent event;
 963   memset(&event, 0, sizeof(event));
 964   event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO;
 965   event.user_data = jit_handler_data;
 966   event.line_info.offset = pc_offset;
 967   event.line_info.pos = position;
 968   event.line_info.position_type = position_type;
 969
 970   code_event_handler_(&event);
 971 }
 972
 973
 974 void* JitLogger::StartCodePosInfoEvent() {
 975   JitCodeEvent event;
 976   memset(&event, 0, sizeof(event));
 977   event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING;
 978
 979   code_event_handler_(&event);
 980   return event.user_data;
 981 }
 982
 983
 984 void JitLogger::EndCodePosInfoEvent(Code* code, void* jit_handler_data) {
 985   JitCodeEvent event;
 986   memset(&event, 0, sizeof(event));
 987   event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING;
 988   event.code_start = code->instruction_start();
 989   event.user_data = jit_handler_data;
 990
 991   code_event_handler_(&event);
 992 }
 993
 994
 995 // The Profiler samples pc and sp values for the main thread.
 996 // Each sample is appended to a circular buffer.
 997 // An independent thread removes data and writes it to the log.
 998 // This design minimizes the time spent in the sampler.
 999 //
1000 class Profiler: public Thread {
1001  public:
1002   explicit Profiler(Isolate* isolate);
1003   void Engage();
1004   void Disengage();
1005
1006   // Inserts collected profiling data into buffer.
1007   void Insert(TickSample* sample) {
1008     if (paused_)
1009       return;
1010
1011     if (Succ(head_) == tail_) {
1012       overflow_ = true;
1013     } else {
1014       buffer_[head_] = *sample;
1015       head_ = Succ(head_);
1016       buffer_semaphore_.Signal();  // Tell we have an element.
1017     }
1018   }
1019
1020   virtual void Run();
1021
1022   // Pause and Resume TickSample data collection.
1023   void pause() { paused_ = true; }
1024   void resume() { paused_ = false; }
1025
1026  private:
1027   // Waits for a signal and removes profiling data.
1028   bool Remove(TickSample* sample) {
1029     buffer_semaphore_.Wait();  // Wait for an element.
1030     *sample = buffer_[tail_];
1031     bool result = overflow_;
1032     tail_ = Succ(tail_);
1033     overflow_ = false;
1034     return result;
1035   }
1036
1037   // Returns the next index in the cyclic buffer.
1038   int Succ(int index) { return (index + 1) % kBufferSize; }
1039
1040   Isolate* isolate_;
1041   // Cyclic buffer for communicating profiling samples
1042   // between the signal handler and the worker thread.
1043   static const int kBufferSize = 128;
1044   TickSample buffer_[kBufferSize];  // Buffer storage.
1045   int head_;  // Index to the buffer head.
1046   int tail_;  // Index to the buffer tail.
1047   bool overflow_;  // Tell whether a buffer overflow has occurred.
1048   // Sempahore used for buffer synchronization.
1049   Semaphore buffer_semaphore_;
1050
1051   // Tells whether profiler is engaged, that is, processing thread is stated.
1052   bool engaged_;
1053
1054   // Tells whether worker thread should continue running.
1055   bool running_;
1056
1057   // Tells whether we are currently recording tick samples.
1058   bool paused_;
1059 };
1060
1061
1062 //
1063 // Ticker used to provide ticks to the profiler and the sliding state
1064 // window.
1065 //
1066 class Ticker: public Sampler {
1067  public:
1068   Ticker(Isolate* isolate, int interval):
1069       Sampler(isolate, interval),
1070       profiler_(NULL) {}
1071
1072   ~Ticker() { if (IsActive()) Stop(); }
1073
1074   virtual void Tick(TickSample* sample) {
1075     if (profiler_) profiler_->Insert(sample);
1076   }
1077
1078   void SetProfiler(Profiler* profiler) {
1079     ASSERT(profiler_ == NULL);
1080     profiler_ = profiler;
1081     IncreaseProfilingDepth();
1082     if (!IsActive()) Start();
1083   }
1084
1085   void ClearProfiler() {
1086     profiler_ = NULL;
1087     if (IsActive()) Stop();
1088     DecreaseProfilingDepth();
1089   }
1090
1091  private:
1092   Profiler* profiler_;
1093 };
1094
1095
1096 //
1097 // Profiler implementation.
1098 //
1099 Profiler::Profiler(Isolate* isolate)
1100     : Thread("v8:Profiler"),
1101       isolate_(isolate),
1102       head_(0),
1103       tail_(0),
1104       overflow_(false),
1105       buffer_semaphore_(0),
1106       engaged_(false),
1107       running_(false),
1108       paused_(false) {
1109 }
1110
1111
1112 void Profiler::Engage() {
1113   if (engaged_) return;
1114   engaged_ = true;
1115
1116   OS::LogSharedLibraryAddresses(isolate_);
1117
1118   // Start thread processing the profiler buffer.
1119   running_ = true;
1120   Start();
1121
1122   // Register to get ticks.
1123   Logger* logger = isolate_->logger();
1124   logger->ticker_->SetProfiler(this);
1125
1126   logger->ProfilerBeginEvent();
1127 }
1128
1129
1130 void Profiler::Disengage() {
1131   if (!engaged_) return;
1132
1133   // Stop receiving ticks.
1134   isolate_->logger()->ticker_->ClearProfiler();
1135
1136   // Terminate the worker thread by setting running_ to false,
1137   // inserting a fake element in the queue and then wait for
1138   // the thread to terminate.
1139   running_ = false;
1140   TickSample sample;
1141   // Reset 'paused_' flag, otherwise semaphore may not be signalled.
1142   resume();
1143   Insert(&sample);
1144   Join();
1145
1146   LOG(isolate_, UncheckedStringEvent("profiler", "end"));
1147 }
1148
1149
1150 void Profiler::Run() {
1151   TickSample sample;
1152   bool overflow = Remove(&sample);
1153   while (running_) {
1154     LOG(isolate_, TickEvent(&sample, overflow));
1155     overflow = Remove(&sample);
1156   }
1157 }
1158
1159
1160 //
1161 // Logger class implementation.
1162 //
1163
1164 Logger::Logger(Isolate* isolate)
1165   : isolate_(isolate),
1166     ticker_(NULL),
1167     profiler_(NULL),
1168     log_events_(NULL),
1169     is_logging_(false),
1170     log_(new Log(this)),
1171     perf_basic_logger_(NULL),
1172     perf_jit_logger_(NULL),
1173     ll_logger_(NULL),
1174     jit_logger_(NULL),
1175     listeners_(5),
1176     is_initialized_(false) {
1177 }
1178
1179
1180 Logger::~Logger() {
1181   delete log_;
1182 }
1183
1184
1185 void Logger::addCodeEventListener(CodeEventListener* listener) {
1186   ASSERT(!hasCodeEventListener(listener));
1187   listeners_.Add(listener);
1188 }
1189
1190
1191 void Logger::removeCodeEventListener(CodeEventListener* listener) {
1192   ASSERT(hasCodeEventListener(listener));
1193   listeners_.RemoveElement(listener);
1194 }
1195
1196
1197 bool Logger::hasCodeEventListener(CodeEventListener* listener) {
1198   return listeners_.Contains(listener);
1199 }
1200
1201
1202 void Logger::ProfilerBeginEvent() {
1203   if (!log_->IsEnabled()) return;
1204   Log::MessageBuilder msg(log_);
1205   msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
1206   msg.WriteToLogFile();
1207 }
1208
1209
1210 void Logger::StringEvent(const char* name, const char* value) {
1211   if (FLAG_log) UncheckedStringEvent(name, value);
1212 }
1213
1214
1215 void Logger::UncheckedStringEvent(const char* name, const char* value) {
1216   if (!log_->IsEnabled()) return;
1217   Log::MessageBuilder msg(log_);
1218   msg.Append("%s,\"%s\"\n", name, value);
1219   msg.WriteToLogFile();
1220 }
1221
1222
1223 void Logger::IntEvent(const char* name, int value) {
1224   if (FLAG_log) UncheckedIntEvent(name, value);
1225 }
1226
1227
1228 void Logger::IntPtrTEvent(const char* name, intptr_t value) {
1229   if (FLAG_log) UncheckedIntPtrTEvent(name, value);
1230 }
1231
1232
1233 void Logger::UncheckedIntEvent(const char* name, int value) {
1234   if (!log_->IsEnabled()) return;
1235   Log::MessageBuilder msg(log_);
1236   msg.Append("%s,%d\n", name, value);
1237   msg.WriteToLogFile();
1238 }
1239
1240
1241 void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
1242   if (!log_->IsEnabled()) return;
1243   Log::MessageBuilder msg(log_);
1244   msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
1245   msg.WriteToLogFile();
1246 }
1247
1248
1249 void Logger::HandleEvent(const char* name, Object** location) {
1250   if (!log_->IsEnabled() || !FLAG_log_handles) return;
1251   Log::MessageBuilder msg(log_);
1252   msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
1253   msg.WriteToLogFile();
1254 }
1255
1256
1257 // ApiEvent is private so all the calls come from the Logger class.  It is the
1258 // caller's responsibility to ensure that log is enabled and that
1259 // FLAG_log_api is true.
1260 void Logger::ApiEvent(const char* format, ...) {
1261   ASSERT(log_->IsEnabled() && FLAG_log_api);
1262   Log::MessageBuilder msg(log_);
1263   va_list ap;
1264   va_start(ap, format);
1265   msg.AppendVA(format, ap);
1266   va_end(ap);
1267   msg.WriteToLogFile();
1268 }
1269
1270
1271 void Logger::ApiNamedSecurityCheck(Object* key) {
1272   if (!log_->IsEnabled() || !FLAG_log_api) return;
1273   if (key->IsString()) {
1274     SmartArrayPointer<char> str =
1275         String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1276     ApiEvent("api,check-security,\"%s\"\n", str.get());
1277   } else if (key->IsSymbol()) {
1278     Symbol* symbol = Symbol::cast(key);
1279     if (symbol->name()->IsUndefined()) {
1280       ApiEvent("api,check-security,symbol(hash %x)\n",
1281                Symbol::cast(key)->Hash());
1282     } else {
1283       SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
1284           DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1285       ApiEvent("api,check-security,symbol(\"%s\" hash %x)\n",
1286                str.get(),
1287                Symbol::cast(key)->Hash());
1288     }
1289   } else if (key->IsUndefined()) {
1290     ApiEvent("api,check-security,undefined\n");
1291   } else {
1292     ApiEvent("api,check-security,['no-name']\n");
1293   }
1294 }
1295
1296
1297 void Logger::SharedLibraryEvent(const char* library_path,
1298                                 uintptr_t start,
1299                                 uintptr_t end) {
1300   if (!log_->IsEnabled() || !FLAG_prof) return;
1301   Log::MessageBuilder msg(log_);
1302   msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
1303              library_path,
1304              start,
1305              end);
1306   msg.WriteToLogFile();
1307 }
1308
1309
1310 void Logger::SharedLibraryEvent(const wchar_t* library_path,
1311                                 uintptr_t start,
1312                                 uintptr_t end) {
1313   if (!log_->IsEnabled() || !FLAG_prof) return;
1314   Log::MessageBuilder msg(log_);
1315   msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
1316              library_path,
1317              start,
1318              end);
1319   msg.WriteToLogFile();
1320 }
1321
1322
1323 void Logger::CodeDeoptEvent(Code* code) {
1324   if (!log_->IsEnabled()) return;
1325   ASSERT(FLAG_log_internal_timer_events);
1326   Log::MessageBuilder msg(log_);
1327   int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
1328   msg.Append("code-deopt,%ld,%d\n", since_epoch, code->CodeSize());
1329   msg.WriteToLogFile();
1330 }
1331
1332
1333 void Logger::TimerEvent(StartEnd se, const char* name) {
1334   if (!log_->IsEnabled()) return;
1335   ASSERT(FLAG_log_internal_timer_events);
1336   Log::MessageBuilder msg(log_);
1337   int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
1338   const char* format = (se == START) ? "timer-event-start,\"%s\",%ld\n"
1339                                      : "timer-event-end,\"%s\",%ld\n";
1340   msg.Append(format, name, since_epoch);
1341   msg.WriteToLogFile();
1342 }
1343
1344
1345 void Logger::EnterExternal(Isolate* isolate) {
1346   LOG(isolate, TimerEvent(START, TimerEventScope::v8_external));
1347   ASSERT(isolate->current_vm_state() == JS);
1348   isolate->set_current_vm_state(EXTERNAL);
1349 }
1350
1351
1352 void Logger::LeaveExternal(Isolate* isolate) {
1353   LOG(isolate, TimerEvent(END, TimerEventScope::v8_external));
1354   ASSERT(isolate->current_vm_state() == EXTERNAL);
1355   isolate->set_current_vm_state(JS);
1356 }
1357
1358
1359 void Logger::TimerEventScope::LogTimerEvent(StartEnd se) {
1360   LOG(isolate_, TimerEvent(se, name_));
1361 }
1362
1363
1364 const char* Logger::TimerEventScope::v8_recompile_synchronous =
1365     "V8.RecompileSynchronous";
1366 const char* Logger::TimerEventScope::v8_recompile_concurrent =
1367     "V8.RecompileConcurrent";
1368 const char* Logger::TimerEventScope::v8_compile_full_code =
1369     "V8.CompileFullCode";
1370 const char* Logger::TimerEventScope::v8_execute = "V8.Execute";
1371 const char* Logger::TimerEventScope::v8_external = "V8.External";
1372
1373
1374 void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
1375   // Prints "/" + re.source + "/" +
1376   //      (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
1377   Log::MessageBuilder msg(log_);
1378
1379   Handle<Object> source = GetProperty(regexp, "source");
1380   if (!source->IsString()) {
1381     msg.Append("no source");
1382     return;
1383   }
1384
1385   switch (regexp->TypeTag()) {
1386     case JSRegExp::ATOM:
1387       msg.Append('a');
1388       break;
1389     default:
1390       break;
1391   }
1392   msg.Append('/');
1393   msg.AppendDetailed(*Handle<String>::cast(source), false);
1394   msg.Append('/');
1395
1396   // global flag
1397   Handle<Object> global = GetProperty(regexp, "global");
1398   if (global->IsTrue()) {
1399     msg.Append('g');
1400   }
1401   // ignorecase flag
1402   Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
1403   if (ignorecase->IsTrue()) {
1404     msg.Append('i');
1405   }
1406   // multiline flag
1407   Handle<Object> multiline = GetProperty(regexp, "multiline");
1408   if (multiline->IsTrue()) {
1409     msg.Append('m');
1410   }
1411
1412   msg.WriteToLogFile();
1413 }
1414
1415
1416 void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
1417   if (!log_->IsEnabled() || !FLAG_log_regexp) return;
1418   Log::MessageBuilder msg(log_);
1419   msg.Append("regexp-compile,");
1420   LogRegExpSource(regexp);
1421   msg.Append(in_cache ? ",hit\n" : ",miss\n");
1422   msg.WriteToLogFile();
1423 }
1424
1425
1426 void Logger::LogRuntime(Vector<const char> format,
1427                         JSArray* args) {
1428   if (!log_->IsEnabled() || !FLAG_log_runtime) return;
1429   HandleScope scope(isolate_);
1430   Log::MessageBuilder msg(log_);
1431   for (int i = 0; i < format.length(); i++) {
1432     char c = format[i];
1433     if (c == '%' && i <= format.length() - 2) {
1434       i++;
1435       ASSERT('0' <= format[i] && format[i] <= '9');
1436       MaybeObject* maybe = args->GetElement(isolate_, format[i] - '0');
1437       Object* obj;
1438       if (!maybe->ToObject(&obj)) {
1439         msg.Append("<exception>");
1440         continue;
1441       }
1442       i++;
1443       switch (format[i]) {
1444         case 's':
1445           msg.AppendDetailed(String::cast(obj), false);
1446           break;
1447         case 'S':
1448           msg.AppendDetailed(String::cast(obj), true);
1449           break;
1450         case 'r':
1451           Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
1452           break;
1453         case 'x':
1454           msg.Append("0x%x", Smi::cast(obj)->value());
1455           break;
1456         case 'i':
1457           msg.Append("%i", Smi::cast(obj)->value());
1458           break;
1459         default:
1460           UNREACHABLE();
1461       }
1462     } else {
1463       msg.Append(c);
1464     }
1465   }
1466   msg.Append('\n');
1467   msg.WriteToLogFile();
1468 }
1469
1470
1471 void Logger::ApiIndexedSecurityCheck(uint32_t index) {
1472   if (!log_->IsEnabled() || !FLAG_log_api) return;
1473   ApiEvent("api,check-security,%u\n", index);
1474 }
1475
1476
1477 void Logger::ApiNamedPropertyAccess(const char* tag,
1478                                     JSObject* holder,
1479                                     Object* name) {
1480   ASSERT(name->IsName());
1481   if (!log_->IsEnabled() || !FLAG_log_api) return;
1482   String* class_name_obj = holder->class_name();
1483   SmartArrayPointer<char> class_name =
1484       class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1485   if (name->IsString()) {
1486     SmartArrayPointer<char> property_name =
1487         String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1488     ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, class_name.get(),
1489              property_name.get());
1490   } else {
1491     Symbol* symbol = Symbol::cast(name);
1492     uint32_t hash = symbol->Hash();
1493     if (symbol->name()->IsUndefined()) {
1494       ApiEvent("api,%s,\"%s\",symbol(hash %x)\n", tag, class_name.get(), hash);
1495     } else {
1496       SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
1497           DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1498       ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)\n",
1499                tag, class_name.get(), str.get(), hash);
1500     }
1501   }
1502 }
1503
1504 void Logger::ApiIndexedPropertyAccess(const char* tag,
1505                                       JSObject* holder,
1506                                       uint32_t index) {
1507   if (!log_->IsEnabled() || !FLAG_log_api) return;
1508   String* class_name_obj = holder->class_name();
1509   SmartArrayPointer<char> class_name =
1510       class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1511   ApiEvent("api,%s,\"%s\",%u\n", tag, class_name.get(), index);
1512 }
1513
1514
1515 void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
1516   if (!log_->IsEnabled() || !FLAG_log_api) return;
1517   String* class_name_obj = object->class_name();
1518   SmartArrayPointer<char> class_name =
1519       class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1520   ApiEvent("api,%s,\"%s\"\n", tag, class_name.get());
1521 }
1522
1523
1524 void Logger::ApiEntryCall(const char* name) {
1525   if (!log_->IsEnabled() || !FLAG_log_api) return;
1526   ApiEvent("api,%s\n", name);
1527 }
1528
1529
1530 void Logger::NewEvent(const char* name, void* object, size_t size) {
1531   if (!log_->IsEnabled() || !FLAG_log) return;
1532   Log::MessageBuilder msg(log_);
1533   msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
1534              static_cast<unsigned int>(size));
1535   msg.WriteToLogFile();
1536 }
1537
1538
1539 void Logger::DeleteEvent(const char* name, void* object) {
1540   if (!log_->IsEnabled() || !FLAG_log) return;
1541   Log::MessageBuilder msg(log_);
1542   msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
1543   msg.WriteToLogFile();
1544 }
1545
1546
1547 void Logger::NewEventStatic(const char* name, void* object, size_t size) {
1548   Isolate::Current()->logger()->NewEvent(name, object, size);
1549 }
1550
1551
1552 void Logger::DeleteEventStatic(const char* name, void* object) {
1553   Isolate::Current()->logger()->DeleteEvent(name, object);
1554 }
1555
1556
1557 void Logger::CallbackEventInternal(const char* prefix, Name* name,
1558                                    Address entry_point) {
1559   if (!FLAG_log_code || !log_->IsEnabled()) return;
1560   Log::MessageBuilder msg(log_);
1561   msg.Append("%s,%s,-2,",
1562              kLogEventsNames[CODE_CREATION_EVENT],
1563              kLogEventsNames[CALLBACK_TAG]);
1564   msg.AppendAddress(entry_point);
1565   if (name->IsString()) {
1566     SmartArrayPointer<char> str =
1567         String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1568     msg.Append(",1,\"%s%s\"", prefix, str.get());
1569   } else {
1570     Symbol* symbol = Symbol::cast(name);
1571     if (symbol->name()->IsUndefined()) {
1572       msg.Append(",1,symbol(hash %x)", prefix, symbol->Hash());
1573     } else {
1574       SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
1575           DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1576       msg.Append(",1,symbol(\"%s\" hash %x)", prefix, str.get(),
1577                  symbol->Hash());
1578     }
1579   }
1580   msg.Append('\n');
1581   msg.WriteToLogFile();
1582 }
1583
1584
1585 void Logger::CallbackEvent(Name* name, Address entry_point) {
1586   PROFILER_LOG(CallbackEvent(name, entry_point));
1587   CallbackEventInternal("", name, entry_point);
1588 }
1589
1590
1591 void Logger::GetterCallbackEvent(Name* name, Address entry_point) {
1592   PROFILER_LOG(GetterCallbackEvent(name, entry_point));
1593   CallbackEventInternal("get ", name, entry_point);
1594 }
1595
1596
1597 void Logger::SetterCallbackEvent(Name* name, Address entry_point) {
1598   PROFILER_LOG(SetterCallbackEvent(name, entry_point));
1599   CallbackEventInternal("set ", name, entry_point);
1600 }
1601
1602
1603 static void AppendCodeCreateHeader(Log::MessageBuilder* msg,
1604                                    Logger::LogEventsAndTags tag,
1605                                    Code* code) {
1606   ASSERT(msg);
1607   msg->Append("%s,%s,%d,",
1608               kLogEventsNames[Logger::CODE_CREATION_EVENT],
1609               kLogEventsNames[tag],
1610               code->kind());
1611   if (xdk::XDKIsAgentAlive()) {
1612     msg->AppendAddress(code->instruction_start());
1613     msg->Append(",%d,", code->instruction_size());
1614   } else {
1615     msg->AppendAddress(code->address());
1616     msg->Append(",%d,", code->ExecutableSize());
1617   }
1618 }
1619
1620
1621 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1622                              Code* code,
1623                              const char* comment) {
1624   PROFILER_LOG(CodeCreateEvent(tag, code, comment));
1625
1626   if (!is_logging_code_events()) return;
1627   CALL_LISTENERS(CodeCreateEvent(tag, code, comment));
1628
1629   if (!FLAG_log_code || !log_->IsEnabled()) return;
1630   Log::MessageBuilder msg(log_);
1631   AppendCodeCreateHeader(&msg, tag, code);
1632   msg.AppendDoubleQuotedString(comment);
1633   msg.Append('\n');
1634   msg.WriteToLogFile();
1635 }
1636
1637
1638 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1639                              Code* code,
1640                              Name* name) {
1641   PROFILER_LOG(CodeCreateEvent(tag, code, name));
1642
1643   if (!is_logging_code_events()) return;
1644   CALL_LISTENERS(CodeCreateEvent(tag, code, name));
1645
1646   if (!FLAG_log_code || !log_->IsEnabled()) return;
1647   Log::MessageBuilder msg(log_);
1648   AppendCodeCreateHeader(&msg, tag, code);
1649   if (name->IsString()) {
1650     msg.Append('"');
1651     msg.AppendDetailed(String::cast(name), false);
1652     msg.Append('"');
1653   } else {
1654     msg.AppendSymbolName(Symbol::cast(name));
1655   }
1656   msg.Append('\n');
1657   msg.WriteToLogFile();
1658 }
1659
1660
1661 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1662                              Code* code,
1663                              SharedFunctionInfo* shared,
1664                              CompilationInfo* info,
1665                              Name* name) {
1666   PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, name));
1667
1668   if (!is_logging_code_events()) return;
1669   CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, name));
1670
1671   if (!FLAG_log_code || !log_->IsEnabled()) return;
1672   if (code == isolate_->builtins()->builtin(Builtins::kCompileUnoptimized))
1673     return;
1674
1675   Log::MessageBuilder msg(log_);
1676   AppendCodeCreateHeader(&msg, tag, code);
1677   if (name->IsString()) {
1678     SmartArrayPointer<char> str =
1679         String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1680     msg.Append("\"%s\"", str.get());
1681   } else {
1682     msg.AppendSymbolName(Symbol::cast(name));
1683   }
1684   msg.Append(',');
1685   msg.AppendAddress(shared->address());
1686   msg.Append(",%s", ComputeMarker(code));
1687   msg.Append('\n');
1688   msg.WriteToLogFile();
1689 }
1690
1691
1692 // Although, it is possible to extract source and line from
1693 // the SharedFunctionInfo object, we left it to caller
1694 // to leave logging functions free from heap allocations.
1695 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1696                              Code* code,
1697                              SharedFunctionInfo* shared,
1698                              CompilationInfo* info,
1699                              Name* source, int line, int column) {
1700   PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, source, line, column));
1701
1702   if (!is_logging_code_events()) return;
1703   CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, source, line,
1704                                  column));
1705
1706   if (!FLAG_log_code || !log_->IsEnabled()) return;
1707   Log::MessageBuilder msg(log_);
1708   AppendCodeCreateHeader(&msg, tag, code);
1709   SmartArrayPointer<char> name =
1710       shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1711   msg.Append("\"%s ", name.get());
1712   if (source->IsString()) {
1713     SmartArrayPointer<char> sourcestr =
1714        String::cast(source)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1715     msg.Append("%s", sourcestr.get());
1716   } else {
1717     msg.AppendSymbolName(Symbol::cast(source));
1718   }
1719   msg.Append(":%d:%d\",", line, column);
1720   msg.AppendAddress(shared->address());
1721   msg.Append(",%s", ComputeMarker(code));
1722   msg.Append('\n');
1723   msg.WriteToLogFile();
1724 }
1725
1726
1727 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1728                              Code* code,
1729                              int args_count) {
1730   PROFILER_LOG(CodeCreateEvent(tag, code, args_count));
1731
1732   if (!is_logging_code_events()) return;
1733   CALL_LISTENERS(CodeCreateEvent(tag, code, args_count));
1734
1735   if (!FLAG_log_code || !log_->IsEnabled()) return;
1736   Log::MessageBuilder msg(log_);
1737   AppendCodeCreateHeader(&msg, tag, code);
1738   msg.Append("\"args_count: %d\"", args_count);
1739   msg.Append('\n');
1740   msg.WriteToLogFile();
1741 }
1742
1743
1744 void Logger::CodeMovingGCEvent() {
1745   PROFILER_LOG(CodeMovingGCEvent());
1746
1747   if (!is_logging_code_events()) return;
1748   if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1749   CALL_LISTENERS(CodeMovingGCEvent());
1750   OS::SignalCodeMovingGC();
1751 }
1752
1753
1754 void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
1755   PROFILER_LOG(RegExpCodeCreateEvent(code, source));
1756
1757   if (!is_logging_code_events()) return;
1758   CALL_LISTENERS(RegExpCodeCreateEvent(code, source));
1759
1760   if (!FLAG_log_code || !log_->IsEnabled()) return;
1761   Log::MessageBuilder msg(log_);
1762   AppendCodeCreateHeader(&msg, REG_EXP_TAG, code);
1763   msg.Append('"');
1764   msg.AppendDetailed(source, false);
1765   msg.Append('"');
1766   msg.Append('\n');
1767   msg.WriteToLogFile();
1768 }
1769
1770
1771 void Logger::CodeMoveEvent(Address from, Address to) {
1772   PROFILER_LOG(CodeMoveEvent(from, to));
1773
1774   if (!is_logging_code_events()) return;
1775   CALL_LISTENERS(CodeMoveEvent(from, to));
1776   MoveEventInternal(CODE_MOVE_EVENT, from, to);
1777 }
1778
1779
1780 void Logger::CodeDeleteEvent(Address from) {
1781   PROFILER_LOG(CodeDeleteEvent(from));
1782
1783   if (!is_logging_code_events()) return;
1784   CALL_LISTENERS(CodeDeleteEvent(from));
1785
1786   if (!FLAG_log_code || !log_->IsEnabled()) return;
1787   Log::MessageBuilder msg(log_);
1788   msg.Append("%s,", kLogEventsNames[CODE_DELETE_EVENT]);
1789   msg.AppendAddress(from);
1790   msg.Append('\n');
1791   msg.WriteToLogFile();
1792 }
1793
1794
1795 void Logger::CodeLinePosInfoAddPositionEvent(void* jit_handler_data,
1796                                      int pc_offset,
1797                                      int position) {
1798   JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
1799                                   pc_offset,
1800                                   position,
1801                                   JitCodeEvent::POSITION));
1802 }
1803
1804
1805 void Logger::CodeLinePosInfoAddStatementPositionEvent(void* jit_handler_data,
1806                                                       int pc_offset,
1807                                                       int position) {
1808   JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
1809                                   pc_offset,
1810                                   position,
1811                                   JitCodeEvent::STATEMENT_POSITION));
1812 }
1813
1814
1815 void Logger::CodeStartLinePosInfoRecordEvent(PositionsRecorder* pos_recorder) {
1816   if (jit_logger_ != NULL) {
1817       pos_recorder->AttachJITHandlerData(jit_logger_->StartCodePosInfoEvent());
1818   }
1819 }
1820
1821
1822 void Logger::CodeEndLinePosInfoRecordEvent(Code* code,
1823                                            void* jit_handler_data) {
1824   JIT_LOG(EndCodePosInfoEvent(code, jit_handler_data));
1825 }
1826
1827
1828 void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
1829   if (code_name == NULL) return;  // Not a code object.
1830   Log::MessageBuilder msg(log_);
1831   msg.Append("%s,%d,", kLogEventsNames[SNAPSHOT_CODE_NAME_EVENT], pos);
1832   msg.AppendDoubleQuotedString(code_name);
1833   msg.Append("\n");
1834   msg.WriteToLogFile();
1835 }
1836
1837
1838 void Logger::SnapshotPositionEvent(Address addr, int pos) {
1839   if (!log_->IsEnabled()) return;
1840   LL_LOG(SnapshotPositionEvent(addr, pos));
1841   if (!FLAG_log_snapshot_positions) return;
1842   Log::MessageBuilder msg(log_);
1843   msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
1844   msg.AppendAddress(addr);
1845   msg.Append(",%d", pos);
1846   msg.Append('\n');
1847   msg.WriteToLogFile();
1848 }
1849
1850
1851 void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1852   PROFILER_LOG(SharedFunctionInfoMoveEvent(from, to));
1853
1854   if (!is_logging_code_events()) return;
1855   MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to);
1856 }
1857
1858
1859 void Logger::MoveEventInternal(LogEventsAndTags event,
1860                                Address from,
1861                                Address to) {
1862   if (!FLAG_log_code || !log_->IsEnabled()) return;
1863
1864   Code* from_code = NULL;
1865   Address to_code = NULL;
1866   if (xdk::XDKIsAgentAlive()) {
1867     from_code = Code::cast(HeapObject::FromAddress(from));
1868     const size_t header_size =
1869       from_code->instruction_start() - reinterpret_cast<byte*>(from_code);
1870     to_code =
1871       reinterpret_cast<byte*>(HeapObject::FromAddress(to)) + header_size;
1872   }
1873
1874   Log::MessageBuilder msg(log_);
1875   msg.Append("%s,", kLogEventsNames[event]);
1876   if (xdk::XDKIsAgentAlive()) {
1877     msg.AppendAddress(from_code->instruction_start());
1878   } else {
1879     msg.AppendAddress(from);
1880   }
1881   msg.Append(',');
1882   if (xdk::XDKIsAgentAlive()) {
1883     msg.AppendAddress(to_code);
1884   } else {
1885     msg.AppendAddress(to);
1886   }
1887   msg.Append('\n');
1888   msg.WriteToLogFile();
1889 }
1890
1891
1892 void Logger::ResourceEvent(const char* name, const char* tag) {
1893   if (!log_->IsEnabled() || !FLAG_log) return;
1894   Log::MessageBuilder msg(log_);
1895   msg.Append("%s,%s,", name, tag);
1896
1897   uint32_t sec, usec;
1898   if (OS::GetUserTime(&sec, &usec) != -1) {
1899     msg.Append("%d,%d,", sec, usec);
1900   }
1901   msg.Append("%.0f", OS::TimeCurrentMillis());
1902
1903   msg.Append('\n');
1904   msg.WriteToLogFile();
1905 }
1906
1907
1908 void Logger::SuspectReadEvent(Name* name, Object* obj) {
1909   if (!log_->IsEnabled() || !FLAG_log_suspect) return;
1910   Log::MessageBuilder msg(log_);
1911   String* class_name = obj->IsJSObject()
1912                        ? JSObject::cast(obj)->class_name()
1913                        : isolate_->heap()->empty_string();
1914   msg.Append("suspect-read,");
1915   msg.Append(class_name);
1916   msg.Append(',');
1917   if (name->IsString()) {
1918     msg.Append('"');
1919     msg.Append(String::cast(name));
1920     msg.Append('"');
1921   } else {
1922     msg.AppendSymbolName(Symbol::cast(name));
1923   }
1924   msg.Append('\n');
1925   msg.WriteToLogFile();
1926 }
1927
1928
1929 void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
1930   if (!log_->IsEnabled() || !FLAG_log_gc) return;
1931   Log::MessageBuilder msg(log_);
1932   // Using non-relative system time in order to be able to synchronize with
1933   // external memory profiling events (e.g. DOM memory size).
1934   msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
1935              space, kind, OS::TimeCurrentMillis());
1936   msg.WriteToLogFile();
1937 }
1938
1939
1940 void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1941   if (!log_->IsEnabled() || !FLAG_log_gc) return;
1942   Log::MessageBuilder msg(log_);
1943   msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1944   msg.WriteToLogFile();
1945 }
1946
1947
1948 void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1949   if (!log_->IsEnabled() || !FLAG_log_gc) return;
1950   Log::MessageBuilder msg(log_);
1951   msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1952   msg.WriteToLogFile();
1953 }
1954
1955
1956 void Logger::DebugTag(const char* call_site_tag) {
1957   if (!log_->IsEnabled() || !FLAG_log) return;
1958   Log::MessageBuilder msg(log_);
1959   msg.Append("debug-tag,%s\n", call_site_tag);
1960   msg.WriteToLogFile();
1961 }
1962
1963
1964 void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1965   if (!log_->IsEnabled() || !FLAG_log) return;
1966   StringBuilder s(parameter.length() + 1);
1967   for (int i = 0; i < parameter.length(); ++i) {
1968     s.AddCharacter(static_cast<char>(parameter[i]));
1969   }
1970   char* parameter_string = s.Finalize();
1971   Log::MessageBuilder msg(log_);
1972   msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1973              event_type,
1974              OS::TimeCurrentMillis(),
1975              parameter_string);
1976   DeleteArray(parameter_string);
1977   msg.WriteToLogFile();
1978 }
1979
1980
1981 void Logger::TickEvent(TickSample* sample, bool overflow) {
1982   if (!log_->IsEnabled() || !FLAG_prof) return;
1983   Log::MessageBuilder msg(log_);
1984   msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
1985   msg.AppendAddress(sample->pc);
1986   msg.Append(",%ld", static_cast<int>(timer_.Elapsed().InMicroseconds()));
1987   if (sample->has_external_callback) {
1988     msg.Append(",1,");
1989     msg.AppendAddress(sample->external_callback);
1990   } else {
1991     msg.Append(",0,");
1992     msg.AppendAddress(sample->tos);
1993   }
1994   msg.Append(",%d", static_cast<int>(sample->state));
1995   if (overflow) {
1996     msg.Append(",overflow");
1997   }
1998   for (int i = 0; i < sample->frames_count; ++i) {
1999     msg.Append(',');
2000     msg.AppendAddress(sample->stack[i]);
2001   }
2002   msg.Append('\n');
2003   msg.WriteToLogFile();
2004 }
2005
2006
2007 void Logger::XDKResumeProfiler() {
2008   if (!log_->IsEnabled()) return;
2009   if (profiler_ != NULL) {
2010     profiler_->resume();
2011     is_logging_ = true;
2012   }
2013 }
2014
2015
2016 void Logger::StopProfiler() {
2017   if (!log_->IsEnabled()) return;
2018   if (profiler_ != NULL) {
2019     profiler_->pause();
2020     is_logging_ = false;
2021   }
2022 }
2023
2024
2025 // This function can be called when Log's mutex is acquired,
2026 // either from main or Profiler's thread.
2027 void Logger::LogFailure() {
2028   StopProfiler();
2029 }
2030
2031
2032 class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
2033  public:
2034   EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
2035                                      Handle<Code>* code_objects,
2036                                      int* count)
2037       : sfis_(sfis), code_objects_(code_objects), count_(count) { }
2038
2039   virtual void EnterContext(Context* context) {}
2040   virtual void LeaveContext(Context* context) {}
2041
2042   virtual void VisitFunction(JSFunction* function) {
2043     SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
2044     Object* maybe_script = sfi->script();
2045     if (maybe_script->IsScript()
2046         && !Script::cast(maybe_script)->HasValidSource()) return;
2047     if (sfis_ != NULL) {
2048       sfis_[*count_] = Handle<SharedFunctionInfo>(sfi);
2049     }
2050     if (code_objects_ != NULL) {
2051       ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
2052       code_objects_[*count_] = Handle<Code>(function->code());
2053     }
2054     *count_ = *count_ + 1;
2055   }
2056
2057  private:
2058   Handle<SharedFunctionInfo>* sfis_;
2059   Handle<Code>* code_objects_;
2060   int* count_;
2061 };
2062
2063
2064 static int EnumerateCompiledFunctions(Heap* heap,
2065                                       Handle<SharedFunctionInfo>* sfis,
2066                                       Handle<Code>* code_objects) {
2067   HeapIterator iterator(heap);
2068   DisallowHeapAllocation no_gc;
2069   int compiled_funcs_count = 0;
2070
2071   // Iterate the heap to find shared function info objects and record
2072   // the unoptimized code for them.
2073   for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
2074     if (!obj->IsSharedFunctionInfo()) continue;
2075     SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
2076     if (sfi->is_compiled()
2077         && (!sfi->script()->IsScript()
2078             || Script::cast(sfi->script())->HasValidSource())) {
2079       if (sfis != NULL) {
2080         sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
2081       }
2082       if (code_objects != NULL) {
2083         code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
2084       }
2085       ++compiled_funcs_count;
2086     }
2087   }
2088
2089   // Iterate all optimized functions in all contexts.
2090   EnumerateOptimizedFunctionsVisitor visitor(sfis,
2091                                              code_objects,
2092                                              &compiled_funcs_count);
2093   Deoptimizer::VisitAllOptimizedFunctions(heap->isolate(), &visitor);
2094
2095   return compiled_funcs_count;
2096 }
2097
2098
2099 void Logger::LogCodeObject(Object* object) {
2100   Code* code_object = Code::cast(object);
2101   LogEventsAndTags tag = Logger::STUB_TAG;
2102   const char* description = "Unknown code from the snapshot";
2103   switch (code_object->kind()) {
2104     case Code::FUNCTION:
2105     case Code::OPTIMIZED_FUNCTION:
2106       return;  // We log this later using LogCompiledFunctions.
2107     case Code::BINARY_OP_IC:
2108     case Code::COMPARE_IC:  // fall through
2109     case Code::COMPARE_NIL_IC:   // fall through
2110     case Code::TO_BOOLEAN_IC:  // fall through
2111     case Code::STUB:
2112       description =
2113           CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
2114       if (description == NULL)
2115         description = "A stub from the snapshot";
2116       tag = Logger::STUB_TAG;
2117       break;
2118     case Code::REGEXP:
2119       description = "Regular expression code";
2120       tag = Logger::REG_EXP_TAG;
2121       break;
2122     case Code::BUILTIN:
2123       description = "A builtin from the snapshot";
2124       tag = Logger::BUILTIN_TAG;
2125       break;
2126     case Code::HANDLER:
2127       description = "An IC handler from the snapshot";
2128       tag = Logger::HANDLER_TAG;
2129       break;
2130     case Code::KEYED_LOAD_IC:
2131       description = "A keyed load IC from the snapshot";
2132       tag = Logger::KEYED_LOAD_IC_TAG;
2133       break;
2134     case Code::LOAD_IC:
2135       description = "A load IC from the snapshot";
2136       tag = Logger::LOAD_IC_TAG;
2137       break;
2138     case Code::STORE_IC:
2139       description = "A store IC from the snapshot";
2140       tag = Logger::STORE_IC_TAG;
2141       break;
2142     case Code::KEYED_STORE_IC:
2143       description = "A keyed store IC from the snapshot";
2144       tag = Logger::KEYED_STORE_IC_TAG;
2145       break;
2146     case Code::NUMBER_OF_KINDS:
2147       break;
2148   }
2149   PROFILE(isolate_, CodeCreateEvent(tag, code_object, description));
2150 }
2151
2152
2153 void Logger::LogCodeObjects() {
2154   // Starting from Chromium v34 this function is also called from
2155   // V8::Initialize. This causes reading the heap to collect already
2156   // compiled methods. For XDK that must be done because XDK profiler
2157   // consumes CODE_ADDED events and mantains a map of compiled methods.
2158   if (xdk::XDKIsAgentAlive()) return;
2159
2160   Heap* heap = isolate_->heap();
2161   heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
2162                           "Logger::LogCodeObjects");
2163   HeapIterator iterator(heap);
2164   DisallowHeapAllocation no_gc;
2165   for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
2166     if (obj->IsCode()) LogCodeObject(obj);
2167   }
2168 }
2169
2170
2171 void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
2172                                  Handle<Code> code) {
2173   Handle<String> func_name(shared->DebugName());
2174   if (shared->script()->IsScript()) {
2175     Handle<Script> script(Script::cast(shared->script()));
2176     int line_num = GetScriptLineNumber(script, shared->start_position()) + 1;
2177     int column_num =
2178         GetScriptColumnNumber(script, shared->start_position()) + 1;
2179     if (script->name()->IsString()) {
2180       Handle<String> script_name(String::cast(script->name()));
2181       if (line_num > 0) {
2182         PROFILE(isolate_,
2183                 CodeCreateEvent(
2184                     Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
2185                     *code, *shared, NULL,
2186                     *script_name, line_num, column_num));
2187       } else {
2188         // Can't distinguish eval and script here, so always use Script.
2189         PROFILE(isolate_,
2190                 CodeCreateEvent(
2191                     Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
2192                     *code, *shared, NULL, *script_name));
2193       }
2194     } else {
2195       PROFILE(isolate_,
2196               CodeCreateEvent(
2197                   Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
2198                   *code, *shared, NULL,
2199                   isolate_->heap()->empty_string(), line_num, column_num));
2200     }
2201   } else if (shared->IsApiFunction()) {
2202     // API function.
2203     FunctionTemplateInfo* fun_data = shared->get_api_func_data();
2204     Object* raw_call_data = fun_data->call_code();
2205     if (!raw_call_data->IsUndefined()) {
2206       CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
2207       Object* callback_obj = call_data->callback();
2208       Address entry_point = v8::ToCData<Address>(callback_obj);
2209       PROFILE(isolate_, CallbackEvent(*func_name, entry_point));
2210     }
2211   } else {
2212     PROFILE(isolate_,
2213             CodeCreateEvent(
2214                 Logger::LAZY_COMPILE_TAG, *code, *shared, NULL, *func_name));
2215   }
2216 }
2217
2218
2219 void Logger::LogCompiledFunctions() {
2220   // Starting from Chromium v34 this function is also called from
2221   // V8::Initialize. This causes reading the heap to collect already
2222   // compiled methods. For XDK that must be done because XDK profiler
2223   // consumes CODE_ADDED events and mantains a map of compiled methods.
2224   if (xdk::XDKIsAgentAlive()) return;
2225
2226   Heap* heap = isolate_->heap();
2227   heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
2228                           "Logger::LogCompiledFunctions");
2229   HandleScope scope(isolate_);
2230   const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL);
2231   ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
2232   ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
2233   EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start());
2234
2235   // During iteration, there can be heap allocation due to
2236   // GetScriptLineNumber call.
2237   for (int i = 0; i < compiled_funcs_count; ++i) {
2238     if (code_objects[i].is_identical_to(
2239             isolate_->builtins()->CompileUnoptimized()))
2240       continue;
2241     LogExistingFunction(sfis[i], code_objects[i]);
2242   }
2243 }
2244
2245
2246 void Logger::LogAccessorCallbacks() {
2247   Heap* heap = isolate_->heap();
2248   heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
2249                           "Logger::LogAccessorCallbacks");
2250   HeapIterator iterator(heap);
2251   DisallowHeapAllocation no_gc;
2252   for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
2253     if (!obj->IsExecutableAccessorInfo()) continue;
2254     ExecutableAccessorInfo* ai = ExecutableAccessorInfo::cast(obj);
2255     if (!ai->name()->IsName()) continue;
2256     Address getter_entry = v8::ToCData<Address>(ai->getter());
2257     Name* name = Name::cast(ai->name());
2258     if (getter_entry != 0) {
2259       PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
2260     }
2261     Address setter_entry = v8::ToCData<Address>(ai->setter());
2262     if (setter_entry != 0) {
2263       PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
2264     }
2265   }
2266 }
2267
2268
2269 static void AddIsolateIdIfNeeded(Isolate* isolate, StringStream* stream) {
2270   if (isolate->IsDefaultIsolate() || !FLAG_logfile_per_isolate) return;
2271   stream->Add("isolate-%p-", isolate);
2272 }
2273
2274
2275 static SmartArrayPointer<const char> PrepareLogFileName(
2276     Isolate* isolate, const char* file_name) {
2277   if (strchr(file_name, '%') != NULL || !isolate->IsDefaultIsolate()) {
2278     // If there's a '%' in the log file name we have to expand
2279     // placeholders.
2280     HeapStringAllocator allocator;
2281     StringStream stream(&allocator);
2282     AddIsolateIdIfNeeded(isolate, &stream);
2283     for (const char* p = file_name; *p; p++) {
2284       if (*p == '%') {
2285         p++;
2286         switch (*p) {
2287           case '\0':
2288             // If there's a % at the end of the string we back up
2289             // one character so we can escape the loop properly.
2290             p--;
2291             break;
2292           case 'p':
2293             stream.Add("%d", OS::GetCurrentProcessId());
2294             break;
2295           case 't': {
2296             // %t expands to the current time in milliseconds.
2297             double time = OS::TimeCurrentMillis();
2298             stream.Add("%.0f", FmtElm(time));
2299             break;
2300           }
2301           case '%':
2302             // %% expands (contracts really) to %.
2303             stream.Put('%');
2304             break;
2305           default:
2306             // All other %'s expand to themselves.
2307             stream.Put('%');
2308             stream.Put(*p);
2309             break;
2310         }
2311       } else {
2312         stream.Put(*p);
2313       }
2314     }
2315     return SmartArrayPointer<const char>(stream.ToCString());
2316   }
2317   int length = StrLength(file_name);
2318   char* str = NewArray<char>(length + 1);
2319   OS::MemCopy(str, file_name, length);
2320   str[length] = '\0';
2321   return SmartArrayPointer<const char>(str);
2322 }
2323
2324
2325 bool Logger::SetUp(Isolate* isolate) {
2326   // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
2327   if (is_initialized_) return true;
2328   is_initialized_ = true;
2329
2330   // --ll-prof implies --log-code and --log-snapshot-positions.
2331   if (FLAG_ll_prof) {
2332     FLAG_log_snapshot_positions = true;
2333   }
2334
2335   SmartArrayPointer<const char> log_file_name =
2336       PrepareLogFileName(isolate, FLAG_logfile);
2337   log_->Initialize(log_file_name.get());
2338
2339
2340   if (FLAG_perf_basic_prof) {
2341     perf_basic_logger_ = new PerfBasicLogger();
2342     addCodeEventListener(perf_basic_logger_);
2343   }
2344
2345   if (FLAG_perf_jit_prof) {
2346     perf_jit_logger_ = new PerfJitLogger();
2347     addCodeEventListener(perf_jit_logger_);
2348   }
2349
2350   if (FLAG_ll_prof) {
2351     ll_logger_ = new LowLevelLogger(log_file_name.get());
2352     addCodeEventListener(ll_logger_);
2353   }
2354
2355   ticker_ = new Ticker(isolate, kSamplingIntervalMs);
2356
2357   if (Log::InitLogAtStart()) {
2358     is_logging_ = true;
2359   }
2360
2361   xdk::XDKInitializeForV8(isolate);
2362
2363   if (FLAG_prof) {
2364     profiler_ = new Profiler(isolate);
2365     is_logging_ = true;
2366     profiler_->Engage();
2367
2368     if (xdk::XDKIsAgentAlive()) {
2369       // A way to to start profiler in pause mode was removed.
2370       // To pause collection of the CPU ticks we need to emulate pause.
2371       // This will be removed later once XDK agent will have own sampler.
2372       profiler_->pause();
2373     }
2374   }
2375
2376   if (FLAG_log_internal_timer_events || FLAG_prof) timer_.Start();
2377
2378   return true;
2379 }
2380
2381
2382 void Logger::SetCodeEventHandler(uint32_t options,
2383                                  JitCodeEventHandler event_handler) {
2384   if (jit_logger_) {
2385       removeCodeEventListener(jit_logger_);
2386       delete jit_logger_;
2387       jit_logger_ = NULL;
2388   }
2389
2390   if (event_handler) {
2391     jit_logger_ = new JitLogger(event_handler);
2392     addCodeEventListener(jit_logger_);
2393     if (options & kJitCodeEventEnumExisting) {
2394       HandleScope scope(isolate_);
2395       LogCodeObjects();
2396       LogCompiledFunctions();
2397     }
2398   }
2399 }
2400
2401
2402 Sampler* Logger::sampler() {
2403   return ticker_;
2404 }
2405
2406
2407 FILE* Logger::TearDown() {
2408   if (!is_initialized_) return NULL;
2409   is_initialized_ = false;
2410
2411   // Stop the profiler before closing the file.
2412   if (profiler_ != NULL) {
2413     profiler_->Disengage();
2414     delete profiler_;
2415     profiler_ = NULL;
2416   }
2417
2418   delete ticker_;
2419   ticker_ = NULL;
2420
2421   if (perf_basic_logger_) {
2422     removeCodeEventListener(perf_basic_logger_);
2423     delete perf_basic_logger_;
2424     perf_basic_logger_ = NULL;
2425   }
2426
2427   if (perf_jit_logger_) {
2428     removeCodeEventListener(perf_jit_logger_);
2429     delete perf_jit_logger_;
2430     perf_jit_logger_ = NULL;
2431   }
2432
2433   if (ll_logger_) {
2434     removeCodeEventListener(ll_logger_);
2435     delete ll_logger_;
2436     ll_logger_ = NULL;
2437   }
2438
2439   if (jit_logger_) {
2440     removeCodeEventListener(jit_logger_);
2441     delete jit_logger_;
2442     jit_logger_ = NULL;
2443   }
2444
2445   return log_->Close();
2446 }
2447
2448 } }  // namespace v8::internal