log.h 18 KB
Newer Older
1
// Copyright 2012 the V8 project authors. All rights reserved.
2 3
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
4

5 6
#ifndef V8_LOGGING_LOG_H_
#define V8_LOGGING_LOG_H_
7

8
#include <atomic>
9
#include <memory>
10
#include <set>
11 12
#include <string>

13
#include "include/v8-profiler.h"
14
#include "src/base/platform/elapsed-timer.h"
15
#include "src/logging/code-events.h"
16
#include "src/objects/objects.h"
17

18
namespace v8 {
19

20 21
namespace sampler {
class Sampler;
22
}  // namespace sampler
23

24
namespace internal {
25

26 27
struct TickSample;

28 29 30 31 32 33 34 35 36 37
// Logger is used for collecting logging information from V8 during
// execution. The result is dumped to a file.
//
// Available command line flags:
//
//  --log
// Minimal logging (no API, code, or GC sample events), default is off.
//
// --log-all
// Log all events to the file, default is off.  This is the same as combining
Hannes Payer's avatar
Hannes Payer committed
38
// --log-api, --log-code, and --log-regexp.
39 40 41 42 43 44 45 46
//
// --log-api
// Log API events to the logfile, default is off.  --log-api implies --log.
//
// --log-code
// Log code (create, move, and delete) events to the logfile, default is off.
// --log-code implies --log.
//
47
// --log-regexp
48
// Log creation and use of regular expressions, Default is off.
49 50
// --log-regexp implies --log.
//
51 52 53 54 55 56
// --logfile <filename>
// Specify the name of the logfile, default is "v8.log".
//
// --prof
// Collect statistical profiling information (ticks), default is off.  The
// tick profiler requires code events, so --prof implies --log-code.
57 58 59 60
//
// --prof-sampling-interval <microseconds>
// The interval between --prof samples, default is 1000 microseconds (5000 on
// Android).
61 62

// Forward declarations.
63
class CodeEventListener;
64
class Isolate;
65
class JitLogger;
66
class Log;
67 68 69
class LowLevelLogger;
class PerfBasicLogger;
class PerfJitLogger;
70
class Profiler;
71
class SourcePosition;
72
class Ticker;
73

74
#undef LOG
75 76
#define LOG(isolate, Call)                  \
  do {                                      \
77
    auto&& logger = (isolate)->logger();    \
78
    if (logger->is_logging()) logger->Call; \
79
  } while (false)
80

81 82
#define LOG_CODE_EVENT(isolate, Call)                        \
  do {                                                       \
83
    auto&& logger = (isolate)->logger();                     \
84
    if (logger->is_listening_to_code_events()) logger->Call; \
85 86
  } while (false)

87 88 89 90 91 92 93 94 95 96
class ExistingCodeLogger {
 public:
  explicit ExistingCodeLogger(Isolate* isolate,
                              CodeEventListener* listener = nullptr)
      : isolate_(isolate), listener_(listener) {}

  void LogCodeObjects();

  void LogCompiledFunctions();
  void LogExistingFunction(Handle<SharedFunctionInfo> shared,
97 98 99
                           Handle<AbstractCode> code,
                           CodeEventListener::LogEventsAndTags tag =
                               CodeEventListener::LAZY_COMPILE_TAG);
100
  void LogCodeObject(Object object);
101 102 103 104 105 106

 private:
  Isolate* isolate_;
  CodeEventListener* listener_;
};

107 108
enum class LogSeparator;

109
class Logger : public CodeEventListener {
110
 public:
111
  enum StartEnd { START = 0, END = 1, STAMP = 2 };
112

113 114 115 116
  enum class ScriptEventType {
    kReserveId,
    kCreate,
    kDeserialize,
117 118
    kBackgroundCompile,
    kStreamingCompile
119 120
  };

121
  explicit Logger(Isolate* isolate);
122
  ~Logger() override;
123

124
  // The separator is used to write an unescaped "," into the log.
125
  static const LogSeparator kNext;
126

127
  // Acquires resources for logging if the right flags are set.
128
  bool SetUp(Isolate* isolate);
129

130 131 132 133 134
  // Frees resources acquired in SetUp.
  // When a temporary file is used for the log, returns its stream descriptor,
  // leaving the file open.
  V8_EXPORT_PRIVATE FILE* TearDownAndGetLogFile();

135
  // Sets the current code event handler.
136
  void SetCodeEventHandler(uint32_t options, JitCodeEventHandler event_handler);
137

138
  sampler::Sampler* sampler();
139
  V8_EXPORT_PRIVATE std::string file_name() const;
140

141
  V8_EXPORT_PRIVATE void StopProfilerThread();
142

143
  // Emits an event with a string value -> (name, value).
144
  V8_EXPORT_PRIVATE void StringEvent(const char* name, const char* value);
145 146

  // Emits an event with an int value -> (name, value).
147
  void IntPtrTEvent(const char* name, intptr_t value);
148 149

  // Emits an event with an handle value -> (name, location).
150
  void HandleEvent(const char* name, Address* location);
151 152

  // Emits memory management events for C allocated structures.
153 154 155
  void NewEvent(const char* name, void* object, size_t size);
  void DeleteEvent(const char* name, void* object);

156 157 158 159
  // Emits an event with a tag, and some resource usage information.
  // -> (name, tag, <rusage information>).
  // Currently, the resource usage information is a process time stamp
  // and a real time timestamp.
160
  void ResourceEvent(const char* name, const char* tag);
161 162 163

  // Emits an event that an undefined property was read from an
  // object.
164
  void SuspectReadEvent(Name name, Object obj);
165

166 167
  // ==== Events logged by --log-function-events ====
  void FunctionEvent(const char* reason, int script_id, double time_delta_ms,
168 169
                     int start_position, int end_position,
                     String function_name);
170 171
  void FunctionEvent(const char* reason, int script_id, double time_delta_ms,
                     int start_position, int end_position,
172
                     const char* function_name = nullptr,
173
                     size_t function_name_length = 0, bool is_one_byte = true);
174

175
  void CompilationCacheEvent(const char* action, const char* cache_type,
176
                             SharedFunctionInfo sfi);
177
  void ScriptEvent(ScriptEventType type, int script_id);
178
  void ScriptDetails(Script script);
179

180
  // ==== Events logged by --log-api. ====
181
  void ApiSecurityCheck();
182
  void ApiNamedPropertyAccess(const char* tag, JSObject holder, Object name);
183
  void ApiIndexedPropertyAccess(const char* tag, JSObject holder,
184
                                uint32_t index);
185
  void ApiObjectAccess(const char* tag, JSObject obj);
186
  void ApiEntryCall(const char* name);
187 188

  // ==== Events logged by --log-code. ====
189 190
  V8_EXPORT_PRIVATE void AddCodeEventListener(CodeEventListener* listener);
  V8_EXPORT_PRIVATE void RemoveCodeEventListener(CodeEventListener* listener);
191

192 193 194 195 196 197 198 199 200 201 202 203
  // CodeEventListener implementation.
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       const char* name) override;
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       Handle<Name> name) override;
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       Handle<SharedFunctionInfo> shared,
                       Handle<Name> script_name) override;
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       Handle<SharedFunctionInfo> shared,
                       Handle<Name> script_name, int line, int column) override;
  void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
204
                       wasm::WasmName name) override;
205 206 207 208 209 210

  void CallbackEvent(Handle<Name> name, Address entry_point) override;
  void GetterCallbackEvent(Handle<Name> name, Address entry_point) override;
  void SetterCallbackEvent(Handle<Name> name, Address entry_point) override;
  void RegExpCodeCreateEvent(Handle<AbstractCode> code,
                             Handle<String> source) override;
211
  void CodeMoveEvent(AbstractCode from, AbstractCode to) override;
212 213 214 215 216
  void SharedFunctionInfoMoveEvent(Address from, Address to) override;
  void CodeMovingGCEvent() override;
  void CodeDisableOptEvent(Handle<AbstractCode> code,
                           Handle<SharedFunctionInfo> shared) override;
  void CodeDeoptEvent(Handle<Code> code, DeoptimizeKind kind, Address pc,
217
                      int fp_to_sp_delta, bool reuse_code) override;
218 219 220 221 222 223
  void CodeDependencyChangeEvent(Handle<Code> code,
                                 Handle<SharedFunctionInfo> sfi,
                                 const char* reason) override;

  void ProcessDeoptEvent(Handle<Code> code, SourcePosition position,
                         const char* kind, const char* reason);
224

225
  // Emits a code line info record event.
226
  void CodeLinePosInfoRecordEvent(Address code_start,
227
                                  ByteArray source_position_table);
228 229
  void CodeLinePosInfoRecordEvent(Address code_start,
                                  Vector<const byte> source_position_table);
230

231
  void CodeNameEvent(Address addr, int pos, const char* code_name);
232

233 234 235
  void 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);
236

237
  void MapEvent(const char* type, Handle<Map> from, Handle<Map> to,
238
                const char* reason = nullptr,
239
                Handle<HeapObject> name_or_sfi = Handle<HeapObject>());
240 241
  void MapCreate(Map map);
  void MapDetails(Map map);
242

243 244
  void SharedLibraryEvent(const std::string& library_path, uintptr_t start,
                          uintptr_t end, intptr_t aslr_slide);
245

246
  void CurrentTimeEvent();
247

248
  V8_EXPORT_PRIVATE void TimerEvent(StartEnd se, const char* name);
249

250 251 252 253
  void BasicBlockCounterEvent(const char* name, int block_id, uint32_t count);

  void BuiltinHashEvent(const char* name, int hash);

254 255
  static void EnterExternal(Isolate* isolate);
  static void LeaveExternal(Isolate* isolate);
256

257 258
  static void DefaultEventLoggerSentinel(const char* name, int event) {}

259 260
  V8_INLINE static void CallEventLogger(Isolate* isolate, const char* name,
                                        StartEnd se, bool expose_to_api);
261

262
  V8_EXPORT_PRIVATE bool is_logging();
263

264
  bool is_listening_to_code_events() override {
265
    return is_logging() || jit_logger_ != nullptr;
266 267
  }

268
  void LogExistingFunction(Handle<SharedFunctionInfo> shared,
269
                           Handle<AbstractCode> code);
270
  // Logs all compiled functions found in the heap.
271
  V8_EXPORT_PRIVATE void LogCompiledFunctions();
272
  // Logs all accessor callbacks found in the heap.
273
  V8_EXPORT_PRIVATE void LogAccessorCallbacks();
274
  // Used for logging stubs found in the snapshot.
275
  V8_EXPORT_PRIVATE void LogCodeObjects();
276 277
  // Logs all Maps found on the heap.
  void LogAllMaps();
278

279
  // Converts tag to a corresponding NATIVE_... if the script is native.
280
  V8_INLINE static CodeEventListener::LogEventsAndTags ToNativeByScript(
281
      CodeEventListener::LogEventsAndTags, Script);
282

283
  // Used for logging stubs found in the snapshot.
284
  void LogCodeObject(Object code_object);
285

286
 private:
287 288
  void UpdateIsLogging(bool value);

289
  // Emits the profiler's first message.
290
  void ProfilerBeginEvent();
291

292
  // Emits callback event messages.
293
  void CallbackEventInternal(const char* prefix, Handle<Name> name,
294
                             Address entry_point);
295

296
  // Internal configurable move event.
297 298
  void MoveEventInternal(CodeEventListener::LogEventsAndTags event,
                         Address from, Address to);
299

300
  // Helper method. It resets name_buffer_ and add tag name into it.
301
  void InitNameBuffer(CodeEventListener::LogEventsAndTags tag);
302

303
  // Emits a profiler tick event. Used by the profiler thread.
304
  void TickEvent(TickSample* sample, bool overflow);
305
  void RuntimeCallTimerEvent();
306

307
  // Logs a StringEvent regardless of whether FLAG_log is true.
308
  void UncheckedStringEvent(const char* name, const char* value);
309

310
  // Logs an IntPtrTEvent regardless of whether FLAG_log is true.
311
  void UncheckedIntPtrTEvent(const char* name, intptr_t value);
312

313 314
  // Logs a scripts sources. Keeps track of all logged scripts to ensure that
  // each script is logged only once.
315
  bool EnsureLogScriptSource(Script script);
316

317 318
  Isolate* isolate_;

319
  // The sampler used by the profiler and the sliding state window.
320
  std::unique_ptr<Ticker> ticker_;
321 322 323 324

  // When the statistical profile is active, profiler_
  // points to a Profiler, that handles collection
  // of samples.
325
  std::unique_ptr<Profiler> profiler_;
326

327
  // Internal implementation classes with access to private members.
328
  friend class Profiler;
329

330
  std::atomic<bool> is_logging_;
331
  std::unique_ptr<Log> log_;
332
#if V8_OS_LINUX
333
  std::unique_ptr<PerfBasicLogger> perf_basic_logger_;
334
  std::unique_ptr<PerfJitLogger> perf_jit_logger_;
335
#endif
336 337
  std::unique_ptr<LowLevelLogger> ll_logger_;
  std::unique_ptr<JitLogger> jit_logger_;
338 339
  std::set<int> logged_source_code_;
  uint32_t next_source_info_id_ = 0;
340

341
  // Guards against multiple calls to TearDown() that can happen in some tests.
342
  // 'true' between SetUp() and TearDown().
343 344
  bool is_initialized_;

345 346
  ExistingCodeLogger existing_code_logger_;

347
  base::ElapsedTimer timer_;
348 349
};

350 351 352 353 354 355 356 357 358
#define TIMER_EVENTS_LIST(V)     \
  V(RecompileSynchronous, true)  \
  V(RecompileConcurrent, true)   \
  V(CompileIgnition, true)       \
  V(CompileFullCode, true)       \
  V(OptimizeCode, true)          \
  V(CompileCode, true)           \
  V(CompileCodeBackground, true) \
  V(DeoptimizeCode, true)        \
359
  V(Execute, true)
360

361 362 363 364 365 366 367
#define V(TimerName, expose)                          \
  class TimerEvent##TimerName : public AllStatic {    \
   public:                                            \
    static const char* name(void* unused = nullptr) { \
      return "V8." #TimerName;                        \
    }                                                 \
    static bool expose_to_api() { return expose; }    \
368 369 370 371 372 373 374 375 376 377 378 379 380 381
  };
TIMER_EVENTS_LIST(V)
#undef V

template <class TimerEvent>
class TimerEventScope {
 public:
  explicit TimerEventScope(Isolate* isolate) : isolate_(isolate) {
    LogTimerEvent(Logger::START);
  }

  ~TimerEventScope() { LogTimerEvent(Logger::END); }

 private:
382
  void LogTimerEvent(Logger::StartEnd se);
383 384 385
  Isolate* isolate_;
};

386
// Abstract
387
class V8_EXPORT_PRIVATE CodeEventLogger : public CodeEventListener {
388
 public:
389
  explicit CodeEventLogger(Isolate* isolate);
390 391
  ~CodeEventLogger() override;

392 393 394 395 396 397 398 399 400 401
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       const char* name) override;
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       Handle<Name> name) override;
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       Handle<SharedFunctionInfo> shared,
                       Handle<Name> script_name) override;
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       Handle<SharedFunctionInfo> shared,
                       Handle<Name> script_name, int line, int column) override;
402
  void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
403 404
                       wasm::WasmName name) override;

405 406 407 408 409
  void RegExpCodeCreateEvent(Handle<AbstractCode> code,
                             Handle<String> source) override;
  void CallbackEvent(Handle<Name> name, Address entry_point) override {}
  void GetterCallbackEvent(Handle<Name> name, Address entry_point) override {}
  void SetterCallbackEvent(Handle<Name> name, Address entry_point) override {}
410 411
  void SharedFunctionInfoMoveEvent(Address from, Address to) override {}
  void CodeMovingGCEvent() override {}
412
  void CodeDeoptEvent(Handle<Code> code, DeoptimizeKind kind, Address pc,
413
                      int fp_to_sp_delta, bool reuse_code) override {}
414 415 416
  void CodeDependencyChangeEvent(Handle<Code> code,
                                 Handle<SharedFunctionInfo> sfi,
                                 const char* reason) override {}
417

418 419 420
 protected:
  Isolate* isolate_;

421 422 423
 private:
  class NameBuffer;

424 425
  virtual void LogRecordedBuffer(Handle<AbstractCode> code,
                                 MaybeHandle<SharedFunctionInfo> maybe_shared,
426
                                 const char* name, int length) = 0;
427
  virtual void LogRecordedBuffer(const wasm::WasmCode* code, const char* name,
428
                                 int length) = 0;
429

430
  std::unique_ptr<NameBuffer> name_buffer_;
431 432
};

433
struct CodeEvent {
434
  Isolate* isolate_;
435 436 437 438 439 440 441 442
  uintptr_t code_start_address;
  size_t code_size;
  Handle<String> function_name;
  Handle<String> script_name;
  int script_line;
  int script_column;
  CodeEventType code_type;
  const char* comment;
443
  uintptr_t previous_code_start_address;
444 445 446 447 448 449 450
};

class ExternalCodeEventListener : public CodeEventListener {
 public:
  explicit ExternalCodeEventListener(Isolate* isolate);
  ~ExternalCodeEventListener() override;

451
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
452
                       const char* comment) override;
453 454 455 456 457 458 459 460
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       Handle<Name> name) override;
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       Handle<SharedFunctionInfo> shared,
                       Handle<Name> name) override;
  void CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
                       Handle<SharedFunctionInfo> shared, Handle<Name> source,
                       int line, int column) override;
461 462 463
  void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
                       wasm::WasmName name) override;

464 465 466 467 468
  void RegExpCodeCreateEvent(Handle<AbstractCode> code,
                             Handle<String> source) override;
  void CallbackEvent(Handle<Name> name, Address entry_point) override {}
  void GetterCallbackEvent(Handle<Name> name, Address entry_point) override {}
  void SetterCallbackEvent(Handle<Name> name, Address entry_point) override {}
469
  void SharedFunctionInfoMoveEvent(Address from, Address to) override {}
470
  void CodeMoveEvent(AbstractCode from, AbstractCode to) override;
471 472
  void CodeDisableOptEvent(Handle<AbstractCode> code,
                           Handle<SharedFunctionInfo> shared) override {}
473
  void CodeMovingGCEvent() override {}
474
  void CodeDeoptEvent(Handle<Code> code, DeoptimizeKind kind, Address pc,
475
                      int fp_to_sp_delta, bool reuse_code) override {}
476 477 478
  void CodeDependencyChangeEvent(Handle<Code> code,
                                 Handle<SharedFunctionInfo> sfi,
                                 const char* reason) override {}
479

480
  void StartListening(v8::CodeEventHandler* code_event_handler);
481 482 483 484 485 486 487 488 489 490 491
  void StopListening();

  bool is_listening_to_code_events() override { return true; }

 private:
  void LogExistingCode();

  bool is_listening_;
  Isolate* isolate_;
  v8::CodeEventHandler* code_event_handler_;
};
492

493 494
}  // namespace internal
}  // namespace v8
495

496
#endif  // V8_LOGGING_LOG_H_