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