log.h 21.7 KB
Newer Older
1
// Copyright 2012 the V8 project authors. All rights reserved.
2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30
// Redistribution and use in source and binary forms, with or without
// modification, are permitted provided that the following conditions are
// met:
//
//     * Redistributions of source code must retain the above copyright
//       notice, this list of conditions and the following disclaimer.
//     * Redistributions in binary form must reproduce the above
//       copyright notice, this list of conditions and the following
//       disclaimer in the documentation and/or other materials provided
//       with the distribution.
//     * Neither the name of Google Inc. nor the names of its
//       contributors may be used to endorse or promote products derived
//       from this software without specific prior written permission.
//
// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.

#ifndef V8_LOG_H_
#define V8_LOG_H_

31
#include "allocation.h"
32
#include "objects.h"
33
#include "platform.h"
34
#include "platform/elapsed-timer.h"
35

36 37
namespace v8 {
namespace internal {
38 39 40 41 42 43 44 45 46 47 48

// 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
49
// --log-api, --log-code, --log-gc, and --log-regexp.
50 51 52 53 54 55 56 57 58 59 60 61
//
// --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.
//
62
// --log-regexp
63
// Log creation and use of regular expressions, Default is off.
64 65
// --log-regexp implies --log.
//
66 67 68 69 70 71 72 73
// --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.
74
class CodeEventListener;
75 76 77 78 79
class CompilationInfo;
class CpuProfiler;
class Isolate;
class Log;
class PositionsRecorder;
80 81
class Profiler;
class Semaphore;
82
class Ticker;
83
struct TickSample;
84 85

#undef LOG
86 87 88 89 90 91
#define LOG(isolate, Call)                          \
  do {                                              \
    v8::internal::Logger* logger =                  \
        (isolate)->logger();                        \
    if (logger->is_logging())                       \
      logger->Call;                                 \
92
  } while (false)
93

94 95 96 97 98 99 100 101 102
#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
103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120
#define LOG_EVENTS_AND_TAGS_LIST(V)                                     \
  V(CODE_CREATION_EVENT,            "code-creation")                    \
  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")               \
121 122 123 124 125 126 127
  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
128 129 130 131 132 133 134 135 136 137 138
  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")                         \
139
  V(HANDLER_TAG,                    "Handler")                          \
danno@chromium.org's avatar
danno@chromium.org committed
140
  V(KEYED_LOAD_IC_TAG,              "KeyedLoadIC")                      \
141
  V(KEYED_LOAD_POLYMORPHIC_IC_TAG,  "KeyedLoadPolymorphicIC")           \
danno@chromium.org's avatar
danno@chromium.org committed
142 143
  V(KEYED_EXTERNAL_ARRAY_LOAD_IC_TAG, "KeyedExternalArrayLoadIC")       \
  V(KEYED_STORE_IC_TAG,             "KeyedStoreIC")                     \
144
  V(KEYED_STORE_POLYMORPHIC_IC_TAG, "KeyedStorePolymorphicIC")          \
danno@chromium.org's avatar
danno@chromium.org committed
145 146 147
  V(KEYED_EXTERNAL_ARRAY_STORE_IC_TAG, "KeyedExternalArrayStoreIC")     \
  V(LAZY_COMPILE_TAG,               "LazyCompile")                      \
  V(LOAD_IC_TAG,                    "LoadIC")                           \
148
  V(LOAD_POLYMORPHIC_IC_TAG,        "LoadPolymorphicIC")                \
danno@chromium.org's avatar
danno@chromium.org committed
149 150 151
  V(REG_EXP_TAG,                    "RegExp")                           \
  V(SCRIPT_TAG,                     "Script")                           \
  V(STORE_IC_TAG,                   "StoreIC")                          \
152
  V(STORE_POLYMORPHIC_IC_TAG,       "StorePolymorphicIC")               \
danno@chromium.org's avatar
danno@chromium.org committed
153 154 155
  V(STUB_TAG,                       "Stub")                             \
  V(NATIVE_FUNCTION_TAG,            "Function")                         \
  V(NATIVE_LAZY_COMPILE_TAG,        "LazyCompile")                      \
156
  V(NATIVE_SCRIPT_TAG,              "Script")
mikhail.naganov@gmail.com's avatar
mikhail.naganov@gmail.com committed
157 158 159
// Note that 'NATIVE_' cases for functions and scripts are mapped onto
// original tags when writing to the log.

160

161
class JitLogger;
162
class PerfBasicLogger;
163
class LowLevelLogger;
164
class PerfJitLogger;
165 166
class Sampler;

167 168
class Logger {
 public:
169
#define DECLARE_ENUM(enum_item, ignore) enum_item,
170 171 172 173 174 175
  enum LogEventsAndTags {
    LOG_EVENTS_AND_TAGS_LIST(DECLARE_ENUM)
    NUMBER_OF_LOG_EVENTS
  };
#undef DECLARE_ENUM

176
  // Acquires resources for logging if the right flags are set.
177
  bool SetUp(Isolate* isolate);
178

179 180 181 182
  // Sets the current code event handler.
  void SetCodeEventHandler(uint32_t options,
                           JitCodeEventHandler event_handler);

183
  Sampler* sampler();
184

185
  // Frees resources acquired in SetUp.
186 187 188
  // When a temporary file is used for the log, returns its stream descriptor,
  // leaving the file open.
  FILE* TearDown();
189 190

  // Emits an event with a string value -> (name, value).
191
  void StringEvent(const char* name, const char* value);
192 193

  // Emits an event with an int value -> (name, value).
194 195
  void IntEvent(const char* name, int value);
  void IntPtrTEvent(const char* name, intptr_t value);
196 197

  // Emits an event with an handle value -> (name, location).
198
  void HandleEvent(const char* name, Object** location);
199 200

  // Emits memory management events for C allocated structures.
201 202 203 204 205 206 207
  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);
208 209 210 211 212

  // 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.
213
  void ResourceEvent(const char* name, const char* tag);
214 215 216

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

219 220
  // 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.
221 222
  void DebugTag(const char* call_site_tag);
  void DebugEvent(const char* event_type, Vector<uint16_t> parameter);
223

224 225

  // ==== Events logged by --log-api. ====
226 227 228 229 230 231 232 233
  void ApiNamedSecurityCheck(Object* key);
  void ApiIndexedSecurityCheck(uint32_t index);
  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);
234 235 236


  // ==== Events logged by --log-code. ====
237 238 239 240 241
  void addCodeEventListener(CodeEventListener* listener);
  void removeCodeEventListener(CodeEventListener* listener);
  bool hasCodeEventListener(CodeEventListener* listener);


242
  // Emits a code event for a callback function.
243 244 245
  void CallbackEvent(Name* name, Address entry_point);
  void GetterCallbackEvent(Name* name, Address entry_point);
  void SetterCallbackEvent(Name* name, Address entry_point);
246
  // Emits a code create event.
247 248 249
  void CodeCreateEvent(LogEventsAndTags tag,
                       Code* code, const char* source);
  void CodeCreateEvent(LogEventsAndTags tag,
250
                       Code* code, Name* name);
251 252 253
  void CodeCreateEvent(LogEventsAndTags tag,
                       Code* code,
                       SharedFunctionInfo* shared,
254
                       CompilationInfo* info,
255
                       Name* name);
256 257 258
  void CodeCreateEvent(LogEventsAndTags tag,
                       Code* code,
                       SharedFunctionInfo* shared,
259
                       CompilationInfo* info,
260
                       Name* source, int line, int column);
261 262
  void CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count);
  void CodeMovingGCEvent();
263
  // Emits a code create event for a RegExp.
264
  void RegExpCodeCreateEvent(Code* code, String* source);
265
  // Emits a code move event.
266
  void CodeMoveEvent(Address from, Address to);
267
  // Emits a code delete event.
268
  void CodeDeleteEvent(Address from);
269 270 271 272 273 274 275 276 277 278 279 280 281
  // 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);
282

283
  void SharedFunctionInfoMoveEvent(Address from, Address to);
284

285
  void CodeNameEvent(Address addr, int pos, const char* code_name);
286
  void SnapshotPositionEvent(Address addr, int pos);
287

288 289
  // ==== Events logged by --log-gc. ====
  // Heap sampling events: start, end, and individual types.
290 291 292 293 294 295
  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,
296
                                         const char* event);
297 298 299 300 301 302 303 304 305 306 307
  void HeapSampleJSProducerEvent(const char* constructor,
                                 Address* stack);
  void HeapSampleStats(const char* space, const char* kind,
                       intptr_t capacity, intptr_t used);

  void SharedLibraryEvent(const char* library_path,
                          uintptr_t start,
                          uintptr_t end);
  void SharedLibraryEvent(const wchar_t* library_path,
                          uintptr_t start,
                          uintptr_t end);
308 309

  // ==== Events logged by --log-timer-events. ====
310 311
  enum StartEnd { START, END };

312 313
  void CodeDeoptEvent(Code* code);

314
  void TimerEvent(StartEnd se, const char* name);
315

316 317
  static void EnterExternal(Isolate* isolate);
  static void LeaveExternal(Isolate* isolate);
318

319 320 321
  static void EmptyLogInternalEvents(const char* name, int se) { }
  static void LogInternalEvents(const char* name, int se);

322 323
  class TimerEventScope {
   public:
324
    TimerEventScope(Isolate* isolate, const char* name)
325
        : isolate_(isolate), name_(name) {
326
      LogTimerEvent(START);
327 328 329
    }

    ~TimerEventScope() {
330
      LogTimerEvent(END);
331 332
    }

333
    void LogTimerEvent(StartEnd se);
334

335
    static const char* v8_recompile_synchronous;
336
    static const char* v8_recompile_concurrent;
337 338
    static const char* v8_compile_full_code;
    static const char* v8_execute;
339
    static const char* v8_external;
340 341

   private:
342
    Isolate* isolate_;
343 344
    const char* name_;
  };
345

346 347 348
  // ==== Events logged by --log-regexp ====
  // Regexp compilation and execution events.

349
  void RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache);
350

351
  // Log an event reported from generated code
352
  void LogRuntime(Vector<const char> format, Handle<JSArray> args);
353

354
  bool is_logging() {
355
    return is_logging_;
356
  }
357

358
  bool is_logging_code_events() {
359
    return is_logging() || jit_logger_ != NULL;
360 361
  }

362 363 364
  // Stop collection of profiling data.
  // When data collection is paused, CPU Tick events are discarded.
  void StopProfiler();
365

366 367
  void LogExistingFunction(Handle<SharedFunctionInfo> shared,
                           Handle<Code> code);
368
  // Logs all compiled functions found in the heap.
369
  void LogCompiledFunctions();
370
  // Logs all accessor callbacks found in the heap.
371
  void LogAccessorCallbacks();
372
  // Used for logging stubs found in the snapshot.
373
  void LogCodeObjects();
374

375 376 377
  // Converts tag to a corresponding NATIVE_... if the script is native.
  INLINE(static LogEventsAndTags ToNativeByScript(LogEventsAndTags, Script*));

378
  // Profiler's sampling interval (in milliseconds).
379 380 381 382 383
#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
384
  static const int kSamplingIntervalMs = 1;
385
#endif
386

387 388 389
  // Callback from Log, stops profiling in case of insufficient resources.
  void LogFailure();

390
 private:
391
  explicit Logger(Isolate* isolate);
392
  ~Logger();
393

394
  // Emits the profiler's first message.
395
  void ProfilerBeginEvent();
396

397
  // Emits callback event messages.
398
  void CallbackEventInternal(const char* prefix,
399
                             Name* name,
400
                             Address entry_point);
401

402
  // Internal configurable move event.
403
  void MoveEventInternal(LogEventsAndTags event, Address from, Address to);
404

405
  // Emits the source code of a regexp. Used by regexp events.
406
  void LogRegExpSource(Handle<JSRegExp> regexp);
407

408
  // Used for logging stubs found in the snapshot.
409
  void LogCodeObject(Object* code_object);
410

411 412 413
  // Helper method. It resets name_buffer_ and add tag name into it.
  void InitNameBuffer(LogEventsAndTags tag);

414
  // Emits a profiler tick event. Used by the profiler thread.
415
  void TickEvent(TickSample* sample, bool overflow);
416

417
  void ApiEvent(const char* name, ...);
418

419
  // Logs a StringEvent regardless of whether FLAG_log is true.
420
  void UncheckedStringEvent(const char* name, const char* value);
421

422
  // Logs an IntEvent regardless of whether FLAG_log is true.
423 424
  void UncheckedIntEvent(const char* name, int value);
  void UncheckedIntPtrTEvent(const char* name, intptr_t value);
425

426 427
  Isolate* isolate_;

428
  // The sampler used by the profiler and the sliding state window.
429
  Ticker* ticker_;
430 431 432 433

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

436 437
  // An array of log events names.
  const char* const* log_events_;
438 439 440 441

  // Internal implementation classes with access to
  // private members.
  friend class EventLog;
442
  friend class Isolate;
443 444
  friend class TimeLog;
  friend class Profiler;
445
  template <StateTag Tag> friend class VMState;
446
  friend class LoggerTestHelper;
447

448
  bool is_logging_;
449
  Log* log_;
450 451
  PerfBasicLogger* perf_basic_logger_;
  PerfJitLogger* perf_jit_logger_;
452
  LowLevelLogger* ll_logger_;
453
  JitLogger* jit_logger_;
454
  List<CodeEventListener*> listeners_;
455

456
  // Guards against multiple calls to TearDown() that can happen in some tests.
457
  // 'true' between SetUp() and TearDown().
458 459
  bool is_initialized_;

460
  ElapsedTimer timer_;
461

462
  friend class CpuProfiler;
463 464 465
};


466 467 468 469 470 471 472 473 474 475 476 477 478 479 480 481 482 483 484 485
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,
486
                               int line, int column) = 0;
487 488 489 490 491 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 519 520 521 522 523 524
  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;
};


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,
525
                               int line, int column);
526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545
  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_;
};


546 547
} }  // namespace v8::internal

548

549
#endif  // V8_LOG_H_