1 // 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
38 namespace v8 {
39 namespace 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 //
48 class 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
IncrementStateCounter(StateTag state)61 void IncrementStateCounter(StateTag state) {
62 Counters::state_counters[state].Increment();
63 }
64
65
DecrementStateCounter(StateTag state)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 //
78 class Profiler: public Thread {
79 public:
80 Profiler();
81 void Engage();
82 void Disengage();
83
84 // Inserts collected profiling data into buffer.
Insert(TickSample * sample)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.
Remove(TickSample * sample)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.
paused()111 static bool paused() { return paused_; }
pause()112 static void pause() { paused_ = true; }
resume()113 static void resume() { paused_ = false; }
114
115 private:
116 // Returns the next index in the cyclic buffer.
Succ(int index)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
135 bool Profiler::paused_ = false;
136
137
138 //
139 // StackTracer implementation
140 //
Trace(TickSample * sample)141 void 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 //
172 class Ticker: public Sampler {
173 public:
Ticker(int interval)174 explicit Ticker(int interval):
175 Sampler(interval, FLAG_prof), window_(NULL), profiler_(NULL) {}
176
~Ticker()177 ~Ticker() { if (IsActive()) Stop(); }
178
SampleStack(TickSample * sample)179 void SampleStack(TickSample* sample) {
180 StackTracer::Trace(sample);
181 }
182
Tick(TickSample * sample)183 void Tick(TickSample* sample) {
184 if (profiler_) profiler_->Insert(sample);
185 if (window_) window_->AddState(sample->state);
186 }
187
SetWindow(SlidingStateWindow * window)188 void SetWindow(SlidingStateWindow* window) {
189 window_ = window;
190 if (!IsActive()) Start();
191 }
192
ClearWindow()193 void ClearWindow() {
194 window_ = NULL;
195 if (!profiler_ && IsActive()) Stop();
196 }
197
SetProfiler(Profiler * profiler)198 void SetProfiler(Profiler* profiler) {
199 profiler_ = profiler;
200 if (!FLAG_prof_lazy && !IsActive()) Start();
201 }
202
ClearProfiler()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 //
SlidingStateWindow()217 SlidingStateWindow::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
~SlidingStateWindow()225 SlidingStateWindow::~SlidingStateWindow() {
226 Logger::ticker_->ClearWindow();
227 }
228
229
AddState(StateTag state)230 void 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 //
Profiler()246 Profiler::Profiler() {
247 buffer_semaphore_ = OS::CreateSemaphore(0);
248 head_ = 0;
249 tail_ = 0;
250 overflow_ = false;
251 running_ = false;
252 }
253
254
Engage()255 void 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
Disengage()270 void 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
Run()288 void 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 //
301 Ticker* Logger::ticker_ = NULL;
302 Profiler* Logger::profiler_ = NULL;
303 VMState* Logger::current_state_ = NULL;
304 VMState Logger::bottom_state_(EXTERNAL);
305 SlidingStateWindow* Logger::sliding_state_window_ = NULL;
306 const char** Logger::log_events_ = NULL;
307 CompressionHelper* Logger::compression_helper_ = NULL;
308 bool Logger::is_logging_ = false;
309
310 #define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name,
311 const 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,
317 const char* kCompressedLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
318 LOG_EVENTS_AND_TAGS_LIST(DECLARE_SHORT_EVENT)
319 };
320 #undef DECLARE_SHORT_EVENT
321
322
ProfilerBeginEvent()323 void 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
LogAliases()334 void 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
Preamble(const char * content)347 void 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
StringEvent(const char * name,const char * value)356 void 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
UncheckedStringEvent(const char * name,const char * value)364 void 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
IntEvent(const char * name,int value)373 void 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
HandleEvent(const char * name,Object ** location)383 void 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.
ApiEvent(const char * format,...)397 void 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
ApiNamedSecurityCheck(Object * key)409 void 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
SharedLibraryEvent(const char * library_path,uintptr_t start,uintptr_t end)425 void 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
SharedLibraryEvent(const wchar_t * library_path,uintptr_t start,uintptr_t end)440 void 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
LogRegExpSource(Handle<JSRegExp> regexp)456 void 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
RegExpCompileEvent(Handle<JSRegExp> regexp,bool in_cache)499 void 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
LogRuntime(Vector<const char> format,JSArray * args)511 void 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
ApiIndexedSecurityCheck(uint32_t index)552 void 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
ApiNamedPropertyAccess(const char * tag,JSObject * holder,Object * name)560 void 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
ApiIndexedPropertyAccess(const char * tag,JSObject * holder,uint32_t index)575 void 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
ApiObjectAccess(const char * tag,JSObject * object)587 void 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
ApiEntryCall(const char * name)598 void 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
NewEvent(const char * name,void * object,size_t size)606 void 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
DeleteEvent(const char * name,void * object)617 void 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.
630 class CompressionHelper {
631 public:
CompressionHelper(int window_size)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.
HandleMessage(LogMessageBuilder * msg)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
CodeCreateEvent(LogEventsAndTags tag,Code * code,const char * comment)663 void 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
CodeCreateEvent(LogEventsAndTags tag,Code * code,String * name)689 void 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
CodeCreateEvent(LogEventsAndTags tag,Code * code,String * name,String * source,int line)708 void 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
CodeCreateEvent(LogEventsAndTags tag,Code * code,int args_count)732 void 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
RegExpCodeCreateEvent(Code * code,String * source)749 void 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
CodeMoveEvent(Address from,Address to)769 void 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
CodeDeleteEvent(Address from)789 void 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
ResourceEvent(const char * name,const char * tag)805 void 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
SuspectReadEvent(String * name,Object * obj)823 void 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
HeapSampleBeginEvent(const char * space,const char * kind)842 void 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
HeapSampleStats(const char * space,const char * kind,int capacity,int used)855 void 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
HeapSampleEndEvent(const char * space,const char * kind)867 void 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
HeapSampleItemEvent(const char * type,int number,int bytes)877 void 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
HeapSampleJSConstructorEvent(const char * constructor,int number,int bytes)887 void 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",
893 constructor != NULL ?
894 (constructor[0] != '\0' ? constructor : "(anonymous)") :
895 "(no_constructor)",
896 number, bytes);
897 msg.WriteToLogFile();
898 #endif
899 }
900
901
DebugTag(const char * call_site_tag)902 void Logger::DebugTag(const char* call_site_tag) {
903 #ifdef ENABLE_LOGGING_AND_PROFILING
904 if (!Log::IsEnabled() || !FLAG_log) return;
905 LogMessageBuilder msg;
906 msg.Append("debug-tag,%s\n", call_site_tag);
907 msg.WriteToLogFile();
908 #endif
909 }
910
911
DebugEvent(const char * event_type,Vector<uint16_t> parameter)912 void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
913 #ifdef ENABLE_LOGGING_AND_PROFILING
914 if (!Log::IsEnabled() || !FLAG_log) return;
915 StringBuilder s(parameter.length() + 1);
916 for (int i = 0; i < parameter.length(); ++i) {
917 s.AddCharacter(static_cast<char>(parameter[i]));
918 }
919 char* parameter_string = s.Finalize();
920 LogMessageBuilder msg;
921 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
922 event_type,
923 OS::TimeCurrentMillis(),
924 parameter_string);
925 DeleteArray(parameter_string);
926 msg.WriteToLogFile();
927 #endif
928 }
929
930
931 #ifdef ENABLE_LOGGING_AND_PROFILING
TickEvent(TickSample * sample,bool overflow)932 void Logger::TickEvent(TickSample* sample, bool overflow) {
933 if (!Log::IsEnabled() || !FLAG_prof) return;
934 static Address prev_sp = NULL;
935 LogMessageBuilder msg;
936 msg.Append("%s,", log_events_[TICK_EVENT]);
937 Address prev_addr = reinterpret_cast<Address>(sample->pc);
938 msg.AppendAddress(prev_addr);
939 msg.Append(',');
940 msg.AppendAddress(reinterpret_cast<Address>(sample->sp), prev_sp);
941 prev_sp = reinterpret_cast<Address>(sample->sp);
942 msg.Append(",%d", static_cast<int>(sample->state));
943 if (overflow) {
944 msg.Append(",overflow");
945 }
946 for (int i = 0; i < sample->frames_count; ++i) {
947 msg.Append(',');
948 msg.AppendAddress(sample->stack[i], prev_addr);
949 prev_addr = sample->stack[i];
950 }
951 if (FLAG_compress_log) {
952 ASSERT(compression_helper_ != NULL);
953 if (!compression_helper_->HandleMessage(&msg)) return;
954 }
955 msg.Append('\n');
956 msg.WriteToLogFile();
957 }
958
959
GetActiveProfilerModules()960 int Logger::GetActiveProfilerModules() {
961 int result = PROFILER_MODULE_NONE;
962 if (!profiler_->paused()) {
963 result |= PROFILER_MODULE_CPU;
964 }
965 if (FLAG_log_gc) {
966 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
967 }
968 return result;
969 }
970
971
PauseProfiler(int flags)972 void Logger::PauseProfiler(int flags) {
973 if (!Log::IsEnabled()) return;
974 const int active_modules = GetActiveProfilerModules();
975 const int modules_to_disable = active_modules & flags;
976 if (modules_to_disable == PROFILER_MODULE_NONE) return;
977
978 if (modules_to_disable & PROFILER_MODULE_CPU) {
979 profiler_->pause();
980 if (FLAG_prof_lazy) {
981 if (!FLAG_sliding_state_window) ticker_->Stop();
982 FLAG_log_code = false;
983 // Must be the same message as Log::kDynamicBufferSeal.
984 LOG(UncheckedStringEvent("profiler", "pause"));
985 }
986 }
987 if (modules_to_disable &
988 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
989 FLAG_log_gc = false;
990 }
991 // Turn off logging if no active modules remain.
992 if ((active_modules & ~flags) == PROFILER_MODULE_NONE) {
993 is_logging_ = false;
994 }
995 }
996
997
ResumeProfiler(int flags)998 void Logger::ResumeProfiler(int flags) {
999 if (!Log::IsEnabled()) return;
1000 const int modules_to_enable = ~GetActiveProfilerModules() & flags;
1001 if (modules_to_enable != PROFILER_MODULE_NONE) {
1002 is_logging_ = true;
1003 }
1004 if (modules_to_enable & PROFILER_MODULE_CPU) {
1005 if (FLAG_prof_lazy) {
1006 LOG(UncheckedStringEvent("profiler", "resume"));
1007 FLAG_log_code = true;
1008 LogCompiledFunctions();
1009 if (!FLAG_sliding_state_window) ticker_->Start();
1010 }
1011 profiler_->resume();
1012 }
1013 if (modules_to_enable &
1014 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
1015 FLAG_log_gc = true;
1016 }
1017 }
1018
1019
1020 // This function can be called when Log's mutex is acquired,
1021 // either from main or Profiler's thread.
StopLoggingAndProfiling()1022 void Logger::StopLoggingAndProfiling() {
1023 Log::stop();
1024 PauseProfiler(PROFILER_MODULE_CPU);
1025 }
1026
1027
IsProfilerSamplerActive()1028 bool Logger::IsProfilerSamplerActive() {
1029 return ticker_->IsActive();
1030 }
1031
1032
GetLogLines(int from_pos,char * dest_buf,int max_size)1033 int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1034 return Log::GetLogLines(from_pos, dest_buf, max_size);
1035 }
1036
1037
LogCompiledFunctions()1038 void Logger::LogCompiledFunctions() {
1039 HandleScope scope;
1040 Handle<SharedFunctionInfo>* sfis = NULL;
1041 int compiled_funcs_count = 0;
1042
1043 {
1044 AssertNoAllocation no_alloc;
1045
1046 HeapIterator iterator;
1047 while (iterator.has_next()) {
1048 HeapObject* obj = iterator.next();
1049 ASSERT(obj != NULL);
1050 if (obj->IsSharedFunctionInfo()
1051 && SharedFunctionInfo::cast(obj)->is_compiled()) {
1052 ++compiled_funcs_count;
1053 }
1054 }
1055
1056 sfis = NewArray< Handle<SharedFunctionInfo> >(compiled_funcs_count);
1057 iterator.reset();
1058
1059 int i = 0;
1060 while (iterator.has_next()) {
1061 HeapObject* obj = iterator.next();
1062 ASSERT(obj != NULL);
1063 if (obj->IsSharedFunctionInfo()
1064 && SharedFunctionInfo::cast(obj)->is_compiled()) {
1065 sfis[i++] = Handle<SharedFunctionInfo>(SharedFunctionInfo::cast(obj));
1066 }
1067 }
1068 }
1069
1070 // During iteration, there can be heap allocation due to
1071 // GetScriptLineNumber call.
1072 for (int i = 0; i < compiled_funcs_count; ++i) {
1073 Handle<SharedFunctionInfo> shared = sfis[i];
1074 Handle<String> name(String::cast(shared->name()));
1075 Handle<String> func_name(name->length() > 0 ?
1076 *name : shared->inferred_name());
1077 if (shared->script()->IsScript()) {
1078 Handle<Script> script(Script::cast(shared->script()));
1079 if (script->name()->IsString()) {
1080 Handle<String> script_name(String::cast(script->name()));
1081 int line_num = GetScriptLineNumber(script, shared->start_position());
1082 if (line_num > 0) {
1083 LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG,
1084 shared->code(), *func_name,
1085 *script_name, line_num + 1));
1086 } else {
1087 // Can't distinguish enum and script here, so always use Script.
1088 LOG(CodeCreateEvent(Logger::SCRIPT_TAG,
1089 shared->code(), *script_name));
1090 }
1091 continue;
1092 }
1093 }
1094 // If no script or script has no name.
1095 LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
1096 }
1097
1098 DeleteArray(sfis);
1099 }
1100
1101 #endif
1102
1103
Setup()1104 bool Logger::Setup() {
1105 #ifdef ENABLE_LOGGING_AND_PROFILING
1106 // --log-all enables all the log flags.
1107 if (FLAG_log_all) {
1108 FLAG_log_runtime = true;
1109 FLAG_log_api = true;
1110 FLAG_log_code = true;
1111 FLAG_log_gc = true;
1112 FLAG_log_suspect = true;
1113 FLAG_log_handles = true;
1114 FLAG_log_regexp = true;
1115 }
1116
1117 // --prof implies --log-code.
1118 if (FLAG_prof) FLAG_log_code = true;
1119
1120 // --prof_lazy controls --log-code, implies --noprof_auto.
1121 if (FLAG_prof_lazy) {
1122 FLAG_log_code = false;
1123 FLAG_prof_auto = false;
1124 }
1125
1126 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1127 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1128 || FLAG_log_regexp || FLAG_log_state_changes;
1129
1130 bool open_log_file = start_logging || FLAG_prof_lazy;
1131
1132 // If we're logging anything, we need to open the log file.
1133 if (open_log_file) {
1134 if (strcmp(FLAG_logfile, "-") == 0) {
1135 Log::OpenStdout();
1136 } else if (strcmp(FLAG_logfile, "*") == 0) {
1137 Log::OpenMemoryBuffer();
1138 } else if (strchr(FLAG_logfile, '%') != NULL) {
1139 // If there's a '%' in the log file name we have to expand
1140 // placeholders.
1141 HeapStringAllocator allocator;
1142 StringStream stream(&allocator);
1143 for (const char* p = FLAG_logfile; *p; p++) {
1144 if (*p == '%') {
1145 p++;
1146 switch (*p) {
1147 case '\0':
1148 // If there's a % at the end of the string we back up
1149 // one character so we can escape the loop properly.
1150 p--;
1151 break;
1152 case 't': {
1153 // %t expands to the current time in milliseconds.
1154 double time = OS::TimeCurrentMillis();
1155 stream.Add("%.0f", FmtElm(time));
1156 break;
1157 }
1158 case '%':
1159 // %% expands (contracts really) to %.
1160 stream.Put('%');
1161 break;
1162 default:
1163 // All other %'s expand to themselves.
1164 stream.Put('%');
1165 stream.Put(*p);
1166 break;
1167 }
1168 } else {
1169 stream.Put(*p);
1170 }
1171 }
1172 SmartPointer<const char> expanded = stream.ToCString();
1173 Log::OpenFile(*expanded);
1174 } else {
1175 Log::OpenFile(FLAG_logfile);
1176 }
1177 }
1178
1179 current_state_ = &bottom_state_;
1180
1181 ticker_ = new Ticker(kSamplingIntervalMs);
1182
1183 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1184 sliding_state_window_ = new SlidingStateWindow();
1185 }
1186
1187 log_events_ = FLAG_compress_log ?
1188 kCompressedLogEventsNames : kLongLogEventsNames;
1189 if (FLAG_compress_log) {
1190 compression_helper_ = new CompressionHelper(kCompressionWindowSize);
1191 }
1192
1193 is_logging_ = start_logging;
1194
1195 if (FLAG_prof) {
1196 profiler_ = new Profiler();
1197 if (!FLAG_prof_auto) {
1198 profiler_->pause();
1199 } else {
1200 is_logging_ = true;
1201 }
1202 profiler_->Engage();
1203 }
1204
1205 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
1206
1207 return true;
1208
1209 #else
1210 return false;
1211 #endif
1212 }
1213
1214
TearDown()1215 void Logger::TearDown() {
1216 #ifdef ENABLE_LOGGING_AND_PROFILING
1217 LogMessageBuilder::set_write_failure_handler(NULL);
1218
1219 // Stop the profiler before closing the file.
1220 if (profiler_ != NULL) {
1221 profiler_->Disengage();
1222 delete profiler_;
1223 profiler_ = NULL;
1224 }
1225
1226 delete compression_helper_;
1227 compression_helper_ = NULL;
1228
1229 delete sliding_state_window_;
1230 sliding_state_window_ = NULL;
1231
1232 delete ticker_;
1233 ticker_ = NULL;
1234
1235 Log::Close();
1236 #endif
1237 }
1238
1239
EnableSlidingStateWindow()1240 void Logger::EnableSlidingStateWindow() {
1241 #ifdef ENABLE_LOGGING_AND_PROFILING
1242 // If the ticker is NULL, Logger::Setup has not been called yet. In
1243 // that case, we set the sliding_state_window flag so that the
1244 // sliding window computation will be started when Logger::Setup is
1245 // called.
1246 if (ticker_ == NULL) {
1247 FLAG_sliding_state_window = true;
1248 return;
1249 }
1250 // Otherwise, if the sliding state window computation has not been
1251 // started we do it now.
1252 if (sliding_state_window_ == NULL) {
1253 sliding_state_window_ = new SlidingStateWindow();
1254 }
1255 #endif
1256 }
1257
1258
1259 } } // namespace v8::internal
1260