1// Copyright 2011 the V8 project authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "src/log.h"
6
7#include <cstdarg>
8#include <memory>
9#include <sstream>
10
11#include "src/api-inl.h"
12#include "src/bailout-reason.h"
13#include "src/base/platform/platform.h"
14#include "src/bootstrapper.h"
15#include "src/counters.h"
16#include "src/deoptimizer.h"
17#include "src/global-handles.h"
18#include "src/interpreter/bytecodes.h"
19#include "src/interpreter/interpreter.h"
20#include "src/isolate.h"
21#include "src/libsampler/sampler.h"
22#include "src/log-inl.h"
23#include "src/log-utils.h"
24#include "src/macro-assembler.h"
25#include "src/memcopy.h"
26#include "src/objects/api-callbacks.h"
27#include "src/perf-jit.h"
28#include "src/profiler/tick-sample.h"
29#include "src/runtime-profiler.h"
30#include "src/snapshot/embedded-data.h"
31#include "src/source-position-table.h"
32#include "src/string-stream.h"
33#include "src/tracing/tracing-category-observer.h"
34#include "src/unicode-inl.h"
35#include "src/vm-state-inl.h"
36#include "src/wasm/wasm-code-manager.h"
37#include "src/wasm/wasm-objects-inl.h"
38
39#include "src/version.h"
40
41namespace v8 {
42namespace internal {
43
44#define DECLARE_EVENT(ignore1, name) #name,
45static const char* kLogEventsNames[CodeEventListener::NUMBER_OF_LOG_EVENTS] = {
46 LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)};
47#undef DECLARE_EVENT
48
49static v8::CodeEventType GetCodeEventTypeForTag(
50 CodeEventListener::LogEventsAndTags tag) {
51 switch (tag) {
52 case CodeEventListener::NUMBER_OF_LOG_EVENTS:
53#define V(Event, _) case CodeEventListener::Event:
54 LOG_EVENTS_LIST(V)
55#undef V
56 return v8::CodeEventType::kUnknownType;
57#define V(From, To) \
58 case CodeEventListener::From: \
59 return v8::CodeEventType::k##To##Type;
60 TAGS_LIST(V)
61#undef V
62 }
63 // The execution should never pass here
64 UNREACHABLE();
65 // NOTE(mmarchini): Workaround to fix a compiler failure on GCC 4.9
66 return v8::CodeEventType::kUnknownType;
67}
68#define CALL_CODE_EVENT_HANDLER(Call) \
69 if (listener_) { \
70 listener_->Call; \
71 } else { \
72 PROFILE(isolate_, Call); \
73 }
74
75static const char* ComputeMarker(SharedFunctionInfo shared, AbstractCode code) {
76 switch (code->kind()) {
77 case AbstractCode::INTERPRETED_FUNCTION:
78 return shared->optimization_disabled() ? "" : "~";
79 case AbstractCode::OPTIMIZED_FUNCTION:
80 return "*";
81 default:
82 return "";
83 }
84}
85
86static const char* ComputeMarker(const wasm::WasmCode* code) {
87 switch (code->kind()) {
88 case wasm::WasmCode::kFunction:
89 return code->is_liftoff() ? "" : "*";
90 case wasm::WasmCode::kInterpreterEntry:
91 return "~";
92 default:
93 return "";
94 }
95}
96
97class CodeEventLogger::NameBuffer {
98 public:
99 NameBuffer() { Reset(); }
100
101 void Reset() {
102 utf8_pos_ = 0;
103 }
104
105 void Init(CodeEventListener::LogEventsAndTags tag) {
106 Reset();
107 AppendBytes(kLogEventsNames[tag]);
108 AppendByte(':');
109 }
110
111 void AppendName(Name name) {
112 if (name->IsString()) {
113 AppendString(String::cast(name));
114 } else {
115 Symbol symbol = Symbol::cast(name);
116 AppendBytes("symbol(");
117 if (!symbol->name()->IsUndefined()) {
118 AppendBytes("\"");
119 AppendString(String::cast(symbol->name()));
120 AppendBytes("\" ");
121 }
122 AppendBytes("hash ");
123 AppendHex(symbol->Hash());
124 AppendByte(')');
125 }
126 }
127
128 void AppendString(String str) {
129 if (str.is_null()) return;
130 int length = 0;
131 std::unique_ptr<char[]> c_str =
132 str->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL, &length);
133 AppendBytes(c_str.get(), length);
134 }
135
136 void AppendBytes(const char* bytes, int size) {
137 size = Min(size, kUtf8BufferSize - utf8_pos_);
138 MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
139 utf8_pos_ += size;
140 }
141
142 void AppendBytes(const char* bytes) {
143 AppendBytes(bytes, StrLength(bytes));
144 }
145
146 void AppendByte(char c) {
147 if (utf8_pos_ >= kUtf8BufferSize) return;
148 utf8_buffer_[utf8_pos_++] = c;
149 }
150
151 void AppendInt(int n) {
152 int space = kUtf8BufferSize - utf8_pos_;
153 if (space <= 0) return;
154 Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
155 int size = SNPrintF(buffer, "%d", n);
156 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
157 utf8_pos_ += size;
158 }
159 }
160
161 void AppendHex(uint32_t n) {
162 int space = kUtf8BufferSize - utf8_pos_;
163 if (space <= 0) return;
164 Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
165 int size = SNPrintF(buffer, "%x", n);
166 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
167 utf8_pos_ += size;
168 }
169 }
170
171 const char* get() { return utf8_buffer_; }
172 int size() const { return utf8_pos_; }
173
174 private:
175 static const int kUtf8BufferSize = 512;
176 static const int kUtf16BufferSize = kUtf8BufferSize;
177
178 int utf8_pos_;
179 char utf8_buffer_[kUtf8BufferSize];
180};
181
182CodeEventLogger::CodeEventLogger(Isolate* isolate)
183 : isolate_(isolate), name_buffer_(new NameBuffer) {}
184
185CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }
186
187void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
188 AbstractCode code, const char* comment) {
189 name_buffer_->Init(tag);
190 name_buffer_->AppendBytes(comment);
191 LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(),
192 name_buffer_->size());
193}
194
195void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
196 AbstractCode code, Name name) {
197 name_buffer_->Init(tag);
198 name_buffer_->AppendName(name);
199 LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(),
200 name_buffer_->size());
201}
202
203void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
204 AbstractCode code,
205 SharedFunctionInfo shared, Name name) {
206 name_buffer_->Init(tag);
207 name_buffer_->AppendBytes(ComputeMarker(shared, code));
208 name_buffer_->AppendByte(' ');
209 name_buffer_->AppendName(name);
210 LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
211}
212
213void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
214 AbstractCode code,
215 SharedFunctionInfo shared, Name source,
216 int line, int column) {
217 name_buffer_->Init(tag);
218 name_buffer_->AppendBytes(ComputeMarker(shared, code));
219 name_buffer_->AppendString(shared->DebugName());
220 name_buffer_->AppendByte(' ');
221 if (source->IsString()) {
222 name_buffer_->AppendString(String::cast(source));
223 } else {
224 name_buffer_->AppendBytes("symbol(hash ");
225 name_buffer_->AppendHex(Name::cast(source)->Hash());
226 name_buffer_->AppendByte(')');
227 }
228 name_buffer_->AppendByte(':');
229 name_buffer_->AppendInt(line);
230 LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
231}
232
233void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag,
234 const wasm::WasmCode* code,
235 wasm::WasmName name) {
236 name_buffer_->Init(tag);
237 if (name.empty()) {
238 name_buffer_->AppendBytes("<wasm-unknown>");
239 } else {
240 name_buffer_->AppendBytes(name.start(), name.length());
241 }
242 name_buffer_->AppendByte('-');
243 if (code->IsAnonymous()) {
244 name_buffer_->AppendBytes("<anonymous>");
245 } else {
246 name_buffer_->AppendInt(code->index());
247 }
248 LogRecordedBuffer(code, name_buffer_->get(), name_buffer_->size());
249}
250
251void CodeEventLogger::RegExpCodeCreateEvent(AbstractCode code, String source) {
252 name_buffer_->Init(CodeEventListener::REG_EXP_TAG);
253 name_buffer_->AppendString(source);
254 LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(),
255 name_buffer_->size());
256}
257
258// Linux perf tool logging support
259class PerfBasicLogger : public CodeEventLogger {
260 public:
261 explicit PerfBasicLogger(Isolate* isolate);
262 ~PerfBasicLogger() override;
263
264 void CodeMoveEvent(AbstractCode from, AbstractCode to) override {}
265 void CodeDisableOptEvent(AbstractCode code,
266 SharedFunctionInfo shared) override {}
267
268 private:
269 void LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared,
270 const char* name, int length) override;
271 void LogRecordedBuffer(const wasm::WasmCode* code, const char* name,
272 int length) override;
273 void WriteLogRecordedBuffer(uintptr_t address, int size, const char* name,
274 int name_length);
275
276 // Extension added to V8 log file name to get the low-level log name.
277 static const char kFilenameFormatString[];
278 static const int kFilenameBufferPadding;
279
280 FILE* perf_output_handle_;
281};
282
283const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
284// Extra space for the PID in the filename
285const int PerfBasicLogger::kFilenameBufferPadding = 16;
286
287PerfBasicLogger::PerfBasicLogger(Isolate* isolate)
288 : CodeEventLogger(isolate), perf_output_handle_(nullptr) {
289 // Open the perf JIT dump file.
290 int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
291 ScopedVector<char> perf_dump_name(bufferSize);
292 int size = SNPrintF(
293 perf_dump_name,
294 kFilenameFormatString,
295 base::OS::GetCurrentProcessId());
296 CHECK_NE(size, -1);
297 perf_output_handle_ =
298 base::OS::FOpen(perf_dump_name.start(), base::OS::LogFileOpenMode);
299 CHECK_NOT_NULL(perf_output_handle_);
300 setvbuf(perf_output_handle_, nullptr, _IOLBF, 0);
301}
302
303
304PerfBasicLogger::~PerfBasicLogger() {
305 fclose(perf_output_handle_);
306 perf_output_handle_ = nullptr;
307}
308
309void PerfBasicLogger::WriteLogRecordedBuffer(uintptr_t address, int size,
310 const char* name,
311 int name_length) {
312 // Linux perf expects hex literals without a leading 0x, while some
313 // implementations of printf might prepend one when using the %p format
314 // for pointers, leading to wrongly formatted JIT symbols maps.
315 //
316 // Instead, we use V8PRIxPTR format string and cast pointer to uintpr_t,
317 // so that we have control over the exact output format.
318 base::OS::FPrint(perf_output_handle_, "%" V8PRIxPTR " %x %.*s\n", address,
319 size, name_length, name);
320}
321
322void PerfBasicLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo,
323 const char* name, int length) {
324 if (FLAG_perf_basic_prof_only_functions &&
325 (code->kind() != AbstractCode::INTERPRETED_FUNCTION &&
326 code->kind() != AbstractCode::BUILTIN &&
327 code->kind() != AbstractCode::OPTIMIZED_FUNCTION)) {
328 return;
329 }
330
331 WriteLogRecordedBuffer(static_cast<uintptr_t>(code->InstructionStart()),
332 code->InstructionSize(), name, length);
333}
334
335void PerfBasicLogger::LogRecordedBuffer(const wasm::WasmCode* code,
336 const char* name, int length) {
337 WriteLogRecordedBuffer(static_cast<uintptr_t>(code->instruction_start()),
338 code->instructions().length(), name, length);
339}
340
341// External CodeEventListener
342ExternalCodeEventListener::ExternalCodeEventListener(Isolate* isolate)
343 : is_listening_(false), isolate_(isolate), code_event_handler_(nullptr) {}
344
345ExternalCodeEventListener::~ExternalCodeEventListener() {
346 if (is_listening_) {
347 StopListening();
348 }
349}
350
351void ExternalCodeEventListener::LogExistingCode() {
352 HandleScope scope(isolate_);
353 ExistingCodeLogger logger(isolate_, this);
354 logger.LogCodeObjects();
355 logger.LogCompiledFunctions();
356}
357
358void ExternalCodeEventListener::StartListening(
359 CodeEventHandler* code_event_handler) {
360 if (is_listening_ || code_event_handler == nullptr) {
361 return;
362 }
363 code_event_handler_ = code_event_handler;
364 is_listening_ = isolate_->code_event_dispatcher()->AddListener(this);
365 if (is_listening_) {
366 LogExistingCode();
367 }
368}
369
370void ExternalCodeEventListener::StopListening() {
371 if (!is_listening_) {
372 return;
373 }
374
375 isolate_->code_event_dispatcher()->RemoveListener(this);
376 is_listening_ = false;
377}
378
379void ExternalCodeEventListener::CodeCreateEvent(
380 CodeEventListener::LogEventsAndTags tag, AbstractCode code,
381 const char* comment) {
382 CodeEvent code_event;
383 code_event.code_start_address =
384 static_cast<uintptr_t>(code->InstructionStart());
385 code_event.code_size = static_cast<size_t>(code->InstructionSize());
386 code_event.function_name = isolate_->factory()->empty_string();
387 code_event.script_name = isolate_->factory()->empty_string();
388 code_event.script_line = 0;
389 code_event.script_column = 0;
390 code_event.code_type = GetCodeEventTypeForTag(tag);
391 code_event.comment = comment;
392
393 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
394}
395
396void ExternalCodeEventListener::CodeCreateEvent(
397 CodeEventListener::LogEventsAndTags tag, AbstractCode code, Name name) {
398 Handle<String> name_string =
399 Name::ToFunctionName(isolate_, Handle<Name>(name, isolate_))
400 .ToHandleChecked();
401
402 CodeEvent code_event;
403 code_event.code_start_address =
404 static_cast<uintptr_t>(code->InstructionStart());
405 code_event.code_size = static_cast<size_t>(code->InstructionSize());
406 code_event.function_name = name_string;
407 code_event.script_name = isolate_->factory()->empty_string();
408 code_event.script_line = 0;
409 code_event.script_column = 0;
410 code_event.code_type = GetCodeEventTypeForTag(tag);
411 code_event.comment = "";
412
413 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
414}
415
416void ExternalCodeEventListener::CodeCreateEvent(
417 CodeEventListener::LogEventsAndTags tag, AbstractCode code,
418 SharedFunctionInfo shared, Name name) {
419 Handle<String> name_string =
420 Name::ToFunctionName(isolate_, Handle<Name>(name, isolate_))
421 .ToHandleChecked();
422
423 CodeEvent code_event;
424 code_event.code_start_address =
425 static_cast<uintptr_t>(code->InstructionStart());
426 code_event.code_size = static_cast<size_t>(code->InstructionSize());
427 code_event.function_name = name_string;
428 code_event.script_name = isolate_->factory()->empty_string();
429 code_event.script_line = 0;
430 code_event.script_column = 0;
431 code_event.code_type = GetCodeEventTypeForTag(tag);
432 code_event.comment = "";
433
434 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
435}
436
437void ExternalCodeEventListener::CodeCreateEvent(
438 CodeEventListener::LogEventsAndTags tag, AbstractCode code,
439 SharedFunctionInfo shared, Name source, int line, int column) {
440 Handle<String> name_string =
441 Name::ToFunctionName(isolate_, Handle<Name>(shared->Name(), isolate_))
442 .ToHandleChecked();
443 Handle<String> source_string =
444 Name::ToFunctionName(isolate_, Handle<Name>(source, isolate_))
445 .ToHandleChecked();
446
447 CodeEvent code_event;
448 code_event.code_start_address =
449 static_cast<uintptr_t>(code->InstructionStart());
450 code_event.code_size = static_cast<size_t>(code->InstructionSize());
451 code_event.function_name = name_string;
452 code_event.script_name = source_string;
453 code_event.script_line = line;
454 code_event.script_column = column;
455 code_event.code_type = GetCodeEventTypeForTag(tag);
456 code_event.comment = "";
457
458 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
459}
460
461void ExternalCodeEventListener::CodeCreateEvent(LogEventsAndTags tag,
462 const wasm::WasmCode* code,
463 wasm::WasmName name) {
464 // TODO(mmarchini): handle later
465}
466
467void ExternalCodeEventListener::RegExpCodeCreateEvent(AbstractCode code,
468 String source) {
469 CodeEvent code_event;
470 code_event.code_start_address =
471 static_cast<uintptr_t>(code->InstructionStart());
472 code_event.code_size = static_cast<size_t>(code->InstructionSize());
473 code_event.function_name = Handle<String>(source, isolate_);
474 code_event.script_name = isolate_->factory()->empty_string();
475 code_event.script_line = 0;
476 code_event.script_column = 0;
477 code_event.code_type = GetCodeEventTypeForTag(CodeEventListener::REG_EXP_TAG);
478 code_event.comment = "";
479
480 code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
481}
482
483// Low-level logging support.
484class LowLevelLogger : public CodeEventLogger {
485 public:
486 LowLevelLogger(Isolate* isolate, const char* file_name);
487 ~LowLevelLogger() override;
488
489 void CodeMoveEvent(AbstractCode from, AbstractCode to) override;
490 void CodeDisableOptEvent(AbstractCode code,
491 SharedFunctionInfo shared) override {}
492 void SnapshotPositionEvent(HeapObject obj, int pos);
493 void CodeMovingGCEvent() override;
494
495 private:
496 void LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared,
497 const char* name, int length) override;
498 void LogRecordedBuffer(const wasm::WasmCode* code, const char* name,
499 int length) override;
500
501 // Low-level profiling event structures.
502 struct CodeCreateStruct {
503 static const char kTag = 'C';
504
505 int32_t name_size;
506 Address code_address;
507 int32_t code_size;
508 };
509
510
511 struct CodeMoveStruct {
512 static const char kTag = 'M';
513
514 Address from_address;
515 Address to_address;
516 };
517
518
519 static const char kCodeMovingGCTag = 'G';
520
521
522 // Extension added to V8 log file name to get the low-level log name.
523 static const char kLogExt[];
524
525 void LogCodeInfo();
526 void LogWriteBytes(const char* bytes, int size);
527
528 template <typename T>
529 void LogWriteStruct(const T& s) {
530 char tag = T::kTag;
531 LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag));
532 LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
533 }
534
535 FILE* ll_output_handle_;
536};
537
538const char LowLevelLogger::kLogExt[] = ".ll";
539
540LowLevelLogger::LowLevelLogger(Isolate* isolate, const char* name)
541 : CodeEventLogger(isolate), ll_output_handle_(nullptr) {
542 // Open the low-level log file.
543 size_t len = strlen(name);
544 ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt)));
545 MemCopy(ll_name.start(), name, len);
546 MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
547 ll_output_handle_ =
548 base::OS::FOpen(ll_name.start(), base::OS::LogFileOpenMode);
549 setvbuf(ll_output_handle_, nullptr, _IOLBF, 0);
550
551 LogCodeInfo();
552}
553
554
555LowLevelLogger::~LowLevelLogger() {
556 fclose(ll_output_handle_);
557 ll_output_handle_ = nullptr;
558}
559
560
561void LowLevelLogger::LogCodeInfo() {
562#if V8_TARGET_ARCH_IA32
563 const char arch[] = "ia32";
564#elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_64_BIT
565 const char arch[] = "x64";
566#elif V8_TARGET_ARCH_ARM
567 const char arch[] = "arm";
568#elif V8_TARGET_ARCH_PPC
569 const char arch[] = "ppc";
570#elif V8_TARGET_ARCH_MIPS
571 const char arch[] = "mips";
572#elif V8_TARGET_ARCH_ARM64
573 const char arch[] = "arm64";
574#elif V8_TARGET_ARCH_S390
575 const char arch[] = "s390";
576#else
577 const char arch[] = "unknown";
578#endif
579 LogWriteBytes(arch, sizeof(arch));
580}
581
582void LowLevelLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo,
583 const char* name, int length) {
584 CodeCreateStruct event;
585 event.name_size = length;
586 event.code_address = code->InstructionStart();
587 event.code_size = code->InstructionSize();
588 LogWriteStruct(event);
589 LogWriteBytes(name, length);
590 LogWriteBytes(reinterpret_cast<const char*>(code->InstructionStart()),
591 code->InstructionSize());
592}
593
594void LowLevelLogger::LogRecordedBuffer(const wasm::WasmCode* code,
595 const char* name, int length) {
596 CodeCreateStruct event;
597 event.name_size = length;
598 event.code_address = code->instruction_start();
599 event.code_size = code->instructions().length();
600 LogWriteStruct(event);
601 LogWriteBytes(name, length);
602 LogWriteBytes(reinterpret_cast<const char*>(code->instruction_start()),
603 code->instructions().length());
604}
605
606void LowLevelLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) {
607 CodeMoveStruct event;
608 event.from_address = from->InstructionStart();
609 event.to_address = to->InstructionStart();
610 LogWriteStruct(event);
611}
612
613void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
614 size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
615 DCHECK(static_cast<size_t>(size) == rv);
616 USE(rv);
617}
618
619
620void LowLevelLogger::CodeMovingGCEvent() {
621 const char tag = kCodeMovingGCTag;
622
623 LogWriteBytes(&tag, sizeof(tag));
624}
625
626class JitLogger : public CodeEventLogger {
627 public:
628 JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler);
629
630 void CodeMoveEvent(AbstractCode from, AbstractCode to) override;
631 void CodeDisableOptEvent(AbstractCode code,
632 SharedFunctionInfo shared) override {}
633 void AddCodeLinePosInfoEvent(void* jit_handler_data, int pc_offset,
634 int position,
635 JitCodeEvent::PositionType position_type);
636
637 void* StartCodePosInfoEvent();
638 void EndCodePosInfoEvent(Address start_address, void* jit_handler_data);
639
640 private:
641 void LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared,
642 const char* name, int length) override;
643 void LogRecordedBuffer(const wasm::WasmCode* code, const char* name,
644 int length) override;
645
646 JitCodeEventHandler code_event_handler_;
647 base::Mutex logger_mutex_;
648};
649
650JitLogger::JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler)
651 : CodeEventLogger(isolate), code_event_handler_(code_event_handler) {}
652
653void JitLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared,
654 const char* name, int length) {
655 JitCodeEvent event;
656 memset(static_cast<void*>(&event), 0, sizeof(event));
657 event.type = JitCodeEvent::CODE_ADDED;
658 event.code_start = reinterpret_cast<void*>(code->InstructionStart());
659 event.code_type =
660 code->IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE;
661 event.code_len = code->InstructionSize();
662 Handle<SharedFunctionInfo> shared_function_handle;
663 if (!shared.is_null() && shared->script()->IsScript()) {
664 shared_function_handle =
665 Handle<SharedFunctionInfo>(shared, shared->GetIsolate());
666 }
667 event.script = ToApiHandle<v8::UnboundScript>(shared_function_handle);
668 event.name.str = name;
669 event.name.len = length;
670 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
671 code_event_handler_(&event);
672}
673
674void JitLogger::LogRecordedBuffer(const wasm::WasmCode* code, const char* name,
675 int length) {
676 JitCodeEvent event;
677 memset(static_cast<void*>(&event), 0, sizeof(event));
678 event.type = JitCodeEvent::CODE_ADDED;
679 event.code_type = JitCodeEvent::JIT_CODE;
680 event.code_start = code->instructions().start();
681 event.code_len = code->instructions().length();
682 event.name.str = name;
683 event.name.len = length;
684 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
685 code_event_handler_(&event);
686}
687
688void JitLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) {
689 base::MutexGuard guard(&logger_mutex_);
690
691 JitCodeEvent event;
692 event.type = JitCodeEvent::CODE_MOVED;
693 event.code_type =
694 from->IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE;
695 event.code_start = reinterpret_cast<void*>(from->InstructionStart());
696 event.code_len = from->InstructionSize();
697 event.new_code_start = reinterpret_cast<void*>(to->InstructionStart());
698 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
699
700 code_event_handler_(&event);
701}
702
703void JitLogger::AddCodeLinePosInfoEvent(
704 void* jit_handler_data,
705 int pc_offset,
706 int position,
707 JitCodeEvent::PositionType position_type) {
708 JitCodeEvent event;
709 memset(static_cast<void*>(&event), 0, sizeof(event));
710 event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO;
711 event.user_data = jit_handler_data;
712 event.line_info.offset = pc_offset;
713 event.line_info.pos = position;
714 event.line_info.position_type = position_type;
715 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
716
717 code_event_handler_(&event);
718}
719
720
721void* JitLogger::StartCodePosInfoEvent() {
722 JitCodeEvent event;
723 memset(static_cast<void*>(&event), 0, sizeof(event));
724 event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING;
725 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
726
727 code_event_handler_(&event);
728 return event.user_data;
729}
730
731void JitLogger::EndCodePosInfoEvent(Address start_address,
732 void* jit_handler_data) {
733 JitCodeEvent event;
734 memset(static_cast<void*>(&event), 0, sizeof(event));
735 event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING;
736 event.code_start = reinterpret_cast<void*>(start_address);
737 event.user_data = jit_handler_data;
738 event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
739
740 code_event_handler_(&event);
741}
742
743
744// TODO(lpy): Keeping sampling thread inside V8 is a workaround currently,
745// the reason is to reduce code duplication during migration to sampler library,
746// sampling thread, as well as the sampler, will be moved to D8 eventually.
747class SamplingThread : public base::Thread {
748 public:
749 static const int kSamplingThreadStackSize = 64 * KB;
750
751 SamplingThread(sampler::Sampler* sampler, int interval_microseconds)
752 : base::Thread(
753 base::Thread::Options("SamplingThread", kSamplingThreadStackSize)),
754 sampler_(sampler),
755 interval_microseconds_(interval_microseconds) {}
756 void Run() override {
757 while (sampler_->IsActive()) {
758 sampler_->DoSample();
759 base::OS::Sleep(
760 base::TimeDelta::FromMicroseconds(interval_microseconds_));
761 }
762 }
763
764 private:
765 sampler::Sampler* sampler_;
766 const int interval_microseconds_;
767};
768
769
770// The Profiler samples pc and sp values for the main thread.
771// Each sample is appended to a circular buffer.
772// An independent thread removes data and writes it to the log.
773// This design minimizes the time spent in the sampler.
774//
775class Profiler: public base::Thread {
776 public:
777 explicit Profiler(Isolate* isolate);
778 void Engage();
779 void Disengage();
780
781 // Inserts collected profiling data into buffer.
782 void Insert(v8::TickSample* sample) {
783 if (Succ(head_) == static_cast<int>(base::Relaxed_Load(&tail_))) {
784 overflow_ = true;
785 } else {
786 buffer_[head_] = *sample;
787 head_ = Succ(head_);
788 buffer_semaphore_.Signal(); // Tell we have an element.
789 }
790 }
791
792 void Run() override;
793
794 private:
795 // Waits for a signal and removes profiling data.
796 bool Remove(v8::TickSample* sample) {
797 buffer_semaphore_.Wait(); // Wait for an element.
798 *sample = buffer_[base::Relaxed_Load(&tail_)];
799 bool result = overflow_;
800 base::Relaxed_Store(
801 &tail_, static_cast<base::Atomic32>(Succ(base::Relaxed_Load(&tail_))));
802 overflow_ = false;
803 return result;
804 }
805
806 // Returns the next index in the cyclic buffer.
807 int Succ(int index) { return (index + 1) % kBufferSize; }
808
809 Isolate* isolate_;
810 // Cyclic buffer for communicating profiling samples
811 // between the signal handler and the worker thread.
812 static const int kBufferSize = 128;
813 v8::TickSample buffer_[kBufferSize]; // Buffer storage.
814 int head_; // Index to the buffer head.
815 base::Atomic32 tail_; // Index to the buffer tail.
816 bool overflow_; // Tell whether a buffer overflow has occurred.
817 // Semaphore used for buffer synchronization.
818 base::Semaphore buffer_semaphore_;
819
820 // Tells whether worker thread should continue running.
821 base::Atomic32 running_;
822};
823
824
825//
826// Ticker used to provide ticks to the profiler and the sliding state
827// window.
828//
829class Ticker: public sampler::Sampler {
830 public:
831 Ticker(Isolate* isolate, int interval_microseconds)
832 : sampler::Sampler(reinterpret_cast<v8::Isolate*>(isolate)),
833 sampling_thread_(
834 base::make_unique<SamplingThread>(this, interval_microseconds)) {}
835
836 ~Ticker() override {
837 if (IsActive()) Stop();
838 }
839
840 void SetProfiler(Profiler* profiler) {
841 DCHECK_NULL(profiler_);
842 profiler_ = profiler;
843 if (!IsActive()) Start();
844 sampling_thread_->StartSynchronously();
845 }
846
847 void ClearProfiler() {
848 profiler_ = nullptr;
849 if (IsActive()) Stop();
850 sampling_thread_->Join();
851 }
852
853 void SampleStack(const v8::RegisterState& state) override {
854 if (!profiler_) return;
855 Isolate* isolate = reinterpret_cast<Isolate*>(this->isolate());
856 TickSample sample;
857 sample.Init(isolate, state, TickSample::kIncludeCEntryFrame, true);
858 profiler_->Insert(&sample);
859 }
860
861 private:
862 Profiler* profiler_ = nullptr;
863 std::unique_ptr<SamplingThread> sampling_thread_;
864};
865
866//
867// Profiler implementation when invoking with --prof.
868//
869Profiler::Profiler(Isolate* isolate)
870 : base::Thread(Options("v8:Profiler")),
871 isolate_(isolate),
872 head_(0),
873 overflow_(false),
874 buffer_semaphore_(0) {
875 base::Relaxed_Store(&tail_, 0);
876 base::Relaxed_Store(&running_, 0);
877}
878
879void Profiler::Engage() {
880 std::vector<base::OS::SharedLibraryAddress> addresses =
881 base::OS::GetSharedLibraryAddresses();
882 for (const auto& address : addresses) {
883 LOG(isolate_, SharedLibraryEvent(address.library_path, address.start,
884 address.end, address.aslr_slide));
885 }
886
887 // Start thread processing the profiler buffer.
888 base::Relaxed_Store(&running_, 1);
889 Start();
890
891 // Register to get ticks.
892 Logger* logger = isolate_->logger();
893 logger->ticker_->SetProfiler(this);
894
895 logger->ProfilerBeginEvent();
896}
897
898
899void Profiler::Disengage() {
900 // Stop receiving ticks.
901 isolate_->logger()->ticker_->ClearProfiler();
902
903 // Terminate the worker thread by setting running_ to false,
904 // inserting a fake element in the queue and then wait for
905 // the thread to terminate.
906 base::Relaxed_Store(&running_, 0);
907 v8::TickSample sample;
908 Insert(&sample);
909 Join();
910
911 LOG(isolate_, UncheckedStringEvent("profiler", "end"));
912}
913
914
915void Profiler::Run() {
916 v8::TickSample sample;
917 bool overflow = Remove(&sample);
918 while (base::Relaxed_Load(&running_)) {
919 LOG(isolate_, TickEvent(&sample, overflow));
920 overflow = Remove(&sample);
921 }
922}
923
924
925//
926// Logger class implementation.
927//
928
929Logger::Logger(Isolate* isolate)
930 : isolate_(isolate),
931 log_events_(nullptr),
932 is_logging_(false),
933 log_(nullptr),
934 is_initialized_(false),
935 existing_code_logger_(isolate) {}
936
937Logger::~Logger() {
938 delete log_;
939}
940
941const LogSeparator Logger::kNext = LogSeparator::kSeparator;
942
943void Logger::AddCodeEventListener(CodeEventListener* listener) {
944 bool result = isolate_->code_event_dispatcher()->AddListener(listener);
945 CHECK(result);
946}
947
948void Logger::RemoveCodeEventListener(CodeEventListener* listener) {
949 isolate_->code_event_dispatcher()->RemoveListener(listener);
950}
951
952void Logger::ProfilerBeginEvent() {
953 if (!log_->IsEnabled()) return;
954 Log::MessageBuilder msg(log_);
955 msg << "profiler" << kNext << "begin" << kNext << FLAG_prof_sampling_interval;
956 msg.WriteToLogFile();
957}
958
959
960void Logger::StringEvent(const char* name, const char* value) {
961 if (FLAG_log) UncheckedStringEvent(name, value);
962}
963
964
965void Logger::UncheckedStringEvent(const char* name, const char* value) {
966 if (!log_->IsEnabled()) return;
967 Log::MessageBuilder msg(log_);
968 msg << name << kNext << value;
969 msg.WriteToLogFile();
970}
971
972
973void Logger::IntPtrTEvent(const char* name, intptr_t value) {
974 if (FLAG_log) UncheckedIntPtrTEvent(name, value);
975}
976
977
978void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
979 if (!log_->IsEnabled()) return;
980 Log::MessageBuilder msg(log_);
981 msg << name << kNext;
982 msg.AppendFormatString("%" V8PRIdPTR, value);
983 msg.WriteToLogFile();
984}
985
986void Logger::HandleEvent(const char* name, Address* location) {
987 if (!log_->IsEnabled() || !FLAG_log_handles) return;
988 Log::MessageBuilder msg(log_);
989 msg << name << kNext << reinterpret_cast<void*>(location);
990 msg.WriteToLogFile();
991}
992
993
994void Logger::ApiSecurityCheck() {
995 if (!log_->IsEnabled() || !FLAG_log_api) return;
996 Log::MessageBuilder msg(log_);
997 msg << "api" << kNext << "check-security";
998 msg.WriteToLogFile();
999}
1000
1001void Logger::SharedLibraryEvent(const std::string& library_path,
1002 uintptr_t start, uintptr_t end,
1003 intptr_t aslr_slide) {
1004 if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
1005 Log::MessageBuilder msg(log_);
1006 msg << "shared-library" << kNext << library_path.c_str() << kNext
1007 << reinterpret_cast<void*>(start) << kNext << reinterpret_cast<void*>(end)
1008 << kNext << aslr_slide;
1009 msg.WriteToLogFile();
1010}
1011
1012void Logger::CodeDeoptEvent(Code code, DeoptimizeKind kind, Address pc,
1013 int fp_to_sp_delta) {
1014 if (!log_->IsEnabled()) return;
1015 Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc);
1016 Log::MessageBuilder msg(log_);
1017 msg << "code-deopt" << kNext << timer_.Elapsed().InMicroseconds() << kNext
1018 << code->CodeSize() << kNext
1019 << reinterpret_cast<void*>(code->InstructionStart());
1020
1021 // Deoptimization position.
1022 std::ostringstream deopt_location;
1023 int inlining_id = -1;
1024 int script_offset = -1;
1025 if (info.position.IsKnown()) {
1026 info.position.Print(deopt_location, code);
1027 inlining_id = info.position.InliningId();
1028 script_offset = info.position.ScriptOffset();
1029 } else {
1030 deopt_location << "<unknown>";
1031 }
1032 msg << kNext << inlining_id << kNext << script_offset << kNext;
1033 msg << Deoptimizer::MessageFor(kind) << kNext;
1034 msg << deopt_location.str().c_str() << kNext
1035 << DeoptimizeReasonToString(info.deopt_reason);
1036 msg.WriteToLogFile();
1037}
1038
1039
1040void Logger::CurrentTimeEvent() {
1041 if (!log_->IsEnabled()) return;
1042 DCHECK(FLAG_log_internal_timer_events);
1043 Log::MessageBuilder msg(log_);
1044 msg << "current-time" << kNext << timer_.Elapsed().InMicroseconds();
1045 msg.WriteToLogFile();
1046}
1047
1048
1049void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
1050 if (!log_->IsEnabled()) return;
1051 Log::MessageBuilder msg(log_);
1052 switch (se) {
1053 case START:
1054 msg << "timer-event-start";
1055 break;
1056 case END:
1057 msg << "timer-event-end";
1058 break;
1059 case STAMP:
1060 msg << "timer-event";
1061 }
1062 msg << kNext << name << kNext << timer_.Elapsed().InMicroseconds();
1063 msg.WriteToLogFile();
1064}
1065
1066// static
1067void Logger::EnterExternal(Isolate* isolate) {
1068 DCHECK(FLAG_log_internal_timer_events);
1069 LOG(isolate, TimerEvent(START, TimerEventExternal::name()));
1070 DCHECK(isolate->current_vm_state() == JS);
1071 isolate->set_current_vm_state(EXTERNAL);
1072}
1073
1074// static
1075void Logger::LeaveExternal(Isolate* isolate) {
1076 DCHECK(FLAG_log_internal_timer_events);
1077 LOG(isolate, TimerEvent(END, TimerEventExternal::name()));
1078 DCHECK(isolate->current_vm_state() == EXTERNAL);
1079 isolate->set_current_vm_state(JS);
1080}
1081
1082// Instantiate template methods.
1083#define V(TimerName, expose) \
1084 template void TimerEventScope<TimerEvent##TimerName>::LogTimerEvent( \
1085 Logger::StartEnd se);
1086TIMER_EVENTS_LIST(V)
1087#undef V
1088
1089void Logger::ApiNamedPropertyAccess(const char* tag, JSObject holder,
1090 Object property_name) {
1091 DCHECK(property_name->IsName());
1092 if (!log_->IsEnabled() || !FLAG_log_api) return;
1093 Log::MessageBuilder msg(log_);
1094 msg << "api" << kNext << tag << kNext << holder->class_name() << kNext
1095 << Name::cast(property_name);
1096 msg.WriteToLogFile();
1097}
1098
1099void Logger::ApiIndexedPropertyAccess(const char* tag, JSObject holder,
1100 uint32_t index) {
1101 if (!log_->IsEnabled() || !FLAG_log_api) return;
1102 Log::MessageBuilder msg(log_);
1103 msg << "api" << kNext << tag << kNext << holder->class_name() << kNext
1104 << index;
1105 msg.WriteToLogFile();
1106}
1107
1108void Logger::ApiObjectAccess(const char* tag, JSObject object) {
1109 if (!log_->IsEnabled() || !FLAG_log_api) return;
1110 Log::MessageBuilder msg(log_);
1111 msg << "api" << kNext << tag << kNext << object->class_name();
1112 msg.WriteToLogFile();
1113}
1114
1115void Logger::ApiEntryCall(const char* name) {
1116 if (!log_->IsEnabled() || !FLAG_log_api) return;
1117 Log::MessageBuilder msg(log_);
1118 msg << "api" << kNext << name;
1119 msg.WriteToLogFile();
1120}
1121
1122
1123void Logger::NewEvent(const char* name, void* object, size_t size) {
1124 if (!log_->IsEnabled() || !FLAG_log) return;
1125 Log::MessageBuilder msg(log_);
1126 msg << "new" << kNext << name << kNext << object << kNext
1127 << static_cast<unsigned int>(size);
1128 msg.WriteToLogFile();
1129}
1130
1131
1132void Logger::DeleteEvent(const char* name, void* object) {
1133 if (!log_->IsEnabled() || !FLAG_log) return;
1134 Log::MessageBuilder msg(log_);
1135 msg << "delete" << kNext << name << kNext << object;
1136 msg.WriteToLogFile();
1137}
1138
1139void Logger::CallbackEventInternal(const char* prefix, Name name,
1140 Address entry_point) {
1141 if (!FLAG_log_code || !log_->IsEnabled()) return;
1142 Log::MessageBuilder msg(log_);
1143 msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << kNext
1144 << kLogEventsNames[CodeEventListener::CALLBACK_TAG] << kNext << -2
1145 << kNext << timer_.Elapsed().InMicroseconds() << kNext
1146 << reinterpret_cast<void*>(entry_point) << kNext << 1 << kNext << prefix
1147 << name;
1148 msg.WriteToLogFile();
1149}
1150
1151void Logger::CallbackEvent(Name name, Address entry_point) {
1152 CallbackEventInternal("", name, entry_point);
1153}
1154
1155void Logger::GetterCallbackEvent(Name name, Address entry_point) {
1156 CallbackEventInternal("get ", name, entry_point);
1157}
1158
1159void Logger::SetterCallbackEvent(Name name, Address entry_point) {
1160 CallbackEventInternal("set ", name, entry_point);
1161}
1162
1163namespace {
1164
1165void AppendCodeCreateHeader(Log::MessageBuilder& msg,
1166 CodeEventListener::LogEventsAndTags tag,
1167 AbstractCode::Kind kind, uint8_t* address, int size,
1168 base::ElapsedTimer* timer) {
1169 msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT]
1170 << Logger::kNext << kLogEventsNames[tag] << Logger::kNext << kind
1171 << Logger::kNext << timer->Elapsed().InMicroseconds() << Logger::kNext
1172 << reinterpret_cast<void*>(address) << Logger::kNext << size
1173 << Logger::kNext;
1174}
1175
1176void AppendCodeCreateHeader(Log::MessageBuilder& msg,
1177 CodeEventListener::LogEventsAndTags tag,
1178 AbstractCode code, base::ElapsedTimer* timer) {
1179 AppendCodeCreateHeader(msg, tag, code->kind(),
1180 reinterpret_cast<uint8_t*>(code->InstructionStart()),
1181 code->InstructionSize(), timer);
1182}
1183
1184} // namespace
1185
1186void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1187 AbstractCode code, const char* comment) {
1188 if (!is_listening_to_code_events()) return;
1189 if (!FLAG_log_code || !log_->IsEnabled()) return;
1190 Log::MessageBuilder msg(log_);
1191 AppendCodeCreateHeader(msg, tag, code, &timer_);
1192 msg << comment;
1193 msg.WriteToLogFile();
1194}
1195
1196void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1197 AbstractCode code, Name name) {
1198 if (!is_listening_to_code_events()) return;
1199 if (!FLAG_log_code || !log_->IsEnabled()) return;
1200 Log::MessageBuilder msg(log_);
1201 AppendCodeCreateHeader(msg, tag, code, &timer_);
1202 msg << name;
1203 msg.WriteToLogFile();
1204}
1205
1206void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1207 AbstractCode code, SharedFunctionInfo shared,
1208 Name name) {
1209 if (!is_listening_to_code_events()) return;
1210 if (!FLAG_log_code || !log_->IsEnabled()) return;
1211 if (code == AbstractCode::cast(
1212 isolate_->builtins()->builtin(Builtins::kCompileLazy))) {
1213 return;
1214 }
1215
1216 Log::MessageBuilder msg(log_);
1217 AppendCodeCreateHeader(msg, tag, code, &timer_);
1218 msg << name << kNext << reinterpret_cast<void*>(shared->address()) << kNext
1219 << ComputeMarker(shared, code);
1220 msg.WriteToLogFile();
1221}
1222
1223void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1224 const wasm::WasmCode* code, wasm::WasmName name) {
1225 if (!is_listening_to_code_events()) return;
1226 if (!FLAG_log_code || !log_->IsEnabled()) return;
1227 Log::MessageBuilder msg(log_);
1228 AppendCodeCreateHeader(msg, tag, AbstractCode::Kind::WASM_FUNCTION,
1229 code->instructions().start(),
1230 code->instructions().length(), &timer_);
1231 if (name.empty()) {
1232 msg << "<unknown wasm>";
1233 } else {
1234 msg.AppendString(name);
1235 }
1236 // We have to add two extra fields that allow the tick processor to group
1237 // events for the same wasm function, even if it gets compiled again. For
1238 // normal JS functions, we use the shared function info. For wasm, the pointer
1239 // to the native module + function index works well enough.
1240 // TODO(herhut) Clean up the tick processor code instead.
1241 void* tag_ptr =
1242 reinterpret_cast<byte*>(code->native_module()) + code->index();
1243 msg << kNext << tag_ptr << kNext << ComputeMarker(code);
1244 msg.WriteToLogFile();
1245}
1246
1247// Although, it is possible to extract source and line from
1248// the SharedFunctionInfo object, we left it to caller
1249// to leave logging functions free from heap allocations.
1250void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1251 AbstractCode code, SharedFunctionInfo shared,
1252 Name source, int line, int column) {
1253 if (!is_listening_to_code_events()) return;
1254 if (!FLAG_log_code || !log_->IsEnabled()) return;
1255 {
1256 Log::MessageBuilder msg(log_);
1257 AppendCodeCreateHeader(msg, tag, code, &timer_);
1258 msg << shared->DebugName() << " " << source << ":" << line << ":" << column
1259 << kNext << reinterpret_cast<void*>(shared->address()) << kNext
1260 << ComputeMarker(shared, code);
1261 msg.WriteToLogFile();
1262 }
1263
1264 if (!FLAG_log_source_code) return;
1265 Object script_object = shared->script();
1266 if (!script_object->IsScript()) return;
1267 Script script = Script::cast(script_object);
1268 if (!EnsureLogScriptSource(script)) return;
1269
1270 // We log source code information in the form:
1271 //
1272 // code-source-info <addr>,<script>,<start>,<end>,<pos>,<inline-pos>,<fns>
1273 //
1274 // where
1275 // <addr> is code object address
1276 // <script> is script id
1277 // <start> is the starting position inside the script
1278 // <end> is the end position inside the script
1279 // <pos> is source position table encoded in the string,
1280 // it is a sequence of C<code-offset>O<script-offset>[I<inlining-id>]
1281 // where
1282 // <code-offset> is the offset within the code object
1283 // <script-offset> is the position within the script
1284 // <inlining-id> is the offset in the <inlining> table
1285 // <inlining> table is a sequence of strings of the form
1286 // F<function-id>O<script-offset>[I<inlining-id>]
1287 // where
1288 // <function-id> is an index into the <fns> function table
1289 // <fns> is the function table encoded as a sequence of strings
1290 // S<shared-function-info-address>
1291 Log::MessageBuilder msg(log_);
1292 msg << "code-source-info" << kNext
1293 << reinterpret_cast<void*>(code->InstructionStart()) << kNext
1294 << script->id() << kNext << shared->StartPosition() << kNext
1295 << shared->EndPosition() << kNext;
1296
1297 SourcePositionTableIterator iterator(code->source_position_table());
1298 bool hasInlined = false;
1299 for (; !iterator.done(); iterator.Advance()) {
1300 SourcePosition pos = iterator.source_position();
1301 msg << "C" << iterator.code_offset() << "O" << pos.ScriptOffset();
1302 if (pos.isInlined()) {
1303 msg << "I" << pos.InliningId();
1304 hasInlined = true;
1305 }
1306 }
1307 msg << kNext;
1308 int maxInlinedId = -1;
1309 if (hasInlined) {
1310 PodArray<InliningPosition> inlining_positions =
1311 DeoptimizationData::cast(Code::cast(code)->deoptimization_data())
1312 ->InliningPositions();
1313 for (int i = 0; i < inlining_positions->length(); i++) {
1314 InliningPosition inlining_pos = inlining_positions->get(i);
1315 msg << "F";
1316 if (inlining_pos.inlined_function_id != -1) {
1317 msg << inlining_pos.inlined_function_id;
1318 if (inlining_pos.inlined_function_id > maxInlinedId) {
1319 maxInlinedId = inlining_pos.inlined_function_id;
1320 }
1321 }
1322 SourcePosition pos = inlining_pos.position;
1323 msg << "O" << pos.ScriptOffset();
1324 if (pos.isInlined()) {
1325 msg << "I" << pos.InliningId();
1326 }
1327 }
1328 }
1329 msg << kNext;
1330 if (hasInlined) {
1331 DeoptimizationData deopt_data =
1332 DeoptimizationData::cast(Code::cast(code)->deoptimization_data());
1333
1334 msg << std::hex;
1335 for (int i = 0; i <= maxInlinedId; i++) {
1336 msg << "S"
1337 << reinterpret_cast<void*>(
1338 deopt_data->GetInlinedFunction(i)->address());
1339 }
1340 msg << std::dec;
1341 }
1342 msg.WriteToLogFile();
1343}
1344
1345void Logger::CodeDisableOptEvent(AbstractCode code, SharedFunctionInfo shared) {
1346 if (!is_listening_to_code_events()) return;
1347 if (!FLAG_log_code || !log_->IsEnabled()) return;
1348 Log::MessageBuilder msg(log_);
1349 msg << kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT] << kNext
1350 << shared->DebugName() << kNext
1351 << GetBailoutReason(shared->disable_optimization_reason());
1352 msg.WriteToLogFile();
1353}
1354
1355void Logger::CodeMovingGCEvent() {
1356 if (!is_listening_to_code_events()) return;
1357 if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1358 base::OS::SignalCodeMovingGC();
1359}
1360
1361void Logger::RegExpCodeCreateEvent(AbstractCode code, String source) {
1362 if (!is_listening_to_code_events()) return;
1363 if (!FLAG_log_code || !log_->IsEnabled()) return;
1364 Log::MessageBuilder msg(log_);
1365 AppendCodeCreateHeader(msg, CodeEventListener::REG_EXP_TAG, code, &timer_);
1366 msg << source;
1367 msg.WriteToLogFile();
1368}
1369
1370void Logger::CodeMoveEvent(AbstractCode from, AbstractCode to) {
1371 if (!is_listening_to_code_events()) return;
1372 MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(),
1373 to->address());
1374}
1375
1376namespace {
1377
1378void CodeLinePosEvent(JitLogger* jit_logger, Address code_start,
1379 SourcePositionTableIterator& iter) {
1380 if (jit_logger) {
1381 void* jit_handler_data = jit_logger->StartCodePosInfoEvent();
1382 for (; !iter.done(); iter.Advance()) {
1383 if (iter.is_statement()) {
1384 jit_logger->AddCodeLinePosInfoEvent(
1385 jit_handler_data, iter.code_offset(),
1386 iter.source_position().ScriptOffset(),
1387 JitCodeEvent::STATEMENT_POSITION);
1388 }
1389 jit_logger->AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(),
1390 iter.source_position().ScriptOffset(),
1391 JitCodeEvent::POSITION);
1392 }
1393 jit_logger->EndCodePosInfoEvent(code_start, jit_handler_data);
1394 }
1395}
1396
1397} // namespace
1398
1399void Logger::CodeLinePosInfoRecordEvent(Address code_start,
1400 ByteArray source_position_table) {
1401 SourcePositionTableIterator iter(source_position_table);
1402 CodeLinePosEvent(jit_logger_.get(), code_start, iter);
1403}
1404
1405void Logger::CodeLinePosInfoRecordEvent(
1406 Address code_start, Vector<const byte> source_position_table) {
1407 SourcePositionTableIterator iter(source_position_table);
1408 CodeLinePosEvent(jit_logger_.get(), code_start, iter);
1409}
1410
1411void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
1412 if (code_name == nullptr) return; // Not a code object.
1413 Log::MessageBuilder msg(log_);
1414 msg << kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT] << kNext
1415 << pos << kNext << code_name;
1416 msg.WriteToLogFile();
1417}
1418
1419
1420void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1421 if (!is_listening_to_code_events()) return;
1422 MoveEventInternal(CodeEventListener::SHARED_FUNC_MOVE_EVENT, from, to);
1423}
1424
1425void Logger::MoveEventInternal(CodeEventListener::LogEventsAndTags event,
1426 Address from, Address to) {
1427 if (!FLAG_log_code || !log_->IsEnabled()) return;
1428 Log::MessageBuilder msg(log_);
1429 msg << kLogEventsNames[event] << kNext << reinterpret_cast<void*>(from)
1430 << kNext << reinterpret_cast<void*>(to);
1431 msg.WriteToLogFile();
1432}
1433
1434
1435void Logger::ResourceEvent(const char* name, const char* tag) {
1436 if (!log_->IsEnabled() || !FLAG_log) return;
1437 Log::MessageBuilder msg(log_);
1438 msg << name << kNext << tag << kNext;
1439
1440 uint32_t sec, usec;
1441 if (base::OS::GetUserTime(&sec, &usec) != -1) {
1442 msg << sec << kNext << usec << kNext;
1443 }
1444 msg.AppendFormatString("%.0f",
1445 V8::GetCurrentPlatform()->CurrentClockTimeMillis());
1446 msg.WriteToLogFile();
1447}
1448
1449void 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 : ReadOnlyRoots(isolate_).empty_string();
1455 msg << "suspect-read" << kNext << class_name << kNext << name;
1456 msg.WriteToLogFile();
1457}
1458
1459namespace {
1460void AppendFunctionMessage(Log::MessageBuilder& msg, const char* reason,
1461 int script_id, double time_delta, int start_position,
1462 int end_position, base::ElapsedTimer* timer) {
1463 msg << "function" << Logger::kNext << reason << Logger::kNext << script_id
1464 << Logger::kNext << start_position << Logger::kNext << end_position
1465 << Logger::kNext << time_delta << Logger::kNext
1466 << timer->Elapsed().InMicroseconds() << Logger::kNext;
1467}
1468} // namespace
1469
1470void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
1471 int start_position, int end_position,
1472 String function_name) {
1473 if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1474 Log::MessageBuilder msg(log_);
1475 AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
1476 end_position, &timer_);
1477 if (!function_name.is_null()) msg << function_name;
1478 msg.WriteToLogFile();
1479}
1480
1481void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
1482 int start_position, int end_position,
1483 const char* function_name,
1484 size_t function_name_length) {
1485 if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1486 Log::MessageBuilder msg(log_);
1487 AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
1488 end_position, &timer_);
1489 if (function_name_length > 0) {
1490 msg.AppendString(function_name, function_name_length);
1491 }
1492 msg.WriteToLogFile();
1493}
1494
1495void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
1496 SharedFunctionInfo sfi) {
1497 if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1498 Log::MessageBuilder msg(log_);
1499 int script_id = -1;
1500 if (sfi->script()->IsScript()) {
1501 script_id = Script::cast(sfi->script())->id();
1502 }
1503 msg << "compilation-cache" << Logger::kNext << action << Logger::kNext
1504 << cache_type << Logger::kNext << script_id << Logger::kNext
1505 << sfi->StartPosition() << Logger::kNext << sfi->EndPosition()
1506 << Logger::kNext << timer_.Elapsed().InMicroseconds();
1507 msg.WriteToLogFile();
1508}
1509
1510void Logger::ScriptEvent(ScriptEventType type, int script_id) {
1511 if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1512 Log::MessageBuilder msg(log_);
1513 msg << "script" << Logger::kNext;
1514 switch (type) {
1515 case ScriptEventType::kReserveId:
1516 msg << "reserve-id";
1517 break;
1518 case ScriptEventType::kCreate:
1519 msg << "create";
1520 break;
1521 case ScriptEventType::kDeserialize:
1522 msg << "deserialize";
1523 break;
1524 case ScriptEventType::kBackgroundCompile:
1525 msg << "background-compile";
1526 break;
1527 case ScriptEventType::kStreamingCompile:
1528 msg << "streaming-compile";
1529 break;
1530 }
1531 msg << Logger::kNext << script_id << Logger::kNext
1532 << timer_.Elapsed().InMicroseconds();
1533 msg.WriteToLogFile();
1534}
1535
1536void Logger::ScriptDetails(Script script) {
1537 if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1538 {
1539 Log::MessageBuilder msg(log_);
1540 msg << "script-details" << Logger::kNext << script->id() << Logger::kNext;
1541 if (script->name()->IsString()) {
1542 msg << String::cast(script->name());
1543 }
1544 msg << Logger::kNext << script->line_offset() << Logger::kNext
1545 << script->column_offset() << Logger::kNext;
1546 if (script->source_mapping_url()->IsString()) {
1547 msg << String::cast(script->source_mapping_url());
1548 }
1549 msg.WriteToLogFile();
1550 }
1551 EnsureLogScriptSource(script);
1552}
1553
1554bool Logger::EnsureLogScriptSource(Script script) {
1555 if (!log_->IsEnabled()) return false;
1556 Log::MessageBuilder msg(log_);
1557 // Make sure the script is written to the log file.
1558 int script_id = script->id();
1559 if (logged_source_code_.find(script_id) != logged_source_code_.end()) {
1560 return true;
1561 }
1562 // This script has not been logged yet.
1563 logged_source_code_.insert(script_id);
1564 Object source_object = script->source();
1565 if (!source_object->IsString()) return false;
1566 String source_code = String::cast(source_object);
1567 msg << "script-source" << kNext << script_id << kNext;
1568
1569 // Log the script name.
1570 if (script->name()->IsString()) {
1571 msg << String::cast(script->name()) << kNext;
1572 } else {
1573 msg << "<unknown>" << kNext;
1574 }
1575
1576 // Log the source code.
1577 msg << source_code;
1578 msg.WriteToLogFile();
1579 return true;
1580}
1581
1582void Logger::RuntimeCallTimerEvent() {
1583 RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats();
1584 RuntimeCallCounter* counter = stats->current_counter();
1585 if (counter == nullptr) return;
1586 Log::MessageBuilder msg(log_);
1587 msg << "active-runtime-timer" << kNext << counter->name();
1588 msg.WriteToLogFile();
1589}
1590
1591void Logger::TickEvent(v8::TickSample* sample, bool overflow) {
1592 if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
1593 if (V8_UNLIKELY(TracingFlags::runtime_stats.load(std::memory_order_relaxed) ==
1594 v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE)) {
1595 RuntimeCallTimerEvent();
1596 }
1597 Log::MessageBuilder msg(log_);
1598 msg << kLogEventsNames[CodeEventListener::TICK_EVENT] << kNext
1599 << reinterpret_cast<void*>(sample->pc) << kNext
1600 << timer_.Elapsed().InMicroseconds();
1601 if (sample->has_external_callback) {
1602 msg << kNext << 1 << kNext
1603 << reinterpret_cast<void*>(sample->external_callback_entry);
1604 } else {
1605 msg << kNext << 0 << kNext << reinterpret_cast<void*>(sample->tos);
1606 }
1607 msg << kNext << static_cast<int>(sample->state);
1608 if (overflow) msg << kNext << "overflow";
1609 for (unsigned i = 0; i < sample->frames_count; ++i) {
1610 msg << kNext << reinterpret_cast<void*>(sample->stack[i]);
1611 }
1612 msg.WriteToLogFile();
1613}
1614
1615void Logger::ICEvent(const char* type, bool keyed, Map map, Object key,
1616 char old_state, char new_state, const char* modifier,
1617 const char* slow_stub_reason) {
1618 if (!log_->IsEnabled() || !FLAG_trace_ic) return;
1619 Log::MessageBuilder msg(log_);
1620 if (keyed) msg << "Keyed";
1621 int line;
1622 int column;
1623 Address pc = isolate_->GetAbstractPC(&line, &column);
1624 msg << type << kNext << reinterpret_cast<void*>(pc) << kNext << line << kNext
1625 << column << kNext << old_state << kNext << new_state << kNext
1626 << AsHex::Address(map.ptr()) << kNext;
1627 if (key->IsSmi()) {
1628 msg << Smi::ToInt(key);
1629 } else if (key->IsNumber()) {
1630 msg << key->Number();
1631 } else if (key->IsName()) {
1632 msg << Name::cast(key);
1633 }
1634 msg << kNext << modifier << kNext;
1635 if (slow_stub_reason != nullptr) {
1636 msg << slow_stub_reason;
1637 }
1638 msg.WriteToLogFile();
1639}
1640
1641void Logger::MapEvent(const char* type, Map from, Map to, const char* reason,
1642 HeapObject name_or_sfi) {
1643 DisallowHeapAllocation no_gc;
1644 if (!log_->IsEnabled() || !FLAG_trace_maps) return;
1645 if (!to.is_null()) MapDetails(to);
1646 int line = -1;
1647 int column = -1;
1648 Address pc = 0;
1649
1650 if (!isolate_->bootstrapper()->IsActive()) {
1651 pc = isolate_->GetAbstractPC(&line, &column);
1652 }
1653 Log::MessageBuilder msg(log_);
1654 msg << "map" << kNext << type << kNext << timer_.Elapsed().InMicroseconds()
1655 << kNext << AsHex::Address(from.ptr()) << kNext
1656 << AsHex::Address(to.ptr()) << kNext << AsHex::Address(pc) << kNext
1657 << line << kNext << column << kNext << reason << kNext;
1658
1659 if (!name_or_sfi.is_null()) {
1660 if (name_or_sfi->IsName()) {
1661 msg << Name::cast(name_or_sfi);
1662 } else if (name_or_sfi->IsSharedFunctionInfo()) {
1663 SharedFunctionInfo sfi = SharedFunctionInfo::cast(name_or_sfi);
1664 msg << sfi->DebugName();
1665#if V8_SFI_HAS_UNIQUE_ID
1666 msg << " " << SharedFunctionInfoWithID::cast(sfi)->unique_id();
1667#endif // V8_SFI_HAS_UNIQUE_ID
1668 }
1669 }
1670 msg.WriteToLogFile();
1671}
1672
1673void Logger::MapCreate(Map map) {
1674 if (!log_->IsEnabled() || !FLAG_trace_maps) return;
1675 DisallowHeapAllocation no_gc;
1676 Log::MessageBuilder msg(log_);
1677 msg << "map-create" << kNext << timer_.Elapsed().InMicroseconds() << kNext
1678 << AsHex::Address(map.ptr());
1679 msg.WriteToLogFile();
1680}
1681
1682void Logger::MapDetails(Map map) {
1683 if (!log_->IsEnabled() || !FLAG_trace_maps) return;
1684 DisallowHeapAllocation no_gc;
1685 Log::MessageBuilder msg(log_);
1686 msg << "map-details" << kNext << timer_.Elapsed().InMicroseconds() << kNext
1687 << AsHex::Address(map.ptr()) << kNext;
1688 if (FLAG_trace_maps_details) {
1689 std::ostringstream buffer;
1690 map->PrintMapDetails(buffer);
1691 msg << buffer.str().c_str();
1692 }
1693 msg.WriteToLogFile();
1694}
1695
1696static void AddFunctionAndCode(SharedFunctionInfo sfi, AbstractCode code_object,
1697 Handle<SharedFunctionInfo>* sfis,
1698 Handle<AbstractCode>* code_objects, int offset) {
1699 if (sfis != nullptr) {
1700 sfis[offset] = Handle<SharedFunctionInfo>(sfi, sfi->GetIsolate());
1701 }
1702 if (code_objects != nullptr) {
1703 code_objects[offset] = Handle<AbstractCode>(code_object, sfi->GetIsolate());
1704 }
1705}
1706
1707static int EnumerateCompiledFunctions(Heap* heap,
1708 Handle<SharedFunctionInfo>* sfis,
1709 Handle<AbstractCode>* code_objects) {
1710 HeapIterator iterator(heap);
1711 DisallowHeapAllocation no_gc;
1712 int compiled_funcs_count = 0;
1713
1714 // Iterate the heap to find shared function info objects and record
1715 // the unoptimized code for them.
1716 for (HeapObject obj = iterator.next(); !obj.is_null();
1717 obj = iterator.next()) {
1718 if (obj->IsSharedFunctionInfo()) {
1719 SharedFunctionInfo sfi = SharedFunctionInfo::cast(obj);
1720 if (sfi->is_compiled() &&
1721 (!sfi->script()->IsScript() ||
1722 Script::cast(sfi->script())->HasValidSource())) {
1723 AddFunctionAndCode(sfi, AbstractCode::cast(sfi->abstract_code()), sfis,
1724 code_objects, compiled_funcs_count);
1725 ++compiled_funcs_count;
1726 }
1727 } else if (obj->IsJSFunction()) {
1728 // Given that we no longer iterate over all optimized JSFunctions, we need
1729 // to take care of this here.
1730 JSFunction function = JSFunction::cast(obj);
1731 SharedFunctionInfo sfi = SharedFunctionInfo::cast(function->shared());
1732 Object maybe_script = sfi->script();
1733 if (maybe_script->IsScript() &&
1734 !Script::cast(maybe_script)->HasValidSource()) {
1735 continue;
1736 }
1737 // TODO(jarin) This leaves out deoptimized code that might still be on the
1738 // stack. Also note that we will not log optimized code objects that are
1739 // only on a type feedback vector. We should make this mroe precise.
1740 if (function->IsOptimized()) {
1741 AddFunctionAndCode(sfi, AbstractCode::cast(function->code()), sfis,
1742 code_objects, compiled_funcs_count);
1743 ++compiled_funcs_count;
1744 }
1745 }
1746 }
1747 return compiled_funcs_count;
1748}
1749
1750static int EnumerateWasmModuleObjects(
1751 Heap* heap, Handle<WasmModuleObject>* module_objects) {
1752 HeapIterator iterator(heap);
1753 DisallowHeapAllocation no_gc;
1754 int module_objects_count = 0;
1755
1756 for (HeapObject obj = iterator.next(); !obj.is_null();
1757 obj = iterator.next()) {
1758 if (obj->IsWasmModuleObject()) {
1759 WasmModuleObject module = WasmModuleObject::cast(obj);
1760 if (module_objects != nullptr) {
1761 module_objects[module_objects_count] =
1762 handle(module, Isolate::FromHeap(heap));
1763 }
1764 module_objects_count++;
1765 }
1766 }
1767 return module_objects_count;
1768}
1769
1770void Logger::LogCodeObject(Object object) {
1771 existing_code_logger_.LogCodeObject(object);
1772}
1773
1774void Logger::LogCodeObjects() { existing_code_logger_.LogCodeObjects(); }
1775
1776void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
1777 Handle<AbstractCode> code) {
1778 existing_code_logger_.LogExistingFunction(shared, code);
1779}
1780
1781void Logger::LogCompiledFunctions() {
1782 existing_code_logger_.LogCompiledFunctions();
1783}
1784
1785void Logger::LogAccessorCallbacks() {
1786 Heap* heap = isolate_->heap();
1787 HeapIterator iterator(heap);
1788 DisallowHeapAllocation no_gc;
1789 for (HeapObject obj = iterator.next(); !obj.is_null();
1790 obj = iterator.next()) {
1791 if (!obj->IsAccessorInfo()) continue;
1792 AccessorInfo ai = AccessorInfo::cast(obj);
1793 if (!ai->name()->IsName()) continue;
1794 Address getter_entry = v8::ToCData<Address>(ai->getter());
1795 Name name = Name::cast(ai->name());
1796 if (getter_entry != 0) {
1797#if USES_FUNCTION_DESCRIPTORS
1798 getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(getter_entry);
1799#endif
1800 PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
1801 }
1802 Address setter_entry = v8::ToCData<Address>(ai->setter());
1803 if (setter_entry != 0) {
1804#if USES_FUNCTION_DESCRIPTORS
1805 setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(setter_entry);
1806#endif
1807 PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
1808 }
1809 }
1810}
1811
1812void Logger::LogAllMaps() {
1813 DisallowHeapAllocation no_gc;
1814 Heap* heap = isolate_->heap();
1815 HeapIterator iterator(heap);
1816 for (HeapObject obj = iterator.next(); !obj.is_null();
1817 obj = iterator.next()) {
1818 if (!obj->IsMap()) continue;
1819 Map map = Map::cast(obj);
1820 MapCreate(map);
1821 MapDetails(map);
1822 }
1823}
1824
1825static void AddIsolateIdIfNeeded(std::ostream& os, // NOLINT
1826 Isolate* isolate) {
1827 if (FLAG_logfile_per_isolate) {
1828 os << "isolate-" << isolate << "-" << base::OS::GetCurrentProcessId()
1829 << "-";
1830 }
1831}
1832
1833static void PrepareLogFileName(std::ostream& os, // NOLINT
1834 Isolate* isolate, const char* file_name) {
1835 int dir_separator_count = 0;
1836 for (const char* p = file_name; *p; p++) {
1837 if (base::OS::isDirectorySeparator(*p)) dir_separator_count++;
1838 }
1839
1840 for (const char* p = file_name; *p; p++) {
1841 if (dir_separator_count == 0) {
1842 AddIsolateIdIfNeeded(os, isolate);
1843 dir_separator_count--;
1844 }
1845 if (*p == '%') {
1846 p++;
1847 switch (*p) {
1848 case '\0':
1849 // If there's a % at the end of the string we back up
1850 // one character so we can escape the loop properly.
1851 p--;
1852 break;
1853 case 'p':
1854 os << base::OS::GetCurrentProcessId();
1855 break;
1856 case 't':
1857 // %t expands to the current time in milliseconds.
1858 os << static_cast<int64_t>(
1859 V8::GetCurrentPlatform()->CurrentClockTimeMillis());
1860 break;
1861 case '%':
1862 // %% expands (contracts really) to %.
1863 os << '%';
1864 break;
1865 default:
1866 // All other %'s expand to themselves.
1867 os << '%' << *p;
1868 break;
1869 }
1870 } else {
1871 if (base::OS::isDirectorySeparator(*p)) dir_separator_count--;
1872 os << *p;
1873 }
1874 }
1875}
1876
1877
1878bool Logger::SetUp(Isolate* isolate) {
1879 // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
1880 if (is_initialized_) return true;
1881 is_initialized_ = true;
1882
1883 std::ostringstream log_file_name;
1884 std::ostringstream source_log_file_name;
1885 PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
1886 log_ = new Log(this, log_file_name.str().c_str());
1887
1888 if (FLAG_perf_basic_prof) {
1889 perf_basic_logger_.reset(new PerfBasicLogger(isolate));
1890 AddCodeEventListener(perf_basic_logger_.get());
1891 }
1892
1893 if (FLAG_perf_prof) {
1894 perf_jit_logger_.reset(new PerfJitLogger(isolate));
1895 AddCodeEventListener(perf_jit_logger_.get());
1896 }
1897
1898 if (FLAG_ll_prof) {
1899 ll_logger_.reset(new LowLevelLogger(isolate, log_file_name.str().c_str()));
1900 AddCodeEventListener(ll_logger_.get());
1901 }
1902
1903 ticker_.reset(new Ticker(isolate, FLAG_prof_sampling_interval));
1904
1905 if (Log::InitLogAtStart()) {
1906 is_logging_ = true;
1907 }
1908
1909 timer_.Start();
1910
1911 if (FLAG_prof_cpp) {
1912 profiler_.reset(new Profiler(isolate));
1913 is_logging_ = true;
1914 profiler_->Engage();
1915 }
1916
1917 if (is_logging_) {
1918 AddCodeEventListener(this);
1919 }
1920
1921 return true;
1922}
1923
1924
1925void Logger::SetCodeEventHandler(uint32_t options,
1926 JitCodeEventHandler event_handler) {
1927 if (jit_logger_) {
1928 RemoveCodeEventListener(jit_logger_.get());
1929 jit_logger_.reset();
1930 }
1931
1932 if (event_handler) {
1933 if (isolate_->wasm_engine() != nullptr) {
1934 isolate_->wasm_engine()->EnableCodeLogging(isolate_);
1935 }
1936 jit_logger_.reset(new JitLogger(isolate_, event_handler));
1937 AddCodeEventListener(jit_logger_.get());
1938 if (options & kJitCodeEventEnumExisting) {
1939 HandleScope scope(isolate_);
1940 LogCodeObjects();
1941 LogCompiledFunctions();
1942 }
1943 }
1944}
1945
1946sampler::Sampler* Logger::sampler() { return ticker_.get(); }
1947
1948void Logger::StopProfilerThread() {
1949 if (profiler_ != nullptr) {
1950 profiler_->Disengage();
1951 profiler_.reset();
1952 }
1953}
1954
1955FILE* Logger::TearDown() {
1956 if (!is_initialized_) return nullptr;
1957 is_initialized_ = false;
1958
1959 // Stop the profiler thread before closing the file.
1960 StopProfilerThread();
1961
1962 ticker_.reset();
1963
1964 if (perf_basic_logger_) {
1965 RemoveCodeEventListener(perf_basic_logger_.get());
1966 perf_basic_logger_.reset();
1967 }
1968
1969 if (perf_jit_logger_) {
1970 RemoveCodeEventListener(perf_jit_logger_.get());
1971 perf_jit_logger_.reset();
1972 }
1973
1974 if (ll_logger_) {
1975 RemoveCodeEventListener(ll_logger_.get());
1976 ll_logger_.reset();
1977 }
1978
1979 if (jit_logger_) {
1980 RemoveCodeEventListener(jit_logger_.get());
1981 jit_logger_.reset();
1982 }
1983
1984 return log_->Close();
1985}
1986
1987void ExistingCodeLogger::LogCodeObject(Object object) {
1988 AbstractCode abstract_code = AbstractCode::cast(object);
1989 CodeEventListener::LogEventsAndTags tag = CodeEventListener::STUB_TAG;
1990 const char* description = "Unknown code from before profiling";
1991 switch (abstract_code->kind()) {
1992 case AbstractCode::INTERPRETED_FUNCTION:
1993 case AbstractCode::OPTIMIZED_FUNCTION:
1994 return; // We log this later using LogCompiledFunctions.
1995 case AbstractCode::BYTECODE_HANDLER:
1996 return; // We log it later by walking the dispatch table.
1997 case AbstractCode::STUB:
1998 description = "STUB code";
1999 tag = CodeEventListener::STUB_TAG;
2000 break;
2001 case AbstractCode::REGEXP:
2002 description = "Regular expression code";
2003 tag = CodeEventListener::REG_EXP_TAG;
2004 break;
2005 case AbstractCode::BUILTIN:
2006 if (Code::cast(object)->is_interpreter_trampoline_builtin() &&
2007 Code::cast(object) !=
2008 *BUILTIN_CODE(isolate_, InterpreterEntryTrampoline)) {
2009 return;
2010 }
2011 description =
2012 isolate_->builtins()->name(abstract_code->GetCode()->builtin_index());
2013 tag = CodeEventListener::BUILTIN_TAG;
2014 break;
2015 case AbstractCode::WASM_FUNCTION:
2016 description = "A Wasm function";
2017 tag = CodeEventListener::FUNCTION_TAG;
2018 break;
2019 case AbstractCode::JS_TO_WASM_FUNCTION:
2020 description = "A JavaScript to Wasm adapter";
2021 tag = CodeEventListener::STUB_TAG;
2022 break;
2023 case AbstractCode::WASM_TO_JS_FUNCTION:
2024 description = "A Wasm to JavaScript adapter";
2025 tag = CodeEventListener::STUB_TAG;
2026 break;
2027 case AbstractCode::WASM_INTERPRETER_ENTRY:
2028 description = "A Wasm to Interpreter adapter";
2029 tag = CodeEventListener::STUB_TAG;
2030 break;
2031 case AbstractCode::C_WASM_ENTRY:
2032 description = "A C to Wasm entry stub";
2033 tag = CodeEventListener::STUB_TAG;
2034 break;
2035 case AbstractCode::NUMBER_OF_KINDS:
2036 UNIMPLEMENTED();
2037 }
2038 CALL_CODE_EVENT_HANDLER(CodeCreateEvent(tag, abstract_code, description))
2039}
2040
2041void ExistingCodeLogger::LogCodeObjects() {
2042 Heap* heap = isolate_->heap();
2043 HeapIterator iterator(heap);
2044 DisallowHeapAllocation no_gc;
2045 for (HeapObject obj = iterator.next(); !obj.is_null();
2046 obj = iterator.next()) {
2047 if (obj->IsCode()) LogCodeObject(obj);
2048 if (obj->IsBytecodeArray()) LogCodeObject(obj);
2049 }
2050}
2051
2052void ExistingCodeLogger::LogCompiledFunctions() {
2053 Heap* heap = isolate_->heap();
2054 HandleScope scope(isolate_);
2055 const int compiled_funcs_count =
2056 EnumerateCompiledFunctions(heap, nullptr, nullptr);
2057 ScopedVector<Handle<SharedFunctionInfo>> sfis(compiled_funcs_count);
2058 ScopedVector<Handle<AbstractCode>> code_objects(compiled_funcs_count);
2059 EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start());
2060
2061 // During iteration, there can be heap allocation due to
2062 // GetScriptLineNumber call.
2063 for (int i = 0; i < compiled_funcs_count; ++i) {
2064 SharedFunctionInfo::EnsureSourcePositionsAvailable(isolate_, sfis[i]);
2065 if (sfis[i]->function_data()->IsInterpreterData()) {
2066 LogExistingFunction(
2067 sfis[i],
2068 Handle<AbstractCode>(
2069 AbstractCode::cast(sfis[i]->InterpreterTrampoline()), isolate_),
2070 CodeEventListener::INTERPRETED_FUNCTION_TAG);
2071 }
2072 if (code_objects[i].is_identical_to(BUILTIN_CODE(isolate_, CompileLazy)))
2073 continue;
2074 LogExistingFunction(sfis[i], code_objects[i]);
2075 }
2076
2077 const int wasm_module_objects_count =
2078 EnumerateWasmModuleObjects(heap, nullptr);
2079 std::unique_ptr<Handle<WasmModuleObject>[]> module_objects(
2080 new Handle<WasmModuleObject>[wasm_module_objects_count]);
2081 EnumerateWasmModuleObjects(heap, module_objects.get());
2082 for (int i = 0; i < wasm_module_objects_count; ++i) {
2083 module_objects[i]->native_module()->LogWasmCodes(isolate_);
2084 }
2085}
2086
2087void ExistingCodeLogger::LogExistingFunction(
2088 Handle<SharedFunctionInfo> shared, Handle<AbstractCode> code,
2089 CodeEventListener::LogEventsAndTags tag) {
2090 if (shared->script()->IsScript()) {
2091 Handle<Script> script(Script::cast(shared->script()), isolate_);
2092 int line_num = Script::GetLineNumber(script, shared->StartPosition()) + 1;
2093 int column_num =
2094 Script::GetColumnNumber(script, shared->StartPosition()) + 1;
2095 if (script->name()->IsString()) {
2096 Handle<String> script_name(String::cast(script->name()), isolate_);
2097 if (line_num > 0) {
2098 CALL_CODE_EVENT_HANDLER(
2099 CodeCreateEvent(Logger::ToNativeByScript(tag, *script), *code,
2100 *shared, *script_name, line_num, column_num))
2101 } else {
2102 // Can't distinguish eval and script here, so always use Script.
2103 CALL_CODE_EVENT_HANDLER(CodeCreateEvent(
2104 Logger::ToNativeByScript(CodeEventListener::SCRIPT_TAG, *script),
2105 *code, *shared, *script_name))
2106 }
2107 } else {
2108 CALL_CODE_EVENT_HANDLER(CodeCreateEvent(
2109 Logger::ToNativeByScript(tag, *script), *code, *shared,
2110 ReadOnlyRoots(isolate_).empty_string(), line_num, column_num))
2111 }
2112 } else if (shared->IsApiFunction()) {
2113 // API function.
2114 FunctionTemplateInfo fun_data = shared->get_api_func_data();
2115 Object raw_call_data = fun_data->call_code();
2116 if (!raw_call_data->IsUndefined(isolate_)) {
2117 CallHandlerInfo call_data = CallHandlerInfo::cast(raw_call_data);
2118 Object callback_obj = call_data->callback();
2119 Address entry_point = v8::ToCData<Address>(callback_obj);
2120#if USES_FUNCTION_DESCRIPTORS
2121 entry_point = *FUNCTION_ENTRYPOINT_ADDRESS(entry_point);
2122#endif
2123 CALL_CODE_EVENT_HANDLER(CallbackEvent(shared->DebugName(), entry_point))
2124 }
2125 }
2126}
2127
2128#undef CALL_CODE_EVENT_HANDLER
2129
2130} // namespace internal
2131} // namespace v8
2132