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