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