blob: 5c700576c8042c640d5f9f425ad0101cc42176e0 [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
194 void SampleStack(TickSample* sample) {
195 StackTracer::Trace(sample);
196 }
197
198 void Tick(TickSample* sample) {
199 if (profiler_) profiler_->Insert(sample);
200 if (window_) window_->AddState(sample->state);
201 }
202
203 void SetWindow(SlidingStateWindow* window) {
204 window_ = window;
205 if (!IsActive()) Start();
206 }
207
208 void ClearWindow() {
209 window_ = NULL;
210 if (!profiler_ && IsActive()) Stop();
211 }
212
213 void SetProfiler(Profiler* profiler) {
214 profiler_ = profiler;
215 if (!FLAG_prof_lazy && !IsActive()) Start();
216 }
217
218 void ClearProfiler() {
219 profiler_ = NULL;
220 if (!window_ && IsActive()) Stop();
221 }
222
223 private:
224 SlidingStateWindow* window_;
225 Profiler* profiler_;
226};
227
228
229//
230// SlidingStateWindow implementation.
231//
232SlidingStateWindow::SlidingStateWindow(): current_index_(0), is_full_(false) {
233 for (int i = 0; i < kBufferSize; i++) {
234 buffer_[i] = static_cast<byte>(OTHER);
235 }
236 Logger::ticker_->SetWindow(this);
237}
238
239
240SlidingStateWindow::~SlidingStateWindow() {
241 Logger::ticker_->ClearWindow();
242}
243
244
245void SlidingStateWindow::AddState(StateTag state) {
246 if (is_full_) {
247 DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
248 } else if (current_index_ == kBufferSize - 1) {
249 is_full_ = true;
250 }
251 buffer_[current_index_] = static_cast<byte>(state);
252 IncrementStateCounter(state);
253 ASSERT(IsPowerOf2(kBufferSize));
254 current_index_ = (current_index_ + 1) & (kBufferSize - 1);
255}
256
257
258//
259// Profiler implementation.
260//
Steve Blockd0582a62009-12-15 09:54:21 +0000261Profiler::Profiler()
262 : head_(0),
263 tail_(0),
264 overflow_(false),
265 buffer_semaphore_(OS::CreateSemaphore(0)),
266 engaged_(false),
267 running_(false) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000268}
269
270
271void Profiler::Engage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000272 if (engaged_) return;
273 engaged_ = true;
274
275 // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
276 // http://code.google.com/p/v8/issues/detail?id=487
277 if (!FLAG_prof_lazy) {
278 OS::LogSharedLibraryAddresses();
279 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000280
281 // Start thread processing the profiler buffer.
282 running_ = true;
283 Start();
284
285 // Register to get ticks.
286 Logger::ticker_->SetProfiler(this);
287
288 Logger::ProfilerBeginEvent();
289 Logger::LogAliases();
290}
291
292
293void Profiler::Disengage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000294 if (!engaged_) return;
295
Steve Blocka7e24c12009-10-30 11:49:00 +0000296 // Stop receiving ticks.
297 Logger::ticker_->ClearProfiler();
298
299 // Terminate the worker thread by setting running_ to false,
300 // inserting a fake element in the queue and then wait for
301 // the thread to terminate.
302 running_ = false;
303 TickSample sample;
304 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
305 resume();
306 Insert(&sample);
307 Join();
308
309 LOG(UncheckedStringEvent("profiler", "end"));
310}
311
312
313void Profiler::Run() {
314 TickSample sample;
Steve Block8defd9f2010-07-08 12:39:36 +0100315 bool overflow = Remove(&sample);
Steve Blocka7e24c12009-10-30 11:49:00 +0000316 while (running_) {
317 LOG(TickEvent(&sample, overflow));
Steve Block8defd9f2010-07-08 12:39:36 +0100318 overflow = Remove(&sample);
Steve Blocka7e24c12009-10-30 11:49:00 +0000319 }
320}
321
322
323//
324// Logger class implementation.
325//
326Ticker* Logger::ticker_ = NULL;
327Profiler* Logger::profiler_ = NULL;
Steve Blocka7e24c12009-10-30 11:49:00 +0000328SlidingStateWindow* Logger::sliding_state_window_ = NULL;
329const char** Logger::log_events_ = NULL;
330CompressionHelper* Logger::compression_helper_ = NULL;
Steve Block6ded16b2010-05-10 14:33:55 +0100331int Logger::logging_nesting_ = 0;
Andrei Popescu402d9372010-02-26 13:31:12 +0000332int Logger::cpu_profiler_nesting_ = 0;
333int Logger::heap_profiler_nesting_ = 0;
Steve Blocka7e24c12009-10-30 11:49:00 +0000334
335#define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name,
336const char* kLongLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
337 LOG_EVENTS_AND_TAGS_LIST(DECLARE_LONG_EVENT)
338};
339#undef DECLARE_LONG_EVENT
340
341#define DECLARE_SHORT_EVENT(ignore1, ignore2, short_name) short_name,
342const char* kCompressedLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
343 LOG_EVENTS_AND_TAGS_LIST(DECLARE_SHORT_EVENT)
344};
345#undef DECLARE_SHORT_EVENT
346
347
348void Logger::ProfilerBeginEvent() {
349 if (!Log::IsEnabled()) return;
350 LogMessageBuilder msg;
351 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
352 if (FLAG_compress_log) {
353 msg.Append("profiler,\"compression\",%d\n", kCompressionWindowSize);
354 }
355 msg.WriteToLogFile();
356}
357
358
359void Logger::LogAliases() {
360 if (!Log::IsEnabled() || !FLAG_compress_log) return;
361 LogMessageBuilder msg;
362 for (int i = 0; i < NUMBER_OF_LOG_EVENTS; ++i) {
363 msg.Append("alias,%s,%s\n",
364 kCompressedLogEventsNames[i], kLongLogEventsNames[i]);
365 }
366 msg.WriteToLogFile();
367}
368
369#endif // ENABLE_LOGGING_AND_PROFILING
370
371
Steve Blocka7e24c12009-10-30 11:49:00 +0000372void Logger::StringEvent(const char* name, const char* value) {
373#ifdef ENABLE_LOGGING_AND_PROFILING
374 if (FLAG_log) UncheckedStringEvent(name, value);
375#endif
376}
377
378
379#ifdef ENABLE_LOGGING_AND_PROFILING
380void Logger::UncheckedStringEvent(const char* name, const char* value) {
381 if (!Log::IsEnabled()) return;
382 LogMessageBuilder msg;
383 msg.Append("%s,\"%s\"\n", name, value);
384 msg.WriteToLogFile();
385}
386#endif
387
388
389void Logger::IntEvent(const char* name, int value) {
390#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block6ded16b2010-05-10 14:33:55 +0100391 if (FLAG_log) UncheckedIntEvent(name, value);
392#endif
393}
394
395
396#ifdef ENABLE_LOGGING_AND_PROFILING
397void Logger::UncheckedIntEvent(const char* name, int value) {
398 if (!Log::IsEnabled()) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000399 LogMessageBuilder msg;
400 msg.Append("%s,%d\n", name, value);
401 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000402}
Steve Block6ded16b2010-05-10 14:33:55 +0100403#endif
Steve Blocka7e24c12009-10-30 11:49:00 +0000404
405
406void Logger::HandleEvent(const char* name, Object** location) {
407#ifdef ENABLE_LOGGING_AND_PROFILING
408 if (!Log::IsEnabled() || !FLAG_log_handles) return;
409 LogMessageBuilder msg;
410 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
411 msg.WriteToLogFile();
412#endif
413}
414
415
416#ifdef ENABLE_LOGGING_AND_PROFILING
417// ApiEvent is private so all the calls come from the Logger class. It is the
418// caller's responsibility to ensure that log is enabled and that
419// FLAG_log_api is true.
420void Logger::ApiEvent(const char* format, ...) {
421 ASSERT(Log::IsEnabled() && FLAG_log_api);
422 LogMessageBuilder msg;
423 va_list ap;
424 va_start(ap, format);
425 msg.AppendVA(format, ap);
426 va_end(ap);
427 msg.WriteToLogFile();
428}
429#endif
430
431
432void Logger::ApiNamedSecurityCheck(Object* key) {
433#ifdef ENABLE_LOGGING_AND_PROFILING
434 if (!Log::IsEnabled() || !FLAG_log_api) return;
435 if (key->IsString()) {
436 SmartPointer<char> str =
437 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
438 ApiEvent("api,check-security,\"%s\"\n", *str);
439 } else if (key->IsUndefined()) {
440 ApiEvent("api,check-security,undefined\n");
441 } else {
442 ApiEvent("api,check-security,['no-name']\n");
443 }
444#endif
445}
446
447
448void Logger::SharedLibraryEvent(const char* library_path,
449 uintptr_t start,
450 uintptr_t end) {
451#ifdef ENABLE_LOGGING_AND_PROFILING
452 if (!Log::IsEnabled() || !FLAG_prof) return;
453 LogMessageBuilder msg;
454 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
455 library_path,
456 start,
457 end);
458 msg.WriteToLogFile();
459#endif
460}
461
462
463void Logger::SharedLibraryEvent(const wchar_t* library_path,
464 uintptr_t start,
465 uintptr_t end) {
466#ifdef ENABLE_LOGGING_AND_PROFILING
467 if (!Log::IsEnabled() || !FLAG_prof) return;
468 LogMessageBuilder msg;
469 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
470 library_path,
471 start,
472 end);
473 msg.WriteToLogFile();
474#endif
475}
476
477
478#ifdef ENABLE_LOGGING_AND_PROFILING
479void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
480 // Prints "/" + re.source + "/" +
481 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
482 LogMessageBuilder msg;
483
484 Handle<Object> source = GetProperty(regexp, "source");
485 if (!source->IsString()) {
486 msg.Append("no source");
487 return;
488 }
489
490 switch (regexp->TypeTag()) {
491 case JSRegExp::ATOM:
492 msg.Append('a');
493 break;
494 default:
495 break;
496 }
497 msg.Append('/');
498 msg.AppendDetailed(*Handle<String>::cast(source), false);
499 msg.Append('/');
500
501 // global flag
502 Handle<Object> global = GetProperty(regexp, "global");
503 if (global->IsTrue()) {
504 msg.Append('g');
505 }
506 // ignorecase flag
507 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
508 if (ignorecase->IsTrue()) {
509 msg.Append('i');
510 }
511 // multiline flag
512 Handle<Object> multiline = GetProperty(regexp, "multiline");
513 if (multiline->IsTrue()) {
514 msg.Append('m');
515 }
516
517 msg.WriteToLogFile();
518}
519#endif // ENABLE_LOGGING_AND_PROFILING
520
521
522void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
523#ifdef ENABLE_LOGGING_AND_PROFILING
524 if (!Log::IsEnabled() || !FLAG_log_regexp) return;
525 LogMessageBuilder msg;
526 msg.Append("regexp-compile,");
527 LogRegExpSource(regexp);
528 msg.Append(in_cache ? ",hit\n" : ",miss\n");
529 msg.WriteToLogFile();
530#endif
531}
532
533
534void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
535#ifdef ENABLE_LOGGING_AND_PROFILING
536 if (!Log::IsEnabled() || !FLAG_log_runtime) return;
537 HandleScope scope;
538 LogMessageBuilder msg;
539 for (int i = 0; i < format.length(); i++) {
540 char c = format[i];
541 if (c == '%' && i <= format.length() - 2) {
542 i++;
543 ASSERT('0' <= format[i] && format[i] <= '9');
544 Object* obj = args->GetElement(format[i] - '0');
545 i++;
546 switch (format[i]) {
547 case 's':
548 msg.AppendDetailed(String::cast(obj), false);
549 break;
550 case 'S':
551 msg.AppendDetailed(String::cast(obj), true);
552 break;
553 case 'r':
554 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
555 break;
556 case 'x':
557 msg.Append("0x%x", Smi::cast(obj)->value());
558 break;
559 case 'i':
560 msg.Append("%i", Smi::cast(obj)->value());
561 break;
562 default:
563 UNREACHABLE();
564 }
565 } else {
566 msg.Append(c);
567 }
568 }
569 msg.Append('\n');
570 msg.WriteToLogFile();
571#endif
572}
573
574
575void Logger::ApiIndexedSecurityCheck(uint32_t index) {
576#ifdef ENABLE_LOGGING_AND_PROFILING
577 if (!Log::IsEnabled() || !FLAG_log_api) return;
578 ApiEvent("api,check-security,%u\n", index);
579#endif
580}
581
582
583void Logger::ApiNamedPropertyAccess(const char* tag,
584 JSObject* holder,
585 Object* name) {
586#ifdef ENABLE_LOGGING_AND_PROFILING
587 ASSERT(name->IsString());
588 if (!Log::IsEnabled() || !FLAG_log_api) return;
589 String* class_name_obj = holder->class_name();
590 SmartPointer<char> class_name =
591 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
592 SmartPointer<char> property_name =
593 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
594 Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
595#endif
596}
597
598void Logger::ApiIndexedPropertyAccess(const char* tag,
599 JSObject* holder,
600 uint32_t index) {
601#ifdef ENABLE_LOGGING_AND_PROFILING
602 if (!Log::IsEnabled() || !FLAG_log_api) return;
603 String* class_name_obj = holder->class_name();
604 SmartPointer<char> class_name =
605 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
606 Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
607#endif
608}
609
610void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
611#ifdef ENABLE_LOGGING_AND_PROFILING
612 if (!Log::IsEnabled() || !FLAG_log_api) return;
613 String* class_name_obj = object->class_name();
614 SmartPointer<char> class_name =
615 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
616 Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
617#endif
618}
619
620
621void Logger::ApiEntryCall(const char* name) {
622#ifdef ENABLE_LOGGING_AND_PROFILING
623 if (!Log::IsEnabled() || !FLAG_log_api) return;
624 Logger::ApiEvent("api,%s\n", name);
625#endif
626}
627
628
629void Logger::NewEvent(const char* name, void* object, size_t size) {
630#ifdef ENABLE_LOGGING_AND_PROFILING
631 if (!Log::IsEnabled() || !FLAG_log) return;
632 LogMessageBuilder msg;
633 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
634 static_cast<unsigned int>(size));
635 msg.WriteToLogFile();
636#endif
637}
638
639
640void Logger::DeleteEvent(const char* name, void* object) {
641#ifdef ENABLE_LOGGING_AND_PROFILING
642 if (!Log::IsEnabled() || !FLAG_log) return;
643 LogMessageBuilder msg;
644 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
645 msg.WriteToLogFile();
646#endif
647}
648
649
650#ifdef ENABLE_LOGGING_AND_PROFILING
651
652// A class that contains all common code dealing with record compression.
653class CompressionHelper {
654 public:
655 explicit CompressionHelper(int window_size)
656 : compressor_(window_size), repeat_count_(0) { }
657
658 // Handles storing message in compressor, retrieving the previous one and
659 // prefixing it with repeat count, if needed.
660 // Returns true if message needs to be written to log.
661 bool HandleMessage(LogMessageBuilder* msg) {
662 if (!msg->StoreInCompressor(&compressor_)) {
663 // Current message repeats the previous one, don't write it.
664 ++repeat_count_;
665 return false;
666 }
667 if (repeat_count_ == 0) {
668 return msg->RetrieveCompressedPrevious(&compressor_);
669 }
670 OS::SNPrintF(prefix_, "%s,%d,",
671 Logger::log_events_[Logger::REPEAT_META_EVENT],
672 repeat_count_ + 1);
673 repeat_count_ = 0;
674 return msg->RetrieveCompressedPrevious(&compressor_, prefix_.start());
675 }
676
677 private:
678 LogRecordCompressor compressor_;
679 int repeat_count_;
680 EmbeddedVector<char, 20> prefix_;
681};
682
683#endif // ENABLE_LOGGING_AND_PROFILING
684
685
Steve Blockd0582a62009-12-15 09:54:21 +0000686#ifdef ENABLE_LOGGING_AND_PROFILING
687void Logger::CallbackEventInternal(const char* prefix, const char* name,
688 Address entry_point) {
689 if (!Log::IsEnabled() || !FLAG_log_code) return;
690 LogMessageBuilder msg;
691 msg.Append("%s,%s,",
692 log_events_[CODE_CREATION_EVENT], log_events_[CALLBACK_TAG]);
693 msg.AppendAddress(entry_point);
694 msg.Append(",1,\"%s%s\"", prefix, name);
695 if (FLAG_compress_log) {
696 ASSERT(compression_helper_ != NULL);
697 if (!compression_helper_->HandleMessage(&msg)) return;
698 }
699 msg.Append('\n');
700 msg.WriteToLogFile();
701}
702#endif
703
704
705void Logger::CallbackEvent(String* name, Address entry_point) {
706#ifdef ENABLE_LOGGING_AND_PROFILING
707 if (!Log::IsEnabled() || !FLAG_log_code) return;
708 SmartPointer<char> str =
709 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
710 CallbackEventInternal("", *str, entry_point);
711#endif
712}
713
714
715void Logger::GetterCallbackEvent(String* name, Address entry_point) {
716#ifdef ENABLE_LOGGING_AND_PROFILING
717 if (!Log::IsEnabled() || !FLAG_log_code) return;
718 SmartPointer<char> str =
719 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
720 CallbackEventInternal("get ", *str, entry_point);
721#endif
722}
723
724
725void Logger::SetterCallbackEvent(String* name, Address entry_point) {
726#ifdef ENABLE_LOGGING_AND_PROFILING
727 if (!Log::IsEnabled() || !FLAG_log_code) return;
728 SmartPointer<char> str =
729 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
730 CallbackEventInternal("set ", *str, entry_point);
731#endif
732}
733
734
Steve Blocka7e24c12009-10-30 11:49:00 +0000735void Logger::CodeCreateEvent(LogEventsAndTags tag,
736 Code* code,
737 const char* comment) {
738#ifdef ENABLE_LOGGING_AND_PROFILING
739 if (!Log::IsEnabled() || !FLAG_log_code) return;
740 LogMessageBuilder msg;
741 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
742 msg.AppendAddress(code->address());
743 msg.Append(",%d,\"", code->ExecutableSize());
744 for (const char* p = comment; *p != '\0'; p++) {
745 if (*p == '"') {
746 msg.Append('\\');
747 }
748 msg.Append(*p);
749 }
750 msg.Append('"');
751 if (FLAG_compress_log) {
752 ASSERT(compression_helper_ != NULL);
753 if (!compression_helper_->HandleMessage(&msg)) return;
754 }
755 msg.Append('\n');
756 msg.WriteToLogFile();
757#endif
758}
759
760
761void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
762#ifdef ENABLE_LOGGING_AND_PROFILING
763 if (!Log::IsEnabled() || !FLAG_log_code) return;
764 LogMessageBuilder msg;
765 SmartPointer<char> str =
766 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
767 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
768 msg.AppendAddress(code->address());
769 msg.Append(",%d,\"%s\"", code->ExecutableSize(), *str);
770 if (FLAG_compress_log) {
771 ASSERT(compression_helper_ != NULL);
772 if (!compression_helper_->HandleMessage(&msg)) return;
773 }
774 msg.Append('\n');
775 msg.WriteToLogFile();
776#endif
777}
778
779
780void Logger::CodeCreateEvent(LogEventsAndTags tag,
781 Code* code, String* name,
782 String* source, int line) {
783#ifdef ENABLE_LOGGING_AND_PROFILING
784 if (!Log::IsEnabled() || !FLAG_log_code) return;
785 LogMessageBuilder msg;
786 SmartPointer<char> str =
787 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
788 SmartPointer<char> sourcestr =
789 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
790 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
791 msg.AppendAddress(code->address());
792 msg.Append(",%d,\"%s %s:%d\"",
793 code->ExecutableSize(), *str, *sourcestr, line);
794 if (FLAG_compress_log) {
795 ASSERT(compression_helper_ != NULL);
796 if (!compression_helper_->HandleMessage(&msg)) return;
797 }
798 msg.Append('\n');
799 msg.WriteToLogFile();
800#endif
801}
802
803
804void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
805#ifdef ENABLE_LOGGING_AND_PROFILING
806 if (!Log::IsEnabled() || !FLAG_log_code) return;
807 LogMessageBuilder msg;
808 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
809 msg.AppendAddress(code->address());
810 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
811 if (FLAG_compress_log) {
812 ASSERT(compression_helper_ != NULL);
813 if (!compression_helper_->HandleMessage(&msg)) return;
814 }
815 msg.Append('\n');
816 msg.WriteToLogFile();
817#endif
818}
819
820
821void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
822#ifdef ENABLE_LOGGING_AND_PROFILING
823 if (!Log::IsEnabled() || !FLAG_log_code) return;
824 LogMessageBuilder msg;
825 msg.Append("%s,%s,",
826 log_events_[CODE_CREATION_EVENT], log_events_[REG_EXP_TAG]);
827 msg.AppendAddress(code->address());
828 msg.Append(",%d,\"", code->ExecutableSize());
829 msg.AppendDetailed(source, false);
830 msg.Append('\"');
831 if (FLAG_compress_log) {
832 ASSERT(compression_helper_ != NULL);
833 if (!compression_helper_->HandleMessage(&msg)) return;
834 }
835 msg.Append('\n');
836 msg.WriteToLogFile();
837#endif
838}
839
840
841void Logger::CodeMoveEvent(Address from, Address to) {
842#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000843 MoveEventInternal(CODE_MOVE_EVENT, from, to);
Steve Blocka7e24c12009-10-30 11:49:00 +0000844#endif
845}
846
847
848void Logger::CodeDeleteEvent(Address from) {
849#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000850 DeleteEventInternal(CODE_DELETE_EVENT, from);
Steve Blocka7e24c12009-10-30 11:49:00 +0000851#endif
852}
853
854
Leon Clarkee46be812010-01-19 14:06:41 +0000855void Logger::SnapshotPositionEvent(Address addr, int pos) {
856#ifdef ENABLE_LOGGING_AND_PROFILING
857 if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return;
858 LogMessageBuilder msg;
859 msg.Append("%s,", log_events_[SNAPSHOT_POSITION_EVENT]);
860 msg.AppendAddress(addr);
861 msg.Append(",%d", pos);
862 if (FLAG_compress_log) {
863 ASSERT(compression_helper_ != NULL);
864 if (!compression_helper_->HandleMessage(&msg)) return;
865 }
866 msg.Append('\n');
867 msg.WriteToLogFile();
868#endif
869}
870
871
Leon Clarked91b9f72010-01-27 17:25:45 +0000872void Logger::FunctionCreateEvent(JSFunction* function) {
873#ifdef ENABLE_LOGGING_AND_PROFILING
Kristian Monsen0d5e1162010-09-30 15:31:59 +0100874 // This function can be called from GC iterators (during Scavenge,
875 // MC, and MS), so marking bits can be set on objects. That's
876 // why unchecked accessors are used here.
Leon Clarked91b9f72010-01-27 17:25:45 +0000877 static Address prev_code = NULL;
878 if (!Log::IsEnabled() || !FLAG_log_code) return;
879 LogMessageBuilder msg;
880 msg.Append("%s,", log_events_[FUNCTION_CREATION_EVENT]);
881 msg.AppendAddress(function->address());
882 msg.Append(',');
Kristian Monsen0d5e1162010-09-30 15:31:59 +0100883 msg.AppendAddress(function->unchecked_code()->address(), prev_code);
884 prev_code = function->unchecked_code()->address();
Leon Clarked91b9f72010-01-27 17:25:45 +0000885 if (FLAG_compress_log) {
886 ASSERT(compression_helper_ != NULL);
887 if (!compression_helper_->HandleMessage(&msg)) return;
888 }
889 msg.Append('\n');
890 msg.WriteToLogFile();
891#endif
892}
893
894
Kristian Monsen0d5e1162010-09-30 15:31:59 +0100895void Logger::FunctionCreateEventFromMove(JSFunction* function,
896 HeapObject*) {
897#ifdef ENABLE_LOGGING_AND_PROFILING
898 if (function->unchecked_code() != Builtins::builtin(Builtins::LazyCompile)) {
899 FunctionCreateEvent(function);
900 }
901#endif
902}
903
904
Leon Clarked91b9f72010-01-27 17:25:45 +0000905void Logger::FunctionMoveEvent(Address from, Address to) {
906#ifdef ENABLE_LOGGING_AND_PROFILING
907 MoveEventInternal(FUNCTION_MOVE_EVENT, from, to);
908#endif
909}
910
911
912void Logger::FunctionDeleteEvent(Address from) {
913#ifdef ENABLE_LOGGING_AND_PROFILING
914 DeleteEventInternal(FUNCTION_DELETE_EVENT, from);
915#endif
916}
917
918
919#ifdef ENABLE_LOGGING_AND_PROFILING
920void Logger::MoveEventInternal(LogEventsAndTags event,
921 Address from,
922 Address to) {
923 static Address prev_to_ = NULL;
924 if (!Log::IsEnabled() || !FLAG_log_code) return;
925 LogMessageBuilder msg;
926 msg.Append("%s,", log_events_[event]);
927 msg.AppendAddress(from);
928 msg.Append(',');
929 msg.AppendAddress(to, prev_to_);
930 prev_to_ = to;
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
941#ifdef ENABLE_LOGGING_AND_PROFILING
942void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
943 if (!Log::IsEnabled() || !FLAG_log_code) return;
944 LogMessageBuilder msg;
945 msg.Append("%s,", log_events_[event]);
946 msg.AppendAddress(from);
947 if (FLAG_compress_log) {
948 ASSERT(compression_helper_ != NULL);
949 if (!compression_helper_->HandleMessage(&msg)) return;
950 }
951 msg.Append('\n');
952 msg.WriteToLogFile();
953}
954#endif
955
956
Steve Blocka7e24c12009-10-30 11:49:00 +0000957void Logger::ResourceEvent(const char* name, const char* tag) {
958#ifdef ENABLE_LOGGING_AND_PROFILING
959 if (!Log::IsEnabled() || !FLAG_log) return;
960 LogMessageBuilder msg;
961 msg.Append("%s,%s,", name, tag);
962
963 uint32_t sec, usec;
964 if (OS::GetUserTime(&sec, &usec) != -1) {
965 msg.Append("%d,%d,", sec, usec);
966 }
967 msg.Append("%.0f", OS::TimeCurrentMillis());
968
969 msg.Append('\n');
970 msg.WriteToLogFile();
971#endif
972}
973
974
975void Logger::SuspectReadEvent(String* name, Object* obj) {
976#ifdef ENABLE_LOGGING_AND_PROFILING
977 if (!Log::IsEnabled() || !FLAG_log_suspect) return;
978 LogMessageBuilder msg;
979 String* class_name = obj->IsJSObject()
980 ? JSObject::cast(obj)->class_name()
981 : Heap::empty_string();
982 msg.Append("suspect-read,");
983 msg.Append(class_name);
984 msg.Append(',');
985 msg.Append('"');
986 msg.Append(name);
987 msg.Append('"');
988 msg.Append('\n');
989 msg.WriteToLogFile();
990#endif
991}
992
993
994void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
995#ifdef ENABLE_LOGGING_AND_PROFILING
996 if (!Log::IsEnabled() || !FLAG_log_gc) return;
997 LogMessageBuilder msg;
998 // Using non-relative system time in order to be able to synchronize with
999 // external memory profiling events (e.g. DOM memory size).
1000 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
1001 space, kind, OS::TimeCurrentMillis());
1002 msg.WriteToLogFile();
1003#endif
1004}
1005
1006
1007void Logger::HeapSampleStats(const char* space, const char* kind,
1008 int capacity, int used) {
1009#ifdef ENABLE_LOGGING_AND_PROFILING
1010 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1011 LogMessageBuilder msg;
1012 msg.Append("heap-sample-stats,\"%s\",\"%s\",%d,%d\n",
1013 space, kind, capacity, used);
1014 msg.WriteToLogFile();
1015#endif
1016}
1017
1018
1019void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1020#ifdef ENABLE_LOGGING_AND_PROFILING
1021 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1022 LogMessageBuilder msg;
1023 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1024 msg.WriteToLogFile();
1025#endif
1026}
1027
1028
1029void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1030#ifdef ENABLE_LOGGING_AND_PROFILING
1031 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1032 LogMessageBuilder msg;
1033 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1034 msg.WriteToLogFile();
1035#endif
1036}
1037
1038
1039void Logger::HeapSampleJSConstructorEvent(const char* constructor,
1040 int number, int bytes) {
1041#ifdef ENABLE_LOGGING_AND_PROFILING
1042 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1043 LogMessageBuilder msg;
1044 msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
1045 msg.WriteToLogFile();
1046#endif
1047}
1048
1049
1050void Logger::HeapSampleJSRetainersEvent(
1051 const char* constructor, const char* event) {
1052#ifdef ENABLE_LOGGING_AND_PROFILING
1053 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1054 // Event starts with comma, so we don't have it in the format string.
1055 static const char* event_text = "heap-js-ret-item,%s";
1056 // We take placeholder strings into account, but it's OK to be conservative.
Steve Blockd0582a62009-12-15 09:54:21 +00001057 static const int event_text_len = StrLength(event_text);
1058 const int cons_len = StrLength(constructor);
1059 const int event_len = StrLength(event);
Steve Blocka7e24c12009-10-30 11:49:00 +00001060 int pos = 0;
1061 // Retainer lists can be long. We may need to split them into multiple events.
1062 do {
1063 LogMessageBuilder msg;
1064 msg.Append(event_text, constructor);
1065 int to_write = event_len - pos;
1066 if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) {
1067 int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len);
1068 ASSERT(cut_pos < event_len);
1069 while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
1070 if (event[cut_pos] != ',') {
1071 // Crash in debug mode, skip in release mode.
1072 ASSERT(false);
1073 return;
1074 }
1075 // Append a piece of event that fits, without trailing comma.
1076 msg.AppendStringPart(event + pos, cut_pos - pos);
1077 // Start next piece with comma.
1078 pos = cut_pos;
1079 } else {
1080 msg.Append("%s", event + pos);
1081 pos += event_len;
1082 }
1083 msg.Append('\n');
1084 msg.WriteToLogFile();
1085 } while (pos < event_len);
1086#endif
1087}
1088
1089
Steve Block3ce2e202009-11-05 08:53:23 +00001090void Logger::HeapSampleJSProducerEvent(const char* constructor,
1091 Address* stack) {
1092#ifdef ENABLE_LOGGING_AND_PROFILING
1093 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1094 LogMessageBuilder msg;
1095 msg.Append("heap-js-prod-item,%s", constructor);
1096 while (*stack != NULL) {
1097 msg.Append(",0x%" V8PRIxPTR, *stack++);
1098 }
1099 msg.Append("\n");
1100 msg.WriteToLogFile();
1101#endif
1102}
1103
1104
Steve Blocka7e24c12009-10-30 11:49:00 +00001105void Logger::DebugTag(const char* call_site_tag) {
1106#ifdef ENABLE_LOGGING_AND_PROFILING
1107 if (!Log::IsEnabled() || !FLAG_log) return;
1108 LogMessageBuilder msg;
1109 msg.Append("debug-tag,%s\n", call_site_tag);
1110 msg.WriteToLogFile();
1111#endif
1112}
1113
1114
1115void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1116#ifdef ENABLE_LOGGING_AND_PROFILING
1117 if (!Log::IsEnabled() || !FLAG_log) return;
1118 StringBuilder s(parameter.length() + 1);
1119 for (int i = 0; i < parameter.length(); ++i) {
1120 s.AddCharacter(static_cast<char>(parameter[i]));
1121 }
1122 char* parameter_string = s.Finalize();
1123 LogMessageBuilder msg;
1124 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1125 event_type,
1126 OS::TimeCurrentMillis(),
1127 parameter_string);
1128 DeleteArray(parameter_string);
1129 msg.WriteToLogFile();
1130#endif
1131}
1132
1133
1134#ifdef ENABLE_LOGGING_AND_PROFILING
1135void Logger::TickEvent(TickSample* sample, bool overflow) {
1136 if (!Log::IsEnabled() || !FLAG_prof) return;
1137 static Address prev_sp = NULL;
Leon Clarked91b9f72010-01-27 17:25:45 +00001138 static Address prev_function = NULL;
Steve Blocka7e24c12009-10-30 11:49:00 +00001139 LogMessageBuilder msg;
1140 msg.Append("%s,", log_events_[TICK_EVENT]);
Leon Clarked91b9f72010-01-27 17:25:45 +00001141 Address prev_addr = sample->pc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001142 msg.AppendAddress(prev_addr);
1143 msg.Append(',');
Leon Clarked91b9f72010-01-27 17:25:45 +00001144 msg.AppendAddress(sample->sp, prev_sp);
1145 prev_sp = sample->sp;
1146 msg.Append(',');
1147 msg.AppendAddress(sample->function, prev_function);
1148 prev_function = sample->function;
Steve Blocka7e24c12009-10-30 11:49:00 +00001149 msg.Append(",%d", static_cast<int>(sample->state));
1150 if (overflow) {
1151 msg.Append(",overflow");
1152 }
1153 for (int i = 0; i < sample->frames_count; ++i) {
1154 msg.Append(',');
1155 msg.AppendAddress(sample->stack[i], prev_addr);
1156 prev_addr = sample->stack[i];
1157 }
1158 if (FLAG_compress_log) {
1159 ASSERT(compression_helper_ != NULL);
1160 if (!compression_helper_->HandleMessage(&msg)) return;
1161 }
1162 msg.Append('\n');
1163 msg.WriteToLogFile();
1164}
1165
1166
1167int Logger::GetActiveProfilerModules() {
1168 int result = PROFILER_MODULE_NONE;
Steve Block8defd9f2010-07-08 12:39:36 +01001169 if (profiler_ != NULL && !profiler_->paused()) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001170 result |= PROFILER_MODULE_CPU;
1171 }
1172 if (FLAG_log_gc) {
1173 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1174 }
1175 return result;
1176}
1177
1178
Andrei Popescu402d9372010-02-26 13:31:12 +00001179void Logger::PauseProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001180 if (!Log::IsEnabled()) return;
Steve Block8defd9f2010-07-08 12:39:36 +01001181 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001182 // It is OK to have negative nesting.
1183 if (--cpu_profiler_nesting_ == 0) {
1184 profiler_->pause();
1185 if (FLAG_prof_lazy) {
1186 if (!FLAG_sliding_state_window) ticker_->Stop();
1187 FLAG_log_code = false;
1188 // Must be the same message as Log::kDynamicBufferSeal.
1189 LOG(UncheckedStringEvent("profiler", "pause"));
1190 }
Steve Block6ded16b2010-05-10 14:33:55 +01001191 --logging_nesting_;
Steve Blocka7e24c12009-10-30 11:49:00 +00001192 }
1193 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001194 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001195 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001196 if (--heap_profiler_nesting_ == 0) {
1197 FLAG_log_gc = false;
Steve Block6ded16b2010-05-10 14:33:55 +01001198 --logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001199 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001200 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001201 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001202 UncheckedIntEvent("close-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001203 }
1204}
1205
1206
Andrei Popescu402d9372010-02-26 13:31:12 +00001207void Logger::ResumeProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001208 if (!Log::IsEnabled()) return;
Andrei Popescu402d9372010-02-26 13:31:12 +00001209 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001210 UncheckedIntEvent("open-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001211 }
Steve Block8defd9f2010-07-08 12:39:36 +01001212 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001213 if (cpu_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001214 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001215 if (FLAG_prof_lazy) {
1216 profiler_->Engage();
1217 LOG(UncheckedStringEvent("profiler", "resume"));
1218 FLAG_log_code = true;
1219 LogCompiledFunctions();
1220 LogFunctionObjects();
1221 LogAccessorCallbacks();
1222 if (!FLAG_sliding_state_window) ticker_->Start();
1223 }
1224 profiler_->resume();
Steve Blocka7e24c12009-10-30 11:49:00 +00001225 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001226 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001227 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001228 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001229 if (heap_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001230 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001231 FLAG_log_gc = true;
1232 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001233 }
1234}
1235
1236
1237// This function can be called when Log's mutex is acquired,
1238// either from main or Profiler's thread.
1239void Logger::StopLoggingAndProfiling() {
1240 Log::stop();
Andrei Popescu402d9372010-02-26 13:31:12 +00001241 PauseProfiler(PROFILER_MODULE_CPU, 0);
Steve Blocka7e24c12009-10-30 11:49:00 +00001242}
1243
1244
1245bool Logger::IsProfilerSamplerActive() {
1246 return ticker_->IsActive();
1247}
1248
1249
1250int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1251 return Log::GetLogLines(from_pos, dest_buf, max_size);
1252}
1253
1254
Steve Block3ce2e202009-11-05 08:53:23 +00001255static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis) {
1256 AssertNoAllocation no_alloc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001257 int compiled_funcs_count = 0;
Steve Block3ce2e202009-11-05 08:53:23 +00001258 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001259 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Block3ce2e202009-11-05 08:53:23 +00001260 if (!obj->IsSharedFunctionInfo()) continue;
1261 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1262 if (sfi->is_compiled()
1263 && (!sfi->script()->IsScript()
1264 || Script::cast(sfi->script())->HasValidSource())) {
1265 if (sfis != NULL)
1266 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1267 ++compiled_funcs_count;
Steve Blocka7e24c12009-10-30 11:49:00 +00001268 }
1269 }
Steve Block3ce2e202009-11-05 08:53:23 +00001270 return compiled_funcs_count;
1271}
1272
1273
Steve Blockd0582a62009-12-15 09:54:21 +00001274void Logger::LogCodeObject(Object* object) {
1275 if (FLAG_log_code) {
1276 Code* code_object = Code::cast(object);
1277 LogEventsAndTags tag = Logger::STUB_TAG;
1278 const char* description = "Unknown code from the snapshot";
1279 switch (code_object->kind()) {
1280 case Code::FUNCTION:
1281 return; // We log this later using LogCompiledFunctions.
Steve Block6ded16b2010-05-10 14:33:55 +01001282 case Code::BINARY_OP_IC:
1283 // fall through
Steve Blockd0582a62009-12-15 09:54:21 +00001284 case Code::STUB:
Kristian Monsen80d68ea2010-09-08 11:05:35 +01001285 description =
1286 CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
Andrei Popescu31002712010-02-23 13:46:05 +00001287 if (description == NULL)
1288 description = "A stub from the snapshot";
Steve Blockd0582a62009-12-15 09:54:21 +00001289 tag = Logger::STUB_TAG;
1290 break;
1291 case Code::BUILTIN:
1292 description = "A builtin from the snapshot";
1293 tag = Logger::BUILTIN_TAG;
1294 break;
1295 case Code::KEYED_LOAD_IC:
1296 description = "A keyed load IC from the snapshot";
1297 tag = Logger::KEYED_LOAD_IC_TAG;
1298 break;
1299 case Code::LOAD_IC:
1300 description = "A load IC from the snapshot";
1301 tag = Logger::LOAD_IC_TAG;
1302 break;
1303 case Code::STORE_IC:
1304 description = "A store IC from the snapshot";
1305 tag = Logger::STORE_IC_TAG;
1306 break;
1307 case Code::KEYED_STORE_IC:
1308 description = "A keyed store IC from the snapshot";
1309 tag = Logger::KEYED_STORE_IC_TAG;
1310 break;
1311 case Code::CALL_IC:
1312 description = "A call IC from the snapshot";
1313 tag = Logger::CALL_IC_TAG;
1314 break;
Ben Murdoch7f4d5bd2010-06-15 11:15:29 +01001315 case Code::KEYED_CALL_IC:
1316 description = "A keyed call IC from the snapshot";
1317 tag = Logger::KEYED_CALL_IC_TAG;
1318 break;
Steve Blockd0582a62009-12-15 09:54:21 +00001319 }
Steve Block6ded16b2010-05-10 14:33:55 +01001320 PROFILE(CodeCreateEvent(tag, code_object, description));
Steve Blockd0582a62009-12-15 09:54:21 +00001321 }
1322}
1323
1324
Andrei Popescu31002712010-02-23 13:46:05 +00001325void Logger::LogCodeObjects() {
1326 AssertNoAllocation no_alloc;
1327 HeapIterator iterator;
1328 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1329 if (obj->IsCode()) LogCodeObject(obj);
1330 }
1331}
1332
1333
Steve Block3ce2e202009-11-05 08:53:23 +00001334void Logger::LogCompiledFunctions() {
1335 HandleScope scope;
1336 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL);
Kristian Monsen25f61362010-05-21 11:50:48 +01001337 ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
1338 EnumerateCompiledFunctions(sfis.start());
Steve Blocka7e24c12009-10-30 11:49:00 +00001339
1340 // During iteration, there can be heap allocation due to
1341 // GetScriptLineNumber call.
1342 for (int i = 0; i < compiled_funcs_count; ++i) {
1343 Handle<SharedFunctionInfo> shared = sfis[i];
1344 Handle<String> name(String::cast(shared->name()));
1345 Handle<String> func_name(name->length() > 0 ?
1346 *name : shared->inferred_name());
1347 if (shared->script()->IsScript()) {
1348 Handle<Script> script(Script::cast(shared->script()));
1349 if (script->name()->IsString()) {
1350 Handle<String> script_name(String::cast(script->name()));
1351 int line_num = GetScriptLineNumber(script, shared->start_position());
1352 if (line_num > 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001353 PROFILE(CodeCreateEvent(
1354 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1355 shared->code(), *func_name,
1356 *script_name, line_num + 1));
Steve Blocka7e24c12009-10-30 11:49:00 +00001357 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001358 // Can't distinguish eval and script here, so always use Script.
1359 PROFILE(CodeCreateEvent(
1360 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1361 shared->code(), *script_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001362 }
Steve Blockd0582a62009-12-15 09:54:21 +00001363 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001364 PROFILE(CodeCreateEvent(
1365 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1366 shared->code(), *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001367 }
Steve Block6ded16b2010-05-10 14:33:55 +01001368 } else if (shared->IsApiFunction()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001369 // API function.
Steve Block6ded16b2010-05-10 14:33:55 +01001370 FunctionTemplateInfo* fun_data = shared->get_api_func_data();
Steve Blockd0582a62009-12-15 09:54:21 +00001371 Object* raw_call_data = fun_data->call_code();
1372 if (!raw_call_data->IsUndefined()) {
1373 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1374 Object* callback_obj = call_data->callback();
1375 Address entry_point = v8::ToCData<Address>(callback_obj);
Steve Block6ded16b2010-05-10 14:33:55 +01001376 PROFILE(CallbackEvent(*func_name, entry_point));
Steve Blockd0582a62009-12-15 09:54:21 +00001377 }
1378 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001379 PROFILE(CodeCreateEvent(
Steve Blockd0582a62009-12-15 09:54:21 +00001380 Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001381 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001382 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001383}
1384
Steve Blockd0582a62009-12-15 09:54:21 +00001385
Leon Clarked91b9f72010-01-27 17:25:45 +00001386void Logger::LogFunctionObjects() {
1387 AssertNoAllocation no_alloc;
1388 HeapIterator iterator;
1389 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1390 if (!obj->IsJSFunction()) continue;
1391 JSFunction* jsf = JSFunction::cast(obj);
1392 if (!jsf->is_compiled()) continue;
Steve Block6ded16b2010-05-10 14:33:55 +01001393 PROFILE(FunctionCreateEvent(jsf));
Leon Clarked91b9f72010-01-27 17:25:45 +00001394 }
1395}
1396
1397
Steve Blockd0582a62009-12-15 09:54:21 +00001398void Logger::LogAccessorCallbacks() {
1399 AssertNoAllocation no_alloc;
1400 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001401 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001402 if (!obj->IsAccessorInfo()) continue;
1403 AccessorInfo* ai = AccessorInfo::cast(obj);
1404 if (!ai->name()->IsString()) continue;
1405 String* name = String::cast(ai->name());
1406 Address getter_entry = v8::ToCData<Address>(ai->getter());
1407 if (getter_entry != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001408 PROFILE(GetterCallbackEvent(name, getter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001409 }
1410 Address setter_entry = v8::ToCData<Address>(ai->setter());
1411 if (setter_entry != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001412 PROFILE(SetterCallbackEvent(name, setter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001413 }
1414 }
1415}
1416
Steve Blocka7e24c12009-10-30 11:49:00 +00001417#endif
1418
1419
1420bool Logger::Setup() {
1421#ifdef ENABLE_LOGGING_AND_PROFILING
1422 // --log-all enables all the log flags.
1423 if (FLAG_log_all) {
1424 FLAG_log_runtime = true;
1425 FLAG_log_api = true;
1426 FLAG_log_code = true;
1427 FLAG_log_gc = true;
1428 FLAG_log_suspect = true;
1429 FLAG_log_handles = true;
1430 FLAG_log_regexp = true;
1431 }
1432
1433 // --prof implies --log-code.
1434 if (FLAG_prof) FLAG_log_code = true;
1435
1436 // --prof_lazy controls --log-code, implies --noprof_auto.
1437 if (FLAG_prof_lazy) {
1438 FLAG_log_code = false;
1439 FLAG_prof_auto = false;
1440 }
1441
1442 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1443 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1444 || FLAG_log_regexp || FLAG_log_state_changes;
1445
1446 bool open_log_file = start_logging || FLAG_prof_lazy;
1447
1448 // If we're logging anything, we need to open the log file.
1449 if (open_log_file) {
1450 if (strcmp(FLAG_logfile, "-") == 0) {
1451 Log::OpenStdout();
1452 } else if (strcmp(FLAG_logfile, "*") == 0) {
1453 Log::OpenMemoryBuffer();
1454 } else if (strchr(FLAG_logfile, '%') != NULL) {
1455 // If there's a '%' in the log file name we have to expand
1456 // placeholders.
1457 HeapStringAllocator allocator;
1458 StringStream stream(&allocator);
1459 for (const char* p = FLAG_logfile; *p; p++) {
1460 if (*p == '%') {
1461 p++;
1462 switch (*p) {
1463 case '\0':
1464 // If there's a % at the end of the string we back up
1465 // one character so we can escape the loop properly.
1466 p--;
1467 break;
1468 case 't': {
1469 // %t expands to the current time in milliseconds.
1470 double time = OS::TimeCurrentMillis();
1471 stream.Add("%.0f", FmtElm(time));
1472 break;
1473 }
1474 case '%':
1475 // %% expands (contracts really) to %.
1476 stream.Put('%');
1477 break;
1478 default:
1479 // All other %'s expand to themselves.
1480 stream.Put('%');
1481 stream.Put(*p);
1482 break;
1483 }
1484 } else {
1485 stream.Put(*p);
1486 }
1487 }
1488 SmartPointer<const char> expanded = stream.ToCString();
1489 Log::OpenFile(*expanded);
1490 } else {
1491 Log::OpenFile(FLAG_logfile);
1492 }
1493 }
1494
Steve Block6ded16b2010-05-10 14:33:55 +01001495 ASSERT(VMState::is_outermost_external());
Steve Blocka7e24c12009-10-30 11:49:00 +00001496
1497 ticker_ = new Ticker(kSamplingIntervalMs);
1498
1499 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1500 sliding_state_window_ = new SlidingStateWindow();
1501 }
1502
1503 log_events_ = FLAG_compress_log ?
1504 kCompressedLogEventsNames : kLongLogEventsNames;
1505 if (FLAG_compress_log) {
1506 compression_helper_ = new CompressionHelper(kCompressionWindowSize);
1507 }
1508
Steve Block6ded16b2010-05-10 14:33:55 +01001509 if (start_logging) {
1510 logging_nesting_ = 1;
1511 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001512
1513 if (FLAG_prof) {
1514 profiler_ = new Profiler();
1515 if (!FLAG_prof_auto) {
1516 profiler_->pause();
1517 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001518 logging_nesting_ = 1;
Steve Blocka7e24c12009-10-30 11:49:00 +00001519 }
Steve Blockd0582a62009-12-15 09:54:21 +00001520 if (!FLAG_prof_lazy) {
1521 profiler_->Engage();
1522 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001523 }
1524
1525 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
1526
1527 return true;
1528
1529#else
1530 return false;
1531#endif
1532}
1533
1534
1535void Logger::TearDown() {
1536#ifdef ENABLE_LOGGING_AND_PROFILING
1537 LogMessageBuilder::set_write_failure_handler(NULL);
1538
1539 // Stop the profiler before closing the file.
1540 if (profiler_ != NULL) {
1541 profiler_->Disengage();
1542 delete profiler_;
1543 profiler_ = NULL;
1544 }
1545
1546 delete compression_helper_;
1547 compression_helper_ = NULL;
1548
1549 delete sliding_state_window_;
1550 sliding_state_window_ = NULL;
1551
1552 delete ticker_;
1553 ticker_ = NULL;
1554
1555 Log::Close();
1556#endif
1557}
1558
1559
1560void Logger::EnableSlidingStateWindow() {
1561#ifdef ENABLE_LOGGING_AND_PROFILING
1562 // If the ticker is NULL, Logger::Setup has not been called yet. In
1563 // that case, we set the sliding_state_window flag so that the
1564 // sliding window computation will be started when Logger::Setup is
1565 // called.
1566 if (ticker_ == NULL) {
1567 FLAG_sliding_state_window = true;
1568 return;
1569 }
1570 // Otherwise, if the sliding state window computation has not been
1571 // started we do it now.
1572 if (sliding_state_window_ == NULL) {
1573 sliding_state_window_ = new SlidingStateWindow();
1574 }
1575#endif
1576}
1577
Steve Blocka7e24c12009-10-30 11:49:00 +00001578} } // namespace v8::internal