blob: 2cc2b8ffa85fd9892a9ab0c4c7f5522bd251a911 [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"
Kristian Monsen80d68ea2010-09-08 11:05:35 +010033#include "code-stubs.h"
Steve Blockd0582a62009-12-15 09:54:21 +000034#include "global-handles.h"
Steve Blocka7e24c12009-10-30 11:49:00 +000035#include "log.h"
36#include "macro-assembler.h"
37#include "serialize.h"
38#include "string-stream.h"
39
40namespace v8 {
41namespace internal {
42
43#ifdef ENABLE_LOGGING_AND_PROFILING
44
45//
46// Sliding state window. Updates counters to keep track of the last
47// window of kBufferSize states. This is useful to track where we
48// spent our time.
49//
50class SlidingStateWindow {
51 public:
52 SlidingStateWindow();
53 ~SlidingStateWindow();
54 void AddState(StateTag state);
55
56 private:
57 static const int kBufferSize = 256;
58 int current_index_;
59 bool is_full_;
60 byte buffer_[kBufferSize];
61
62
63 void IncrementStateCounter(StateTag state) {
64 Counters::state_counters[state].Increment();
65 }
66
67
68 void DecrementStateCounter(StateTag state) {
69 Counters::state_counters[state].Decrement();
70 }
71};
72
73
74//
75// The Profiler samples pc and sp values for the main thread.
76// Each sample is appended to a circular buffer.
77// An independent thread removes data and writes it to the log.
78// This design minimizes the time spent in the sampler.
79//
80class Profiler: public Thread {
81 public:
82 Profiler();
83 void Engage();
84 void Disengage();
85
86 // Inserts collected profiling data into buffer.
87 void Insert(TickSample* sample) {
88 if (paused_)
89 return;
90
91 if (Succ(head_) == tail_) {
92 overflow_ = true;
93 } else {
94 buffer_[head_] = *sample;
95 head_ = Succ(head_);
96 buffer_semaphore_->Signal(); // Tell we have an element.
97 }
98 }
99
100 // Waits for a signal and removes profiling data.
101 bool Remove(TickSample* sample) {
102 buffer_semaphore_->Wait(); // Wait for an element.
103 *sample = buffer_[tail_];
104 bool result = overflow_;
105 tail_ = Succ(tail_);
106 overflow_ = false;
107 return result;
108 }
109
110 void Run();
111
112 // Pause and Resume TickSample data collection.
113 static bool paused() { return paused_; }
114 static void pause() { paused_ = true; }
115 static void resume() { paused_ = false; }
116
117 private:
118 // Returns the next index in the cyclic buffer.
119 int Succ(int index) { return (index + 1) % kBufferSize; }
120
121 // Cyclic buffer for communicating profiling samples
122 // between the signal handler and the worker thread.
123 static const int kBufferSize = 128;
124 TickSample buffer_[kBufferSize]; // Buffer storage.
125 int head_; // Index to the buffer head.
126 int tail_; // Index to the buffer tail.
127 bool overflow_; // Tell whether a buffer overflow has occurred.
128 Semaphore* buffer_semaphore_; // Sempahore used for buffer synchronization.
129
Steve Blockd0582a62009-12-15 09:54:21 +0000130 // Tells whether profiler is engaged, that is, processing thread is stated.
131 bool engaged_;
132
Steve Blocka7e24c12009-10-30 11:49:00 +0000133 // Tells whether worker thread should continue running.
134 bool running_;
135
136 // Tells whether we are currently recording tick samples.
137 static bool paused_;
138};
139
140bool Profiler::paused_ = false;
141
142
143//
144// StackTracer implementation
145//
146void StackTracer::Trace(TickSample* sample) {
Steve Block6ded16b2010-05-10 14:33:55 +0100147 sample->function = NULL;
148 sample->frames_count = 0;
149
150 if (sample->state == GC) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000151
152 const Address js_entry_sp = Top::js_entry_sp(Top::GetCurrentThread());
153 if (js_entry_sp == 0) {
154 // Not executing JS now.
Steve Blocka7e24c12009-10-30 11:49:00 +0000155 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;
Steve Block6ded16b2010-05-10 14:33:55 +0100166 const Address callback = VMState::external_callback();
Steve Blockd0582a62009-12-15 09:54:21 +0000167 if (callback != NULL) {
168 sample->stack[i++] = callback;
169 }
170
Leon Clarked91b9f72010-01-27 17:25:45 +0000171 SafeStackTraceFrameIterator it(sample->fp, sample->sp,
172 sample->sp, js_entry_sp);
Steve Blocka7e24c12009-10-30 11:49:00 +0000173 while (!it.done() && i < TickSample::kMaxFramesCount) {
Kristian Monsen0d5e1162010-09-30 15:31:59 +0100174 sample->stack[i++] =
175 reinterpret_cast<Address>(it.frame()->function_slot_object()) -
176 kHeapObjectTag;
Steve Blocka7e24c12009-10-30 11:49:00 +0000177 it.Advance();
178 }
179 sample->frames_count = i;
180}
181
182
183//
184// Ticker used to provide ticks to the profiler and the sliding state
185// window.
186//
187class Ticker: public Sampler {
188 public:
189 explicit Ticker(int interval):
190 Sampler(interval, FLAG_prof), window_(NULL), profiler_(NULL) {}
191
192 ~Ticker() { if (IsActive()) Stop(); }
193
Ben Murdochf87a2032010-10-22 12:50:53 +0100194 virtual void SampleStack(TickSample* sample) {
195 ASSERT(IsSynchronous());
Steve Blocka7e24c12009-10-30 11:49:00 +0000196 StackTracer::Trace(sample);
197 }
198
Ben Murdochf87a2032010-10-22 12:50:53 +0100199 virtual void Tick(TickSample* sample) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000200 if (profiler_) profiler_->Insert(sample);
201 if (window_) window_->AddState(sample->state);
202 }
203
204 void SetWindow(SlidingStateWindow* window) {
205 window_ = window;
206 if (!IsActive()) Start();
207 }
208
209 void ClearWindow() {
210 window_ = NULL;
211 if (!profiler_ && IsActive()) Stop();
212 }
213
214 void SetProfiler(Profiler* profiler) {
215 profiler_ = profiler;
216 if (!FLAG_prof_lazy && !IsActive()) Start();
217 }
218
219 void ClearProfiler() {
220 profiler_ = NULL;
221 if (!window_ && IsActive()) Stop();
222 }
223
224 private:
225 SlidingStateWindow* window_;
226 Profiler* profiler_;
227};
228
229
230//
231// SlidingStateWindow implementation.
232//
233SlidingStateWindow::SlidingStateWindow(): current_index_(0), is_full_(false) {
234 for (int i = 0; i < kBufferSize; i++) {
235 buffer_[i] = static_cast<byte>(OTHER);
236 }
237 Logger::ticker_->SetWindow(this);
238}
239
240
241SlidingStateWindow::~SlidingStateWindow() {
242 Logger::ticker_->ClearWindow();
243}
244
245
246void SlidingStateWindow::AddState(StateTag state) {
247 if (is_full_) {
248 DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
249 } else if (current_index_ == kBufferSize - 1) {
250 is_full_ = true;
251 }
252 buffer_[current_index_] = static_cast<byte>(state);
253 IncrementStateCounter(state);
254 ASSERT(IsPowerOf2(kBufferSize));
255 current_index_ = (current_index_ + 1) & (kBufferSize - 1);
256}
257
258
259//
260// Profiler implementation.
261//
Steve Blockd0582a62009-12-15 09:54:21 +0000262Profiler::Profiler()
263 : head_(0),
264 tail_(0),
265 overflow_(false),
266 buffer_semaphore_(OS::CreateSemaphore(0)),
267 engaged_(false),
268 running_(false) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000269}
270
271
272void Profiler::Engage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000273 if (engaged_) return;
274 engaged_ = true;
275
276 // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
277 // http://code.google.com/p/v8/issues/detail?id=487
278 if (!FLAG_prof_lazy) {
279 OS::LogSharedLibraryAddresses();
280 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000281
282 // Start thread processing the profiler buffer.
283 running_ = true;
284 Start();
285
286 // Register to get ticks.
287 Logger::ticker_->SetProfiler(this);
288
289 Logger::ProfilerBeginEvent();
290 Logger::LogAliases();
291}
292
293
294void Profiler::Disengage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000295 if (!engaged_) return;
296
Steve Blocka7e24c12009-10-30 11:49:00 +0000297 // Stop receiving ticks.
298 Logger::ticker_->ClearProfiler();
299
300 // Terminate the worker thread by setting running_ to false,
301 // inserting a fake element in the queue and then wait for
302 // the thread to terminate.
303 running_ = false;
304 TickSample sample;
305 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
306 resume();
307 Insert(&sample);
308 Join();
309
310 LOG(UncheckedStringEvent("profiler", "end"));
311}
312
313
314void Profiler::Run() {
315 TickSample sample;
Steve Block8defd9f2010-07-08 12:39:36 +0100316 bool overflow = Remove(&sample);
Steve Blocka7e24c12009-10-30 11:49:00 +0000317 while (running_) {
318 LOG(TickEvent(&sample, overflow));
Steve Block8defd9f2010-07-08 12:39:36 +0100319 overflow = Remove(&sample);
Steve Blocka7e24c12009-10-30 11:49:00 +0000320 }
321}
322
323
324//
325// Logger class implementation.
326//
327Ticker* Logger::ticker_ = NULL;
328Profiler* Logger::profiler_ = NULL;
Steve Blocka7e24c12009-10-30 11:49:00 +0000329SlidingStateWindow* Logger::sliding_state_window_ = NULL;
330const char** Logger::log_events_ = NULL;
331CompressionHelper* Logger::compression_helper_ = NULL;
Steve Block6ded16b2010-05-10 14:33:55 +0100332int Logger::logging_nesting_ = 0;
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
Steve Block6ded16b2010-05-10 14:33:55 +0100392 if (FLAG_log) UncheckedIntEvent(name, value);
393#endif
394}
395
396
Ben Murdochf87a2032010-10-22 12:50:53 +0100397void Logger::IntPtrTEvent(const char* name, intptr_t value) {
398#ifdef ENABLE_LOGGING_AND_PROFILING
399 if (FLAG_log) UncheckedIntPtrTEvent(name, value);
400#endif
401}
402
403
Steve Block6ded16b2010-05-10 14:33:55 +0100404#ifdef ENABLE_LOGGING_AND_PROFILING
405void Logger::UncheckedIntEvent(const char* name, int value) {
406 if (!Log::IsEnabled()) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000407 LogMessageBuilder msg;
408 msg.Append("%s,%d\n", name, value);
409 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000410}
Steve Block6ded16b2010-05-10 14:33:55 +0100411#endif
Steve Blocka7e24c12009-10-30 11:49:00 +0000412
413
Ben Murdochf87a2032010-10-22 12:50:53 +0100414#ifdef ENABLE_LOGGING_AND_PROFILING
415void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
416 if (!Log::IsEnabled()) return;
417 LogMessageBuilder msg;
418 msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
419 msg.WriteToLogFile();
420}
421#endif
422
423
Steve Blocka7e24c12009-10-30 11:49:00 +0000424void Logger::HandleEvent(const char* name, Object** location) {
425#ifdef ENABLE_LOGGING_AND_PROFILING
426 if (!Log::IsEnabled() || !FLAG_log_handles) return;
427 LogMessageBuilder msg;
428 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
429 msg.WriteToLogFile();
430#endif
431}
432
433
434#ifdef ENABLE_LOGGING_AND_PROFILING
435// ApiEvent is private so all the calls come from the Logger class. It is the
436// caller's responsibility to ensure that log is enabled and that
437// FLAG_log_api is true.
438void Logger::ApiEvent(const char* format, ...) {
439 ASSERT(Log::IsEnabled() && FLAG_log_api);
440 LogMessageBuilder msg;
441 va_list ap;
442 va_start(ap, format);
443 msg.AppendVA(format, ap);
444 va_end(ap);
445 msg.WriteToLogFile();
446}
447#endif
448
449
450void Logger::ApiNamedSecurityCheck(Object* key) {
451#ifdef ENABLE_LOGGING_AND_PROFILING
452 if (!Log::IsEnabled() || !FLAG_log_api) return;
453 if (key->IsString()) {
454 SmartPointer<char> str =
455 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
456 ApiEvent("api,check-security,\"%s\"\n", *str);
457 } else if (key->IsUndefined()) {
458 ApiEvent("api,check-security,undefined\n");
459 } else {
460 ApiEvent("api,check-security,['no-name']\n");
461 }
462#endif
463}
464
465
466void Logger::SharedLibraryEvent(const char* library_path,
467 uintptr_t start,
468 uintptr_t end) {
469#ifdef ENABLE_LOGGING_AND_PROFILING
470 if (!Log::IsEnabled() || !FLAG_prof) return;
471 LogMessageBuilder msg;
472 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
473 library_path,
474 start,
475 end);
476 msg.WriteToLogFile();
477#endif
478}
479
480
481void Logger::SharedLibraryEvent(const wchar_t* library_path,
482 uintptr_t start,
483 uintptr_t end) {
484#ifdef ENABLE_LOGGING_AND_PROFILING
485 if (!Log::IsEnabled() || !FLAG_prof) return;
486 LogMessageBuilder msg;
487 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
488 library_path,
489 start,
490 end);
491 msg.WriteToLogFile();
492#endif
493}
494
495
496#ifdef ENABLE_LOGGING_AND_PROFILING
497void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
498 // Prints "/" + re.source + "/" +
499 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
500 LogMessageBuilder msg;
501
502 Handle<Object> source = GetProperty(regexp, "source");
503 if (!source->IsString()) {
504 msg.Append("no source");
505 return;
506 }
507
508 switch (regexp->TypeTag()) {
509 case JSRegExp::ATOM:
510 msg.Append('a');
511 break;
512 default:
513 break;
514 }
515 msg.Append('/');
516 msg.AppendDetailed(*Handle<String>::cast(source), false);
517 msg.Append('/');
518
519 // global flag
520 Handle<Object> global = GetProperty(regexp, "global");
521 if (global->IsTrue()) {
522 msg.Append('g');
523 }
524 // ignorecase flag
525 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
526 if (ignorecase->IsTrue()) {
527 msg.Append('i');
528 }
529 // multiline flag
530 Handle<Object> multiline = GetProperty(regexp, "multiline");
531 if (multiline->IsTrue()) {
532 msg.Append('m');
533 }
534
535 msg.WriteToLogFile();
536}
537#endif // ENABLE_LOGGING_AND_PROFILING
538
539
540void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
541#ifdef ENABLE_LOGGING_AND_PROFILING
542 if (!Log::IsEnabled() || !FLAG_log_regexp) return;
543 LogMessageBuilder msg;
544 msg.Append("regexp-compile,");
545 LogRegExpSource(regexp);
546 msg.Append(in_cache ? ",hit\n" : ",miss\n");
547 msg.WriteToLogFile();
548#endif
549}
550
551
552void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
553#ifdef ENABLE_LOGGING_AND_PROFILING
554 if (!Log::IsEnabled() || !FLAG_log_runtime) return;
555 HandleScope scope;
556 LogMessageBuilder msg;
557 for (int i = 0; i < format.length(); i++) {
558 char c = format[i];
559 if (c == '%' && i <= format.length() - 2) {
560 i++;
561 ASSERT('0' <= format[i] && format[i] <= '9');
John Reck59135872010-11-02 12:39:01 -0700562 MaybeObject* maybe = args->GetElement(format[i] - '0');
563 Object* obj;
564 if (!maybe->ToObject(&obj)) {
565 msg.Append("<exception>");
566 continue;
567 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000568 i++;
569 switch (format[i]) {
570 case 's':
571 msg.AppendDetailed(String::cast(obj), false);
572 break;
573 case 'S':
574 msg.AppendDetailed(String::cast(obj), true);
575 break;
576 case 'r':
577 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
578 break;
579 case 'x':
580 msg.Append("0x%x", Smi::cast(obj)->value());
581 break;
582 case 'i':
583 msg.Append("%i", Smi::cast(obj)->value());
584 break;
585 default:
586 UNREACHABLE();
587 }
588 } else {
589 msg.Append(c);
590 }
591 }
592 msg.Append('\n');
593 msg.WriteToLogFile();
594#endif
595}
596
597
598void Logger::ApiIndexedSecurityCheck(uint32_t index) {
599#ifdef ENABLE_LOGGING_AND_PROFILING
600 if (!Log::IsEnabled() || !FLAG_log_api) return;
601 ApiEvent("api,check-security,%u\n", index);
602#endif
603}
604
605
606void Logger::ApiNamedPropertyAccess(const char* tag,
607 JSObject* holder,
608 Object* name) {
609#ifdef ENABLE_LOGGING_AND_PROFILING
610 ASSERT(name->IsString());
611 if (!Log::IsEnabled() || !FLAG_log_api) return;
612 String* class_name_obj = holder->class_name();
613 SmartPointer<char> class_name =
614 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
615 SmartPointer<char> property_name =
616 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
617 Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
618#endif
619}
620
621void Logger::ApiIndexedPropertyAccess(const char* tag,
622 JSObject* holder,
623 uint32_t index) {
624#ifdef ENABLE_LOGGING_AND_PROFILING
625 if (!Log::IsEnabled() || !FLAG_log_api) return;
626 String* class_name_obj = holder->class_name();
627 SmartPointer<char> class_name =
628 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
629 Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
630#endif
631}
632
633void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
634#ifdef ENABLE_LOGGING_AND_PROFILING
635 if (!Log::IsEnabled() || !FLAG_log_api) return;
636 String* class_name_obj = object->class_name();
637 SmartPointer<char> class_name =
638 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
639 Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
640#endif
641}
642
643
644void Logger::ApiEntryCall(const char* name) {
645#ifdef ENABLE_LOGGING_AND_PROFILING
646 if (!Log::IsEnabled() || !FLAG_log_api) return;
647 Logger::ApiEvent("api,%s\n", name);
648#endif
649}
650
651
652void Logger::NewEvent(const char* name, void* object, size_t size) {
653#ifdef ENABLE_LOGGING_AND_PROFILING
654 if (!Log::IsEnabled() || !FLAG_log) return;
655 LogMessageBuilder msg;
656 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
657 static_cast<unsigned int>(size));
658 msg.WriteToLogFile();
659#endif
660}
661
662
663void Logger::DeleteEvent(const char* name, void* object) {
664#ifdef ENABLE_LOGGING_AND_PROFILING
665 if (!Log::IsEnabled() || !FLAG_log) return;
666 LogMessageBuilder msg;
667 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
668 msg.WriteToLogFile();
669#endif
670}
671
672
673#ifdef ENABLE_LOGGING_AND_PROFILING
674
675// A class that contains all common code dealing with record compression.
676class CompressionHelper {
677 public:
678 explicit CompressionHelper(int window_size)
679 : compressor_(window_size), repeat_count_(0) { }
680
681 // Handles storing message in compressor, retrieving the previous one and
682 // prefixing it with repeat count, if needed.
683 // Returns true if message needs to be written to log.
684 bool HandleMessage(LogMessageBuilder* msg) {
685 if (!msg->StoreInCompressor(&compressor_)) {
686 // Current message repeats the previous one, don't write it.
687 ++repeat_count_;
688 return false;
689 }
690 if (repeat_count_ == 0) {
691 return msg->RetrieveCompressedPrevious(&compressor_);
692 }
693 OS::SNPrintF(prefix_, "%s,%d,",
694 Logger::log_events_[Logger::REPEAT_META_EVENT],
695 repeat_count_ + 1);
696 repeat_count_ = 0;
697 return msg->RetrieveCompressedPrevious(&compressor_, prefix_.start());
698 }
699
700 private:
701 LogRecordCompressor compressor_;
702 int repeat_count_;
703 EmbeddedVector<char, 20> prefix_;
704};
705
706#endif // ENABLE_LOGGING_AND_PROFILING
707
708
Steve Blockd0582a62009-12-15 09:54:21 +0000709#ifdef ENABLE_LOGGING_AND_PROFILING
710void Logger::CallbackEventInternal(const char* prefix, const char* name,
711 Address entry_point) {
712 if (!Log::IsEnabled() || !FLAG_log_code) return;
713 LogMessageBuilder msg;
714 msg.Append("%s,%s,",
715 log_events_[CODE_CREATION_EVENT], log_events_[CALLBACK_TAG]);
716 msg.AppendAddress(entry_point);
717 msg.Append(",1,\"%s%s\"", prefix, name);
718 if (FLAG_compress_log) {
719 ASSERT(compression_helper_ != NULL);
720 if (!compression_helper_->HandleMessage(&msg)) return;
721 }
722 msg.Append('\n');
723 msg.WriteToLogFile();
724}
725#endif
726
727
728void Logger::CallbackEvent(String* name, Address entry_point) {
729#ifdef ENABLE_LOGGING_AND_PROFILING
730 if (!Log::IsEnabled() || !FLAG_log_code) return;
731 SmartPointer<char> str =
732 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
733 CallbackEventInternal("", *str, entry_point);
734#endif
735}
736
737
738void Logger::GetterCallbackEvent(String* name, Address entry_point) {
739#ifdef ENABLE_LOGGING_AND_PROFILING
740 if (!Log::IsEnabled() || !FLAG_log_code) return;
741 SmartPointer<char> str =
742 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
743 CallbackEventInternal("get ", *str, entry_point);
744#endif
745}
746
747
748void Logger::SetterCallbackEvent(String* name, Address entry_point) {
749#ifdef ENABLE_LOGGING_AND_PROFILING
750 if (!Log::IsEnabled() || !FLAG_log_code) return;
751 SmartPointer<char> str =
752 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
753 CallbackEventInternal("set ", *str, entry_point);
754#endif
755}
756
757
Steve Blocka7e24c12009-10-30 11:49:00 +0000758void Logger::CodeCreateEvent(LogEventsAndTags tag,
759 Code* code,
760 const char* comment) {
761#ifdef ENABLE_LOGGING_AND_PROFILING
762 if (!Log::IsEnabled() || !FLAG_log_code) return;
763 LogMessageBuilder msg;
764 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
765 msg.AppendAddress(code->address());
766 msg.Append(",%d,\"", code->ExecutableSize());
767 for (const char* p = comment; *p != '\0'; p++) {
768 if (*p == '"') {
769 msg.Append('\\');
770 }
771 msg.Append(*p);
772 }
773 msg.Append('"');
Ben Murdochf87a2032010-10-22 12:50:53 +0100774 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000775 if (FLAG_compress_log) {
776 ASSERT(compression_helper_ != NULL);
777 if (!compression_helper_->HandleMessage(&msg)) return;
778 }
779 msg.Append('\n');
780 msg.WriteToLogFile();
781#endif
782}
783
784
785void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
786#ifdef ENABLE_LOGGING_AND_PROFILING
787 if (!Log::IsEnabled() || !FLAG_log_code) return;
788 LogMessageBuilder msg;
789 SmartPointer<char> str =
790 name->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\"", code->ExecutableSize(), *str);
Ben Murdochf87a2032010-10-22 12:50:53 +0100794 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000795 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,
806 Code* code, String* name,
807 String* source, int line) {
808#ifdef ENABLE_LOGGING_AND_PROFILING
809 if (!Log::IsEnabled() || !FLAG_log_code) return;
810 LogMessageBuilder msg;
811 SmartPointer<char> str =
812 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
813 SmartPointer<char> sourcestr =
814 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
815 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
816 msg.AppendAddress(code->address());
817 msg.Append(",%d,\"%s %s:%d\"",
818 code->ExecutableSize(), *str, *sourcestr, line);
Ben Murdochf87a2032010-10-22 12:50:53 +0100819 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000820 if (FLAG_compress_log) {
821 ASSERT(compression_helper_ != NULL);
822 if (!compression_helper_->HandleMessage(&msg)) return;
823 }
824 msg.Append('\n');
825 msg.WriteToLogFile();
826#endif
827}
828
829
830void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
831#ifdef ENABLE_LOGGING_AND_PROFILING
832 if (!Log::IsEnabled() || !FLAG_log_code) return;
833 LogMessageBuilder msg;
834 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
835 msg.AppendAddress(code->address());
836 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
Ben Murdochf87a2032010-10-22 12:50:53 +0100837 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000838 if (FLAG_compress_log) {
839 ASSERT(compression_helper_ != NULL);
840 if (!compression_helper_->HandleMessage(&msg)) return;
841 }
842 msg.Append('\n');
843 msg.WriteToLogFile();
844#endif
845}
846
847
Ben Murdochf87a2032010-10-22 12:50:53 +0100848void Logger::CodeMovingGCEvent() {
849#ifdef ENABLE_LOGGING_AND_PROFILING
850 if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
851 LogMessageBuilder msg;
852 msg.Append("%s\n", log_events_[CODE_MOVING_GC]);
853 msg.WriteToLogFile();
854 OS::SignalCodeMovingGC();
855#endif
856}
857
858
Steve Blocka7e24c12009-10-30 11:49:00 +0000859void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
860#ifdef ENABLE_LOGGING_AND_PROFILING
861 if (!Log::IsEnabled() || !FLAG_log_code) return;
862 LogMessageBuilder msg;
863 msg.Append("%s,%s,",
864 log_events_[CODE_CREATION_EVENT], log_events_[REG_EXP_TAG]);
865 msg.AppendAddress(code->address());
866 msg.Append(",%d,\"", code->ExecutableSize());
867 msg.AppendDetailed(source, false);
868 msg.Append('\"');
Ben Murdochf87a2032010-10-22 12:50:53 +0100869 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000870 if (FLAG_compress_log) {
871 ASSERT(compression_helper_ != NULL);
872 if (!compression_helper_->HandleMessage(&msg)) return;
873 }
874 msg.Append('\n');
875 msg.WriteToLogFile();
876#endif
877}
878
879
880void Logger::CodeMoveEvent(Address from, Address to) {
881#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000882 MoveEventInternal(CODE_MOVE_EVENT, from, to);
Steve Blocka7e24c12009-10-30 11:49:00 +0000883#endif
884}
885
886
887void Logger::CodeDeleteEvent(Address from) {
888#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000889 DeleteEventInternal(CODE_DELETE_EVENT, from);
Steve Blocka7e24c12009-10-30 11:49:00 +0000890#endif
891}
892
893
Leon Clarkee46be812010-01-19 14:06:41 +0000894void Logger::SnapshotPositionEvent(Address addr, int pos) {
895#ifdef ENABLE_LOGGING_AND_PROFILING
896 if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return;
897 LogMessageBuilder msg;
898 msg.Append("%s,", log_events_[SNAPSHOT_POSITION_EVENT]);
899 msg.AppendAddress(addr);
900 msg.Append(",%d", pos);
901 if (FLAG_compress_log) {
902 ASSERT(compression_helper_ != NULL);
903 if (!compression_helper_->HandleMessage(&msg)) return;
904 }
905 msg.Append('\n');
906 msg.WriteToLogFile();
907#endif
908}
909
910
Leon Clarked91b9f72010-01-27 17:25:45 +0000911void Logger::FunctionCreateEvent(JSFunction* function) {
912#ifdef ENABLE_LOGGING_AND_PROFILING
Kristian Monsen0d5e1162010-09-30 15:31:59 +0100913 // This function can be called from GC iterators (during Scavenge,
914 // MC, and MS), so marking bits can be set on objects. That's
915 // why unchecked accessors are used here.
Leon Clarked91b9f72010-01-27 17:25:45 +0000916 static Address prev_code = NULL;
917 if (!Log::IsEnabled() || !FLAG_log_code) return;
918 LogMessageBuilder msg;
919 msg.Append("%s,", log_events_[FUNCTION_CREATION_EVENT]);
920 msg.AppendAddress(function->address());
921 msg.Append(',');
Kristian Monsen0d5e1162010-09-30 15:31:59 +0100922 msg.AppendAddress(function->unchecked_code()->address(), prev_code);
923 prev_code = function->unchecked_code()->address();
Leon Clarked91b9f72010-01-27 17:25:45 +0000924 if (FLAG_compress_log) {
925 ASSERT(compression_helper_ != NULL);
926 if (!compression_helper_->HandleMessage(&msg)) return;
927 }
928 msg.Append('\n');
929 msg.WriteToLogFile();
930#endif
931}
932
933
Ben Murdochf87a2032010-10-22 12:50:53 +0100934void Logger::FunctionCreateEventFromMove(JSFunction* function) {
Kristian Monsen0d5e1162010-09-30 15:31:59 +0100935#ifdef ENABLE_LOGGING_AND_PROFILING
936 if (function->unchecked_code() != Builtins::builtin(Builtins::LazyCompile)) {
937 FunctionCreateEvent(function);
938 }
939#endif
940}
941
942
Leon Clarked91b9f72010-01-27 17:25:45 +0000943void Logger::FunctionMoveEvent(Address from, Address to) {
944#ifdef ENABLE_LOGGING_AND_PROFILING
945 MoveEventInternal(FUNCTION_MOVE_EVENT, from, to);
946#endif
947}
948
949
950void Logger::FunctionDeleteEvent(Address from) {
951#ifdef ENABLE_LOGGING_AND_PROFILING
952 DeleteEventInternal(FUNCTION_DELETE_EVENT, from);
953#endif
954}
955
956
957#ifdef ENABLE_LOGGING_AND_PROFILING
958void Logger::MoveEventInternal(LogEventsAndTags event,
959 Address from,
960 Address to) {
961 static Address prev_to_ = NULL;
962 if (!Log::IsEnabled() || !FLAG_log_code) return;
963 LogMessageBuilder msg;
964 msg.Append("%s,", log_events_[event]);
965 msg.AppendAddress(from);
966 msg.Append(',');
967 msg.AppendAddress(to, prev_to_);
968 prev_to_ = to;
969 if (FLAG_compress_log) {
970 ASSERT(compression_helper_ != NULL);
971 if (!compression_helper_->HandleMessage(&msg)) return;
972 }
973 msg.Append('\n');
974 msg.WriteToLogFile();
975}
976#endif
977
978
979#ifdef ENABLE_LOGGING_AND_PROFILING
980void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
981 if (!Log::IsEnabled() || !FLAG_log_code) return;
982 LogMessageBuilder msg;
983 msg.Append("%s,", log_events_[event]);
984 msg.AppendAddress(from);
985 if (FLAG_compress_log) {
986 ASSERT(compression_helper_ != NULL);
987 if (!compression_helper_->HandleMessage(&msg)) return;
988 }
989 msg.Append('\n');
990 msg.WriteToLogFile();
991}
992#endif
993
994
Steve Blocka7e24c12009-10-30 11:49:00 +0000995void Logger::ResourceEvent(const char* name, const char* tag) {
996#ifdef ENABLE_LOGGING_AND_PROFILING
997 if (!Log::IsEnabled() || !FLAG_log) return;
998 LogMessageBuilder msg;
999 msg.Append("%s,%s,", name, tag);
1000
1001 uint32_t sec, usec;
1002 if (OS::GetUserTime(&sec, &usec) != -1) {
1003 msg.Append("%d,%d,", sec, usec);
1004 }
1005 msg.Append("%.0f", OS::TimeCurrentMillis());
1006
1007 msg.Append('\n');
1008 msg.WriteToLogFile();
1009#endif
1010}
1011
1012
1013void Logger::SuspectReadEvent(String* name, Object* obj) {
1014#ifdef ENABLE_LOGGING_AND_PROFILING
1015 if (!Log::IsEnabled() || !FLAG_log_suspect) return;
1016 LogMessageBuilder msg;
1017 String* class_name = obj->IsJSObject()
1018 ? JSObject::cast(obj)->class_name()
1019 : Heap::empty_string();
1020 msg.Append("suspect-read,");
1021 msg.Append(class_name);
1022 msg.Append(',');
1023 msg.Append('"');
1024 msg.Append(name);
1025 msg.Append('"');
1026 msg.Append('\n');
1027 msg.WriteToLogFile();
1028#endif
1029}
1030
1031
1032void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
1033#ifdef ENABLE_LOGGING_AND_PROFILING
1034 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1035 LogMessageBuilder msg;
1036 // Using non-relative system time in order to be able to synchronize with
1037 // external memory profiling events (e.g. DOM memory size).
1038 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
1039 space, kind, OS::TimeCurrentMillis());
1040 msg.WriteToLogFile();
1041#endif
1042}
1043
1044
1045void Logger::HeapSampleStats(const char* space, const char* kind,
Ben Murdochf87a2032010-10-22 12:50:53 +01001046 intptr_t capacity, intptr_t used) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001047#ifdef ENABLE_LOGGING_AND_PROFILING
1048 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1049 LogMessageBuilder msg;
Ben Murdochf87a2032010-10-22 12:50:53 +01001050 msg.Append("heap-sample-stats,\"%s\",\"%s\","
1051 "%" V8_PTR_PREFIX "d,%" V8_PTR_PREFIX "d\n",
Steve Blocka7e24c12009-10-30 11:49:00 +00001052 space, kind, capacity, used);
1053 msg.WriteToLogFile();
1054#endif
1055}
1056
1057
1058void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1059#ifdef ENABLE_LOGGING_AND_PROFILING
1060 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1061 LogMessageBuilder msg;
1062 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1063 msg.WriteToLogFile();
1064#endif
1065}
1066
1067
1068void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1069#ifdef ENABLE_LOGGING_AND_PROFILING
1070 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1071 LogMessageBuilder msg;
1072 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1073 msg.WriteToLogFile();
1074#endif
1075}
1076
1077
1078void Logger::HeapSampleJSConstructorEvent(const char* constructor,
1079 int number, int bytes) {
1080#ifdef ENABLE_LOGGING_AND_PROFILING
1081 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1082 LogMessageBuilder msg;
1083 msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
1084 msg.WriteToLogFile();
1085#endif
1086}
1087
1088
1089void Logger::HeapSampleJSRetainersEvent(
1090 const char* constructor, const char* event) {
1091#ifdef ENABLE_LOGGING_AND_PROFILING
1092 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1093 // Event starts with comma, so we don't have it in the format string.
1094 static const char* event_text = "heap-js-ret-item,%s";
1095 // We take placeholder strings into account, but it's OK to be conservative.
Steve Blockd0582a62009-12-15 09:54:21 +00001096 static const int event_text_len = StrLength(event_text);
1097 const int cons_len = StrLength(constructor);
1098 const int event_len = StrLength(event);
Steve Blocka7e24c12009-10-30 11:49:00 +00001099 int pos = 0;
1100 // Retainer lists can be long. We may need to split them into multiple events.
1101 do {
1102 LogMessageBuilder msg;
1103 msg.Append(event_text, constructor);
1104 int to_write = event_len - pos;
1105 if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) {
1106 int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len);
1107 ASSERT(cut_pos < event_len);
1108 while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
1109 if (event[cut_pos] != ',') {
1110 // Crash in debug mode, skip in release mode.
1111 ASSERT(false);
1112 return;
1113 }
1114 // Append a piece of event that fits, without trailing comma.
1115 msg.AppendStringPart(event + pos, cut_pos - pos);
1116 // Start next piece with comma.
1117 pos = cut_pos;
1118 } else {
1119 msg.Append("%s", event + pos);
1120 pos += event_len;
1121 }
1122 msg.Append('\n');
1123 msg.WriteToLogFile();
1124 } while (pos < event_len);
1125#endif
1126}
1127
1128
Steve Block3ce2e202009-11-05 08:53:23 +00001129void Logger::HeapSampleJSProducerEvent(const char* constructor,
1130 Address* stack) {
1131#ifdef ENABLE_LOGGING_AND_PROFILING
1132 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1133 LogMessageBuilder msg;
1134 msg.Append("heap-js-prod-item,%s", constructor);
1135 while (*stack != NULL) {
1136 msg.Append(",0x%" V8PRIxPTR, *stack++);
1137 }
1138 msg.Append("\n");
1139 msg.WriteToLogFile();
1140#endif
1141}
1142
1143
Steve Blocka7e24c12009-10-30 11:49:00 +00001144void Logger::DebugTag(const char* call_site_tag) {
1145#ifdef ENABLE_LOGGING_AND_PROFILING
1146 if (!Log::IsEnabled() || !FLAG_log) return;
1147 LogMessageBuilder msg;
1148 msg.Append("debug-tag,%s\n", call_site_tag);
1149 msg.WriteToLogFile();
1150#endif
1151}
1152
1153
1154void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1155#ifdef ENABLE_LOGGING_AND_PROFILING
1156 if (!Log::IsEnabled() || !FLAG_log) return;
1157 StringBuilder s(parameter.length() + 1);
1158 for (int i = 0; i < parameter.length(); ++i) {
1159 s.AddCharacter(static_cast<char>(parameter[i]));
1160 }
1161 char* parameter_string = s.Finalize();
1162 LogMessageBuilder msg;
1163 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1164 event_type,
1165 OS::TimeCurrentMillis(),
1166 parameter_string);
1167 DeleteArray(parameter_string);
1168 msg.WriteToLogFile();
1169#endif
1170}
1171
1172
1173#ifdef ENABLE_LOGGING_AND_PROFILING
1174void Logger::TickEvent(TickSample* sample, bool overflow) {
1175 if (!Log::IsEnabled() || !FLAG_prof) return;
1176 static Address prev_sp = NULL;
Leon Clarked91b9f72010-01-27 17:25:45 +00001177 static Address prev_function = NULL;
Steve Blocka7e24c12009-10-30 11:49:00 +00001178 LogMessageBuilder msg;
1179 msg.Append("%s,", log_events_[TICK_EVENT]);
Leon Clarked91b9f72010-01-27 17:25:45 +00001180 Address prev_addr = sample->pc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001181 msg.AppendAddress(prev_addr);
1182 msg.Append(',');
Leon Clarked91b9f72010-01-27 17:25:45 +00001183 msg.AppendAddress(sample->sp, prev_sp);
1184 prev_sp = sample->sp;
1185 msg.Append(',');
1186 msg.AppendAddress(sample->function, prev_function);
1187 prev_function = sample->function;
Steve Blocka7e24c12009-10-30 11:49:00 +00001188 msg.Append(",%d", static_cast<int>(sample->state));
1189 if (overflow) {
1190 msg.Append(",overflow");
1191 }
1192 for (int i = 0; i < sample->frames_count; ++i) {
1193 msg.Append(',');
1194 msg.AppendAddress(sample->stack[i], prev_addr);
1195 prev_addr = sample->stack[i];
1196 }
1197 if (FLAG_compress_log) {
1198 ASSERT(compression_helper_ != NULL);
1199 if (!compression_helper_->HandleMessage(&msg)) return;
1200 }
1201 msg.Append('\n');
1202 msg.WriteToLogFile();
1203}
1204
1205
1206int Logger::GetActiveProfilerModules() {
1207 int result = PROFILER_MODULE_NONE;
Steve Block8defd9f2010-07-08 12:39:36 +01001208 if (profiler_ != NULL && !profiler_->paused()) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001209 result |= PROFILER_MODULE_CPU;
1210 }
1211 if (FLAG_log_gc) {
1212 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1213 }
1214 return result;
1215}
1216
1217
Andrei Popescu402d9372010-02-26 13:31:12 +00001218void Logger::PauseProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001219 if (!Log::IsEnabled()) return;
Steve Block8defd9f2010-07-08 12:39:36 +01001220 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001221 // It is OK to have negative nesting.
1222 if (--cpu_profiler_nesting_ == 0) {
1223 profiler_->pause();
1224 if (FLAG_prof_lazy) {
1225 if (!FLAG_sliding_state_window) ticker_->Stop();
1226 FLAG_log_code = false;
1227 // Must be the same message as Log::kDynamicBufferSeal.
1228 LOG(UncheckedStringEvent("profiler", "pause"));
1229 }
Steve Block6ded16b2010-05-10 14:33:55 +01001230 --logging_nesting_;
Steve Blocka7e24c12009-10-30 11:49:00 +00001231 }
1232 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001233 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001234 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001235 if (--heap_profiler_nesting_ == 0) {
1236 FLAG_log_gc = false;
Steve Block6ded16b2010-05-10 14:33:55 +01001237 --logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001238 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001239 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001240 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001241 UncheckedIntEvent("close-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001242 }
1243}
1244
1245
Andrei Popescu402d9372010-02-26 13:31:12 +00001246void Logger::ResumeProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001247 if (!Log::IsEnabled()) return;
Andrei Popescu402d9372010-02-26 13:31:12 +00001248 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001249 UncheckedIntEvent("open-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001250 }
Steve Block8defd9f2010-07-08 12:39:36 +01001251 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001252 if (cpu_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001253 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001254 if (FLAG_prof_lazy) {
1255 profiler_->Engage();
1256 LOG(UncheckedStringEvent("profiler", "resume"));
1257 FLAG_log_code = true;
1258 LogCompiledFunctions();
1259 LogFunctionObjects();
1260 LogAccessorCallbacks();
1261 if (!FLAG_sliding_state_window) ticker_->Start();
1262 }
1263 profiler_->resume();
Steve Blocka7e24c12009-10-30 11:49:00 +00001264 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001265 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001266 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001267 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001268 if (heap_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001269 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001270 FLAG_log_gc = true;
1271 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001272 }
1273}
1274
1275
1276// This function can be called when Log's mutex is acquired,
1277// either from main or Profiler's thread.
1278void Logger::StopLoggingAndProfiling() {
1279 Log::stop();
Andrei Popescu402d9372010-02-26 13:31:12 +00001280 PauseProfiler(PROFILER_MODULE_CPU, 0);
Steve Blocka7e24c12009-10-30 11:49:00 +00001281}
1282
1283
1284bool Logger::IsProfilerSamplerActive() {
1285 return ticker_->IsActive();
1286}
1287
1288
1289int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1290 return Log::GetLogLines(from_pos, dest_buf, max_size);
1291}
1292
1293
Steve Block3ce2e202009-11-05 08:53:23 +00001294static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis) {
1295 AssertNoAllocation no_alloc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001296 int compiled_funcs_count = 0;
Steve Block3ce2e202009-11-05 08:53:23 +00001297 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001298 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Block3ce2e202009-11-05 08:53:23 +00001299 if (!obj->IsSharedFunctionInfo()) continue;
1300 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1301 if (sfi->is_compiled()
1302 && (!sfi->script()->IsScript()
1303 || Script::cast(sfi->script())->HasValidSource())) {
1304 if (sfis != NULL)
1305 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1306 ++compiled_funcs_count;
Steve Blocka7e24c12009-10-30 11:49:00 +00001307 }
1308 }
Steve Block3ce2e202009-11-05 08:53:23 +00001309 return compiled_funcs_count;
1310}
1311
1312
Steve Blockd0582a62009-12-15 09:54:21 +00001313void Logger::LogCodeObject(Object* object) {
1314 if (FLAG_log_code) {
1315 Code* code_object = Code::cast(object);
1316 LogEventsAndTags tag = Logger::STUB_TAG;
1317 const char* description = "Unknown code from the snapshot";
1318 switch (code_object->kind()) {
1319 case Code::FUNCTION:
1320 return; // We log this later using LogCompiledFunctions.
Steve Block6ded16b2010-05-10 14:33:55 +01001321 case Code::BINARY_OP_IC:
1322 // fall through
Steve Blockd0582a62009-12-15 09:54:21 +00001323 case Code::STUB:
Kristian Monsen80d68ea2010-09-08 11:05:35 +01001324 description =
1325 CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
Andrei Popescu31002712010-02-23 13:46:05 +00001326 if (description == NULL)
1327 description = "A stub from the snapshot";
Steve Blockd0582a62009-12-15 09:54:21 +00001328 tag = Logger::STUB_TAG;
1329 break;
1330 case Code::BUILTIN:
1331 description = "A builtin from the snapshot";
1332 tag = Logger::BUILTIN_TAG;
1333 break;
1334 case Code::KEYED_LOAD_IC:
1335 description = "A keyed load IC from the snapshot";
1336 tag = Logger::KEYED_LOAD_IC_TAG;
1337 break;
1338 case Code::LOAD_IC:
1339 description = "A load IC from the snapshot";
1340 tag = Logger::LOAD_IC_TAG;
1341 break;
1342 case Code::STORE_IC:
1343 description = "A store IC from the snapshot";
1344 tag = Logger::STORE_IC_TAG;
1345 break;
1346 case Code::KEYED_STORE_IC:
1347 description = "A keyed store IC from the snapshot";
1348 tag = Logger::KEYED_STORE_IC_TAG;
1349 break;
1350 case Code::CALL_IC:
1351 description = "A call IC from the snapshot";
1352 tag = Logger::CALL_IC_TAG;
1353 break;
Ben Murdoch7f4d5bd2010-06-15 11:15:29 +01001354 case Code::KEYED_CALL_IC:
1355 description = "A keyed call IC from the snapshot";
1356 tag = Logger::KEYED_CALL_IC_TAG;
1357 break;
Steve Blockd0582a62009-12-15 09:54:21 +00001358 }
Steve Block6ded16b2010-05-10 14:33:55 +01001359 PROFILE(CodeCreateEvent(tag, code_object, description));
Steve Blockd0582a62009-12-15 09:54:21 +00001360 }
1361}
1362
1363
Ben Murdochf87a2032010-10-22 12:50:53 +01001364void Logger::LogCodeInfo() {
1365#ifdef ENABLE_LOGGING_AND_PROFILING
1366 if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
1367#if V8_TARGET_ARCH_IA32
1368 const char arch[] = "ia32";
1369#elif V8_TARGET_ARCH_X64
1370 const char arch[] = "x64";
1371#elif V8_TARGET_ARCH_ARM
1372 const char arch[] = "arm";
1373#else
1374 const char arch[] = "unknown";
1375#endif
1376 LogMessageBuilder msg;
1377 msg.Append("code-info,%s,%d\n", arch, Code::kHeaderSize);
1378 msg.WriteToLogFile();
1379#endif // ENABLE_LOGGING_AND_PROFILING
1380}
1381
1382
1383void Logger::LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg) {
1384 if (!FLAG_ll_prof || Log::output_code_handle_ == NULL) return;
1385 int pos = static_cast<int>(ftell(Log::output_code_handle_));
John Reck59135872010-11-02 12:39:01 -07001386 size_t rv = fwrite(code->instruction_start(), 1, code->instruction_size(),
1387 Log::output_code_handle_);
1388 ASSERT(static_cast<size_t>(code->instruction_size()) == rv);
1389 USE(rv);
Ben Murdochf87a2032010-10-22 12:50:53 +01001390 msg->Append(",%d", pos);
1391}
1392
1393
Andrei Popescu31002712010-02-23 13:46:05 +00001394void Logger::LogCodeObjects() {
1395 AssertNoAllocation no_alloc;
1396 HeapIterator iterator;
1397 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1398 if (obj->IsCode()) LogCodeObject(obj);
1399 }
1400}
1401
1402
Steve Block3ce2e202009-11-05 08:53:23 +00001403void Logger::LogCompiledFunctions() {
1404 HandleScope scope;
1405 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL);
Kristian Monsen25f61362010-05-21 11:50:48 +01001406 ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
1407 EnumerateCompiledFunctions(sfis.start());
Steve Blocka7e24c12009-10-30 11:49:00 +00001408
1409 // During iteration, there can be heap allocation due to
1410 // GetScriptLineNumber call.
1411 for (int i = 0; i < compiled_funcs_count; ++i) {
1412 Handle<SharedFunctionInfo> shared = sfis[i];
1413 Handle<String> name(String::cast(shared->name()));
1414 Handle<String> func_name(name->length() > 0 ?
1415 *name : shared->inferred_name());
1416 if (shared->script()->IsScript()) {
1417 Handle<Script> script(Script::cast(shared->script()));
1418 if (script->name()->IsString()) {
1419 Handle<String> script_name(String::cast(script->name()));
1420 int line_num = GetScriptLineNumber(script, shared->start_position());
1421 if (line_num > 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001422 PROFILE(CodeCreateEvent(
1423 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1424 shared->code(), *func_name,
1425 *script_name, line_num + 1));
Steve Blocka7e24c12009-10-30 11:49:00 +00001426 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001427 // Can't distinguish eval and script here, so always use Script.
1428 PROFILE(CodeCreateEvent(
1429 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1430 shared->code(), *script_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001431 }
Steve Blockd0582a62009-12-15 09:54:21 +00001432 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001433 PROFILE(CodeCreateEvent(
1434 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1435 shared->code(), *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001436 }
Steve Block6ded16b2010-05-10 14:33:55 +01001437 } else if (shared->IsApiFunction()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001438 // API function.
Steve Block6ded16b2010-05-10 14:33:55 +01001439 FunctionTemplateInfo* fun_data = shared->get_api_func_data();
Steve Blockd0582a62009-12-15 09:54:21 +00001440 Object* raw_call_data = fun_data->call_code();
1441 if (!raw_call_data->IsUndefined()) {
1442 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1443 Object* callback_obj = call_data->callback();
1444 Address entry_point = v8::ToCData<Address>(callback_obj);
Steve Block6ded16b2010-05-10 14:33:55 +01001445 PROFILE(CallbackEvent(*func_name, entry_point));
Steve Blockd0582a62009-12-15 09:54:21 +00001446 }
1447 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001448 PROFILE(CodeCreateEvent(
Steve Blockd0582a62009-12-15 09:54:21 +00001449 Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001450 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001451 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001452}
1453
Steve Blockd0582a62009-12-15 09:54:21 +00001454
Leon Clarked91b9f72010-01-27 17:25:45 +00001455void Logger::LogFunctionObjects() {
1456 AssertNoAllocation no_alloc;
1457 HeapIterator iterator;
1458 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1459 if (!obj->IsJSFunction()) continue;
1460 JSFunction* jsf = JSFunction::cast(obj);
1461 if (!jsf->is_compiled()) continue;
Steve Block6ded16b2010-05-10 14:33:55 +01001462 PROFILE(FunctionCreateEvent(jsf));
Leon Clarked91b9f72010-01-27 17:25:45 +00001463 }
1464}
1465
1466
Steve Blockd0582a62009-12-15 09:54:21 +00001467void Logger::LogAccessorCallbacks() {
1468 AssertNoAllocation no_alloc;
1469 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001470 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001471 if (!obj->IsAccessorInfo()) continue;
1472 AccessorInfo* ai = AccessorInfo::cast(obj);
1473 if (!ai->name()->IsString()) continue;
1474 String* name = String::cast(ai->name());
1475 Address getter_entry = v8::ToCData<Address>(ai->getter());
1476 if (getter_entry != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001477 PROFILE(GetterCallbackEvent(name, getter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001478 }
1479 Address setter_entry = v8::ToCData<Address>(ai->setter());
1480 if (setter_entry != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001481 PROFILE(SetterCallbackEvent(name, setter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001482 }
1483 }
1484}
1485
Steve Blocka7e24c12009-10-30 11:49:00 +00001486#endif
1487
1488
1489bool Logger::Setup() {
1490#ifdef ENABLE_LOGGING_AND_PROFILING
1491 // --log-all enables all the log flags.
1492 if (FLAG_log_all) {
1493 FLAG_log_runtime = true;
1494 FLAG_log_api = true;
1495 FLAG_log_code = true;
1496 FLAG_log_gc = true;
1497 FLAG_log_suspect = true;
1498 FLAG_log_handles = true;
1499 FLAG_log_regexp = true;
1500 }
1501
1502 // --prof implies --log-code.
1503 if (FLAG_prof) FLAG_log_code = true;
1504
Ben Murdochf87a2032010-10-22 12:50:53 +01001505 // --ll-prof implies --log-code and --log-snapshot-positions.
1506 if (FLAG_ll_prof) {
1507 FLAG_log_code = true;
1508 FLAG_log_snapshot_positions = true;
1509 }
1510
Steve Blocka7e24c12009-10-30 11:49:00 +00001511 // --prof_lazy controls --log-code, implies --noprof_auto.
1512 if (FLAG_prof_lazy) {
1513 FLAG_log_code = false;
1514 FLAG_prof_auto = false;
1515 }
1516
1517 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1518 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1519 || FLAG_log_regexp || FLAG_log_state_changes;
1520
1521 bool open_log_file = start_logging || FLAG_prof_lazy;
1522
1523 // If we're logging anything, we need to open the log file.
1524 if (open_log_file) {
1525 if (strcmp(FLAG_logfile, "-") == 0) {
1526 Log::OpenStdout();
1527 } else if (strcmp(FLAG_logfile, "*") == 0) {
1528 Log::OpenMemoryBuffer();
1529 } else if (strchr(FLAG_logfile, '%') != NULL) {
1530 // If there's a '%' in the log file name we have to expand
1531 // placeholders.
1532 HeapStringAllocator allocator;
1533 StringStream stream(&allocator);
1534 for (const char* p = FLAG_logfile; *p; p++) {
1535 if (*p == '%') {
1536 p++;
1537 switch (*p) {
1538 case '\0':
1539 // If there's a % at the end of the string we back up
1540 // one character so we can escape the loop properly.
1541 p--;
1542 break;
1543 case 't': {
1544 // %t expands to the current time in milliseconds.
1545 double time = OS::TimeCurrentMillis();
1546 stream.Add("%.0f", FmtElm(time));
1547 break;
1548 }
1549 case '%':
1550 // %% expands (contracts really) to %.
1551 stream.Put('%');
1552 break;
1553 default:
1554 // All other %'s expand to themselves.
1555 stream.Put('%');
1556 stream.Put(*p);
1557 break;
1558 }
1559 } else {
1560 stream.Put(*p);
1561 }
1562 }
1563 SmartPointer<const char> expanded = stream.ToCString();
1564 Log::OpenFile(*expanded);
1565 } else {
1566 Log::OpenFile(FLAG_logfile);
1567 }
1568 }
1569
Steve Block6ded16b2010-05-10 14:33:55 +01001570 ASSERT(VMState::is_outermost_external());
Steve Blocka7e24c12009-10-30 11:49:00 +00001571
Ben Murdochf87a2032010-10-22 12:50:53 +01001572 if (FLAG_ll_prof) LogCodeInfo();
1573
Steve Blocka7e24c12009-10-30 11:49:00 +00001574 ticker_ = new Ticker(kSamplingIntervalMs);
1575
1576 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1577 sliding_state_window_ = new SlidingStateWindow();
1578 }
1579
1580 log_events_ = FLAG_compress_log ?
1581 kCompressedLogEventsNames : kLongLogEventsNames;
1582 if (FLAG_compress_log) {
1583 compression_helper_ = new CompressionHelper(kCompressionWindowSize);
1584 }
1585
Steve Block6ded16b2010-05-10 14:33:55 +01001586 if (start_logging) {
1587 logging_nesting_ = 1;
1588 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001589
1590 if (FLAG_prof) {
1591 profiler_ = new Profiler();
1592 if (!FLAG_prof_auto) {
1593 profiler_->pause();
1594 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001595 logging_nesting_ = 1;
Steve Blocka7e24c12009-10-30 11:49:00 +00001596 }
Steve Blockd0582a62009-12-15 09:54:21 +00001597 if (!FLAG_prof_lazy) {
1598 profiler_->Engage();
1599 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001600 }
1601
1602 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
1603
1604 return true;
1605
1606#else
1607 return false;
1608#endif
1609}
1610
1611
1612void Logger::TearDown() {
1613#ifdef ENABLE_LOGGING_AND_PROFILING
1614 LogMessageBuilder::set_write_failure_handler(NULL);
1615
1616 // Stop the profiler before closing the file.
1617 if (profiler_ != NULL) {
1618 profiler_->Disengage();
1619 delete profiler_;
1620 profiler_ = NULL;
1621 }
1622
1623 delete compression_helper_;
1624 compression_helper_ = NULL;
1625
1626 delete sliding_state_window_;
1627 sliding_state_window_ = NULL;
1628
1629 delete ticker_;
1630 ticker_ = NULL;
1631
1632 Log::Close();
1633#endif
1634}
1635
1636
1637void Logger::EnableSlidingStateWindow() {
1638#ifdef ENABLE_LOGGING_AND_PROFILING
1639 // If the ticker is NULL, Logger::Setup has not been called yet. In
1640 // that case, we set the sliding_state_window flag so that the
1641 // sliding window computation will be started when Logger::Setup is
1642 // called.
1643 if (ticker_ == NULL) {
1644 FLAG_sliding_state_window = true;
1645 return;
1646 }
1647 // Otherwise, if the sliding state window computation has not been
1648 // started we do it now.
1649 if (sliding_state_window_ == NULL) {
1650 sliding_state_window_ = new SlidingStateWindow();
1651 }
1652#endif
1653}
1654
Steve Blocka7e24c12009-10-30 11:49:00 +00001655} } // namespace v8::internal