1 // Copyright 2011 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 "code-stubs.h"
34 #include "deoptimizer.h"
35 #include "global-handles.h"
36 #include "log.h"
37 #include "macro-assembler.h"
38 #include "platform.h"
39 #include "runtime-profiler.h"
40 #include "serialize.h"
41 #include "string-stream.h"
42 #include "vm-state-inl.h"
43
44 namespace v8 {
45 namespace internal {
46
47 //
48 // Sliding state window. Updates counters to keep track of the last
49 // window of kBufferSize states. This is useful to track where we
50 // spent our time.
51 //
52 class SlidingStateWindow {
53 public:
54 explicit SlidingStateWindow(Isolate* isolate);
55 ~SlidingStateWindow();
56 void AddState(StateTag state);
57
58 private:
59 static const int kBufferSize = 256;
60 Counters* counters_;
61 int current_index_;
62 bool is_full_;
63 byte buffer_[kBufferSize];
64
65
IncrementStateCounter(StateTag state)66 void IncrementStateCounter(StateTag state) {
67 counters_->state_counters(state)->Increment();
68 }
69
70
DecrementStateCounter(StateTag state)71 void DecrementStateCounter(StateTag state) {
72 counters_->state_counters(state)->Decrement();
73 }
74 };
75
76
77 //
78 // The Profiler samples pc and sp values for the main thread.
79 // Each sample is appended to a circular buffer.
80 // An independent thread removes data and writes it to the log.
81 // This design minimizes the time spent in the sampler.
82 //
83 class Profiler: public Thread {
84 public:
85 explicit Profiler(Isolate* isolate);
86 void Engage();
87 void Disengage();
88
89 // Inserts collected profiling data into buffer.
Insert(TickSample * sample)90 void Insert(TickSample* sample) {
91 if (paused_)
92 return;
93
94 if (Succ(head_) == tail_) {
95 overflow_ = true;
96 } else {
97 buffer_[head_] = *sample;
98 head_ = Succ(head_);
99 buffer_semaphore_->Signal(); // Tell we have an element.
100 }
101 }
102
103 // Waits for a signal and removes profiling data.
Remove(TickSample * sample)104 bool Remove(TickSample* sample) {
105 buffer_semaphore_->Wait(); // Wait for an element.
106 *sample = buffer_[tail_];
107 bool result = overflow_;
108 tail_ = Succ(tail_);
109 overflow_ = false;
110 return result;
111 }
112
113 void Run();
114
115 // Pause and Resume TickSample data collection.
paused() const116 bool paused() const { return paused_; }
pause()117 void pause() { paused_ = true; }
resume()118 void resume() { paused_ = false; }
119
120 private:
121 // Returns the next index in the cyclic buffer.
Succ(int index)122 int Succ(int index) { return (index + 1) % kBufferSize; }
123
124 Isolate* isolate_;
125 // Cyclic buffer for communicating profiling samples
126 // between the signal handler and the worker thread.
127 static const int kBufferSize = 128;
128 TickSample buffer_[kBufferSize]; // Buffer storage.
129 int head_; // Index to the buffer head.
130 int tail_; // Index to the buffer tail.
131 bool overflow_; // Tell whether a buffer overflow has occurred.
132 Semaphore* buffer_semaphore_; // Sempahore used for buffer synchronization.
133
134 // Tells whether profiler is engaged, that is, processing thread is stated.
135 bool engaged_;
136
137 // Tells whether worker thread should continue running.
138 bool running_;
139
140 // Tells whether we are currently recording tick samples.
141 bool paused_;
142 };
143
144
145 //
146 // StackTracer implementation
147 //
Trace(Isolate * isolate,TickSample * sample)148 void StackTracer::Trace(Isolate* isolate, TickSample* sample) {
149 ASSERT(isolate->IsInitialized());
150
151 // Avoid collecting traces while doing GC.
152 if (sample->state == GC) return;
153
154 const Address js_entry_sp =
155 Isolate::js_entry_sp(isolate->thread_local_top());
156 if (js_entry_sp == 0) {
157 // Not executing JS now.
158 return;
159 }
160
161 const Address callback = isolate->external_callback();
162 if (callback != NULL) {
163 sample->external_callback = callback;
164 sample->has_external_callback = true;
165 } else {
166 // Sample potential return address value for frameless invocation of
167 // stubs (we'll figure out later, if this value makes sense).
168 sample->tos = Memory::Address_at(sample->sp);
169 sample->has_external_callback = false;
170 }
171
172 SafeStackTraceFrameIterator it(isolate,
173 sample->fp, sample->sp,
174 sample->sp, js_entry_sp);
175 int i = 0;
176 while (!it.done() && i < TickSample::kMaxFramesCount) {
177 sample->stack[i++] = it.frame()->pc();
178 it.Advance();
179 }
180 sample->frames_count = i;
181 }
182
183
184 //
185 // Ticker used to provide ticks to the profiler and the sliding state
186 // window.
187 //
188 class Ticker: public Sampler {
189 public:
Ticker(Isolate * isolate,int interval)190 Ticker(Isolate* isolate, int interval):
191 Sampler(isolate, interval),
192 window_(NULL),
193 profiler_(NULL) {}
194
~Ticker()195 ~Ticker() { if (IsActive()) Stop(); }
196
Tick(TickSample * sample)197 virtual void Tick(TickSample* sample) {
198 if (profiler_) profiler_->Insert(sample);
199 if (window_) window_->AddState(sample->state);
200 }
201
SetWindow(SlidingStateWindow * window)202 void SetWindow(SlidingStateWindow* window) {
203 window_ = window;
204 if (!IsActive()) Start();
205 }
206
ClearWindow()207 void ClearWindow() {
208 window_ = NULL;
209 if (!profiler_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
210 }
211
SetProfiler(Profiler * profiler)212 void SetProfiler(Profiler* profiler) {
213 ASSERT(profiler_ == NULL);
214 profiler_ = profiler;
215 IncreaseProfilingDepth();
216 if (!FLAG_prof_lazy && !IsActive()) Start();
217 }
218
ClearProfiler()219 void ClearProfiler() {
220 DecreaseProfilingDepth();
221 profiler_ = NULL;
222 if (!window_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
223 }
224
225 protected:
DoSampleStack(TickSample * sample)226 virtual void DoSampleStack(TickSample* sample) {
227 StackTracer::Trace(isolate(), sample);
228 }
229
230 private:
231 SlidingStateWindow* window_;
232 Profiler* profiler_;
233 };
234
235
236 //
237 // SlidingStateWindow implementation.
238 //
SlidingStateWindow(Isolate * isolate)239 SlidingStateWindow::SlidingStateWindow(Isolate* isolate)
240 : counters_(isolate->counters()), current_index_(0), is_full_(false) {
241 for (int i = 0; i < kBufferSize; i++) {
242 buffer_[i] = static_cast<byte>(OTHER);
243 }
244 isolate->logger()->ticker_->SetWindow(this);
245 }
246
247
~SlidingStateWindow()248 SlidingStateWindow::~SlidingStateWindow() {
249 LOGGER->ticker_->ClearWindow();
250 }
251
252
AddState(StateTag state)253 void SlidingStateWindow::AddState(StateTag state) {
254 if (is_full_) {
255 DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
256 } else if (current_index_ == kBufferSize - 1) {
257 is_full_ = true;
258 }
259 buffer_[current_index_] = static_cast<byte>(state);
260 IncrementStateCounter(state);
261 ASSERT(IsPowerOf2(kBufferSize));
262 current_index_ = (current_index_ + 1) & (kBufferSize - 1);
263 }
264
265
266 //
267 // Profiler implementation.
268 //
Profiler(Isolate * isolate)269 Profiler::Profiler(Isolate* isolate)
270 : Thread("v8:Profiler"),
271 isolate_(isolate),
272 head_(0),
273 tail_(0),
274 overflow_(false),
275 buffer_semaphore_(OS::CreateSemaphore(0)),
276 engaged_(false),
277 running_(false),
278 paused_(false) {
279 }
280
281
Engage()282 void Profiler::Engage() {
283 if (engaged_) return;
284 engaged_ = true;
285
286 // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
287 // http://code.google.com/p/v8/issues/detail?id=487
288 if (!FLAG_prof_lazy) {
289 OS::LogSharedLibraryAddresses();
290 }
291
292 // Start thread processing the profiler buffer.
293 running_ = true;
294 Start();
295
296 // Register to get ticks.
297 LOGGER->ticker_->SetProfiler(this);
298
299 LOGGER->ProfilerBeginEvent();
300 }
301
302
Disengage()303 void Profiler::Disengage() {
304 if (!engaged_) return;
305
306 // Stop receiving ticks.
307 LOGGER->ticker_->ClearProfiler();
308
309 // Terminate the worker thread by setting running_ to false,
310 // inserting a fake element in the queue and then wait for
311 // the thread to terminate.
312 running_ = false;
313 TickSample sample;
314 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
315 resume();
316 Insert(&sample);
317 Join();
318
319 LOG(ISOLATE, UncheckedStringEvent("profiler", "end"));
320 }
321
322
Run()323 void Profiler::Run() {
324 TickSample sample;
325 bool overflow = Remove(&sample);
326 while (running_) {
327 LOG(isolate_, TickEvent(&sample, overflow));
328 overflow = Remove(&sample);
329 }
330 }
331
332
333 // Low-level profiling event structures.
334
335 struct LowLevelCodeCreateStruct {
336 static const char kTag = 'C';
337
338 int32_t name_size;
339 Address code_address;
340 int32_t code_size;
341 };
342
343
344 struct LowLevelCodeMoveStruct {
345 static const char kTag = 'M';
346
347 Address from_address;
348 Address to_address;
349 };
350
351
352 struct LowLevelCodeDeleteStruct {
353 static const char kTag = 'D';
354
355 Address address;
356 };
357
358
359 struct LowLevelSnapshotPositionStruct {
360 static const char kTag = 'P';
361
362 Address address;
363 int32_t position;
364 };
365
366
367 static const char kCodeMovingGCTag = 'G';
368
369
370 //
371 // Logger class implementation.
372 //
373
374 class Logger::NameMap {
375 public:
NameMap()376 NameMap() : impl_(&PointerEquals) {}
377
~NameMap()378 ~NameMap() {
379 for (HashMap::Entry* p = impl_.Start(); p != NULL; p = impl_.Next(p)) {
380 DeleteArray(static_cast<const char*>(p->value));
381 }
382 }
383
Insert(Address code_address,const char * name,int name_size)384 void Insert(Address code_address, const char* name, int name_size) {
385 HashMap::Entry* entry = FindOrCreateEntry(code_address);
386 if (entry->value == NULL) {
387 entry->value = CopyName(name, name_size);
388 }
389 }
390
Lookup(Address code_address)391 const char* Lookup(Address code_address) {
392 HashMap::Entry* entry = FindEntry(code_address);
393 return (entry != NULL) ? static_cast<const char*>(entry->value) : NULL;
394 }
395
Remove(Address code_address)396 void Remove(Address code_address) {
397 HashMap::Entry* entry = FindEntry(code_address);
398 if (entry != NULL) {
399 DeleteArray(static_cast<char*>(entry->value));
400 RemoveEntry(entry);
401 }
402 }
403
Move(Address from,Address to)404 void Move(Address from, Address to) {
405 if (from == to) return;
406 HashMap::Entry* from_entry = FindEntry(from);
407 ASSERT(from_entry != NULL);
408 void* value = from_entry->value;
409 RemoveEntry(from_entry);
410 HashMap::Entry* to_entry = FindOrCreateEntry(to);
411 ASSERT(to_entry->value == NULL);
412 to_entry->value = value;
413 }
414
415 private:
PointerEquals(void * lhs,void * rhs)416 static bool PointerEquals(void* lhs, void* rhs) {
417 return lhs == rhs;
418 }
419
CopyName(const char * name,int name_size)420 static char* CopyName(const char* name, int name_size) {
421 char* result = NewArray<char>(name_size + 1);
422 for (int i = 0; i < name_size; ++i) {
423 char c = name[i];
424 if (c == '\0') c = ' ';
425 result[i] = c;
426 }
427 result[name_size] = '\0';
428 return result;
429 }
430
FindOrCreateEntry(Address code_address)431 HashMap::Entry* FindOrCreateEntry(Address code_address) {
432 return impl_.Lookup(code_address, ComputePointerHash(code_address), true);
433 }
434
FindEntry(Address code_address)435 HashMap::Entry* FindEntry(Address code_address) {
436 return impl_.Lookup(code_address, ComputePointerHash(code_address), false);
437 }
438
RemoveEntry(HashMap::Entry * entry)439 void RemoveEntry(HashMap::Entry* entry) {
440 impl_.Remove(entry->key, entry->hash);
441 }
442
443 HashMap impl_;
444
445 DISALLOW_COPY_AND_ASSIGN(NameMap);
446 };
447
448
449 class Logger::NameBuffer {
450 public:
NameBuffer()451 NameBuffer() { Reset(); }
452
Reset()453 void Reset() {
454 utf8_pos_ = 0;
455 }
456
AppendString(String * str)457 void AppendString(String* str) {
458 if (str == NULL) return;
459 if (str->HasOnlyAsciiChars()) {
460 int utf8_length = Min(str->length(), kUtf8BufferSize - utf8_pos_);
461 String::WriteToFlat(str, utf8_buffer_ + utf8_pos_, 0, utf8_length);
462 utf8_pos_ += utf8_length;
463 return;
464 }
465 int uc16_length = Min(str->length(), kUtf16BufferSize);
466 String::WriteToFlat(str, utf16_buffer, 0, uc16_length);
467 int previous = unibrow::Utf16::kNoPreviousCharacter;
468 for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
469 uc16 c = utf16_buffer[i];
470 if (c <= String::kMaxAsciiCharCodeU) {
471 utf8_buffer_[utf8_pos_++] = static_cast<char>(c);
472 } else {
473 int char_length = unibrow::Utf8::Length(c, previous);
474 if (utf8_pos_ + char_length > kUtf8BufferSize) break;
475 unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous);
476 utf8_pos_ += char_length;
477 }
478 previous = c;
479 }
480 }
481
AppendBytes(const char * bytes,int size)482 void AppendBytes(const char* bytes, int size) {
483 size = Min(size, kUtf8BufferSize - utf8_pos_);
484 memcpy(utf8_buffer_ + utf8_pos_, bytes, size);
485 utf8_pos_ += size;
486 }
487
AppendBytes(const char * bytes)488 void AppendBytes(const char* bytes) {
489 AppendBytes(bytes, StrLength(bytes));
490 }
491
AppendByte(char c)492 void AppendByte(char c) {
493 if (utf8_pos_ >= kUtf8BufferSize) return;
494 utf8_buffer_[utf8_pos_++] = c;
495 }
496
AppendInt(int n)497 void AppendInt(int n) {
498 Vector<char> buffer(utf8_buffer_ + utf8_pos_, kUtf8BufferSize - utf8_pos_);
499 int size = OS::SNPrintF(buffer, "%d", n);
500 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
501 utf8_pos_ += size;
502 }
503 }
504
get()505 const char* get() { return utf8_buffer_; }
size() const506 int size() const { return utf8_pos_; }
507
508 private:
509 static const int kUtf8BufferSize = 512;
510 static const int kUtf16BufferSize = 128;
511
512 int utf8_pos_;
513 char utf8_buffer_[kUtf8BufferSize];
514 uc16 utf16_buffer[kUtf16BufferSize];
515 };
516
517
Logger()518 Logger::Logger()
519 : ticker_(NULL),
520 profiler_(NULL),
521 sliding_state_window_(NULL),
522 log_events_(NULL),
523 logging_nesting_(0),
524 cpu_profiler_nesting_(0),
525 log_(new Log(this)),
526 name_buffer_(new NameBuffer),
527 address_to_name_map_(NULL),
528 is_initialized_(false),
529 last_address_(NULL),
530 prev_sp_(NULL),
531 prev_function_(NULL),
532 prev_to_(NULL),
533 prev_code_(NULL) {
534 }
535
536
~Logger()537 Logger::~Logger() {
538 delete address_to_name_map_;
539 delete name_buffer_;
540 delete log_;
541 }
542
543
544 #define DECLARE_EVENT(ignore1, name) name,
545 static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
546 LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
547 };
548 #undef DECLARE_EVENT
549
550
ProfilerBeginEvent()551 void Logger::ProfilerBeginEvent() {
552 if (!log_->IsEnabled()) return;
553 LogMessageBuilder msg(this);
554 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
555 msg.WriteToLogFile();
556 }
557
558
StringEvent(const char * name,const char * value)559 void Logger::StringEvent(const char* name, const char* value) {
560 if (FLAG_log) UncheckedStringEvent(name, value);
561 }
562
563
UncheckedStringEvent(const char * name,const char * value)564 void Logger::UncheckedStringEvent(const char* name, const char* value) {
565 if (!log_->IsEnabled()) return;
566 LogMessageBuilder msg(this);
567 msg.Append("%s,\"%s\"\n", name, value);
568 msg.WriteToLogFile();
569 }
570
571
IntEvent(const char * name,int value)572 void Logger::IntEvent(const char* name, int value) {
573 if (FLAG_log) UncheckedIntEvent(name, value);
574 }
575
576
IntPtrTEvent(const char * name,intptr_t value)577 void Logger::IntPtrTEvent(const char* name, intptr_t value) {
578 if (FLAG_log) UncheckedIntPtrTEvent(name, value);
579 }
580
581
UncheckedIntEvent(const char * name,int value)582 void Logger::UncheckedIntEvent(const char* name, int value) {
583 if (!log_->IsEnabled()) return;
584 LogMessageBuilder msg(this);
585 msg.Append("%s,%d\n", name, value);
586 msg.WriteToLogFile();
587 }
588
589
UncheckedIntPtrTEvent(const char * name,intptr_t value)590 void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
591 if (!log_->IsEnabled()) return;
592 LogMessageBuilder msg(this);
593 msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
594 msg.WriteToLogFile();
595 }
596
597
HandleEvent(const char * name,Object ** location)598 void Logger::HandleEvent(const char* name, Object** location) {
599 if (!log_->IsEnabled() || !FLAG_log_handles) return;
600 LogMessageBuilder msg(this);
601 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
602 msg.WriteToLogFile();
603 }
604
605
606 // ApiEvent is private so all the calls come from the Logger class. It is the
607 // caller's responsibility to ensure that log is enabled and that
608 // FLAG_log_api is true.
ApiEvent(const char * format,...)609 void Logger::ApiEvent(const char* format, ...) {
610 ASSERT(log_->IsEnabled() && FLAG_log_api);
611 LogMessageBuilder msg(this);
612 va_list ap;
613 va_start(ap, format);
614 msg.AppendVA(format, ap);
615 va_end(ap);
616 msg.WriteToLogFile();
617 }
618
619
ApiNamedSecurityCheck(Object * key)620 void Logger::ApiNamedSecurityCheck(Object* key) {
621 if (!log_->IsEnabled() || !FLAG_log_api) return;
622 if (key->IsString()) {
623 SmartArrayPointer<char> str =
624 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
625 ApiEvent("api,check-security,\"%s\"\n", *str);
626 } else if (key->IsUndefined()) {
627 ApiEvent("api,check-security,undefined\n");
628 } else {
629 ApiEvent("api,check-security,['no-name']\n");
630 }
631 }
632
633
SharedLibraryEvent(const char * library_path,uintptr_t start,uintptr_t end)634 void Logger::SharedLibraryEvent(const char* library_path,
635 uintptr_t start,
636 uintptr_t end) {
637 if (!log_->IsEnabled() || !FLAG_prof) return;
638 LogMessageBuilder msg(this);
639 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
640 library_path,
641 start,
642 end);
643 msg.WriteToLogFile();
644 }
645
646
SharedLibraryEvent(const wchar_t * library_path,uintptr_t start,uintptr_t end)647 void Logger::SharedLibraryEvent(const wchar_t* library_path,
648 uintptr_t start,
649 uintptr_t end) {
650 if (!log_->IsEnabled() || !FLAG_prof) return;
651 LogMessageBuilder msg(this);
652 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
653 library_path,
654 start,
655 end);
656 msg.WriteToLogFile();
657 }
658
659
LogRegExpSource(Handle<JSRegExp> regexp)660 void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
661 // Prints "/" + re.source + "/" +
662 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
663 LogMessageBuilder msg(this);
664
665 Handle<Object> source = GetProperty(regexp, "source");
666 if (!source->IsString()) {
667 msg.Append("no source");
668 return;
669 }
670
671 switch (regexp->TypeTag()) {
672 case JSRegExp::ATOM:
673 msg.Append('a');
674 break;
675 default:
676 break;
677 }
678 msg.Append('/');
679 msg.AppendDetailed(*Handle<String>::cast(source), false);
680 msg.Append('/');
681
682 // global flag
683 Handle<Object> global = GetProperty(regexp, "global");
684 if (global->IsTrue()) {
685 msg.Append('g');
686 }
687 // ignorecase flag
688 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
689 if (ignorecase->IsTrue()) {
690 msg.Append('i');
691 }
692 // multiline flag
693 Handle<Object> multiline = GetProperty(regexp, "multiline");
694 if (multiline->IsTrue()) {
695 msg.Append('m');
696 }
697
698 msg.WriteToLogFile();
699 }
700
701
RegExpCompileEvent(Handle<JSRegExp> regexp,bool in_cache)702 void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
703 if (!log_->IsEnabled() || !FLAG_log_regexp) return;
704 LogMessageBuilder msg(this);
705 msg.Append("regexp-compile,");
706 LogRegExpSource(regexp);
707 msg.Append(in_cache ? ",hit\n" : ",miss\n");
708 msg.WriteToLogFile();
709 }
710
711
LogRuntime(Vector<const char> format,JSArray * args)712 void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
713 if (!log_->IsEnabled() || !FLAG_log_runtime) return;
714 HandleScope scope;
715 LogMessageBuilder msg(this);
716 for (int i = 0; i < format.length(); i++) {
717 char c = format[i];
718 if (c == '%' && i <= format.length() - 2) {
719 i++;
720 ASSERT('0' <= format[i] && format[i] <= '9');
721 MaybeObject* maybe = args->GetElement(format[i] - '0');
722 Object* obj;
723 if (!maybe->ToObject(&obj)) {
724 msg.Append("<exception>");
725 continue;
726 }
727 i++;
728 switch (format[i]) {
729 case 's':
730 msg.AppendDetailed(String::cast(obj), false);
731 break;
732 case 'S':
733 msg.AppendDetailed(String::cast(obj), true);
734 break;
735 case 'r':
736 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
737 break;
738 case 'x':
739 msg.Append("0x%x", Smi::cast(obj)->value());
740 break;
741 case 'i':
742 msg.Append("%i", Smi::cast(obj)->value());
743 break;
744 default:
745 UNREACHABLE();
746 }
747 } else {
748 msg.Append(c);
749 }
750 }
751 msg.Append('\n');
752 msg.WriteToLogFile();
753 }
754
755
ApiIndexedSecurityCheck(uint32_t index)756 void Logger::ApiIndexedSecurityCheck(uint32_t index) {
757 if (!log_->IsEnabled() || !FLAG_log_api) return;
758 ApiEvent("api,check-security,%u\n", index);
759 }
760
761
ApiNamedPropertyAccess(const char * tag,JSObject * holder,Object * name)762 void Logger::ApiNamedPropertyAccess(const char* tag,
763 JSObject* holder,
764 Object* name) {
765 ASSERT(name->IsString());
766 if (!log_->IsEnabled() || !FLAG_log_api) return;
767 String* class_name_obj = holder->class_name();
768 SmartArrayPointer<char> class_name =
769 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
770 SmartArrayPointer<char> property_name =
771 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
772 ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
773 }
774
ApiIndexedPropertyAccess(const char * tag,JSObject * holder,uint32_t index)775 void Logger::ApiIndexedPropertyAccess(const char* tag,
776 JSObject* holder,
777 uint32_t index) {
778 if (!log_->IsEnabled() || !FLAG_log_api) return;
779 String* class_name_obj = holder->class_name();
780 SmartArrayPointer<char> class_name =
781 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
782 ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
783 }
784
ApiObjectAccess(const char * tag,JSObject * object)785 void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
786 if (!log_->IsEnabled() || !FLAG_log_api) return;
787 String* class_name_obj = object->class_name();
788 SmartArrayPointer<char> class_name =
789 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
790 ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
791 }
792
793
ApiEntryCall(const char * name)794 void Logger::ApiEntryCall(const char* name) {
795 if (!log_->IsEnabled() || !FLAG_log_api) return;
796 ApiEvent("api,%s\n", name);
797 }
798
799
NewEvent(const char * name,void * object,size_t size)800 void Logger::NewEvent(const char* name, void* object, size_t size) {
801 if (!log_->IsEnabled() || !FLAG_log) return;
802 LogMessageBuilder msg(this);
803 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
804 static_cast<unsigned int>(size));
805 msg.WriteToLogFile();
806 }
807
808
DeleteEvent(const char * name,void * object)809 void Logger::DeleteEvent(const char* name, void* object) {
810 if (!log_->IsEnabled() || !FLAG_log) return;
811 LogMessageBuilder msg(this);
812 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
813 msg.WriteToLogFile();
814 }
815
816
NewEventStatic(const char * name,void * object,size_t size)817 void Logger::NewEventStatic(const char* name, void* object, size_t size) {
818 LOGGER->NewEvent(name, object, size);
819 }
820
821
DeleteEventStatic(const char * name,void * object)822 void Logger::DeleteEventStatic(const char* name, void* object) {
823 LOGGER->DeleteEvent(name, object);
824 }
825
CallbackEventInternal(const char * prefix,const char * name,Address entry_point)826 void Logger::CallbackEventInternal(const char* prefix, const char* name,
827 Address entry_point) {
828 if (!log_->IsEnabled() || !FLAG_log_code) return;
829 LogMessageBuilder msg(this);
830 msg.Append("%s,%s,",
831 kLogEventsNames[CODE_CREATION_EVENT],
832 kLogEventsNames[CALLBACK_TAG]);
833 msg.AppendAddress(entry_point);
834 msg.Append(",1,\"%s%s\"", prefix, name);
835 msg.Append('\n');
836 msg.WriteToLogFile();
837 }
838
839
CallbackEvent(String * name,Address entry_point)840 void Logger::CallbackEvent(String* name, Address entry_point) {
841 if (!log_->IsEnabled() || !FLAG_log_code) return;
842 SmartArrayPointer<char> str =
843 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
844 CallbackEventInternal("", *str, entry_point);
845 }
846
847
GetterCallbackEvent(String * name,Address entry_point)848 void Logger::GetterCallbackEvent(String* name, Address entry_point) {
849 if (!log_->IsEnabled() || !FLAG_log_code) return;
850 SmartArrayPointer<char> str =
851 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
852 CallbackEventInternal("get ", *str, entry_point);
853 }
854
855
SetterCallbackEvent(String * name,Address entry_point)856 void Logger::SetterCallbackEvent(String* name, Address entry_point) {
857 if (!log_->IsEnabled() || !FLAG_log_code) return;
858 SmartArrayPointer<char> str =
859 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
860 CallbackEventInternal("set ", *str, entry_point);
861 }
862
863
CodeCreateEvent(LogEventsAndTags tag,Code * code,const char * comment)864 void Logger::CodeCreateEvent(LogEventsAndTags tag,
865 Code* code,
866 const char* comment) {
867 if (!log_->IsEnabled()) return;
868 if (FLAG_ll_prof || Serializer::enabled()) {
869 name_buffer_->Reset();
870 name_buffer_->AppendBytes(kLogEventsNames[tag]);
871 name_buffer_->AppendByte(':');
872 name_buffer_->AppendBytes(comment);
873 }
874 if (FLAG_ll_prof) {
875 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
876 }
877 if (Serializer::enabled()) {
878 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
879 }
880 if (!FLAG_log_code) return;
881 LogMessageBuilder msg(this);
882 msg.Append("%s,%s,",
883 kLogEventsNames[CODE_CREATION_EVENT],
884 kLogEventsNames[tag]);
885 msg.AppendAddress(code->address());
886 msg.Append(",%d,\"", code->ExecutableSize());
887 for (const char* p = comment; *p != '\0'; p++) {
888 if (*p == '"') {
889 msg.Append('\\');
890 }
891 msg.Append(*p);
892 }
893 msg.Append('"');
894 msg.Append('\n');
895 msg.WriteToLogFile();
896 }
897
898
CodeCreateEvent(LogEventsAndTags tag,Code * code,String * name)899 void Logger::CodeCreateEvent(LogEventsAndTags tag,
900 Code* code,
901 String* name) {
902 if (!log_->IsEnabled()) return;
903 if (FLAG_ll_prof || Serializer::enabled()) {
904 name_buffer_->Reset();
905 name_buffer_->AppendBytes(kLogEventsNames[tag]);
906 name_buffer_->AppendByte(':');
907 name_buffer_->AppendString(name);
908 }
909 if (FLAG_ll_prof) {
910 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
911 }
912 if (Serializer::enabled()) {
913 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
914 }
915 if (!FLAG_log_code) return;
916 LogMessageBuilder msg(this);
917 msg.Append("%s,%s,",
918 kLogEventsNames[CODE_CREATION_EVENT],
919 kLogEventsNames[tag]);
920 msg.AppendAddress(code->address());
921 msg.Append(",%d,\"", code->ExecutableSize());
922 msg.AppendDetailed(name, false);
923 msg.Append('"');
924 msg.Append('\n');
925 msg.WriteToLogFile();
926 }
927
928
929 // ComputeMarker must only be used when SharedFunctionInfo is known.
ComputeMarker(Code * code)930 static const char* ComputeMarker(Code* code) {
931 switch (code->kind()) {
932 case Code::FUNCTION: return code->optimizable() ? "~" : "";
933 case Code::OPTIMIZED_FUNCTION: return "*";
934 default: return "";
935 }
936 }
937
938
CodeCreateEvent(LogEventsAndTags tag,Code * code,SharedFunctionInfo * shared,String * name)939 void Logger::CodeCreateEvent(LogEventsAndTags tag,
940 Code* code,
941 SharedFunctionInfo* shared,
942 String* name) {
943 if (!log_->IsEnabled()) return;
944 if (FLAG_ll_prof || Serializer::enabled()) {
945 name_buffer_->Reset();
946 name_buffer_->AppendBytes(kLogEventsNames[tag]);
947 name_buffer_->AppendByte(':');
948 name_buffer_->AppendBytes(ComputeMarker(code));
949 name_buffer_->AppendString(name);
950 }
951 if (FLAG_ll_prof) {
952 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
953 }
954 if (Serializer::enabled()) {
955 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
956 }
957 if (!FLAG_log_code) return;
958 if (code == Isolate::Current()->builtins()->builtin(
959 Builtins::kLazyCompile))
960 return;
961
962 LogMessageBuilder msg(this);
963 SmartArrayPointer<char> str =
964 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
965 msg.Append("%s,%s,",
966 kLogEventsNames[CODE_CREATION_EVENT],
967 kLogEventsNames[tag]);
968 msg.AppendAddress(code->address());
969 msg.Append(",%d,\"%s\",", code->ExecutableSize(), *str);
970 msg.AppendAddress(shared->address());
971 msg.Append(",%s", ComputeMarker(code));
972 msg.Append('\n');
973 msg.WriteToLogFile();
974 }
975
976
977 // Although, it is possible to extract source and line from
978 // the SharedFunctionInfo object, we left it to caller
979 // to leave logging functions free from heap allocations.
CodeCreateEvent(LogEventsAndTags tag,Code * code,SharedFunctionInfo * shared,String * source,int line)980 void Logger::CodeCreateEvent(LogEventsAndTags tag,
981 Code* code,
982 SharedFunctionInfo* shared,
983 String* source, int line) {
984 if (!log_->IsEnabled()) return;
985 if (FLAG_ll_prof || Serializer::enabled()) {
986 name_buffer_->Reset();
987 name_buffer_->AppendBytes(kLogEventsNames[tag]);
988 name_buffer_->AppendByte(':');
989 name_buffer_->AppendBytes(ComputeMarker(code));
990 name_buffer_->AppendString(shared->DebugName());
991 name_buffer_->AppendByte(' ');
992 name_buffer_->AppendString(source);
993 name_buffer_->AppendByte(':');
994 name_buffer_->AppendInt(line);
995 }
996 if (FLAG_ll_prof) {
997 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
998 }
999 if (Serializer::enabled()) {
1000 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
1001 }
1002 if (!FLAG_log_code) return;
1003 LogMessageBuilder msg(this);
1004 SmartArrayPointer<char> name =
1005 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1006 SmartArrayPointer<char> sourcestr =
1007 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1008 msg.Append("%s,%s,",
1009 kLogEventsNames[CODE_CREATION_EVENT],
1010 kLogEventsNames[tag]);
1011 msg.AppendAddress(code->address());
1012 msg.Append(",%d,\"%s %s:%d\",",
1013 code->ExecutableSize(),
1014 *name,
1015 *sourcestr,
1016 line);
1017 msg.AppendAddress(shared->address());
1018 msg.Append(",%s", ComputeMarker(code));
1019 msg.Append('\n');
1020 msg.WriteToLogFile();
1021 }
1022
1023
CodeCreateEvent(LogEventsAndTags tag,Code * code,int args_count)1024 void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
1025 if (!log_->IsEnabled()) return;
1026 if (FLAG_ll_prof || Serializer::enabled()) {
1027 name_buffer_->Reset();
1028 name_buffer_->AppendBytes(kLogEventsNames[tag]);
1029 name_buffer_->AppendByte(':');
1030 name_buffer_->AppendInt(args_count);
1031 }
1032 if (FLAG_ll_prof) {
1033 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
1034 }
1035 if (Serializer::enabled()) {
1036 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
1037 }
1038 if (!FLAG_log_code) return;
1039 LogMessageBuilder msg(this);
1040 msg.Append("%s,%s,",
1041 kLogEventsNames[CODE_CREATION_EVENT],
1042 kLogEventsNames[tag]);
1043 msg.AppendAddress(code->address());
1044 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
1045 msg.Append('\n');
1046 msg.WriteToLogFile();
1047 }
1048
1049
CodeMovingGCEvent()1050 void Logger::CodeMovingGCEvent() {
1051 if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1052 LowLevelLogWriteBytes(&kCodeMovingGCTag, sizeof(kCodeMovingGCTag));
1053 OS::SignalCodeMovingGC();
1054 }
1055
1056
RegExpCodeCreateEvent(Code * code,String * source)1057 void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
1058 if (!log_->IsEnabled()) return;
1059 if (FLAG_ll_prof || Serializer::enabled()) {
1060 name_buffer_->Reset();
1061 name_buffer_->AppendBytes(kLogEventsNames[REG_EXP_TAG]);
1062 name_buffer_->AppendByte(':');
1063 name_buffer_->AppendString(source);
1064 }
1065 if (FLAG_ll_prof) {
1066 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
1067 }
1068 if (Serializer::enabled()) {
1069 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
1070 }
1071 if (!FLAG_log_code) return;
1072 LogMessageBuilder msg(this);
1073 msg.Append("%s,%s,",
1074 kLogEventsNames[CODE_CREATION_EVENT],
1075 kLogEventsNames[REG_EXP_TAG]);
1076 msg.AppendAddress(code->address());
1077 msg.Append(",%d,\"", code->ExecutableSize());
1078 msg.AppendDetailed(source, false);
1079 msg.Append('\"');
1080 msg.Append('\n');
1081 msg.WriteToLogFile();
1082 }
1083
1084
CodeMoveEvent(Address from,Address to)1085 void Logger::CodeMoveEvent(Address from, Address to) {
1086 if (!log_->IsEnabled()) return;
1087 if (FLAG_ll_prof) LowLevelCodeMoveEvent(from, to);
1088 if (Serializer::enabled() && address_to_name_map_ != NULL) {
1089 address_to_name_map_->Move(from, to);
1090 }
1091 MoveEventInternal(CODE_MOVE_EVENT, from, to);
1092 }
1093
1094
CodeDeleteEvent(Address from)1095 void Logger::CodeDeleteEvent(Address from) {
1096 if (!log_->IsEnabled()) return;
1097 if (FLAG_ll_prof) LowLevelCodeDeleteEvent(from);
1098 if (Serializer::enabled() && address_to_name_map_ != NULL) {
1099 address_to_name_map_->Remove(from);
1100 }
1101 DeleteEventInternal(CODE_DELETE_EVENT, from);
1102 }
1103
1104
SnapshotPositionEvent(Address addr,int pos)1105 void Logger::SnapshotPositionEvent(Address addr, int pos) {
1106 if (!log_->IsEnabled()) return;
1107 if (FLAG_ll_prof) LowLevelSnapshotPositionEvent(addr, pos);
1108 if (Serializer::enabled() && address_to_name_map_ != NULL) {
1109 const char* code_name = address_to_name_map_->Lookup(addr);
1110 if (code_name == NULL) return; // Not a code object.
1111 LogMessageBuilder msg(this);
1112 msg.Append("%s,%d,\"", kLogEventsNames[SNAPSHOT_CODE_NAME_EVENT], pos);
1113 for (const char* p = code_name; *p != '\0'; ++p) {
1114 if (*p == '"') msg.Append('\\');
1115 msg.Append(*p);
1116 }
1117 msg.Append("\"\n");
1118 msg.WriteToLogFile();
1119 }
1120 if (!FLAG_log_snapshot_positions) return;
1121 LogMessageBuilder msg(this);
1122 msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
1123 msg.AppendAddress(addr);
1124 msg.Append(",%d", pos);
1125 msg.Append('\n');
1126 msg.WriteToLogFile();
1127 }
1128
1129
SharedFunctionInfoMoveEvent(Address from,Address to)1130 void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1131 MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to);
1132 }
1133
1134
MoveEventInternal(LogEventsAndTags event,Address from,Address to)1135 void Logger::MoveEventInternal(LogEventsAndTags event,
1136 Address from,
1137 Address to) {
1138 if (!log_->IsEnabled() || !FLAG_log_code) return;
1139 LogMessageBuilder msg(this);
1140 msg.Append("%s,", kLogEventsNames[event]);
1141 msg.AppendAddress(from);
1142 msg.Append(',');
1143 msg.AppendAddress(to);
1144 msg.Append('\n');
1145 msg.WriteToLogFile();
1146 }
1147
1148
DeleteEventInternal(LogEventsAndTags event,Address from)1149 void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
1150 if (!log_->IsEnabled() || !FLAG_log_code) return;
1151 LogMessageBuilder msg(this);
1152 msg.Append("%s,", kLogEventsNames[event]);
1153 msg.AppendAddress(from);
1154 msg.Append('\n');
1155 msg.WriteToLogFile();
1156 }
1157
1158
ResourceEvent(const char * name,const char * tag)1159 void Logger::ResourceEvent(const char* name, const char* tag) {
1160 if (!log_->IsEnabled() || !FLAG_log) return;
1161 LogMessageBuilder msg(this);
1162 msg.Append("%s,%s,", name, tag);
1163
1164 uint32_t sec, usec;
1165 if (OS::GetUserTime(&sec, &usec) != -1) {
1166 msg.Append("%d,%d,", sec, usec);
1167 }
1168 msg.Append("%.0f", OS::TimeCurrentMillis());
1169
1170 msg.Append('\n');
1171 msg.WriteToLogFile();
1172 }
1173
1174
SuspectReadEvent(String * name,Object * obj)1175 void Logger::SuspectReadEvent(String* name, Object* obj) {
1176 if (!log_->IsEnabled() || !FLAG_log_suspect) return;
1177 LogMessageBuilder msg(this);
1178 String* class_name = obj->IsJSObject()
1179 ? JSObject::cast(obj)->class_name()
1180 : HEAP->empty_string();
1181 msg.Append("suspect-read,");
1182 msg.Append(class_name);
1183 msg.Append(',');
1184 msg.Append('"');
1185 msg.Append(name);
1186 msg.Append('"');
1187 msg.Append('\n');
1188 msg.WriteToLogFile();
1189 }
1190
1191
HeapSampleBeginEvent(const char * space,const char * kind)1192 void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
1193 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1194 LogMessageBuilder msg(this);
1195 // Using non-relative system time in order to be able to synchronize with
1196 // external memory profiling events (e.g. DOM memory size).
1197 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
1198 space, kind, OS::TimeCurrentMillis());
1199 msg.WriteToLogFile();
1200 }
1201
1202
HeapSampleEndEvent(const char * space,const char * kind)1203 void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1204 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1205 LogMessageBuilder msg(this);
1206 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1207 msg.WriteToLogFile();
1208 }
1209
1210
HeapSampleItemEvent(const char * type,int number,int bytes)1211 void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1212 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1213 LogMessageBuilder msg(this);
1214 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1215 msg.WriteToLogFile();
1216 }
1217
1218
DebugTag(const char * call_site_tag)1219 void Logger::DebugTag(const char* call_site_tag) {
1220 if (!log_->IsEnabled() || !FLAG_log) return;
1221 LogMessageBuilder msg(this);
1222 msg.Append("debug-tag,%s\n", call_site_tag);
1223 msg.WriteToLogFile();
1224 }
1225
1226
DebugEvent(const char * event_type,Vector<uint16_t> parameter)1227 void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1228 if (!log_->IsEnabled() || !FLAG_log) return;
1229 StringBuilder s(parameter.length() + 1);
1230 for (int i = 0; i < parameter.length(); ++i) {
1231 s.AddCharacter(static_cast<char>(parameter[i]));
1232 }
1233 char* parameter_string = s.Finalize();
1234 LogMessageBuilder msg(this);
1235 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1236 event_type,
1237 OS::TimeCurrentMillis(),
1238 parameter_string);
1239 DeleteArray(parameter_string);
1240 msg.WriteToLogFile();
1241 }
1242
1243
TickEvent(TickSample * sample,bool overflow)1244 void Logger::TickEvent(TickSample* sample, bool overflow) {
1245 if (!log_->IsEnabled() || !FLAG_prof) return;
1246 LogMessageBuilder msg(this);
1247 msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
1248 msg.AppendAddress(sample->pc);
1249 msg.Append(',');
1250 msg.AppendAddress(sample->sp);
1251 if (sample->has_external_callback) {
1252 msg.Append(",1,");
1253 msg.AppendAddress(sample->external_callback);
1254 } else {
1255 msg.Append(",0,");
1256 msg.AppendAddress(sample->tos);
1257 }
1258 msg.Append(",%d", static_cast<int>(sample->state));
1259 if (overflow) {
1260 msg.Append(",overflow");
1261 }
1262 for (int i = 0; i < sample->frames_count; ++i) {
1263 msg.Append(',');
1264 msg.AppendAddress(sample->stack[i]);
1265 }
1266 msg.Append('\n');
1267 msg.WriteToLogFile();
1268 }
1269
1270
IsProfilerPaused()1271 bool Logger::IsProfilerPaused() {
1272 return profiler_ == NULL || profiler_->paused();
1273 }
1274
1275
PauseProfiler()1276 void Logger::PauseProfiler() {
1277 if (!log_->IsEnabled()) return;
1278 if (profiler_ != NULL) {
1279 // It is OK to have negative nesting.
1280 if (--cpu_profiler_nesting_ == 0) {
1281 profiler_->pause();
1282 if (FLAG_prof_lazy) {
1283 if (!FLAG_sliding_state_window && !RuntimeProfiler::IsEnabled()) {
1284 ticker_->Stop();
1285 }
1286 FLAG_log_code = false;
1287 LOG(ISOLATE, UncheckedStringEvent("profiler", "pause"));
1288 }
1289 --logging_nesting_;
1290 }
1291 }
1292 }
1293
1294
ResumeProfiler()1295 void Logger::ResumeProfiler() {
1296 if (!log_->IsEnabled()) return;
1297 if (profiler_ != NULL) {
1298 if (cpu_profiler_nesting_++ == 0) {
1299 ++logging_nesting_;
1300 if (FLAG_prof_lazy) {
1301 profiler_->Engage();
1302 LOG(ISOLATE, UncheckedStringEvent("profiler", "resume"));
1303 FLAG_log_code = true;
1304 LogCompiledFunctions();
1305 LogAccessorCallbacks();
1306 if (!FLAG_sliding_state_window && !ticker_->IsActive()) {
1307 ticker_->Start();
1308 }
1309 }
1310 profiler_->resume();
1311 }
1312 }
1313 }
1314
1315
1316 // This function can be called when Log's mutex is acquired,
1317 // either from main or Profiler's thread.
LogFailure()1318 void Logger::LogFailure() {
1319 PauseProfiler();
1320 }
1321
1322
IsProfilerSamplerActive()1323 bool Logger::IsProfilerSamplerActive() {
1324 return ticker_->IsActive();
1325 }
1326
1327
1328 class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1329 public:
EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo> * sfis,Handle<Code> * code_objects,int * count)1330 EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1331 Handle<Code>* code_objects,
1332 int* count)
1333 : sfis_(sfis), code_objects_(code_objects), count_(count) { }
1334
EnterContext(Context * context)1335 virtual void EnterContext(Context* context) {}
LeaveContext(Context * context)1336 virtual void LeaveContext(Context* context) {}
1337
VisitFunction(JSFunction * function)1338 virtual void VisitFunction(JSFunction* function) {
1339 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
1340 Object* maybe_script = sfi->script();
1341 if (maybe_script->IsScript()
1342 && !Script::cast(maybe_script)->HasValidSource()) return;
1343 if (sfis_ != NULL) {
1344 sfis_[*count_] = Handle<SharedFunctionInfo>(sfi);
1345 }
1346 if (code_objects_ != NULL) {
1347 ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
1348 code_objects_[*count_] = Handle<Code>(function->code());
1349 }
1350 *count_ = *count_ + 1;
1351 }
1352
1353 private:
1354 Handle<SharedFunctionInfo>* sfis_;
1355 Handle<Code>* code_objects_;
1356 int* count_;
1357 };
1358
1359
EnumerateCompiledFunctions(Handle<SharedFunctionInfo> * sfis,Handle<Code> * code_objects)1360 static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis,
1361 Handle<Code>* code_objects) {
1362 HeapIterator iterator;
1363 AssertNoAllocation no_alloc;
1364 int compiled_funcs_count = 0;
1365
1366 // Iterate the heap to find shared function info objects and record
1367 // the unoptimized code for them.
1368 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1369 if (!obj->IsSharedFunctionInfo()) continue;
1370 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1371 if (sfi->is_compiled()
1372 && (!sfi->script()->IsScript()
1373 || Script::cast(sfi->script())->HasValidSource())) {
1374 if (sfis != NULL) {
1375 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1376 }
1377 if (code_objects != NULL) {
1378 code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
1379 }
1380 ++compiled_funcs_count;
1381 }
1382 }
1383
1384 // Iterate all optimized functions in all contexts.
1385 EnumerateOptimizedFunctionsVisitor visitor(sfis,
1386 code_objects,
1387 &compiled_funcs_count);
1388 Deoptimizer::VisitAllOptimizedFunctions(&visitor);
1389
1390 return compiled_funcs_count;
1391 }
1392
1393
LogCodeObject(Object * object)1394 void Logger::LogCodeObject(Object* object) {
1395 if (FLAG_log_code || FLAG_ll_prof) {
1396 Code* code_object = Code::cast(object);
1397 LogEventsAndTags tag = Logger::STUB_TAG;
1398 const char* description = "Unknown code from the snapshot";
1399 switch (code_object->kind()) {
1400 case Code::FUNCTION:
1401 case Code::OPTIMIZED_FUNCTION:
1402 return; // We log this later using LogCompiledFunctions.
1403 case Code::UNARY_OP_IC: // fall through
1404 case Code::BINARY_OP_IC: // fall through
1405 case Code::COMPARE_IC: // fall through
1406 case Code::TO_BOOLEAN_IC: // fall through
1407 case Code::STUB:
1408 description =
1409 CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
1410 if (description == NULL)
1411 description = "A stub from the snapshot";
1412 tag = Logger::STUB_TAG;
1413 break;
1414 case Code::BUILTIN:
1415 description = "A builtin from the snapshot";
1416 tag = Logger::BUILTIN_TAG;
1417 break;
1418 case Code::KEYED_LOAD_IC:
1419 description = "A keyed load IC from the snapshot";
1420 tag = Logger::KEYED_LOAD_IC_TAG;
1421 break;
1422 case Code::LOAD_IC:
1423 description = "A load IC from the snapshot";
1424 tag = Logger::LOAD_IC_TAG;
1425 break;
1426 case Code::STORE_IC:
1427 description = "A store IC from the snapshot";
1428 tag = Logger::STORE_IC_TAG;
1429 break;
1430 case Code::KEYED_STORE_IC:
1431 description = "A keyed store IC from the snapshot";
1432 tag = Logger::KEYED_STORE_IC_TAG;
1433 break;
1434 case Code::CALL_IC:
1435 description = "A call IC from the snapshot";
1436 tag = Logger::CALL_IC_TAG;
1437 break;
1438 case Code::KEYED_CALL_IC:
1439 description = "A keyed call IC from the snapshot";
1440 tag = Logger::KEYED_CALL_IC_TAG;
1441 break;
1442 }
1443 PROFILE(ISOLATE, CodeCreateEvent(tag, code_object, description));
1444 }
1445 }
1446
1447
LogCodeInfo()1448 void Logger::LogCodeInfo() {
1449 if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1450 #if V8_TARGET_ARCH_IA32
1451 const char arch[] = "ia32";
1452 #elif V8_TARGET_ARCH_X64
1453 const char arch[] = "x64";
1454 #elif V8_TARGET_ARCH_ARM
1455 const char arch[] = "arm";
1456 #elif V8_TARGET_ARCH_MIPS
1457 const char arch[] = "mips";
1458 #else
1459 const char arch[] = "unknown";
1460 #endif
1461 LowLevelLogWriteBytes(arch, sizeof(arch));
1462 }
1463
1464
RegisterSnapshotCodeName(Code * code,const char * name,int name_size)1465 void Logger::RegisterSnapshotCodeName(Code* code,
1466 const char* name,
1467 int name_size) {
1468 ASSERT(Serializer::enabled());
1469 if (address_to_name_map_ == NULL) {
1470 address_to_name_map_ = new NameMap;
1471 }
1472 address_to_name_map_->Insert(code->address(), name, name_size);
1473 }
1474
1475
LowLevelCodeCreateEvent(Code * code,const char * name,int name_size)1476 void Logger::LowLevelCodeCreateEvent(Code* code,
1477 const char* name,
1478 int name_size) {
1479 if (log_->ll_output_handle_ == NULL) return;
1480 LowLevelCodeCreateStruct event;
1481 event.name_size = name_size;
1482 event.code_address = code->instruction_start();
1483 ASSERT(event.code_address == code->address() + Code::kHeaderSize);
1484 event.code_size = code->instruction_size();
1485 LowLevelLogWriteStruct(event);
1486 LowLevelLogWriteBytes(name, name_size);
1487 LowLevelLogWriteBytes(
1488 reinterpret_cast<const char*>(code->instruction_start()),
1489 code->instruction_size());
1490 }
1491
1492
LowLevelCodeMoveEvent(Address from,Address to)1493 void Logger::LowLevelCodeMoveEvent(Address from, Address to) {
1494 if (log_->ll_output_handle_ == NULL) return;
1495 LowLevelCodeMoveStruct event;
1496 event.from_address = from + Code::kHeaderSize;
1497 event.to_address = to + Code::kHeaderSize;
1498 LowLevelLogWriteStruct(event);
1499 }
1500
1501
LowLevelCodeDeleteEvent(Address from)1502 void Logger::LowLevelCodeDeleteEvent(Address from) {
1503 if (log_->ll_output_handle_ == NULL) return;
1504 LowLevelCodeDeleteStruct event;
1505 event.address = from + Code::kHeaderSize;
1506 LowLevelLogWriteStruct(event);
1507 }
1508
1509
LowLevelSnapshotPositionEvent(Address addr,int pos)1510 void Logger::LowLevelSnapshotPositionEvent(Address addr, int pos) {
1511 if (log_->ll_output_handle_ == NULL) return;
1512 LowLevelSnapshotPositionStruct event;
1513 event.address = addr + Code::kHeaderSize;
1514 event.position = pos;
1515 LowLevelLogWriteStruct(event);
1516 }
1517
1518
LowLevelLogWriteBytes(const char * bytes,int size)1519 void Logger::LowLevelLogWriteBytes(const char* bytes, int size) {
1520 size_t rv = fwrite(bytes, 1, size, log_->ll_output_handle_);
1521 ASSERT(static_cast<size_t>(size) == rv);
1522 USE(rv);
1523 }
1524
1525
LogCodeObjects()1526 void Logger::LogCodeObjects() {
1527 HEAP->CollectAllGarbage(Heap::kMakeHeapIterableMask,
1528 "Logger::LogCodeObjects");
1529 HeapIterator iterator;
1530 AssertNoAllocation no_alloc;
1531 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1532 if (obj->IsCode()) LogCodeObject(obj);
1533 }
1534 }
1535
1536
LogExistingFunction(Handle<SharedFunctionInfo> shared,Handle<Code> code)1537 void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
1538 Handle<Code> code) {
1539 Handle<String> func_name(shared->DebugName());
1540 if (shared->script()->IsScript()) {
1541 Handle<Script> script(Script::cast(shared->script()));
1542 if (script->name()->IsString()) {
1543 Handle<String> script_name(String::cast(script->name()));
1544 int line_num = GetScriptLineNumber(script, shared->start_position());
1545 if (line_num > 0) {
1546 PROFILE(ISOLATE,
1547 CodeCreateEvent(
1548 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1549 *code, *shared,
1550 *script_name, line_num + 1));
1551 } else {
1552 // Can't distinguish eval and script here, so always use Script.
1553 PROFILE(ISOLATE,
1554 CodeCreateEvent(
1555 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1556 *code, *shared, *script_name));
1557 }
1558 } else {
1559 PROFILE(ISOLATE,
1560 CodeCreateEvent(
1561 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1562 *code, *shared, *func_name));
1563 }
1564 } else if (shared->IsApiFunction()) {
1565 // API function.
1566 FunctionTemplateInfo* fun_data = shared->get_api_func_data();
1567 Object* raw_call_data = fun_data->call_code();
1568 if (!raw_call_data->IsUndefined()) {
1569 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1570 Object* callback_obj = call_data->callback();
1571 Address entry_point = v8::ToCData<Address>(callback_obj);
1572 PROFILE(ISOLATE, CallbackEvent(*func_name, entry_point));
1573 }
1574 } else {
1575 PROFILE(ISOLATE,
1576 CodeCreateEvent(
1577 Logger::LAZY_COMPILE_TAG, *code, *shared, *func_name));
1578 }
1579 }
1580
1581
LogCompiledFunctions()1582 void Logger::LogCompiledFunctions() {
1583 HEAP->CollectAllGarbage(Heap::kMakeHeapIterableMask,
1584 "Logger::LogCompiledFunctions");
1585 HandleScope scope;
1586 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL, NULL);
1587 ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
1588 ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
1589 EnumerateCompiledFunctions(sfis.start(), code_objects.start());
1590
1591 // During iteration, there can be heap allocation due to
1592 // GetScriptLineNumber call.
1593 for (int i = 0; i < compiled_funcs_count; ++i) {
1594 if (*code_objects[i] == Isolate::Current()->builtins()->builtin(
1595 Builtins::kLazyCompile))
1596 continue;
1597 LogExistingFunction(sfis[i], code_objects[i]);
1598 }
1599 }
1600
1601
LogAccessorCallbacks()1602 void Logger::LogAccessorCallbacks() {
1603 HEAP->CollectAllGarbage(Heap::kMakeHeapIterableMask,
1604 "Logger::LogAccessorCallbacks");
1605 HeapIterator iterator;
1606 AssertNoAllocation no_alloc;
1607 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1608 if (!obj->IsAccessorInfo()) continue;
1609 AccessorInfo* ai = AccessorInfo::cast(obj);
1610 if (!ai->name()->IsString()) continue;
1611 String* name = String::cast(ai->name());
1612 Address getter_entry = v8::ToCData<Address>(ai->getter());
1613 if (getter_entry != 0) {
1614 PROFILE(ISOLATE, GetterCallbackEvent(name, getter_entry));
1615 }
1616 Address setter_entry = v8::ToCData<Address>(ai->setter());
1617 if (setter_entry != 0) {
1618 PROFILE(ISOLATE, SetterCallbackEvent(name, setter_entry));
1619 }
1620 }
1621 }
1622
1623
SetUp()1624 bool Logger::SetUp() {
1625 // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
1626 if (is_initialized_) return true;
1627 is_initialized_ = true;
1628
1629 // --ll-prof implies --log-code and --log-snapshot-positions.
1630 if (FLAG_ll_prof) {
1631 FLAG_log_snapshot_positions = true;
1632 }
1633
1634 // --prof_lazy controls --log-code, implies --noprof_auto.
1635 if (FLAG_prof_lazy) {
1636 FLAG_log_code = false;
1637 FLAG_prof_auto = false;
1638 }
1639
1640 // TODO(isolates): this assert introduces cyclic dependency (logger
1641 // -> thread local top -> heap -> logger).
1642 // ASSERT(VMState::is_outermost_external());
1643
1644 log_->Initialize();
1645
1646 if (FLAG_ll_prof) LogCodeInfo();
1647
1648 Isolate* isolate = Isolate::Current();
1649 ticker_ = new Ticker(isolate, kSamplingIntervalMs);
1650
1651 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1652 sliding_state_window_ = new SlidingStateWindow(isolate);
1653 }
1654
1655 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1656 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1657 || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof;
1658
1659 if (start_logging) {
1660 logging_nesting_ = 1;
1661 }
1662
1663 if (FLAG_prof) {
1664 profiler_ = new Profiler(isolate);
1665 if (!FLAG_prof_auto) {
1666 profiler_->pause();
1667 } else {
1668 logging_nesting_ = 1;
1669 }
1670 if (!FLAG_prof_lazy) {
1671 profiler_->Engage();
1672 }
1673 }
1674
1675 return true;
1676 }
1677
1678
sampler()1679 Sampler* Logger::sampler() {
1680 return ticker_;
1681 }
1682
1683
EnsureTickerStarted()1684 void Logger::EnsureTickerStarted() {
1685 ASSERT(ticker_ != NULL);
1686 if (!ticker_->IsActive()) ticker_->Start();
1687 }
1688
1689
EnsureTickerStopped()1690 void Logger::EnsureTickerStopped() {
1691 if (ticker_ != NULL && ticker_->IsActive()) ticker_->Stop();
1692 }
1693
1694
TearDown()1695 FILE* Logger::TearDown() {
1696 if (!is_initialized_) return NULL;
1697 is_initialized_ = false;
1698
1699 // Stop the profiler before closing the file.
1700 if (profiler_ != NULL) {
1701 profiler_->Disengage();
1702 delete profiler_;
1703 profiler_ = NULL;
1704 }
1705
1706 delete sliding_state_window_;
1707 sliding_state_window_ = NULL;
1708
1709 delete ticker_;
1710 ticker_ = NULL;
1711
1712 return log_->Close();
1713 }
1714
1715
EnableSlidingStateWindow()1716 void Logger::EnableSlidingStateWindow() {
1717 // If the ticker is NULL, Logger::SetUp has not been called yet. In
1718 // that case, we set the sliding_state_window flag so that the
1719 // sliding window computation will be started when Logger::SetUp is
1720 // called.
1721 if (ticker_ == NULL) {
1722 FLAG_sliding_state_window = true;
1723 return;
1724 }
1725 // Otherwise, if the sliding state window computation has not been
1726 // started we do it now.
1727 if (sliding_state_window_ == NULL) {
1728 sliding_state_window_ = new SlidingStateWindow(Isolate::Current());
1729 }
1730 }
1731
1732 // Protects the state below.
1733 static LazyMutex active_samplers_mutex = LAZY_MUTEX_INITIALIZER;
1734
1735 List<Sampler*>* SamplerRegistry::active_samplers_ = NULL;
1736
1737
IterateActiveSamplers(VisitSampler func,void * param)1738 bool SamplerRegistry::IterateActiveSamplers(VisitSampler func, void* param) {
1739 ScopedLock lock(active_samplers_mutex.Pointer());
1740 for (int i = 0;
1741 ActiveSamplersExist() && i < active_samplers_->length();
1742 ++i) {
1743 func(active_samplers_->at(i), param);
1744 }
1745 return ActiveSamplersExist();
1746 }
1747
1748
ComputeCpuProfiling(Sampler * sampler,void * flag_ptr)1749 static void ComputeCpuProfiling(Sampler* sampler, void* flag_ptr) {
1750 bool* flag = reinterpret_cast<bool*>(flag_ptr);
1751 *flag |= sampler->IsProfiling();
1752 }
1753
1754
GetState()1755 SamplerRegistry::State SamplerRegistry::GetState() {
1756 bool flag = false;
1757 if (!IterateActiveSamplers(&ComputeCpuProfiling, &flag)) {
1758 return HAS_NO_SAMPLERS;
1759 }
1760 return flag ? HAS_CPU_PROFILING_SAMPLERS : HAS_SAMPLERS;
1761 }
1762
1763
AddActiveSampler(Sampler * sampler)1764 void SamplerRegistry::AddActiveSampler(Sampler* sampler) {
1765 ASSERT(sampler->IsActive());
1766 ScopedLock lock(active_samplers_mutex.Pointer());
1767 if (active_samplers_ == NULL) {
1768 active_samplers_ = new List<Sampler*>;
1769 } else {
1770 ASSERT(!active_samplers_->Contains(sampler));
1771 }
1772 active_samplers_->Add(sampler);
1773 }
1774
1775
RemoveActiveSampler(Sampler * sampler)1776 void SamplerRegistry::RemoveActiveSampler(Sampler* sampler) {
1777 ASSERT(sampler->IsActive());
1778 ScopedLock lock(active_samplers_mutex.Pointer());
1779 ASSERT(active_samplers_ != NULL);
1780 bool removed = active_samplers_->RemoveElement(sampler);
1781 ASSERT(removed);
1782 USE(removed);
1783 }
1784
1785 } } // namespace v8::internal
1786