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