The data contained in this repository can be downloaded to your computer using one of several clients.
Please see the documentation of your version control software client for more information.

Please select the desired protocol below to get the URL.

This URL has Read-Only access.

Statistics
| Branch: | Revision:

main_repo / deps / v8 / src / log.cc @ 40c0f755

History | View | Annotate | Download (32.1 KB)

1 40c0f755 Ryan
// Copyright 2009 the V8 project authors. All rights reserved.
2
// Redistribution and use in source and binary forms, with or without
3
// modification, are permitted provided that the following conditions are
4
// met:
5
//
6
//     * Redistributions of source code must retain the above copyright
7
//       notice, this list of conditions and the following disclaimer.
8
//     * Redistributions in binary form must reproduce the above
9
//       copyright notice, this list of conditions and the following
10
//       disclaimer in the documentation and/or other materials provided
11
//       with the distribution.
12
//     * Neither the name of Google Inc. nor the names of its
13
//       contributors may be used to endorse or promote products derived
14
//       from this software without specific prior written permission.
15
//
16
// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
17
// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
18
// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
19
// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
20
// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
21
// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
22
// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
23
// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
24
// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
25
// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
26
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
27
28
#include <stdarg.h>
29
30
#include "v8.h"
31
32
#include "bootstrapper.h"
33
#include "log.h"
34
#include "macro-assembler.h"
35
#include "platform.h"
36
#include "serialize.h"
37
#include "string-stream.h"
38
39
namespace v8 { namespace internal {
40
41
#ifdef ENABLE_LOGGING_AND_PROFILING
42
43
//
44
// Sliding state window.  Updates counters to keep track of the last
45
// window of kBufferSize states.  This is useful to track where we
46
// spent our time.
47
//
48
class SlidingStateWindow {
49
 public:
50
  SlidingStateWindow();
51
  ~SlidingStateWindow();
52
  void AddState(StateTag state);
53
54
 private:
55
  static const int kBufferSize = 256;
56
  int current_index_;
57
  bool is_full_;
58
  byte buffer_[kBufferSize];
59
60
61
  void IncrementStateCounter(StateTag state) {
62
    Counters::state_counters[state].Increment();
63
  }
64
65
66
  void DecrementStateCounter(StateTag state) {
67
    Counters::state_counters[state].Decrement();
68
  }
69
};
70
71
72
//
73
// The Profiler samples pc and sp values for the main thread.
74
// Each sample is appended to a circular buffer.
75
// An independent thread removes data and writes it to the log.
76
// This design minimizes the time spent in the sampler.
77
//
78
class Profiler: public Thread {
79
 public:
80
  Profiler();
81
  void Engage();
82
  void Disengage();
83
84
  // Inserts collected profiling data into buffer.
85
  void Insert(TickSample* sample) {
86
    if (paused_)
87
      return;
88
89
    if (Succ(head_) == tail_) {
90
      overflow_ = true;
91
    } else {
92
      buffer_[head_] = *sample;
93
      head_ = Succ(head_);
94
      buffer_semaphore_->Signal();  // Tell we have an element.
95
    }
96
  }
97
98
  // Waits for a signal and removes profiling data.
99
  bool Remove(TickSample* sample) {
100
    buffer_semaphore_->Wait();  // Wait for an element.
101
    *sample = buffer_[tail_];
102
    bool result = overflow_;
103
    tail_ = Succ(tail_);
104
    overflow_ = false;
105
    return result;
106
  }
107
108
  void Run();
109
110
  // Pause and Resume TickSample data collection.
111
  static bool paused() { return paused_; }
112
  static void pause() { paused_ = true; }
113
  static void resume() { paused_ = false; }
114
115
 private:
116
  // Returns the next index in the cyclic buffer.
117
  int Succ(int index) { return (index + 1) % kBufferSize; }
118
119
  // Cyclic buffer for communicating profiling samples
120
  // between the signal handler and the worker thread.
121
  static const int kBufferSize = 128;
122
  TickSample buffer_[kBufferSize];  // Buffer storage.
123
  int head_;  // Index to the buffer head.
124
  int tail_;  // Index to the buffer tail.
125
  bool overflow_;  // Tell whether a buffer overflow has occurred.
126
  Semaphore* buffer_semaphore_;  // Sempahore used for buffer synchronization.
127
128
  // Tells whether worker thread should continue running.
129
  bool running_;
130
131
  // Tells whether we are currently recording tick samples.
132
  static bool paused_;
133
};
134
135
bool Profiler::paused_ = false;
136
137
138
//
139
// StackTracer implementation
140
//
141
void StackTracer::Trace(TickSample* sample) {
142
  if (sample->state == GC) {
143
    sample->frames_count = 0;
144
    return;
145
  }
146
147
  SafeStackTraceFrameIterator it(
148
      reinterpret_cast<Address>(sample->fp),
149
      reinterpret_cast<Address>(sample->sp),
150
      reinterpret_cast<Address>(sample->sp),
151
      reinterpret_cast<Address>(low_stack_bound_));
152
  int i = 0;
153
  while (!it.done() && i < TickSample::kMaxFramesCount) {
154
    sample->stack[i++] = it.frame()->pc();
155
    it.Advance();
156
  }
157
  sample->frames_count = i;
158
}
159
160
161
//
162
// Ticker used to provide ticks to the profiler and the sliding state
163
// window.
164
//
165
class Ticker: public Sampler {
166
 public:
167
  explicit Ticker(int interval, unsigned int low_stack_bound):
168
      Sampler(interval, FLAG_prof), window_(NULL), profiler_(NULL),
169
      stack_tracer_(low_stack_bound) {}
170
171
  ~Ticker() { if (IsActive()) Stop(); }
172
173
  void Tick(TickSample* sample) {
174
    if (IsProfiling()) stack_tracer_.Trace(sample);
175
    if (profiler_) profiler_->Insert(sample);
176
    if (window_) window_->AddState(sample->state);
177
  }
178
179
  void SetWindow(SlidingStateWindow* window) {
180
    window_ = window;
181
    if (!IsActive()) Start();
182
  }
183
184
  void ClearWindow() {
185
    window_ = NULL;
186
    if (!profiler_ && IsActive()) Stop();
187
  }
188
189
  void SetProfiler(Profiler* profiler) {
190
    profiler_ = profiler;
191
    if (!IsActive()) Start();
192
  }
193
194
  void ClearProfiler() {
195
    profiler_ = NULL;
196
    if (!window_ && IsActive()) Stop();
197
  }
198
199
 private:
200
  SlidingStateWindow* window_;
201
  Profiler* profiler_;
202
  StackTracer stack_tracer_;
203
};
204
205
206
//
207
// SlidingStateWindow implementation.
208
//
209
SlidingStateWindow::SlidingStateWindow(): current_index_(0), is_full_(false) {
210
  for (int i = 0; i < kBufferSize; i++) {
211
    buffer_[i] = static_cast<byte>(OTHER);
212
  }
213
  Logger::ticker_->SetWindow(this);
214
}
215
216
217
SlidingStateWindow::~SlidingStateWindow() {
218
  Logger::ticker_->ClearWindow();
219
}
220
221
222
void SlidingStateWindow::AddState(StateTag state) {
223
  if (is_full_) {
224
    DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
225
  } else if (current_index_ == kBufferSize - 1) {
226
    is_full_ = true;
227
  }
228
  buffer_[current_index_] = static_cast<byte>(state);
229
  IncrementStateCounter(state);
230
  ASSERT(IsPowerOf2(kBufferSize));
231
  current_index_ = (current_index_ + 1) & (kBufferSize - 1);
232
}
233
234
235
//
236
// Profiler implementation.
237
//
238
Profiler::Profiler() {
239
  buffer_semaphore_ = OS::CreateSemaphore(0);
240
  head_ = 0;
241
  tail_ = 0;
242
  overflow_ = false;
243
  running_ = false;
244
}
245
246
247
void Profiler::Engage() {
248
  OS::LogSharedLibraryAddresses();
249
250
  // Start thread processing the profiler buffer.
251
  running_ = true;
252
  Start();
253
254
  // Register to get ticks.
255
  Logger::ticker_->SetProfiler(this);
256
257
  LOG(UncheckedStringEvent("profiler", "begin"));
258
}
259
260
261
void Profiler::Disengage() {
262
  // Stop receiving ticks.
263
  Logger::ticker_->ClearProfiler();
264
265
  // Terminate the worker thread by setting running_ to false,
266
  // inserting a fake element in the queue and then wait for
267
  // the thread to terminate.
268
  running_ = false;
269
  TickSample sample;
270
  Insert(&sample);
271
  Join();
272
273
  LOG(UncheckedStringEvent("profiler", "end"));
274
}
275
276
277
void Profiler::Run() {
278
  TickSample sample;
279
  bool overflow = Logger::profiler_->Remove(&sample);
280
  while (running_) {
281
    LOG(TickEvent(&sample, overflow));
282
    overflow = Logger::profiler_->Remove(&sample);
283
  }
284
}
285
286
287
#ifdef ENABLE_LOGGING_AND_PROFILING
288
// Utility class for formatting log messages. It fills the message into the
289
// static buffer in Logger.
290
class LogMessageBuilder BASE_EMBEDDED {
291
 public:
292
  explicit LogMessageBuilder();
293
  ~LogMessageBuilder() { }
294
295
  void Append(const char* format, ...);
296
  void Append(const char* format, va_list args);
297
  void Append(const char c);
298
  void Append(String *str);
299
  void AppendDetailed(String* str, bool show_impl_info);
300
301
  void WriteToLogFile();
302
  void WriteCStringToLogFile(const char* str);
303
304
 private:
305
  ScopedLock sl;
306
  int pos_;
307
};
308
309
310
// Create a message builder starting from position 0. This acquires the mutex
311
// in the logger as well.
312
LogMessageBuilder::LogMessageBuilder(): sl(Logger::mutex_), pos_(0) {
313
  ASSERT(Logger::message_buffer_ != NULL);
314
}
315
316
317
// Append string data to the log message.
318
void LogMessageBuilder::Append(const char* format, ...) {
319
  Vector<char> buf(Logger::message_buffer_ + pos_,
320
                   Logger::kMessageBufferSize - pos_);
321
  va_list args;
322
  va_start(args, format);
323
  Append(format, args);
324
  va_end(args);
325
  ASSERT(pos_ <= Logger::kMessageBufferSize);
326
}
327
328
329
// Append string data to the log message.
330
void LogMessageBuilder::Append(const char* format, va_list args) {
331
  Vector<char> buf(Logger::message_buffer_ + pos_,
332
                   Logger::kMessageBufferSize - pos_);
333
  int result = v8::internal::OS::VSNPrintF(buf, format, args);
334
335
  // Result is -1 if output was truncated.
336
  if (result >= 0) {
337
    pos_ += result;
338
  } else {
339
    pos_ = Logger::kMessageBufferSize;
340
  }
341
  ASSERT(pos_ <= Logger::kMessageBufferSize);
342
}
343
344
345
// Append a character to the log message.
346
void LogMessageBuilder::Append(const char c) {
347
  if (pos_ < Logger::kMessageBufferSize) {
348
    Logger::message_buffer_[pos_++] = c;
349
  }
350
  ASSERT(pos_ <= Logger::kMessageBufferSize);
351
}
352
353
354
// Append a heap string.
355
void LogMessageBuilder::Append(String* str) {
356
  AssertNoAllocation no_heap_allocation;  // Ensure string stay valid.
357
  int length = str->length();
358
  for (int i = 0; i < length; i++) {
359
    Append(static_cast<char>(str->Get(i)));
360
  }
361
}
362
363
void LogMessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
364
  AssertNoAllocation no_heap_allocation;  // Ensure string stay valid.
365
  int len = str->length();
366
  if (len > 0x1000)
367
    len = 0x1000;
368
  if (show_impl_info) {
369
    Append(StringShape(str).IsAsciiRepresentation() ? 'a' : '2');
370
    if (StringShape(str).IsExternal())
371
      Append('e');
372
    if (StringShape(str).IsSymbol())
373
      Append('#');
374
    Append(":%i:", str->length());
375
  }
376
  for (int i = 0; i < len; i++) {
377
    uc32 c = str->Get(i);
378
    if (c > 0xff) {
379
      Append("\\u%04x", c);
380
    } else if (c < 32 || c > 126) {
381
      Append("\\x%02x", c);
382
    } else if (c == ',') {
383
      Append("\\,");
384
    } else if (c == '\\') {
385
      Append("\\\\");
386
    } else {
387
      Append("%lc", c);
388
    }
389
  }
390
}
391
392
// Write the log message to the log file currently opened.
393
void LogMessageBuilder::WriteToLogFile() {
394
  ASSERT(pos_ <= Logger::kMessageBufferSize);
395
  size_t rv = fwrite(Logger::message_buffer_, 1, pos_, Logger::logfile_);
396
  ASSERT(rv == static_cast<size_t>(pos_));
397
  USE(rv);
398
}
399
400
// Write a null-terminated string to to the log file currently opened.
401
void LogMessageBuilder::WriteCStringToLogFile(const char* str) {
402
  size_t len = strlen(str);
403
  size_t rv = fwrite(str, 1, len, Logger::logfile_);
404
  ASSERT(rv == len);
405
  USE(rv);
406
}
407
#endif
408
409
410
//
411
// Logger class implementation.
412
//
413
Ticker* Logger::ticker_ = NULL;
414
char* Logger::message_buffer_ = NULL;
415
FILE* Logger::logfile_ = NULL;
416
Profiler* Logger::profiler_ = NULL;
417
Mutex* Logger::mutex_ = NULL;
418
VMState* Logger::current_state_ = NULL;
419
VMState Logger::bottom_state_(EXTERNAL);
420
SlidingStateWindow* Logger::sliding_state_window_ = NULL;
421
422
#endif  // ENABLE_LOGGING_AND_PROFILING
423
424
425
void Logger::Preamble(const char* content) {
426
#ifdef ENABLE_LOGGING_AND_PROFILING
427
  if (logfile_ == NULL || !FLAG_log_code) return;
428
  LogMessageBuilder msg;
429
  msg.WriteCStringToLogFile(content);
430
#endif
431
}
432
433
434
void Logger::StringEvent(const char* name, const char* value) {
435
#ifdef ENABLE_LOGGING_AND_PROFILING
436
  if (FLAG_log) UncheckedStringEvent(name, value);
437
#endif
438
}
439
440
441
#ifdef ENABLE_LOGGING_AND_PROFILING
442
void Logger::UncheckedStringEvent(const char* name, const char* value) {
443
  if (logfile_ == NULL) return;
444
  LogMessageBuilder msg;
445
  msg.Append("%s,\"%s\"\n", name, value);
446
  msg.WriteToLogFile();
447
}
448
#endif
449
450
451
void Logger::IntEvent(const char* name, int value) {
452
#ifdef ENABLE_LOGGING_AND_PROFILING
453
  if (logfile_ == NULL || !FLAG_log) return;
454
  LogMessageBuilder msg;
455
  msg.Append("%s,%d\n", name, value);
456
  msg.WriteToLogFile();
457
#endif
458
}
459
460
461
void Logger::HandleEvent(const char* name, Object** location) {
462
#ifdef ENABLE_LOGGING_AND_PROFILING
463
  if (logfile_ == NULL || !FLAG_log_handles) return;
464
  LogMessageBuilder msg;
465
  msg.Append("%s,0x%x\n", name,
466
             reinterpret_cast<unsigned int>(location));
467
  msg.WriteToLogFile();
468
#endif
469
}
470
471
472
#ifdef ENABLE_LOGGING_AND_PROFILING
473
// ApiEvent is private so all the calls come from the Logger class.  It is the
474
// caller's responsibility to ensure that logfile_ is not NULL and that
475
// FLAG_log_api is true.
476
void Logger::ApiEvent(const char* format, ...) {
477
  ASSERT(logfile_ != NULL && FLAG_log_api);
478
  LogMessageBuilder msg;
479
  va_list ap;
480
  va_start(ap, format);
481
  msg.Append(format, ap);
482
  va_end(ap);
483
  msg.WriteToLogFile();
484
}
485
#endif
486
487
488
void Logger::ApiNamedSecurityCheck(Object* key) {
489
#ifdef ENABLE_LOGGING_AND_PROFILING
490
  if (logfile_ == NULL || !FLAG_log_api) return;
491
  if (key->IsString()) {
492
    SmartPointer<char> str =
493
        String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
494
    ApiEvent("api,check-security,\"%s\"\n", *str);
495
  } else if (key->IsUndefined()) {
496
    ApiEvent("api,check-security,undefined\n");
497
  } else {
498
    ApiEvent("api,check-security,['no-name']\n");
499
  }
500
#endif
501
}
502
503
504
void Logger::SharedLibraryEvent(const char* library_path,
505
                                unsigned start,
506
                                unsigned end) {
507
#ifdef ENABLE_LOGGING_AND_PROFILING
508
  if (logfile_ == NULL || !FLAG_prof) return;
509
  LogMessageBuilder msg;
510
  msg.Append("shared-library,\"%s\",0x%08x,0x%08x\n", library_path,
511
             start, end);
512
  msg.WriteToLogFile();
513
#endif
514
}
515
516
517
void Logger::SharedLibraryEvent(const wchar_t* library_path,
518
                                unsigned start,
519
                                unsigned end) {
520
#ifdef ENABLE_LOGGING_AND_PROFILING
521
  if (logfile_ == NULL || !FLAG_prof) return;
522
  LogMessageBuilder msg;
523
  msg.Append("shared-library,\"%ls\",0x%08x,0x%08x\n", library_path,
524
             start, end);
525
  msg.WriteToLogFile();
526
#endif
527
}
528
529
530
#ifdef ENABLE_LOGGING_AND_PROFILING
531
void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
532
  // Prints "/" + re.source + "/" +
533
  //      (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
534
  LogMessageBuilder msg;
535
536
  Handle<Object> source = GetProperty(regexp, "source");
537
  if (!source->IsString()) {
538
    msg.Append("no source");
539
    return;
540
  }
541
542
  switch (regexp->TypeTag()) {
543
    case JSRegExp::ATOM:
544
      msg.Append('a');
545
      break;
546
    default:
547
      break;
548
  }
549
  msg.Append('/');
550
  msg.AppendDetailed(*Handle<String>::cast(source), false);
551
  msg.Append('/');
552
553
  // global flag
554
  Handle<Object> global = GetProperty(regexp, "global");
555
  if (global->IsTrue()) {
556
    msg.Append('g');
557
  }
558
  // ignorecase flag
559
  Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
560
  if (ignorecase->IsTrue()) {
561
    msg.Append('i');
562
  }
563
  // multiline flag
564
  Handle<Object> multiline = GetProperty(regexp, "multiline");
565
  if (multiline->IsTrue()) {
566
    msg.Append('m');
567
  }
568
569
  msg.WriteToLogFile();
570
}
571
#endif  // ENABLE_LOGGING_AND_PROFILING
572
573
574
void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
575
#ifdef ENABLE_LOGGING_AND_PROFILING
576
  if (logfile_ == NULL || !FLAG_log_regexp) return;
577
  LogMessageBuilder msg;
578
  msg.Append("regexp-compile,");
579
  LogRegExpSource(regexp);
580
  msg.Append(in_cache ? ",hit\n" : ",miss\n");
581
  msg.WriteToLogFile();
582
#endif
583
}
584
585
586
void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
587
#ifdef ENABLE_LOGGING_AND_PROFILING
588
  if (logfile_ == NULL || !FLAG_log_runtime) return;
589
  HandleScope scope;
590
  LogMessageBuilder msg;
591
  for (int i = 0; i < format.length(); i++) {
592
    char c = format[i];
593
    if (c == '%' && i <= format.length() - 2) {
594
      i++;
595
      ASSERT('0' <= format[i] && format[i] <= '9');
596
      Object* obj = args->GetElement(format[i] - '0');
597
      i++;
598
      switch (format[i]) {
599
        case 's':
600
          msg.AppendDetailed(String::cast(obj), false);
601
          break;
602
        case 'S':
603
          msg.AppendDetailed(String::cast(obj), true);
604
          break;
605
        case 'r':
606
          Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
607
          break;
608
        case 'x':
609
          msg.Append("0x%x", Smi::cast(obj)->value());
610
          break;
611
        case 'i':
612
          msg.Append("%i", Smi::cast(obj)->value());
613
          break;
614
        default:
615
          UNREACHABLE();
616
      }
617
    } else {
618
      msg.Append(c);
619
    }
620
  }
621
  msg.Append('\n');
622
  msg.WriteToLogFile();
623
#endif
624
}
625
626
627
void Logger::ApiIndexedSecurityCheck(uint32_t index) {
628
#ifdef ENABLE_LOGGING_AND_PROFILING
629
  if (logfile_ == NULL || !FLAG_log_api) return;
630
  ApiEvent("api,check-security,%u\n", index);
631
#endif
632
}
633
634
635
void Logger::ApiNamedPropertyAccess(const char* tag,
636
                                    JSObject* holder,
637
                                    Object* name) {
638
#ifdef ENABLE_LOGGING_AND_PROFILING
639
  ASSERT(name->IsString());
640
  if (logfile_ == NULL || !FLAG_log_api) return;
641
  String* class_name_obj = holder->class_name();
642
  SmartPointer<char> class_name =
643
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
644
  SmartPointer<char> property_name =
645
      String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
646
  Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
647
#endif
648
}
649
650
void Logger::ApiIndexedPropertyAccess(const char* tag,
651
                                      JSObject* holder,
652
                                      uint32_t index) {
653
#ifdef ENABLE_LOGGING_AND_PROFILING
654
  if (logfile_ == NULL || !FLAG_log_api) return;
655
  String* class_name_obj = holder->class_name();
656
  SmartPointer<char> class_name =
657
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
658
  Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
659
#endif
660
}
661
662
void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
663
#ifdef ENABLE_LOGGING_AND_PROFILING
664
  if (logfile_ == NULL || !FLAG_log_api) return;
665
  String* class_name_obj = object->class_name();
666
  SmartPointer<char> class_name =
667
      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
668
  Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
669
#endif
670
}
671
672
673
void Logger::ApiEntryCall(const char* name) {
674
#ifdef ENABLE_LOGGING_AND_PROFILING
675
  if (logfile_ == NULL || !FLAG_log_api) return;
676
  Logger::ApiEvent("api,%s\n", name);
677
#endif
678
}
679
680
681
void Logger::NewEvent(const char* name, void* object, size_t size) {
682
#ifdef ENABLE_LOGGING_AND_PROFILING
683
  if (logfile_ == NULL || !FLAG_log) return;
684
  LogMessageBuilder msg;
685
  msg.Append("new,%s,0x%x,%u\n", name,
686
             reinterpret_cast<unsigned int>(object),
687
             static_cast<unsigned int>(size));
688
  msg.WriteToLogFile();
689
#endif
690
}
691
692
693
void Logger::DeleteEvent(const char* name, void* object) {
694
#ifdef ENABLE_LOGGING_AND_PROFILING
695
  if (logfile_ == NULL || !FLAG_log) return;
696
  LogMessageBuilder msg;
697
  msg.Append("delete,%s,0x%x\n", name,
698
             reinterpret_cast<unsigned int>(object));
699
  msg.WriteToLogFile();
700
#endif
701
}
702
703
704
void Logger::CodeCreateEvent(const char* tag, Code* code, const char* comment) {
705
#ifdef ENABLE_LOGGING_AND_PROFILING
706
  if (logfile_ == NULL || !FLAG_log_code) return;
707
  LogMessageBuilder msg;
708
  msg.Append("code-creation,%s,0x%x,%d,\"", tag,
709
             reinterpret_cast<unsigned int>(code->address()),
710
             code->ExecutableSize());
711
  for (const char* p = comment; *p != '\0'; p++) {
712
    if (*p == '"') {
713
      msg.Append('\\');
714
    }
715
    msg.Append(*p);
716
  }
717
  msg.Append('"');
718
  msg.Append('\n');
719
  msg.WriteToLogFile();
720
#endif
721
}
722
723
724
void Logger::CodeCreateEvent(const char* tag, Code* code, String* name) {
725
#ifdef ENABLE_LOGGING_AND_PROFILING
726
  if (logfile_ == NULL || !FLAG_log_code) return;
727
  LogMessageBuilder msg;
728
  SmartPointer<char> str =
729
      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
730
  msg.Append("code-creation,%s,0x%x,%d,\"%s\"\n", tag,
731
             reinterpret_cast<unsigned int>(code->address()),
732
             code->ExecutableSize(), *str);
733
  msg.WriteToLogFile();
734
#endif
735
}
736
737
738
void Logger::CodeCreateEvent(const char* tag, Code* code, String* name,
739
                             String* source, int line) {
740
#ifdef ENABLE_LOGGING_AND_PROFILING
741
  if (logfile_ == NULL || !FLAG_log_code) return;
742
  LogMessageBuilder msg;
743
  SmartPointer<char> str =
744
      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
745
  SmartPointer<char> sourcestr =
746
      source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
747
  msg.Append("code-creation,%s,0x%x,%d,\"%s %s:%d\"\n", tag,
748
             reinterpret_cast<unsigned int>(code->address()),
749
             code->ExecutableSize(),
750
             *str, *sourcestr, line);
751
  msg.WriteToLogFile();
752
#endif
753
}
754
755
756
void Logger::CodeCreateEvent(const char* tag, Code* code, int args_count) {
757
#ifdef ENABLE_LOGGING_AND_PROFILING
758
  if (logfile_ == NULL || !FLAG_log_code) return;
759
  LogMessageBuilder msg;
760
  msg.Append("code-creation,%s,0x%x,%d,\"args_count: %d\"\n", tag,
761
             reinterpret_cast<unsigned int>(code->address()),
762
             code->ExecutableSize(),
763
             args_count);
764
  msg.WriteToLogFile();
765
#endif
766
}
767
768
769
void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
770
#ifdef ENABLE_LOGGING_AND_PROFILING
771
  if (logfile_ == NULL || !FLAG_log_code) return;
772
  LogMessageBuilder msg;
773
  msg.Append("code-creation,%s,0x%x,%d,\"", "RegExp",
774
             reinterpret_cast<unsigned int>(code->address()),
775
             code->ExecutableSize());
776
  msg.AppendDetailed(source, false);
777
  msg.Append("\"\n");
778
  msg.WriteToLogFile();
779
#endif
780
}
781
782
783
void Logger::CodeAllocateEvent(Code* code, Assembler* assem) {
784
#ifdef ENABLE_LOGGING_AND_PROFILING
785
  if (logfile_ == NULL || !FLAG_log_code) return;
786
  LogMessageBuilder msg;
787
  msg.Append("code-allocate,0x%x,0x%x\n",
788
             reinterpret_cast<unsigned int>(code->address()),
789
             reinterpret_cast<unsigned int>(assem));
790
  msg.WriteToLogFile();
791
#endif
792
}
793
794
795
void Logger::CodeMoveEvent(Address from, Address to) {
796
#ifdef ENABLE_LOGGING_AND_PROFILING
797
  if (logfile_ == NULL || !FLAG_log_code) return;
798
  LogMessageBuilder msg;
799
  msg.Append("code-move,0x%x,0x%x\n",
800
             reinterpret_cast<unsigned int>(from),
801
             reinterpret_cast<unsigned int>(to));
802
  msg.WriteToLogFile();
803
#endif
804
}
805
806
807
void Logger::CodeDeleteEvent(Address from) {
808
#ifdef ENABLE_LOGGING_AND_PROFILING
809
  if (logfile_ == NULL || !FLAG_log_code) return;
810
  LogMessageBuilder msg;
811
  msg.Append("code-delete,0x%x\n", reinterpret_cast<unsigned int>(from));
812
  msg.WriteToLogFile();
813
#endif
814
}
815
816
817
void Logger::BeginCodeRegionEvent(CodeRegion* region,
818
                                  Assembler* masm,
819
                                  const char* name) {
820
#ifdef ENABLE_LOGGING_AND_PROFILING
821
  if (logfile_ == NULL || !FLAG_log_code) return;
822
  LogMessageBuilder msg;
823
  msg.Append("begin-code-region,0x%x,0x%x,0x%x,%s\n",
824
             reinterpret_cast<unsigned int>(region),
825
             reinterpret_cast<unsigned int>(masm),
826
             masm->pc_offset(),
827
             name);
828
  msg.WriteToLogFile();
829
#endif
830
}
831
832
833
void Logger::EndCodeRegionEvent(CodeRegion* region, Assembler* masm) {
834
#ifdef ENABLE_LOGGING_AND_PROFILING
835
  if (logfile_ == NULL || !FLAG_log_code) return;
836
  LogMessageBuilder msg;
837
  msg.Append("end-code-region,0x%x,0x%x,0x%x\n",
838
             reinterpret_cast<unsigned int>(region),
839
             reinterpret_cast<unsigned int>(masm),
840
             masm->pc_offset());
841
  msg.WriteToLogFile();
842
#endif
843
}
844
845
846
void Logger::ResourceEvent(const char* name, const char* tag) {
847
#ifdef ENABLE_LOGGING_AND_PROFILING
848
  if (logfile_ == NULL || !FLAG_log) return;
849
  LogMessageBuilder msg;
850
  msg.Append("%s,%s,", name, tag);
851
852
  uint32_t sec, usec;
853
  if (OS::GetUserTime(&sec, &usec) != -1) {
854
    msg.Append("%d,%d,", sec, usec);
855
  }
856
  msg.Append("%.0f", OS::TimeCurrentMillis());
857
858
  msg.Append('\n');
859
  msg.WriteToLogFile();
860
#endif
861
}
862
863
864
void Logger::SuspectReadEvent(String* name, Object* obj) {
865
#ifdef ENABLE_LOGGING_AND_PROFILING
866
  if (logfile_ == NULL || !FLAG_log_suspect) return;
867
  LogMessageBuilder msg;
868
  String* class_name = obj->IsJSObject()
869
                       ? JSObject::cast(obj)->class_name()
870
                       : Heap::empty_string();
871
  ScopedLock sl(mutex_);
872
  msg.Append("suspect-read,");
873
  msg.Append(class_name);
874
  msg.Append(',');
875
  msg.Append('"');
876
  msg.Append(name);
877
  msg.Append('"');
878
  msg.Append('\n');
879
  msg.WriteToLogFile();
880
#endif
881
}
882
883
884
void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
885
#ifdef ENABLE_LOGGING_AND_PROFILING
886
  if (logfile_ == NULL || !FLAG_log_gc) return;
887
  LogMessageBuilder msg;
888
  msg.Append("heap-sample-begin,\"%s\",\"%s\"\n", space, kind);
889
  msg.WriteToLogFile();
890
#endif
891
}
892
893
894
void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
895
#ifdef ENABLE_LOGGING_AND_PROFILING
896
  if (logfile_ == NULL || !FLAG_log_gc) return;
897
  LogMessageBuilder msg;
898
  msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
899
  msg.WriteToLogFile();
900
#endif
901
}
902
903
904
void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
905
#ifdef ENABLE_LOGGING_AND_PROFILING
906
  if (logfile_ == NULL || !FLAG_log_gc) return;
907
  LogMessageBuilder msg;
908
  msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
909
  msg.WriteToLogFile();
910
#endif
911
}
912
913
914
void Logger::DebugTag(const char* call_site_tag) {
915
#ifdef ENABLE_LOGGING_AND_PROFILING
916
  if (logfile_ == NULL || !FLAG_log) return;
917
  LogMessageBuilder msg;
918
  msg.Append("debug-tag,%s\n", call_site_tag);
919
  msg.WriteToLogFile();
920
#endif
921
}
922
923
924
void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
925
#ifdef ENABLE_LOGGING_AND_PROFILING
926
  if (logfile_ == NULL || !FLAG_log) return;
927
  StringBuilder s(parameter.length() + 1);
928
  for (int i = 0; i < parameter.length(); ++i) {
929
    s.AddCharacter(static_cast<char>(parameter[i]));
930
  }
931
  char* parameter_string = s.Finalize();
932
  LogMessageBuilder msg;
933
  msg.Append("debug-queue-event,%s,%15.3f,%s\n",
934
             event_type,
935
             OS::TimeCurrentMillis(),
936
             parameter_string);
937
  DeleteArray(parameter_string);
938
  msg.WriteToLogFile();
939
#endif
940
}
941
942
943
#ifdef ENABLE_LOGGING_AND_PROFILING
944
void Logger::TickEvent(TickSample* sample, bool overflow) {
945
  if (logfile_ == NULL || !FLAG_prof) return;
946
  LogMessageBuilder msg;
947
  msg.Append("tick,0x%x,0x%x,%d", sample->pc, sample->sp,
948
             static_cast<int>(sample->state));
949
  if (overflow) {
950
    msg.Append(",overflow");
951
  }
952
  for (int i = 0; i < sample->frames_count; ++i) {
953
    msg.Append(",0x%x", reinterpret_cast<uint32_t>(sample->stack[i]));
954
  }
955
  msg.Append('\n');
956
  msg.WriteToLogFile();
957
}
958
959
960
bool Logger::IsProfilerPaused() {
961
  return profiler_->paused();
962
}
963
964
965
void Logger::PauseProfiler() {
966
  profiler_->pause();
967
}
968
969
970
void Logger::ResumeProfiler() {
971
  profiler_->resume();
972
}
973
#endif
974
975
976
bool Logger::Setup() {
977
#ifdef ENABLE_LOGGING_AND_PROFILING
978
  // --log-all enables all the log flags.
979
  if (FLAG_log_all) {
980
    FLAG_log_runtime = true;
981
    FLAG_log_api = true;
982
    FLAG_log_code = true;
983
    FLAG_log_gc = true;
984
    FLAG_log_suspect = true;
985
    FLAG_log_handles = true;
986
    FLAG_log_regexp = true;
987
  }
988
989
  // --prof implies --log-code.
990
  if (FLAG_prof) FLAG_log_code = true;
991
992
  bool open_log_file = FLAG_log || FLAG_log_runtime || FLAG_log_api
993
      || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
994
      || FLAG_log_regexp || FLAG_log_state_changes;
995
996
  // If we're logging anything, we need to open the log file.
997
  if (open_log_file) {
998
    if (strcmp(FLAG_logfile, "-") == 0) {
999
      logfile_ = stdout;
1000
    } else if (strchr(FLAG_logfile, '%') != NULL) {
1001
      // If there's a '%' in the log file name we have to expand
1002
      // placeholders.
1003
      HeapStringAllocator allocator;
1004
      StringStream stream(&allocator);
1005
      for (const char* p = FLAG_logfile; *p; p++) {
1006
        if (*p == '%') {
1007
          p++;
1008
          switch (*p) {
1009
            case '\0':
1010
              // If there's a % at the end of the string we back up
1011
              // one character so we can escape the loop properly.
1012
              p--;
1013
              break;
1014
            case 't': {
1015
              // %t expands to the current time in milliseconds.
1016
              uint32_t time = static_cast<uint32_t>(OS::TimeCurrentMillis());
1017
              stream.Add("%u", time);
1018
              break;
1019
            }
1020
            case '%':
1021
              // %% expands (contracts really) to %.
1022
              stream.Put('%');
1023
              break;
1024
            default:
1025
              // All other %'s expand to themselves.
1026
              stream.Put('%');
1027
              stream.Put(*p);
1028
              break;
1029
          }
1030
        } else {
1031
          stream.Put(*p);
1032
        }
1033
      }
1034
      SmartPointer<const char> expanded = stream.ToCString();
1035
      logfile_ = OS::FOpen(*expanded, OS::LogFileOpenMode);
1036
    } else {
1037
      logfile_ = OS::FOpen(FLAG_logfile, OS::LogFileOpenMode);
1038
    }
1039
    message_buffer_ = NewArray<char>(kMessageBufferSize);
1040
    mutex_ = OS::CreateMutex();
1041
  }
1042
1043
  current_state_ = &bottom_state_;
1044
1045
  // as log is initialized early with V8, we can assume that JS execution
1046
  // frames can never reach this point on stack
1047
  int stack_var;
1048
  ticker_ = new Ticker(1, reinterpret_cast<unsigned int>(&stack_var));
1049
1050
  if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1051
    sliding_state_window_ = new SlidingStateWindow();
1052
  }
1053
1054
  if (FLAG_prof) {
1055
    profiler_ = new Profiler();
1056
    if (!FLAG_prof_auto)
1057
      profiler_->pause();
1058
    profiler_->Engage();
1059
  }
1060
1061
  return true;
1062
1063
#else
1064
  return false;
1065
#endif
1066
}
1067
1068
1069
void Logger::TearDown() {
1070
#ifdef ENABLE_LOGGING_AND_PROFILING
1071
  // Stop the profiler before closing the file.
1072
  if (profiler_ != NULL) {
1073
    profiler_->Disengage();
1074
    delete profiler_;
1075
    profiler_ = NULL;
1076
  }
1077
1078
  delete sliding_state_window_;
1079
1080
  delete ticker_;
1081
1082
  if (logfile_ != NULL) {
1083
    fclose(logfile_);
1084
    logfile_ = NULL;
1085
    delete mutex_;
1086
    mutex_ = NULL;
1087
    DeleteArray(message_buffer_);
1088
  }
1089
#endif
1090
}
1091
1092
1093
void Logger::EnableSlidingStateWindow() {
1094
#ifdef ENABLE_LOGGING_AND_PROFILING
1095
  // If the ticker is NULL, Logger::Setup has not been called yet.  In
1096
  // that case, we set the sliding_state_window flag so that the
1097
  // sliding window computation will be started when Logger::Setup is
1098
  // called.
1099
  if (ticker_ == NULL) {
1100
    FLAG_sliding_state_window = true;
1101
    return;
1102
  }
1103
  // Otherwise, if the sliding state window computation has not been
1104
  // started we do it now.
1105
  if (sliding_state_window_ == NULL) {
1106
    sliding_state_window_ = new SlidingStateWindow();
1107
  }
1108
#endif
1109
}
1110
1111
1112
//
1113
// VMState class implementation.  A simple stack of VM states held by the
1114
// logger and partially threaded through the call stack.  States are pushed by
1115
// VMState construction and popped by destruction.
1116
//
1117
#ifdef ENABLE_LOGGING_AND_PROFILING
1118
static const char* StateToString(StateTag state) {
1119
  switch (state) {
1120
    case JS:
1121
      return "JS";
1122
    case GC:
1123
      return "GC";
1124
    case COMPILER:
1125
      return "COMPILER";
1126
    case OTHER:
1127
      return "OTHER";
1128
    default:
1129
      UNREACHABLE();
1130
      return NULL;
1131
  }
1132
}
1133
1134
VMState::VMState(StateTag state) {
1135
#if !defined(ENABLE_HEAP_PROTECTION)
1136
  // When not protecting the heap, there is no difference between
1137
  // EXTERNAL and OTHER.  As an optimizatin in that case, we will not
1138
  // perform EXTERNAL->OTHER transitions through the API.  We thus
1139
  // compress the two states into one.
1140
  if (state == EXTERNAL) state = OTHER;
1141
#endif
1142
  state_ = state;
1143
  previous_ = Logger::current_state_;
1144
  Logger::current_state_ = this;
1145
1146
  if (FLAG_log_state_changes) {
1147
    LOG(UncheckedStringEvent("Entering", StateToString(state_)));
1148
    if (previous_ != NULL) {
1149
      LOG(UncheckedStringEvent("From", StateToString(previous_->state_)));
1150
    }
1151
  }
1152
1153
#ifdef ENABLE_HEAP_PROTECTION
1154
  if (FLAG_protect_heap && previous_ != NULL) {
1155
    if (state_ == EXTERNAL) {
1156
      // We are leaving V8.
1157
      ASSERT(previous_->state_ != EXTERNAL);
1158
      Heap::Protect();
1159
    } else if (previous_->state_ == EXTERNAL) {
1160
      // We are entering V8.
1161
      Heap::Unprotect();
1162
    }
1163
  }
1164
#endif
1165
}
1166
1167
1168
VMState::~VMState() {
1169
  Logger::current_state_ = previous_;
1170
1171
  if (FLAG_log_state_changes) {
1172
    LOG(UncheckedStringEvent("Leaving", StateToString(state_)));
1173
    if (previous_ != NULL) {
1174
      LOG(UncheckedStringEvent("To", StateToString(previous_->state_)));
1175
    }
1176
  }
1177
1178
#ifdef ENABLE_HEAP_PROTECTION
1179
  if (FLAG_protect_heap && previous_ != NULL) {
1180
    if (state_ == EXTERNAL) {
1181
      // We are reentering V8.
1182
      ASSERT(previous_->state_ != EXTERNAL);
1183
      Heap::Unprotect();
1184
    } else if (previous_->state_ == EXTERNAL) {
1185
      // We are leaving V8.
1186
      Heap::Protect();
1187
    }
1188
  }
1189
#endif
1190
}
1191
#endif
1192
1193
} }  // namespace v8::internal