blob: d1d9a31e49b1b76a8201f9a13d8849a2f9bc299d [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
Steve Block3ce2e202009-11-05 08:53:23 +0000937void Logger::HeapSampleJSProducerEvent(const char* constructor,
938 Address* stack) {
939#ifdef ENABLE_LOGGING_AND_PROFILING
940 if (!Log::IsEnabled() || !FLAG_log_gc) return;
941 LogMessageBuilder msg;
942 msg.Append("heap-js-prod-item,%s", constructor);
943 while (*stack != NULL) {
944 msg.Append(",0x%" V8PRIxPTR, *stack++);
945 }
946 msg.Append("\n");
947 msg.WriteToLogFile();
948#endif
949}
950
951
Steve Blocka7e24c12009-10-30 11:49:00 +0000952void Logger::DebugTag(const char* call_site_tag) {
953#ifdef ENABLE_LOGGING_AND_PROFILING
954 if (!Log::IsEnabled() || !FLAG_log) return;
955 LogMessageBuilder msg;
956 msg.Append("debug-tag,%s\n", call_site_tag);
957 msg.WriteToLogFile();
958#endif
959}
960
961
962void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
963#ifdef ENABLE_LOGGING_AND_PROFILING
964 if (!Log::IsEnabled() || !FLAG_log) return;
965 StringBuilder s(parameter.length() + 1);
966 for (int i = 0; i < parameter.length(); ++i) {
967 s.AddCharacter(static_cast<char>(parameter[i]));
968 }
969 char* parameter_string = s.Finalize();
970 LogMessageBuilder msg;
971 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
972 event_type,
973 OS::TimeCurrentMillis(),
974 parameter_string);
975 DeleteArray(parameter_string);
976 msg.WriteToLogFile();
977#endif
978}
979
980
981#ifdef ENABLE_LOGGING_AND_PROFILING
982void Logger::TickEvent(TickSample* sample, bool overflow) {
983 if (!Log::IsEnabled() || !FLAG_prof) return;
984 static Address prev_sp = NULL;
985 LogMessageBuilder msg;
986 msg.Append("%s,", log_events_[TICK_EVENT]);
987 Address prev_addr = reinterpret_cast<Address>(sample->pc);
988 msg.AppendAddress(prev_addr);
989 msg.Append(',');
990 msg.AppendAddress(reinterpret_cast<Address>(sample->sp), prev_sp);
991 prev_sp = reinterpret_cast<Address>(sample->sp);
992 msg.Append(",%d", static_cast<int>(sample->state));
993 if (overflow) {
994 msg.Append(",overflow");
995 }
996 for (int i = 0; i < sample->frames_count; ++i) {
997 msg.Append(',');
998 msg.AppendAddress(sample->stack[i], prev_addr);
999 prev_addr = sample->stack[i];
1000 }
1001 if (FLAG_compress_log) {
1002 ASSERT(compression_helper_ != NULL);
1003 if (!compression_helper_->HandleMessage(&msg)) return;
1004 }
1005 msg.Append('\n');
1006 msg.WriteToLogFile();
1007}
1008
1009
1010int Logger::GetActiveProfilerModules() {
1011 int result = PROFILER_MODULE_NONE;
1012 if (!profiler_->paused()) {
1013 result |= PROFILER_MODULE_CPU;
1014 }
1015 if (FLAG_log_gc) {
1016 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1017 }
1018 return result;
1019}
1020
1021
1022void Logger::PauseProfiler(int flags) {
1023 if (!Log::IsEnabled()) return;
1024 const int active_modules = GetActiveProfilerModules();
1025 const int modules_to_disable = active_modules & flags;
1026 if (modules_to_disable == PROFILER_MODULE_NONE) return;
1027
1028 if (modules_to_disable & PROFILER_MODULE_CPU) {
1029 profiler_->pause();
1030 if (FLAG_prof_lazy) {
1031 if (!FLAG_sliding_state_window) ticker_->Stop();
1032 FLAG_log_code = false;
1033 // Must be the same message as Log::kDynamicBufferSeal.
1034 LOG(UncheckedStringEvent("profiler", "pause"));
1035 }
1036 }
1037 if (modules_to_disable &
1038 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
1039 FLAG_log_gc = false;
1040 }
1041 // Turn off logging if no active modules remain.
1042 if ((active_modules & ~flags) == PROFILER_MODULE_NONE) {
1043 is_logging_ = false;
1044 }
1045}
1046
1047
1048void Logger::ResumeProfiler(int flags) {
1049 if (!Log::IsEnabled()) return;
1050 const int modules_to_enable = ~GetActiveProfilerModules() & flags;
1051 if (modules_to_enable != PROFILER_MODULE_NONE) {
1052 is_logging_ = true;
1053 }
1054 if (modules_to_enable & PROFILER_MODULE_CPU) {
1055 if (FLAG_prof_lazy) {
1056 LOG(UncheckedStringEvent("profiler", "resume"));
1057 FLAG_log_code = true;
1058 LogCompiledFunctions();
1059 if (!FLAG_sliding_state_window) ticker_->Start();
1060 }
1061 profiler_->resume();
1062 }
1063 if (modules_to_enable &
1064 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
1065 FLAG_log_gc = true;
1066 }
1067}
1068
1069
1070// This function can be called when Log's mutex is acquired,
1071// either from main or Profiler's thread.
1072void Logger::StopLoggingAndProfiling() {
1073 Log::stop();
1074 PauseProfiler(PROFILER_MODULE_CPU);
1075}
1076
1077
1078bool Logger::IsProfilerSamplerActive() {
1079 return ticker_->IsActive();
1080}
1081
1082
1083int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1084 return Log::GetLogLines(from_pos, dest_buf, max_size);
1085}
1086
1087
Steve Block3ce2e202009-11-05 08:53:23 +00001088static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis) {
1089 AssertNoAllocation no_alloc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001090 int compiled_funcs_count = 0;
Steve Block3ce2e202009-11-05 08:53:23 +00001091 HeapIterator iterator;
1092 while (iterator.has_next()) {
1093 HeapObject* obj = iterator.next();
1094 ASSERT(obj != NULL);
1095 if (!obj->IsSharedFunctionInfo()) continue;
1096 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1097 if (sfi->is_compiled()
1098 && (!sfi->script()->IsScript()
1099 || Script::cast(sfi->script())->HasValidSource())) {
1100 if (sfis != NULL)
1101 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1102 ++compiled_funcs_count;
Steve Blocka7e24c12009-10-30 11:49:00 +00001103 }
1104 }
Steve Block3ce2e202009-11-05 08:53:23 +00001105 return compiled_funcs_count;
1106}
1107
1108
1109void Logger::LogCompiledFunctions() {
1110 HandleScope scope;
1111 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL);
1112 Handle<SharedFunctionInfo>* sfis =
1113 NewArray< Handle<SharedFunctionInfo> >(compiled_funcs_count);
1114 EnumerateCompiledFunctions(sfis);
Steve Blocka7e24c12009-10-30 11:49:00 +00001115
1116 // During iteration, there can be heap allocation due to
1117 // GetScriptLineNumber call.
1118 for (int i = 0; i < compiled_funcs_count; ++i) {
1119 Handle<SharedFunctionInfo> shared = sfis[i];
1120 Handle<String> name(String::cast(shared->name()));
1121 Handle<String> func_name(name->length() > 0 ?
1122 *name : shared->inferred_name());
1123 if (shared->script()->IsScript()) {
1124 Handle<Script> script(Script::cast(shared->script()));
1125 if (script->name()->IsString()) {
1126 Handle<String> script_name(String::cast(script->name()));
1127 int line_num = GetScriptLineNumber(script, shared->start_position());
1128 if (line_num > 0) {
1129 LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG,
1130 shared->code(), *func_name,
1131 *script_name, line_num + 1));
1132 } else {
1133 // Can't distinguish enum and script here, so always use Script.
1134 LOG(CodeCreateEvent(Logger::SCRIPT_TAG,
1135 shared->code(), *script_name));
1136 }
1137 continue;
1138 }
1139 }
1140 // If no script or script has no name.
1141 LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
1142 }
1143
1144 DeleteArray(sfis);
1145}
1146
1147#endif
1148
1149
1150bool Logger::Setup() {
1151#ifdef ENABLE_LOGGING_AND_PROFILING
1152 // --log-all enables all the log flags.
1153 if (FLAG_log_all) {
1154 FLAG_log_runtime = true;
1155 FLAG_log_api = true;
1156 FLAG_log_code = true;
1157 FLAG_log_gc = true;
1158 FLAG_log_suspect = true;
1159 FLAG_log_handles = true;
1160 FLAG_log_regexp = true;
1161 }
1162
1163 // --prof implies --log-code.
1164 if (FLAG_prof) FLAG_log_code = true;
1165
1166 // --prof_lazy controls --log-code, implies --noprof_auto.
1167 if (FLAG_prof_lazy) {
1168 FLAG_log_code = false;
1169 FLAG_prof_auto = false;
1170 }
1171
1172 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1173 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1174 || FLAG_log_regexp || FLAG_log_state_changes;
1175
1176 bool open_log_file = start_logging || FLAG_prof_lazy;
1177
1178 // If we're logging anything, we need to open the log file.
1179 if (open_log_file) {
1180 if (strcmp(FLAG_logfile, "-") == 0) {
1181 Log::OpenStdout();
1182 } else if (strcmp(FLAG_logfile, "*") == 0) {
1183 Log::OpenMemoryBuffer();
1184 } else if (strchr(FLAG_logfile, '%') != NULL) {
1185 // If there's a '%' in the log file name we have to expand
1186 // placeholders.
1187 HeapStringAllocator allocator;
1188 StringStream stream(&allocator);
1189 for (const char* p = FLAG_logfile; *p; p++) {
1190 if (*p == '%') {
1191 p++;
1192 switch (*p) {
1193 case '\0':
1194 // If there's a % at the end of the string we back up
1195 // one character so we can escape the loop properly.
1196 p--;
1197 break;
1198 case 't': {
1199 // %t expands to the current time in milliseconds.
1200 double time = OS::TimeCurrentMillis();
1201 stream.Add("%.0f", FmtElm(time));
1202 break;
1203 }
1204 case '%':
1205 // %% expands (contracts really) to %.
1206 stream.Put('%');
1207 break;
1208 default:
1209 // All other %'s expand to themselves.
1210 stream.Put('%');
1211 stream.Put(*p);
1212 break;
1213 }
1214 } else {
1215 stream.Put(*p);
1216 }
1217 }
1218 SmartPointer<const char> expanded = stream.ToCString();
1219 Log::OpenFile(*expanded);
1220 } else {
1221 Log::OpenFile(FLAG_logfile);
1222 }
1223 }
1224
1225 current_state_ = &bottom_state_;
1226
1227 ticker_ = new Ticker(kSamplingIntervalMs);
1228
1229 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1230 sliding_state_window_ = new SlidingStateWindow();
1231 }
1232
1233 log_events_ = FLAG_compress_log ?
1234 kCompressedLogEventsNames : kLongLogEventsNames;
1235 if (FLAG_compress_log) {
1236 compression_helper_ = new CompressionHelper(kCompressionWindowSize);
1237 }
1238
1239 is_logging_ = start_logging;
1240
1241 if (FLAG_prof) {
1242 profiler_ = new Profiler();
1243 if (!FLAG_prof_auto) {
1244 profiler_->pause();
1245 } else {
1246 is_logging_ = true;
1247 }
1248 profiler_->Engage();
1249 }
1250
1251 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
1252
1253 return true;
1254
1255#else
1256 return false;
1257#endif
1258}
1259
1260
1261void Logger::TearDown() {
1262#ifdef ENABLE_LOGGING_AND_PROFILING
1263 LogMessageBuilder::set_write_failure_handler(NULL);
1264
1265 // Stop the profiler before closing the file.
1266 if (profiler_ != NULL) {
1267 profiler_->Disengage();
1268 delete profiler_;
1269 profiler_ = NULL;
1270 }
1271
1272 delete compression_helper_;
1273 compression_helper_ = NULL;
1274
1275 delete sliding_state_window_;
1276 sliding_state_window_ = NULL;
1277
1278 delete ticker_;
1279 ticker_ = NULL;
1280
1281 Log::Close();
1282#endif
1283}
1284
1285
1286void Logger::EnableSlidingStateWindow() {
1287#ifdef ENABLE_LOGGING_AND_PROFILING
1288 // If the ticker is NULL, Logger::Setup has not been called yet. In
1289 // that case, we set the sliding_state_window flag so that the
1290 // sliding window computation will be started when Logger::Setup is
1291 // called.
1292 if (ticker_ == NULL) {
1293 FLAG_sliding_state_window = true;
1294 return;
1295 }
1296 // Otherwise, if the sliding state window computation has not been
1297 // started we do it now.
1298 if (sliding_state_window_ == NULL) {
1299 sliding_state_window_ = new SlidingStateWindow();
1300 }
1301#endif
1302}
1303
1304
1305} } // namespace v8::internal