log.h 20.9 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 7

#ifndef V8_LOG_H_
#define V8_LOG_H_

8 9
#include <string>

10
#include "src/allocation.h"
11 12
#include "src/base/platform/elapsed-timer.h"
#include "src/base/platform/platform.h"
13
#include "src/objects.h"
14

15
namespace v8 {
16 17 18 19 20

namespace base {
class Semaphore;
}

21
namespace internal {
22 23 24 25 26 27 28 29 30 31 32

// 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
33
// --log-api, --log-code, --log-gc, and --log-regexp.
34 35 36 37 38 39 40 41 42 43 44 45
//
// --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.
//
// --log-gc
// Log GC heap samples after each GC that can be processed by hp2ps, default
// is off.  --log-gc implies --log.
//
46
// --log-regexp
47
// Log creation and use of regular expressions, Default is off.
48 49
// --log-regexp implies --log.
//
50 51 52 53 54 55 56 57
// --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.

// Forward declarations.
58
class CodeEventListener;
59 60 61 62 63
class CompilationInfo;
class CpuProfiler;
class Isolate;
class Log;
class PositionsRecorder;
64
class Profiler;
65
class Ticker;
66
struct TickSample;
67 68

#undef LOG
69 70 71 72 73 74
#define LOG(isolate, Call)                          \
  do {                                              \
    v8::internal::Logger* logger =                  \
        (isolate)->logger();                        \
    if (logger->is_logging())                       \
      logger->Call;                                 \
75
  } while (false)
76

77 78 79 80 81 82 83 84 85
#define LOG_CODE_EVENT(isolate, Call)               \
  do {                                              \
    v8::internal::Logger* logger =                  \
        (isolate)->logger();                        \
    if (logger->is_logging_code_events())           \
      logger->Call;                                 \
  } while (false)


danno@chromium.org's avatar
danno@chromium.org committed
86 87
#define LOG_EVENTS_AND_TAGS_LIST(V)                                     \
  V(CODE_CREATION_EVENT,            "code-creation")                    \
88
  V(CODE_DISABLE_OPT_EVENT,         "code-disable-optimization")        \
danno@chromium.org's avatar
danno@chromium.org committed
89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104
  V(CODE_MOVE_EVENT,                "code-move")                        \
  V(CODE_DELETE_EVENT,              "code-delete")                      \
  V(CODE_MOVING_GC,                 "code-moving-gc")                   \
  V(SHARED_FUNC_MOVE_EVENT,         "sfi-move")                         \
  V(SNAPSHOT_POSITION_EVENT,        "snapshot-pos")                     \
  V(SNAPSHOT_CODE_NAME_EVENT,       "snapshot-code-name")               \
  V(TICK_EVENT,                     "tick")                             \
  V(REPEAT_META_EVENT,              "repeat")                           \
  V(BUILTIN_TAG,                    "Builtin")                          \
  V(CALL_DEBUG_BREAK_TAG,           "CallDebugBreak")                   \
  V(CALL_DEBUG_PREPARE_STEP_IN_TAG, "CallDebugPrepareStepIn")           \
  V(CALL_INITIALIZE_TAG,            "CallInitialize")                   \
  V(CALL_MEGAMORPHIC_TAG,           "CallMegamorphic")                  \
  V(CALL_MISS_TAG,                  "CallMiss")                         \
  V(CALL_NORMAL_TAG,                "CallNormal")                       \
  V(CALL_PRE_MONOMORPHIC_TAG,       "CallPreMonomorphic")               \
105 106 107 108 109 110 111
  V(LOAD_INITIALIZE_TAG,            "LoadInitialize")                   \
  V(LOAD_PREMONOMORPHIC_TAG,        "LoadPreMonomorphic")               \
  V(LOAD_MEGAMORPHIC_TAG,           "LoadMegamorphic")                  \
  V(STORE_INITIALIZE_TAG,           "StoreInitialize")                  \
  V(STORE_PREMONOMORPHIC_TAG,       "StorePreMonomorphic")              \
  V(STORE_GENERIC_TAG,              "StoreGeneric")                     \
  V(STORE_MEGAMORPHIC_TAG,          "StoreMegamorphic")                 \
danno@chromium.org's avatar
danno@chromium.org committed
112 113 114 115 116 117 118 119 120 121 122
  V(KEYED_CALL_DEBUG_BREAK_TAG,     "KeyedCallDebugBreak")              \
  V(KEYED_CALL_DEBUG_PREPARE_STEP_IN_TAG,                               \
    "KeyedCallDebugPrepareStepIn")                                      \
  V(KEYED_CALL_INITIALIZE_TAG,      "KeyedCallInitialize")              \
  V(KEYED_CALL_MEGAMORPHIC_TAG,     "KeyedCallMegamorphic")             \
  V(KEYED_CALL_MISS_TAG,            "KeyedCallMiss")                    \
  V(KEYED_CALL_NORMAL_TAG,          "KeyedCallNormal")                  \
  V(KEYED_CALL_PRE_MONOMORPHIC_TAG, "KeyedCallPreMonomorphic")          \
  V(CALLBACK_TAG,                   "Callback")                         \
  V(EVAL_TAG,                       "Eval")                             \
  V(FUNCTION_TAG,                   "Function")                         \
123
  V(HANDLER_TAG,                    "Handler")                          \
danno@chromium.org's avatar
danno@chromium.org committed
124
  V(KEYED_LOAD_IC_TAG,              "KeyedLoadIC")                      \
125
  V(KEYED_LOAD_POLYMORPHIC_IC_TAG,  "KeyedLoadPolymorphicIC")           \
danno@chromium.org's avatar
danno@chromium.org committed
126 127
  V(KEYED_EXTERNAL_ARRAY_LOAD_IC_TAG, "KeyedExternalArrayLoadIC")       \
  V(KEYED_STORE_IC_TAG,             "KeyedStoreIC")                     \
128
  V(KEYED_STORE_POLYMORPHIC_IC_TAG, "KeyedStorePolymorphicIC")          \
danno@chromium.org's avatar
danno@chromium.org committed
129 130
  V(KEYED_EXTERNAL_ARRAY_STORE_IC_TAG, "KeyedExternalArrayStoreIC")     \
  V(LAZY_COMPILE_TAG,               "LazyCompile")                      \
131
  V(CALL_IC_TAG,                    "CallIC")                           \
danno@chromium.org's avatar
danno@chromium.org committed
132
  V(LOAD_IC_TAG,                    "LoadIC")                           \
133
  V(LOAD_POLYMORPHIC_IC_TAG,        "LoadPolymorphicIC")                \
danno@chromium.org's avatar
danno@chromium.org committed
134 135 136
  V(REG_EXP_TAG,                    "RegExp")                           \
  V(SCRIPT_TAG,                     "Script")                           \
  V(STORE_IC_TAG,                   "StoreIC")                          \
137
  V(STORE_POLYMORPHIC_IC_TAG,       "StorePolymorphicIC")               \
danno@chromium.org's avatar
danno@chromium.org committed
138 139 140
  V(STUB_TAG,                       "Stub")                             \
  V(NATIVE_FUNCTION_TAG,            "Function")                         \
  V(NATIVE_LAZY_COMPILE_TAG,        "LazyCompile")                      \
141
  V(NATIVE_SCRIPT_TAG,              "Script")
mikhail.naganov@gmail.com's avatar
mikhail.naganov@gmail.com committed
142 143 144
// Note that 'NATIVE_' cases for functions and scripts are mapped onto
// original tags when writing to the log.

145

146
class JitLogger;
147
class PerfBasicLogger;
148
class LowLevelLogger;
149
class PerfJitLogger;
150 151
class Sampler;

152 153
class Logger {
 public:
154 155
  enum StartEnd { START = 0, END = 1 };

156
#define DECLARE_ENUM(enum_item, ignore) enum_item,
157 158 159 160 161 162
  enum LogEventsAndTags {
    LOG_EVENTS_AND_TAGS_LIST(DECLARE_ENUM)
    NUMBER_OF_LOG_EVENTS
  };
#undef DECLARE_ENUM

163
  // Acquires resources for logging if the right flags are set.
164
  bool SetUp(Isolate* isolate);
165

166 167 168 169
  // Sets the current code event handler.
  void SetCodeEventHandler(uint32_t options,
                           JitCodeEventHandler event_handler);

170
  Sampler* sampler();
171

172
  // Frees resources acquired in SetUp.
173 174 175
  // When a temporary file is used for the log, returns its stream descriptor,
  // leaving the file open.
  FILE* TearDown();
176 177

  // Emits an event with a string value -> (name, value).
178
  void StringEvent(const char* name, const char* value);
179 180

  // Emits an event with an int value -> (name, value).
181 182
  void IntEvent(const char* name, int value);
  void IntPtrTEvent(const char* name, intptr_t value);
183 184

  // Emits an event with an handle value -> (name, location).
185
  void HandleEvent(const char* name, Object** location);
186 187

  // Emits memory management events for C allocated structures.
188 189 190 191 192 193 194
  void NewEvent(const char* name, void* object, size_t size);
  void DeleteEvent(const char* name, void* object);

  // Static versions of the above, operate on current isolate's logger.
  // Used in TRACK_MEMORY(TypeName) defined in globals.h
  static void NewEventStatic(const char* name, void* object, size_t size);
  static void DeleteEventStatic(const char* name, void* object);
195 196 197 198 199

  // 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.
200
  void ResourceEvent(const char* name, const char* tag);
201 202 203

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

206 207
  // Emits an event when a message is put on or read from a debugging queue.
  // DebugTag lets us put a call-site specific label on the event.
208 209
  void DebugTag(const char* call_site_tag);
  void DebugEvent(const char* event_type, Vector<uint16_t> parameter);
210

211 212

  // ==== Events logged by --log-api. ====
213
  void ApiSecurityCheck();
214 215 216 217 218 219
  void ApiNamedPropertyAccess(const char* tag, JSObject* holder, Object* name);
  void ApiIndexedPropertyAccess(const char* tag,
                                JSObject* holder,
                                uint32_t index);
  void ApiObjectAccess(const char* tag, JSObject* obj);
  void ApiEntryCall(const char* name);
220 221 222


  // ==== Events logged by --log-code. ====
223 224 225 226 227
  void addCodeEventListener(CodeEventListener* listener);
  void removeCodeEventListener(CodeEventListener* listener);
  bool hasCodeEventListener(CodeEventListener* listener);


228
  // Emits a code event for a callback function.
229 230 231
  void CallbackEvent(Name* name, Address entry_point);
  void GetterCallbackEvent(Name* name, Address entry_point);
  void SetterCallbackEvent(Name* name, Address entry_point);
232
  // Emits a code create event.
233 234 235
  void CodeCreateEvent(LogEventsAndTags tag,
                       Code* code, const char* source);
  void CodeCreateEvent(LogEventsAndTags tag,
236
                       Code* code, Name* name);
237 238 239
  void CodeCreateEvent(LogEventsAndTags tag,
                       Code* code,
                       SharedFunctionInfo* shared,
240
                       CompilationInfo* info,
241
                       Name* name);
242 243 244
  void CodeCreateEvent(LogEventsAndTags tag,
                       Code* code,
                       SharedFunctionInfo* shared,
245
                       CompilationInfo* info,
246
                       Name* source, int line, int column);
247
  void CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count);
248 249
  // Emits a code deoptimization event.
  void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared);
250
  void CodeMovingGCEvent();
251
  // Emits a code create event for a RegExp.
252
  void RegExpCodeCreateEvent(Code* code, String* source);
253
  // Emits a code move event.
254
  void CodeMoveEvent(Address from, Address to);
255
  // Emits a code delete event.
256
  void CodeDeleteEvent(Address from);
257 258 259 260 261 262 263 264 265 266 267 268 269
  // Emits a code line info add event with Postion type.
  void CodeLinePosInfoAddPositionEvent(void* jit_handler_data,
                                       int pc_offset,
                                       int position);
  // Emits a code line info add event with StatementPostion type.
  void CodeLinePosInfoAddStatementPositionEvent(void* jit_handler_data,
                                                int pc_offset,
                                                int position);
  // Emits a code line info start to record event
  void CodeStartLinePosInfoRecordEvent(PositionsRecorder* pos_recorder);
  // Emits a code line info finish record event.
  // It's the callee's responsibility to dispose the parameter jit_handler_data.
  void CodeEndLinePosInfoRecordEvent(Code* code, void* jit_handler_data);
270

271
  void SharedFunctionInfoMoveEvent(Address from, Address to);
272

273
  void CodeNameEvent(Address addr, int pos, const char* code_name);
274
  void SnapshotPositionEvent(Address addr, int pos);
275

276 277
  // ==== Events logged by --log-gc. ====
  // Heap sampling events: start, end, and individual types.
278 279 280 281 282 283
  void HeapSampleBeginEvent(const char* space, const char* kind);
  void HeapSampleEndEvent(const char* space, const char* kind);
  void HeapSampleItemEvent(const char* type, int number, int bytes);
  void HeapSampleJSConstructorEvent(const char* constructor,
                                    int number, int bytes);
  void HeapSampleJSRetainersEvent(const char* constructor,
284
                                         const char* event);
285 286 287 288 289
  void HeapSampleJSProducerEvent(const char* constructor,
                                 Address* stack);
  void HeapSampleStats(const char* space, const char* kind,
                       intptr_t capacity, intptr_t used);

290
  void SharedLibraryEvent(const std::string& library_path,
291 292
                          uintptr_t start,
                          uintptr_t end);
293

294 295
  void CodeDeoptEvent(Code* code, int bailout_id, Address from,
                      int fp_to_sp_delta);
296
  void CurrentTimeEvent();
297

298
  void TimerEvent(StartEnd se, const char* name);
299

300 301
  static void EnterExternal(Isolate* isolate);
  static void LeaveExternal(Isolate* isolate);
302

303 304 305 306
  static void DefaultEventLoggerSentinel(const char* name, int event) {}

  INLINE(static void CallEventLogger(Isolate* isolate, const char* name,
                                     StartEnd se, bool expose_to_api));
307

308 309 310
  // ==== Events logged by --log-regexp ====
  // Regexp compilation and execution events.

311
  void RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache);
312

313
  bool is_logging() {
314
    return is_logging_;
315
  }
316

317
  bool is_logging_code_events() {
318
    return is_logging() || jit_logger_ != NULL;
319 320
  }

321 322 323
  // Stop collection of profiling data.
  // When data collection is paused, CPU Tick events are discarded.
  void StopProfiler();
324

325 326
  void LogExistingFunction(Handle<SharedFunctionInfo> shared,
                           Handle<Code> code);
327
  // Logs all compiled functions found in the heap.
328
  void LogCompiledFunctions();
329
  // Logs all accessor callbacks found in the heap.
330
  void LogAccessorCallbacks();
331
  // Used for logging stubs found in the snapshot.
332
  void LogCodeObjects();
333

334 335 336
  // Converts tag to a corresponding NATIVE_... if the script is native.
  INLINE(static LogEventsAndTags ToNativeByScript(LogEventsAndTags, Script*));

337
  // Profiler's sampling interval (in milliseconds).
338 339 340 341 342
#if defined(ANDROID)
  // Phones and tablets have processors that are much slower than desktop
  // and laptop computers for which current heuristics are tuned.
  static const int kSamplingIntervalMs = 5;
#else
343
  static const int kSamplingIntervalMs = 1;
344
#endif
345

346 347 348
  // Callback from Log, stops profiling in case of insufficient resources.
  void LogFailure();

349
 private:
350
  explicit Logger(Isolate* isolate);
351
  ~Logger();
352

353
  // Emits the profiler's first message.
354
  void ProfilerBeginEvent();
355

356
  // Emits callback event messages.
357
  void CallbackEventInternal(const char* prefix,
358
                             Name* name,
359
                             Address entry_point);
360

361
  // Internal configurable move event.
362
  void MoveEventInternal(LogEventsAndTags event, Address from, Address to);
363

364
  // Emits the source code of a regexp. Used by regexp events.
365
  void LogRegExpSource(Handle<JSRegExp> regexp);
366

367
  // Used for logging stubs found in the snapshot.
368
  void LogCodeObject(Object* code_object);
369

370 371 372
  // Helper method. It resets name_buffer_ and add tag name into it.
  void InitNameBuffer(LogEventsAndTags tag);

373
  // Emits a profiler tick event. Used by the profiler thread.
374
  void TickEvent(TickSample* sample, bool overflow);
375

376
  void ApiEvent(const char* name, ...);
377

378
  // Logs a StringEvent regardless of whether FLAG_log is true.
379
  void UncheckedStringEvent(const char* name, const char* value);
380

381
  // Logs an IntEvent regardless of whether FLAG_log is true.
382 383
  void UncheckedIntEvent(const char* name, int value);
  void UncheckedIntPtrTEvent(const char* name, intptr_t value);
384

385 386
  Isolate* isolate_;

387
  // The sampler used by the profiler and the sliding state window.
388
  Ticker* ticker_;
389 390 391 392

  // When the statistical profile is active, profiler_
  // points to a Profiler, that handles collection
  // of samples.
393
  Profiler* profiler_;
394

395 396
  // An array of log events names.
  const char* const* log_events_;
397 398 399 400

  // Internal implementation classes with access to
  // private members.
  friend class EventLog;
401
  friend class Isolate;
402 403
  friend class TimeLog;
  friend class Profiler;
404
  template <StateTag Tag> friend class VMState;
405
  friend class LoggerTestHelper;
406

407
  bool is_logging_;
408
  Log* log_;
409 410
  PerfBasicLogger* perf_basic_logger_;
  PerfJitLogger* perf_jit_logger_;
411
  LowLevelLogger* ll_logger_;
412
  JitLogger* jit_logger_;
413
  List<CodeEventListener*> listeners_;
414

415
  // Guards against multiple calls to TearDown() that can happen in some tests.
416
  // 'true' between SetUp() and TearDown().
417 418
  bool is_initialized_;

419
  base::ElapsedTimer timer_;
420

421
  friend class CpuProfiler;
422 423 424
};


425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458
#define TIMER_EVENTS_LIST(V)    \
  V(RecompileSynchronous, true) \
  V(RecompileConcurrent, true)  \
  V(CompileFullCode, true)      \
  V(Execute, true)              \
  V(External, true)             \
  V(IcMiss, false)

#define V(TimerName, expose)                                                  \
  class TimerEvent##TimerName : public AllStatic {                            \
   public:                                                                    \
    static const char* name(void* unused = NULL) { return "V8." #TimerName; } \
    static bool expose_to_api() { return expose; }                            \
  };
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); }

  void LogTimerEvent(Logger::StartEnd se);

 private:
  Isolate* isolate_;
};


459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474 475 476 477 478
class CodeEventListener {
 public:
  virtual ~CodeEventListener() {}

  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               const char* comment) = 0;
  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               Name* name) = 0;
  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               SharedFunctionInfo* shared,
                               CompilationInfo* info,
                               Name* name) = 0;
  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               SharedFunctionInfo* shared,
                               CompilationInfo* info,
                               Name* source,
479
                               int line, int column) = 0;
480 481 482 483 484 485 486 487 488 489 490
  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               int args_count) = 0;
  virtual void CallbackEvent(Name* name, Address entry_point) = 0;
  virtual void GetterCallbackEvent(Name* name, Address entry_point) = 0;
  virtual void SetterCallbackEvent(Name* name, Address entry_point) = 0;
  virtual void RegExpCodeCreateEvent(Code* code, String* source) = 0;
  virtual void CodeMoveEvent(Address from, Address to) = 0;
  virtual void CodeDeleteEvent(Address from) = 0;
  virtual void SharedFunctionInfoMoveEvent(Address from, Address to) = 0;
  virtual void CodeMovingGCEvent() = 0;
491
  virtual void CodeDisableOptEvent(Code* code, SharedFunctionInfo* shared) = 0;
492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518
};


class CodeEventLogger : public CodeEventListener {
 public:
  CodeEventLogger();
  virtual ~CodeEventLogger();

  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               const char* comment);
  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               Name* name);
  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               int args_count);
  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               SharedFunctionInfo* shared,
                               CompilationInfo* info,
                               Name* name);
  virtual void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code,
                               SharedFunctionInfo* shared,
                               CompilationInfo* info,
                               Name* source,
519
                               int line, int column);
520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539
  virtual void RegExpCodeCreateEvent(Code* code, String* source);

  virtual void CallbackEvent(Name* name, Address entry_point) { }
  virtual void GetterCallbackEvent(Name* name, Address entry_point) { }
  virtual void SetterCallbackEvent(Name* name, Address entry_point) { }
  virtual void SharedFunctionInfoMoveEvent(Address from, Address to) { }
  virtual void CodeMovingGCEvent() { }

 private:
  class NameBuffer;

  virtual void LogRecordedBuffer(Code* code,
                                 SharedFunctionInfo* shared,
                                 const char* name,
                                 int length) = 0;

  NameBuffer* name_buffer_;
};


540 541
} }  // namespace v8::internal

542

543
#endif  // V8_LOG_H_