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
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.
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.
32 #include "bootstrapper.h"
33 #include "code-stubs.h"
34 #include "cpu-profiler.h"
35 #include "deoptimizer.h"
36 #include "global-handles.h"
38 #include "log-utils.h"
39 #include "macro-assembler.h"
41 #include "runtime-profiler.h"
42 #include "serialize.h"
43 #include "string-stream.h"
44 #include "vm-state-inl.h"
50 #define DECLARE_EVENT(ignore1, name) name,
51 static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
52 LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
57 #define CALL_LISTENERS(Call) \
58 for (int i = 0; i < listeners_.length(); ++i) { \
59 listeners_[i]->Call; \
62 #define PROFILER_LOG(Call) \
64 CpuProfiler* cpu_profiler = isolate_->cpu_profiler(); \
65 if (cpu_profiler->is_profiling()) { \
70 // ComputeMarker must only be used when SharedFunctionInfo is known.
71 static const char* ComputeMarker(Code* code) {
72 switch (code->kind()) {
73 case Code::FUNCTION: return code->optimizable() ? "~" : "";
74 case Code::OPTIMIZED_FUNCTION: return "*";
80 class CodeEventLogger::NameBuffer {
82 NameBuffer() { Reset(); }
88 void Init(Logger::LogEventsAndTags tag) {
90 AppendBytes(kLogEventsNames[tag]);
94 void AppendName(Name* name) {
95 if (name->IsString()) {
96 AppendString(String::cast(name));
98 Symbol* symbol = Symbol::cast(name);
99 AppendBytes("symbol(");
100 if (!symbol->name()->IsUndefined()) {
102 AppendString(String::cast(symbol->name()));
105 AppendBytes("hash ");
106 AppendHex(symbol->Hash());
111 void AppendString(String* str) {
112 if (str == NULL) return;
113 int uc16_length = Min(str->length(), kUtf16BufferSize);
114 String::WriteToFlat(str, utf16_buffer, 0, uc16_length);
115 int previous = unibrow::Utf16::kNoPreviousCharacter;
116 for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
117 uc16 c = utf16_buffer[i];
118 if (c <= unibrow::Utf8::kMaxOneByteChar) {
119 utf8_buffer_[utf8_pos_++] = static_cast<char>(c);
121 int char_length = unibrow::Utf8::Length(c, previous);
122 if (utf8_pos_ + char_length > kUtf8BufferSize) break;
123 unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous);
124 utf8_pos_ += char_length;
130 void AppendBytes(const char* bytes, int size) {
131 size = Min(size, kUtf8BufferSize - utf8_pos_);
132 OS::MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
136 void AppendBytes(const char* bytes) {
137 AppendBytes(bytes, StrLength(bytes));
140 void AppendByte(char c) {
141 if (utf8_pos_ >= kUtf8BufferSize) return;
142 utf8_buffer_[utf8_pos_++] = c;
145 void AppendInt(int n) {
146 Vector<char> buffer(utf8_buffer_ + utf8_pos_,
147 kUtf8BufferSize - utf8_pos_);
148 int size = OS::SNPrintF(buffer, "%d", n);
149 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
154 void AppendHex(uint32_t n) {
155 Vector<char> buffer(utf8_buffer_ + utf8_pos_,
156 kUtf8BufferSize - utf8_pos_);
157 int size = OS::SNPrintF(buffer, "%x", n);
158 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
163 const char* get() { return utf8_buffer_; }
164 int size() const { return utf8_pos_; }
167 static const int kUtf8BufferSize = 512;
168 static const int kUtf16BufferSize = 128;
171 char utf8_buffer_[kUtf8BufferSize];
172 uc16 utf16_buffer[kUtf16BufferSize];
176 CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { }
178 CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }
181 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
183 const char* comment) {
184 name_buffer_->Init(tag);
185 name_buffer_->AppendBytes(comment);
186 LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
190 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
193 name_buffer_->Init(tag);
194 name_buffer_->AppendName(name);
195 LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
199 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
201 SharedFunctionInfo* shared,
202 CompilationInfo* info,
204 name_buffer_->Init(tag);
205 name_buffer_->AppendBytes(ComputeMarker(code));
206 name_buffer_->AppendName(name);
207 LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
211 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
213 SharedFunctionInfo* shared,
214 CompilationInfo* info,
215 Name* source, int line, int column) {
216 name_buffer_->Init(tag);
217 name_buffer_->AppendBytes(ComputeMarker(code));
218 name_buffer_->AppendString(shared->DebugName());
219 name_buffer_->AppendByte(' ');
220 if (source->IsString()) {
221 name_buffer_->AppendString(String::cast(source));
223 name_buffer_->AppendBytes("symbol(hash ");
224 name_buffer_->AppendHex(Name::cast(source)->Hash());
225 name_buffer_->AppendByte(')');
227 name_buffer_->AppendByte(':');
228 name_buffer_->AppendInt(line);
229 LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
233 void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag,
236 name_buffer_->Init(tag);
237 name_buffer_->AppendInt(args_count);
238 LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
242 void CodeEventLogger::RegExpCodeCreateEvent(Code* code, String* source) {
243 name_buffer_->Init(Logger::REG_EXP_TAG);
244 name_buffer_->AppendString(source);
245 LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
249 // Linux perf tool logging support
250 class PerfBasicLogger : public CodeEventLogger {
253 virtual ~PerfBasicLogger();
255 virtual void CodeMoveEvent(Address from, Address to) { }
256 virtual void CodeDeleteEvent(Address from) { }
259 virtual void LogRecordedBuffer(Code* code,
260 SharedFunctionInfo* shared,
264 // Extension added to V8 log file name to get the low-level log name.
265 static const char kFilenameFormatString[];
266 static const int kFilenameBufferPadding;
268 // File buffer size of the low-level log. We don't use the default to
269 // minimize the associated overhead.
270 static const int kLogBufferSize = 2 * MB;
272 FILE* perf_output_handle_;
275 const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
276 // Extra space for the PID in the filename
277 const int PerfBasicLogger::kFilenameBufferPadding = 16;
279 PerfBasicLogger::PerfBasicLogger()
280 : perf_output_handle_(NULL) {
281 // Open the perf JIT dump file.
282 int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
283 ScopedVector<char> perf_dump_name(bufferSize);
284 int size = OS::SNPrintF(
286 kFilenameFormatString,
287 OS::GetCurrentProcessId());
289 perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);
290 CHECK_NE(perf_output_handle_, NULL);
291 setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);
295 PerfBasicLogger::~PerfBasicLogger() {
296 fclose(perf_output_handle_);
297 perf_output_handle_ = NULL;
301 void PerfBasicLogger::LogRecordedBuffer(Code* code,
305 ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);
307 OS::FPrint(perf_output_handle_, "%llx %x %.*s\n",
308 reinterpret_cast<uint64_t>(code->instruction_start()),
309 code->instruction_size(),
314 // Linux perf tool logging support
315 class PerfJitLogger : public CodeEventLogger {
318 virtual ~PerfJitLogger();
320 virtual void CodeMoveEvent(Address from, Address to) { }
321 virtual void CodeDeleteEvent(Address from) { }
324 virtual void LogRecordedBuffer(Code* code,
325 SharedFunctionInfo* shared,
329 // Extension added to V8 log file name to get the low-level log name.
330 static const char kFilenameFormatString[];
331 static const int kFilenameBufferPadding;
333 // File buffer size of the low-level log. We don't use the default to
334 // minimize the associated overhead.
335 static const int kLogBufferSize = 2 * MB;
337 void LogWriteBytes(const char* bytes, int size);
338 void LogWriteHeader();
340 static const uint32_t kJitHeaderMagic = 0x4F74496A;
341 static const uint32_t kJitHeaderVersion = 0x2;
342 static const uint32_t kElfMachIA32 = 3;
343 static const uint32_t kElfMachX64 = 62;
344 static const uint32_t kElfMachARM = 40;
345 static const uint32_t kElfMachMIPS = 10;
357 enum jit_record_type {
359 // JIT_CODE_UNLOAD = 1,
360 // JIT_CODE_CLOSE = 2,
361 // JIT_CODE_DEBUG_INFO = 3,
362 // JIT_CODE_PAGE_MAP = 4,
366 struct jr_code_load {
376 uint32_t GetElfMach() {
377 #if V8_TARGET_ARCH_IA32
379 #elif V8_TARGET_ARCH_X64
381 #elif V8_TARGET_ARCH_ARM
383 #elif V8_TARGET_ARCH_MIPS
391 FILE* perf_output_handle_;
394 const char PerfJitLogger::kFilenameFormatString[] = "/tmp/jit-%d.dump";
396 // Extra padding for the PID in the filename
397 const int PerfJitLogger::kFilenameBufferPadding = 16;
399 PerfJitLogger::PerfJitLogger()
400 : perf_output_handle_(NULL) {
401 // Open the perf JIT dump file.
402 int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
403 ScopedVector<char> perf_dump_name(bufferSize);
404 int size = OS::SNPrintF(
406 kFilenameFormatString,
407 OS::GetCurrentProcessId());
409 perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);
410 CHECK_NE(perf_output_handle_, NULL);
411 setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);
417 PerfJitLogger::~PerfJitLogger() {
418 fclose(perf_output_handle_);
419 perf_output_handle_ = NULL;
423 void PerfJitLogger::LogRecordedBuffer(Code* code,
427 ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);
428 ASSERT(perf_output_handle_ != NULL);
430 const char* code_name = name;
431 uint8_t* code_pointer = reinterpret_cast<uint8_t*>(code->instruction_start());
432 uint32_t code_size = code->instruction_size();
434 static const char string_terminator[] = "\0";
436 jr_code_load code_load;
437 code_load.id = JIT_CODE_LOAD;
438 code_load.total_size = sizeof(code_load) + length + 1 + code_size;
439 code_load.timestamp =
440 static_cast<uint64_t>(OS::TimeCurrentMillis() * 1000.0);
441 code_load.vma = 0x0; // Our addresses are absolute.
442 code_load.code_addr = reinterpret_cast<uint64_t>(code->instruction_start());
443 code_load.code_size = code_size;
446 LogWriteBytes(reinterpret_cast<const char*>(&code_load), sizeof(code_load));
447 LogWriteBytes(code_name, length);
448 LogWriteBytes(string_terminator, 1);
449 LogWriteBytes(reinterpret_cast<const char*>(code_pointer), code_size);
453 void PerfJitLogger::LogWriteBytes(const char* bytes, int size) {
454 size_t rv = fwrite(bytes, 1, size, perf_output_handle_);
455 ASSERT(static_cast<size_t>(size) == rv);
460 void PerfJitLogger::LogWriteHeader() {
461 ASSERT(perf_output_handle_ != NULL);
463 header.magic = kJitHeaderMagic;
464 header.version = kJitHeaderVersion;
465 header.total_size = sizeof(jitheader);
466 header.pad1 = 0xdeadbeef;
467 header.elf_mach = GetElfMach();
468 header.pid = OS::GetCurrentProcessId();
469 header.timestamp = static_cast<uint64_t>(OS::TimeCurrentMillis() * 1000.0);
470 LogWriteBytes(reinterpret_cast<const char*>(&header), sizeof(header));
474 // Low-level logging support.
475 #define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;
477 class LowLevelLogger : public CodeEventLogger {
479 explicit LowLevelLogger(const char* file_name);
480 virtual ~LowLevelLogger();
482 virtual void CodeMoveEvent(Address from, Address to);
483 virtual void CodeDeleteEvent(Address from);
484 virtual void SnapshotPositionEvent(Address addr, int pos);
485 virtual void CodeMovingGCEvent();
488 virtual void LogRecordedBuffer(Code* code,
489 SharedFunctionInfo* shared,
493 // Low-level profiling event structures.
494 struct CodeCreateStruct {
495 static const char kTag = 'C';
498 Address code_address;
503 struct CodeMoveStruct {
504 static const char kTag = 'M';
506 Address from_address;
511 struct CodeDeleteStruct {
512 static const char kTag = 'D';
518 struct SnapshotPositionStruct {
519 static const char kTag = 'P';
526 static const char kCodeMovingGCTag = 'G';
529 // Extension added to V8 log file name to get the low-level log name.
530 static const char kLogExt[];
532 // File buffer size of the low-level log. We don't use the default to
533 // minimize the associated overhead.
534 static const int kLogBufferSize = 2 * MB;
537 void LogWriteBytes(const char* bytes, int size);
539 template <typename T>
540 void LogWriteStruct(const T& s) {
542 LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag));
543 LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
546 FILE* ll_output_handle_;
549 const char LowLevelLogger::kLogExt[] = ".ll";
551 LowLevelLogger::LowLevelLogger(const char* name)
552 : ll_output_handle_(NULL) {
553 // Open the low-level log file.
554 size_t len = strlen(name);
555 ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt)));
556 OS::MemCopy(ll_name.start(), name, len);
557 OS::MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
558 ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode);
559 setvbuf(ll_output_handle_, NULL, _IOFBF, kLogBufferSize);
565 LowLevelLogger::~LowLevelLogger() {
566 fclose(ll_output_handle_);
567 ll_output_handle_ = NULL;
571 void LowLevelLogger::LogCodeInfo() {
572 #if V8_TARGET_ARCH_IA32
573 const char arch[] = "ia32";
574 #elif V8_TARGET_ARCH_X64
575 const char arch[] = "x64";
576 #elif V8_TARGET_ARCH_ARM
577 const char arch[] = "arm";
578 #elif V8_TARGET_ARCH_MIPS
579 const char arch[] = "mips";
581 const char arch[] = "unknown";
583 LogWriteBytes(arch, sizeof(arch));
587 void LowLevelLogger::LogRecordedBuffer(Code* code,
591 CodeCreateStruct event;
592 event.name_size = length;
593 event.code_address = code->instruction_start();
594 ASSERT(event.code_address == code->address() + Code::kHeaderSize);
595 event.code_size = code->instruction_size();
596 LogWriteStruct(event);
597 LogWriteBytes(name, length);
599 reinterpret_cast<const char*>(code->instruction_start()),
600 code->instruction_size());
604 void LowLevelLogger::CodeMoveEvent(Address from, Address to) {
605 CodeMoveStruct event;
606 event.from_address = from + Code::kHeaderSize;
607 event.to_address = to + Code::kHeaderSize;
608 LogWriteStruct(event);
612 void LowLevelLogger::CodeDeleteEvent(Address from) {
613 CodeDeleteStruct event;
614 event.address = from + Code::kHeaderSize;
615 LogWriteStruct(event);
619 void LowLevelLogger::SnapshotPositionEvent(Address addr, int pos) {
620 SnapshotPositionStruct event;
621 event.address = addr + Code::kHeaderSize;
622 event.position = pos;
623 LogWriteStruct(event);
627 void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
628 size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
629 ASSERT(static_cast<size_t>(size) == rv);
634 void LowLevelLogger::CodeMovingGCEvent() {
635 const char tag = kCodeMovingGCTag;
637 LogWriteBytes(&tag, sizeof(tag));
641 #define JIT_LOG(Call) if (jit_logger_) jit_logger_->Call;
644 class JitLogger : public CodeEventLogger {
646 explicit JitLogger(JitCodeEventHandler code_event_handler);
648 virtual void CodeMoveEvent(Address from, Address to);
649 virtual void CodeDeleteEvent(Address from);
650 virtual void AddCodeLinePosInfoEvent(
651 void* jit_handler_data,
654 JitCodeEvent::PositionType position_type);
656 void* StartCodePosInfoEvent();
657 void EndCodePosInfoEvent(Code* code, void* jit_handler_data);
660 virtual void LogRecordedBuffer(Code* code,
661 SharedFunctionInfo* shared,
665 JitCodeEventHandler code_event_handler_;
669 JitLogger::JitLogger(JitCodeEventHandler code_event_handler)
670 : code_event_handler_(code_event_handler) {
674 void JitLogger::LogRecordedBuffer(Code* code,
675 SharedFunctionInfo* shared,
679 memset(&event, 0, sizeof(event));
680 event.type = JitCodeEvent::CODE_ADDED;
681 event.code_start = code->instruction_start();
682 event.code_len = code->instruction_size();
683 Handle<Script> script_handle;
684 if (shared && shared->script()->IsScript()) {
685 script_handle = Handle<Script>(Script::cast(shared->script()));
687 event.script = ToApiHandle<v8::Script>(script_handle);
688 event.name.str = name;
689 event.name.len = length;
690 code_event_handler_(&event);
694 void JitLogger::CodeMoveEvent(Address from, Address to) {
695 Code* from_code = Code::cast(HeapObject::FromAddress(from));
698 event.type = JitCodeEvent::CODE_MOVED;
699 event.code_start = from_code->instruction_start();
700 event.code_len = from_code->instruction_size();
702 // Calculate the header size.
703 const size_t header_size =
704 from_code->instruction_start() - reinterpret_cast<byte*>(from_code);
706 // Calculate the new start address of the instructions.
707 event.new_code_start =
708 reinterpret_cast<byte*>(HeapObject::FromAddress(to)) + header_size;
710 code_event_handler_(&event);
714 void JitLogger::CodeDeleteEvent(Address from) {
715 Code* from_code = Code::cast(HeapObject::FromAddress(from));
718 event.type = JitCodeEvent::CODE_REMOVED;
719 event.code_start = from_code->instruction_start();
720 event.code_len = from_code->instruction_size();
722 code_event_handler_(&event);
725 void JitLogger::AddCodeLinePosInfoEvent(
726 void* jit_handler_data,
729 JitCodeEvent::PositionType position_type) {
731 memset(&event, 0, sizeof(event));
732 event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO;
733 event.user_data = jit_handler_data;
734 event.line_info.offset = pc_offset;
735 event.line_info.pos = position;
736 event.line_info.position_type = position_type;
738 code_event_handler_(&event);
742 void* JitLogger::StartCodePosInfoEvent() {
744 memset(&event, 0, sizeof(event));
745 event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING;
747 code_event_handler_(&event);
748 return event.user_data;
752 void JitLogger::EndCodePosInfoEvent(Code* code, void* jit_handler_data) {
754 memset(&event, 0, sizeof(event));
755 event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING;
756 event.code_start = code->instruction_start();
757 event.user_data = jit_handler_data;
759 code_event_handler_(&event);
763 // The Profiler samples pc and sp values for the main thread.
764 // Each sample is appended to a circular buffer.
765 // An independent thread removes data and writes it to the log.
766 // This design minimizes the time spent in the sampler.
768 class Profiler: public Thread {
770 explicit Profiler(Isolate* isolate);
774 // Inserts collected profiling data into buffer.
775 void Insert(TickSample* sample) {
779 if (Succ(head_) == tail_) {
782 buffer_[head_] = *sample;
784 buffer_semaphore_.Signal(); // Tell we have an element.
790 // Pause and Resume TickSample data collection.
791 void pause() { paused_ = true; }
792 void resume() { paused_ = false; }
795 // Waits for a signal and removes profiling data.
796 bool Remove(TickSample* sample) {
797 buffer_semaphore_.Wait(); // Wait for an element.
798 *sample = buffer_[tail_];
799 bool result = overflow_;
805 // Returns the next index in the cyclic buffer.
806 int Succ(int index) { return (index + 1) % kBufferSize; }
809 // Cyclic buffer for communicating profiling samples
810 // between the signal handler and the worker thread.
811 static const int kBufferSize = 128;
812 TickSample buffer_[kBufferSize]; // Buffer storage.
813 int head_; // Index to the buffer head.
814 int tail_; // Index to the buffer tail.
815 bool overflow_; // Tell whether a buffer overflow has occurred.
816 // Sempahore used for buffer synchronization.
817 Semaphore buffer_semaphore_;
819 // Tells whether profiler is engaged, that is, processing thread is stated.
822 // Tells whether worker thread should continue running.
825 // Tells whether we are currently recording tick samples.
831 // Ticker used to provide ticks to the profiler and the sliding state
834 class Ticker: public Sampler {
836 Ticker(Isolate* isolate, int interval):
837 Sampler(isolate, interval),
840 ~Ticker() { if (IsActive()) Stop(); }
842 virtual void Tick(TickSample* sample) {
843 if (profiler_) profiler_->Insert(sample);
846 void SetProfiler(Profiler* profiler) {
847 ASSERT(profiler_ == NULL);
848 profiler_ = profiler;
849 IncreaseProfilingDepth();
850 if (!IsActive()) Start();
853 void ClearProfiler() {
855 if (IsActive()) Stop();
856 DecreaseProfilingDepth();
865 // Profiler implementation.
867 Profiler::Profiler(Isolate* isolate)
868 : Thread("v8:Profiler"),
873 buffer_semaphore_(0),
880 void Profiler::Engage() {
881 if (engaged_) return;
884 OS::LogSharedLibraryAddresses(isolate_);
886 // Start thread processing the profiler buffer.
890 // Register to get ticks.
891 Logger* logger = isolate_->logger();
892 logger->ticker_->SetProfiler(this);
894 logger->ProfilerBeginEvent();
898 void Profiler::Disengage() {
899 if (!engaged_) return;
901 // Stop receiving ticks.
902 isolate_->logger()->ticker_->ClearProfiler();
904 // Terminate the worker thread by setting running_ to false,
905 // inserting a fake element in the queue and then wait for
906 // the thread to terminate.
909 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
914 LOG(isolate_, UncheckedStringEvent("profiler", "end"));
918 void Profiler::Run() {
920 bool overflow = Remove(&sample);
922 LOG(isolate_, TickEvent(&sample, overflow));
923 overflow = Remove(&sample);
929 // Logger class implementation.
932 Logger::Logger(Isolate* isolate)
939 perf_basic_logger_(NULL),
940 perf_jit_logger_(NULL),
944 is_initialized_(false) {
953 void Logger::addCodeEventListener(CodeEventListener* listener) {
954 ASSERT(!hasCodeEventListener(listener));
955 listeners_.Add(listener);
959 void Logger::removeCodeEventListener(CodeEventListener* listener) {
960 ASSERT(hasCodeEventListener(listener));
961 listeners_.RemoveElement(listener);
965 bool Logger::hasCodeEventListener(CodeEventListener* listener) {
966 return listeners_.Contains(listener);
970 void Logger::ProfilerBeginEvent() {
971 if (!log_->IsEnabled()) return;
972 Log::MessageBuilder msg(log_);
973 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
974 msg.WriteToLogFile();
978 void Logger::StringEvent(const char* name, const char* value) {
979 if (FLAG_log) UncheckedStringEvent(name, value);
983 void Logger::UncheckedStringEvent(const char* name, const char* value) {
984 if (!log_->IsEnabled()) return;
985 Log::MessageBuilder msg(log_);
986 msg.Append("%s,\"%s\"\n", name, value);
987 msg.WriteToLogFile();
991 void Logger::IntEvent(const char* name, int value) {
992 if (FLAG_log) UncheckedIntEvent(name, value);
996 void Logger::IntPtrTEvent(const char* name, intptr_t value) {
997 if (FLAG_log) UncheckedIntPtrTEvent(name, value);
1001 void Logger::UncheckedIntEvent(const char* name, int value) {
1002 if (!log_->IsEnabled()) return;
1003 Log::MessageBuilder msg(log_);
1004 msg.Append("%s,%d\n", name, value);
1005 msg.WriteToLogFile();
1009 void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
1010 if (!log_->IsEnabled()) return;
1011 Log::MessageBuilder msg(log_);
1012 msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
1013 msg.WriteToLogFile();
1017 void Logger::HandleEvent(const char* name, Object** location) {
1018 if (!log_->IsEnabled() || !FLAG_log_handles) return;
1019 Log::MessageBuilder msg(log_);
1020 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
1021 msg.WriteToLogFile();
1025 // ApiEvent is private so all the calls come from the Logger class. It is the
1026 // caller's responsibility to ensure that log is enabled and that
1027 // FLAG_log_api is true.
1028 void Logger::ApiEvent(const char* format, ...) {
1029 ASSERT(log_->IsEnabled() && FLAG_log_api);
1030 Log::MessageBuilder msg(log_);
1032 va_start(ap, format);
1033 msg.AppendVA(format, ap);
1035 msg.WriteToLogFile();
1039 void Logger::ApiNamedSecurityCheck(Object* key) {
1040 if (!log_->IsEnabled() || !FLAG_log_api) return;
1041 if (key->IsString()) {
1042 SmartArrayPointer<char> str =
1043 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1044 ApiEvent("api,check-security,\"%s\"\n", str.get());
1045 } else if (key->IsSymbol()) {
1046 Symbol* symbol = Symbol::cast(key);
1047 if (symbol->name()->IsUndefined()) {
1048 ApiEvent("api,check-security,symbol(hash %x)\n",
1049 Symbol::cast(key)->Hash());
1051 SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
1052 DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1053 ApiEvent("api,check-security,symbol(\"%s\" hash %x)\n",
1055 Symbol::cast(key)->Hash());
1057 } else if (key->IsUndefined()) {
1058 ApiEvent("api,check-security,undefined\n");
1060 ApiEvent("api,check-security,['no-name']\n");
1065 void Logger::SharedLibraryEvent(const char* library_path,
1068 if (!log_->IsEnabled() || !FLAG_prof) return;
1069 Log::MessageBuilder msg(log_);
1070 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
1074 msg.WriteToLogFile();
1078 void Logger::SharedLibraryEvent(const wchar_t* library_path,
1081 if (!log_->IsEnabled() || !FLAG_prof) return;
1082 Log::MessageBuilder msg(log_);
1083 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
1087 msg.WriteToLogFile();
1091 void Logger::CodeDeoptEvent(Code* code) {
1092 if (!log_->IsEnabled()) return;
1093 ASSERT(FLAG_log_internal_timer_events);
1094 Log::MessageBuilder msg(log_);
1095 int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
1096 msg.Append("code-deopt,%ld,%d\n", since_epoch, code->CodeSize());
1097 msg.WriteToLogFile();
1101 void Logger::TimerEvent(StartEnd se, const char* name) {
1102 if (!log_->IsEnabled()) return;
1103 ASSERT(FLAG_log_internal_timer_events);
1104 Log::MessageBuilder msg(log_);
1105 int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
1106 const char* format = (se == START) ? "timer-event-start,\"%s\",%ld\n"
1107 : "timer-event-end,\"%s\",%ld\n";
1108 msg.Append(format, name, since_epoch);
1109 msg.WriteToLogFile();
1113 void Logger::EnterExternal(Isolate* isolate) {
1114 LOG(isolate, TimerEvent(START, TimerEventScope::v8_external));
1115 ASSERT(isolate->current_vm_state() == JS);
1116 isolate->set_current_vm_state(EXTERNAL);
1120 void Logger::LeaveExternal(Isolate* isolate) {
1121 LOG(isolate, TimerEvent(END, TimerEventScope::v8_external));
1122 ASSERT(isolate->current_vm_state() == EXTERNAL);
1123 isolate->set_current_vm_state(JS);
1127 void Logger::TimerEventScope::LogTimerEvent(StartEnd se) {
1128 LOG(isolate_, TimerEvent(se, name_));
1132 const char* Logger::TimerEventScope::v8_recompile_synchronous =
1133 "V8.RecompileSynchronous";
1134 const char* Logger::TimerEventScope::v8_recompile_concurrent =
1135 "V8.RecompileConcurrent";
1136 const char* Logger::TimerEventScope::v8_compile_full_code =
1137 "V8.CompileFullCode";
1138 const char* Logger::TimerEventScope::v8_execute = "V8.Execute";
1139 const char* Logger::TimerEventScope::v8_external = "V8.External";
1142 void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
1143 // Prints "/" + re.source + "/" +
1144 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
1145 Log::MessageBuilder msg(log_);
1147 Handle<Object> source = GetProperty(regexp, "source");
1148 if (!source->IsString()) {
1149 msg.Append("no source");
1153 switch (regexp->TypeTag()) {
1154 case JSRegExp::ATOM:
1161 msg.AppendDetailed(*Handle<String>::cast(source), false);
1165 Handle<Object> global = GetProperty(regexp, "global");
1166 if (global->IsTrue()) {
1170 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
1171 if (ignorecase->IsTrue()) {
1175 Handle<Object> multiline = GetProperty(regexp, "multiline");
1176 if (multiline->IsTrue()) {
1180 msg.WriteToLogFile();
1184 void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
1185 if (!log_->IsEnabled() || !FLAG_log_regexp) return;
1186 Log::MessageBuilder msg(log_);
1187 msg.Append("regexp-compile,");
1188 LogRegExpSource(regexp);
1189 msg.Append(in_cache ? ",hit\n" : ",miss\n");
1190 msg.WriteToLogFile();
1194 void Logger::LogRuntime(Vector<const char> format,
1196 if (!log_->IsEnabled() || !FLAG_log_runtime) return;
1197 HandleScope scope(isolate_);
1198 Log::MessageBuilder msg(log_);
1199 for (int i = 0; i < format.length(); i++) {
1201 if (c == '%' && i <= format.length() - 2) {
1203 ASSERT('0' <= format[i] && format[i] <= '9');
1204 MaybeObject* maybe = args->GetElement(isolate_, format[i] - '0');
1206 if (!maybe->ToObject(&obj)) {
1207 msg.Append("<exception>");
1211 switch (format[i]) {
1213 msg.AppendDetailed(String::cast(obj), false);
1216 msg.AppendDetailed(String::cast(obj), true);
1219 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
1222 msg.Append("0x%x", Smi::cast(obj)->value());
1225 msg.Append("%i", Smi::cast(obj)->value());
1235 msg.WriteToLogFile();
1239 void Logger::ApiIndexedSecurityCheck(uint32_t index) {
1240 if (!log_->IsEnabled() || !FLAG_log_api) return;
1241 ApiEvent("api,check-security,%u\n", index);
1245 void Logger::ApiNamedPropertyAccess(const char* tag,
1248 ASSERT(name->IsName());
1249 if (!log_->IsEnabled() || !FLAG_log_api) return;
1250 String* class_name_obj = holder->class_name();
1251 SmartArrayPointer<char> class_name =
1252 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1253 if (name->IsString()) {
1254 SmartArrayPointer<char> property_name =
1255 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1256 ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, class_name.get(),
1257 property_name.get());
1259 Symbol* symbol = Symbol::cast(name);
1260 uint32_t hash = symbol->Hash();
1261 if (symbol->name()->IsUndefined()) {
1262 ApiEvent("api,%s,\"%s\",symbol(hash %x)\n", tag, class_name.get(), hash);
1264 SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
1265 DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1266 ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)\n",
1267 tag, class_name.get(), str.get(), hash);
1272 void Logger::ApiIndexedPropertyAccess(const char* tag,
1275 if (!log_->IsEnabled() || !FLAG_log_api) return;
1276 String* class_name_obj = holder->class_name();
1277 SmartArrayPointer<char> class_name =
1278 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1279 ApiEvent("api,%s,\"%s\",%u\n", tag, class_name.get(), index);
1283 void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
1284 if (!log_->IsEnabled() || !FLAG_log_api) return;
1285 String* class_name_obj = object->class_name();
1286 SmartArrayPointer<char> class_name =
1287 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1288 ApiEvent("api,%s,\"%s\"\n", tag, class_name.get());
1292 void Logger::ApiEntryCall(const char* name) {
1293 if (!log_->IsEnabled() || !FLAG_log_api) return;
1294 ApiEvent("api,%s\n", name);
1298 void Logger::NewEvent(const char* name, void* object, size_t size) {
1299 if (!log_->IsEnabled() || !FLAG_log) return;
1300 Log::MessageBuilder msg(log_);
1301 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
1302 static_cast<unsigned int>(size));
1303 msg.WriteToLogFile();
1307 void Logger::DeleteEvent(const char* name, void* object) {
1308 if (!log_->IsEnabled() || !FLAG_log) return;
1309 Log::MessageBuilder msg(log_);
1310 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
1311 msg.WriteToLogFile();
1315 void Logger::NewEventStatic(const char* name, void* object, size_t size) {
1316 Isolate::Current()->logger()->NewEvent(name, object, size);
1320 void Logger::DeleteEventStatic(const char* name, void* object) {
1321 Isolate::Current()->logger()->DeleteEvent(name, object);
1325 void Logger::CallbackEventInternal(const char* prefix, Name* name,
1326 Address entry_point) {
1327 if (!FLAG_log_code || !log_->IsEnabled()) return;
1328 Log::MessageBuilder msg(log_);
1329 msg.Append("%s,%s,-2,",
1330 kLogEventsNames[CODE_CREATION_EVENT],
1331 kLogEventsNames[CALLBACK_TAG]);
1332 msg.AppendAddress(entry_point);
1333 if (name->IsString()) {
1334 SmartArrayPointer<char> str =
1335 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1336 msg.Append(",1,\"%s%s\"", prefix, str.get());
1338 Symbol* symbol = Symbol::cast(name);
1339 if (symbol->name()->IsUndefined()) {
1340 msg.Append(",1,symbol(hash %x)", prefix, symbol->Hash());
1342 SmartArrayPointer<char> str = String::cast(symbol->name())->ToCString(
1343 DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1344 msg.Append(",1,symbol(\"%s\" hash %x)", prefix, str.get(),
1349 msg.WriteToLogFile();
1353 void Logger::CallbackEvent(Name* name, Address entry_point) {
1354 PROFILER_LOG(CallbackEvent(name, entry_point));
1355 CallbackEventInternal("", name, entry_point);
1359 void Logger::GetterCallbackEvent(Name* name, Address entry_point) {
1360 PROFILER_LOG(GetterCallbackEvent(name, entry_point));
1361 CallbackEventInternal("get ", name, entry_point);
1365 void Logger::SetterCallbackEvent(Name* name, Address entry_point) {
1366 PROFILER_LOG(SetterCallbackEvent(name, entry_point));
1367 CallbackEventInternal("set ", name, entry_point);
1371 static void AppendCodeCreateHeader(Log::MessageBuilder* msg,
1372 Logger::LogEventsAndTags tag,
1375 msg->Append("%s,%s,%d,",
1376 kLogEventsNames[Logger::CODE_CREATION_EVENT],
1377 kLogEventsNames[tag],
1379 msg->AppendAddress(code->address());
1380 msg->Append(",%d,", code->ExecutableSize());
1384 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1386 const char* comment) {
1387 PROFILER_LOG(CodeCreateEvent(tag, code, comment));
1389 if (!is_logging_code_events()) return;
1390 CALL_LISTENERS(CodeCreateEvent(tag, code, comment));
1392 if (!FLAG_log_code || !log_->IsEnabled()) return;
1393 Log::MessageBuilder msg(log_);
1394 AppendCodeCreateHeader(&msg, tag, code);
1395 msg.AppendDoubleQuotedString(comment);
1397 msg.WriteToLogFile();
1401 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1404 PROFILER_LOG(CodeCreateEvent(tag, code, name));
1406 if (!is_logging_code_events()) return;
1407 CALL_LISTENERS(CodeCreateEvent(tag, code, name));
1409 if (!FLAG_log_code || !log_->IsEnabled()) return;
1410 Log::MessageBuilder msg(log_);
1411 AppendCodeCreateHeader(&msg, tag, code);
1412 if (name->IsString()) {
1414 msg.AppendDetailed(String::cast(name), false);
1417 msg.AppendSymbolName(Symbol::cast(name));
1420 msg.WriteToLogFile();
1424 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1426 SharedFunctionInfo* shared,
1427 CompilationInfo* info,
1429 PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, name));
1431 if (!is_logging_code_events()) return;
1432 CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, name));
1434 if (!FLAG_log_code || !log_->IsEnabled()) return;
1435 if (code == isolate_->builtins()->builtin(Builtins::kCompileUnoptimized))
1438 Log::MessageBuilder msg(log_);
1439 AppendCodeCreateHeader(&msg, tag, code);
1440 if (name->IsString()) {
1441 SmartArrayPointer<char> str =
1442 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1443 msg.Append("\"%s\"", str.get());
1445 msg.AppendSymbolName(Symbol::cast(name));
1448 msg.AppendAddress(shared->address());
1449 msg.Append(",%s", ComputeMarker(code));
1451 msg.WriteToLogFile();
1455 // Although, it is possible to extract source and line from
1456 // the SharedFunctionInfo object, we left it to caller
1457 // to leave logging functions free from heap allocations.
1458 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1460 SharedFunctionInfo* shared,
1461 CompilationInfo* info,
1462 Name* source, int line, int column) {
1463 PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, source, line, column));
1465 if (!is_logging_code_events()) return;
1466 CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, source, line,
1469 if (!FLAG_log_code || !log_->IsEnabled()) return;
1470 Log::MessageBuilder msg(log_);
1471 AppendCodeCreateHeader(&msg, tag, code);
1472 SmartArrayPointer<char> name =
1473 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1474 msg.Append("\"%s ", name.get());
1475 if (source->IsString()) {
1476 SmartArrayPointer<char> sourcestr =
1477 String::cast(source)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1478 msg.Append("%s", sourcestr.get());
1480 msg.AppendSymbolName(Symbol::cast(source));
1482 msg.Append(":%d:%d\",", line, column);
1483 msg.AppendAddress(shared->address());
1484 msg.Append(",%s", ComputeMarker(code));
1486 msg.WriteToLogFile();
1490 void Logger::CodeCreateEvent(LogEventsAndTags tag,
1493 PROFILER_LOG(CodeCreateEvent(tag, code, args_count));
1495 if (!is_logging_code_events()) return;
1496 CALL_LISTENERS(CodeCreateEvent(tag, code, args_count));
1498 if (!FLAG_log_code || !log_->IsEnabled()) return;
1499 Log::MessageBuilder msg(log_);
1500 AppendCodeCreateHeader(&msg, tag, code);
1501 msg.Append("\"args_count: %d\"", args_count);
1503 msg.WriteToLogFile();
1507 void Logger::CodeMovingGCEvent() {
1508 PROFILER_LOG(CodeMovingGCEvent());
1510 if (!is_logging_code_events()) return;
1511 if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1512 CALL_LISTENERS(CodeMovingGCEvent());
1513 OS::SignalCodeMovingGC();
1517 void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
1518 PROFILER_LOG(RegExpCodeCreateEvent(code, source));
1520 if (!is_logging_code_events()) return;
1521 CALL_LISTENERS(RegExpCodeCreateEvent(code, source));
1523 if (!FLAG_log_code || !log_->IsEnabled()) return;
1524 Log::MessageBuilder msg(log_);
1525 AppendCodeCreateHeader(&msg, REG_EXP_TAG, code);
1527 msg.AppendDetailed(source, false);
1530 msg.WriteToLogFile();
1534 void Logger::CodeMoveEvent(Address from, Address to) {
1535 PROFILER_LOG(CodeMoveEvent(from, to));
1537 if (!is_logging_code_events()) return;
1538 CALL_LISTENERS(CodeMoveEvent(from, to));
1539 MoveEventInternal(CODE_MOVE_EVENT, from, to);
1543 void Logger::CodeDeleteEvent(Address from) {
1544 PROFILER_LOG(CodeDeleteEvent(from));
1546 if (!is_logging_code_events()) return;
1547 CALL_LISTENERS(CodeDeleteEvent(from));
1549 if (!FLAG_log_code || !log_->IsEnabled()) return;
1550 Log::MessageBuilder msg(log_);
1551 msg.Append("%s,", kLogEventsNames[CODE_DELETE_EVENT]);
1552 msg.AppendAddress(from);
1554 msg.WriteToLogFile();
1558 void Logger::CodeLinePosInfoAddPositionEvent(void* jit_handler_data,
1561 JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
1564 JitCodeEvent::POSITION));
1568 void Logger::CodeLinePosInfoAddStatementPositionEvent(void* jit_handler_data,
1571 JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data,
1574 JitCodeEvent::STATEMENT_POSITION));
1578 void Logger::CodeStartLinePosInfoRecordEvent(PositionsRecorder* pos_recorder) {
1579 if (jit_logger_ != NULL) {
1580 pos_recorder->AttachJITHandlerData(jit_logger_->StartCodePosInfoEvent());
1585 void Logger::CodeEndLinePosInfoRecordEvent(Code* code,
1586 void* jit_handler_data) {
1587 JIT_LOG(EndCodePosInfoEvent(code, jit_handler_data));
1591 void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
1592 if (code_name == NULL) return; // Not a code object.
1593 Log::MessageBuilder msg(log_);
1594 msg.Append("%s,%d,", kLogEventsNames[SNAPSHOT_CODE_NAME_EVENT], pos);
1595 msg.AppendDoubleQuotedString(code_name);
1597 msg.WriteToLogFile();
1601 void Logger::SnapshotPositionEvent(Address addr, int pos) {
1602 if (!log_->IsEnabled()) return;
1603 LL_LOG(SnapshotPositionEvent(addr, pos));
1604 if (!FLAG_log_snapshot_positions) return;
1605 Log::MessageBuilder msg(log_);
1606 msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
1607 msg.AppendAddress(addr);
1608 msg.Append(",%d", pos);
1610 msg.WriteToLogFile();
1614 void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1615 PROFILER_LOG(SharedFunctionInfoMoveEvent(from, to));
1617 if (!is_logging_code_events()) return;
1618 MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to);
1622 void Logger::MoveEventInternal(LogEventsAndTags event,
1625 if (!FLAG_log_code || !log_->IsEnabled()) return;
1626 Log::MessageBuilder msg(log_);
1627 msg.Append("%s,", kLogEventsNames[event]);
1628 msg.AppendAddress(from);
1630 msg.AppendAddress(to);
1632 msg.WriteToLogFile();
1636 void Logger::ResourceEvent(const char* name, const char* tag) {
1637 if (!log_->IsEnabled() || !FLAG_log) return;
1638 Log::MessageBuilder msg(log_);
1639 msg.Append("%s,%s,", name, tag);
1642 if (OS::GetUserTime(&sec, &usec) != -1) {
1643 msg.Append("%d,%d,", sec, usec);
1645 msg.Append("%.0f", OS::TimeCurrentMillis());
1648 msg.WriteToLogFile();
1652 void Logger::SuspectReadEvent(Name* name, Object* obj) {
1653 if (!log_->IsEnabled() || !FLAG_log_suspect) return;
1654 Log::MessageBuilder msg(log_);
1655 String* class_name = obj->IsJSObject()
1656 ? JSObject::cast(obj)->class_name()
1657 : isolate_->heap()->empty_string();
1658 msg.Append("suspect-read,");
1659 msg.Append(class_name);
1661 if (name->IsString()) {
1663 msg.Append(String::cast(name));
1666 msg.AppendSymbolName(Symbol::cast(name));
1669 msg.WriteToLogFile();
1673 void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
1674 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1675 Log::MessageBuilder msg(log_);
1676 // Using non-relative system time in order to be able to synchronize with
1677 // external memory profiling events (e.g. DOM memory size).
1678 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
1679 space, kind, OS::TimeCurrentMillis());
1680 msg.WriteToLogFile();
1684 void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1685 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1686 Log::MessageBuilder msg(log_);
1687 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1688 msg.WriteToLogFile();
1692 void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1693 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1694 Log::MessageBuilder msg(log_);
1695 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1696 msg.WriteToLogFile();
1700 void Logger::DebugTag(const char* call_site_tag) {
1701 if (!log_->IsEnabled() || !FLAG_log) return;
1702 Log::MessageBuilder msg(log_);
1703 msg.Append("debug-tag,%s\n", call_site_tag);
1704 msg.WriteToLogFile();
1708 void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1709 if (!log_->IsEnabled() || !FLAG_log) return;
1710 StringBuilder s(parameter.length() + 1);
1711 for (int i = 0; i < parameter.length(); ++i) {
1712 s.AddCharacter(static_cast<char>(parameter[i]));
1714 char* parameter_string = s.Finalize();
1715 Log::MessageBuilder msg(log_);
1716 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1718 OS::TimeCurrentMillis(),
1720 DeleteArray(parameter_string);
1721 msg.WriteToLogFile();
1725 void Logger::TickEvent(TickSample* sample, bool overflow) {
1726 if (!log_->IsEnabled() || !FLAG_prof) return;
1727 Log::MessageBuilder msg(log_);
1728 msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
1729 msg.AppendAddress(sample->pc);
1730 msg.Append(",%ld", static_cast<int>(timer_.Elapsed().InMicroseconds()));
1731 if (sample->has_external_callback) {
1733 msg.AppendAddress(sample->external_callback);
1736 msg.AppendAddress(sample->tos);
1738 msg.Append(",%d", static_cast<int>(sample->state));
1740 msg.Append(",overflow");
1742 for (int i = 0; i < sample->frames_count; ++i) {
1744 msg.AppendAddress(sample->stack[i]);
1747 msg.WriteToLogFile();
1751 void Logger::StopProfiler() {
1752 if (!log_->IsEnabled()) return;
1753 if (profiler_ != NULL) {
1755 is_logging_ = false;
1760 // This function can be called when Log's mutex is acquired,
1761 // either from main or Profiler's thread.
1762 void Logger::LogFailure() {
1767 class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1769 EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1770 Handle<Code>* code_objects,
1772 : sfis_(sfis), code_objects_(code_objects), count_(count) { }
1774 virtual void EnterContext(Context* context) {}
1775 virtual void LeaveContext(Context* context) {}
1777 virtual void VisitFunction(JSFunction* function) {
1778 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
1779 Object* maybe_script = sfi->script();
1780 if (maybe_script->IsScript()
1781 && !Script::cast(maybe_script)->HasValidSource()) return;
1782 if (sfis_ != NULL) {
1783 sfis_[*count_] = Handle<SharedFunctionInfo>(sfi);
1785 if (code_objects_ != NULL) {
1786 ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
1787 code_objects_[*count_] = Handle<Code>(function->code());
1789 *count_ = *count_ + 1;
1793 Handle<SharedFunctionInfo>* sfis_;
1794 Handle<Code>* code_objects_;
1799 static int EnumerateCompiledFunctions(Heap* heap,
1800 Handle<SharedFunctionInfo>* sfis,
1801 Handle<Code>* code_objects) {
1802 HeapIterator iterator(heap);
1803 DisallowHeapAllocation no_gc;
1804 int compiled_funcs_count = 0;
1806 // Iterate the heap to find shared function info objects and record
1807 // the unoptimized code for them.
1808 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1809 if (!obj->IsSharedFunctionInfo()) continue;
1810 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1811 if (sfi->is_compiled()
1812 && (!sfi->script()->IsScript()
1813 || Script::cast(sfi->script())->HasValidSource())) {
1815 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
1817 if (code_objects != NULL) {
1818 code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
1820 ++compiled_funcs_count;
1824 // Iterate all optimized functions in all contexts.
1825 EnumerateOptimizedFunctionsVisitor visitor(sfis,
1827 &compiled_funcs_count);
1828 Deoptimizer::VisitAllOptimizedFunctions(heap->isolate(), &visitor);
1830 return compiled_funcs_count;
1834 void Logger::LogCodeObject(Object* object) {
1835 Code* code_object = Code::cast(object);
1836 LogEventsAndTags tag = Logger::STUB_TAG;
1837 const char* description = "Unknown code from the snapshot";
1838 switch (code_object->kind()) {
1839 case Code::FUNCTION:
1840 case Code::OPTIMIZED_FUNCTION:
1841 return; // We log this later using LogCompiledFunctions.
1842 case Code::BINARY_OP_IC:
1843 case Code::COMPARE_IC: // fall through
1844 case Code::COMPARE_NIL_IC: // fall through
1845 case Code::TO_BOOLEAN_IC: // fall through
1848 CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
1849 if (description == NULL)
1850 description = "A stub from the snapshot";
1851 tag = Logger::STUB_TAG;
1854 description = "Regular expression code";
1855 tag = Logger::REG_EXP_TAG;
1858 description = "A builtin from the snapshot";
1859 tag = Logger::BUILTIN_TAG;
1862 description = "An IC handler from the snapshot";
1863 tag = Logger::HANDLER_TAG;
1865 case Code::KEYED_LOAD_IC:
1866 description = "A keyed load IC from the snapshot";
1867 tag = Logger::KEYED_LOAD_IC_TAG;
1870 description = "A load IC from the snapshot";
1871 tag = Logger::LOAD_IC_TAG;
1873 case Code::STORE_IC:
1874 description = "A store IC from the snapshot";
1875 tag = Logger::STORE_IC_TAG;
1877 case Code::KEYED_STORE_IC:
1878 description = "A keyed store IC from the snapshot";
1879 tag = Logger::KEYED_STORE_IC_TAG;
1881 case Code::NUMBER_OF_KINDS:
1884 PROFILE(isolate_, CodeCreateEvent(tag, code_object, description));
1888 void Logger::LogCodeObjects() {
1889 Heap* heap = isolate_->heap();
1890 heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
1891 "Logger::LogCodeObjects");
1892 HeapIterator iterator(heap);
1893 DisallowHeapAllocation no_gc;
1894 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1895 if (obj->IsCode()) LogCodeObject(obj);
1900 void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
1901 Handle<Code> code) {
1902 Handle<String> func_name(shared->DebugName());
1903 if (shared->script()->IsScript()) {
1904 Handle<Script> script(Script::cast(shared->script()));
1905 int line_num = GetScriptLineNumber(script, shared->start_position()) + 1;
1907 GetScriptColumnNumber(script, shared->start_position()) + 1;
1908 if (script->name()->IsString()) {
1909 Handle<String> script_name(String::cast(script->name()));
1913 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1914 *code, *shared, NULL,
1915 *script_name, line_num, column_num));
1917 // Can't distinguish eval and script here, so always use Script.
1920 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1921 *code, *shared, NULL, *script_name));
1926 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1927 *code, *shared, NULL,
1928 isolate_->heap()->empty_string(), line_num, column_num));
1930 } else if (shared->IsApiFunction()) {
1932 FunctionTemplateInfo* fun_data = shared->get_api_func_data();
1933 Object* raw_call_data = fun_data->call_code();
1934 if (!raw_call_data->IsUndefined()) {
1935 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1936 Object* callback_obj = call_data->callback();
1937 Address entry_point = v8::ToCData<Address>(callback_obj);
1938 PROFILE(isolate_, CallbackEvent(*func_name, entry_point));
1943 Logger::LAZY_COMPILE_TAG, *code, *shared, NULL, *func_name));
1948 void Logger::LogCompiledFunctions() {
1949 Heap* heap = isolate_->heap();
1950 heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
1951 "Logger::LogCompiledFunctions");
1952 HandleScope scope(isolate_);
1953 const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL);
1954 ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
1955 ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
1956 EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start());
1958 // During iteration, there can be heap allocation due to
1959 // GetScriptLineNumber call.
1960 for (int i = 0; i < compiled_funcs_count; ++i) {
1961 if (code_objects[i].is_identical_to(
1962 isolate_->builtins()->CompileUnoptimized()))
1964 LogExistingFunction(sfis[i], code_objects[i]);
1969 void Logger::LogAccessorCallbacks() {
1970 Heap* heap = isolate_->heap();
1971 heap->CollectAllGarbage(Heap::kMakeHeapIterableMask,
1972 "Logger::LogAccessorCallbacks");
1973 HeapIterator iterator(heap);
1974 DisallowHeapAllocation no_gc;
1975 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1976 if (!obj->IsExecutableAccessorInfo()) continue;
1977 ExecutableAccessorInfo* ai = ExecutableAccessorInfo::cast(obj);
1978 if (!ai->name()->IsName()) continue;
1979 Address getter_entry = v8::ToCData<Address>(ai->getter());
1980 Name* name = Name::cast(ai->name());
1981 if (getter_entry != 0) {
1982 PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
1984 Address setter_entry = v8::ToCData<Address>(ai->setter());
1985 if (setter_entry != 0) {
1986 PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
1992 static void AddIsolateIdIfNeeded(Isolate* isolate, StringStream* stream) {
1993 if (isolate->IsDefaultIsolate() || !FLAG_logfile_per_isolate) return;
1994 stream->Add("isolate-%p-", isolate);
1998 static SmartArrayPointer<const char> PrepareLogFileName(
1999 Isolate* isolate, const char* file_name) {
2000 if (strchr(file_name, '%') != NULL || !isolate->IsDefaultIsolate()) {
2001 // If there's a '%' in the log file name we have to expand
2003 HeapStringAllocator allocator;
2004 StringStream stream(&allocator);
2005 AddIsolateIdIfNeeded(isolate, &stream);
2006 for (const char* p = file_name; *p; p++) {
2011 // If there's a % at the end of the string we back up
2012 // one character so we can escape the loop properly.
2016 stream.Add("%d", OS::GetCurrentProcessId());
2019 // %t expands to the current time in milliseconds.
2020 double time = OS::TimeCurrentMillis();
2021 stream.Add("%.0f", FmtElm(time));
2025 // %% expands (contracts really) to %.
2029 // All other %'s expand to themselves.
2038 return SmartArrayPointer<const char>(stream.ToCString());
2040 int length = StrLength(file_name);
2041 char* str = NewArray<char>(length + 1);
2042 OS::MemCopy(str, file_name, length);
2044 return SmartArrayPointer<const char>(str);
2048 bool Logger::SetUp(Isolate* isolate) {
2049 // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
2050 if (is_initialized_) return true;
2051 is_initialized_ = true;
2053 // --ll-prof implies --log-code and --log-snapshot-positions.
2055 FLAG_log_snapshot_positions = true;
2058 SmartArrayPointer<const char> log_file_name =
2059 PrepareLogFileName(isolate, FLAG_logfile);
2060 log_->Initialize(log_file_name.get());
2063 if (FLAG_perf_basic_prof) {
2064 perf_basic_logger_ = new PerfBasicLogger();
2065 addCodeEventListener(perf_basic_logger_);
2068 if (FLAG_perf_jit_prof) {
2069 perf_jit_logger_ = new PerfJitLogger();
2070 addCodeEventListener(perf_jit_logger_);
2074 ll_logger_ = new LowLevelLogger(log_file_name.get());
2075 addCodeEventListener(ll_logger_);
2078 ticker_ = new Ticker(isolate, kSamplingIntervalMs);
2080 if (Log::InitLogAtStart()) {
2085 profiler_ = new Profiler(isolate);
2087 profiler_->Engage();
2090 if (FLAG_log_internal_timer_events || FLAG_prof) timer_.Start();
2096 void Logger::SetCodeEventHandler(uint32_t options,
2097 JitCodeEventHandler event_handler) {
2099 removeCodeEventListener(jit_logger_);
2104 if (event_handler) {
2105 jit_logger_ = new JitLogger(event_handler);
2106 addCodeEventListener(jit_logger_);
2107 if (options & kJitCodeEventEnumExisting) {
2108 HandleScope scope(isolate_);
2110 LogCompiledFunctions();
2116 Sampler* Logger::sampler() {
2121 FILE* Logger::TearDown() {
2122 if (!is_initialized_) return NULL;
2123 is_initialized_ = false;
2125 // Stop the profiler before closing the file.
2126 if (profiler_ != NULL) {
2127 profiler_->Disengage();
2135 if (perf_basic_logger_) {
2136 removeCodeEventListener(perf_basic_logger_);
2137 delete perf_basic_logger_;
2138 perf_basic_logger_ = NULL;
2141 if (perf_jit_logger_) {
2142 removeCodeEventListener(perf_jit_logger_);
2143 delete perf_jit_logger_;
2144 perf_jit_logger_ = NULL;
2148 removeCodeEventListener(ll_logger_);
2154 removeCodeEventListener(jit_logger_);
2159 return log_->Close();
2162 } } // namespace v8::internal