blob: e1ebc87c65f6c2526373bda52edb5b3004c20304 [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) {
Steve Block6ded16b2010-05-10 14:33:55 +0100146 sample->function = NULL;
147 sample->frames_count = 0;
148
149 if (sample->state == GC) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000150
151 const Address js_entry_sp = Top::js_entry_sp(Top::GetCurrentThread());
152 if (js_entry_sp == 0) {
153 // Not executing JS now.
Steve Blocka7e24c12009-10-30 11:49:00 +0000154 return;
155 }
156
Leon Clarked91b9f72010-01-27 17:25:45 +0000157 const Address functionAddr =
158 sample->fp + JavaScriptFrameConstants::kFunctionOffset;
159 if (SafeStackFrameIterator::IsWithinBounds(sample->sp, js_entry_sp,
160 functionAddr)) {
161 sample->function = Memory::Address_at(functionAddr) - kHeapObjectTag;
162 }
163
Steve Blockd0582a62009-12-15 09:54:21 +0000164 int i = 0;
Steve Block6ded16b2010-05-10 14:33:55 +0100165 const Address callback = VMState::external_callback();
Steve Blockd0582a62009-12-15 09:54:21 +0000166 if (callback != NULL) {
167 sample->stack[i++] = callback;
168 }
169
Leon Clarked91b9f72010-01-27 17:25:45 +0000170 SafeStackTraceFrameIterator it(sample->fp, sample->sp,
171 sample->sp, js_entry_sp);
Steve Blocka7e24c12009-10-30 11:49:00 +0000172 while (!it.done() && i < TickSample::kMaxFramesCount) {
173 sample->stack[i++] = it.frame()->pc();
174 it.Advance();
175 }
176 sample->frames_count = i;
177}
178
179
180//
181// Ticker used to provide ticks to the profiler and the sliding state
182// window.
183//
184class Ticker: public Sampler {
185 public:
186 explicit Ticker(int interval):
187 Sampler(interval, FLAG_prof), window_(NULL), profiler_(NULL) {}
188
189 ~Ticker() { if (IsActive()) Stop(); }
190
191 void SampleStack(TickSample* sample) {
192 StackTracer::Trace(sample);
193 }
194
195 void Tick(TickSample* sample) {
196 if (profiler_) profiler_->Insert(sample);
197 if (window_) window_->AddState(sample->state);
198 }
199
200 void SetWindow(SlidingStateWindow* window) {
201 window_ = window;
202 if (!IsActive()) Start();
203 }
204
205 void ClearWindow() {
206 window_ = NULL;
207 if (!profiler_ && IsActive()) Stop();
208 }
209
210 void SetProfiler(Profiler* profiler) {
211 profiler_ = profiler;
212 if (!FLAG_prof_lazy && !IsActive()) Start();
213 }
214
215 void ClearProfiler() {
216 profiler_ = NULL;
217 if (!window_ && IsActive()) Stop();
218 }
219
220 private:
221 SlidingStateWindow* window_;
222 Profiler* profiler_;
223};
224
225
226//
227// SlidingStateWindow implementation.
228//
229SlidingStateWindow::SlidingStateWindow(): current_index_(0), is_full_(false) {
230 for (int i = 0; i < kBufferSize; i++) {
231 buffer_[i] = static_cast<byte>(OTHER);
232 }
233 Logger::ticker_->SetWindow(this);
234}
235
236
237SlidingStateWindow::~SlidingStateWindow() {
238 Logger::ticker_->ClearWindow();
239}
240
241
242void SlidingStateWindow::AddState(StateTag state) {
243 if (is_full_) {
244 DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
245 } else if (current_index_ == kBufferSize - 1) {
246 is_full_ = true;
247 }
248 buffer_[current_index_] = static_cast<byte>(state);
249 IncrementStateCounter(state);
250 ASSERT(IsPowerOf2(kBufferSize));
251 current_index_ = (current_index_ + 1) & (kBufferSize - 1);
252}
253
254
255//
256// Profiler implementation.
257//
Steve Blockd0582a62009-12-15 09:54:21 +0000258Profiler::Profiler()
259 : head_(0),
260 tail_(0),
261 overflow_(false),
262 buffer_semaphore_(OS::CreateSemaphore(0)),
263 engaged_(false),
264 running_(false) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000265}
266
267
268void Profiler::Engage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000269 if (engaged_) return;
270 engaged_ = true;
271
272 // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
273 // http://code.google.com/p/v8/issues/detail?id=487
274 if (!FLAG_prof_lazy) {
275 OS::LogSharedLibraryAddresses();
276 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000277
278 // Start thread processing the profiler buffer.
279 running_ = true;
280 Start();
281
282 // Register to get ticks.
283 Logger::ticker_->SetProfiler(this);
284
285 Logger::ProfilerBeginEvent();
286 Logger::LogAliases();
287}
288
289
290void Profiler::Disengage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000291 if (!engaged_) return;
292
Steve Blocka7e24c12009-10-30 11:49:00 +0000293 // Stop receiving ticks.
294 Logger::ticker_->ClearProfiler();
295
296 // Terminate the worker thread by setting running_ to false,
297 // inserting a fake element in the queue and then wait for
298 // the thread to terminate.
299 running_ = false;
300 TickSample sample;
301 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
302 resume();
303 Insert(&sample);
304 Join();
305
306 LOG(UncheckedStringEvent("profiler", "end"));
307}
308
309
310void Profiler::Run() {
311 TickSample sample;
312 bool overflow = Logger::profiler_->Remove(&sample);
313 while (running_) {
314 LOG(TickEvent(&sample, overflow));
315 overflow = Logger::profiler_->Remove(&sample);
316 }
317}
318
319
320//
321// Logger class implementation.
322//
323Ticker* Logger::ticker_ = NULL;
324Profiler* Logger::profiler_ = NULL;
Steve Blocka7e24c12009-10-30 11:49:00 +0000325SlidingStateWindow* Logger::sliding_state_window_ = NULL;
326const char** Logger::log_events_ = NULL;
327CompressionHelper* Logger::compression_helper_ = NULL;
Steve Block6ded16b2010-05-10 14:33:55 +0100328int Logger::logging_nesting_ = 0;
Andrei Popescu402d9372010-02-26 13:31:12 +0000329int Logger::cpu_profiler_nesting_ = 0;
330int Logger::heap_profiler_nesting_ = 0;
Steve Blocka7e24c12009-10-30 11:49:00 +0000331
332#define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name,
333const char* kLongLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
334 LOG_EVENTS_AND_TAGS_LIST(DECLARE_LONG_EVENT)
335};
336#undef DECLARE_LONG_EVENT
337
338#define DECLARE_SHORT_EVENT(ignore1, ignore2, short_name) short_name,
339const char* kCompressedLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
340 LOG_EVENTS_AND_TAGS_LIST(DECLARE_SHORT_EVENT)
341};
342#undef DECLARE_SHORT_EVENT
343
344
345void Logger::ProfilerBeginEvent() {
346 if (!Log::IsEnabled()) return;
347 LogMessageBuilder msg;
348 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
349 if (FLAG_compress_log) {
350 msg.Append("profiler,\"compression\",%d\n", kCompressionWindowSize);
351 }
352 msg.WriteToLogFile();
353}
354
355
356void Logger::LogAliases() {
357 if (!Log::IsEnabled() || !FLAG_compress_log) return;
358 LogMessageBuilder msg;
359 for (int i = 0; i < NUMBER_OF_LOG_EVENTS; ++i) {
360 msg.Append("alias,%s,%s\n",
361 kCompressedLogEventsNames[i], kLongLogEventsNames[i]);
362 }
363 msg.WriteToLogFile();
364}
365
366#endif // ENABLE_LOGGING_AND_PROFILING
367
368
Steve Blocka7e24c12009-10-30 11:49:00 +0000369void Logger::StringEvent(const char* name, const char* value) {
370#ifdef ENABLE_LOGGING_AND_PROFILING
371 if (FLAG_log) UncheckedStringEvent(name, value);
372#endif
373}
374
375
376#ifdef ENABLE_LOGGING_AND_PROFILING
377void Logger::UncheckedStringEvent(const char* name, const char* value) {
378 if (!Log::IsEnabled()) return;
379 LogMessageBuilder msg;
380 msg.Append("%s,\"%s\"\n", name, value);
381 msg.WriteToLogFile();
382}
383#endif
384
385
386void Logger::IntEvent(const char* name, int value) {
387#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block6ded16b2010-05-10 14:33:55 +0100388 if (FLAG_log) UncheckedIntEvent(name, value);
389#endif
390}
391
392
393#ifdef ENABLE_LOGGING_AND_PROFILING
394void Logger::UncheckedIntEvent(const char* name, int value) {
395 if (!Log::IsEnabled()) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000396 LogMessageBuilder msg;
397 msg.Append("%s,%d\n", name, value);
398 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000399}
Steve Block6ded16b2010-05-10 14:33:55 +0100400#endif
Steve Blocka7e24c12009-10-30 11:49:00 +0000401
402
403void Logger::HandleEvent(const char* name, Object** location) {
404#ifdef ENABLE_LOGGING_AND_PROFILING
405 if (!Log::IsEnabled() || !FLAG_log_handles) return;
406 LogMessageBuilder msg;
407 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
408 msg.WriteToLogFile();
409#endif
410}
411
412
413#ifdef ENABLE_LOGGING_AND_PROFILING
414// ApiEvent is private so all the calls come from the Logger class. It is the
415// caller's responsibility to ensure that log is enabled and that
416// FLAG_log_api is true.
417void Logger::ApiEvent(const char* format, ...) {
418 ASSERT(Log::IsEnabled() && FLAG_log_api);
419 LogMessageBuilder msg;
420 va_list ap;
421 va_start(ap, format);
422 msg.AppendVA(format, ap);
423 va_end(ap);
424 msg.WriteToLogFile();
425}
426#endif
427
428
429void Logger::ApiNamedSecurityCheck(Object* key) {
430#ifdef ENABLE_LOGGING_AND_PROFILING
431 if (!Log::IsEnabled() || !FLAG_log_api) return;
432 if (key->IsString()) {
433 SmartPointer<char> str =
434 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
435 ApiEvent("api,check-security,\"%s\"\n", *str);
436 } else if (key->IsUndefined()) {
437 ApiEvent("api,check-security,undefined\n");
438 } else {
439 ApiEvent("api,check-security,['no-name']\n");
440 }
441#endif
442}
443
444
445void Logger::SharedLibraryEvent(const char* library_path,
446 uintptr_t start,
447 uintptr_t end) {
448#ifdef ENABLE_LOGGING_AND_PROFILING
449 if (!Log::IsEnabled() || !FLAG_prof) return;
450 LogMessageBuilder msg;
451 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
452 library_path,
453 start,
454 end);
455 msg.WriteToLogFile();
456#endif
457}
458
459
460void Logger::SharedLibraryEvent(const wchar_t* library_path,
461 uintptr_t start,
462 uintptr_t end) {
463#ifdef ENABLE_LOGGING_AND_PROFILING
464 if (!Log::IsEnabled() || !FLAG_prof) return;
465 LogMessageBuilder msg;
466 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
467 library_path,
468 start,
469 end);
470 msg.WriteToLogFile();
471#endif
472}
473
474
475#ifdef ENABLE_LOGGING_AND_PROFILING
476void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
477 // Prints "/" + re.source + "/" +
478 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
479 LogMessageBuilder msg;
480
481 Handle<Object> source = GetProperty(regexp, "source");
482 if (!source->IsString()) {
483 msg.Append("no source");
484 return;
485 }
486
487 switch (regexp->TypeTag()) {
488 case JSRegExp::ATOM:
489 msg.Append('a');
490 break;
491 default:
492 break;
493 }
494 msg.Append('/');
495 msg.AppendDetailed(*Handle<String>::cast(source), false);
496 msg.Append('/');
497
498 // global flag
499 Handle<Object> global = GetProperty(regexp, "global");
500 if (global->IsTrue()) {
501 msg.Append('g');
502 }
503 // ignorecase flag
504 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
505 if (ignorecase->IsTrue()) {
506 msg.Append('i');
507 }
508 // multiline flag
509 Handle<Object> multiline = GetProperty(regexp, "multiline");
510 if (multiline->IsTrue()) {
511 msg.Append('m');
512 }
513
514 msg.WriteToLogFile();
515}
516#endif // ENABLE_LOGGING_AND_PROFILING
517
518
519void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
520#ifdef ENABLE_LOGGING_AND_PROFILING
521 if (!Log::IsEnabled() || !FLAG_log_regexp) return;
522 LogMessageBuilder msg;
523 msg.Append("regexp-compile,");
524 LogRegExpSource(regexp);
525 msg.Append(in_cache ? ",hit\n" : ",miss\n");
526 msg.WriteToLogFile();
527#endif
528}
529
530
531void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
532#ifdef ENABLE_LOGGING_AND_PROFILING
533 if (!Log::IsEnabled() || !FLAG_log_runtime) return;
534 HandleScope scope;
535 LogMessageBuilder msg;
536 for (int i = 0; i < format.length(); i++) {
537 char c = format[i];
538 if (c == '%' && i <= format.length() - 2) {
539 i++;
540 ASSERT('0' <= format[i] && format[i] <= '9');
541 Object* obj = args->GetElement(format[i] - '0');
542 i++;
543 switch (format[i]) {
544 case 's':
545 msg.AppendDetailed(String::cast(obj), false);
546 break;
547 case 'S':
548 msg.AppendDetailed(String::cast(obj), true);
549 break;
550 case 'r':
551 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
552 break;
553 case 'x':
554 msg.Append("0x%x", Smi::cast(obj)->value());
555 break;
556 case 'i':
557 msg.Append("%i", Smi::cast(obj)->value());
558 break;
559 default:
560 UNREACHABLE();
561 }
562 } else {
563 msg.Append(c);
564 }
565 }
566 msg.Append('\n');
567 msg.WriteToLogFile();
568#endif
569}
570
571
572void Logger::ApiIndexedSecurityCheck(uint32_t index) {
573#ifdef ENABLE_LOGGING_AND_PROFILING
574 if (!Log::IsEnabled() || !FLAG_log_api) return;
575 ApiEvent("api,check-security,%u\n", index);
576#endif
577}
578
579
580void Logger::ApiNamedPropertyAccess(const char* tag,
581 JSObject* holder,
582 Object* name) {
583#ifdef ENABLE_LOGGING_AND_PROFILING
584 ASSERT(name->IsString());
585 if (!Log::IsEnabled() || !FLAG_log_api) return;
586 String* class_name_obj = holder->class_name();
587 SmartPointer<char> class_name =
588 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
589 SmartPointer<char> property_name =
590 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
591 Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
592#endif
593}
594
595void Logger::ApiIndexedPropertyAccess(const char* tag,
596 JSObject* holder,
597 uint32_t index) {
598#ifdef ENABLE_LOGGING_AND_PROFILING
599 if (!Log::IsEnabled() || !FLAG_log_api) return;
600 String* class_name_obj = holder->class_name();
601 SmartPointer<char> class_name =
602 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
603 Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
604#endif
605}
606
607void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
608#ifdef ENABLE_LOGGING_AND_PROFILING
609 if (!Log::IsEnabled() || !FLAG_log_api) return;
610 String* class_name_obj = object->class_name();
611 SmartPointer<char> class_name =
612 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
613 Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
614#endif
615}
616
617
618void Logger::ApiEntryCall(const char* name) {
619#ifdef ENABLE_LOGGING_AND_PROFILING
620 if (!Log::IsEnabled() || !FLAG_log_api) return;
621 Logger::ApiEvent("api,%s\n", name);
622#endif
623}
624
625
626void Logger::NewEvent(const char* name, void* object, size_t size) {
627#ifdef ENABLE_LOGGING_AND_PROFILING
628 if (!Log::IsEnabled() || !FLAG_log) return;
629 LogMessageBuilder msg;
630 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
631 static_cast<unsigned int>(size));
632 msg.WriteToLogFile();
633#endif
634}
635
636
637void Logger::DeleteEvent(const char* name, void* object) {
638#ifdef ENABLE_LOGGING_AND_PROFILING
639 if (!Log::IsEnabled() || !FLAG_log) return;
640 LogMessageBuilder msg;
641 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
642 msg.WriteToLogFile();
643#endif
644}
645
646
647#ifdef ENABLE_LOGGING_AND_PROFILING
648
649// A class that contains all common code dealing with record compression.
650class CompressionHelper {
651 public:
652 explicit CompressionHelper(int window_size)
653 : compressor_(window_size), repeat_count_(0) { }
654
655 // Handles storing message in compressor, retrieving the previous one and
656 // prefixing it with repeat count, if needed.
657 // Returns true if message needs to be written to log.
658 bool HandleMessage(LogMessageBuilder* msg) {
659 if (!msg->StoreInCompressor(&compressor_)) {
660 // Current message repeats the previous one, don't write it.
661 ++repeat_count_;
662 return false;
663 }
664 if (repeat_count_ == 0) {
665 return msg->RetrieveCompressedPrevious(&compressor_);
666 }
667 OS::SNPrintF(prefix_, "%s,%d,",
668 Logger::log_events_[Logger::REPEAT_META_EVENT],
669 repeat_count_ + 1);
670 repeat_count_ = 0;
671 return msg->RetrieveCompressedPrevious(&compressor_, prefix_.start());
672 }
673
674 private:
675 LogRecordCompressor compressor_;
676 int repeat_count_;
677 EmbeddedVector<char, 20> prefix_;
678};
679
680#endif // ENABLE_LOGGING_AND_PROFILING
681
682
Steve Blockd0582a62009-12-15 09:54:21 +0000683#ifdef ENABLE_LOGGING_AND_PROFILING
684void Logger::CallbackEventInternal(const char* prefix, const char* name,
685 Address entry_point) {
686 if (!Log::IsEnabled() || !FLAG_log_code) return;
687 LogMessageBuilder msg;
688 msg.Append("%s,%s,",
689 log_events_[CODE_CREATION_EVENT], log_events_[CALLBACK_TAG]);
690 msg.AppendAddress(entry_point);
691 msg.Append(",1,\"%s%s\"", prefix, name);
692 if (FLAG_compress_log) {
693 ASSERT(compression_helper_ != NULL);
694 if (!compression_helper_->HandleMessage(&msg)) return;
695 }
696 msg.Append('\n');
697 msg.WriteToLogFile();
698}
699#endif
700
701
702void Logger::CallbackEvent(String* name, Address entry_point) {
703#ifdef ENABLE_LOGGING_AND_PROFILING
704 if (!Log::IsEnabled() || !FLAG_log_code) return;
705 SmartPointer<char> str =
706 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
707 CallbackEventInternal("", *str, entry_point);
708#endif
709}
710
711
712void Logger::GetterCallbackEvent(String* name, Address entry_point) {
713#ifdef ENABLE_LOGGING_AND_PROFILING
714 if (!Log::IsEnabled() || !FLAG_log_code) return;
715 SmartPointer<char> str =
716 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
717 CallbackEventInternal("get ", *str, entry_point);
718#endif
719}
720
721
722void Logger::SetterCallbackEvent(String* name, Address entry_point) {
723#ifdef ENABLE_LOGGING_AND_PROFILING
724 if (!Log::IsEnabled() || !FLAG_log_code) return;
725 SmartPointer<char> str =
726 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
727 CallbackEventInternal("set ", *str, entry_point);
728#endif
729}
730
731
Steve Blocka7e24c12009-10-30 11:49:00 +0000732void Logger::CodeCreateEvent(LogEventsAndTags tag,
733 Code* code,
734 const char* comment) {
735#ifdef ENABLE_LOGGING_AND_PROFILING
736 if (!Log::IsEnabled() || !FLAG_log_code) return;
737 LogMessageBuilder msg;
738 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
739 msg.AppendAddress(code->address());
740 msg.Append(",%d,\"", code->ExecutableSize());
741 for (const char* p = comment; *p != '\0'; p++) {
742 if (*p == '"') {
743 msg.Append('\\');
744 }
745 msg.Append(*p);
746 }
747 msg.Append('"');
748 if (FLAG_compress_log) {
749 ASSERT(compression_helper_ != NULL);
750 if (!compression_helper_->HandleMessage(&msg)) return;
751 }
752 msg.Append('\n');
753 msg.WriteToLogFile();
754#endif
755}
756
757
758void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
759#ifdef ENABLE_LOGGING_AND_PROFILING
760 if (!Log::IsEnabled() || !FLAG_log_code) return;
761 LogMessageBuilder msg;
762 SmartPointer<char> str =
763 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
764 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
765 msg.AppendAddress(code->address());
766 msg.Append(",%d,\"%s\"", code->ExecutableSize(), *str);
767 if (FLAG_compress_log) {
768 ASSERT(compression_helper_ != NULL);
769 if (!compression_helper_->HandleMessage(&msg)) return;
770 }
771 msg.Append('\n');
772 msg.WriteToLogFile();
773#endif
774}
775
776
777void Logger::CodeCreateEvent(LogEventsAndTags tag,
778 Code* code, String* name,
779 String* source, int line) {
780#ifdef ENABLE_LOGGING_AND_PROFILING
781 if (!Log::IsEnabled() || !FLAG_log_code) return;
782 LogMessageBuilder msg;
783 SmartPointer<char> str =
784 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
785 SmartPointer<char> sourcestr =
786 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
787 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
788 msg.AppendAddress(code->address());
789 msg.Append(",%d,\"%s %s:%d\"",
790 code->ExecutableSize(), *str, *sourcestr, line);
791 if (FLAG_compress_log) {
792 ASSERT(compression_helper_ != NULL);
793 if (!compression_helper_->HandleMessage(&msg)) return;
794 }
795 msg.Append('\n');
796 msg.WriteToLogFile();
797#endif
798}
799
800
801void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
802#ifdef ENABLE_LOGGING_AND_PROFILING
803 if (!Log::IsEnabled() || !FLAG_log_code) return;
804 LogMessageBuilder msg;
805 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
806 msg.AppendAddress(code->address());
807 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
808 if (FLAG_compress_log) {
809 ASSERT(compression_helper_ != NULL);
810 if (!compression_helper_->HandleMessage(&msg)) return;
811 }
812 msg.Append('\n');
813 msg.WriteToLogFile();
814#endif
815}
816
817
818void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
819#ifdef ENABLE_LOGGING_AND_PROFILING
820 if (!Log::IsEnabled() || !FLAG_log_code) return;
821 LogMessageBuilder msg;
822 msg.Append("%s,%s,",
823 log_events_[CODE_CREATION_EVENT], log_events_[REG_EXP_TAG]);
824 msg.AppendAddress(code->address());
825 msg.Append(",%d,\"", code->ExecutableSize());
826 msg.AppendDetailed(source, false);
827 msg.Append('\"');
828 if (FLAG_compress_log) {
829 ASSERT(compression_helper_ != NULL);
830 if (!compression_helper_->HandleMessage(&msg)) return;
831 }
832 msg.Append('\n');
833 msg.WriteToLogFile();
834#endif
835}
836
837
838void Logger::CodeMoveEvent(Address from, Address to) {
839#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000840 MoveEventInternal(CODE_MOVE_EVENT, from, to);
Steve Blocka7e24c12009-10-30 11:49:00 +0000841#endif
842}
843
844
845void Logger::CodeDeleteEvent(Address from) {
846#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000847 DeleteEventInternal(CODE_DELETE_EVENT, from);
Steve Blocka7e24c12009-10-30 11:49:00 +0000848#endif
849}
850
851
Leon Clarkee46be812010-01-19 14:06:41 +0000852void Logger::SnapshotPositionEvent(Address addr, int pos) {
853#ifdef ENABLE_LOGGING_AND_PROFILING
854 if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return;
855 LogMessageBuilder msg;
856 msg.Append("%s,", log_events_[SNAPSHOT_POSITION_EVENT]);
857 msg.AppendAddress(addr);
858 msg.Append(",%d", pos);
859 if (FLAG_compress_log) {
860 ASSERT(compression_helper_ != NULL);
861 if (!compression_helper_->HandleMessage(&msg)) return;
862 }
863 msg.Append('\n');
864 msg.WriteToLogFile();
865#endif
866}
867
868
Leon Clarked91b9f72010-01-27 17:25:45 +0000869void Logger::FunctionCreateEvent(JSFunction* function) {
870#ifdef ENABLE_LOGGING_AND_PROFILING
871 static Address prev_code = NULL;
872 if (!Log::IsEnabled() || !FLAG_log_code) return;
873 LogMessageBuilder msg;
874 msg.Append("%s,", log_events_[FUNCTION_CREATION_EVENT]);
875 msg.AppendAddress(function->address());
876 msg.Append(',');
877 msg.AppendAddress(function->code()->address(), prev_code);
878 prev_code = function->code()->address();
879 if (FLAG_compress_log) {
880 ASSERT(compression_helper_ != NULL);
881 if (!compression_helper_->HandleMessage(&msg)) return;
882 }
883 msg.Append('\n');
884 msg.WriteToLogFile();
885#endif
886}
887
888
889void Logger::FunctionMoveEvent(Address from, Address to) {
890#ifdef ENABLE_LOGGING_AND_PROFILING
891 MoveEventInternal(FUNCTION_MOVE_EVENT, from, to);
892#endif
893}
894
895
896void Logger::FunctionDeleteEvent(Address from) {
897#ifdef ENABLE_LOGGING_AND_PROFILING
898 DeleteEventInternal(FUNCTION_DELETE_EVENT, from);
899#endif
900}
901
902
903#ifdef ENABLE_LOGGING_AND_PROFILING
904void Logger::MoveEventInternal(LogEventsAndTags event,
905 Address from,
906 Address to) {
907 static Address prev_to_ = NULL;
908 if (!Log::IsEnabled() || !FLAG_log_code) return;
909 LogMessageBuilder msg;
910 msg.Append("%s,", log_events_[event]);
911 msg.AppendAddress(from);
912 msg.Append(',');
913 msg.AppendAddress(to, prev_to_);
914 prev_to_ = to;
915 if (FLAG_compress_log) {
916 ASSERT(compression_helper_ != NULL);
917 if (!compression_helper_->HandleMessage(&msg)) return;
918 }
919 msg.Append('\n');
920 msg.WriteToLogFile();
921}
922#endif
923
924
925#ifdef ENABLE_LOGGING_AND_PROFILING
926void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
927 if (!Log::IsEnabled() || !FLAG_log_code) return;
928 LogMessageBuilder msg;
929 msg.Append("%s,", log_events_[event]);
930 msg.AppendAddress(from);
931 if (FLAG_compress_log) {
932 ASSERT(compression_helper_ != NULL);
933 if (!compression_helper_->HandleMessage(&msg)) return;
934 }
935 msg.Append('\n');
936 msg.WriteToLogFile();
937}
938#endif
939
940
Steve Blocka7e24c12009-10-30 11:49:00 +0000941void Logger::ResourceEvent(const char* name, const char* tag) {
942#ifdef ENABLE_LOGGING_AND_PROFILING
943 if (!Log::IsEnabled() || !FLAG_log) return;
944 LogMessageBuilder msg;
945 msg.Append("%s,%s,", name, tag);
946
947 uint32_t sec, usec;
948 if (OS::GetUserTime(&sec, &usec) != -1) {
949 msg.Append("%d,%d,", sec, usec);
950 }
951 msg.Append("%.0f", OS::TimeCurrentMillis());
952
953 msg.Append('\n');
954 msg.WriteToLogFile();
955#endif
956}
957
958
959void Logger::SuspectReadEvent(String* name, Object* obj) {
960#ifdef ENABLE_LOGGING_AND_PROFILING
961 if (!Log::IsEnabled() || !FLAG_log_suspect) return;
962 LogMessageBuilder msg;
963 String* class_name = obj->IsJSObject()
964 ? JSObject::cast(obj)->class_name()
965 : Heap::empty_string();
966 msg.Append("suspect-read,");
967 msg.Append(class_name);
968 msg.Append(',');
969 msg.Append('"');
970 msg.Append(name);
971 msg.Append('"');
972 msg.Append('\n');
973 msg.WriteToLogFile();
974#endif
975}
976
977
978void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
979#ifdef ENABLE_LOGGING_AND_PROFILING
980 if (!Log::IsEnabled() || !FLAG_log_gc) return;
981 LogMessageBuilder msg;
982 // Using non-relative system time in order to be able to synchronize with
983 // external memory profiling events (e.g. DOM memory size).
984 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
985 space, kind, OS::TimeCurrentMillis());
986 msg.WriteToLogFile();
987#endif
988}
989
990
991void Logger::HeapSampleStats(const char* space, const char* kind,
992 int capacity, int used) {
993#ifdef ENABLE_LOGGING_AND_PROFILING
994 if (!Log::IsEnabled() || !FLAG_log_gc) return;
995 LogMessageBuilder msg;
996 msg.Append("heap-sample-stats,\"%s\",\"%s\",%d,%d\n",
997 space, kind, capacity, used);
998 msg.WriteToLogFile();
999#endif
1000}
1001
1002
1003void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1004#ifdef ENABLE_LOGGING_AND_PROFILING
1005 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1006 LogMessageBuilder msg;
1007 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1008 msg.WriteToLogFile();
1009#endif
1010}
1011
1012
1013void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1014#ifdef ENABLE_LOGGING_AND_PROFILING
1015 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1016 LogMessageBuilder msg;
1017 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1018 msg.WriteToLogFile();
1019#endif
1020}
1021
1022
1023void Logger::HeapSampleJSConstructorEvent(const char* constructor,
1024 int number, int bytes) {
1025#ifdef ENABLE_LOGGING_AND_PROFILING
1026 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1027 LogMessageBuilder msg;
1028 msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
1029 msg.WriteToLogFile();
1030#endif
1031}
1032
1033
1034void Logger::HeapSampleJSRetainersEvent(
1035 const char* constructor, const char* event) {
1036#ifdef ENABLE_LOGGING_AND_PROFILING
1037 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1038 // Event starts with comma, so we don't have it in the format string.
1039 static const char* event_text = "heap-js-ret-item,%s";
1040 // We take placeholder strings into account, but it's OK to be conservative.
Steve Blockd0582a62009-12-15 09:54:21 +00001041 static const int event_text_len = StrLength(event_text);
1042 const int cons_len = StrLength(constructor);
1043 const int event_len = StrLength(event);
Steve Blocka7e24c12009-10-30 11:49:00 +00001044 int pos = 0;
1045 // Retainer lists can be long. We may need to split them into multiple events.
1046 do {
1047 LogMessageBuilder msg;
1048 msg.Append(event_text, constructor);
1049 int to_write = event_len - pos;
1050 if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) {
1051 int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len);
1052 ASSERT(cut_pos < event_len);
1053 while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
1054 if (event[cut_pos] != ',') {
1055 // Crash in debug mode, skip in release mode.
1056 ASSERT(false);
1057 return;
1058 }
1059 // Append a piece of event that fits, without trailing comma.
1060 msg.AppendStringPart(event + pos, cut_pos - pos);
1061 // Start next piece with comma.
1062 pos = cut_pos;
1063 } else {
1064 msg.Append("%s", event + pos);
1065 pos += event_len;
1066 }
1067 msg.Append('\n');
1068 msg.WriteToLogFile();
1069 } while (pos < event_len);
1070#endif
1071}
1072
1073
Steve Block3ce2e202009-11-05 08:53:23 +00001074void Logger::HeapSampleJSProducerEvent(const char* constructor,
1075 Address* stack) {
1076#ifdef ENABLE_LOGGING_AND_PROFILING
1077 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1078 LogMessageBuilder msg;
1079 msg.Append("heap-js-prod-item,%s", constructor);
1080 while (*stack != NULL) {
1081 msg.Append(",0x%" V8PRIxPTR, *stack++);
1082 }
1083 msg.Append("\n");
1084 msg.WriteToLogFile();
1085#endif
1086}
1087
1088
Steve Blocka7e24c12009-10-30 11:49:00 +00001089void Logger::DebugTag(const char* call_site_tag) {
1090#ifdef ENABLE_LOGGING_AND_PROFILING
1091 if (!Log::IsEnabled() || !FLAG_log) return;
1092 LogMessageBuilder msg;
1093 msg.Append("debug-tag,%s\n", call_site_tag);
1094 msg.WriteToLogFile();
1095#endif
1096}
1097
1098
1099void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1100#ifdef ENABLE_LOGGING_AND_PROFILING
1101 if (!Log::IsEnabled() || !FLAG_log) return;
1102 StringBuilder s(parameter.length() + 1);
1103 for (int i = 0; i < parameter.length(); ++i) {
1104 s.AddCharacter(static_cast<char>(parameter[i]));
1105 }
1106 char* parameter_string = s.Finalize();
1107 LogMessageBuilder msg;
1108 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1109 event_type,
1110 OS::TimeCurrentMillis(),
1111 parameter_string);
1112 DeleteArray(parameter_string);
1113 msg.WriteToLogFile();
1114#endif
1115}
1116
1117
1118#ifdef ENABLE_LOGGING_AND_PROFILING
1119void Logger::TickEvent(TickSample* sample, bool overflow) {
1120 if (!Log::IsEnabled() || !FLAG_prof) return;
1121 static Address prev_sp = NULL;
Leon Clarked91b9f72010-01-27 17:25:45 +00001122 static Address prev_function = NULL;
Steve Blocka7e24c12009-10-30 11:49:00 +00001123 LogMessageBuilder msg;
1124 msg.Append("%s,", log_events_[TICK_EVENT]);
Leon Clarked91b9f72010-01-27 17:25:45 +00001125 Address prev_addr = sample->pc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001126 msg.AppendAddress(prev_addr);
1127 msg.Append(',');
Leon Clarked91b9f72010-01-27 17:25:45 +00001128 msg.AppendAddress(sample->sp, prev_sp);
1129 prev_sp = sample->sp;
1130 msg.Append(',');
1131 msg.AppendAddress(sample->function, prev_function);
1132 prev_function = sample->function;
Steve Blocka7e24c12009-10-30 11:49:00 +00001133 msg.Append(",%d", static_cast<int>(sample->state));
1134 if (overflow) {
1135 msg.Append(",overflow");
1136 }
1137 for (int i = 0; i < sample->frames_count; ++i) {
1138 msg.Append(',');
1139 msg.AppendAddress(sample->stack[i], prev_addr);
1140 prev_addr = sample->stack[i];
1141 }
1142 if (FLAG_compress_log) {
1143 ASSERT(compression_helper_ != NULL);
1144 if (!compression_helper_->HandleMessage(&msg)) return;
1145 }
1146 msg.Append('\n');
1147 msg.WriteToLogFile();
1148}
1149
1150
1151int Logger::GetActiveProfilerModules() {
1152 int result = PROFILER_MODULE_NONE;
1153 if (!profiler_->paused()) {
1154 result |= PROFILER_MODULE_CPU;
1155 }
1156 if (FLAG_log_gc) {
1157 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1158 }
1159 return result;
1160}
1161
1162
Andrei Popescu402d9372010-02-26 13:31:12 +00001163void Logger::PauseProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001164 if (!Log::IsEnabled()) return;
Andrei Popescu402d9372010-02-26 13:31:12 +00001165 if (flags & PROFILER_MODULE_CPU) {
1166 // It is OK to have negative nesting.
1167 if (--cpu_profiler_nesting_ == 0) {
1168 profiler_->pause();
1169 if (FLAG_prof_lazy) {
1170 if (!FLAG_sliding_state_window) ticker_->Stop();
1171 FLAG_log_code = false;
1172 // Must be the same message as Log::kDynamicBufferSeal.
1173 LOG(UncheckedStringEvent("profiler", "pause"));
1174 }
Steve Block6ded16b2010-05-10 14:33:55 +01001175 --logging_nesting_;
Steve Blocka7e24c12009-10-30 11:49:00 +00001176 }
1177 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001178 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001179 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001180 if (--heap_profiler_nesting_ == 0) {
1181 FLAG_log_gc = false;
Steve Block6ded16b2010-05-10 14:33:55 +01001182 --logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001183 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001184 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001185 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001186 UncheckedIntEvent("close-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001187 }
1188}
1189
1190
Andrei Popescu402d9372010-02-26 13:31:12 +00001191void Logger::ResumeProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001192 if (!Log::IsEnabled()) return;
Andrei Popescu402d9372010-02-26 13:31:12 +00001193 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001194 UncheckedIntEvent("open-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001195 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001196 if (flags & PROFILER_MODULE_CPU) {
1197 if (cpu_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001198 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001199 if (FLAG_prof_lazy) {
1200 profiler_->Engage();
1201 LOG(UncheckedStringEvent("profiler", "resume"));
1202 FLAG_log_code = true;
1203 LogCompiledFunctions();
1204 LogFunctionObjects();
1205 LogAccessorCallbacks();
1206 if (!FLAG_sliding_state_window) ticker_->Start();
1207 }
1208 profiler_->resume();
Steve Blocka7e24c12009-10-30 11:49:00 +00001209 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001210 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001211 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001212 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001213 if (heap_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001214 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001215 FLAG_log_gc = true;
1216 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001217 }
1218}
1219
1220
1221// This function can be called when Log's mutex is acquired,
1222// either from main or Profiler's thread.
1223void Logger::StopLoggingAndProfiling() {
1224 Log::stop();
Andrei Popescu402d9372010-02-26 13:31:12 +00001225 PauseProfiler(PROFILER_MODULE_CPU, 0);
Steve Blocka7e24c12009-10-30 11:49:00 +00001226}
1227
1228
1229bool Logger::IsProfilerSamplerActive() {
1230 return ticker_->IsActive();
1231}
1232
1233
1234int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1235 return Log::GetLogLines(from_pos, dest_buf, max_size);
1236}
1237
1238
Steve Block3ce2e202009-11-05 08:53:23 +00001239static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis) {
1240 AssertNoAllocation no_alloc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001241 int compiled_funcs_count = 0;
Steve Block3ce2e202009-11-05 08:53:23 +00001242 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001243 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Block3ce2e202009-11-05 08:53:23 +00001244 if (!obj->IsSharedFunctionInfo()) continue;
1245 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1246 if (sfi->is_compiled()
1247 && (!sfi->script()->IsScript()
1248 || Script::cast(sfi->script())->HasValidSource())) {
1249 if (sfis != NULL)
1250 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1251 ++compiled_funcs_count;
Steve Blocka7e24c12009-10-30 11:49:00 +00001252 }
1253 }
Steve Block3ce2e202009-11-05 08:53:23 +00001254 return compiled_funcs_count;
1255}
1256
1257
Steve Blockd0582a62009-12-15 09:54:21 +00001258void Logger::LogCodeObject(Object* object) {
1259 if (FLAG_log_code) {
1260 Code* code_object = Code::cast(object);
1261 LogEventsAndTags tag = Logger::STUB_TAG;
1262 const char* description = "Unknown code from the snapshot";
1263 switch (code_object->kind()) {
1264 case Code::FUNCTION:
1265 return; // We log this later using LogCompiledFunctions.
Steve Block6ded16b2010-05-10 14:33:55 +01001266 case Code::BINARY_OP_IC:
1267 // fall through
Steve Blockd0582a62009-12-15 09:54:21 +00001268 case Code::STUB:
Andrei Popescu31002712010-02-23 13:46:05 +00001269 description = CodeStub::MajorName(code_object->major_key(), true);
1270 if (description == NULL)
1271 description = "A stub from the snapshot";
Steve Blockd0582a62009-12-15 09:54:21 +00001272 tag = Logger::STUB_TAG;
1273 break;
1274 case Code::BUILTIN:
1275 description = "A builtin from the snapshot";
1276 tag = Logger::BUILTIN_TAG;
1277 break;
1278 case Code::KEYED_LOAD_IC:
1279 description = "A keyed load IC from the snapshot";
1280 tag = Logger::KEYED_LOAD_IC_TAG;
1281 break;
1282 case Code::LOAD_IC:
1283 description = "A load IC from the snapshot";
1284 tag = Logger::LOAD_IC_TAG;
1285 break;
1286 case Code::STORE_IC:
1287 description = "A store IC from the snapshot";
1288 tag = Logger::STORE_IC_TAG;
1289 break;
1290 case Code::KEYED_STORE_IC:
1291 description = "A keyed store IC from the snapshot";
1292 tag = Logger::KEYED_STORE_IC_TAG;
1293 break;
1294 case Code::CALL_IC:
1295 description = "A call IC from the snapshot";
1296 tag = Logger::CALL_IC_TAG;
1297 break;
1298 }
Steve Block6ded16b2010-05-10 14:33:55 +01001299 PROFILE(CodeCreateEvent(tag, code_object, description));
Steve Blockd0582a62009-12-15 09:54:21 +00001300 }
1301}
1302
1303
Andrei Popescu31002712010-02-23 13:46:05 +00001304void Logger::LogCodeObjects() {
1305 AssertNoAllocation no_alloc;
1306 HeapIterator iterator;
1307 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1308 if (obj->IsCode()) LogCodeObject(obj);
1309 }
1310}
1311
1312
Steve Block3ce2e202009-11-05 08:53:23 +00001313void Logger::LogCompiledFunctions() {
1314 HandleScope scope;
1315 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL);
1316 Handle<SharedFunctionInfo>* sfis =
1317 NewArray< Handle<SharedFunctionInfo> >(compiled_funcs_count);
1318 EnumerateCompiledFunctions(sfis);
Steve Blocka7e24c12009-10-30 11:49:00 +00001319
1320 // During iteration, there can be heap allocation due to
1321 // GetScriptLineNumber call.
1322 for (int i = 0; i < compiled_funcs_count; ++i) {
1323 Handle<SharedFunctionInfo> shared = sfis[i];
1324 Handle<String> name(String::cast(shared->name()));
1325 Handle<String> func_name(name->length() > 0 ?
1326 *name : shared->inferred_name());
1327 if (shared->script()->IsScript()) {
1328 Handle<Script> script(Script::cast(shared->script()));
1329 if (script->name()->IsString()) {
1330 Handle<String> script_name(String::cast(script->name()));
1331 int line_num = GetScriptLineNumber(script, shared->start_position());
1332 if (line_num > 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001333 PROFILE(CodeCreateEvent(
1334 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1335 shared->code(), *func_name,
1336 *script_name, line_num + 1));
Steve Blocka7e24c12009-10-30 11:49:00 +00001337 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001338 // Can't distinguish eval and script here, so always use Script.
1339 PROFILE(CodeCreateEvent(
1340 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1341 shared->code(), *script_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001342 }
Steve Blockd0582a62009-12-15 09:54:21 +00001343 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001344 PROFILE(CodeCreateEvent(
1345 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1346 shared->code(), *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001347 }
Steve Block6ded16b2010-05-10 14:33:55 +01001348 } else if (shared->IsApiFunction()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001349 // API function.
Steve Block6ded16b2010-05-10 14:33:55 +01001350 FunctionTemplateInfo* fun_data = shared->get_api_func_data();
Steve Blockd0582a62009-12-15 09:54:21 +00001351 Object* raw_call_data = fun_data->call_code();
1352 if (!raw_call_data->IsUndefined()) {
1353 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1354 Object* callback_obj = call_data->callback();
1355 Address entry_point = v8::ToCData<Address>(callback_obj);
Steve Block6ded16b2010-05-10 14:33:55 +01001356 PROFILE(CallbackEvent(*func_name, entry_point));
Steve Blockd0582a62009-12-15 09:54:21 +00001357 }
1358 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001359 PROFILE(CodeCreateEvent(
Steve Blockd0582a62009-12-15 09:54:21 +00001360 Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001361 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001362 }
1363
1364 DeleteArray(sfis);
1365}
1366
Steve Blockd0582a62009-12-15 09:54:21 +00001367
Leon Clarked91b9f72010-01-27 17:25:45 +00001368void Logger::LogFunctionObjects() {
1369 AssertNoAllocation no_alloc;
1370 HeapIterator iterator;
1371 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1372 if (!obj->IsJSFunction()) continue;
1373 JSFunction* jsf = JSFunction::cast(obj);
1374 if (!jsf->is_compiled()) continue;
Steve Block6ded16b2010-05-10 14:33:55 +01001375 PROFILE(FunctionCreateEvent(jsf));
Leon Clarked91b9f72010-01-27 17:25:45 +00001376 }
1377}
1378
1379
Steve Blockd0582a62009-12-15 09:54:21 +00001380void Logger::LogAccessorCallbacks() {
1381 AssertNoAllocation no_alloc;
1382 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001383 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001384 if (!obj->IsAccessorInfo()) continue;
1385 AccessorInfo* ai = AccessorInfo::cast(obj);
1386 if (!ai->name()->IsString()) continue;
1387 String* name = String::cast(ai->name());
1388 Address getter_entry = v8::ToCData<Address>(ai->getter());
1389 if (getter_entry != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001390 PROFILE(GetterCallbackEvent(name, getter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001391 }
1392 Address setter_entry = v8::ToCData<Address>(ai->setter());
1393 if (setter_entry != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001394 PROFILE(SetterCallbackEvent(name, setter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001395 }
1396 }
1397}
1398
Steve Blocka7e24c12009-10-30 11:49:00 +00001399#endif
1400
1401
1402bool Logger::Setup() {
1403#ifdef ENABLE_LOGGING_AND_PROFILING
1404 // --log-all enables all the log flags.
1405 if (FLAG_log_all) {
1406 FLAG_log_runtime = true;
1407 FLAG_log_api = true;
1408 FLAG_log_code = true;
1409 FLAG_log_gc = true;
1410 FLAG_log_suspect = true;
1411 FLAG_log_handles = true;
1412 FLAG_log_regexp = true;
1413 }
1414
1415 // --prof implies --log-code.
1416 if (FLAG_prof) FLAG_log_code = true;
1417
1418 // --prof_lazy controls --log-code, implies --noprof_auto.
1419 if (FLAG_prof_lazy) {
1420 FLAG_log_code = false;
1421 FLAG_prof_auto = false;
1422 }
1423
1424 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1425 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1426 || FLAG_log_regexp || FLAG_log_state_changes;
1427
1428 bool open_log_file = start_logging || FLAG_prof_lazy;
1429
1430 // If we're logging anything, we need to open the log file.
1431 if (open_log_file) {
1432 if (strcmp(FLAG_logfile, "-") == 0) {
1433 Log::OpenStdout();
1434 } else if (strcmp(FLAG_logfile, "*") == 0) {
1435 Log::OpenMemoryBuffer();
1436 } else if (strchr(FLAG_logfile, '%') != NULL) {
1437 // If there's a '%' in the log file name we have to expand
1438 // placeholders.
1439 HeapStringAllocator allocator;
1440 StringStream stream(&allocator);
1441 for (const char* p = FLAG_logfile; *p; p++) {
1442 if (*p == '%') {
1443 p++;
1444 switch (*p) {
1445 case '\0':
1446 // If there's a % at the end of the string we back up
1447 // one character so we can escape the loop properly.
1448 p--;
1449 break;
1450 case 't': {
1451 // %t expands to the current time in milliseconds.
1452 double time = OS::TimeCurrentMillis();
1453 stream.Add("%.0f", FmtElm(time));
1454 break;
1455 }
1456 case '%':
1457 // %% expands (contracts really) to %.
1458 stream.Put('%');
1459 break;
1460 default:
1461 // All other %'s expand to themselves.
1462 stream.Put('%');
1463 stream.Put(*p);
1464 break;
1465 }
1466 } else {
1467 stream.Put(*p);
1468 }
1469 }
1470 SmartPointer<const char> expanded = stream.ToCString();
1471 Log::OpenFile(*expanded);
1472 } else {
1473 Log::OpenFile(FLAG_logfile);
1474 }
1475 }
1476
Steve Block6ded16b2010-05-10 14:33:55 +01001477 ASSERT(VMState::is_outermost_external());
Steve Blocka7e24c12009-10-30 11:49:00 +00001478
1479 ticker_ = new Ticker(kSamplingIntervalMs);
1480
1481 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1482 sliding_state_window_ = new SlidingStateWindow();
1483 }
1484
1485 log_events_ = FLAG_compress_log ?
1486 kCompressedLogEventsNames : kLongLogEventsNames;
1487 if (FLAG_compress_log) {
1488 compression_helper_ = new CompressionHelper(kCompressionWindowSize);
1489 }
1490
Steve Block6ded16b2010-05-10 14:33:55 +01001491 if (start_logging) {
1492 logging_nesting_ = 1;
1493 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001494
1495 if (FLAG_prof) {
1496 profiler_ = new Profiler();
1497 if (!FLAG_prof_auto) {
1498 profiler_->pause();
1499 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001500 logging_nesting_ = 1;
Steve Blocka7e24c12009-10-30 11:49:00 +00001501 }
Steve Blockd0582a62009-12-15 09:54:21 +00001502 if (!FLAG_prof_lazy) {
1503 profiler_->Engage();
1504 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001505 }
1506
1507 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
1508
1509 return true;
1510
1511#else
1512 return false;
1513#endif
1514}
1515
1516
1517void Logger::TearDown() {
1518#ifdef ENABLE_LOGGING_AND_PROFILING
1519 LogMessageBuilder::set_write_failure_handler(NULL);
1520
1521 // Stop the profiler before closing the file.
1522 if (profiler_ != NULL) {
1523 profiler_->Disengage();
1524 delete profiler_;
1525 profiler_ = NULL;
1526 }
1527
1528 delete compression_helper_;
1529 compression_helper_ = NULL;
1530
1531 delete sliding_state_window_;
1532 sliding_state_window_ = NULL;
1533
1534 delete ticker_;
1535 ticker_ = NULL;
1536
1537 Log::Close();
1538#endif
1539}
1540
1541
1542void Logger::EnableSlidingStateWindow() {
1543#ifdef ENABLE_LOGGING_AND_PROFILING
1544 // If the ticker is NULL, Logger::Setup has not been called yet. In
1545 // that case, we set the sliding_state_window flag so that the
1546 // sliding window computation will be started when Logger::Setup is
1547 // called.
1548 if (ticker_ == NULL) {
1549 FLAG_sliding_state_window = true;
1550 return;
1551 }
1552 // Otherwise, if the sliding state window computation has not been
1553 // started we do it now.
1554 if (sliding_state_window_ == NULL) {
1555 sliding_state_window_ = new SlidingStateWindow();
1556 }
1557#endif
1558}
1559
Steve Blocka7e24c12009-10-30 11:49:00 +00001560} } // namespace v8::internal