blob: 5de7429e5d244cfc69cc128add4fa1d3901d83b3 [file] [log] [blame]
Steve Blocka7e24c12009-10-30 11:49:00 +00001// 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"
Steve Blockd0582a62009-12-15 09:54:21 +000033#include "global-handles.h"
Steve Blocka7e24c12009-10-30 11:49:00 +000034#include "log.h"
35#include "macro-assembler.h"
36#include "serialize.h"
37#include "string-stream.h"
38
39namespace v8 {
40namespace 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//
49class 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
62 void IncrementStateCounter(StateTag state) {
63 Counters::state_counters[state].Increment();
64 }
65
66
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//
79class Profiler: public Thread {
80 public:
81 Profiler();
82 void Engage();
83 void Disengage();
84
85 // Inserts collected profiling data into buffer.
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.
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.
112 static bool paused() { return paused_; }
113 static void pause() { paused_ = true; }
114 static void resume() { paused_ = false; }
115
116 private:
117 // Returns the next index in the cyclic buffer.
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
Steve Blockd0582a62009-12-15 09:54:21 +0000129 // Tells whether profiler is engaged, that is, processing thread is stated.
130 bool engaged_;
131
Steve Blocka7e24c12009-10-30 11:49:00 +0000132 // 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
139bool Profiler::paused_ = false;
140
141
142//
143// StackTracer implementation
144//
145void 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
Leon Clarked91b9f72010-01-27 17:25:45 +0000158 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
Steve Blockd0582a62009-12-15 09:54:21 +0000165 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
Leon Clarked91b9f72010-01-27 17:25:45 +0000172 SafeStackTraceFrameIterator it(sample->fp, sample->sp,
173 sample->sp, js_entry_sp);
Steve Blocka7e24c12009-10-30 11:49:00 +0000174 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//
186class Ticker: public Sampler {
187 public:
188 explicit Ticker(int interval):
189 Sampler(interval, FLAG_prof), window_(NULL), profiler_(NULL) {}
190
191 ~Ticker() { if (IsActive()) Stop(); }
192
193 void SampleStack(TickSample* sample) {
194 StackTracer::Trace(sample);
195 }
196
197 void Tick(TickSample* sample) {
198 if (profiler_) profiler_->Insert(sample);
199 if (window_) window_->AddState(sample->state);
200 }
201
202 void SetWindow(SlidingStateWindow* window) {
203 window_ = window;
204 if (!IsActive()) Start();
205 }
206
207 void ClearWindow() {
208 window_ = NULL;
209 if (!profiler_ && IsActive()) Stop();
210 }
211
212 void SetProfiler(Profiler* profiler) {
213 profiler_ = profiler;
214 if (!FLAG_prof_lazy && !IsActive()) Start();
215 }
216
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//
231SlidingStateWindow::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
239SlidingStateWindow::~SlidingStateWindow() {
240 Logger::ticker_->ClearWindow();
241}
242
243
244void 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//
Steve Blockd0582a62009-12-15 09:54:21 +0000260Profiler::Profiler()
261 : head_(0),
262 tail_(0),
263 overflow_(false),
264 buffer_semaphore_(OS::CreateSemaphore(0)),
265 engaged_(false),
266 running_(false) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000267}
268
269
270void Profiler::Engage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000271 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 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000279
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
292void Profiler::Disengage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000293 if (!engaged_) return;
294
Steve Blocka7e24c12009-10-30 11:49:00 +0000295 // 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
312void 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//
325Ticker* Logger::ticker_ = NULL;
326Profiler* Logger::profiler_ = NULL;
327VMState* Logger::current_state_ = NULL;
328VMState Logger::bottom_state_(EXTERNAL);
329SlidingStateWindow* Logger::sliding_state_window_ = NULL;
330const char** Logger::log_events_ = NULL;
331CompressionHelper* Logger::compression_helper_ = NULL;
332bool Logger::is_logging_ = false;
333
334#define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name,
335const char* kLongLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
336 LOG_EVENTS_AND_TAGS_LIST(DECLARE_LONG_EVENT)
337};
338#undef DECLARE_LONG_EVENT
339
340#define DECLARE_SHORT_EVENT(ignore1, ignore2, short_name) short_name,
341const char* kCompressedLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
342 LOG_EVENTS_AND_TAGS_LIST(DECLARE_SHORT_EVENT)
343};
344#undef DECLARE_SHORT_EVENT
345
346
347void Logger::ProfilerBeginEvent() {
348 if (!Log::IsEnabled()) return;
349 LogMessageBuilder msg;
350 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
351 if (FLAG_compress_log) {
352 msg.Append("profiler,\"compression\",%d\n", kCompressionWindowSize);
353 }
354 msg.WriteToLogFile();
355}
356
357
358void Logger::LogAliases() {
359 if (!Log::IsEnabled() || !FLAG_compress_log) return;
360 LogMessageBuilder msg;
361 for (int i = 0; i < NUMBER_OF_LOG_EVENTS; ++i) {
362 msg.Append("alias,%s,%s\n",
363 kCompressedLogEventsNames[i], kLongLogEventsNames[i]);
364 }
365 msg.WriteToLogFile();
366}
367
368#endif // ENABLE_LOGGING_AND_PROFILING
369
370
371void Logger::Preamble(const char* content) {
372#ifdef ENABLE_LOGGING_AND_PROFILING
373 if (!Log::IsEnabled() || !FLAG_log_code) return;
374 LogMessageBuilder msg;
375 msg.WriteCStringToLogFile(content);
376#endif
377}
378
379
380void Logger::StringEvent(const char* name, const char* value) {
381#ifdef ENABLE_LOGGING_AND_PROFILING
382 if (FLAG_log) UncheckedStringEvent(name, value);
383#endif
384}
385
386
387#ifdef ENABLE_LOGGING_AND_PROFILING
388void Logger::UncheckedStringEvent(const char* name, const char* value) {
389 if (!Log::IsEnabled()) return;
390 LogMessageBuilder msg;
391 msg.Append("%s,\"%s\"\n", name, value);
392 msg.WriteToLogFile();
393}
394#endif
395
396
397void Logger::IntEvent(const char* name, int value) {
398#ifdef ENABLE_LOGGING_AND_PROFILING
399 if (!Log::IsEnabled() || !FLAG_log) return;
400 LogMessageBuilder msg;
401 msg.Append("%s,%d\n", name, value);
402 msg.WriteToLogFile();
403#endif
404}
405
406
407void Logger::HandleEvent(const char* name, Object** location) {
408#ifdef ENABLE_LOGGING_AND_PROFILING
409 if (!Log::IsEnabled() || !FLAG_log_handles) return;
410 LogMessageBuilder msg;
411 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
412 msg.WriteToLogFile();
413#endif
414}
415
416
417#ifdef ENABLE_LOGGING_AND_PROFILING
418// ApiEvent is private so all the calls come from the Logger class. It is the
419// caller's responsibility to ensure that log is enabled and that
420// FLAG_log_api is true.
421void Logger::ApiEvent(const char* format, ...) {
422 ASSERT(Log::IsEnabled() && FLAG_log_api);
423 LogMessageBuilder msg;
424 va_list ap;
425 va_start(ap, format);
426 msg.AppendVA(format, ap);
427 va_end(ap);
428 msg.WriteToLogFile();
429}
430#endif
431
432
433void Logger::ApiNamedSecurityCheck(Object* key) {
434#ifdef ENABLE_LOGGING_AND_PROFILING
435 if (!Log::IsEnabled() || !FLAG_log_api) return;
436 if (key->IsString()) {
437 SmartPointer<char> str =
438 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
439 ApiEvent("api,check-security,\"%s\"\n", *str);
440 } else if (key->IsUndefined()) {
441 ApiEvent("api,check-security,undefined\n");
442 } else {
443 ApiEvent("api,check-security,['no-name']\n");
444 }
445#endif
446}
447
448
449void Logger::SharedLibraryEvent(const char* library_path,
450 uintptr_t start,
451 uintptr_t end) {
452#ifdef ENABLE_LOGGING_AND_PROFILING
453 if (!Log::IsEnabled() || !FLAG_prof) return;
454 LogMessageBuilder msg;
455 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
456 library_path,
457 start,
458 end);
459 msg.WriteToLogFile();
460#endif
461}
462
463
464void Logger::SharedLibraryEvent(const wchar_t* library_path,
465 uintptr_t start,
466 uintptr_t end) {
467#ifdef ENABLE_LOGGING_AND_PROFILING
468 if (!Log::IsEnabled() || !FLAG_prof) return;
469 LogMessageBuilder msg;
470 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
471 library_path,
472 start,
473 end);
474 msg.WriteToLogFile();
475#endif
476}
477
478
479#ifdef ENABLE_LOGGING_AND_PROFILING
480void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
481 // Prints "/" + re.source + "/" +
482 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
483 LogMessageBuilder msg;
484
485 Handle<Object> source = GetProperty(regexp, "source");
486 if (!source->IsString()) {
487 msg.Append("no source");
488 return;
489 }
490
491 switch (regexp->TypeTag()) {
492 case JSRegExp::ATOM:
493 msg.Append('a');
494 break;
495 default:
496 break;
497 }
498 msg.Append('/');
499 msg.AppendDetailed(*Handle<String>::cast(source), false);
500 msg.Append('/');
501
502 // global flag
503 Handle<Object> global = GetProperty(regexp, "global");
504 if (global->IsTrue()) {
505 msg.Append('g');
506 }
507 // ignorecase flag
508 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
509 if (ignorecase->IsTrue()) {
510 msg.Append('i');
511 }
512 // multiline flag
513 Handle<Object> multiline = GetProperty(regexp, "multiline");
514 if (multiline->IsTrue()) {
515 msg.Append('m');
516 }
517
518 msg.WriteToLogFile();
519}
520#endif // ENABLE_LOGGING_AND_PROFILING
521
522
523void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
524#ifdef ENABLE_LOGGING_AND_PROFILING
525 if (!Log::IsEnabled() || !FLAG_log_regexp) return;
526 LogMessageBuilder msg;
527 msg.Append("regexp-compile,");
528 LogRegExpSource(regexp);
529 msg.Append(in_cache ? ",hit\n" : ",miss\n");
530 msg.WriteToLogFile();
531#endif
532}
533
534
535void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
536#ifdef ENABLE_LOGGING_AND_PROFILING
537 if (!Log::IsEnabled() || !FLAG_log_runtime) return;
538 HandleScope scope;
539 LogMessageBuilder msg;
540 for (int i = 0; i < format.length(); i++) {
541 char c = format[i];
542 if (c == '%' && i <= format.length() - 2) {
543 i++;
544 ASSERT('0' <= format[i] && format[i] <= '9');
545 Object* obj = args->GetElement(format[i] - '0');
546 i++;
547 switch (format[i]) {
548 case 's':
549 msg.AppendDetailed(String::cast(obj), false);
550 break;
551 case 'S':
552 msg.AppendDetailed(String::cast(obj), true);
553 break;
554 case 'r':
555 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
556 break;
557 case 'x':
558 msg.Append("0x%x", Smi::cast(obj)->value());
559 break;
560 case 'i':
561 msg.Append("%i", Smi::cast(obj)->value());
562 break;
563 default:
564 UNREACHABLE();
565 }
566 } else {
567 msg.Append(c);
568 }
569 }
570 msg.Append('\n');
571 msg.WriteToLogFile();
572#endif
573}
574
575
576void Logger::ApiIndexedSecurityCheck(uint32_t index) {
577#ifdef ENABLE_LOGGING_AND_PROFILING
578 if (!Log::IsEnabled() || !FLAG_log_api) return;
579 ApiEvent("api,check-security,%u\n", index);
580#endif
581}
582
583
584void Logger::ApiNamedPropertyAccess(const char* tag,
585 JSObject* holder,
586 Object* name) {
587#ifdef ENABLE_LOGGING_AND_PROFILING
588 ASSERT(name->IsString());
589 if (!Log::IsEnabled() || !FLAG_log_api) return;
590 String* class_name_obj = holder->class_name();
591 SmartPointer<char> class_name =
592 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
593 SmartPointer<char> property_name =
594 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
595 Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
596#endif
597}
598
599void Logger::ApiIndexedPropertyAccess(const char* tag,
600 JSObject* holder,
601 uint32_t index) {
602#ifdef ENABLE_LOGGING_AND_PROFILING
603 if (!Log::IsEnabled() || !FLAG_log_api) return;
604 String* class_name_obj = holder->class_name();
605 SmartPointer<char> class_name =
606 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
607 Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
608#endif
609}
610
611void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
612#ifdef ENABLE_LOGGING_AND_PROFILING
613 if (!Log::IsEnabled() || !FLAG_log_api) return;
614 String* class_name_obj = object->class_name();
615 SmartPointer<char> class_name =
616 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
617 Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
618#endif
619}
620
621
622void Logger::ApiEntryCall(const char* name) {
623#ifdef ENABLE_LOGGING_AND_PROFILING
624 if (!Log::IsEnabled() || !FLAG_log_api) return;
625 Logger::ApiEvent("api,%s\n", name);
626#endif
627}
628
629
630void Logger::NewEvent(const char* name, void* object, size_t size) {
631#ifdef ENABLE_LOGGING_AND_PROFILING
632 if (!Log::IsEnabled() || !FLAG_log) return;
633 LogMessageBuilder msg;
634 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
635 static_cast<unsigned int>(size));
636 msg.WriteToLogFile();
637#endif
638}
639
640
641void Logger::DeleteEvent(const char* name, void* object) {
642#ifdef ENABLE_LOGGING_AND_PROFILING
643 if (!Log::IsEnabled() || !FLAG_log) return;
644 LogMessageBuilder msg;
645 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
646 msg.WriteToLogFile();
647#endif
648}
649
650
651#ifdef ENABLE_LOGGING_AND_PROFILING
652
653// A class that contains all common code dealing with record compression.
654class CompressionHelper {
655 public:
656 explicit CompressionHelper(int window_size)
657 : compressor_(window_size), repeat_count_(0) { }
658
659 // Handles storing message in compressor, retrieving the previous one and
660 // prefixing it with repeat count, if needed.
661 // Returns true if message needs to be written to log.
662 bool HandleMessage(LogMessageBuilder* msg) {
663 if (!msg->StoreInCompressor(&compressor_)) {
664 // Current message repeats the previous one, don't write it.
665 ++repeat_count_;
666 return false;
667 }
668 if (repeat_count_ == 0) {
669 return msg->RetrieveCompressedPrevious(&compressor_);
670 }
671 OS::SNPrintF(prefix_, "%s,%d,",
672 Logger::log_events_[Logger::REPEAT_META_EVENT],
673 repeat_count_ + 1);
674 repeat_count_ = 0;
675 return msg->RetrieveCompressedPrevious(&compressor_, prefix_.start());
676 }
677
678 private:
679 LogRecordCompressor compressor_;
680 int repeat_count_;
681 EmbeddedVector<char, 20> prefix_;
682};
683
684#endif // ENABLE_LOGGING_AND_PROFILING
685
686
Steve Blockd0582a62009-12-15 09:54:21 +0000687#ifdef ENABLE_LOGGING_AND_PROFILING
688void Logger::CallbackEventInternal(const char* prefix, const char* name,
689 Address entry_point) {
690 if (!Log::IsEnabled() || !FLAG_log_code) return;
691 LogMessageBuilder msg;
692 msg.Append("%s,%s,",
693 log_events_[CODE_CREATION_EVENT], log_events_[CALLBACK_TAG]);
694 msg.AppendAddress(entry_point);
695 msg.Append(",1,\"%s%s\"", prefix, name);
696 if (FLAG_compress_log) {
697 ASSERT(compression_helper_ != NULL);
698 if (!compression_helper_->HandleMessage(&msg)) return;
699 }
700 msg.Append('\n');
701 msg.WriteToLogFile();
702}
703#endif
704
705
706void Logger::CallbackEvent(String* name, Address entry_point) {
707#ifdef ENABLE_LOGGING_AND_PROFILING
708 if (!Log::IsEnabled() || !FLAG_log_code) return;
709 SmartPointer<char> str =
710 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
711 CallbackEventInternal("", *str, entry_point);
712#endif
713}
714
715
716void Logger::GetterCallbackEvent(String* name, Address entry_point) {
717#ifdef ENABLE_LOGGING_AND_PROFILING
718 if (!Log::IsEnabled() || !FLAG_log_code) return;
719 SmartPointer<char> str =
720 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
721 CallbackEventInternal("get ", *str, entry_point);
722#endif
723}
724
725
726void Logger::SetterCallbackEvent(String* name, Address entry_point) {
727#ifdef ENABLE_LOGGING_AND_PROFILING
728 if (!Log::IsEnabled() || !FLAG_log_code) return;
729 SmartPointer<char> str =
730 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
731 CallbackEventInternal("set ", *str, entry_point);
732#endif
733}
734
735
Steve Blocka7e24c12009-10-30 11:49:00 +0000736void Logger::CodeCreateEvent(LogEventsAndTags tag,
737 Code* code,
738 const char* comment) {
739#ifdef ENABLE_LOGGING_AND_PROFILING
740 if (!Log::IsEnabled() || !FLAG_log_code) return;
741 LogMessageBuilder msg;
742 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
743 msg.AppendAddress(code->address());
744 msg.Append(",%d,\"", code->ExecutableSize());
745 for (const char* p = comment; *p != '\0'; p++) {
746 if (*p == '"') {
747 msg.Append('\\');
748 }
749 msg.Append(*p);
750 }
751 msg.Append('"');
752 if (FLAG_compress_log) {
753 ASSERT(compression_helper_ != NULL);
754 if (!compression_helper_->HandleMessage(&msg)) return;
755 }
756 msg.Append('\n');
757 msg.WriteToLogFile();
758#endif
759}
760
761
762void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
763#ifdef ENABLE_LOGGING_AND_PROFILING
764 if (!Log::IsEnabled() || !FLAG_log_code) return;
765 LogMessageBuilder msg;
766 SmartPointer<char> str =
767 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
768 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
769 msg.AppendAddress(code->address());
770 msg.Append(",%d,\"%s\"", code->ExecutableSize(), *str);
771 if (FLAG_compress_log) {
772 ASSERT(compression_helper_ != NULL);
773 if (!compression_helper_->HandleMessage(&msg)) return;
774 }
775 msg.Append('\n');
776 msg.WriteToLogFile();
777#endif
778}
779
780
781void Logger::CodeCreateEvent(LogEventsAndTags tag,
782 Code* code, String* name,
783 String* source, int line) {
784#ifdef ENABLE_LOGGING_AND_PROFILING
785 if (!Log::IsEnabled() || !FLAG_log_code) return;
786 LogMessageBuilder msg;
787 SmartPointer<char> str =
788 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
789 SmartPointer<char> sourcestr =
790 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
791 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
792 msg.AppendAddress(code->address());
793 msg.Append(",%d,\"%s %s:%d\"",
794 code->ExecutableSize(), *str, *sourcestr, line);
795 if (FLAG_compress_log) {
796 ASSERT(compression_helper_ != NULL);
797 if (!compression_helper_->HandleMessage(&msg)) return;
798 }
799 msg.Append('\n');
800 msg.WriteToLogFile();
801#endif
802}
803
804
805void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
806#ifdef ENABLE_LOGGING_AND_PROFILING
807 if (!Log::IsEnabled() || !FLAG_log_code) return;
808 LogMessageBuilder msg;
809 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
810 msg.AppendAddress(code->address());
811 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
812 if (FLAG_compress_log) {
813 ASSERT(compression_helper_ != NULL);
814 if (!compression_helper_->HandleMessage(&msg)) return;
815 }
816 msg.Append('\n');
817 msg.WriteToLogFile();
818#endif
819}
820
821
822void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
823#ifdef ENABLE_LOGGING_AND_PROFILING
824 if (!Log::IsEnabled() || !FLAG_log_code) return;
825 LogMessageBuilder msg;
826 msg.Append("%s,%s,",
827 log_events_[CODE_CREATION_EVENT], log_events_[REG_EXP_TAG]);
828 msg.AppendAddress(code->address());
829 msg.Append(",%d,\"", code->ExecutableSize());
830 msg.AppendDetailed(source, false);
831 msg.Append('\"');
832 if (FLAG_compress_log) {
833 ASSERT(compression_helper_ != NULL);
834 if (!compression_helper_->HandleMessage(&msg)) return;
835 }
836 msg.Append('\n');
837 msg.WriteToLogFile();
838#endif
839}
840
841
842void Logger::CodeMoveEvent(Address from, Address to) {
843#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000844 MoveEventInternal(CODE_MOVE_EVENT, from, to);
Steve Blocka7e24c12009-10-30 11:49:00 +0000845#endif
846}
847
848
849void Logger::CodeDeleteEvent(Address from) {
850#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000851 DeleteEventInternal(CODE_DELETE_EVENT, from);
Steve Blocka7e24c12009-10-30 11:49:00 +0000852#endif
853}
854
855
Leon Clarkee46be812010-01-19 14:06:41 +0000856void Logger::SnapshotPositionEvent(Address addr, int pos) {
857#ifdef ENABLE_LOGGING_AND_PROFILING
858 if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return;
859 LogMessageBuilder msg;
860 msg.Append("%s,", log_events_[SNAPSHOT_POSITION_EVENT]);
861 msg.AppendAddress(addr);
862 msg.Append(",%d", pos);
863 if (FLAG_compress_log) {
864 ASSERT(compression_helper_ != NULL);
865 if (!compression_helper_->HandleMessage(&msg)) return;
866 }
867 msg.Append('\n');
868 msg.WriteToLogFile();
869#endif
870}
871
872
Leon Clarked91b9f72010-01-27 17:25:45 +0000873void Logger::FunctionCreateEvent(JSFunction* function) {
874#ifdef ENABLE_LOGGING_AND_PROFILING
875 static Address prev_code = NULL;
876 if (!Log::IsEnabled() || !FLAG_log_code) return;
877 LogMessageBuilder msg;
878 msg.Append("%s,", log_events_[FUNCTION_CREATION_EVENT]);
879 msg.AppendAddress(function->address());
880 msg.Append(',');
881 msg.AppendAddress(function->code()->address(), prev_code);
882 prev_code = function->code()->address();
883 if (FLAG_compress_log) {
884 ASSERT(compression_helper_ != NULL);
885 if (!compression_helper_->HandleMessage(&msg)) return;
886 }
887 msg.Append('\n');
888 msg.WriteToLogFile();
889#endif
890}
891
892
893void Logger::FunctionMoveEvent(Address from, Address to) {
894#ifdef ENABLE_LOGGING_AND_PROFILING
895 MoveEventInternal(FUNCTION_MOVE_EVENT, from, to);
896#endif
897}
898
899
900void Logger::FunctionDeleteEvent(Address from) {
901#ifdef ENABLE_LOGGING_AND_PROFILING
902 DeleteEventInternal(FUNCTION_DELETE_EVENT, from);
903#endif
904}
905
906
907#ifdef ENABLE_LOGGING_AND_PROFILING
908void Logger::MoveEventInternal(LogEventsAndTags event,
909 Address from,
910 Address to) {
911 static Address prev_to_ = NULL;
912 if (!Log::IsEnabled() || !FLAG_log_code) return;
913 LogMessageBuilder msg;
914 msg.Append("%s,", log_events_[event]);
915 msg.AppendAddress(from);
916 msg.Append(',');
917 msg.AppendAddress(to, prev_to_);
918 prev_to_ = to;
919 if (FLAG_compress_log) {
920 ASSERT(compression_helper_ != NULL);
921 if (!compression_helper_->HandleMessage(&msg)) return;
922 }
923 msg.Append('\n');
924 msg.WriteToLogFile();
925}
926#endif
927
928
929#ifdef ENABLE_LOGGING_AND_PROFILING
930void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
931 if (!Log::IsEnabled() || !FLAG_log_code) return;
932 LogMessageBuilder msg;
933 msg.Append("%s,", log_events_[event]);
934 msg.AppendAddress(from);
935 if (FLAG_compress_log) {
936 ASSERT(compression_helper_ != NULL);
937 if (!compression_helper_->HandleMessage(&msg)) return;
938 }
939 msg.Append('\n');
940 msg.WriteToLogFile();
941}
942#endif
943
944
Steve Blocka7e24c12009-10-30 11:49:00 +0000945void Logger::ResourceEvent(const char* name, const char* tag) {
946#ifdef ENABLE_LOGGING_AND_PROFILING
947 if (!Log::IsEnabled() || !FLAG_log) return;
948 LogMessageBuilder msg;
949 msg.Append("%s,%s,", name, tag);
950
951 uint32_t sec, usec;
952 if (OS::GetUserTime(&sec, &usec) != -1) {
953 msg.Append("%d,%d,", sec, usec);
954 }
955 msg.Append("%.0f", OS::TimeCurrentMillis());
956
957 msg.Append('\n');
958 msg.WriteToLogFile();
959#endif
960}
961
962
963void Logger::SuspectReadEvent(String* name, Object* obj) {
964#ifdef ENABLE_LOGGING_AND_PROFILING
965 if (!Log::IsEnabled() || !FLAG_log_suspect) return;
966 LogMessageBuilder msg;
967 String* class_name = obj->IsJSObject()
968 ? JSObject::cast(obj)->class_name()
969 : Heap::empty_string();
970 msg.Append("suspect-read,");
971 msg.Append(class_name);
972 msg.Append(',');
973 msg.Append('"');
974 msg.Append(name);
975 msg.Append('"');
976 msg.Append('\n');
977 msg.WriteToLogFile();
978#endif
979}
980
981
982void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
983#ifdef ENABLE_LOGGING_AND_PROFILING
984 if (!Log::IsEnabled() || !FLAG_log_gc) return;
985 LogMessageBuilder msg;
986 // Using non-relative system time in order to be able to synchronize with
987 // external memory profiling events (e.g. DOM memory size).
988 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
989 space, kind, OS::TimeCurrentMillis());
990 msg.WriteToLogFile();
991#endif
992}
993
994
995void Logger::HeapSampleStats(const char* space, const char* kind,
996 int capacity, int used) {
997#ifdef ENABLE_LOGGING_AND_PROFILING
998 if (!Log::IsEnabled() || !FLAG_log_gc) return;
999 LogMessageBuilder msg;
1000 msg.Append("heap-sample-stats,\"%s\",\"%s\",%d,%d\n",
1001 space, kind, capacity, used);
1002 msg.WriteToLogFile();
1003#endif
1004}
1005
1006
1007void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1008#ifdef ENABLE_LOGGING_AND_PROFILING
1009 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1010 LogMessageBuilder msg;
1011 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1012 msg.WriteToLogFile();
1013#endif
1014}
1015
1016
1017void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1018#ifdef ENABLE_LOGGING_AND_PROFILING
1019 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1020 LogMessageBuilder msg;
1021 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1022 msg.WriteToLogFile();
1023#endif
1024}
1025
1026
1027void Logger::HeapSampleJSConstructorEvent(const char* constructor,
1028 int number, int bytes) {
1029#ifdef ENABLE_LOGGING_AND_PROFILING
1030 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1031 LogMessageBuilder msg;
1032 msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
1033 msg.WriteToLogFile();
1034#endif
1035}
1036
1037
1038void Logger::HeapSampleJSRetainersEvent(
1039 const char* constructor, const char* event) {
1040#ifdef ENABLE_LOGGING_AND_PROFILING
1041 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1042 // Event starts with comma, so we don't have it in the format string.
1043 static const char* event_text = "heap-js-ret-item,%s";
1044 // We take placeholder strings into account, but it's OK to be conservative.
Steve Blockd0582a62009-12-15 09:54:21 +00001045 static const int event_text_len = StrLength(event_text);
1046 const int cons_len = StrLength(constructor);
1047 const int event_len = StrLength(event);
Steve Blocka7e24c12009-10-30 11:49:00 +00001048 int pos = 0;
1049 // Retainer lists can be long. We may need to split them into multiple events.
1050 do {
1051 LogMessageBuilder msg;
1052 msg.Append(event_text, constructor);
1053 int to_write = event_len - pos;
1054 if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) {
1055 int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len);
1056 ASSERT(cut_pos < event_len);
1057 while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
1058 if (event[cut_pos] != ',') {
1059 // Crash in debug mode, skip in release mode.
1060 ASSERT(false);
1061 return;
1062 }
1063 // Append a piece of event that fits, without trailing comma.
1064 msg.AppendStringPart(event + pos, cut_pos - pos);
1065 // Start next piece with comma.
1066 pos = cut_pos;
1067 } else {
1068 msg.Append("%s", event + pos);
1069 pos += event_len;
1070 }
1071 msg.Append('\n');
1072 msg.WriteToLogFile();
1073 } while (pos < event_len);
1074#endif
1075}
1076
1077
Steve Block3ce2e202009-11-05 08:53:23 +00001078void Logger::HeapSampleJSProducerEvent(const char* constructor,
1079 Address* stack) {
1080#ifdef ENABLE_LOGGING_AND_PROFILING
1081 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1082 LogMessageBuilder msg;
1083 msg.Append("heap-js-prod-item,%s", constructor);
1084 while (*stack != NULL) {
1085 msg.Append(",0x%" V8PRIxPTR, *stack++);
1086 }
1087 msg.Append("\n");
1088 msg.WriteToLogFile();
1089#endif
1090}
1091
1092
Steve Blocka7e24c12009-10-30 11:49:00 +00001093void Logger::DebugTag(const char* call_site_tag) {
1094#ifdef ENABLE_LOGGING_AND_PROFILING
1095 if (!Log::IsEnabled() || !FLAG_log) return;
1096 LogMessageBuilder msg;
1097 msg.Append("debug-tag,%s\n", call_site_tag);
1098 msg.WriteToLogFile();
1099#endif
1100}
1101
1102
1103void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1104#ifdef ENABLE_LOGGING_AND_PROFILING
1105 if (!Log::IsEnabled() || !FLAG_log) return;
1106 StringBuilder s(parameter.length() + 1);
1107 for (int i = 0; i < parameter.length(); ++i) {
1108 s.AddCharacter(static_cast<char>(parameter[i]));
1109 }
1110 char* parameter_string = s.Finalize();
1111 LogMessageBuilder msg;
1112 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1113 event_type,
1114 OS::TimeCurrentMillis(),
1115 parameter_string);
1116 DeleteArray(parameter_string);
1117 msg.WriteToLogFile();
1118#endif
1119}
1120
1121
1122#ifdef ENABLE_LOGGING_AND_PROFILING
1123void Logger::TickEvent(TickSample* sample, bool overflow) {
1124 if (!Log::IsEnabled() || !FLAG_prof) return;
1125 static Address prev_sp = NULL;
Leon Clarked91b9f72010-01-27 17:25:45 +00001126 static Address prev_function = NULL;
Steve Blocka7e24c12009-10-30 11:49:00 +00001127 LogMessageBuilder msg;
1128 msg.Append("%s,", log_events_[TICK_EVENT]);
Leon Clarked91b9f72010-01-27 17:25:45 +00001129 Address prev_addr = sample->pc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001130 msg.AppendAddress(prev_addr);
1131 msg.Append(',');
Leon Clarked91b9f72010-01-27 17:25:45 +00001132 msg.AppendAddress(sample->sp, prev_sp);
1133 prev_sp = sample->sp;
1134 msg.Append(',');
1135 msg.AppendAddress(sample->function, prev_function);
1136 prev_function = sample->function;
Steve Blocka7e24c12009-10-30 11:49:00 +00001137 msg.Append(",%d", static_cast<int>(sample->state));
1138 if (overflow) {
1139 msg.Append(",overflow");
1140 }
1141 for (int i = 0; i < sample->frames_count; ++i) {
1142 msg.Append(',');
1143 msg.AppendAddress(sample->stack[i], prev_addr);
1144 prev_addr = sample->stack[i];
1145 }
1146 if (FLAG_compress_log) {
1147 ASSERT(compression_helper_ != NULL);
1148 if (!compression_helper_->HandleMessage(&msg)) return;
1149 }
1150 msg.Append('\n');
1151 msg.WriteToLogFile();
1152}
1153
1154
1155int Logger::GetActiveProfilerModules() {
1156 int result = PROFILER_MODULE_NONE;
1157 if (!profiler_->paused()) {
1158 result |= PROFILER_MODULE_CPU;
1159 }
1160 if (FLAG_log_gc) {
1161 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1162 }
1163 return result;
1164}
1165
1166
1167void Logger::PauseProfiler(int flags) {
1168 if (!Log::IsEnabled()) return;
1169 const int active_modules = GetActiveProfilerModules();
1170 const int modules_to_disable = active_modules & flags;
1171 if (modules_to_disable == PROFILER_MODULE_NONE) return;
1172
1173 if (modules_to_disable & PROFILER_MODULE_CPU) {
1174 profiler_->pause();
1175 if (FLAG_prof_lazy) {
1176 if (!FLAG_sliding_state_window) ticker_->Stop();
1177 FLAG_log_code = false;
1178 // Must be the same message as Log::kDynamicBufferSeal.
1179 LOG(UncheckedStringEvent("profiler", "pause"));
1180 }
1181 }
1182 if (modules_to_disable &
1183 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
1184 FLAG_log_gc = false;
1185 }
1186 // Turn off logging if no active modules remain.
1187 if ((active_modules & ~flags) == PROFILER_MODULE_NONE) {
1188 is_logging_ = false;
1189 }
1190}
1191
1192
1193void Logger::ResumeProfiler(int flags) {
1194 if (!Log::IsEnabled()) return;
1195 const int modules_to_enable = ~GetActiveProfilerModules() & flags;
1196 if (modules_to_enable != PROFILER_MODULE_NONE) {
1197 is_logging_ = true;
1198 }
1199 if (modules_to_enable & PROFILER_MODULE_CPU) {
1200 if (FLAG_prof_lazy) {
Steve Blockd0582a62009-12-15 09:54:21 +00001201 profiler_->Engage();
Steve Blocka7e24c12009-10-30 11:49:00 +00001202 LOG(UncheckedStringEvent("profiler", "resume"));
1203 FLAG_log_code = true;
1204 LogCompiledFunctions();
Leon Clarked91b9f72010-01-27 17:25:45 +00001205 LogFunctionObjects();
Steve Blockd0582a62009-12-15 09:54:21 +00001206 LogAccessorCallbacks();
Steve Blocka7e24c12009-10-30 11:49:00 +00001207 if (!FLAG_sliding_state_window) ticker_->Start();
1208 }
1209 profiler_->resume();
1210 }
1211 if (modules_to_enable &
1212 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
1213 FLAG_log_gc = true;
1214 }
1215}
1216
1217
1218// This function can be called when Log's mutex is acquired,
1219// either from main or Profiler's thread.
1220void Logger::StopLoggingAndProfiling() {
1221 Log::stop();
1222 PauseProfiler(PROFILER_MODULE_CPU);
1223}
1224
1225
1226bool Logger::IsProfilerSamplerActive() {
1227 return ticker_->IsActive();
1228}
1229
1230
1231int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1232 return Log::GetLogLines(from_pos, dest_buf, max_size);
1233}
1234
1235
Steve Block3ce2e202009-11-05 08:53:23 +00001236static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis) {
1237 AssertNoAllocation no_alloc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001238 int compiled_funcs_count = 0;
Steve Block3ce2e202009-11-05 08:53:23 +00001239 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001240 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Block3ce2e202009-11-05 08:53:23 +00001241 if (!obj->IsSharedFunctionInfo()) continue;
1242 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1243 if (sfi->is_compiled()
1244 && (!sfi->script()->IsScript()
1245 || Script::cast(sfi->script())->HasValidSource())) {
1246 if (sfis != NULL)
1247 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1248 ++compiled_funcs_count;
Steve Blocka7e24c12009-10-30 11:49:00 +00001249 }
1250 }
Steve Block3ce2e202009-11-05 08:53:23 +00001251 return compiled_funcs_count;
1252}
1253
1254
Steve Blockd0582a62009-12-15 09:54:21 +00001255void Logger::LogCodeObject(Object* object) {
1256 if (FLAG_log_code) {
1257 Code* code_object = Code::cast(object);
1258 LogEventsAndTags tag = Logger::STUB_TAG;
1259 const char* description = "Unknown code from the snapshot";
1260 switch (code_object->kind()) {
1261 case Code::FUNCTION:
1262 return; // We log this later using LogCompiledFunctions.
1263 case Code::STUB:
1264 description = CodeStub::MajorName(code_object->major_key());
1265 tag = Logger::STUB_TAG;
1266 break;
1267 case Code::BUILTIN:
1268 description = "A builtin from the snapshot";
1269 tag = Logger::BUILTIN_TAG;
1270 break;
1271 case Code::KEYED_LOAD_IC:
1272 description = "A keyed load IC from the snapshot";
1273 tag = Logger::KEYED_LOAD_IC_TAG;
1274 break;
1275 case Code::LOAD_IC:
1276 description = "A load IC from the snapshot";
1277 tag = Logger::LOAD_IC_TAG;
1278 break;
1279 case Code::STORE_IC:
1280 description = "A store IC from the snapshot";
1281 tag = Logger::STORE_IC_TAG;
1282 break;
1283 case Code::KEYED_STORE_IC:
1284 description = "A keyed store IC from the snapshot";
1285 tag = Logger::KEYED_STORE_IC_TAG;
1286 break;
1287 case Code::CALL_IC:
1288 description = "A call IC from the snapshot";
1289 tag = Logger::CALL_IC_TAG;
1290 break;
1291 }
1292 LOG(CodeCreateEvent(tag, code_object, description));
1293 }
1294}
1295
1296
Steve Block3ce2e202009-11-05 08:53:23 +00001297void Logger::LogCompiledFunctions() {
1298 HandleScope scope;
1299 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL);
1300 Handle<SharedFunctionInfo>* sfis =
1301 NewArray< Handle<SharedFunctionInfo> >(compiled_funcs_count);
1302 EnumerateCompiledFunctions(sfis);
Steve Blocka7e24c12009-10-30 11:49:00 +00001303
1304 // During iteration, there can be heap allocation due to
1305 // GetScriptLineNumber call.
1306 for (int i = 0; i < compiled_funcs_count; ++i) {
1307 Handle<SharedFunctionInfo> shared = sfis[i];
1308 Handle<String> name(String::cast(shared->name()));
1309 Handle<String> func_name(name->length() > 0 ?
1310 *name : shared->inferred_name());
1311 if (shared->script()->IsScript()) {
1312 Handle<Script> script(Script::cast(shared->script()));
1313 if (script->name()->IsString()) {
1314 Handle<String> script_name(String::cast(script->name()));
1315 int line_num = GetScriptLineNumber(script, shared->start_position());
1316 if (line_num > 0) {
1317 LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG,
1318 shared->code(), *func_name,
1319 *script_name, line_num + 1));
1320 } else {
1321 // Can't distinguish enum and script here, so always use Script.
1322 LOG(CodeCreateEvent(Logger::SCRIPT_TAG,
1323 shared->code(), *script_name));
1324 }
Steve Blockd0582a62009-12-15 09:54:21 +00001325 } else {
1326 LOG(CodeCreateEvent(
1327 Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001328 }
Steve Blockd0582a62009-12-15 09:54:21 +00001329 } else if (shared->function_data()->IsFunctionTemplateInfo()) {
1330 // API function.
1331 FunctionTemplateInfo* fun_data =
1332 FunctionTemplateInfo::cast(shared->function_data());
1333 Object* raw_call_data = fun_data->call_code();
1334 if (!raw_call_data->IsUndefined()) {
1335 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1336 Object* callback_obj = call_data->callback();
1337 Address entry_point = v8::ToCData<Address>(callback_obj);
1338 LOG(CallbackEvent(*func_name, entry_point));
1339 }
1340 } else {
1341 LOG(CodeCreateEvent(
1342 Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001343 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001344 }
1345
1346 DeleteArray(sfis);
1347}
1348
Steve Blockd0582a62009-12-15 09:54:21 +00001349
Leon Clarked91b9f72010-01-27 17:25:45 +00001350void Logger::LogFunctionObjects() {
1351 AssertNoAllocation no_alloc;
1352 HeapIterator iterator;
1353 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1354 if (!obj->IsJSFunction()) continue;
1355 JSFunction* jsf = JSFunction::cast(obj);
1356 if (!jsf->is_compiled()) continue;
1357 LOG(FunctionCreateEvent(jsf));
1358 }
1359}
1360
1361
Steve Blockd0582a62009-12-15 09:54:21 +00001362void Logger::LogAccessorCallbacks() {
1363 AssertNoAllocation no_alloc;
1364 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001365 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001366 if (!obj->IsAccessorInfo()) continue;
1367 AccessorInfo* ai = AccessorInfo::cast(obj);
1368 if (!ai->name()->IsString()) continue;
1369 String* name = String::cast(ai->name());
1370 Address getter_entry = v8::ToCData<Address>(ai->getter());
1371 if (getter_entry != 0) {
1372 LOG(GetterCallbackEvent(name, getter_entry));
1373 }
1374 Address setter_entry = v8::ToCData<Address>(ai->setter());
1375 if (setter_entry != 0) {
1376 LOG(SetterCallbackEvent(name, setter_entry));
1377 }
1378 }
1379}
1380
Steve Blocka7e24c12009-10-30 11:49:00 +00001381#endif
1382
1383
1384bool Logger::Setup() {
1385#ifdef ENABLE_LOGGING_AND_PROFILING
1386 // --log-all enables all the log flags.
1387 if (FLAG_log_all) {
1388 FLAG_log_runtime = true;
1389 FLAG_log_api = true;
1390 FLAG_log_code = true;
1391 FLAG_log_gc = true;
1392 FLAG_log_suspect = true;
1393 FLAG_log_handles = true;
1394 FLAG_log_regexp = true;
1395 }
1396
1397 // --prof implies --log-code.
1398 if (FLAG_prof) FLAG_log_code = true;
1399
1400 // --prof_lazy controls --log-code, implies --noprof_auto.
1401 if (FLAG_prof_lazy) {
1402 FLAG_log_code = false;
1403 FLAG_prof_auto = false;
1404 }
1405
1406 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1407 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1408 || FLAG_log_regexp || FLAG_log_state_changes;
1409
1410 bool open_log_file = start_logging || FLAG_prof_lazy;
1411
1412 // If we're logging anything, we need to open the log file.
1413 if (open_log_file) {
1414 if (strcmp(FLAG_logfile, "-") == 0) {
1415 Log::OpenStdout();
1416 } else if (strcmp(FLAG_logfile, "*") == 0) {
1417 Log::OpenMemoryBuffer();
1418 } else if (strchr(FLAG_logfile, '%') != NULL) {
1419 // If there's a '%' in the log file name we have to expand
1420 // placeholders.
1421 HeapStringAllocator allocator;
1422 StringStream stream(&allocator);
1423 for (const char* p = FLAG_logfile; *p; p++) {
1424 if (*p == '%') {
1425 p++;
1426 switch (*p) {
1427 case '\0':
1428 // If there's a % at the end of the string we back up
1429 // one character so we can escape the loop properly.
1430 p--;
1431 break;
1432 case 't': {
1433 // %t expands to the current time in milliseconds.
1434 double time = OS::TimeCurrentMillis();
1435 stream.Add("%.0f", FmtElm(time));
1436 break;
1437 }
1438 case '%':
1439 // %% expands (contracts really) to %.
1440 stream.Put('%');
1441 break;
1442 default:
1443 // All other %'s expand to themselves.
1444 stream.Put('%');
1445 stream.Put(*p);
1446 break;
1447 }
1448 } else {
1449 stream.Put(*p);
1450 }
1451 }
1452 SmartPointer<const char> expanded = stream.ToCString();
1453 Log::OpenFile(*expanded);
1454 } else {
1455 Log::OpenFile(FLAG_logfile);
1456 }
1457 }
1458
1459 current_state_ = &bottom_state_;
1460
1461 ticker_ = new Ticker(kSamplingIntervalMs);
1462
1463 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1464 sliding_state_window_ = new SlidingStateWindow();
1465 }
1466
1467 log_events_ = FLAG_compress_log ?
1468 kCompressedLogEventsNames : kLongLogEventsNames;
1469 if (FLAG_compress_log) {
1470 compression_helper_ = new CompressionHelper(kCompressionWindowSize);
1471 }
1472
1473 is_logging_ = start_logging;
1474
1475 if (FLAG_prof) {
1476 profiler_ = new Profiler();
1477 if (!FLAG_prof_auto) {
1478 profiler_->pause();
1479 } else {
1480 is_logging_ = true;
1481 }
Steve Blockd0582a62009-12-15 09:54:21 +00001482 if (!FLAG_prof_lazy) {
1483 profiler_->Engage();
1484 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001485 }
1486
1487 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
1488
1489 return true;
1490
1491#else
1492 return false;
1493#endif
1494}
1495
1496
1497void Logger::TearDown() {
1498#ifdef ENABLE_LOGGING_AND_PROFILING
1499 LogMessageBuilder::set_write_failure_handler(NULL);
1500
1501 // Stop the profiler before closing the file.
1502 if (profiler_ != NULL) {
1503 profiler_->Disengage();
1504 delete profiler_;
1505 profiler_ = NULL;
1506 }
1507
1508 delete compression_helper_;
1509 compression_helper_ = NULL;
1510
1511 delete sliding_state_window_;
1512 sliding_state_window_ = NULL;
1513
1514 delete ticker_;
1515 ticker_ = NULL;
1516
1517 Log::Close();
1518#endif
1519}
1520
1521
1522void Logger::EnableSlidingStateWindow() {
1523#ifdef ENABLE_LOGGING_AND_PROFILING
1524 // If the ticker is NULL, Logger::Setup has not been called yet. In
1525 // that case, we set the sliding_state_window flag so that the
1526 // sliding window computation will be started when Logger::Setup is
1527 // called.
1528 if (ticker_ == NULL) {
1529 FLAG_sliding_state_window = true;
1530 return;
1531 }
1532 // Otherwise, if the sliding state window computation has not been
1533 // started we do it now.
1534 if (sliding_state_window_ == NULL) {
1535 sliding_state_window_ = new SlidingStateWindow();
1536 }
1537#endif
1538}
1539
1540
1541} } // namespace v8::internal