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