• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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