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