log.cc revision e0cee9b3ed82e2391fd85d118aeaa4ea361c687d 
1// 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 "code-stubs.h"
34#include "deoptimizer.h"
35#include "global-handles.h"
36#include "log.h"
37#include "macro-assembler.h"
38#include "runtime-profiler.h"
39#include "serialize.h"
40#include "string-stream.h"
41#include "vm-state-inl.h"
42
43namespace v8 {
44namespace internal {
45
46#ifdef ENABLE_LOGGING_AND_PROFILING
47
48//
49// Sliding state window.  Updates counters to keep track of the last
50// window of kBufferSize states.  This is useful to track where we
51// spent our time.
52//
53class SlidingStateWindow {
54 public:
55  SlidingStateWindow();
56  ~SlidingStateWindow();
57  void AddState(StateTag state);
58
59 private:
60  static const int kBufferSize = 256;
61  int current_index_;
62  bool is_full_;
63  byte buffer_[kBufferSize];
64
65
66  void IncrementStateCounter(StateTag state) {
67    Counters::state_counters[state].Increment();
68  }
69
70
71  void DecrementStateCounter(StateTag state) {
72    Counters::state_counters[state].Decrement();
73  }
74};
75
76
77//
78// The Profiler samples pc and sp values for the main thread.
79// Each sample is appended to a circular buffer.
80// An independent thread removes data and writes it to the log.
81// This design minimizes the time spent in the sampler.
82//
83class Profiler: public Thread {
84 public:
85  Profiler();
86  void Engage();
87  void Disengage();
88
89  // Inserts collected profiling data into buffer.
90  void Insert(TickSample* sample) {
91    if (paused_)
92      return;
93
94    if (Succ(head_) == tail_) {
95      overflow_ = true;
96    } else {
97      buffer_[head_] = *sample;
98      head_ = Succ(head_);
99      buffer_semaphore_->Signal();  // Tell we have an element.
100    }
101  }
102
103  // Waits for a signal and removes profiling data.
104  bool Remove(TickSample* sample) {
105    buffer_semaphore_->Wait();  // Wait for an element.
106    *sample = buffer_[tail_];
107    bool result = overflow_;
108    tail_ = Succ(tail_);
109    overflow_ = false;
110    return result;
111  }
112
113  void Run();
114
115  // Pause and Resume TickSample data collection.
116  static bool paused() { return paused_; }
117  static void pause() { paused_ = true; }
118  static void resume() { paused_ = false; }
119
120 private:
121  // Returns the next index in the cyclic buffer.
122  int Succ(int index) { return (index + 1) % kBufferSize; }
123
124  // Cyclic buffer for communicating profiling samples
125  // between the signal handler and the worker thread.
126  static const int kBufferSize = 128;
127  TickSample buffer_[kBufferSize];  // Buffer storage.
128  int head_;  // Index to the buffer head.
129  int tail_;  // Index to the buffer tail.
130  bool overflow_;  // Tell whether a buffer overflow has occurred.
131  Semaphore* buffer_semaphore_;  // Sempahore used for buffer synchronization.
132
133  // Tells whether profiler is engaged, that is, processing thread is stated.
134  bool engaged_;
135
136  // Tells whether worker thread should continue running.
137  bool running_;
138
139  // Tells whether we are currently recording tick samples.
140  static bool paused_;
141};
142
143bool Profiler::paused_ = false;
144
145
146//
147// StackTracer implementation
148//
149void StackTracer::Trace(TickSample* sample) {
150  sample->tos = NULL;
151  sample->frames_count = 0;
152
153  // Avoid collecting traces while doing GC.
154  if (sample->state == GC) return;
155
156  const Address js_entry_sp = Top::js_entry_sp(Top::GetCurrentThread());
157  if (js_entry_sp == 0) {
158    // Not executing JS now.
159    return;
160  }
161
162  // Sample potential return address value for frameless invocation of
163  // stubs (we'll figure out later, if this value makes sense).
164  sample->tos = Memory::Address_at(sample->sp);
165
166  int i = 0;
167  const Address callback = Top::external_callback();
168  // Surprisingly, PC can point _exactly_ to callback start, with good
169  // probability, and this will result in reporting fake nested
170  // callback call.
171  if (callback != NULL && callback != sample->pc) {
172    sample->stack[i++] = callback;
173  }
174
175  SafeStackTraceFrameIterator it(sample->fp, sample->sp,
176                                 sample->sp, js_entry_sp);
177  while (!it.done() && i < TickSample::kMaxFramesCount) {
178    sample->stack[i++] = it.frame()->pc();
179    it.Advance();
180  }
181  sample->frames_count = i;
182}
183
184
185//
186// Ticker used to provide ticks to the profiler and the sliding state
187// window.
188//
189class Ticker: public Sampler {
190 public:
191  explicit Ticker(int interval) :
192      Sampler(interval),
193      window_(NULL),
194      profiler_(NULL) {}
195
196  ~Ticker() { if (IsActive()) Stop(); }
197
198  virtual void Tick(TickSample* sample) {
199    if (profiler_) profiler_->Insert(sample);
200    if (window_) window_->AddState(sample->state);
201  }
202
203  void SetWindow(SlidingStateWindow* window) {
204    window_ = window;
205    if (!IsActive()) Start();
206  }
207
208  void ClearWindow() {
209    window_ = NULL;
210    if (!profiler_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
211  }
212
213  void SetProfiler(Profiler* profiler) {
214    ASSERT(profiler_ == NULL);
215    profiler_ = profiler;
216    IncreaseProfilingDepth();
217    if (!FLAG_prof_lazy && !IsActive()) Start();
218  }
219
220  void ClearProfiler() {
221    DecreaseProfilingDepth();
222    profiler_ = NULL;
223    if (!window_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
224  }
225
226 protected:
227  virtual void DoSampleStack(TickSample* sample) {
228    StackTracer::Trace(sample);
229  }
230
231 private:
232  SlidingStateWindow* window_;
233  Profiler* profiler_;
234};
235
236
237//
238// SlidingStateWindow implementation.
239//
240SlidingStateWindow::SlidingStateWindow(): current_index_(0), is_full_(false) {
241  for (int i = 0; i < kBufferSize; i++) {
242    buffer_[i] = static_cast<byte>(OTHER);
243  }
244  Logger::ticker_->SetWindow(this);
245}
246
247
248SlidingStateWindow::~SlidingStateWindow() {
249  Logger::ticker_->ClearWindow();
250}
251
252
253void SlidingStateWindow::AddState(StateTag state) {
254  if (is_full_) {
255    DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
256  } else if (current_index_ == kBufferSize - 1) {
257    is_full_ = true;
258  }
259  buffer_[current_index_] = static_cast<byte>(state);
260  IncrementStateCounter(state);
261  ASSERT(IsPowerOf2(kBufferSize));
262  current_index_ = (current_index_ + 1) & (kBufferSize - 1);
263}
264
265
266//
267// Profiler implementation.
268//
269Profiler::Profiler()
270    : Thread("v8:Profiler"),
271      head_(0),
272      tail_(0),
273      overflow_(false),
274      buffer_semaphore_(OS::CreateSemaphore(0)),
275      engaged_(false),
276      running_(false) {
277}
278
279
280void Profiler::Engage() {
281  if (engaged_) return;
282  engaged_ = true;
283
284  // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
285  // http://code.google.com/p/v8/issues/detail?id=487
286  if (!FLAG_prof_lazy) {
287    OS::LogSharedLibraryAddresses();
288  }
289
290  // Start thread processing the profiler buffer.
291  running_ = true;
292  Start();
293
294  // Register to get ticks.
295  Logger::ticker_->SetProfiler(this);
296
297  Logger::ProfilerBeginEvent();
298}
299
300
301void Profiler::Disengage() {
302  if (!engaged_) return;
303
304  // Stop receiving ticks.
305  Logger::ticker_->ClearProfiler();
306
307  // Terminate the worker thread by setting running_ to false,
308  // inserting a fake element in the queue and then wait for
309  // the thread to terminate.
310  running_ = false;
311  TickSample sample;
312  // Reset 'paused_' flag, otherwise semaphore may not be signalled.
313  resume();
314  Insert(&sample);
315  Join();
316
317  LOG(UncheckedStringEvent("profiler", "end"));
318}
319
320
321void Profiler::Run() {
322  TickSample sample;
323  bool overflow = Remove(&sample);
324  while (running_) {
325    LOG(TickEvent(&sample, overflow));
326    overflow = Remove(&sample);
327  }
328}
329
330
331//
332// Logger class implementation.
333//
334Ticker* Logger::ticker_ = NULL;
335Profiler* Logger::profiler_ = NULL;
336SlidingStateWindow* Logger::sliding_state_window_ = NULL;
337int Logger::logging_nesting_ = 0;
338int Logger::cpu_profiler_nesting_ = 0;
339int Logger::heap_profiler_nesting_ = 0;
340
341#define DECLARE_EVENT(ignore1, name) name,
342const char* kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
343  LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
344};
345#undef DECLARE_EVENT
346
347
348void Logger::ProfilerBeginEvent() {
349  if (!Log::IsEnabled()) return;
350  LogMessageBuilder msg;
351  msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
352  msg.WriteToLogFile();
353}
354
355#endif  // ENABLE_LOGGING_AND_PROFILING
356
357
358void Logger::StringEvent(const char* name, const char* value) {
359#ifdef ENABLE_LOGGING_AND_PROFILING
360  if (FLAG_log) UncheckedStringEvent(name, value);
361#endif
362}
363
364
365#ifdef ENABLE_LOGGING_AND_PROFILING
366void Logger::UncheckedStringEvent(const char* name, const char* value) {
367  if (!Log::IsEnabled()) return;
368  LogMessageBuilder msg;
369  msg.Append("%s,\"%s\"\n", name, value);
370  msg.WriteToLogFile();
371}
372#endif
373
374
375void Logger::IntEvent(const char* name, int value) {
376#ifdef ENABLE_LOGGING_AND_PROFILING
377  if (FLAG_log) UncheckedIntEvent(name, value);
378#endif
379}
380
381
382void Logger::IntPtrTEvent(const char* name, intptr_t value) {
383#ifdef ENABLE_LOGGING_AND_PROFILING
384  if (FLAG_log) UncheckedIntPtrTEvent(name, value);
385#endif
386}
387
388
389#ifdef ENABLE_LOGGING_AND_PROFILING
390void Logger::UncheckedIntEvent(const char* name, int value) {
391  if (!Log::IsEnabled()) return;
392  LogMessageBuilder msg;
393  msg.Append("%s,%d\n", name, value);
394  msg.WriteToLogFile();
395}
396#endif
397
398
399#ifdef ENABLE_LOGGING_AND_PROFILING
400void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
401  if (!Log::IsEnabled()) return;
402  LogMessageBuilder msg;
403  msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
404  msg.WriteToLogFile();
405}
406#endif
407
408
409void Logger::HandleEvent(const char* name, Object** location) {
410#ifdef ENABLE_LOGGING_AND_PROFILING
411  if (!Log::IsEnabled() || !FLAG_log_handles) return;
412  LogMessageBuilder msg;
413  msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
414  msg.WriteToLogFile();
415#endif
416}
417
418
419#ifdef ENABLE_LOGGING_AND_PROFILING
420// ApiEvent is private so all the calls come from the Logger class.  It is the
421// caller's responsibility to ensure that log is enabled and that
422// FLAG_log_api is true.
423void Logger::ApiEvent(const char* format, ...) {
424  ASSERT(Log::IsEnabled() && FLAG_log_api);
425  LogMessageBuilder msg;
426  va_list ap;
427  va_start(ap, format);
428  msg.AppendVA(format, ap);
429  va_end(ap);
430  msg.WriteToLogFile();
431}
432#endif
433
434
435void Logger::ApiNamedSecurityCheck(Object* key) {
436#ifdef ENABLE_LOGGING_AND_PROFILING
437  if (!Log::IsEnabled() || !FLAG_log_api) return;
438  if (key->IsString()) {
439    SmartPointer<char> str =
440        String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
441    ApiEvent("api,check-security,\"%s\"\n", *str);
442  } else if (key->IsUndefined()) {
443    ApiEvent("api,check-security,undefined\n");
444  } else {
445    ApiEvent("api,check-security,['no-name']\n");
446  }
447#endif
448}
449
450
451void Logger::SharedLibraryEvent(const char* library_path,
452                                uintptr_t start,
453                                uintptr_t end) {
454#ifdef ENABLE_LOGGING_AND_PROFILING
455  if (!Log::IsEnabled() || !FLAG_prof) return;
456  LogMessageBuilder msg;
457  msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
458             library_path,
459             start,
460             end);
461  msg.WriteToLogFile();
462#endif
463}
464
465
466void Logger::SharedLibraryEvent(const wchar_t* library_path,
467                                uintptr_t start,
468                                uintptr_t end) {
469#ifdef ENABLE_LOGGING_AND_PROFILING
470  if (!Log::IsEnabled() || !FLAG_prof) return;
471  LogMessageBuilder msg;
472  msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
473             library_path,
474             start,
475             end);
476  msg.WriteToLogFile();
477#endif
478}
479
480
481#ifdef ENABLE_LOGGING_AND_PROFILING
482void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
483  // Prints "/" + re.source + "/" +
484  //      (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
485  LogMessageBuilder msg;
486
487  Handle<Object> source = GetProperty(regexp, "source");
488  if (!source->IsString()) {
489    msg.Append("no source");
490    return;
491  }
492
493  switch (regexp->TypeTag()) {
494    case JSRegExp::ATOM:
495      msg.Append('a');
496      break;
497    default:
498      break;
499  }
500  msg.Append('/');
501  msg.AppendDetailed(*Handle<String>::cast(source), false);
502  msg.Append('/');
503
504  // global flag
505  Handle<Object> global = GetProperty(regexp, "global");
506  if (global->IsTrue()) {
507    msg.Append('g');
508  }
509  // ignorecase flag
510  Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
511  if (ignorecase->IsTrue()) {
512    msg.Append('i');
513  }
514  // multiline flag
515  Handle<Object> multiline = GetProperty(regexp, "multiline");
516  if (multiline->IsTrue()) {
517    msg.Append('m');
518  }
519
520  msg.WriteToLogFile();
521}
522#endif  // ENABLE_LOGGING_AND_PROFILING
523
524
525void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
526#ifdef ENABLE_LOGGING_AND_PROFILING
527  if (!Log::IsEnabled() || !FLAG_log_regexp) return;
528  LogMessageBuilder msg;
529  msg.Append("regexp-compile,");
530  LogRegExpSource(regexp);
531  msg.Append(in_cache ? ",hit\n" : ",miss\n");
532  msg.WriteToLogFile();
533#endif
534}
535
536
537void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
538#ifdef ENABLE_LOGGING_AND_PROFILING
539  if (!Log::IsEnabled() || !FLAG_log_runtime) return;
540  HandleScope scope;
541  LogMessageBuilder msg;
542  for (int i = 0; i < format.length(); i++) {
543    char c = format[i];
544    if (c == '%' && i <= format.length() - 2) {
545      i++;
546      ASSERT('0' <= format[i] && format[i] <= '9');
547      MaybeObject* maybe = args->GetElement(format[i] - '0');
548      Object* obj;
549      if (!maybe->ToObject(&obj)) {
550        msg.Append("<exception>");
551        continue;
552      }
553      i++;
554      switch (format[i]) {
555        case 's':
556          msg.AppendDetailed(String::cast(obj), false);
557          break;
558        case 'S':
559          msg.AppendDetailed(String::cast(obj), true);
560          break;
561        case 'r':
562          Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
563          break;
564        case 'x':
565          msg.Append("0x%x", Smi::cast(obj)->value());
566          break;
567        case 'i':
568          msg.Append("%i", Smi::cast(obj)->value());
569          break;
570        default:
571          UNREACHABLE();
572      }
573    } else {
574      msg.Append(c);
575    }
576  }
577  msg.Append('\n');
578  msg.WriteToLogFile();
579#endif
580}
581
582
583void Logger::ApiIndexedSecurityCheck(uint32_t index) {
584#ifdef ENABLE_LOGGING_AND_PROFILING
585  if (!Log::IsEnabled() || !FLAG_log_api) return;
586  ApiEvent("api,check-security,%u\n", index);
587#endif
588}
589
590
591void Logger::ApiNamedPropertyAccess(const char* tag,
592                                    JSObject* holder,
593                                    Object* name) {
594#ifdef ENABLE_LOGGING_AND_PROFILING
595  ASSERT(name->IsString());
596  if (!Log::IsEnabled() || !FLAG_log_api) return;
597  String* class_name_obj = holder->class_name();
598  SmartPointer<char> class_name =
599      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
600  SmartPointer<char> property_name =
601      String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
602  Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
603#endif
604}
605
606void Logger::ApiIndexedPropertyAccess(const char* tag,
607                                      JSObject* holder,
608                                      uint32_t index) {
609#ifdef ENABLE_LOGGING_AND_PROFILING
610  if (!Log::IsEnabled() || !FLAG_log_api) return;
611  String* class_name_obj = holder->class_name();
612  SmartPointer<char> class_name =
613      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
614  Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
615#endif
616}
617
618void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
619#ifdef ENABLE_LOGGING_AND_PROFILING
620  if (!Log::IsEnabled() || !FLAG_log_api) return;
621  String* class_name_obj = object->class_name();
622  SmartPointer<char> class_name =
623      class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
624  Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
625#endif
626}
627
628
629void Logger::ApiEntryCall(const char* name) {
630#ifdef ENABLE_LOGGING_AND_PROFILING
631  if (!Log::IsEnabled() || !FLAG_log_api) return;
632  Logger::ApiEvent("api,%s\n", name);
633#endif
634}
635
636
637void Logger::NewEvent(const char* name, void* object, size_t size) {
638#ifdef ENABLE_LOGGING_AND_PROFILING
639  if (!Log::IsEnabled() || !FLAG_log) return;
640  LogMessageBuilder msg;
641  msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
642             static_cast<unsigned int>(size));
643  msg.WriteToLogFile();
644#endif
645}
646
647
648void Logger::DeleteEvent(const char* name, void* object) {
649#ifdef ENABLE_LOGGING_AND_PROFILING
650  if (!Log::IsEnabled() || !FLAG_log) return;
651  LogMessageBuilder msg;
652  msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
653  msg.WriteToLogFile();
654#endif
655}
656
657
658#ifdef ENABLE_LOGGING_AND_PROFILING
659void Logger::CallbackEventInternal(const char* prefix, const char* name,
660                                   Address entry_point) {
661  if (!Log::IsEnabled() || !FLAG_log_code) return;
662  LogMessageBuilder msg;
663  msg.Append("%s,%s,",
664             kLogEventsNames[CODE_CREATION_EVENT],
665             kLogEventsNames[CALLBACK_TAG]);
666  msg.AppendAddress(entry_point);
667  msg.Append(",1,\"%s%s\"", prefix, name);
668  msg.Append('\n');
669  msg.WriteToLogFile();
670}
671#endif
672
673
674void Logger::CallbackEvent(String* name, Address entry_point) {
675#ifdef ENABLE_LOGGING_AND_PROFILING
676  if (!Log::IsEnabled() || !FLAG_log_code) return;
677  SmartPointer<char> str =
678      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
679  CallbackEventInternal("", *str, entry_point);
680#endif
681}
682
683
684void Logger::GetterCallbackEvent(String* name, Address entry_point) {
685#ifdef ENABLE_LOGGING_AND_PROFILING
686  if (!Log::IsEnabled() || !FLAG_log_code) return;
687  SmartPointer<char> str =
688      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
689  CallbackEventInternal("get ", *str, entry_point);
690#endif
691}
692
693
694void Logger::SetterCallbackEvent(String* name, Address entry_point) {
695#ifdef ENABLE_LOGGING_AND_PROFILING
696  if (!Log::IsEnabled() || !FLAG_log_code) return;
697  SmartPointer<char> str =
698      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
699  CallbackEventInternal("set ", *str, entry_point);
700#endif
701}
702
703
704void Logger::CodeCreateEvent(LogEventsAndTags tag,
705                             Code* code,
706                             const char* comment) {
707#ifdef ENABLE_LOGGING_AND_PROFILING
708  if (!Log::IsEnabled() || !FLAG_log_code) return;
709  LogMessageBuilder msg;
710  msg.Append("%s,%s,",
711             kLogEventsNames[CODE_CREATION_EVENT],
712             kLogEventsNames[tag]);
713  msg.AppendAddress(code->address());
714  msg.Append(",%d,\"", code->ExecutableSize());
715  for (const char* p = comment; *p != '\0'; p++) {
716    if (*p == '"') {
717      msg.Append('\\');
718    }
719    msg.Append(*p);
720  }
721  msg.Append('"');
722  LowLevelCodeCreateEvent(code, &msg);
723  msg.Append('\n');
724  msg.WriteToLogFile();
725#endif
726}
727
728
729void Logger::CodeCreateEvent(LogEventsAndTags tag,
730                             Code* code,
731                             String* name) {
732#ifdef ENABLE_LOGGING_AND_PROFILING
733  if (name != NULL) {
734    SmartPointer<char> str =
735        name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
736    CodeCreateEvent(tag, code, *str);
737  } else {
738    CodeCreateEvent(tag, code, "");
739  }
740#endif
741}
742
743
744#ifdef ENABLE_LOGGING_AND_PROFILING
745// ComputeMarker must only be used when SharedFunctionInfo is known.
746static const char* ComputeMarker(Code* code) {
747  switch (code->kind()) {
748    case Code::FUNCTION: return code->optimizable() ? "~" : "";
749    case Code::OPTIMIZED_FUNCTION: return "*";
750    default: return "";
751  }
752}
753#endif
754
755
756void Logger::CodeCreateEvent(LogEventsAndTags tag,
757                             Code* code,
758                             SharedFunctionInfo* shared,
759                             String* name) {
760#ifdef ENABLE_LOGGING_AND_PROFILING
761  if (!Log::IsEnabled() || !FLAG_log_code) return;
762  if (code == Builtins::builtin(Builtins::LazyCompile)) return;
763  LogMessageBuilder msg;
764  SmartPointer<char> str =
765      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
766  msg.Append("%s,%s,",
767             kLogEventsNames[CODE_CREATION_EVENT],
768             kLogEventsNames[tag]);
769  msg.AppendAddress(code->address());
770  msg.Append(",%d,\"%s\",", code->ExecutableSize(), *str);
771  msg.AppendAddress(shared->address());
772  msg.Append(",%s", ComputeMarker(code));
773  LowLevelCodeCreateEvent(code, &msg);
774  msg.Append('\n');
775  msg.WriteToLogFile();
776#endif
777}
778
779
780// Although, it is possible to extract source and line from
781// the SharedFunctionInfo object, we left it to caller
782// to leave logging functions free from heap allocations.
783void Logger::CodeCreateEvent(LogEventsAndTags tag,
784                             Code* code,
785                             SharedFunctionInfo* shared,
786                             String* source, int line) {
787#ifdef ENABLE_LOGGING_AND_PROFILING
788  if (!Log::IsEnabled() || !FLAG_log_code) return;
789  LogMessageBuilder msg;
790  SmartPointer<char> name =
791      shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
792  SmartPointer<char> sourcestr =
793      source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
794  msg.Append("%s,%s,",
795             kLogEventsNames[CODE_CREATION_EVENT],
796             kLogEventsNames[tag]);
797  msg.AppendAddress(code->address());
798  msg.Append(",%d,\"%s %s:%d\",",
799             code->ExecutableSize(),
800             *name,
801             *sourcestr,
802             line);
803  msg.AppendAddress(shared->address());
804  msg.Append(",%s", ComputeMarker(code));
805  LowLevelCodeCreateEvent(code, &msg);
806  msg.Append('\n');
807  msg.WriteToLogFile();
808#endif
809}
810
811
812void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
813#ifdef ENABLE_LOGGING_AND_PROFILING
814  if (!Log::IsEnabled() || !FLAG_log_code) return;
815  LogMessageBuilder msg;
816  msg.Append("%s,%s,",
817             kLogEventsNames[CODE_CREATION_EVENT],
818             kLogEventsNames[tag]);
819  msg.AppendAddress(code->address());
820  msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
821  LowLevelCodeCreateEvent(code, &msg);
822  msg.Append('\n');
823  msg.WriteToLogFile();
824#endif
825}
826
827
828void Logger::CodeMovingGCEvent() {
829#ifdef ENABLE_LOGGING_AND_PROFILING
830  if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
831  LogMessageBuilder msg;
832  msg.Append("%s\n", kLogEventsNames[CODE_MOVING_GC]);
833  msg.WriteToLogFile();
834  OS::SignalCodeMovingGC();
835#endif
836}
837
838
839void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
840#ifdef ENABLE_LOGGING_AND_PROFILING
841  if (!Log::IsEnabled() || !FLAG_log_code) return;
842  LogMessageBuilder msg;
843  msg.Append("%s,%s,",
844             kLogEventsNames[CODE_CREATION_EVENT],
845             kLogEventsNames[REG_EXP_TAG]);
846  msg.AppendAddress(code->address());
847  msg.Append(",%d,\"", code->ExecutableSize());
848  msg.AppendDetailed(source, false);
849  msg.Append('\"');
850  LowLevelCodeCreateEvent(code, &msg);
851  msg.Append('\n');
852  msg.WriteToLogFile();
853#endif
854}
855
856
857void Logger::CodeMoveEvent(Address from, Address to) {
858#ifdef ENABLE_LOGGING_AND_PROFILING
859  MoveEventInternal(CODE_MOVE_EVENT, from, to);
860#endif
861}
862
863
864void Logger::CodeDeleteEvent(Address from) {
865#ifdef ENABLE_LOGGING_AND_PROFILING
866  DeleteEventInternal(CODE_DELETE_EVENT, from);
867#endif
868}
869
870
871void Logger::SnapshotPositionEvent(Address addr, int pos) {
872#ifdef ENABLE_LOGGING_AND_PROFILING
873  if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return;
874  LogMessageBuilder msg;
875  msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
876  msg.AppendAddress(addr);
877  msg.Append(",%d", pos);
878  msg.Append('\n');
879  msg.WriteToLogFile();
880#endif
881}
882
883
884void Logger::SFIMoveEvent(Address from, Address to) {
885#ifdef ENABLE_LOGGING_AND_PROFILING
886  MoveEventInternal(SFI_MOVE_EVENT, from, to);
887#endif
888}
889
890
891#ifdef ENABLE_LOGGING_AND_PROFILING
892void Logger::MoveEventInternal(LogEventsAndTags event,
893                               Address from,
894                               Address to) {
895  if (!Log::IsEnabled() || !FLAG_log_code) return;
896  LogMessageBuilder msg;
897  msg.Append("%s,", kLogEventsNames[event]);
898  msg.AppendAddress(from);
899  msg.Append(',');
900  msg.AppendAddress(to);
901  msg.Append('\n');
902  msg.WriteToLogFile();
903}
904#endif
905
906
907#ifdef ENABLE_LOGGING_AND_PROFILING
908void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
909  if (!Log::IsEnabled() || !FLAG_log_code) return;
910  LogMessageBuilder msg;
911  msg.Append("%s,", kLogEventsNames[event]);
912  msg.AppendAddress(from);
913  msg.Append('\n');
914  msg.WriteToLogFile();
915}
916#endif
917
918
919void Logger::ResourceEvent(const char* name, const char* tag) {
920#ifdef ENABLE_LOGGING_AND_PROFILING
921  if (!Log::IsEnabled() || !FLAG_log) return;
922  LogMessageBuilder msg;
923  msg.Append("%s,%s,", name, tag);
924
925  uint32_t sec, usec;
926  if (OS::GetUserTime(&sec, &usec) != -1) {
927    msg.Append("%d,%d,", sec, usec);
928  }
929  msg.Append("%.0f", OS::TimeCurrentMillis());
930
931  msg.Append('\n');
932  msg.WriteToLogFile();
933#endif
934}
935
936
937void Logger::SuspectReadEvent(String* name, Object* obj) {
938#ifdef ENABLE_LOGGING_AND_PROFILING
939  if (!Log::IsEnabled() || !FLAG_log_suspect) return;
940  LogMessageBuilder msg;
941  String* class_name = obj->IsJSObject()
942                       ? JSObject::cast(obj)->class_name()
943                       : Heap::empty_string();
944  msg.Append("suspect-read,");
945  msg.Append(class_name);
946  msg.Append(',');
947  msg.Append('"');
948  msg.Append(name);
949  msg.Append('"');
950  msg.Append('\n');
951  msg.WriteToLogFile();
952#endif
953}
954
955
956void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
957#ifdef ENABLE_LOGGING_AND_PROFILING
958  if (!Log::IsEnabled() || !FLAG_log_gc) return;
959  LogMessageBuilder msg;
960  // Using non-relative system time in order to be able to synchronize with
961  // external memory profiling events (e.g. DOM memory size).
962  msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
963             space, kind, OS::TimeCurrentMillis());
964  msg.WriteToLogFile();
965#endif
966}
967
968
969void Logger::HeapSampleStats(const char* space, const char* kind,
970                             intptr_t capacity, intptr_t used) {
971#ifdef ENABLE_LOGGING_AND_PROFILING
972  if (!Log::IsEnabled() || !FLAG_log_gc) return;
973  LogMessageBuilder msg;
974  msg.Append("heap-sample-stats,\"%s\",\"%s\","
975                 "%" V8_PTR_PREFIX "d,%" V8_PTR_PREFIX "d\n",
976             space, kind, capacity, used);
977  msg.WriteToLogFile();
978#endif
979}
980
981
982void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
983#ifdef ENABLE_LOGGING_AND_PROFILING
984  if (!Log::IsEnabled() || !FLAG_log_gc) return;
985  LogMessageBuilder msg;
986  msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
987  msg.WriteToLogFile();
988#endif
989}
990
991
992void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
993#ifdef ENABLE_LOGGING_AND_PROFILING
994  if (!Log::IsEnabled() || !FLAG_log_gc) return;
995  LogMessageBuilder msg;
996  msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
997  msg.WriteToLogFile();
998#endif
999}
1000
1001
1002void Logger::HeapSampleJSConstructorEvent(const char* constructor,
1003                                          int number, int bytes) {
1004#ifdef ENABLE_LOGGING_AND_PROFILING
1005  if (!Log::IsEnabled() || !FLAG_log_gc) return;
1006  LogMessageBuilder msg;
1007  msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
1008  msg.WriteToLogFile();
1009#endif
1010}
1011
1012
1013void Logger::HeapSampleJSRetainersEvent(
1014    const char* constructor, const char* event) {
1015#ifdef ENABLE_LOGGING_AND_PROFILING
1016  if (!Log::IsEnabled() || !FLAG_log_gc) return;
1017  // Event starts with comma, so we don't have it in the format string.
1018  static const char* event_text = "heap-js-ret-item,%s";
1019  // We take placeholder strings into account, but it's OK to be conservative.
1020  static const int event_text_len = StrLength(event_text);
1021  const int cons_len = StrLength(constructor);
1022  const int event_len = StrLength(event);
1023  int pos = 0;
1024  // Retainer lists can be long. We may need to split them into multiple events.
1025  do {
1026    LogMessageBuilder msg;
1027    msg.Append(event_text, constructor);
1028    int to_write = event_len - pos;
1029    if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) {
1030      int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len);
1031      ASSERT(cut_pos < event_len);
1032      while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
1033      if (event[cut_pos] != ',') {
1034        // Crash in debug mode, skip in release mode.
1035        ASSERT(false);
1036        return;
1037      }
1038      // Append a piece of event that fits, without trailing comma.
1039      msg.AppendStringPart(event + pos, cut_pos - pos);
1040      // Start next piece with comma.
1041      pos = cut_pos;
1042    } else {
1043      msg.Append("%s", event + pos);
1044      pos += event_len;
1045    }
1046    msg.Append('\n');
1047    msg.WriteToLogFile();
1048  } while (pos < event_len);
1049#endif
1050}
1051
1052
1053void Logger::HeapSampleJSProducerEvent(const char* constructor,
1054                                       Address* stack) {
1055#ifdef ENABLE_LOGGING_AND_PROFILING
1056  if (!Log::IsEnabled() || !FLAG_log_gc) return;
1057  LogMessageBuilder msg;
1058  msg.Append("heap-js-prod-item,%s", constructor);
1059  while (*stack != NULL) {
1060    msg.Append(",0x%" V8PRIxPTR, *stack++);
1061  }
1062  msg.Append("\n");
1063  msg.WriteToLogFile();
1064#endif
1065}
1066
1067
1068void Logger::DebugTag(const char* call_site_tag) {
1069#ifdef ENABLE_LOGGING_AND_PROFILING
1070  if (!Log::IsEnabled() || !FLAG_log) return;
1071  LogMessageBuilder msg;
1072  msg.Append("debug-tag,%s\n", call_site_tag);
1073  msg.WriteToLogFile();
1074#endif
1075}
1076
1077
1078void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1079#ifdef ENABLE_LOGGING_AND_PROFILING
1080  if (!Log::IsEnabled() || !FLAG_log) return;
1081  StringBuilder s(parameter.length() + 1);
1082  for (int i = 0; i < parameter.length(); ++i) {
1083    s.AddCharacter(static_cast<char>(parameter[i]));
1084  }
1085  char* parameter_string = s.Finalize();
1086  LogMessageBuilder msg;
1087  msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1088             event_type,
1089             OS::TimeCurrentMillis(),
1090             parameter_string);
1091  DeleteArray(parameter_string);
1092  msg.WriteToLogFile();
1093#endif
1094}
1095
1096
1097#ifdef ENABLE_LOGGING_AND_PROFILING
1098void Logger::TickEvent(TickSample* sample, bool overflow) {
1099  if (!Log::IsEnabled() || !FLAG_prof) return;
1100  LogMessageBuilder msg;
1101  msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
1102  msg.AppendAddress(sample->pc);
1103  msg.Append(',');
1104  msg.AppendAddress(sample->sp);
1105  msg.Append(',');
1106  msg.AppendAddress(sample->tos);
1107  msg.Append(",%d", static_cast<int>(sample->state));
1108  if (overflow) {
1109    msg.Append(",overflow");
1110  }
1111  for (int i = 0; i < sample->frames_count; ++i) {
1112    msg.Append(',');
1113    msg.AppendAddress(sample->stack[i]);
1114  }
1115  msg.Append('\n');
1116  msg.WriteToLogFile();
1117}
1118
1119
1120int Logger::GetActiveProfilerModules() {
1121  int result = PROFILER_MODULE_NONE;
1122  if (profiler_ != NULL && !profiler_->paused()) {
1123    result |= PROFILER_MODULE_CPU;
1124  }
1125  if (FLAG_log_gc) {
1126    result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1127  }
1128  return result;
1129}
1130
1131
1132void Logger::PauseProfiler(int flags, int tag) {
1133  if (!Log::IsEnabled()) return;
1134  if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
1135    // It is OK to have negative nesting.
1136    if (--cpu_profiler_nesting_ == 0) {
1137      profiler_->pause();
1138      if (FLAG_prof_lazy) {
1139        if (!FLAG_sliding_state_window && !RuntimeProfiler::IsEnabled()) {
1140          ticker_->Stop();
1141        }
1142        FLAG_log_code = false;
1143        // Must be the same message as Log::kDynamicBufferSeal.
1144        LOG(UncheckedStringEvent("profiler", "pause"));
1145      }
1146      --logging_nesting_;
1147    }
1148  }
1149  if (flags &
1150      (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
1151    if (--heap_profiler_nesting_ == 0) {
1152      FLAG_log_gc = false;
1153      --logging_nesting_;
1154    }
1155  }
1156  if (tag != 0) {
1157    UncheckedIntEvent("close-tag", tag);
1158  }
1159}
1160
1161
1162void Logger::ResumeProfiler(int flags, int tag) {
1163  if (!Log::IsEnabled()) return;
1164  if (tag != 0) {
1165    UncheckedIntEvent("open-tag", tag);
1166  }
1167  if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
1168    if (cpu_profiler_nesting_++ == 0) {
1169      ++logging_nesting_;
1170      if (FLAG_prof_lazy) {
1171        profiler_->Engage();
1172        LOG(UncheckedStringEvent("profiler", "resume"));
1173        FLAG_log_code = true;
1174        LogCompiledFunctions();
1175        LogAccessorCallbacks();
1176        if (!FLAG_sliding_state_window && !ticker_->IsActive()) {
1177          ticker_->Start();
1178        }
1179      }
1180      profiler_->resume();
1181    }
1182  }
1183  if (flags &
1184      (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
1185    if (heap_profiler_nesting_++ == 0) {
1186      ++logging_nesting_;
1187      FLAG_log_gc = true;
1188    }
1189  }
1190}
1191
1192
1193// This function can be called when Log's mutex is acquired,
1194// either from main or Profiler's thread.
1195void Logger::StopLoggingAndProfiling() {
1196  Log::stop();
1197  PauseProfiler(PROFILER_MODULE_CPU, 0);
1198}
1199
1200
1201bool Logger::IsProfilerSamplerActive() {
1202  return ticker_->IsActive();
1203}
1204
1205
1206int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1207  return Log::GetLogLines(from_pos, dest_buf, max_size);
1208}
1209
1210
1211class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1212 public:
1213  EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1214                                     Handle<Code>* code_objects,
1215                                     int* count)
1216      : sfis_(sfis), code_objects_(code_objects), count_(count) { }
1217
1218  virtual void EnterContext(Context* context) {}
1219  virtual void LeaveContext(Context* context) {}
1220
1221  virtual void VisitFunction(JSFunction* function) {
1222    if (sfis_ != NULL) {
1223      sfis_[*count_] = Handle<SharedFunctionInfo>(function->shared());
1224    }
1225    if (code_objects_ != NULL) {
1226      ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
1227      code_objects_[*count_] = Handle<Code>(function->code());
1228    }
1229    *count_ = *count_ + 1;
1230  }
1231
1232 private:
1233  Handle<SharedFunctionInfo>* sfis_;
1234  Handle<Code>* code_objects_;
1235  int* count_;
1236};
1237
1238
1239static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis,
1240                                      Handle<Code>* code_objects) {
1241  AssertNoAllocation no_alloc;
1242  int compiled_funcs_count = 0;
1243
1244  // Iterate the heap to find shared function info objects and record
1245  // the unoptimized code for them.
1246  HeapIterator iterator;
1247  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1248    if (!obj->IsSharedFunctionInfo()) continue;
1249    SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1250    if (sfi->is_compiled()
1251        && (!sfi->script()->IsScript()
1252            || Script::cast(sfi->script())->HasValidSource())) {
1253      if (sfis != NULL) {
1254        sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1255      }
1256      if (code_objects != NULL) {
1257        code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
1258      }
1259      ++compiled_funcs_count;
1260    }
1261  }
1262
1263  // Iterate all optimized functions in all contexts.
1264  EnumerateOptimizedFunctionsVisitor visitor(sfis,
1265                                             code_objects,
1266                                             &compiled_funcs_count);
1267  Deoptimizer::VisitAllOptimizedFunctions(&visitor);
1268
1269  return compiled_funcs_count;
1270}
1271
1272
1273void Logger::LogCodeObject(Object* object) {
1274  if (FLAG_log_code) {
1275    Code* code_object = Code::cast(object);
1276    LogEventsAndTags tag = Logger::STUB_TAG;
1277    const char* description = "Unknown code from the snapshot";
1278    switch (code_object->kind()) {
1279      case Code::FUNCTION:
1280      case Code::OPTIMIZED_FUNCTION:
1281        return;  // We log this later using LogCompiledFunctions.
1282      case Code::BINARY_OP_IC:  // fall through
1283      case Code::TYPE_RECORDING_BINARY_OP_IC:   // fall through
1284      case Code::COMPARE_IC:  // fall through
1285      case Code::STUB:
1286        description =
1287            CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
1288        if (description == NULL)
1289          description = "A stub from the snapshot";
1290        tag = Logger::STUB_TAG;
1291        break;
1292      case Code::BUILTIN:
1293        description = "A builtin from the snapshot";
1294        tag = Logger::BUILTIN_TAG;
1295        break;
1296      case Code::KEYED_LOAD_IC:
1297        description = "A keyed load IC from the snapshot";
1298        tag = Logger::KEYED_LOAD_IC_TAG;
1299        break;
1300      case Code::LOAD_IC:
1301        description = "A load IC from the snapshot";
1302        tag = Logger::LOAD_IC_TAG;
1303        break;
1304      case Code::STORE_IC:
1305        description = "A store IC from the snapshot";
1306        tag = Logger::STORE_IC_TAG;
1307        break;
1308      case Code::KEYED_STORE_IC:
1309        description = "A keyed store IC from the snapshot";
1310        tag = Logger::KEYED_STORE_IC_TAG;
1311        break;
1312      case Code::CALL_IC:
1313        description = "A call IC from the snapshot";
1314        tag = Logger::CALL_IC_TAG;
1315        break;
1316      case Code::KEYED_CALL_IC:
1317        description = "A keyed call IC from the snapshot";
1318        tag = Logger::KEYED_CALL_IC_TAG;
1319        break;
1320    }
1321    PROFILE(CodeCreateEvent(tag, code_object, description));
1322  }
1323}
1324
1325
1326void Logger::LogCodeInfo() {
1327#ifdef ENABLE_LOGGING_AND_PROFILING
1328  if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
1329#if V8_TARGET_ARCH_IA32
1330  const char arch[] = "ia32";
1331#elif V8_TARGET_ARCH_X64
1332  const char arch[] = "x64";
1333#elif V8_TARGET_ARCH_ARM
1334  const char arch[] = "arm";
1335#else
1336  const char arch[] = "unknown";
1337#endif
1338  LogMessageBuilder msg;
1339  msg.Append("code-info,%s,%d\n", arch, Code::kHeaderSize);
1340  msg.WriteToLogFile();
1341#endif  // ENABLE_LOGGING_AND_PROFILING
1342}
1343
1344
1345void Logger::LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg) {
1346  if (!FLAG_ll_prof || Log::output_code_handle_ == NULL) return;
1347  int pos = static_cast<int>(ftell(Log::output_code_handle_));
1348  size_t rv = fwrite(code->instruction_start(), 1, code->instruction_size(),
1349                     Log::output_code_handle_);
1350  ASSERT(static_cast<size_t>(code->instruction_size()) == rv);
1351  USE(rv);
1352  msg->Append(",%d", pos);
1353}
1354
1355
1356void Logger::LogCodeObjects() {
1357  AssertNoAllocation no_alloc;
1358  HeapIterator iterator;
1359  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1360    if (obj->IsCode()) LogCodeObject(obj);
1361  }
1362}
1363
1364
1365void Logger::LogCompiledFunctions() {
1366  HandleScope scope;
1367  const int compiled_funcs_count = EnumerateCompiledFunctions(NULL, NULL);
1368  ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
1369  ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
1370  EnumerateCompiledFunctions(sfis.start(), code_objects.start());
1371
1372  // During iteration, there can be heap allocation due to
1373  // GetScriptLineNumber call.
1374  for (int i = 0; i < compiled_funcs_count; ++i) {
1375    if (*code_objects[i] == Builtins::builtin(Builtins::LazyCompile)) continue;
1376    Handle<SharedFunctionInfo> shared = sfis[i];
1377    Handle<String> func_name(shared->DebugName());
1378    if (shared->script()->IsScript()) {
1379      Handle<Script> script(Script::cast(shared->script()));
1380      if (script->name()->IsString()) {
1381        Handle<String> script_name(String::cast(script->name()));
1382        int line_num = GetScriptLineNumber(script, shared->start_position());
1383        if (line_num > 0) {
1384          PROFILE(CodeCreateEvent(
1385              Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1386              *code_objects[i], *shared,
1387              *script_name, line_num + 1));
1388        } else {
1389          // Can't distinguish eval and script here, so always use Script.
1390          PROFILE(CodeCreateEvent(
1391              Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1392              *code_objects[i], *shared, *script_name));
1393        }
1394      } else {
1395        PROFILE(CodeCreateEvent(
1396            Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1397            *code_objects[i], *shared, *func_name));
1398      }
1399    } else if (shared->IsApiFunction()) {
1400      // API function.
1401      FunctionTemplateInfo* fun_data = shared->get_api_func_data();
1402      Object* raw_call_data = fun_data->call_code();
1403      if (!raw_call_data->IsUndefined()) {
1404        CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1405        Object* callback_obj = call_data->callback();
1406        Address entry_point = v8::ToCData<Address>(callback_obj);
1407        PROFILE(CallbackEvent(*func_name, entry_point));
1408      }
1409    } else {
1410      PROFILE(CodeCreateEvent(
1411          Logger::LAZY_COMPILE_TAG, *code_objects[i], *shared, *func_name));
1412    }
1413  }
1414}
1415
1416
1417void Logger::LogAccessorCallbacks() {
1418  AssertNoAllocation no_alloc;
1419  HeapIterator iterator;
1420  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1421    if (!obj->IsAccessorInfo()) continue;
1422    AccessorInfo* ai = AccessorInfo::cast(obj);
1423    if (!ai->name()->IsString()) continue;
1424    String* name = String::cast(ai->name());
1425    Address getter_entry = v8::ToCData<Address>(ai->getter());
1426    if (getter_entry != 0) {
1427      PROFILE(GetterCallbackEvent(name, getter_entry));
1428    }
1429    Address setter_entry = v8::ToCData<Address>(ai->setter());
1430    if (setter_entry != 0) {
1431      PROFILE(SetterCallbackEvent(name, setter_entry));
1432    }
1433  }
1434}
1435
1436#endif
1437
1438
1439bool Logger::Setup() {
1440#ifdef ENABLE_LOGGING_AND_PROFILING
1441  // --log-all enables all the log flags.
1442  if (FLAG_log_all) {
1443    FLAG_log_runtime = true;
1444    FLAG_log_api = true;
1445    FLAG_log_code = true;
1446    FLAG_log_gc = true;
1447    FLAG_log_suspect = true;
1448    FLAG_log_handles = true;
1449    FLAG_log_regexp = true;
1450  }
1451
1452  // --prof implies --log-code.
1453  if (FLAG_prof) FLAG_log_code = true;
1454
1455  // --ll-prof implies --log-code and --log-snapshot-positions.
1456  if (FLAG_ll_prof) {
1457    FLAG_log_code = true;
1458    FLAG_log_snapshot_positions = true;
1459  }
1460
1461  // --prof_lazy controls --log-code, implies --noprof_auto.
1462  if (FLAG_prof_lazy) {
1463    FLAG_log_code = false;
1464    FLAG_prof_auto = false;
1465  }
1466
1467  bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1468      || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1469      || FLAG_log_regexp || FLAG_log_state_changes;
1470
1471  bool open_log_file = start_logging || FLAG_prof_lazy;
1472
1473  // If we're logging anything, we need to open the log file.
1474  if (open_log_file) {
1475    if (strcmp(FLAG_logfile, "-") == 0) {
1476      Log::OpenStdout();
1477    } else if (strcmp(FLAG_logfile, "*") == 0) {
1478      Log::OpenMemoryBuffer();
1479    } else if (strchr(FLAG_logfile, '%') != NULL) {
1480      // If there's a '%' in the log file name we have to expand
1481      // placeholders.
1482      HeapStringAllocator allocator;
1483      StringStream stream(&allocator);
1484      for (const char* p = FLAG_logfile; *p; p++) {
1485        if (*p == '%') {
1486          p++;
1487          switch (*p) {
1488            case '\0':
1489              // If there's a % at the end of the string we back up
1490              // one character so we can escape the loop properly.
1491              p--;
1492              break;
1493            case 't': {
1494              // %t expands to the current time in milliseconds.
1495              double time = OS::TimeCurrentMillis();
1496              stream.Add("%.0f", FmtElm(time));
1497              break;
1498            }
1499            case '%':
1500              // %% expands (contracts really) to %.
1501              stream.Put('%');
1502              break;
1503            default:
1504              // All other %'s expand to themselves.
1505              stream.Put('%');
1506              stream.Put(*p);
1507              break;
1508          }
1509        } else {
1510          stream.Put(*p);
1511        }
1512      }
1513      SmartPointer<const char> expanded = stream.ToCString();
1514      Log::OpenFile(*expanded);
1515    } else {
1516      Log::OpenFile(FLAG_logfile);
1517    }
1518  }
1519
1520  if (FLAG_ll_prof) LogCodeInfo();
1521
1522  ticker_ = new Ticker(kSamplingIntervalMs);
1523
1524  if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1525    sliding_state_window_ = new SlidingStateWindow();
1526  }
1527
1528  if (start_logging) {
1529    logging_nesting_ = 1;
1530  }
1531
1532  if (FLAG_prof) {
1533    profiler_ = new Profiler();
1534    if (!FLAG_prof_auto) {
1535      profiler_->pause();
1536    } else {
1537      logging_nesting_ = 1;
1538    }
1539    if (!FLAG_prof_lazy) {
1540      profiler_->Engage();
1541    }
1542  }
1543
1544  LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
1545  return true;
1546
1547#else
1548  return false;
1549#endif
1550}
1551
1552
1553void Logger::EnsureTickerStarted() {
1554#ifdef ENABLE_LOGGING_AND_PROFILING
1555  ASSERT(ticker_ != NULL);
1556  if (!ticker_->IsActive()) ticker_->Start();
1557#endif
1558}
1559
1560
1561void Logger::EnsureTickerStopped() {
1562#ifdef ENABLE_LOGGING_AND_PROFILING
1563  if (ticker_ != NULL && ticker_->IsActive()) ticker_->Stop();
1564#endif
1565}
1566
1567
1568void Logger::TearDown() {
1569#ifdef ENABLE_LOGGING_AND_PROFILING
1570  LogMessageBuilder::set_write_failure_handler(NULL);
1571
1572  // Stop the profiler before closing the file.
1573  if (profiler_ != NULL) {
1574    profiler_->Disengage();
1575    delete profiler_;
1576    profiler_ = NULL;
1577  }
1578
1579  delete sliding_state_window_;
1580  sliding_state_window_ = NULL;
1581
1582  delete ticker_;
1583  ticker_ = NULL;
1584
1585  Log::Close();
1586#endif
1587}
1588
1589
1590void Logger::EnableSlidingStateWindow() {
1591#ifdef ENABLE_LOGGING_AND_PROFILING
1592  // If the ticker is NULL, Logger::Setup has not been called yet.  In
1593  // that case, we set the sliding_state_window flag so that the
1594  // sliding window computation will be started when Logger::Setup is
1595  // called.
1596  if (ticker_ == NULL) {
1597    FLAG_sliding_state_window = true;
1598    return;
1599  }
1600  // Otherwise, if the sliding state window computation has not been
1601  // started we do it now.
1602  if (sliding_state_window_ == NULL) {
1603    sliding_state_window_ = new SlidingStateWindow();
1604  }
1605#endif
1606}
1607
1608} }  // namespace v8::internal
1609