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