blob: a3fef7310bfc027b2fbe6527e8028fc64f5e6229 [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;
Andrei Popescu402d9372010-02-26 13:31:12 +0000333int Logger::cpu_profiler_nesting_ = 0;
334int Logger::heap_profiler_nesting_ = 0;
Steve Blocka7e24c12009-10-30 11:49:00 +0000335
336#define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name,
337const 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,
343const char* kCompressedLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
344 LOG_EVENTS_AND_TAGS_LIST(DECLARE_SHORT_EVENT)
345};
346#undef DECLARE_SHORT_EVENT
347
348
349void 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
360void 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
Steve Blocka7e24c12009-10-30 11:49:00 +0000373void 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
381void 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
390void 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
400void 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.
414void 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
426void 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
442void 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
457void 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
473void 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
516void 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
528void 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
569void 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
577void 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
592void 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
604void 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
615void 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
623void 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
634void 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.
647class CompressionHelper {
648 public:
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.
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
Steve Blockd0582a62009-12-15 09:54:21 +0000680#ifdef ENABLE_LOGGING_AND_PROFILING
681void 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
699void 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
709void 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
719void 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
Steve Blocka7e24c12009-10-30 11:49:00 +0000729void 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
755void 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
774void 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
798void 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
815void 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
835void Logger::CodeMoveEvent(Address from, Address to) {
836#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000837 MoveEventInternal(CODE_MOVE_EVENT, from, to);
Steve Blocka7e24c12009-10-30 11:49:00 +0000838#endif
839}
840
841
842void Logger::CodeDeleteEvent(Address from) {
843#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000844 DeleteEventInternal(CODE_DELETE_EVENT, from);
Steve Blocka7e24c12009-10-30 11:49:00 +0000845#endif
846}
847
848
Leon Clarkee46be812010-01-19 14:06:41 +0000849void 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
Leon Clarked91b9f72010-01-27 17:25:45 +0000866void 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
886void Logger::FunctionMoveEvent(Address from, Address to) {
887#ifdef ENABLE_LOGGING_AND_PROFILING
888 MoveEventInternal(FUNCTION_MOVE_EVENT, from, to);
889#endif
890}
891
892
893void 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
901void 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
923void 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
Steve Blocka7e24c12009-10-30 11:49:00 +0000938void 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
956void 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
975void 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
988void 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
1000void 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
1010void 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
1020void 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
1031void 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.
Steve Blockd0582a62009-12-15 09:54:21 +00001038 static const int event_text_len = StrLength(event_text);
1039 const int cons_len = StrLength(constructor);
1040 const int event_len = StrLength(event);
Steve Blocka7e24c12009-10-30 11:49:00 +00001041 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
Steve Block3ce2e202009-11-05 08:53:23 +00001071void 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
Steve Blocka7e24c12009-10-30 11:49:00 +00001086void 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
1096void 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
1116void Logger::TickEvent(TickSample* sample, bool overflow) {
1117 if (!Log::IsEnabled() || !FLAG_prof) return;
1118 static Address prev_sp = NULL;
Leon Clarked91b9f72010-01-27 17:25:45 +00001119 static Address prev_function = NULL;
Steve Blocka7e24c12009-10-30 11:49:00 +00001120 LogMessageBuilder msg;
1121 msg.Append("%s,", log_events_[TICK_EVENT]);
Leon Clarked91b9f72010-01-27 17:25:45 +00001122 Address prev_addr = sample->pc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001123 msg.AppendAddress(prev_addr);
1124 msg.Append(',');
Leon Clarked91b9f72010-01-27 17:25:45 +00001125 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;
Steve Blocka7e24c12009-10-30 11:49:00 +00001130 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
1148int 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
Andrei Popescu402d9372010-02-26 13:31:12 +00001160void Logger::PauseProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001161 if (!Log::IsEnabled()) return;
Andrei Popescu402d9372010-02-26 13:31:12 +00001162 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 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001172 }
1173 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001174 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001175 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001176 if (--heap_profiler_nesting_ == 0) {
1177 FLAG_log_gc = false;
1178 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001179 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001180 if (tag != 0) {
1181 IntEvent("close-tag", tag);
1182 }
1183 if (GetActiveProfilerModules() == PROFILER_MODULE_NONE) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001184 is_logging_ = false;
1185 }
1186}
1187
1188
Andrei Popescu402d9372010-02-26 13:31:12 +00001189void Logger::ResumeProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001190 if (!Log::IsEnabled()) return;
Andrei Popescu402d9372010-02-26 13:31:12 +00001191 if (tag != 0) {
1192 IntEvent("open-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001193 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001194 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();
Steve Blocka7e24c12009-10-30 11:49:00 +00001207 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001208 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001209 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001210 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001211 if (heap_profiler_nesting_++ == 0) {
1212 is_logging_ = true;
1213 FLAG_log_gc = true;
1214 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001215 }
1216}
1217
1218
1219// This function can be called when Log's mutex is acquired,
1220// either from main or Profiler's thread.
1221void Logger::StopLoggingAndProfiling() {
1222 Log::stop();
Andrei Popescu402d9372010-02-26 13:31:12 +00001223 PauseProfiler(PROFILER_MODULE_CPU, 0);
Steve Blocka7e24c12009-10-30 11:49:00 +00001224}
1225
1226
1227bool Logger::IsProfilerSamplerActive() {
1228 return ticker_->IsActive();
1229}
1230
1231
1232int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1233 return Log::GetLogLines(from_pos, dest_buf, max_size);
1234}
1235
1236
Steve Block3ce2e202009-11-05 08:53:23 +00001237static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis) {
1238 AssertNoAllocation no_alloc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001239 int compiled_funcs_count = 0;
Steve Block3ce2e202009-11-05 08:53:23 +00001240 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001241 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Block3ce2e202009-11-05 08:53:23 +00001242 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;
Steve Blocka7e24c12009-10-30 11:49:00 +00001250 }
1251 }
Steve Block3ce2e202009-11-05 08:53:23 +00001252 return compiled_funcs_count;
1253}
1254
1255
Steve Blockd0582a62009-12-15 09:54:21 +00001256void 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:
Andrei Popescu31002712010-02-23 13:46:05 +00001265 description = CodeStub::MajorName(code_object->major_key(), true);
1266 if (description == NULL)
1267 description = "A stub from the snapshot";
Steve Blockd0582a62009-12-15 09:54:21 +00001268 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
Andrei Popescu31002712010-02-23 13:46:05 +00001300void 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
Steve Block3ce2e202009-11-05 08:53:23 +00001309void 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);
Steve Blocka7e24c12009-10-30 11:49:00 +00001315
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 }
Steve Blockd0582a62009-12-15 09:54:21 +00001337 } else {
1338 LOG(CodeCreateEvent(
1339 Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001340 }
Steve Blockd0582a62009-12-15 09:54:21 +00001341 } 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));
Steve Blocka7e24c12009-10-30 11:49:00 +00001355 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001356 }
1357
1358 DeleteArray(sfis);
1359}
1360
Steve Blockd0582a62009-12-15 09:54:21 +00001361
Leon Clarked91b9f72010-01-27 17:25:45 +00001362void 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
Steve Blockd0582a62009-12-15 09:54:21 +00001374void Logger::LogAccessorCallbacks() {
1375 AssertNoAllocation no_alloc;
1376 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001377 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001378 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
Steve Blocka7e24c12009-10-30 11:49:00 +00001393#endif
1394
1395
1396bool 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 }
Steve Blockd0582a62009-12-15 09:54:21 +00001494 if (!FLAG_prof_lazy) {
1495 profiler_->Engage();
1496 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001497 }
1498
1499 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
1500
1501 return true;
1502
1503#else
1504 return false;
1505#endif
1506}
1507
1508
1509void 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
1534void 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