blob: d225c3b49515a4df9d3574fe6246d92bcc95d62d [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"
33#include "log.h"
34#include "macro-assembler.h"
35#include "serialize.h"
36#include "string-stream.h"
37
38namespace v8 {
39namespace internal {
40
41#ifdef ENABLE_LOGGING_AND_PROFILING
42
43//
44// Sliding state window. Updates counters to keep track of the last
45// window of kBufferSize states. This is useful to track where we
46// spent our time.
47//
48class SlidingStateWindow {
49 public:
50 SlidingStateWindow();
51 ~SlidingStateWindow();
52 void AddState(StateTag state);
53
54 private:
55 static const int kBufferSize = 256;
56 int current_index_;
57 bool is_full_;
58 byte buffer_[kBufferSize];
59
60
61 void IncrementStateCounter(StateTag state) {
62 Counters::state_counters[state].Increment();
63 }
64
65
66 void DecrementStateCounter(StateTag state) {
67 Counters::state_counters[state].Decrement();
68 }
69};
70
71
72//
73// The Profiler samples pc and sp values for the main thread.
74// Each sample is appended to a circular buffer.
75// An independent thread removes data and writes it to the log.
76// This design minimizes the time spent in the sampler.
77//
78class Profiler: public Thread {
79 public:
80 Profiler();
81 void Engage();
82 void Disengage();
83
84 // Inserts collected profiling data into buffer.
85 void Insert(TickSample* sample) {
86 if (paused_)
87 return;
88
89 if (Succ(head_) == tail_) {
90 overflow_ = true;
91 } else {
92 buffer_[head_] = *sample;
93 head_ = Succ(head_);
94 buffer_semaphore_->Signal(); // Tell we have an element.
95 }
96 }
97
98 // Waits for a signal and removes profiling data.
99 bool Remove(TickSample* sample) {
100 buffer_semaphore_->Wait(); // Wait for an element.
101 *sample = buffer_[tail_];
102 bool result = overflow_;
103 tail_ = Succ(tail_);
104 overflow_ = false;
105 return result;
106 }
107
108 void Run();
109
110 // Pause and Resume TickSample data collection.
111 static bool paused() { return paused_; }
112 static void pause() { paused_ = true; }
113 static void resume() { paused_ = false; }
114
115 private:
116 // Returns the next index in the cyclic buffer.
117 int Succ(int index) { return (index + 1) % kBufferSize; }
118
119 // Cyclic buffer for communicating profiling samples
120 // between the signal handler and the worker thread.
121 static const int kBufferSize = 128;
122 TickSample buffer_[kBufferSize]; // Buffer storage.
123 int head_; // Index to the buffer head.
124 int tail_; // Index to the buffer tail.
125 bool overflow_; // Tell whether a buffer overflow has occurred.
126 Semaphore* buffer_semaphore_; // Sempahore used for buffer synchronization.
127
128 // Tells whether worker thread should continue running.
129 bool running_;
130
131 // Tells whether we are currently recording tick samples.
132 static bool paused_;
133};
134
135bool Profiler::paused_ = false;
136
137
138//
139// StackTracer implementation
140//
141void StackTracer::Trace(TickSample* sample) {
142 if (sample->state == GC) {
143 sample->frames_count = 0;
144 return;
145 }
146
147 const Address js_entry_sp = Top::js_entry_sp(Top::GetCurrentThread());
148 if (js_entry_sp == 0) {
149 // Not executing JS now.
150 sample->frames_count = 0;
151 return;
152 }
153
154 SafeStackTraceFrameIterator it(
155 reinterpret_cast<Address>(sample->fp),
156 reinterpret_cast<Address>(sample->sp),
157 reinterpret_cast<Address>(sample->sp),
158 js_entry_sp);
159 int i = 0;
160 while (!it.done() && i < TickSample::kMaxFramesCount) {
161 sample->stack[i++] = it.frame()->pc();
162 it.Advance();
163 }
164 sample->frames_count = i;
165}
166
167
168//
169// Ticker used to provide ticks to the profiler and the sliding state
170// window.
171//
172class Ticker: public Sampler {
173 public:
174 explicit Ticker(int interval):
175 Sampler(interval, FLAG_prof), window_(NULL), profiler_(NULL) {}
176
177 ~Ticker() { if (IsActive()) Stop(); }
178
179 void SampleStack(TickSample* sample) {
180 StackTracer::Trace(sample);
181 }
182
183 void Tick(TickSample* sample) {
184 if (profiler_) profiler_->Insert(sample);
185 if (window_) window_->AddState(sample->state);
186 }
187
188 void SetWindow(SlidingStateWindow* window) {
189 window_ = window;
190 if (!IsActive()) Start();
191 }
192
193 void ClearWindow() {
194 window_ = NULL;
195 if (!profiler_ && IsActive()) Stop();
196 }
197
198 void SetProfiler(Profiler* profiler) {
199 profiler_ = profiler;
200 if (!FLAG_prof_lazy && !IsActive()) Start();
201 }
202
203 void ClearProfiler() {
204 profiler_ = NULL;
205 if (!window_ && IsActive()) Stop();
206 }
207
208 private:
209 SlidingStateWindow* window_;
210 Profiler* profiler_;
211};
212
213
214//
215// SlidingStateWindow implementation.
216//
217SlidingStateWindow::SlidingStateWindow(): current_index_(0), is_full_(false) {
218 for (int i = 0; i < kBufferSize; i++) {
219 buffer_[i] = static_cast<byte>(OTHER);
220 }
221 Logger::ticker_->SetWindow(this);
222}
223
224
225SlidingStateWindow::~SlidingStateWindow() {
226 Logger::ticker_->ClearWindow();
227}
228
229
230void SlidingStateWindow::AddState(StateTag state) {
231 if (is_full_) {
232 DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
233 } else if (current_index_ == kBufferSize - 1) {
234 is_full_ = true;
235 }
236 buffer_[current_index_] = static_cast<byte>(state);
237 IncrementStateCounter(state);
238 ASSERT(IsPowerOf2(kBufferSize));
239 current_index_ = (current_index_ + 1) & (kBufferSize - 1);
240}
241
242
243//
244// Profiler implementation.
245//
246Profiler::Profiler() {
247 buffer_semaphore_ = OS::CreateSemaphore(0);
248 head_ = 0;
249 tail_ = 0;
250 overflow_ = false;
251 running_ = false;
252}
253
254
255void Profiler::Engage() {
256 OS::LogSharedLibraryAddresses();
257
258 // Start thread processing the profiler buffer.
259 running_ = true;
260 Start();
261
262 // Register to get ticks.
263 Logger::ticker_->SetProfiler(this);
264
265 Logger::ProfilerBeginEvent();
266 Logger::LogAliases();
267}
268
269
270void Profiler::Disengage() {
271 // Stop receiving ticks.
272 Logger::ticker_->ClearProfiler();
273
274 // Terminate the worker thread by setting running_ to false,
275 // inserting a fake element in the queue and then wait for
276 // the thread to terminate.
277 running_ = false;
278 TickSample sample;
279 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
280 resume();
281 Insert(&sample);
282 Join();
283
284 LOG(UncheckedStringEvent("profiler", "end"));
285}
286
287
288void Profiler::Run() {
289 TickSample sample;
290 bool overflow = Logger::profiler_->Remove(&sample);
291 while (running_) {
292 LOG(TickEvent(&sample, overflow));
293 overflow = Logger::profiler_->Remove(&sample);
294 }
295}
296
297
298//
299// Logger class implementation.
300//
301Ticker* Logger::ticker_ = NULL;
302Profiler* Logger::profiler_ = NULL;
303VMState* Logger::current_state_ = NULL;
304VMState Logger::bottom_state_(EXTERNAL);
305SlidingStateWindow* Logger::sliding_state_window_ = NULL;
306const char** Logger::log_events_ = NULL;
307CompressionHelper* Logger::compression_helper_ = NULL;
308bool Logger::is_logging_ = false;
309
310#define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name,
311const char* kLongLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
312 LOG_EVENTS_AND_TAGS_LIST(DECLARE_LONG_EVENT)
313};
314#undef DECLARE_LONG_EVENT
315
316#define DECLARE_SHORT_EVENT(ignore1, ignore2, short_name) short_name,
317const char* kCompressedLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
318 LOG_EVENTS_AND_TAGS_LIST(DECLARE_SHORT_EVENT)
319};
320#undef DECLARE_SHORT_EVENT
321
322
323void Logger::ProfilerBeginEvent() {
324 if (!Log::IsEnabled()) return;
325 LogMessageBuilder msg;
326 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
327 if (FLAG_compress_log) {
328 msg.Append("profiler,\"compression\",%d\n", kCompressionWindowSize);
329 }
330 msg.WriteToLogFile();
331}
332
333
334void Logger::LogAliases() {
335 if (!Log::IsEnabled() || !FLAG_compress_log) return;
336 LogMessageBuilder msg;
337 for (int i = 0; i < NUMBER_OF_LOG_EVENTS; ++i) {
338 msg.Append("alias,%s,%s\n",
339 kCompressedLogEventsNames[i], kLongLogEventsNames[i]);
340 }
341 msg.WriteToLogFile();
342}
343
344#endif // ENABLE_LOGGING_AND_PROFILING
345
346
347void Logger::Preamble(const char* content) {
348#ifdef ENABLE_LOGGING_AND_PROFILING
349 if (!Log::IsEnabled() || !FLAG_log_code) return;
350 LogMessageBuilder msg;
351 msg.WriteCStringToLogFile(content);
352#endif
353}
354
355
356void Logger::StringEvent(const char* name, const char* value) {
357#ifdef ENABLE_LOGGING_AND_PROFILING
358 if (FLAG_log) UncheckedStringEvent(name, value);
359#endif
360}
361
362
363#ifdef ENABLE_LOGGING_AND_PROFILING
364void Logger::UncheckedStringEvent(const char* name, const char* value) {
365 if (!Log::IsEnabled()) return;
366 LogMessageBuilder msg;
367 msg.Append("%s,\"%s\"\n", name, value);
368 msg.WriteToLogFile();
369}
370#endif
371
372
373void Logger::IntEvent(const char* name, int value) {
374#ifdef ENABLE_LOGGING_AND_PROFILING
375 if (!Log::IsEnabled() || !FLAG_log) return;
376 LogMessageBuilder msg;
377 msg.Append("%s,%d\n", name, value);
378 msg.WriteToLogFile();
379#endif
380}
381
382
383void Logger::HandleEvent(const char* name, Object** location) {
384#ifdef ENABLE_LOGGING_AND_PROFILING
385 if (!Log::IsEnabled() || !FLAG_log_handles) return;
386 LogMessageBuilder msg;
387 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
388 msg.WriteToLogFile();
389#endif
390}
391
392
393#ifdef ENABLE_LOGGING_AND_PROFILING
394// ApiEvent is private so all the calls come from the Logger class. It is the
395// caller's responsibility to ensure that log is enabled and that
396// FLAG_log_api is true.
397void Logger::ApiEvent(const char* format, ...) {
398 ASSERT(Log::IsEnabled() && FLAG_log_api);
399 LogMessageBuilder msg;
400 va_list ap;
401 va_start(ap, format);
402 msg.AppendVA(format, ap);
403 va_end(ap);
404 msg.WriteToLogFile();
405}
406#endif
407
408
409void Logger::ApiNamedSecurityCheck(Object* key) {
410#ifdef ENABLE_LOGGING_AND_PROFILING
411 if (!Log::IsEnabled() || !FLAG_log_api) return;
412 if (key->IsString()) {
413 SmartPointer<char> str =
414 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
415 ApiEvent("api,check-security,\"%s\"\n", *str);
416 } else if (key->IsUndefined()) {
417 ApiEvent("api,check-security,undefined\n");
418 } else {
419 ApiEvent("api,check-security,['no-name']\n");
420 }
421#endif
422}
423
424
425void Logger::SharedLibraryEvent(const char* library_path,
426 uintptr_t start,
427 uintptr_t end) {
428#ifdef ENABLE_LOGGING_AND_PROFILING
429 if (!Log::IsEnabled() || !FLAG_prof) return;
430 LogMessageBuilder msg;
431 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
432 library_path,
433 start,
434 end);
435 msg.WriteToLogFile();
436#endif
437}
438
439
440void Logger::SharedLibraryEvent(const wchar_t* library_path,
441 uintptr_t start,
442 uintptr_t end) {
443#ifdef ENABLE_LOGGING_AND_PROFILING
444 if (!Log::IsEnabled() || !FLAG_prof) return;
445 LogMessageBuilder msg;
446 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
447 library_path,
448 start,
449 end);
450 msg.WriteToLogFile();
451#endif
452}
453
454
455#ifdef ENABLE_LOGGING_AND_PROFILING
456void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
457 // Prints "/" + re.source + "/" +
458 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
459 LogMessageBuilder msg;
460
461 Handle<Object> source = GetProperty(regexp, "source");
462 if (!source->IsString()) {
463 msg.Append("no source");
464 return;
465 }
466
467 switch (regexp->TypeTag()) {
468 case JSRegExp::ATOM:
469 msg.Append('a');
470 break;
471 default:
472 break;
473 }
474 msg.Append('/');
475 msg.AppendDetailed(*Handle<String>::cast(source), false);
476 msg.Append('/');
477
478 // global flag
479 Handle<Object> global = GetProperty(regexp, "global");
480 if (global->IsTrue()) {
481 msg.Append('g');
482 }
483 // ignorecase flag
484 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
485 if (ignorecase->IsTrue()) {
486 msg.Append('i');
487 }
488 // multiline flag
489 Handle<Object> multiline = GetProperty(regexp, "multiline");
490 if (multiline->IsTrue()) {
491 msg.Append('m');
492 }
493
494 msg.WriteToLogFile();
495}
496#endif // ENABLE_LOGGING_AND_PROFILING
497
498
499void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
500#ifdef ENABLE_LOGGING_AND_PROFILING
501 if (!Log::IsEnabled() || !FLAG_log_regexp) return;
502 LogMessageBuilder msg;
503 msg.Append("regexp-compile,");
504 LogRegExpSource(regexp);
505 msg.Append(in_cache ? ",hit\n" : ",miss\n");
506 msg.WriteToLogFile();
507#endif
508}
509
510
511void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
512#ifdef ENABLE_LOGGING_AND_PROFILING
513 if (!Log::IsEnabled() || !FLAG_log_runtime) return;
514 HandleScope scope;
515 LogMessageBuilder msg;
516 for (int i = 0; i < format.length(); i++) {
517 char c = format[i];
518 if (c == '%' && i <= format.length() - 2) {
519 i++;
520 ASSERT('0' <= format[i] && format[i] <= '9');
521 Object* obj = args->GetElement(format[i] - '0');
522 i++;
523 switch (format[i]) {
524 case 's':
525 msg.AppendDetailed(String::cast(obj), false);
526 break;
527 case 'S':
528 msg.AppendDetailed(String::cast(obj), true);
529 break;
530 case 'r':
531 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
532 break;
533 case 'x':
534 msg.Append("0x%x", Smi::cast(obj)->value());
535 break;
536 case 'i':
537 msg.Append("%i", Smi::cast(obj)->value());
538 break;
539 default:
540 UNREACHABLE();
541 }
542 } else {
543 msg.Append(c);
544 }
545 }
546 msg.Append('\n');
547 msg.WriteToLogFile();
548#endif
549}
550
551
552void Logger::ApiIndexedSecurityCheck(uint32_t index) {
553#ifdef ENABLE_LOGGING_AND_PROFILING
554 if (!Log::IsEnabled() || !FLAG_log_api) return;
555 ApiEvent("api,check-security,%u\n", index);
556#endif
557}
558
559
560void Logger::ApiNamedPropertyAccess(const char* tag,
561 JSObject* holder,
562 Object* name) {
563#ifdef ENABLE_LOGGING_AND_PROFILING
564 ASSERT(name->IsString());
565 if (!Log::IsEnabled() || !FLAG_log_api) return;
566 String* class_name_obj = holder->class_name();
567 SmartPointer<char> class_name =
568 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
569 SmartPointer<char> property_name =
570 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
571 Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
572#endif
573}
574
575void Logger::ApiIndexedPropertyAccess(const char* tag,
576 JSObject* holder,
577 uint32_t index) {
578#ifdef ENABLE_LOGGING_AND_PROFILING
579 if (!Log::IsEnabled() || !FLAG_log_api) return;
580 String* class_name_obj = holder->class_name();
581 SmartPointer<char> class_name =
582 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
583 Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
584#endif
585}
586
587void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
588#ifdef ENABLE_LOGGING_AND_PROFILING
589 if (!Log::IsEnabled() || !FLAG_log_api) return;
590 String* class_name_obj = object->class_name();
591 SmartPointer<char> class_name =
592 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
593 Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
594#endif
595}
596
597
598void Logger::ApiEntryCall(const char* name) {
599#ifdef ENABLE_LOGGING_AND_PROFILING
600 if (!Log::IsEnabled() || !FLAG_log_api) return;
601 Logger::ApiEvent("api,%s\n", name);
602#endif
603}
604
605
606void Logger::NewEvent(const char* name, void* object, size_t size) {
607#ifdef ENABLE_LOGGING_AND_PROFILING
608 if (!Log::IsEnabled() || !FLAG_log) return;
609 LogMessageBuilder msg;
610 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
611 static_cast<unsigned int>(size));
612 msg.WriteToLogFile();
613#endif
614}
615
616
617void Logger::DeleteEvent(const char* name, void* object) {
618#ifdef ENABLE_LOGGING_AND_PROFILING
619 if (!Log::IsEnabled() || !FLAG_log) return;
620 LogMessageBuilder msg;
621 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
622 msg.WriteToLogFile();
623#endif
624}
625
626
627#ifdef ENABLE_LOGGING_AND_PROFILING
628
629// A class that contains all common code dealing with record compression.
630class CompressionHelper {
631 public:
632 explicit CompressionHelper(int window_size)
633 : compressor_(window_size), repeat_count_(0) { }
634
635 // Handles storing message in compressor, retrieving the previous one and
636 // prefixing it with repeat count, if needed.
637 // Returns true if message needs to be written to log.
638 bool HandleMessage(LogMessageBuilder* msg) {
639 if (!msg->StoreInCompressor(&compressor_)) {
640 // Current message repeats the previous one, don't write it.
641 ++repeat_count_;
642 return false;
643 }
644 if (repeat_count_ == 0) {
645 return msg->RetrieveCompressedPrevious(&compressor_);
646 }
647 OS::SNPrintF(prefix_, "%s,%d,",
648 Logger::log_events_[Logger::REPEAT_META_EVENT],
649 repeat_count_ + 1);
650 repeat_count_ = 0;
651 return msg->RetrieveCompressedPrevious(&compressor_, prefix_.start());
652 }
653
654 private:
655 LogRecordCompressor compressor_;
656 int repeat_count_;
657 EmbeddedVector<char, 20> prefix_;
658};
659
660#endif // ENABLE_LOGGING_AND_PROFILING
661
662
663void Logger::CodeCreateEvent(LogEventsAndTags tag,
664 Code* code,
665 const char* comment) {
666#ifdef ENABLE_LOGGING_AND_PROFILING
667 if (!Log::IsEnabled() || !FLAG_log_code) return;
668 LogMessageBuilder msg;
669 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
670 msg.AppendAddress(code->address());
671 msg.Append(",%d,\"", code->ExecutableSize());
672 for (const char* p = comment; *p != '\0'; p++) {
673 if (*p == '"') {
674 msg.Append('\\');
675 }
676 msg.Append(*p);
677 }
678 msg.Append('"');
679 if (FLAG_compress_log) {
680 ASSERT(compression_helper_ != NULL);
681 if (!compression_helper_->HandleMessage(&msg)) return;
682 }
683 msg.Append('\n');
684 msg.WriteToLogFile();
685#endif
686}
687
688
689void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
690#ifdef ENABLE_LOGGING_AND_PROFILING
691 if (!Log::IsEnabled() || !FLAG_log_code) return;
692 LogMessageBuilder msg;
693 SmartPointer<char> str =
694 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
695 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
696 msg.AppendAddress(code->address());
697 msg.Append(",%d,\"%s\"", code->ExecutableSize(), *str);
698 if (FLAG_compress_log) {
699 ASSERT(compression_helper_ != NULL);
700 if (!compression_helper_->HandleMessage(&msg)) return;
701 }
702 msg.Append('\n');
703 msg.WriteToLogFile();
704#endif
705}
706
707
708void Logger::CodeCreateEvent(LogEventsAndTags tag,
709 Code* code, String* name,
710 String* source, int line) {
711#ifdef ENABLE_LOGGING_AND_PROFILING
712 if (!Log::IsEnabled() || !FLAG_log_code) return;
713 LogMessageBuilder msg;
714 SmartPointer<char> str =
715 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
716 SmartPointer<char> sourcestr =
717 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
718 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
719 msg.AppendAddress(code->address());
720 msg.Append(",%d,\"%s %s:%d\"",
721 code->ExecutableSize(), *str, *sourcestr, line);
722 if (FLAG_compress_log) {
723 ASSERT(compression_helper_ != NULL);
724 if (!compression_helper_->HandleMessage(&msg)) return;
725 }
726 msg.Append('\n');
727 msg.WriteToLogFile();
728#endif
729}
730
731
732void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
733#ifdef ENABLE_LOGGING_AND_PROFILING
734 if (!Log::IsEnabled() || !FLAG_log_code) return;
735 LogMessageBuilder msg;
736 msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
737 msg.AppendAddress(code->address());
738 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
739 if (FLAG_compress_log) {
740 ASSERT(compression_helper_ != NULL);
741 if (!compression_helper_->HandleMessage(&msg)) return;
742 }
743 msg.Append('\n');
744 msg.WriteToLogFile();
745#endif
746}
747
748
749void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
750#ifdef ENABLE_LOGGING_AND_PROFILING
751 if (!Log::IsEnabled() || !FLAG_log_code) return;
752 LogMessageBuilder msg;
753 msg.Append("%s,%s,",
754 log_events_[CODE_CREATION_EVENT], log_events_[REG_EXP_TAG]);
755 msg.AppendAddress(code->address());
756 msg.Append(",%d,\"", code->ExecutableSize());
757 msg.AppendDetailed(source, false);
758 msg.Append('\"');
759 if (FLAG_compress_log) {
760 ASSERT(compression_helper_ != NULL);
761 if (!compression_helper_->HandleMessage(&msg)) return;
762 }
763 msg.Append('\n');
764 msg.WriteToLogFile();
765#endif
766}
767
768
769void Logger::CodeMoveEvent(Address from, Address to) {
770#ifdef ENABLE_LOGGING_AND_PROFILING
771 static Address prev_to_ = NULL;
772 if (!Log::IsEnabled() || !FLAG_log_code) return;
773 LogMessageBuilder msg;
774 msg.Append("%s,", log_events_[CODE_MOVE_EVENT]);
775 msg.AppendAddress(from);
776 msg.Append(',');
777 msg.AppendAddress(to, prev_to_);
778 prev_to_ = to;
779 if (FLAG_compress_log) {
780 ASSERT(compression_helper_ != NULL);
781 if (!compression_helper_->HandleMessage(&msg)) return;
782 }
783 msg.Append('\n');
784 msg.WriteToLogFile();
785#endif
786}
787
788
789void Logger::CodeDeleteEvent(Address from) {
790#ifdef ENABLE_LOGGING_AND_PROFILING
791 if (!Log::IsEnabled() || !FLAG_log_code) return;
792 LogMessageBuilder msg;
793 msg.Append("%s,", log_events_[CODE_DELETE_EVENT]);
794 msg.AppendAddress(from);
795 if (FLAG_compress_log) {
796 ASSERT(compression_helper_ != NULL);
797 if (!compression_helper_->HandleMessage(&msg)) return;
798 }
799 msg.Append('\n');
800 msg.WriteToLogFile();
801#endif
802}
803
804
805void Logger::ResourceEvent(const char* name, const char* tag) {
806#ifdef ENABLE_LOGGING_AND_PROFILING
807 if (!Log::IsEnabled() || !FLAG_log) return;
808 LogMessageBuilder msg;
809 msg.Append("%s,%s,", name, tag);
810
811 uint32_t sec, usec;
812 if (OS::GetUserTime(&sec, &usec) != -1) {
813 msg.Append("%d,%d,", sec, usec);
814 }
815 msg.Append("%.0f", OS::TimeCurrentMillis());
816
817 msg.Append('\n');
818 msg.WriteToLogFile();
819#endif
820}
821
822
823void Logger::SuspectReadEvent(String* name, Object* obj) {
824#ifdef ENABLE_LOGGING_AND_PROFILING
825 if (!Log::IsEnabled() || !FLAG_log_suspect) return;
826 LogMessageBuilder msg;
827 String* class_name = obj->IsJSObject()
828 ? JSObject::cast(obj)->class_name()
829 : Heap::empty_string();
830 msg.Append("suspect-read,");
831 msg.Append(class_name);
832 msg.Append(',');
833 msg.Append('"');
834 msg.Append(name);
835 msg.Append('"');
836 msg.Append('\n');
837 msg.WriteToLogFile();
838#endif
839}
840
841
842void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
843#ifdef ENABLE_LOGGING_AND_PROFILING
844 if (!Log::IsEnabled() || !FLAG_log_gc) return;
845 LogMessageBuilder msg;
846 // Using non-relative system time in order to be able to synchronize with
847 // external memory profiling events (e.g. DOM memory size).
848 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
849 space, kind, OS::TimeCurrentMillis());
850 msg.WriteToLogFile();
851#endif
852}
853
854
855void Logger::HeapSampleStats(const char* space, const char* kind,
856 int capacity, int used) {
857#ifdef ENABLE_LOGGING_AND_PROFILING
858 if (!Log::IsEnabled() || !FLAG_log_gc) return;
859 LogMessageBuilder msg;
860 msg.Append("heap-sample-stats,\"%s\",\"%s\",%d,%d\n",
861 space, kind, capacity, used);
862 msg.WriteToLogFile();
863#endif
864}
865
866
867void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
868#ifdef ENABLE_LOGGING_AND_PROFILING
869 if (!Log::IsEnabled() || !FLAG_log_gc) return;
870 LogMessageBuilder msg;
871 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
872 msg.WriteToLogFile();
873#endif
874}
875
876
877void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
878#ifdef ENABLE_LOGGING_AND_PROFILING
879 if (!Log::IsEnabled() || !FLAG_log_gc) return;
880 LogMessageBuilder msg;
881 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
882 msg.WriteToLogFile();
883#endif
884}
885
886
887void Logger::HeapSampleJSConstructorEvent(const char* constructor,
888 int number, int bytes) {
889#ifdef ENABLE_LOGGING_AND_PROFILING
890 if (!Log::IsEnabled() || !FLAG_log_gc) return;
891 LogMessageBuilder msg;
892 msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
893 msg.WriteToLogFile();
894#endif
895}
896
897
898void Logger::HeapSampleJSRetainersEvent(
899 const char* constructor, const char* event) {
900#ifdef ENABLE_LOGGING_AND_PROFILING
901 if (!Log::IsEnabled() || !FLAG_log_gc) return;
902 // Event starts with comma, so we don't have it in the format string.
903 static const char* event_text = "heap-js-ret-item,%s";
904 // We take placeholder strings into account, but it's OK to be conservative.
905 static const int event_text_len = strlen(event_text);
906 const int cons_len = strlen(constructor), event_len = strlen(event);
907 int pos = 0;
908 // Retainer lists can be long. We may need to split them into multiple events.
909 do {
910 LogMessageBuilder msg;
911 msg.Append(event_text, constructor);
912 int to_write = event_len - pos;
913 if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) {
914 int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len);
915 ASSERT(cut_pos < event_len);
916 while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
917 if (event[cut_pos] != ',') {
918 // Crash in debug mode, skip in release mode.
919 ASSERT(false);
920 return;
921 }
922 // Append a piece of event that fits, without trailing comma.
923 msg.AppendStringPart(event + pos, cut_pos - pos);
924 // Start next piece with comma.
925 pos = cut_pos;
926 } else {
927 msg.Append("%s", event + pos);
928 pos += event_len;
929 }
930 msg.Append('\n');
931 msg.WriteToLogFile();
932 } while (pos < event_len);
933#endif
934}
935
936
937void Logger::DebugTag(const char* call_site_tag) {
938#ifdef ENABLE_LOGGING_AND_PROFILING
939 if (!Log::IsEnabled() || !FLAG_log) return;
940 LogMessageBuilder msg;
941 msg.Append("debug-tag,%s\n", call_site_tag);
942 msg.WriteToLogFile();
943#endif
944}
945
946
947void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
948#ifdef ENABLE_LOGGING_AND_PROFILING
949 if (!Log::IsEnabled() || !FLAG_log) return;
950 StringBuilder s(parameter.length() + 1);
951 for (int i = 0; i < parameter.length(); ++i) {
952 s.AddCharacter(static_cast<char>(parameter[i]));
953 }
954 char* parameter_string = s.Finalize();
955 LogMessageBuilder msg;
956 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
957 event_type,
958 OS::TimeCurrentMillis(),
959 parameter_string);
960 DeleteArray(parameter_string);
961 msg.WriteToLogFile();
962#endif
963}
964
965
966#ifdef ENABLE_LOGGING_AND_PROFILING
967void Logger::TickEvent(TickSample* sample, bool overflow) {
968 if (!Log::IsEnabled() || !FLAG_prof) return;
969 static Address prev_sp = NULL;
970 LogMessageBuilder msg;
971 msg.Append("%s,", log_events_[TICK_EVENT]);
972 Address prev_addr = reinterpret_cast<Address>(sample->pc);
973 msg.AppendAddress(prev_addr);
974 msg.Append(',');
975 msg.AppendAddress(reinterpret_cast<Address>(sample->sp), prev_sp);
976 prev_sp = reinterpret_cast<Address>(sample->sp);
977 msg.Append(",%d", static_cast<int>(sample->state));
978 if (overflow) {
979 msg.Append(",overflow");
980 }
981 for (int i = 0; i < sample->frames_count; ++i) {
982 msg.Append(',');
983 msg.AppendAddress(sample->stack[i], prev_addr);
984 prev_addr = sample->stack[i];
985 }
986 if (FLAG_compress_log) {
987 ASSERT(compression_helper_ != NULL);
988 if (!compression_helper_->HandleMessage(&msg)) return;
989 }
990 msg.Append('\n');
991 msg.WriteToLogFile();
992}
993
994
995int Logger::GetActiveProfilerModules() {
996 int result = PROFILER_MODULE_NONE;
997 if (!profiler_->paused()) {
998 result |= PROFILER_MODULE_CPU;
999 }
1000 if (FLAG_log_gc) {
1001 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1002 }
1003 return result;
1004}
1005
1006
1007void Logger::PauseProfiler(int flags) {
1008 if (!Log::IsEnabled()) return;
1009 const int active_modules = GetActiveProfilerModules();
1010 const int modules_to_disable = active_modules & flags;
1011 if (modules_to_disable == PROFILER_MODULE_NONE) return;
1012
1013 if (modules_to_disable & PROFILER_MODULE_CPU) {
1014 profiler_->pause();
1015 if (FLAG_prof_lazy) {
1016 if (!FLAG_sliding_state_window) ticker_->Stop();
1017 FLAG_log_code = false;
1018 // Must be the same message as Log::kDynamicBufferSeal.
1019 LOG(UncheckedStringEvent("profiler", "pause"));
1020 }
1021 }
1022 if (modules_to_disable &
1023 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
1024 FLAG_log_gc = false;
1025 }
1026 // Turn off logging if no active modules remain.
1027 if ((active_modules & ~flags) == PROFILER_MODULE_NONE) {
1028 is_logging_ = false;
1029 }
1030}
1031
1032
1033void Logger::ResumeProfiler(int flags) {
1034 if (!Log::IsEnabled()) return;
1035 const int modules_to_enable = ~GetActiveProfilerModules() & flags;
1036 if (modules_to_enable != PROFILER_MODULE_NONE) {
1037 is_logging_ = true;
1038 }
1039 if (modules_to_enable & PROFILER_MODULE_CPU) {
1040 if (FLAG_prof_lazy) {
1041 LOG(UncheckedStringEvent("profiler", "resume"));
1042 FLAG_log_code = true;
1043 LogCompiledFunctions();
1044 if (!FLAG_sliding_state_window) ticker_->Start();
1045 }
1046 profiler_->resume();
1047 }
1048 if (modules_to_enable &
1049 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
1050 FLAG_log_gc = true;
1051 }
1052}
1053
1054
1055// This function can be called when Log's mutex is acquired,
1056// either from main or Profiler's thread.
1057void Logger::StopLoggingAndProfiling() {
1058 Log::stop();
1059 PauseProfiler(PROFILER_MODULE_CPU);
1060}
1061
1062
1063bool Logger::IsProfilerSamplerActive() {
1064 return ticker_->IsActive();
1065}
1066
1067
1068int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1069 return Log::GetLogLines(from_pos, dest_buf, max_size);
1070}
1071
1072
1073void Logger::LogCompiledFunctions() {
1074 HandleScope scope;
1075 Handle<SharedFunctionInfo>* sfis = NULL;
1076 int compiled_funcs_count = 0;
1077
1078 {
1079 AssertNoAllocation no_alloc;
1080
1081 HeapIterator iterator;
1082 while (iterator.has_next()) {
1083 HeapObject* obj = iterator.next();
1084 ASSERT(obj != NULL);
1085 if (obj->IsSharedFunctionInfo()
1086 && SharedFunctionInfo::cast(obj)->is_compiled()) {
1087 ++compiled_funcs_count;
1088 }
1089 }
1090
1091 sfis = NewArray< Handle<SharedFunctionInfo> >(compiled_funcs_count);
1092 iterator.reset();
1093
1094 int i = 0;
1095 while (iterator.has_next()) {
1096 HeapObject* obj = iterator.next();
1097 ASSERT(obj != NULL);
1098 if (obj->IsSharedFunctionInfo()
1099 && SharedFunctionInfo::cast(obj)->is_compiled()) {
1100 sfis[i++] = Handle<SharedFunctionInfo>(SharedFunctionInfo::cast(obj));
1101 }
1102 }
1103 }
1104
1105 // During iteration, there can be heap allocation due to
1106 // GetScriptLineNumber call.
1107 for (int i = 0; i < compiled_funcs_count; ++i) {
1108 Handle<SharedFunctionInfo> shared = sfis[i];
1109 Handle<String> name(String::cast(shared->name()));
1110 Handle<String> func_name(name->length() > 0 ?
1111 *name : shared->inferred_name());
1112 if (shared->script()->IsScript()) {
1113 Handle<Script> script(Script::cast(shared->script()));
1114 if (script->name()->IsString()) {
1115 Handle<String> script_name(String::cast(script->name()));
1116 int line_num = GetScriptLineNumber(script, shared->start_position());
1117 if (line_num > 0) {
1118 LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG,
1119 shared->code(), *func_name,
1120 *script_name, line_num + 1));
1121 } else {
1122 // Can't distinguish enum and script here, so always use Script.
1123 LOG(CodeCreateEvent(Logger::SCRIPT_TAG,
1124 shared->code(), *script_name));
1125 }
1126 continue;
1127 }
1128 }
1129 // If no script or script has no name.
1130 LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
1131 }
1132
1133 DeleteArray(sfis);
1134}
1135
1136#endif
1137
1138
1139bool Logger::Setup() {
1140#ifdef ENABLE_LOGGING_AND_PROFILING
1141 // --log-all enables all the log flags.
1142 if (FLAG_log_all) {
1143 FLAG_log_runtime = true;
1144 FLAG_log_api = true;
1145 FLAG_log_code = true;
1146 FLAG_log_gc = true;
1147 FLAG_log_suspect = true;
1148 FLAG_log_handles = true;
1149 FLAG_log_regexp = true;
1150 }
1151
1152 // --prof implies --log-code.
1153 if (FLAG_prof) FLAG_log_code = true;
1154
1155 // --prof_lazy controls --log-code, implies --noprof_auto.
1156 if (FLAG_prof_lazy) {
1157 FLAG_log_code = false;
1158 FLAG_prof_auto = false;
1159 }
1160
1161 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1162 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1163 || FLAG_log_regexp || FLAG_log_state_changes;
1164
1165 bool open_log_file = start_logging || FLAG_prof_lazy;
1166
1167 // If we're logging anything, we need to open the log file.
1168 if (open_log_file) {
1169 if (strcmp(FLAG_logfile, "-") == 0) {
1170 Log::OpenStdout();
1171 } else if (strcmp(FLAG_logfile, "*") == 0) {
1172 Log::OpenMemoryBuffer();
1173 } else if (strchr(FLAG_logfile, '%') != NULL) {
1174 // If there's a '%' in the log file name we have to expand
1175 // placeholders.
1176 HeapStringAllocator allocator;
1177 StringStream stream(&allocator);
1178 for (const char* p = FLAG_logfile; *p; p++) {
1179 if (*p == '%') {
1180 p++;
1181 switch (*p) {
1182 case '\0':
1183 // If there's a % at the end of the string we back up
1184 // one character so we can escape the loop properly.
1185 p--;
1186 break;
1187 case 't': {
1188 // %t expands to the current time in milliseconds.
1189 double time = OS::TimeCurrentMillis();
1190 stream.Add("%.0f", FmtElm(time));
1191 break;
1192 }
1193 case '%':
1194 // %% expands (contracts really) to %.
1195 stream.Put('%');
1196 break;
1197 default:
1198 // All other %'s expand to themselves.
1199 stream.Put('%');
1200 stream.Put(*p);
1201 break;
1202 }
1203 } else {
1204 stream.Put(*p);
1205 }
1206 }
1207 SmartPointer<const char> expanded = stream.ToCString();
1208 Log::OpenFile(*expanded);
1209 } else {
1210 Log::OpenFile(FLAG_logfile);
1211 }
1212 }
1213
1214 current_state_ = &bottom_state_;
1215
1216 ticker_ = new Ticker(kSamplingIntervalMs);
1217
1218 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1219 sliding_state_window_ = new SlidingStateWindow();
1220 }
1221
1222 log_events_ = FLAG_compress_log ?
1223 kCompressedLogEventsNames : kLongLogEventsNames;
1224 if (FLAG_compress_log) {
1225 compression_helper_ = new CompressionHelper(kCompressionWindowSize);
1226 }
1227
1228 is_logging_ = start_logging;
1229
1230 if (FLAG_prof) {
1231 profiler_ = new Profiler();
1232 if (!FLAG_prof_auto) {
1233 profiler_->pause();
1234 } else {
1235 is_logging_ = true;
1236 }
1237 profiler_->Engage();
1238 }
1239
1240 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
1241
1242 return true;
1243
1244#else
1245 return false;
1246#endif
1247}
1248
1249
1250void Logger::TearDown() {
1251#ifdef ENABLE_LOGGING_AND_PROFILING
1252 LogMessageBuilder::set_write_failure_handler(NULL);
1253
1254 // Stop the profiler before closing the file.
1255 if (profiler_ != NULL) {
1256 profiler_->Disengage();
1257 delete profiler_;
1258 profiler_ = NULL;
1259 }
1260
1261 delete compression_helper_;
1262 compression_helper_ = NULL;
1263
1264 delete sliding_state_window_;
1265 sliding_state_window_ = NULL;
1266
1267 delete ticker_;
1268 ticker_ = NULL;
1269
1270 Log::Close();
1271#endif
1272}
1273
1274
1275void Logger::EnableSlidingStateWindow() {
1276#ifdef ENABLE_LOGGING_AND_PROFILING
1277 // If the ticker is NULL, Logger::Setup has not been called yet. In
1278 // that case, we set the sliding_state_window flag so that the
1279 // sliding window computation will be started when Logger::Setup is
1280 // called.
1281 if (ticker_ == NULL) {
1282 FLAG_sliding_state_window = true;
1283 return;
1284 }
1285 // Otherwise, if the sliding state window computation has not been
1286 // started we do it now.
1287 if (sliding_state_window_ == NULL) {
1288 sliding_state_window_ = new SlidingStateWindow();
1289 }
1290#endif
1291}
1292
1293
1294} } // namespace v8::internal