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