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