Line data Source code
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 :
41 : namespace v8 {
42 : namespace internal {
43 :
44 : #define DECLARE_EVENT(ignore1, name) #name,
45 : static const char* kLogEventsNames[CodeEventListener::NUMBER_OF_LOG_EVENTS] = {
46 : LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)};
47 : #undef DECLARE_EVENT
48 :
49 20029 : static v8::CodeEventType GetCodeEventTypeForTag(
50 : CodeEventListener::LogEventsAndTags tag) {
51 20029 : 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 19912 : TAGS_LIST(V)
61 : #undef V
62 : }
63 : // The execution should never pass here
64 0 : 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 :
75 488 : static const char* ComputeMarker(SharedFunctionInfo shared, AbstractCode code) {
76 488 : switch (code->kind()) {
77 : case AbstractCode::INTERPRETED_FUNCTION:
78 374 : return shared->optimization_disabled() ? "" : "~";
79 : case AbstractCode::OPTIMIZED_FUNCTION:
80 : return "*";
81 : default:
82 33 : return "";
83 : }
84 : }
85 :
86 : static const char* ComputeMarker(const wasm::WasmCode* code) {
87 0 : switch (code->kind()) {
88 : case wasm::WasmCode::kFunction:
89 0 : return code->is_liftoff() ? "" : "*";
90 : case wasm::WasmCode::kInterpreterEntry:
91 : return "~";
92 : default:
93 : return "";
94 : }
95 : }
96 :
97 : class CodeEventLogger::NameBuffer {
98 : public:
99 : NameBuffer() { Reset(); }
100 :
101 : void Reset() {
102 6087 : utf8_pos_ = 0;
103 : }
104 :
105 5545 : void Init(CodeEventListener::LogEventsAndTags tag) {
106 : Reset();
107 5545 : AppendBytes(kLogEventsNames[tag]);
108 : AppendByte(':');
109 5545 : }
110 :
111 0 : void AppendName(Name name) {
112 0 : if (name->IsString()) {
113 0 : AppendString(String::cast(name));
114 : } else {
115 0 : Symbol symbol = Symbol::cast(name);
116 : AppendBytes("symbol(");
117 0 : if (!symbol->name()->IsUndefined()) {
118 : AppendBytes("\"");
119 0 : AppendString(String::cast(symbol->name()));
120 : AppendBytes("\" ");
121 : }
122 : AppendBytes("hash ");
123 0 : AppendHex(symbol->Hash());
124 : AppendByte(')');
125 : }
126 0 : }
127 :
128 604 : void AppendString(String str) {
129 604 : if (str.is_null()) return;
130 604 : int length = 0;
131 : std::unique_ptr<char[]> c_str =
132 604 : str->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL, &length);
133 1208 : AppendBytes(c_str.get(), length);
134 : }
135 :
136 11694 : void AppendBytes(const char* bytes, int size) {
137 11694 : size = Min(size, kUtf8BufferSize - utf8_pos_);
138 11694 : MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
139 11694 : utf8_pos_ += size;
140 11694 : }
141 :
142 : void AppendBytes(const char* bytes) {
143 11090 : AppendBytes(bytes, StrLength(bytes));
144 : }
145 :
146 : void AppendByte(char c) {
147 6149 : if (utf8_pos_ >= kUtf8BufferSize) return;
148 6125 : utf8_buffer_[utf8_pos_++] = c;
149 : }
150 :
151 302 : void AppendInt(int n) {
152 302 : int space = kUtf8BufferSize - utf8_pos_;
153 314 : if (space <= 0) return;
154 290 : Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
155 290 : int size = SNPrintF(buffer, "%d", n);
156 290 : if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
157 290 : utf8_pos_ += size;
158 : }
159 : }
160 :
161 0 : void AppendHex(uint32_t n) {
162 0 : int space = kUtf8BufferSize - utf8_pos_;
163 0 : if (space <= 0) return;
164 0 : Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
165 0 : int size = SNPrintF(buffer, "%x", n);
166 0 : if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
167 0 : utf8_pos_ += size;
168 : }
169 : }
170 :
171 5545 : 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 :
182 507 : CodeEventLogger::CodeEventLogger(Isolate* isolate)
183 1084 : : isolate_(isolate), name_buffer_(new NameBuffer) {}
184 :
185 1084 : CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }
186 :
187 5243 : void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
188 : AbstractCode code, const char* comment) {
189 5243 : name_buffer_->Init(tag);
190 5243 : name_buffer_->AppendBytes(comment);
191 5243 : LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(),
192 10486 : name_buffer_->size());
193 5243 : }
194 :
195 0 : void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
196 : AbstractCode code, Name name) {
197 0 : name_buffer_->Init(tag);
198 0 : name_buffer_->AppendName(name);
199 0 : LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(),
200 0 : name_buffer_->size());
201 0 : }
202 :
203 0 : void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
204 : AbstractCode code,
205 : SharedFunctionInfo shared, Name name) {
206 0 : name_buffer_->Init(tag);
207 0 : name_buffer_->AppendBytes(ComputeMarker(shared, code));
208 0 : name_buffer_->AppendByte(' ');
209 0 : name_buffer_->AppendName(name);
210 0 : LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
211 0 : }
212 :
213 302 : void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
214 : AbstractCode code,
215 : SharedFunctionInfo shared, Name source,
216 : int line, int column) {
217 302 : name_buffer_->Init(tag);
218 302 : name_buffer_->AppendBytes(ComputeMarker(shared, code));
219 302 : name_buffer_->AppendString(shared->DebugName());
220 302 : name_buffer_->AppendByte(' ');
221 302 : if (source->IsString()) {
222 302 : name_buffer_->AppendString(String::cast(source));
223 : } else {
224 0 : name_buffer_->AppendBytes("symbol(hash ");
225 0 : name_buffer_->AppendHex(Name::cast(source)->Hash());
226 0 : name_buffer_->AppendByte(')');
227 : }
228 302 : name_buffer_->AppendByte(':');
229 302 : name_buffer_->AppendInt(line);
230 604 : LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
231 302 : }
232 :
233 0 : void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag,
234 : const wasm::WasmCode* code,
235 : wasm::WasmName name) {
236 0 : name_buffer_->Init(tag);
237 0 : if (name.empty()) {
238 0 : name_buffer_->AppendBytes("<wasm-unknown>");
239 : } else {
240 0 : name_buffer_->AppendBytes(name.start(), name.length());
241 : }
242 0 : name_buffer_->AppendByte('-');
243 0 : if (code->IsAnonymous()) {
244 0 : name_buffer_->AppendBytes("<anonymous>");
245 : } else {
246 0 : name_buffer_->AppendInt(code->index());
247 : }
248 0 : LogRecordedBuffer(code, name_buffer_->get(), name_buffer_->size());
249 0 : }
250 :
251 0 : void CodeEventLogger::RegExpCodeCreateEvent(AbstractCode code, String source) {
252 0 : name_buffer_->Init(CodeEventListener::REG_EXP_TAG);
253 0 : name_buffer_->AppendString(source);
254 0 : LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(),
255 0 : name_buffer_->size());
256 0 : }
257 :
258 : // Linux perf tool logging support
259 : class PerfBasicLogger : public CodeEventLogger {
260 : public:
261 : explicit PerfBasicLogger(Isolate* isolate);
262 : ~PerfBasicLogger() override;
263 :
264 0 : void CodeMoveEvent(AbstractCode from, AbstractCode to) override {}
265 0 : void CodeDisableOptEvent(AbstractCode code,
266 0 : 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 :
283 : const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
284 : // Extra space for the PID in the filename
285 : const int PerfBasicLogger::kFilenameBufferPadding = 16;
286 :
287 0 : PerfBasicLogger::PerfBasicLogger(Isolate* isolate)
288 0 : : 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 0 : int size = SNPrintF(
293 : perf_dump_name,
294 : kFilenameFormatString,
295 0 : base::OS::GetCurrentProcessId());
296 0 : CHECK_NE(size, -1);
297 : perf_output_handle_ =
298 0 : base::OS::FOpen(perf_dump_name.start(), base::OS::LogFileOpenMode);
299 0 : CHECK_NOT_NULL(perf_output_handle_);
300 0 : setvbuf(perf_output_handle_, nullptr, _IOLBF, 0);
301 0 : }
302 :
303 :
304 0 : PerfBasicLogger::~PerfBasicLogger() {
305 0 : fclose(perf_output_handle_);
306 0 : perf_output_handle_ = nullptr;
307 0 : }
308 :
309 0 : void 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 0 : base::OS::FPrint(perf_output_handle_, "%" V8PRIxPTR " %x %.*s\n", address,
319 0 : size, name_length, name);
320 0 : }
321 :
322 0 : void PerfBasicLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo,
323 : const char* name, int length) {
324 0 : if (FLAG_perf_basic_prof_only_functions &&
325 0 : (code->kind() != AbstractCode::INTERPRETED_FUNCTION &&
326 0 : code->kind() != AbstractCode::BUILTIN &&
327 0 : code->kind() != AbstractCode::OPTIMIZED_FUNCTION)) {
328 : return;
329 : }
330 :
331 0 : WriteLogRecordedBuffer(static_cast<uintptr_t>(code->InstructionStart()),
332 : code->InstructionSize(), name, length);
333 : }
334 :
335 0 : void 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 0 : }
340 :
341 : // External CodeEventListener
342 19 : ExternalCodeEventListener::ExternalCodeEventListener(Isolate* isolate)
343 19 : : is_listening_(false), isolate_(isolate), code_event_handler_(nullptr) {}
344 :
345 57 : ExternalCodeEventListener::~ExternalCodeEventListener() {
346 19 : if (is_listening_) {
347 : StopListening();
348 : }
349 38 : }
350 :
351 19 : void ExternalCodeEventListener::LogExistingCode() {
352 19 : HandleScope scope(isolate_);
353 19 : ExistingCodeLogger logger(isolate_, this);
354 19 : logger.LogCodeObjects();
355 19 : logger.LogCompiledFunctions();
356 19 : }
357 :
358 19 : void ExternalCodeEventListener::StartListening(
359 : CodeEventHandler* code_event_handler) {
360 19 : if (is_listening_ || code_event_handler == nullptr) {
361 : return;
362 : }
363 19 : code_event_handler_ = code_event_handler;
364 38 : is_listening_ = isolate_->code_event_dispatcher()->AddListener(this);
365 19 : if (is_listening_) {
366 19 : LogExistingCode();
367 : }
368 : }
369 :
370 0 : void ExternalCodeEventListener::StopListening() {
371 19 : if (!is_listening_) {
372 : return;
373 : }
374 :
375 38 : isolate_->code_event_dispatcher()->RemoveListener(this);
376 19 : is_listening_ = false;
377 : }
378 :
379 19918 : void ExternalCodeEventListener::CodeCreateEvent(
380 : CodeEventListener::LogEventsAndTags tag, AbstractCode code,
381 : const char* comment) {
382 : CodeEvent code_event;
383 : code_event.code_start_address =
384 19918 : static_cast<uintptr_t>(code->InstructionStart());
385 19918 : code_event.code_size = static_cast<size_t>(code->InstructionSize());
386 39836 : code_event.function_name = isolate_->factory()->empty_string();
387 19918 : code_event.script_name = isolate_->factory()->empty_string();
388 19918 : code_event.script_line = 0;
389 19918 : code_event.script_column = 0;
390 19918 : code_event.code_type = GetCodeEventTypeForTag(tag);
391 19918 : code_event.comment = comment;
392 :
393 19918 : code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
394 19918 : }
395 :
396 0 : void ExternalCodeEventListener::CodeCreateEvent(
397 : CodeEventListener::LogEventsAndTags tag, AbstractCode code, Name name) {
398 : Handle<String> name_string =
399 0 : Name::ToFunctionName(isolate_, Handle<Name>(name, isolate_))
400 : .ToHandleChecked();
401 :
402 : CodeEvent code_event;
403 : code_event.code_start_address =
404 0 : static_cast<uintptr_t>(code->InstructionStart());
405 0 : code_event.code_size = static_cast<size_t>(code->InstructionSize());
406 0 : code_event.function_name = name_string;
407 0 : code_event.script_name = isolate_->factory()->empty_string();
408 0 : code_event.script_line = 0;
409 0 : code_event.script_column = 0;
410 0 : code_event.code_type = GetCodeEventTypeForTag(tag);
411 0 : code_event.comment = "";
412 :
413 0 : code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
414 0 : }
415 :
416 0 : void ExternalCodeEventListener::CodeCreateEvent(
417 : CodeEventListener::LogEventsAndTags tag, AbstractCode code,
418 : SharedFunctionInfo shared, Name name) {
419 : Handle<String> name_string =
420 0 : Name::ToFunctionName(isolate_, Handle<Name>(name, isolate_))
421 : .ToHandleChecked();
422 :
423 : CodeEvent code_event;
424 : code_event.code_start_address =
425 0 : static_cast<uintptr_t>(code->InstructionStart());
426 0 : code_event.code_size = static_cast<size_t>(code->InstructionSize());
427 0 : code_event.function_name = name_string;
428 0 : code_event.script_name = isolate_->factory()->empty_string();
429 0 : code_event.script_line = 0;
430 0 : code_event.script_column = 0;
431 0 : code_event.code_type = GetCodeEventTypeForTag(tag);
432 0 : code_event.comment = "";
433 :
434 0 : code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
435 0 : }
436 :
437 111 : void ExternalCodeEventListener::CodeCreateEvent(
438 : CodeEventListener::LogEventsAndTags tag, AbstractCode code,
439 : SharedFunctionInfo shared, Name source, int line, int column) {
440 : Handle<String> name_string =
441 333 : Name::ToFunctionName(isolate_, Handle<Name>(shared->Name(), isolate_))
442 : .ToHandleChecked();
443 : Handle<String> source_string =
444 333 : Name::ToFunctionName(isolate_, Handle<Name>(source, isolate_))
445 : .ToHandleChecked();
446 :
447 : CodeEvent code_event;
448 : code_event.code_start_address =
449 111 : static_cast<uintptr_t>(code->InstructionStart());
450 111 : code_event.code_size = static_cast<size_t>(code->InstructionSize());
451 111 : code_event.function_name = name_string;
452 111 : code_event.script_name = source_string;
453 111 : code_event.script_line = line;
454 111 : code_event.script_column = column;
455 111 : code_event.code_type = GetCodeEventTypeForTag(tag);
456 111 : code_event.comment = "";
457 :
458 111 : code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
459 111 : }
460 :
461 0 : void ExternalCodeEventListener::CodeCreateEvent(LogEventsAndTags tag,
462 : const wasm::WasmCode* code,
463 : wasm::WasmName name) {
464 : // TODO(mmarchini): handle later
465 0 : }
466 :
467 0 : void ExternalCodeEventListener::RegExpCodeCreateEvent(AbstractCode code,
468 : String source) {
469 : CodeEvent code_event;
470 : code_event.code_start_address =
471 0 : static_cast<uintptr_t>(code->InstructionStart());
472 0 : code_event.code_size = static_cast<size_t>(code->InstructionSize());
473 0 : code_event.function_name = Handle<String>(source, isolate_);
474 0 : code_event.script_name = isolate_->factory()->empty_string();
475 0 : code_event.script_line = 0;
476 0 : code_event.script_column = 0;
477 0 : code_event.code_type = GetCodeEventTypeForTag(CodeEventListener::REG_EXP_TAG);
478 0 : code_event.comment = "";
479 :
480 0 : code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
481 0 : }
482 :
483 : // Low-level logging support.
484 : class 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 0 : void CodeDisableOptEvent(AbstractCode code,
491 0 : 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 0 : void LogWriteStruct(const T& s) {
530 0 : char tag = T::kTag;
531 : LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag));
532 : LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
533 0 : }
534 :
535 : FILE* ll_output_handle_;
536 : };
537 :
538 : const char LowLevelLogger::kLogExt[] = ".ll";
539 :
540 0 : LowLevelLogger::LowLevelLogger(Isolate* isolate, const char* name)
541 0 : : CodeEventLogger(isolate), ll_output_handle_(nullptr) {
542 : // Open the low-level log file.
543 0 : size_t len = strlen(name);
544 0 : ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt)));
545 : MemCopy(ll_name.start(), name, len);
546 0 : MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
547 : ll_output_handle_ =
548 0 : base::OS::FOpen(ll_name.start(), base::OS::LogFileOpenMode);
549 0 : setvbuf(ll_output_handle_, nullptr, _IOLBF, 0);
550 :
551 : LogCodeInfo();
552 0 : }
553 :
554 :
555 0 : LowLevelLogger::~LowLevelLogger() {
556 0 : fclose(ll_output_handle_);
557 0 : ll_output_handle_ = nullptr;
558 0 : }
559 :
560 :
561 0 : void 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 0 : 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 0 : }
581 :
582 0 : void LowLevelLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo,
583 : const char* name, int length) {
584 : CodeCreateStruct event;
585 0 : event.name_size = length;
586 0 : event.code_address = code->InstructionStart();
587 0 : event.code_size = code->InstructionSize();
588 0 : LogWriteStruct(event);
589 : LogWriteBytes(name, length);
590 0 : LogWriteBytes(reinterpret_cast<const char*>(code->InstructionStart()),
591 : code->InstructionSize());
592 0 : }
593 :
594 0 : void LowLevelLogger::LogRecordedBuffer(const wasm::WasmCode* code,
595 : const char* name, int length) {
596 : CodeCreateStruct event;
597 0 : event.name_size = length;
598 0 : event.code_address = code->instruction_start();
599 0 : event.code_size = code->instructions().length();
600 0 : LogWriteStruct(event);
601 : LogWriteBytes(name, length);
602 : LogWriteBytes(reinterpret_cast<const char*>(code->instruction_start()),
603 : code->instructions().length());
604 0 : }
605 :
606 0 : void LowLevelLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) {
607 : CodeMoveStruct event;
608 0 : event.from_address = from->InstructionStart();
609 0 : event.to_address = to->InstructionStart();
610 0 : LogWriteStruct(event);
611 0 : }
612 :
613 0 : void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
614 0 : size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
615 : DCHECK(static_cast<size_t>(size) == rv);
616 : USE(rv);
617 0 : }
618 :
619 :
620 0 : void LowLevelLogger::CodeMovingGCEvent() {
621 0 : const char tag = kCodeMovingGCTag;
622 :
623 : LogWriteBytes(&tag, sizeof(tag));
624 0 : }
625 :
626 70 : class JitLogger : public CodeEventLogger {
627 : public:
628 : JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler);
629 :
630 : void CodeMoveEvent(AbstractCode from, AbstractCode to) override;
631 10 : void CodeDisableOptEvent(AbstractCode code,
632 10 : 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 :
650 35 : JitLogger::JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler)
651 35 : : CodeEventLogger(isolate), code_event_handler_(code_event_handler) {}
652 :
653 5516 : void 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 5516 : event.code_start = reinterpret_cast<void*>(code->InstructionStart());
659 : event.code_type =
660 5516 : code->IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE;
661 5516 : event.code_len = code->InstructionSize();
662 : Handle<SharedFunctionInfo> shared_function_handle;
663 5789 : if (!shared.is_null() && shared->script()->IsScript()) {
664 : shared_function_handle =
665 : Handle<SharedFunctionInfo>(shared, shared->GetIsolate());
666 : }
667 5516 : event.script = ToApiHandle<v8::UnboundScript>(shared_function_handle);
668 5516 : event.name.str = name;
669 5516 : event.name.len = length;
670 5516 : event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
671 5516 : code_event_handler_(&event);
672 5516 : }
673 :
674 0 : void 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 0 : event.code_type = JitCodeEvent::JIT_CODE;
680 0 : event.code_start = code->instructions().start();
681 0 : event.code_len = code->instructions().length();
682 0 : event.name.str = name;
683 0 : event.name.len = length;
684 0 : event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
685 0 : code_event_handler_(&event);
686 0 : }
687 :
688 189 : void JitLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) {
689 189 : base::MutexGuard guard(&logger_mutex_);
690 :
691 : JitCodeEvent event;
692 189 : event.type = JitCodeEvent::CODE_MOVED;
693 : event.code_type =
694 189 : from->IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE;
695 189 : event.code_start = reinterpret_cast<void*>(from->InstructionStart());
696 189 : event.code_len = from->InstructionSize();
697 189 : event.new_code_start = reinterpret_cast<void*>(to->InstructionStart());
698 189 : event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
699 :
700 189 : code_event_handler_(&event);
701 189 : }
702 :
703 2161 : void 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 2161 : event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO;
711 2161 : event.user_data = jit_handler_data;
712 2161 : event.line_info.offset = pc_offset;
713 2161 : event.line_info.pos = position;
714 2161 : event.line_info.position_type = position_type;
715 2161 : event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
716 :
717 2161 : code_event_handler_(&event);
718 2161 : }
719 :
720 :
721 230 : void* JitLogger::StartCodePosInfoEvent() {
722 : JitCodeEvent event;
723 : memset(static_cast<void*>(&event), 0, sizeof(event));
724 230 : event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING;
725 230 : event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
726 :
727 230 : code_event_handler_(&event);
728 230 : return event.user_data;
729 : }
730 :
731 230 : void JitLogger::EndCodePosInfoEvent(Address start_address,
732 : void* jit_handler_data) {
733 : JitCodeEvent event;
734 : memset(static_cast<void*>(&event), 0, sizeof(event));
735 230 : event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING;
736 230 : event.code_start = reinterpret_cast<void*>(start_address);
737 230 : event.user_data = jit_handler_data;
738 230 : event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
739 :
740 230 : code_event_handler_(&event);
741 230 : }
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.
747 62427 : class 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 62442 : interval_microseconds_(interval_microseconds) {}
756 0 : void Run() override {
757 0 : while (sampler_->IsActive()) {
758 0 : sampler_->DoSample();
759 0 : base::OS::Sleep(
760 0 : base::TimeDelta::FromMicroseconds(interval_microseconds_));
761 : }
762 0 : }
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 : //
775 0 : class 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 0 : void Insert(v8::TickSample* sample) {
783 0 : if (Succ(head_) == static_cast<int>(base::Relaxed_Load(&tail_))) {
784 0 : overflow_ = true;
785 : } else {
786 0 : buffer_[head_] = *sample;
787 0 : head_ = Succ(head_);
788 0 : buffer_semaphore_.Signal(); // Tell we have an element.
789 : }
790 0 : }
791 :
792 : void Run() override;
793 :
794 : private:
795 : // Waits for a signal and removes profiling data.
796 0 : bool Remove(v8::TickSample* sample) {
797 0 : buffer_semaphore_.Wait(); // Wait for an element.
798 0 : *sample = buffer_[base::Relaxed_Load(&tail_)];
799 0 : bool result = overflow_;
800 : base::Relaxed_Store(
801 : &tail_, static_cast<base::Atomic32>(Succ(base::Relaxed_Load(&tail_))));
802 0 : overflow_ = false;
803 0 : return result;
804 : }
805 :
806 : // Returns the next index in the cyclic buffer.
807 0 : 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 : //
829 : class Ticker: public sampler::Sampler {
830 : public:
831 62442 : Ticker(Isolate* isolate, int interval_microseconds)
832 : : sampler::Sampler(reinterpret_cast<v8::Isolate*>(isolate)),
833 : sampling_thread_(
834 62442 : base::make_unique<SamplingThread>(this, interval_microseconds)) {}
835 :
836 187281 : ~Ticker() override {
837 62427 : if (IsActive()) Stop();
838 124854 : }
839 :
840 0 : void SetProfiler(Profiler* profiler) {
841 : DCHECK_NULL(profiler_);
842 0 : profiler_ = profiler;
843 0 : if (!IsActive()) Start();
844 0 : sampling_thread_->StartSynchronously();
845 0 : }
846 :
847 0 : void ClearProfiler() {
848 0 : profiler_ = nullptr;
849 0 : if (IsActive()) Stop();
850 0 : sampling_thread_->Join();
851 0 : }
852 :
853 0 : void SampleStack(const v8::RegisterState& state) override {
854 0 : if (!profiler_) return;
855 : Isolate* isolate = reinterpret_cast<Isolate*>(this->isolate());
856 : TickSample sample;
857 0 : sample.Init(isolate, state, TickSample::kIncludeCEntryFrame, true);
858 0 : 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 : //
869 0 : Profiler::Profiler(Isolate* isolate)
870 : : base::Thread(Options("v8:Profiler")),
871 : isolate_(isolate),
872 : head_(0),
873 : overflow_(false),
874 0 : buffer_semaphore_(0) {
875 0 : base::Relaxed_Store(&tail_, 0);
876 0 : base::Relaxed_Store(&running_, 0);
877 0 : }
878 :
879 0 : void Profiler::Engage() {
880 : std::vector<base::OS::SharedLibraryAddress> addresses =
881 0 : base::OS::GetSharedLibraryAddresses();
882 0 : for (const auto& address : addresses) {
883 0 : LOG(isolate_, SharedLibraryEvent(address.library_path, address.start,
884 : address.end, address.aslr_slide));
885 : }
886 :
887 : // Start thread processing the profiler buffer.
888 0 : base::Relaxed_Store(&running_, 1);
889 0 : Start();
890 :
891 : // Register to get ticks.
892 0 : Logger* logger = isolate_->logger();
893 0 : logger->ticker_->SetProfiler(this);
894 :
895 0 : logger->ProfilerBeginEvent();
896 0 : }
897 :
898 :
899 0 : void Profiler::Disengage() {
900 : // Stop receiving ticks.
901 0 : 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 0 : base::Relaxed_Store(&running_, 0);
907 : v8::TickSample sample;
908 0 : Insert(&sample);
909 0 : Join();
910 :
911 0 : LOG(isolate_, UncheckedStringEvent("profiler", "end"));
912 0 : }
913 :
914 :
915 0 : void Profiler::Run() {
916 : v8::TickSample sample;
917 0 : bool overflow = Remove(&sample);
918 0 : while (base::Relaxed_Load(&running_)) {
919 0 : LOG(isolate_, TickEvent(&sample, overflow));
920 0 : overflow = Remove(&sample);
921 : }
922 0 : }
923 :
924 :
925 : //
926 : // Logger class implementation.
927 : //
928 :
929 62439 : Logger::Logger(Isolate* isolate)
930 : : isolate_(isolate),
931 : log_events_(nullptr),
932 : is_logging_(false),
933 : log_(nullptr),
934 : is_initialized_(false),
935 249756 : existing_code_logger_(isolate) {}
936 :
937 187281 : Logger::~Logger() {
938 124854 : delete log_;
939 124854 : }
940 :
941 : const LogSeparator Logger::kNext = LogSeparator::kSeparator;
942 :
943 1389 : void Logger::AddCodeEventListener(CodeEventListener* listener) {
944 2778 : bool result = isolate_->code_event_dispatcher()->AddListener(listener);
945 1389 : CHECK(result);
946 1389 : }
947 :
948 1290 : void Logger::RemoveCodeEventListener(CodeEventListener* listener) {
949 2650 : isolate_->code_event_dispatcher()->RemoveListener(listener);
950 1290 : }
951 :
952 0 : void Logger::ProfilerBeginEvent() {
953 0 : if (!log_->IsEnabled()) return;
954 0 : Log::MessageBuilder msg(log_);
955 0 : msg << "profiler" << kNext << "begin" << kNext << FLAG_prof_sampling_interval;
956 0 : msg.WriteToLogFile();
957 : }
958 :
959 :
960 0 : void Logger::StringEvent(const char* name, const char* value) {
961 0 : if (FLAG_log) UncheckedStringEvent(name, value);
962 0 : }
963 :
964 :
965 0 : void Logger::UncheckedStringEvent(const char* name, const char* value) {
966 0 : if (!log_->IsEnabled()) return;
967 0 : Log::MessageBuilder msg(log_);
968 0 : msg << name << kNext << value;
969 0 : msg.WriteToLogFile();
970 : }
971 :
972 :
973 118 : void Logger::IntPtrTEvent(const char* name, intptr_t value) {
974 118 : if (FLAG_log) UncheckedIntPtrTEvent(name, value);
975 118 : }
976 :
977 :
978 118 : void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
979 236 : if (!log_->IsEnabled()) return;
980 118 : Log::MessageBuilder msg(log_);
981 118 : msg << name << kNext;
982 118 : msg.AppendFormatString("%" V8PRIdPTR, value);
983 118 : msg.WriteToLogFile();
984 : }
985 :
986 0 : void Logger::HandleEvent(const char* name, Address* location) {
987 0 : if (!log_->IsEnabled() || !FLAG_log_handles) return;
988 0 : Log::MessageBuilder msg(log_);
989 0 : msg << name << kNext << reinterpret_cast<void*>(location);
990 0 : msg.WriteToLogFile();
991 : }
992 :
993 :
994 0 : void Logger::ApiSecurityCheck() {
995 0 : if (!log_->IsEnabled() || !FLAG_log_api) return;
996 0 : Log::MessageBuilder msg(log_);
997 0 : msg << "api" << kNext << "check-security";
998 0 : msg.WriteToLogFile();
999 : }
1000 :
1001 0 : void Logger::SharedLibraryEvent(const std::string& library_path,
1002 : uintptr_t start, uintptr_t end,
1003 : intptr_t aslr_slide) {
1004 0 : if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
1005 0 : Log::MessageBuilder msg(log_);
1006 0 : msg << "shared-library" << kNext << library_path.c_str() << kNext
1007 0 : << reinterpret_cast<void*>(start) << kNext << reinterpret_cast<void*>(end)
1008 0 : << kNext << aslr_slide;
1009 0 : msg.WriteToLogFile();
1010 : }
1011 :
1012 6 : void Logger::CodeDeoptEvent(Code code, DeoptimizeKind kind, Address pc,
1013 : int fp_to_sp_delta) {
1014 12 : if (!log_->IsEnabled()) return;
1015 6 : Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc);
1016 6 : Log::MessageBuilder msg(log_);
1017 18 : msg << "code-deopt" << kNext << timer_.Elapsed().InMicroseconds() << kNext
1018 6 : << code->CodeSize() << kNext
1019 12 : << reinterpret_cast<void*>(code->InstructionStart());
1020 :
1021 : // Deoptimization position.
1022 12 : std::ostringstream deopt_location;
1023 : int inlining_id = -1;
1024 : int script_offset = -1;
1025 6 : if (info.position.IsKnown()) {
1026 6 : info.position.Print(deopt_location, code);
1027 : inlining_id = info.position.InliningId();
1028 : script_offset = info.position.ScriptOffset();
1029 : } else {
1030 0 : deopt_location << "<unknown>";
1031 : }
1032 18 : msg << kNext << inlining_id << kNext << script_offset << kNext;
1033 6 : msg << Deoptimizer::MessageFor(kind) << kNext;
1034 12 : msg << deopt_location.str().c_str() << kNext
1035 12 : << DeoptimizeReasonToString(info.deopt_reason);
1036 6 : msg.WriteToLogFile();
1037 : }
1038 :
1039 :
1040 0 : void Logger::CurrentTimeEvent() {
1041 0 : if (!log_->IsEnabled()) return;
1042 : DCHECK(FLAG_log_internal_timer_events);
1043 0 : Log::MessageBuilder msg(log_);
1044 0 : msg << "current-time" << kNext << timer_.Elapsed().InMicroseconds();
1045 0 : msg.WriteToLogFile();
1046 : }
1047 :
1048 :
1049 449 : void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
1050 898 : if (!log_->IsEnabled()) return;
1051 449 : Log::MessageBuilder msg(log_);
1052 449 : switch (se) {
1053 : case START:
1054 217 : msg << "timer-event-start";
1055 217 : break;
1056 : case END:
1057 217 : msg << "timer-event-end";
1058 217 : break;
1059 : case STAMP:
1060 15 : msg << "timer-event";
1061 : }
1062 898 : msg << kNext << name << kNext << timer_.Elapsed().InMicroseconds();
1063 449 : msg.WriteToLogFile();
1064 : }
1065 :
1066 : // static
1067 0 : void Logger::EnterExternal(Isolate* isolate) {
1068 : DCHECK(FLAG_log_internal_timer_events);
1069 0 : LOG(isolate, TimerEvent(START, TimerEventExternal::name()));
1070 : DCHECK(isolate->current_vm_state() == JS);
1071 : isolate->set_current_vm_state(EXTERNAL);
1072 0 : }
1073 :
1074 : // static
1075 0 : void Logger::LeaveExternal(Isolate* isolate) {
1076 : DCHECK(FLAG_log_internal_timer_events);
1077 0 : LOG(isolate, TimerEvent(END, TimerEventExternal::name()));
1078 : DCHECK(isolate->current_vm_state() == EXTERNAL);
1079 : isolate->set_current_vm_state(JS);
1080 0 : }
1081 :
1082 : // Instantiate template methods.
1083 : #define V(TimerName, expose) \
1084 : template void TimerEventScope<TimerEvent##TimerName>::LogTimerEvent( \
1085 : Logger::StartEnd se);
1086 : TIMER_EVENTS_LIST(V)
1087 : #undef V
1088 :
1089 0 : void Logger::ApiNamedPropertyAccess(const char* tag, JSObject holder,
1090 : Object property_name) {
1091 : DCHECK(property_name->IsName());
1092 0 : if (!log_->IsEnabled() || !FLAG_log_api) return;
1093 0 : Log::MessageBuilder msg(log_);
1094 0 : msg << "api" << kNext << tag << kNext << holder->class_name() << kNext
1095 0 : << Name::cast(property_name);
1096 0 : msg.WriteToLogFile();
1097 : }
1098 :
1099 0 : void Logger::ApiIndexedPropertyAccess(const char* tag, JSObject holder,
1100 : uint32_t index) {
1101 0 : if (!log_->IsEnabled() || !FLAG_log_api) return;
1102 0 : Log::MessageBuilder msg(log_);
1103 0 : msg << "api" << kNext << tag << kNext << holder->class_name() << kNext
1104 : << index;
1105 0 : msg.WriteToLogFile();
1106 : }
1107 :
1108 0 : void Logger::ApiObjectAccess(const char* tag, JSObject object) {
1109 0 : if (!log_->IsEnabled() || !FLAG_log_api) return;
1110 0 : Log::MessageBuilder msg(log_);
1111 0 : msg << "api" << kNext << tag << kNext << object->class_name();
1112 0 : msg.WriteToLogFile();
1113 : }
1114 :
1115 1689 : void Logger::ApiEntryCall(const char* name) {
1116 4943 : if (!log_->IsEnabled() || !FLAG_log_api) return;
1117 124 : Log::MessageBuilder msg(log_);
1118 124 : msg << "api" << kNext << name;
1119 124 : msg.WriteToLogFile();
1120 : }
1121 :
1122 :
1123 785 : void Logger::NewEvent(const char* name, void* object, size_t size) {
1124 1570 : if (!log_->IsEnabled() || !FLAG_log) return;
1125 785 : Log::MessageBuilder msg(log_);
1126 785 : msg << "new" << kNext << name << kNext << object << kNext
1127 : << static_cast<unsigned int>(size);
1128 785 : msg.WriteToLogFile();
1129 : }
1130 :
1131 :
1132 775 : void Logger::DeleteEvent(const char* name, void* object) {
1133 2322 : if (!log_->IsEnabled() || !FLAG_log) return;
1134 3 : Log::MessageBuilder msg(log_);
1135 3 : msg << "delete" << kNext << name << kNext << object;
1136 3 : msg.WriteToLogFile();
1137 : }
1138 :
1139 382 : void Logger::CallbackEventInternal(const char* prefix, Name name,
1140 : Address entry_point) {
1141 764 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1142 382 : Log::MessageBuilder msg(log_);
1143 382 : msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << kNext
1144 764 : << kLogEventsNames[CodeEventListener::CALLBACK_TAG] << kNext << -2
1145 1528 : << kNext << timer_.Elapsed().InMicroseconds() << kNext
1146 1146 : << reinterpret_cast<void*>(entry_point) << kNext << 1 << kNext << prefix
1147 382 : << name;
1148 382 : msg.WriteToLogFile();
1149 : }
1150 :
1151 257 : void Logger::CallbackEvent(Name name, Address entry_point) {
1152 257 : CallbackEventInternal("", name, entry_point);
1153 257 : }
1154 :
1155 65 : void Logger::GetterCallbackEvent(Name name, Address entry_point) {
1156 65 : CallbackEventInternal("get ", name, entry_point);
1157 65 : }
1158 :
1159 60 : void Logger::SetterCallbackEvent(Name name, Address entry_point) {
1160 60 : CallbackEventInternal("set ", name, entry_point);
1161 60 : }
1162 :
1163 : namespace {
1164 :
1165 5426 : void AppendCodeCreateHeader(Log::MessageBuilder& msg,
1166 : CodeEventListener::LogEventsAndTags tag,
1167 : AbstractCode::Kind kind, uint8_t* address, int size,
1168 : base::ElapsedTimer* timer) {
1169 5426 : msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT]
1170 10852 : << Logger::kNext << kLogEventsNames[tag] << Logger::kNext << kind
1171 21704 : << Logger::kNext << timer->Elapsed().InMicroseconds() << Logger::kNext
1172 5426 : << reinterpret_cast<void*>(address) << Logger::kNext << size
1173 5426 : << Logger::kNext;
1174 5426 : }
1175 :
1176 5426 : void AppendCodeCreateHeader(Log::MessageBuilder& msg,
1177 : CodeEventListener::LogEventsAndTags tag,
1178 : AbstractCode code, base::ElapsedTimer* timer) {
1179 10852 : AppendCodeCreateHeader(msg, tag, code->kind(),
1180 5426 : reinterpret_cast<uint8_t*>(code->InstructionStart()),
1181 5426 : code->InstructionSize(), timer);
1182 5426 : }
1183 :
1184 : } // namespace
1185 :
1186 5240 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1187 : AbstractCode code, const char* comment) {
1188 5240 : if (!is_listening_to_code_events()) return;
1189 10480 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1190 5240 : Log::MessageBuilder msg(log_);
1191 5240 : AppendCodeCreateHeader(msg, tag, code, &timer_);
1192 5240 : msg << comment;
1193 5240 : msg.WriteToLogFile();
1194 : }
1195 :
1196 0 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1197 : AbstractCode code, Name name) {
1198 0 : if (!is_listening_to_code_events()) return;
1199 0 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1200 0 : Log::MessageBuilder msg(log_);
1201 0 : AppendCodeCreateHeader(msg, tag, code, &timer_);
1202 0 : msg << name;
1203 0 : msg.WriteToLogFile();
1204 : }
1205 :
1206 0 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1207 : AbstractCode code, SharedFunctionInfo shared,
1208 : Name name) {
1209 0 : if (!is_listening_to_code_events()) return;
1210 0 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1211 0 : if (code == AbstractCode::cast(
1212 0 : isolate_->builtins()->builtin(Builtins::kCompileLazy))) {
1213 : return;
1214 : }
1215 :
1216 0 : Log::MessageBuilder msg(log_);
1217 0 : AppendCodeCreateHeader(msg, tag, code, &timer_);
1218 0 : msg << name << kNext << reinterpret_cast<void*>(shared->address()) << kNext
1219 0 : << ComputeMarker(shared, code);
1220 0 : msg.WriteToLogFile();
1221 : }
1222 :
1223 0 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1224 : const wasm::WasmCode* code, wasm::WasmName name) {
1225 0 : if (!is_listening_to_code_events()) return;
1226 0 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1227 0 : Log::MessageBuilder msg(log_);
1228 0 : AppendCodeCreateHeader(msg, tag, AbstractCode::Kind::WASM_FUNCTION,
1229 : code->instructions().start(),
1230 0 : code->instructions().length(), &timer_);
1231 0 : if (name.empty()) {
1232 0 : msg << "<unknown wasm>";
1233 : } else {
1234 0 : 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 0 : reinterpret_cast<byte*>(code->native_module()) + code->index();
1243 0 : msg << kNext << tag_ptr << kNext << ComputeMarker(code);
1244 0 : 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.
1250 186 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1251 : AbstractCode code, SharedFunctionInfo shared,
1252 : Name source, int line, int column) {
1253 372 : if (!is_listening_to_code_events()) return;
1254 372 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1255 : {
1256 186 : Log::MessageBuilder msg(log_);
1257 186 : AppendCodeCreateHeader(msg, tag, code, &timer_);
1258 372 : msg << shared->DebugName() << " " << source << ":" << line << ":" << column
1259 372 : << kNext << reinterpret_cast<void*>(shared->address()) << kNext
1260 372 : << ComputeMarker(shared, code);
1261 186 : msg.WriteToLogFile();
1262 : }
1263 :
1264 186 : if (!FLAG_log_source_code) return;
1265 0 : Object script_object = shared->script();
1266 0 : if (!script_object->IsScript()) return;
1267 : Script script = Script::cast(script_object);
1268 0 : 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 0 : Log::MessageBuilder msg(log_);
1292 0 : msg << "code-source-info" << kNext
1293 0 : << reinterpret_cast<void*>(code->InstructionStart()) << kNext
1294 0 : << script->id() << kNext << shared->StartPosition() << kNext
1295 0 : << shared->EndPosition() << kNext;
1296 :
1297 0 : SourcePositionTableIterator iterator(code->source_position_table());
1298 : bool hasInlined = false;
1299 0 : for (; !iterator.done(); iterator.Advance()) {
1300 : SourcePosition pos = iterator.source_position();
1301 0 : msg << "C" << iterator.code_offset() << "O" << pos.ScriptOffset();
1302 0 : if (pos.isInlined()) {
1303 0 : msg << "I" << pos.InliningId();
1304 : hasInlined = true;
1305 : }
1306 : }
1307 0 : msg << kNext;
1308 : int maxInlinedId = -1;
1309 0 : if (hasInlined) {
1310 : PodArray<InliningPosition> inlining_positions =
1311 0 : DeoptimizationData::cast(Code::cast(code)->deoptimization_data())
1312 0 : ->InliningPositions();
1313 0 : for (int i = 0; i < inlining_positions->length(); i++) {
1314 : InliningPosition inlining_pos = inlining_positions->get(i);
1315 0 : msg << "F";
1316 0 : if (inlining_pos.inlined_function_id != -1) {
1317 : msg << inlining_pos.inlined_function_id;
1318 0 : if (inlining_pos.inlined_function_id > maxInlinedId) {
1319 : maxInlinedId = inlining_pos.inlined_function_id;
1320 : }
1321 : }
1322 : SourcePosition pos = inlining_pos.position;
1323 0 : msg << "O" << pos.ScriptOffset();
1324 0 : if (pos.isInlined()) {
1325 0 : msg << "I" << pos.InliningId();
1326 : }
1327 : }
1328 : }
1329 0 : msg << kNext;
1330 0 : if (hasInlined) {
1331 : DeoptimizationData deopt_data =
1332 0 : DeoptimizationData::cast(Code::cast(code)->deoptimization_data());
1333 :
1334 : msg << std::hex;
1335 0 : for (int i = 0; i <= maxInlinedId; i++) {
1336 0 : msg << "S"
1337 : << reinterpret_cast<void*>(
1338 0 : deopt_data->GetInlinedFunction(i)->address());
1339 : }
1340 : msg << std::dec;
1341 : }
1342 0 : msg.WriteToLogFile();
1343 : }
1344 :
1345 1 : void Logger::CodeDisableOptEvent(AbstractCode code, SharedFunctionInfo shared) {
1346 1 : if (!is_listening_to_code_events()) return;
1347 2 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1348 1 : Log::MessageBuilder msg(log_);
1349 1 : msg << kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT] << kNext
1350 2 : << shared->DebugName() << kNext
1351 2 : << GetBailoutReason(shared->disable_optimization_reason());
1352 1 : msg.WriteToLogFile();
1353 : }
1354 :
1355 16 : void Logger::CodeMovingGCEvent() {
1356 16 : if (!is_listening_to_code_events()) return;
1357 32 : if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1358 0 : base::OS::SignalCodeMovingGC();
1359 : }
1360 :
1361 0 : void Logger::RegExpCodeCreateEvent(AbstractCode code, String source) {
1362 0 : if (!is_listening_to_code_events()) return;
1363 0 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1364 0 : Log::MessageBuilder msg(log_);
1365 0 : AppendCodeCreateHeader(msg, CodeEventListener::REG_EXP_TAG, code, &timer_);
1366 0 : msg << source;
1367 0 : msg.WriteToLogFile();
1368 : }
1369 :
1370 0 : void Logger::CodeMoveEvent(AbstractCode from, AbstractCode to) {
1371 0 : if (!is_listening_to_code_events()) return;
1372 : MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(),
1373 0 : to->address());
1374 : }
1375 :
1376 : namespace {
1377 :
1378 375 : void CodeLinePosEvent(JitLogger* jit_logger, Address code_start,
1379 : SourcePositionTableIterator& iter) {
1380 375 : if (jit_logger) {
1381 230 : void* jit_handler_data = jit_logger->StartCodePosInfoEvent();
1382 3202 : for (; !iter.done(); iter.Advance()) {
1383 1486 : if (iter.is_statement()) {
1384 : jit_logger->AddCodeLinePosInfoEvent(
1385 : jit_handler_data, iter.code_offset(),
1386 : iter.source_position().ScriptOffset(),
1387 675 : JitCodeEvent::STATEMENT_POSITION);
1388 : }
1389 : jit_logger->AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(),
1390 : iter.source_position().ScriptOffset(),
1391 1486 : JitCodeEvent::POSITION);
1392 : }
1393 230 : jit_logger->EndCodePosInfoEvent(code_start, jit_handler_data);
1394 : }
1395 375 : }
1396 :
1397 : } // namespace
1398 :
1399 375 : void Logger::CodeLinePosInfoRecordEvent(Address code_start,
1400 : ByteArray source_position_table) {
1401 375 : SourcePositionTableIterator iter(source_position_table);
1402 375 : CodeLinePosEvent(jit_logger_.get(), code_start, iter);
1403 375 : }
1404 :
1405 0 : void Logger::CodeLinePosInfoRecordEvent(
1406 : Address code_start, Vector<const byte> source_position_table) {
1407 0 : SourcePositionTableIterator iter(source_position_table);
1408 0 : CodeLinePosEvent(jit_logger_.get(), code_start, iter);
1409 0 : }
1410 :
1411 0 : void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
1412 0 : if (code_name == nullptr) return; // Not a code object.
1413 0 : Log::MessageBuilder msg(log_);
1414 0 : msg << kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT] << kNext
1415 0 : << pos << kNext << code_name;
1416 0 : msg.WriteToLogFile();
1417 : }
1418 :
1419 :
1420 2049 : void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1421 2049 : if (!is_listening_to_code_events()) return;
1422 2050 : MoveEventInternal(CodeEventListener::SHARED_FUNC_MOVE_EVENT, from, to);
1423 : }
1424 :
1425 2050 : void Logger::MoveEventInternal(CodeEventListener::LogEventsAndTags event,
1426 : Address from, Address to) {
1427 4100 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1428 0 : Log::MessageBuilder msg(log_);
1429 0 : msg << kLogEventsNames[event] << kNext << reinterpret_cast<void*>(from)
1430 0 : << kNext << reinterpret_cast<void*>(to);
1431 0 : msg.WriteToLogFile();
1432 : }
1433 :
1434 :
1435 48 : void Logger::ResourceEvent(const char* name, const char* tag) {
1436 96 : if (!log_->IsEnabled() || !FLAG_log) return;
1437 48 : Log::MessageBuilder msg(log_);
1438 48 : msg << name << kNext << tag << kNext;
1439 :
1440 : uint32_t sec, usec;
1441 48 : if (base::OS::GetUserTime(&sec, &usec) != -1) {
1442 144 : msg << sec << kNext << usec << kNext;
1443 : }
1444 48 : msg.AppendFormatString("%.0f",
1445 96 : V8::GetCurrentPlatform()->CurrentClockTimeMillis());
1446 48 : msg.WriteToLogFile();
1447 : }
1448 :
1449 0 : void Logger::SuspectReadEvent(Name name, Object obj) {
1450 0 : if (!log_->IsEnabled() || !FLAG_log_suspect) return;
1451 0 : Log::MessageBuilder msg(log_);
1452 : String class_name = obj->IsJSObject()
1453 0 : ? JSObject::cast(obj)->class_name()
1454 0 : : ReadOnlyRoots(isolate_).empty_string();
1455 0 : msg << "suspect-read" << kNext << class_name << kNext << name;
1456 0 : msg.WriteToLogFile();
1457 : }
1458 :
1459 : namespace {
1460 196 : void 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 196 : msg << "function" << Logger::kNext << reason << Logger::kNext << script_id
1464 392 : << Logger::kNext << start_position << Logger::kNext << end_position
1465 392 : << Logger::kNext << time_delta << Logger::kNext
1466 392 : << timer->Elapsed().InMicroseconds() << Logger::kNext;
1467 196 : }
1468 : } // namespace
1469 :
1470 92 : void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
1471 : int start_position, int end_position,
1472 : String function_name) {
1473 184 : if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1474 92 : Log::MessageBuilder msg(log_);
1475 92 : AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
1476 92 : end_position, &timer_);
1477 92 : if (!function_name.is_null()) msg << function_name;
1478 92 : msg.WriteToLogFile();
1479 : }
1480 :
1481 104 : void 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 208 : if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1486 104 : Log::MessageBuilder msg(log_);
1487 104 : AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
1488 104 : end_position, &timer_);
1489 104 : if (function_name_length > 0) {
1490 72 : msg.AppendString(function_name, function_name_length);
1491 : }
1492 104 : msg.WriteToLogFile();
1493 : }
1494 :
1495 51 : void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
1496 : SharedFunctionInfo sfi) {
1497 142 : if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1498 11 : Log::MessageBuilder msg(log_);
1499 : int script_id = -1;
1500 22 : if (sfi->script()->IsScript()) {
1501 11 : script_id = Script::cast(sfi->script())->id();
1502 : }
1503 11 : msg << "compilation-cache" << Logger::kNext << action << Logger::kNext
1504 22 : << cache_type << Logger::kNext << script_id << Logger::kNext
1505 22 : << sfi->StartPosition() << Logger::kNext << sfi->EndPosition()
1506 33 : << Logger::kNext << timer_.Elapsed().InMicroseconds();
1507 11 : msg.WriteToLogFile();
1508 : }
1509 :
1510 279 : void Logger::ScriptEvent(ScriptEventType type, int script_id) {
1511 791 : if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1512 46 : Log::MessageBuilder msg(log_);
1513 46 : msg << "script" << Logger::kNext;
1514 46 : switch (type) {
1515 : case ScriptEventType::kReserveId:
1516 11 : msg << "reserve-id";
1517 11 : break;
1518 : case ScriptEventType::kCreate:
1519 11 : msg << "create";
1520 11 : break;
1521 : case ScriptEventType::kDeserialize:
1522 24 : msg << "deserialize";
1523 24 : break;
1524 : case ScriptEventType::kBackgroundCompile:
1525 0 : msg << "background-compile";
1526 0 : break;
1527 : case ScriptEventType::kStreamingCompile:
1528 0 : msg << "streaming-compile";
1529 0 : break;
1530 : }
1531 92 : msg << Logger::kNext << script_id << Logger::kNext
1532 92 : << timer_.Elapsed().InMicroseconds();
1533 46 : msg.WriteToLogFile();
1534 : }
1535 :
1536 228 : void Logger::ScriptDetails(Script script) {
1537 456 : if (!log_->IsEnabled() || !FLAG_log_function_events) return;
1538 : {
1539 35 : Log::MessageBuilder msg(log_);
1540 70 : msg << "script-details" << Logger::kNext << script->id() << Logger::kNext;
1541 35 : if (script->name()->IsString()) {
1542 8 : msg << String::cast(script->name());
1543 : }
1544 70 : msg << Logger::kNext << script->line_offset() << Logger::kNext
1545 35 : << script->column_offset() << Logger::kNext;
1546 35 : if (script->source_mapping_url()->IsString()) {
1547 0 : msg << String::cast(script->source_mapping_url());
1548 : }
1549 35 : msg.WriteToLogFile();
1550 : }
1551 35 : EnsureLogScriptSource(script);
1552 : }
1553 :
1554 35 : bool Logger::EnsureLogScriptSource(Script script) {
1555 70 : if (!log_->IsEnabled()) return false;
1556 35 : Log::MessageBuilder msg(log_);
1557 : // Make sure the script is written to the log file.
1558 35 : int script_id = script->id();
1559 35 : 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 35 : if (!source_object->IsString()) return false;
1566 35 : String source_code = String::cast(source_object);
1567 70 : msg << "script-source" << kNext << script_id << kNext;
1568 :
1569 : // Log the script name.
1570 35 : if (script->name()->IsString()) {
1571 8 : msg << String::cast(script->name()) << kNext;
1572 : } else {
1573 27 : msg << "<unknown>" << kNext;
1574 : }
1575 :
1576 : // Log the source code.
1577 35 : msg << source_code;
1578 35 : msg.WriteToLogFile();
1579 35 : return true;
1580 : }
1581 :
1582 0 : void Logger::RuntimeCallTimerEvent() {
1583 0 : RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats();
1584 : RuntimeCallCounter* counter = stats->current_counter();
1585 0 : if (counter == nullptr) return;
1586 0 : Log::MessageBuilder msg(log_);
1587 0 : msg << "active-runtime-timer" << kNext << counter->name();
1588 0 : msg.WriteToLogFile();
1589 : }
1590 :
1591 0 : void Logger::TickEvent(v8::TickSample* sample, bool overflow) {
1592 0 : if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
1593 0 : if (V8_UNLIKELY(TracingFlags::runtime_stats.load(std::memory_order_relaxed) ==
1594 : v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE)) {
1595 0 : RuntimeCallTimerEvent();
1596 : }
1597 0 : Log::MessageBuilder msg(log_);
1598 0 : msg << kLogEventsNames[CodeEventListener::TICK_EVENT] << kNext
1599 0 : << reinterpret_cast<void*>(sample->pc) << kNext
1600 0 : << timer_.Elapsed().InMicroseconds();
1601 0 : if (sample->has_external_callback) {
1602 0 : msg << kNext << 1 << kNext
1603 0 : << reinterpret_cast<void*>(sample->external_callback_entry);
1604 : } else {
1605 0 : msg << kNext << 0 << kNext << reinterpret_cast<void*>(sample->tos);
1606 : }
1607 0 : msg << kNext << static_cast<int>(sample->state);
1608 0 : if (overflow) msg << kNext << "overflow";
1609 0 : for (unsigned i = 0; i < sample->frames_count; ++i) {
1610 0 : msg << kNext << reinterpret_cast<void*>(sample->stack[i]);
1611 : }
1612 0 : msg.WriteToLogFile();
1613 : }
1614 :
1615 0 : void 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 0 : if (!log_->IsEnabled() || !FLAG_trace_ic) return;
1619 0 : Log::MessageBuilder msg(log_);
1620 0 : if (keyed) msg << "Keyed";
1621 : int line;
1622 : int column;
1623 0 : Address pc = isolate_->GetAbstractPC(&line, &column);
1624 0 : msg << type << kNext << reinterpret_cast<void*>(pc) << kNext << line << kNext
1625 0 : << column << kNext << old_state << kNext << new_state << kNext
1626 0 : << AsHex::Address(map.ptr()) << kNext;
1627 0 : if (key->IsSmi()) {
1628 : msg << Smi::ToInt(key);
1629 0 : } else if (key->IsNumber()) {
1630 : msg << key->Number();
1631 0 : } else if (key->IsName()) {
1632 0 : msg << Name::cast(key);
1633 : }
1634 0 : msg << kNext << modifier << kNext;
1635 0 : if (slow_stub_reason != nullptr) {
1636 0 : msg << slow_stub_reason;
1637 : }
1638 0 : msg.WriteToLogFile();
1639 : }
1640 :
1641 6911 : void Logger::MapEvent(const char* type, Map from, Map to, const char* reason,
1642 : HeapObject name_or_sfi) {
1643 : DisallowHeapAllocation no_gc;
1644 13822 : if (!log_->IsEnabled() || !FLAG_trace_maps) return;
1645 6911 : if (!to.is_null()) MapDetails(to);
1646 6911 : int line = -1;
1647 6911 : int column = -1;
1648 : Address pc = 0;
1649 :
1650 6911 : if (!isolate_->bootstrapper()->IsActive()) {
1651 4124 : pc = isolate_->GetAbstractPC(&line, &column);
1652 : }
1653 6911 : Log::MessageBuilder msg(log_);
1654 13822 : msg << "map" << kNext << type << kNext << timer_.Elapsed().InMicroseconds()
1655 13822 : << kNext << AsHex::Address(from.ptr()) << kNext
1656 13822 : << AsHex::Address(to.ptr()) << kNext << AsHex::Address(pc) << kNext
1657 20733 : << line << kNext << column << kNext << reason << kNext;
1658 :
1659 6911 : if (!name_or_sfi.is_null()) {
1660 4677 : if (name_or_sfi->IsName()) {
1661 4677 : msg << Name::cast(name_or_sfi);
1662 0 : } else if (name_or_sfi->IsSharedFunctionInfo()) {
1663 0 : SharedFunctionInfo sfi = SharedFunctionInfo::cast(name_or_sfi);
1664 0 : 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 6911 : msg.WriteToLogFile();
1671 : }
1672 :
1673 15772 : void Logger::MapCreate(Map map) {
1674 31544 : if (!log_->IsEnabled() || !FLAG_trace_maps) return;
1675 : DisallowHeapAllocation no_gc;
1676 15772 : Log::MessageBuilder msg(log_);
1677 47316 : msg << "map-create" << kNext << timer_.Elapsed().InMicroseconds() << kNext
1678 : << AsHex::Address(map.ptr());
1679 15772 : msg.WriteToLogFile();
1680 : }
1681 :
1682 15856 : void Logger::MapDetails(Map map) {
1683 31796 : if (!log_->IsEnabled() || !FLAG_trace_maps) return;
1684 : DisallowHeapAllocation no_gc;
1685 15772 : Log::MessageBuilder msg(log_);
1686 47316 : msg << "map-details" << kNext << timer_.Elapsed().InMicroseconds() << kNext
1687 15772 : << AsHex::Address(map.ptr()) << kNext;
1688 15772 : if (FLAG_trace_maps_details) {
1689 31544 : std::ostringstream buffer;
1690 15772 : map->PrintMapDetails(buffer);
1691 31544 : msg << buffer.str().c_str();
1692 : }
1693 15772 : msg.WriteToLogFile();
1694 : }
1695 :
1696 2272556 : static void AddFunctionAndCode(SharedFunctionInfo sfi, AbstractCode code_object,
1697 : Handle<SharedFunctionInfo>* sfis,
1698 : Handle<AbstractCode>* code_objects, int offset) {
1699 2272556 : if (sfis != nullptr) {
1700 2272556 : sfis[offset] = Handle<SharedFunctionInfo>(sfi, sfi->GetIsolate());
1701 : }
1702 2272556 : if (code_objects != nullptr) {
1703 2272556 : code_objects[offset] = Handle<AbstractCode>(code_object, sfi->GetIsolate());
1704 : }
1705 2272556 : }
1706 :
1707 1632 : static int EnumerateCompiledFunctions(Heap* heap,
1708 : Handle<SharedFunctionInfo>* sfis,
1709 : Handle<AbstractCode>* code_objects) {
1710 3264 : 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 24542732 : for (HeapObject obj = iterator.next(); !obj.is_null();
1717 : obj = iterator.next()) {
1718 24541100 : if (obj->IsSharedFunctionInfo()) {
1719 2086990 : SharedFunctionInfo sfi = SharedFunctionInfo::cast(obj);
1720 6245972 : if (sfi->is_compiled() &&
1721 3077892 : (!sfi->script()->IsScript() ||
1722 3092890 : Script::cast(sfi->script())->HasValidSource())) {
1723 4143944 : AddFunctionAndCode(sfi, AbstractCode::cast(sfi->abstract_code()), sfis,
1724 2071972 : code_objects, compiled_funcs_count);
1725 2071972 : ++compiled_funcs_count;
1726 : }
1727 22454110 : } 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 2056498 : JSFunction function = JSFunction::cast(obj);
1731 2056498 : SharedFunctionInfo sfi = SharedFunctionInfo::cast(function->shared());
1732 2056498 : Object maybe_script = sfi->script();
1733 6169494 : if (maybe_script->IsScript() &&
1734 4098234 : !Script::cast(maybe_script)->HasValidSource()) {
1735 20 : 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 2056478 : if (function->IsOptimized()) {
1741 : AddFunctionAndCode(sfi, AbstractCode::cast(function->code()), sfis,
1742 200584 : code_objects, compiled_funcs_count);
1743 200584 : ++compiled_funcs_count;
1744 : }
1745 : }
1746 : }
1747 1632 : return compiled_funcs_count;
1748 : }
1749 :
1750 1632 : static int EnumerateWasmModuleObjects(
1751 : Heap* heap, Handle<WasmModuleObject>* module_objects) {
1752 3264 : HeapIterator iterator(heap);
1753 : DisallowHeapAllocation no_gc;
1754 : int module_objects_count = 0;
1755 :
1756 24543816 : for (HeapObject obj = iterator.next(); !obj.is_null();
1757 : obj = iterator.next()) {
1758 24542184 : if (obj->IsWasmModuleObject()) {
1759 : WasmModuleObject module = WasmModuleObject::cast(obj);
1760 0 : if (module_objects != nullptr) {
1761 : module_objects[module_objects_count] =
1762 0 : handle(module, Isolate::FromHeap(heap));
1763 : }
1764 0 : module_objects_count++;
1765 : }
1766 : }
1767 1632 : return module_objects_count;
1768 : }
1769 :
1770 0 : void Logger::LogCodeObject(Object object) {
1771 0 : existing_code_logger_.LogCodeObject(object);
1772 0 : }
1773 :
1774 35 : void Logger::LogCodeObjects() { existing_code_logger_.LogCodeObjects(); }
1775 :
1776 0 : void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
1777 : Handle<AbstractCode> code) {
1778 0 : existing_code_logger_.LogExistingFunction(shared, code);
1779 0 : }
1780 :
1781 792 : void Logger::LogCompiledFunctions() {
1782 797 : existing_code_logger_.LogCompiledFunctions();
1783 792 : }
1784 :
1785 768 : void Logger::LogAccessorCallbacks() {
1786 768 : Heap* heap = isolate_->heap();
1787 1536 : HeapIterator iterator(heap);
1788 : DisallowHeapAllocation no_gc;
1789 11685956 : for (HeapObject obj = iterator.next(); !obj.is_null();
1790 : obj = iterator.next()) {
1791 23361308 : if (!obj->IsAccessorInfo()) continue;
1792 : AccessorInfo ai = AccessorInfo::cast(obj);
1793 9068 : if (!ai->name()->IsName()) continue;
1794 : Address getter_entry = v8::ToCData<Address>(ai->getter());
1795 9068 : Name name = Name::cast(ai->name());
1796 9068 : if (getter_entry != 0) {
1797 : #if USES_FUNCTION_DESCRIPTORS
1798 : getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(getter_entry);
1799 : #endif
1800 18136 : PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
1801 : }
1802 : Address setter_entry = v8::ToCData<Address>(ai->setter());
1803 9068 : if (setter_entry != 0) {
1804 : #if USES_FUNCTION_DESCRIPTORS
1805 : setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(setter_entry);
1806 : #endif
1807 18126 : PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
1808 : }
1809 : }
1810 768 : }
1811 :
1812 17 : void Logger::LogAllMaps() {
1813 : DisallowHeapAllocation no_gc;
1814 17 : Heap* heap = isolate_->heap();
1815 34 : HeapIterator iterator(heap);
1816 84966 : for (HeapObject obj = iterator.next(); !obj.is_null();
1817 : obj = iterator.next()) {
1818 167280 : if (!obj->IsMap()) continue;
1819 2618 : Map map = Map::cast(obj);
1820 2618 : MapCreate(map);
1821 2618 : MapDetails(map);
1822 : }
1823 17 : }
1824 :
1825 62442 : static void AddIsolateIdIfNeeded(std::ostream& os, // NOLINT
1826 : Isolate* isolate) {
1827 62442 : if (FLAG_logfile_per_isolate) {
1828 63182 : os << "isolate-" << isolate << "-" << base::OS::GetCurrentProcessId()
1829 31591 : << "-";
1830 : }
1831 62442 : }
1832 :
1833 62442 : static void PrepareLogFileName(std::ostream& os, // NOLINT
1834 : Isolate* isolate, const char* file_name) {
1835 : int dir_separator_count = 0;
1836 811156 : for (const char* p = file_name; *p; p++) {
1837 374357 : if (base::OS::isDirectorySeparator(*p)) dir_separator_count++;
1838 : }
1839 :
1840 811156 : for (const char* p = file_name; *p; p++) {
1841 374357 : if (dir_separator_count == 0) {
1842 62442 : AddIsolateIdIfNeeded(os, isolate);
1843 62442 : dir_separator_count--;
1844 : }
1845 374357 : if (*p == '%') {
1846 0 : p++;
1847 0 : 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 0 : os << base::OS::GetCurrentProcessId();
1855 0 : break;
1856 : case 't':
1857 : // %t expands to the current time in milliseconds.
1858 : os << static_cast<int64_t>(
1859 0 : 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 374357 : if (base::OS::isDirectorySeparator(*p)) dir_separator_count--;
1872 374357 : os << *p;
1873 : }
1874 : }
1875 62442 : }
1876 :
1877 :
1878 62442 : bool Logger::SetUp(Isolate* isolate) {
1879 : // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
1880 62442 : if (is_initialized_) return true;
1881 62442 : is_initialized_ = true;
1882 :
1883 124884 : std::ostringstream log_file_name;
1884 124884 : std::ostringstream source_log_file_name;
1885 62442 : PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
1886 124884 : log_ = new Log(this, log_file_name.str().c_str());
1887 :
1888 62442 : if (FLAG_perf_basic_prof) {
1889 0 : perf_basic_logger_.reset(new PerfBasicLogger(isolate));
1890 0 : AddCodeEventListener(perf_basic_logger_.get());
1891 : }
1892 :
1893 62442 : if (FLAG_perf_prof) {
1894 0 : perf_jit_logger_.reset(new PerfJitLogger(isolate));
1895 0 : AddCodeEventListener(perf_jit_logger_.get());
1896 : }
1897 :
1898 62442 : if (FLAG_ll_prof) {
1899 0 : ll_logger_.reset(new LowLevelLogger(isolate, log_file_name.str().c_str()));
1900 0 : AddCodeEventListener(ll_logger_.get());
1901 : }
1902 :
1903 62442 : ticker_.reset(new Ticker(isolate, FLAG_prof_sampling_interval));
1904 :
1905 62442 : if (Log::InitLogAtStart()) {
1906 59 : is_logging_ = true;
1907 : }
1908 :
1909 : timer_.Start();
1910 :
1911 62442 : if (FLAG_prof_cpp) {
1912 0 : profiler_.reset(new Profiler(isolate));
1913 0 : is_logging_ = true;
1914 0 : profiler_->Engage();
1915 : }
1916 :
1917 62442 : if (is_logging_) {
1918 59 : AddCodeEventListener(this);
1919 : }
1920 :
1921 : return true;
1922 : }
1923 :
1924 :
1925 60 : void Logger::SetCodeEventHandler(uint32_t options,
1926 : JitCodeEventHandler event_handler) {
1927 60 : if (jit_logger_) {
1928 : RemoveCodeEventListener(jit_logger_.get());
1929 : jit_logger_.reset();
1930 : }
1931 :
1932 60 : if (event_handler) {
1933 35 : if (isolate_->wasm_engine() != nullptr) {
1934 35 : isolate_->wasm_engine()->EnableCodeLogging(isolate_);
1935 : }
1936 35 : jit_logger_.reset(new JitLogger(isolate_, event_handler));
1937 35 : AddCodeEventListener(jit_logger_.get());
1938 35 : if (options & kJitCodeEventEnumExisting) {
1939 5 : HandleScope scope(isolate_);
1940 : LogCodeObjects();
1941 : LogCompiledFunctions();
1942 : }
1943 : }
1944 60 : }
1945 :
1946 124854 : sampler::Sampler* Logger::sampler() { return ticker_.get(); }
1947 :
1948 124854 : void Logger::StopProfilerThread() {
1949 124854 : if (profiler_ != nullptr) {
1950 0 : profiler_->Disengage();
1951 : profiler_.reset();
1952 : }
1953 124854 : }
1954 :
1955 62540 : FILE* Logger::TearDown() {
1956 62540 : if (!is_initialized_) return nullptr;
1957 62427 : is_initialized_ = false;
1958 :
1959 : // Stop the profiler thread before closing the file.
1960 62427 : StopProfilerThread();
1961 :
1962 : ticker_.reset();
1963 :
1964 62427 : if (perf_basic_logger_) {
1965 : RemoveCodeEventListener(perf_basic_logger_.get());
1966 : perf_basic_logger_.reset();
1967 : }
1968 :
1969 62427 : if (perf_jit_logger_) {
1970 : RemoveCodeEventListener(perf_jit_logger_.get());
1971 : perf_jit_logger_.reset();
1972 : }
1973 :
1974 62427 : if (ll_logger_) {
1975 : RemoveCodeEventListener(ll_logger_.get());
1976 : ll_logger_.reset();
1977 : }
1978 :
1979 62427 : if (jit_logger_) {
1980 : RemoveCodeEventListener(jit_logger_.get());
1981 : jit_logger_.reset();
1982 : }
1983 :
1984 62427 : return log_->Close();
1985 : }
1986 :
1987 82422 : void ExistingCodeLogger::LogCodeObject(Object object) {
1988 82422 : AbstractCode abstract_code = AbstractCode::cast(object);
1989 : CodeEventListener::LogEventsAndTags tag = CodeEventListener::STUB_TAG;
1990 : const char* description = "Unknown code from before profiling";
1991 82422 : switch (abstract_code->kind()) {
1992 : case AbstractCode::INTERPRETED_FUNCTION:
1993 : case AbstractCode::OPTIMIZED_FUNCTION:
1994 25818 : 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 12 : break;
2001 : case AbstractCode::REGEXP:
2002 : description = "Regular expression code";
2003 : tag = CodeEventListener::REG_EXP_TAG;
2004 0 : break;
2005 : case AbstractCode::BUILTIN:
2006 56986 : if (Code::cast(object)->is_interpreter_trampoline_builtin() &&
2007 : Code::cast(object) !=
2008 448 : *BUILTIN_CODE(isolate_, InterpreterEntryTrampoline)) {
2009 : return;
2010 : }
2011 : description =
2012 56592 : isolate_->builtins()->name(abstract_code->GetCode()->builtin_index());
2013 : tag = CodeEventListener::BUILTIN_TAG;
2014 56592 : break;
2015 : case AbstractCode::WASM_FUNCTION:
2016 : description = "A Wasm function";
2017 : tag = CodeEventListener::FUNCTION_TAG;
2018 0 : break;
2019 : case AbstractCode::JS_TO_WASM_FUNCTION:
2020 : description = "A JavaScript to Wasm adapter";
2021 : tag = CodeEventListener::STUB_TAG;
2022 0 : break;
2023 : case AbstractCode::WASM_TO_JS_FUNCTION:
2024 : description = "A Wasm to JavaScript adapter";
2025 : tag = CodeEventListener::STUB_TAG;
2026 0 : break;
2027 : case AbstractCode::WASM_INTERPRETER_ENTRY:
2028 : description = "A Wasm to Interpreter adapter";
2029 : tag = CodeEventListener::STUB_TAG;
2030 0 : break;
2031 : case AbstractCode::C_WASM_ENTRY:
2032 : description = "A C to Wasm entry stub";
2033 : tag = CodeEventListener::STUB_TAG;
2034 0 : break;
2035 : case AbstractCode::NUMBER_OF_KINDS:
2036 0 : UNIMPLEMENTED();
2037 : }
2038 93290 : CALL_CODE_EVENT_HANDLER(CodeCreateEvent(tag, abstract_code, description))
2039 : }
2040 :
2041 54 : void ExistingCodeLogger::LogCodeObjects() {
2042 54 : Heap* heap = isolate_->heap();
2043 108 : HeapIterator iterator(heap);
2044 : DisallowHeapAllocation no_gc;
2045 391731 : for (HeapObject obj = iterator.next(); !obj.is_null();
2046 : obj = iterator.next()) {
2047 391677 : if (obj->IsCode()) LogCodeObject(obj);
2048 391677 : if (obj->IsBytecodeArray()) LogCodeObject(obj);
2049 : }
2050 54 : }
2051 :
2052 816 : void ExistingCodeLogger::LogCompiledFunctions() {
2053 816 : Heap* heap = isolate_->heap();
2054 : HandleScope scope(isolate_);
2055 : const int compiled_funcs_count =
2056 816 : EnumerateCompiledFunctions(heap, nullptr, nullptr);
2057 : ScopedVector<Handle<SharedFunctionInfo>> sfis(compiled_funcs_count);
2058 : ScopedVector<Handle<AbstractCode>> code_objects(compiled_funcs_count);
2059 816 : EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start());
2060 :
2061 : // During iteration, there can be heap allocation due to
2062 : // GetScriptLineNumber call.
2063 2273372 : for (int i = 0; i < compiled_funcs_count; ++i) {
2064 2272556 : SharedFunctionInfo::EnsureSourcePositionsAvailable(isolate_, sfis[i]);
2065 1136278 : if (sfis[i]->function_data()->IsInterpreterData()) {
2066 20 : LogExistingFunction(
2067 : sfis[i],
2068 : Handle<AbstractCode>(
2069 : AbstractCode::cast(sfis[i]->InterpreterTrampoline()), isolate_),
2070 10 : CodeEventListener::INTERPRETED_FUNCTION_TAG);
2071 : }
2072 3408834 : if (code_objects[i].is_identical_to(BUILTIN_CODE(isolate_, CompileLazy)))
2073 : continue;
2074 1136278 : LogExistingFunction(sfis[i], code_objects[i]);
2075 : }
2076 :
2077 : const int wasm_module_objects_count =
2078 816 : EnumerateWasmModuleObjects(heap, nullptr);
2079 : std::unique_ptr<Handle<WasmModuleObject>[]> module_objects(
2080 816 : new Handle<WasmModuleObject>[wasm_module_objects_count]);
2081 816 : EnumerateWasmModuleObjects(heap, module_objects.get());
2082 816 : for (int i = 0; i < wasm_module_objects_count; ++i) {
2083 0 : module_objects[i]->native_module()->LogWasmCodes(isolate_);
2084 : }
2085 816 : }
2086 :
2087 1136288 : void ExistingCodeLogger::LogExistingFunction(
2088 : Handle<SharedFunctionInfo> shared, Handle<AbstractCode> code,
2089 : CodeEventListener::LogEventsAndTags tag) {
2090 2272576 : if (shared->script()->IsScript()) {
2091 1809726 : Handle<Script> script(Script::cast(shared->script()), isolate_);
2092 603242 : int line_num = Script::GetLineNumber(script, shared->StartPosition()) + 1;
2093 : int column_num =
2094 603242 : Script::GetColumnNumber(script, shared->StartPosition()) + 1;
2095 603242 : if (script->name()->IsString()) {
2096 855 : Handle<String> script_name(String::cast(script->name()), isolate_);
2097 855 : if (line_num > 0) {
2098 3420 : 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 0 : CALL_CODE_EVENT_HANDLER(CodeCreateEvent(
2104 : Logger::ToNativeByScript(CodeEventListener::SCRIPT_TAG, *script),
2105 : *code, *shared, *script_name))
2106 : }
2107 : } else {
2108 1807161 : CALL_CODE_EVENT_HANDLER(CodeCreateEvent(
2109 : Logger::ToNativeByScript(tag, *script), *code, *shared,
2110 : ReadOnlyRoots(isolate_).empty_string(), line_num, column_num))
2111 : }
2112 533046 : } 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 33552 : 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 49683 : CALL_CODE_EVENT_HANDLER(CallbackEvent(shared->DebugName(), entry_point))
2124 : }
2125 : }
2126 1136288 : }
2127 :
2128 : #undef CALL_CODE_EVENT_HANDLER
2129 :
2130 : } // namespace internal
2131 122036 : } // namespace v8
|
