Line data Source code
1 : // Copyright 2011 the V8 project authors. All rights reserved.
2 : // Use of this source code is governed by a BSD-style license that can be
3 : // found in the LICENSE file.
4 :
5 : #include "src/log.h"
6 :
7 : #include <cstdarg>
8 : #include <memory>
9 : #include <sstream>
10 :
11 : #include "src/bailout-reason.h"
12 : #include "src/base/platform/platform.h"
13 : #include "src/bootstrapper.h"
14 : #include "src/code-stubs.h"
15 : #include "src/counters.h"
16 : #include "src/deoptimizer.h"
17 : #include "src/global-handles.h"
18 : #include "src/interpreter/bytecodes.h"
19 : #include "src/interpreter/interpreter.h"
20 : #include "src/libsampler/sampler.h"
21 : #include "src/log-inl.h"
22 : #include "src/log-utils.h"
23 : #include "src/macro-assembler.h"
24 : #include "src/perf-jit.h"
25 : #include "src/profiler/profiler-listener.h"
26 : #include "src/profiler/tick-sample.h"
27 : #include "src/runtime-profiler.h"
28 : #include "src/source-position-table.h"
29 : #include "src/string-stream.h"
30 : #include "src/tracing/tracing-category-observer.h"
31 : #include "src/vm-state-inl.h"
32 :
33 : namespace v8 {
34 : namespace internal {
35 :
36 : #define DECLARE_EVENT(ignore1, name) name,
37 : static const char* kLogEventsNames[CodeEventListener::NUMBER_OF_LOG_EVENTS] = {
38 : LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)};
39 : #undef DECLARE_EVENT
40 :
41 21721 : static const char* ComputeMarker(SharedFunctionInfo* shared,
42 : AbstractCode* code) {
43 21721 : switch (code->kind()) {
44 : case AbstractCode::FUNCTION:
45 : case AbstractCode::INTERPRETED_FUNCTION:
46 592 : return shared->optimization_disabled() ? "" : "~";
47 : case AbstractCode::OPTIMIZED_FUNCTION:
48 : return "*";
49 : default:
50 21048 : return "";
51 : }
52 : }
53 :
54 :
55 : class CodeEventLogger::NameBuffer {
56 : public:
57 : NameBuffer() { Reset(); }
58 :
59 : void Reset() {
60 11916 : utf8_pos_ = 0;
61 : }
62 :
63 11581 : void Init(CodeEventListener::LogEventsAndTags tag) {
64 : Reset();
65 11581 : AppendBytes(kLogEventsNames[tag]);
66 : AppendByte(':');
67 11581 : }
68 :
69 5373 : void AppendName(Name* name) {
70 5373 : if (name->IsString()) {
71 5373 : AppendString(String::cast(name));
72 : } else {
73 : Symbol* symbol = Symbol::cast(name);
74 0 : AppendBytes("symbol(");
75 0 : if (!symbol->name()->IsUndefined(symbol->GetIsolate())) {
76 0 : AppendBytes("\"");
77 0 : AppendString(String::cast(symbol->name()));
78 0 : AppendBytes("\" ");
79 : }
80 0 : AppendBytes("hash ");
81 0 : AppendHex(symbol->Hash());
82 : AppendByte(')');
83 : }
84 5373 : }
85 :
86 6441 : void AppendString(String* str) {
87 12882 : if (str == NULL) return;
88 : int uc16_length = Min(str->length(), kUtf16BufferSize);
89 6441 : String::WriteToFlat(str, utf16_buffer, 0, uc16_length);
90 : int previous = unibrow::Utf16::kNoPreviousCharacter;
91 14165 : for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
92 7724 : uc16 c = utf16_buffer[i];
93 7724 : if (c <= unibrow::Utf8::kMaxOneByteChar) {
94 7724 : utf8_buffer_[utf8_pos_++] = static_cast<char>(c);
95 : } else {
96 0 : int char_length = unibrow::Utf8::Length(c, previous);
97 0 : if (utf8_pos_ + char_length > kUtf8BufferSize) break;
98 0 : unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous);
99 0 : utf8_pos_ += char_length;
100 : }
101 7724 : previous = c;
102 : }
103 : }
104 :
105 23162 : void AppendBytes(const char* bytes, int size) {
106 23162 : size = Min(size, kUtf8BufferSize - utf8_pos_);
107 23162 : MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
108 23162 : utf8_pos_ += size;
109 23162 : }
110 :
111 23162 : void AppendBytes(const char* bytes) {
112 23162 : AppendBytes(bytes, StrLength(bytes));
113 23162 : }
114 :
115 : void AppendByte(char c) {
116 12649 : if (utf8_pos_ >= kUtf8BufferSize) return;
117 12625 : utf8_buffer_[utf8_pos_++] = c;
118 : }
119 :
120 534 : void AppendInt(int n) {
121 534 : int space = kUtf8BufferSize - utf8_pos_;
122 546 : if (space <= 0) return;
123 522 : Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
124 522 : int size = SNPrintF(buffer, "%d", n);
125 522 : if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
126 522 : utf8_pos_ += size;
127 : }
128 : }
129 :
130 0 : void AppendHex(uint32_t n) {
131 0 : int space = kUtf8BufferSize - utf8_pos_;
132 0 : if (space <= 0) return;
133 0 : Vector<char> buffer(utf8_buffer_ + utf8_pos_, space);
134 0 : int size = SNPrintF(buffer, "%x", n);
135 0 : if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
136 0 : utf8_pos_ += size;
137 : }
138 : }
139 :
140 : const char* get() { return utf8_buffer_; }
141 : int size() const { return utf8_pos_; }
142 :
143 : private:
144 : static const int kUtf8BufferSize = 512;
145 : static const int kUtf16BufferSize = kUtf8BufferSize;
146 :
147 : int utf8_pos_;
148 : char utf8_buffer_[kUtf8BufferSize];
149 : uc16 utf16_buffer[kUtf16BufferSize];
150 : };
151 :
152 :
153 966 : CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { }
154 :
155 631 : CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }
156 :
157 5674 : void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
158 : AbstractCode* code, const char* comment) {
159 11348 : name_buffer_->Init(tag);
160 5674 : name_buffer_->AppendBytes(comment);
161 11348 : LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
162 5674 : }
163 :
164 0 : void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
165 : AbstractCode* code, Name* name) {
166 0 : name_buffer_->Init(tag);
167 0 : name_buffer_->AppendName(name);
168 0 : LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
169 0 : }
170 :
171 5373 : void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
172 : AbstractCode* code,
173 : SharedFunctionInfo* shared, Name* name) {
174 10746 : name_buffer_->Init(tag);
175 5373 : name_buffer_->AppendBytes(ComputeMarker(shared, code));
176 5373 : name_buffer_->AppendName(name);
177 10746 : LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
178 5373 : }
179 :
180 534 : void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
181 : AbstractCode* code,
182 : SharedFunctionInfo* shared, Name* source,
183 : int line, int column) {
184 1068 : name_buffer_->Init(tag);
185 534 : name_buffer_->AppendBytes(ComputeMarker(shared, code));
186 534 : name_buffer_->AppendString(shared->DebugName());
187 534 : name_buffer_->AppendByte(' ');
188 534 : if (source->IsString()) {
189 534 : name_buffer_->AppendString(String::cast(source));
190 : } else {
191 0 : name_buffer_->AppendBytes("symbol(hash ");
192 0 : name_buffer_->AppendHex(Name::cast(source)->Hash());
193 0 : name_buffer_->AppendByte(')');
194 : }
195 534 : name_buffer_->AppendByte(':');
196 534 : name_buffer_->AppendInt(line);
197 1068 : LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
198 534 : }
199 :
200 0 : void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
201 : AbstractCode* code, int args_count) {
202 0 : name_buffer_->Init(tag);
203 0 : name_buffer_->AppendInt(args_count);
204 0 : LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
205 0 : }
206 :
207 0 : void CodeEventLogger::RegExpCodeCreateEvent(AbstractCode* code,
208 : String* source) {
209 0 : name_buffer_->Init(CodeEventListener::REG_EXP_TAG);
210 0 : name_buffer_->AppendString(source);
211 0 : LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size());
212 0 : }
213 :
214 :
215 : // Linux perf tool logging support
216 : class PerfBasicLogger : public CodeEventLogger {
217 : public:
218 : PerfBasicLogger();
219 : ~PerfBasicLogger() override;
220 :
221 0 : void CodeMoveEvent(AbstractCode* from, Address to) override {}
222 0 : void CodeDisableOptEvent(AbstractCode* code,
223 0 : SharedFunctionInfo* shared) override {}
224 :
225 : private:
226 : void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
227 : const char* name, int length) override;
228 :
229 : // Extension added to V8 log file name to get the low-level log name.
230 : static const char kFilenameFormatString[];
231 : static const int kFilenameBufferPadding;
232 :
233 : FILE* perf_output_handle_;
234 : };
235 :
236 : const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
237 : // Extra space for the PID in the filename
238 : const int PerfBasicLogger::kFilenameBufferPadding = 16;
239 :
240 0 : PerfBasicLogger::PerfBasicLogger()
241 0 : : perf_output_handle_(NULL) {
242 : // Open the perf JIT dump file.
243 : int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
244 : ScopedVector<char> perf_dump_name(bufferSize);
245 : int size = SNPrintF(
246 : perf_dump_name,
247 : kFilenameFormatString,
248 0 : base::OS::GetCurrentProcessId());
249 0 : CHECK_NE(size, -1);
250 : perf_output_handle_ =
251 0 : base::OS::FOpen(perf_dump_name.start(), base::OS::LogFileOpenMode);
252 0 : CHECK_NOT_NULL(perf_output_handle_);
253 0 : setvbuf(perf_output_handle_, NULL, _IOLBF, 0);
254 0 : }
255 :
256 :
257 0 : PerfBasicLogger::~PerfBasicLogger() {
258 0 : fclose(perf_output_handle_);
259 0 : perf_output_handle_ = NULL;
260 0 : }
261 :
262 0 : void PerfBasicLogger::LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo*,
263 : const char* name, int length) {
264 0 : if (FLAG_perf_basic_prof_only_functions &&
265 0 : (code->kind() != AbstractCode::FUNCTION &&
266 0 : code->kind() != AbstractCode::INTERPRETED_FUNCTION &&
267 0 : code->kind() != AbstractCode::OPTIMIZED_FUNCTION)) {
268 0 : return;
269 : }
270 :
271 : // Linux perf expects hex literals without a leading 0x, while some
272 : // implementations of printf might prepend one when using the %p format
273 : // for pointers, leading to wrongly formatted JIT symbols maps.
274 : //
275 : // Instead, we use V8PRIxPTR format string and cast pointer to uintpr_t,
276 : // so that we have control over the exact output format.
277 : base::OS::FPrint(perf_output_handle_, "%" V8PRIxPTR " %x %.*s\n",
278 0 : reinterpret_cast<uintptr_t>(code->instruction_start()),
279 0 : code->instruction_size(), length, name);
280 : }
281 :
282 : // Low-level logging support.
283 : #define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;
284 :
285 : class LowLevelLogger : public CodeEventLogger {
286 : public:
287 : explicit LowLevelLogger(const char* file_name);
288 : ~LowLevelLogger() override;
289 :
290 : void CodeMoveEvent(AbstractCode* from, Address to) override;
291 0 : void CodeDisableOptEvent(AbstractCode* code,
292 0 : SharedFunctionInfo* shared) override {}
293 : void SnapshotPositionEvent(HeapObject* obj, int pos);
294 : void CodeMovingGCEvent() override;
295 :
296 : private:
297 : void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
298 : const char* name, int length) override;
299 :
300 : // Low-level profiling event structures.
301 : struct CodeCreateStruct {
302 : static const char kTag = 'C';
303 :
304 : int32_t name_size;
305 : Address code_address;
306 : int32_t code_size;
307 : };
308 :
309 :
310 : struct CodeMoveStruct {
311 : static const char kTag = 'M';
312 :
313 : Address from_address;
314 : Address to_address;
315 : };
316 :
317 :
318 : static const char kCodeMovingGCTag = 'G';
319 :
320 :
321 : // Extension added to V8 log file name to get the low-level log name.
322 : static const char kLogExt[];
323 :
324 : void LogCodeInfo();
325 : void LogWriteBytes(const char* bytes, int size);
326 :
327 : template <typename T>
328 0 : void LogWriteStruct(const T& s) {
329 0 : char tag = T::kTag;
330 : LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag));
331 : LogWriteBytes(reinterpret_cast<const char*>(&s), sizeof(s));
332 0 : }
333 :
334 : FILE* ll_output_handle_;
335 : };
336 :
337 : const char LowLevelLogger::kLogExt[] = ".ll";
338 :
339 0 : LowLevelLogger::LowLevelLogger(const char* name)
340 0 : : ll_output_handle_(NULL) {
341 : // Open the low-level log file.
342 0 : size_t len = strlen(name);
343 0 : ScopedVector<char> ll_name(static_cast<int>(len + sizeof(kLogExt)));
344 : MemCopy(ll_name.start(), name, len);
345 0 : MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt));
346 : ll_output_handle_ =
347 0 : base::OS::FOpen(ll_name.start(), base::OS::LogFileOpenMode);
348 0 : setvbuf(ll_output_handle_, NULL, _IOLBF, 0);
349 :
350 : LogCodeInfo();
351 0 : }
352 :
353 :
354 0 : LowLevelLogger::~LowLevelLogger() {
355 0 : fclose(ll_output_handle_);
356 0 : ll_output_handle_ = NULL;
357 0 : }
358 :
359 :
360 0 : void LowLevelLogger::LogCodeInfo() {
361 : #if V8_TARGET_ARCH_IA32
362 : const char arch[] = "ia32";
363 : #elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_64_BIT
364 0 : const char arch[] = "x64";
365 : #elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_32_BIT
366 : const char arch[] = "x32";
367 : #elif V8_TARGET_ARCH_ARM
368 : const char arch[] = "arm";
369 : #elif V8_TARGET_ARCH_PPC
370 : const char arch[] = "ppc";
371 : #elif V8_TARGET_ARCH_MIPS
372 : const char arch[] = "mips";
373 : #elif V8_TARGET_ARCH_X87
374 : const char arch[] = "x87";
375 : #elif V8_TARGET_ARCH_ARM64
376 : const char arch[] = "arm64";
377 : #elif V8_TARGET_ARCH_S390
378 : const char arch[] = "s390";
379 : #else
380 : const char arch[] = "unknown";
381 : #endif
382 : LogWriteBytes(arch, sizeof(arch));
383 0 : }
384 :
385 0 : void LowLevelLogger::LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo*,
386 : const char* name, int length) {
387 : CodeCreateStruct event;
388 0 : event.name_size = length;
389 0 : event.code_address = code->instruction_start();
390 0 : event.code_size = code->instruction_size();
391 0 : LogWriteStruct(event);
392 : LogWriteBytes(name, length);
393 : LogWriteBytes(
394 0 : reinterpret_cast<const char*>(code->instruction_start()),
395 0 : code->instruction_size());
396 0 : }
397 :
398 0 : void LowLevelLogger::CodeMoveEvent(AbstractCode* from, Address to) {
399 : CodeMoveStruct event;
400 0 : event.from_address = from->instruction_start();
401 0 : size_t header_size = from->instruction_start() - from->address();
402 0 : event.to_address = to + header_size;
403 0 : LogWriteStruct(event);
404 0 : }
405 :
406 :
407 0 : void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
408 0 : size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
409 : DCHECK(static_cast<size_t>(size) == rv);
410 : USE(rv);
411 0 : }
412 :
413 :
414 0 : void LowLevelLogger::CodeMovingGCEvent() {
415 0 : const char tag = kCodeMovingGCTag;
416 :
417 : LogWriteBytes(&tag, sizeof(tag));
418 0 : }
419 :
420 117 : class JitLogger : public CodeEventLogger {
421 : public:
422 : explicit JitLogger(JitCodeEventHandler code_event_handler);
423 :
424 : void CodeMoveEvent(AbstractCode* from, Address to) override;
425 4 : void CodeDisableOptEvent(AbstractCode* code,
426 4 : SharedFunctionInfo* shared) override {}
427 : void AddCodeLinePosInfoEvent(void* jit_handler_data, int pc_offset,
428 : int position,
429 : JitCodeEvent::PositionType position_type);
430 :
431 : void* StartCodePosInfoEvent();
432 : void EndCodePosInfoEvent(AbstractCode* code, void* jit_handler_data);
433 :
434 : private:
435 : void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
436 : const char* name, int length) override;
437 :
438 : JitCodeEventHandler code_event_handler_;
439 : base::Mutex logger_mutex_;
440 : };
441 :
442 :
443 39 : JitLogger::JitLogger(JitCodeEventHandler code_event_handler)
444 39 : : code_event_handler_(code_event_handler) {
445 39 : }
446 :
447 8895 : void JitLogger::LogRecordedBuffer(AbstractCode* code,
448 : SharedFunctionInfo* shared, const char* name,
449 : int length) {
450 : JitCodeEvent event;
451 : memset(&event, 0, sizeof(event));
452 : event.type = JitCodeEvent::CODE_ADDED;
453 8895 : event.code_start = code->instruction_start();
454 8895 : event.code_len = code->instruction_size();
455 : Handle<SharedFunctionInfo> shared_function_handle;
456 12121 : if (shared && shared->script()->IsScript()) {
457 : shared_function_handle = Handle<SharedFunctionInfo>(shared);
458 : }
459 8895 : event.script = ToApiHandle<v8::UnboundScript>(shared_function_handle);
460 8895 : event.name.str = name;
461 8895 : event.name.len = length;
462 8895 : code_event_handler_(&event);
463 8895 : }
464 :
465 238 : void JitLogger::CodeMoveEvent(AbstractCode* from, Address to) {
466 238 : base::LockGuard<base::Mutex> guard(&logger_mutex_);
467 :
468 : JitCodeEvent event;
469 238 : event.type = JitCodeEvent::CODE_MOVED;
470 238 : event.code_start = from->instruction_start();
471 238 : event.code_len = from->instruction_size();
472 :
473 : // Calculate the header size.
474 238 : const size_t header_size = from->instruction_start() - from->address();
475 :
476 : // Calculate the new start address of the instructions.
477 238 : event.new_code_start = to + header_size;
478 :
479 238 : code_event_handler_(&event);
480 238 : }
481 :
482 4244 : void JitLogger::AddCodeLinePosInfoEvent(
483 : void* jit_handler_data,
484 : int pc_offset,
485 : int position,
486 : JitCodeEvent::PositionType position_type) {
487 : JitCodeEvent event;
488 : memset(&event, 0, sizeof(event));
489 4244 : event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO;
490 4244 : event.user_data = jit_handler_data;
491 4244 : event.line_info.offset = pc_offset;
492 4244 : event.line_info.pos = position;
493 4244 : event.line_info.position_type = position_type;
494 :
495 4244 : code_event_handler_(&event);
496 4244 : }
497 :
498 :
499 325 : void* JitLogger::StartCodePosInfoEvent() {
500 : JitCodeEvent event;
501 : memset(&event, 0, sizeof(event));
502 325 : event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING;
503 :
504 325 : code_event_handler_(&event);
505 325 : return event.user_data;
506 : }
507 :
508 325 : void JitLogger::EndCodePosInfoEvent(AbstractCode* code,
509 : void* jit_handler_data) {
510 : JitCodeEvent event;
511 : memset(&event, 0, sizeof(event));
512 325 : event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING;
513 325 : event.code_start = code->instruction_start();
514 325 : event.user_data = jit_handler_data;
515 :
516 325 : code_event_handler_(&event);
517 325 : }
518 :
519 :
520 : // TODO(lpy): Keeping sampling thread inside V8 is a workaround currently,
521 : // the reason is to reduce code duplication during migration to sampler library,
522 : // sampling thread, as well as the sampler, will be moved to D8 eventually.
523 59285 : class SamplingThread : public base::Thread {
524 : public:
525 : static const int kSamplingThreadStackSize = 64 * KB;
526 :
527 : SamplingThread(sampler::Sampler* sampler, int interval_microseconds)
528 : : base::Thread(
529 : base::Thread::Options("SamplingThread", kSamplingThreadStackSize)),
530 : sampler_(sampler),
531 60782 : interval_microseconds_(interval_microseconds) {}
532 0 : void Run() override {
533 0 : while (sampler_->IsProfiling()) {
534 0 : sampler_->DoSample();
535 : base::OS::Sleep(
536 0 : base::TimeDelta::FromMicroseconds(interval_microseconds_));
537 : }
538 0 : }
539 :
540 : private:
541 : sampler::Sampler* sampler_;
542 : const int interval_microseconds_;
543 : };
544 :
545 :
546 : // The Profiler samples pc and sp values for the main thread.
547 : // Each sample is appended to a circular buffer.
548 : // An independent thread removes data and writes it to the log.
549 : // This design minimizes the time spent in the sampler.
550 : //
551 0 : class Profiler: public base::Thread {
552 : public:
553 : explicit Profiler(Isolate* isolate);
554 : void Engage();
555 : void Disengage();
556 :
557 : // Inserts collected profiling data into buffer.
558 0 : void Insert(v8::TickSample* sample) {
559 0 : if (paused_)
560 0 : return;
561 :
562 0 : if (Succ(head_) == static_cast<int>(base::NoBarrier_Load(&tail_))) {
563 0 : overflow_ = true;
564 : } else {
565 0 : buffer_[head_] = *sample;
566 0 : head_ = Succ(head_);
567 0 : buffer_semaphore_.Signal(); // Tell we have an element.
568 : }
569 : }
570 :
571 : virtual void Run();
572 :
573 : // Pause and Resume TickSample data collection.
574 0 : void pause() { paused_ = true; }
575 0 : void resume() { paused_ = false; }
576 :
577 : private:
578 : // Waits for a signal and removes profiling data.
579 0 : bool Remove(v8::TickSample* sample) {
580 0 : buffer_semaphore_.Wait(); // Wait for an element.
581 0 : *sample = buffer_[base::NoBarrier_Load(&tail_)];
582 0 : bool result = overflow_;
583 : base::NoBarrier_Store(&tail_, static_cast<base::Atomic32>(
584 : Succ(base::NoBarrier_Load(&tail_))));
585 0 : overflow_ = false;
586 0 : return result;
587 : }
588 :
589 : // Returns the next index in the cyclic buffer.
590 0 : int Succ(int index) { return (index + 1) % kBufferSize; }
591 :
592 : Isolate* isolate_;
593 : // Cyclic buffer for communicating profiling samples
594 : // between the signal handler and the worker thread.
595 : static const int kBufferSize = 128;
596 : v8::TickSample buffer_[kBufferSize]; // Buffer storage.
597 : int head_; // Index to the buffer head.
598 : base::Atomic32 tail_; // Index to the buffer tail.
599 : bool overflow_; // Tell whether a buffer overflow has occurred.
600 : // Sempahore used for buffer synchronization.
601 : base::Semaphore buffer_semaphore_;
602 :
603 : // Tells whether profiler is engaged, that is, processing thread is stated.
604 : bool engaged_;
605 :
606 : // Tells whether worker thread should continue running.
607 : base::Atomic32 running_;
608 :
609 : // Tells whether we are currently recording tick samples.
610 : bool paused_;
611 : };
612 :
613 :
614 : //
615 : // Ticker used to provide ticks to the profiler and the sliding state
616 : // window.
617 : //
618 : class Ticker: public sampler::Sampler {
619 : public:
620 60782 : Ticker(Isolate* isolate, int interval_microseconds)
621 : : sampler::Sampler(reinterpret_cast<v8::Isolate*>(isolate)),
622 : profiler_(nullptr),
623 121564 : sampling_thread_(new SamplingThread(this, interval_microseconds)) {}
624 :
625 177855 : ~Ticker() {
626 59285 : if (IsActive()) Stop();
627 59285 : delete sampling_thread_;
628 118570 : }
629 :
630 0 : void SetProfiler(Profiler* profiler) {
631 : DCHECK(profiler_ == nullptr);
632 0 : profiler_ = profiler;
633 0 : IncreaseProfilingDepth();
634 0 : if (!IsActive()) Start();
635 0 : sampling_thread_->StartSynchronously();
636 0 : }
637 :
638 0 : void ClearProfiler() {
639 0 : profiler_ = nullptr;
640 0 : if (IsActive()) Stop();
641 0 : DecreaseProfilingDepth();
642 0 : sampling_thread_->Join();
643 0 : }
644 :
645 0 : void SampleStack(const v8::RegisterState& state) override {
646 0 : if (!profiler_) return;
647 0 : Isolate* isolate = reinterpret_cast<Isolate*>(this->isolate());
648 : TickSample sample;
649 0 : sample.Init(isolate, state, TickSample::kIncludeCEntryFrame, true);
650 0 : profiler_->Insert(&sample);
651 : }
652 :
653 : private:
654 : Profiler* profiler_;
655 : SamplingThread* sampling_thread_;
656 : };
657 :
658 :
659 : //
660 : // Profiler implementation.
661 : //
662 0 : Profiler::Profiler(Isolate* isolate)
663 : : base::Thread(Options("v8:Profiler")),
664 : isolate_(isolate),
665 : head_(0),
666 : overflow_(false),
667 : buffer_semaphore_(0),
668 : engaged_(false),
669 0 : paused_(false) {
670 0 : base::NoBarrier_Store(&tail_, 0);
671 0 : base::NoBarrier_Store(&running_, 0);
672 0 : }
673 :
674 :
675 0 : void Profiler::Engage() {
676 0 : if (engaged_) return;
677 0 : engaged_ = true;
678 :
679 : std::vector<base::OS::SharedLibraryAddress> addresses =
680 0 : base::OS::GetSharedLibraryAddresses();
681 0 : for (size_t i = 0; i < addresses.size(); ++i) {
682 0 : LOG(isolate_,
683 : SharedLibraryEvent(addresses[i].library_path, addresses[i].start,
684 : addresses[i].end, addresses[i].aslr_slide));
685 : }
686 :
687 : // Start thread processing the profiler buffer.
688 0 : base::NoBarrier_Store(&running_, 1);
689 0 : Start();
690 :
691 : // Register to get ticks.
692 0 : Logger* logger = isolate_->logger();
693 0 : logger->ticker_->SetProfiler(this);
694 :
695 0 : logger->ProfilerBeginEvent();
696 : }
697 :
698 :
699 0 : void Profiler::Disengage() {
700 0 : if (!engaged_) return;
701 :
702 : // Stop receiving ticks.
703 0 : isolate_->logger()->ticker_->ClearProfiler();
704 :
705 : // Terminate the worker thread by setting running_ to false,
706 : // inserting a fake element in the queue and then wait for
707 : // the thread to terminate.
708 0 : base::NoBarrier_Store(&running_, 0);
709 : v8::TickSample sample;
710 : // Reset 'paused_' flag, otherwise semaphore may not be signalled.
711 : resume();
712 0 : Insert(&sample);
713 0 : Join();
714 :
715 0 : LOG(isolate_, UncheckedStringEvent("profiler", "end"));
716 : }
717 :
718 :
719 0 : void Profiler::Run() {
720 : v8::TickSample sample;
721 0 : bool overflow = Remove(&sample);
722 0 : while (base::NoBarrier_Load(&running_)) {
723 0 : LOG(isolate_, TickEvent(&sample, overflow));
724 0 : overflow = Remove(&sample);
725 : }
726 0 : }
727 :
728 :
729 : //
730 : // Logger class implementation.
731 : //
732 :
733 60782 : Logger::Logger(Isolate* isolate)
734 : : isolate_(isolate),
735 : ticker_(NULL),
736 : profiler_(NULL),
737 : log_events_(NULL),
738 : is_logging_(false),
739 60782 : log_(new Log(this)),
740 : perf_basic_logger_(NULL),
741 : perf_jit_logger_(NULL),
742 : ll_logger_(NULL),
743 : jit_logger_(NULL),
744 : listeners_(5),
745 243128 : is_initialized_(false) {}
746 :
747 118570 : Logger::~Logger() {
748 118570 : delete log_;
749 118570 : }
750 :
751 296 : void Logger::addCodeEventListener(CodeEventListener* listener) {
752 1306 : bool result = isolate_->code_event_dispatcher()->AddListener(listener);
753 : USE(result);
754 : DCHECK(result);
755 296 : }
756 :
757 290 : void Logger::removeCodeEventListener(CodeEventListener* listener) {
758 1722 : isolate_->code_event_dispatcher()->RemoveListener(listener);
759 290 : }
760 :
761 0 : void Logger::ProfilerBeginEvent() {
762 0 : if (!log_->IsEnabled()) return;
763 0 : Log::MessageBuilder msg(log_);
764 0 : msg.Append("profiler,\"begin\",%d", FLAG_prof_sampling_interval);
765 0 : msg.WriteToLogFile();
766 : }
767 :
768 :
769 0 : void Logger::StringEvent(const char* name, const char* value) {
770 0 : if (FLAG_log) UncheckedStringEvent(name, value);
771 0 : }
772 :
773 :
774 0 : void Logger::UncheckedStringEvent(const char* name, const char* value) {
775 0 : if (!log_->IsEnabled()) return;
776 0 : Log::MessageBuilder msg(log_);
777 0 : msg.Append("%s,\"%s\"", name, value);
778 0 : msg.WriteToLogFile();
779 : }
780 :
781 :
782 0 : void Logger::IntEvent(const char* name, int value) {
783 0 : if (FLAG_log) UncheckedIntEvent(name, value);
784 0 : }
785 :
786 :
787 48 : void Logger::IntPtrTEvent(const char* name, intptr_t value) {
788 48 : if (FLAG_log) UncheckedIntPtrTEvent(name, value);
789 48 : }
790 :
791 :
792 0 : void Logger::UncheckedIntEvent(const char* name, int value) {
793 0 : if (!log_->IsEnabled()) return;
794 0 : Log::MessageBuilder msg(log_);
795 0 : msg.Append("%s,%d", name, value);
796 0 : msg.WriteToLogFile();
797 : }
798 :
799 :
800 48 : void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
801 96 : if (!log_->IsEnabled()) return;
802 48 : Log::MessageBuilder msg(log_);
803 48 : msg.Append("%s,%" V8PRIdPTR, name, value);
804 48 : msg.WriteToLogFile();
805 : }
806 :
807 :
808 0 : void Logger::HandleEvent(const char* name, Object** location) {
809 0 : if (!log_->IsEnabled() || !FLAG_log_handles) return;
810 0 : Log::MessageBuilder msg(log_);
811 0 : msg.Append("%s,%p", name, static_cast<void*>(location));
812 0 : msg.WriteToLogFile();
813 : }
814 :
815 :
816 : // ApiEvent is private so all the calls come from the Logger class. It is the
817 : // caller's responsibility to ensure that log is enabled and that
818 : // FLAG_log_api is true.
819 0 : void Logger::ApiEvent(const char* format, ...) {
820 : DCHECK(log_->IsEnabled() && FLAG_log_api);
821 0 : Log::MessageBuilder msg(log_);
822 : va_list ap;
823 0 : va_start(ap, format);
824 0 : msg.AppendVA(format, ap);
825 0 : va_end(ap);
826 0 : msg.WriteToLogFile();
827 0 : }
828 :
829 :
830 0 : void Logger::ApiSecurityCheck() {
831 0 : if (!log_->IsEnabled() || !FLAG_log_api) return;
832 0 : ApiEvent("api,check-security");
833 : }
834 :
835 0 : void Logger::SharedLibraryEvent(const std::string& library_path,
836 : uintptr_t start, uintptr_t end,
837 : intptr_t aslr_slide) {
838 0 : if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
839 0 : Log::MessageBuilder msg(log_);
840 : msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR
841 : ",%" V8PRIdPTR,
842 0 : library_path.c_str(), start, end, aslr_slide);
843 0 : msg.WriteToLogFile();
844 : }
845 :
846 0 : void Logger::CodeDeoptEvent(Code* code, DeoptKind kind, Address pc,
847 : int fp_to_sp_delta) {
848 0 : if (!log_->IsEnabled()) return;
849 0 : Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc);
850 0 : Log::MessageBuilder msg(log_);
851 : int since_epoch = timer_.IsStarted()
852 : ? static_cast<int>(timer_.Elapsed().InMicroseconds())
853 0 : : -1;
854 0 : msg.Append("code-deopt,%d,%d,", since_epoch, code->CodeSize());
855 0 : msg.AppendAddress(code->address());
856 :
857 : // Deoptimization position.
858 0 : std::ostringstream deopt_location;
859 : int inlining_id = -1;
860 : int script_offset = -1;
861 0 : if (info.position.IsKnown()) {
862 0 : info.position.Print(deopt_location, code);
863 : inlining_id = info.position.InliningId();
864 : script_offset = info.position.ScriptOffset();
865 : } else {
866 0 : deopt_location << "<unknown>";
867 : }
868 0 : msg.Append(",%d,%d,", inlining_id, script_offset);
869 0 : switch (kind) {
870 : case kLazy:
871 0 : msg.Append("\"lazy\",");
872 0 : break;
873 : case kSoft:
874 0 : msg.Append("\"soft\",");
875 0 : break;
876 : case kEager:
877 0 : msg.Append("\"eager\",");
878 0 : break;
879 : }
880 0 : msg.AppendDoubleQuotedString(deopt_location.str().c_str());
881 0 : msg.Append(",");
882 0 : msg.AppendDoubleQuotedString(DeoptimizeReasonToString(info.deopt_reason));
883 0 : msg.WriteToLogFile();
884 : }
885 :
886 :
887 0 : void Logger::CurrentTimeEvent() {
888 0 : if (!log_->IsEnabled()) return;
889 : DCHECK(FLAG_log_timer_events || FLAG_prof_cpp);
890 0 : Log::MessageBuilder msg(log_);
891 0 : int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
892 0 : msg.Append("current-time,%d", since_epoch);
893 0 : msg.WriteToLogFile();
894 : }
895 :
896 :
897 0 : void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
898 0 : if (!log_->IsEnabled()) return;
899 : DCHECK(FLAG_log_internal_timer_events);
900 0 : Log::MessageBuilder msg(log_);
901 0 : int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
902 : const char* format = (se == START) ? "timer-event-start,\"%s\",%ld"
903 0 : : "timer-event-end,\"%s\",%ld";
904 0 : msg.Append(format, name, since_epoch);
905 0 : msg.WriteToLogFile();
906 : }
907 :
908 :
909 0 : void Logger::EnterExternal(Isolate* isolate) {
910 0 : LOG(isolate, TimerEvent(START, TimerEventExternal::name()));
911 : DCHECK(isolate->current_vm_state() == JS);
912 : isolate->set_current_vm_state(EXTERNAL);
913 0 : }
914 :
915 :
916 0 : void Logger::LeaveExternal(Isolate* isolate) {
917 0 : LOG(isolate, TimerEvent(END, TimerEventExternal::name()));
918 : DCHECK(isolate->current_vm_state() == EXTERNAL);
919 : isolate->set_current_vm_state(JS);
920 0 : }
921 :
922 : // Instantiate template methods.
923 : #define V(TimerName, expose) \
924 : template void TimerEventScope<TimerEvent##TimerName>::LogTimerEvent( \
925 : Logger::StartEnd se);
926 : TIMER_EVENTS_LIST(V)
927 : #undef V
928 :
929 336 : void Logger::ApiNamedPropertyAccess(const char* tag,
930 : JSObject* holder,
931 : Object* name) {
932 : DCHECK(name->IsName());
933 1008 : if (!log_->IsEnabled() || !FLAG_log_api) return;
934 0 : String* class_name_obj = holder->class_name();
935 : std::unique_ptr<char[]> class_name =
936 0 : class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
937 0 : if (name->IsString()) {
938 : std::unique_ptr<char[]> property_name =
939 0 : String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
940 : ApiEvent("api,%s,\"%s\",\"%s\"", tag, class_name.get(),
941 0 : property_name.get());
942 : } else {
943 : Symbol* symbol = Symbol::cast(name);
944 : uint32_t hash = symbol->Hash();
945 0 : if (symbol->name()->IsUndefined(symbol->GetIsolate())) {
946 0 : ApiEvent("api,%s,\"%s\",symbol(hash %x)", tag, class_name.get(), hash);
947 : } else {
948 : std::unique_ptr<char[]> str =
949 : String::cast(symbol->name())
950 0 : ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
951 : ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)", tag, class_name.get(),
952 0 : str.get(), hash);
953 : }
954 : }
955 : }
956 :
957 0 : void Logger::ApiIndexedPropertyAccess(const char* tag,
958 : JSObject* holder,
959 : uint32_t index) {
960 0 : if (!log_->IsEnabled() || !FLAG_log_api) return;
961 0 : String* class_name_obj = holder->class_name();
962 : std::unique_ptr<char[]> class_name =
963 0 : class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
964 0 : ApiEvent("api,%s,\"%s\",%u", tag, class_name.get(), index);
965 : }
966 :
967 :
968 0 : void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
969 0 : if (!log_->IsEnabled() || !FLAG_log_api) return;
970 0 : String* class_name_obj = object->class_name();
971 : std::unique_ptr<char[]> class_name =
972 0 : class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
973 0 : ApiEvent("api,%s,\"%s\"", tag, class_name.get());
974 : }
975 :
976 :
977 522 : void Logger::ApiEntryCall(const char* name) {
978 1566 : if (!log_->IsEnabled() || !FLAG_log_api) return;
979 0 : ApiEvent("api,%s", name);
980 : }
981 :
982 :
983 318 : void Logger::NewEvent(const char* name, void* object, size_t size) {
984 636 : if (!log_->IsEnabled() || !FLAG_log) return;
985 318 : Log::MessageBuilder msg(log_);
986 318 : msg.Append("new,%s,%p,%u", name, object, static_cast<unsigned int>(size));
987 318 : msg.WriteToLogFile();
988 : }
989 :
990 :
991 294 : void Logger::DeleteEvent(const char* name, void* object) {
992 882 : if (!log_->IsEnabled() || !FLAG_log) return;
993 0 : Log::MessageBuilder msg(log_);
994 0 : msg.Append("delete,%s,%p", name, object);
995 0 : msg.WriteToLogFile();
996 : }
997 :
998 :
999 900 : void Logger::CallbackEventInternal(const char* prefix, Name* name,
1000 : Address entry_point) {
1001 1800 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1002 900 : Log::MessageBuilder msg(log_);
1003 : msg.Append("%s,%s,-2,",
1004 : kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT],
1005 900 : kLogEventsNames[CodeEventListener::CALLBACK_TAG]);
1006 : int timestamp = timer_.IsStarted()
1007 : ? static_cast<int>(timer_.Elapsed().InMicroseconds())
1008 900 : : -1;
1009 900 : msg.Append("%d,", timestamp);
1010 900 : msg.AppendAddress(entry_point);
1011 900 : if (name->IsString()) {
1012 : std::unique_ptr<char[]> str =
1013 888 : String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1014 888 : msg.Append(",1,\"%s%s\"", prefix, str.get());
1015 : } else {
1016 : Symbol* symbol = Symbol::cast(name);
1017 12 : if (symbol->name()->IsUndefined(symbol->GetIsolate())) {
1018 0 : msg.Append(",1,symbol(hash %x)", symbol->Hash());
1019 : } else {
1020 : std::unique_ptr<char[]> str =
1021 : String::cast(symbol->name())
1022 12 : ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1023 : msg.Append(",1,symbol(\"%s%s\" hash %x)", prefix, str.get(),
1024 12 : symbol->Hash());
1025 : }
1026 : }
1027 900 : msg.WriteToLogFile();
1028 : }
1029 :
1030 :
1031 198 : void Logger::CallbackEvent(Name* name, Address entry_point) {
1032 198 : CallbackEventInternal("", name, entry_point);
1033 198 : }
1034 :
1035 :
1036 354 : void Logger::GetterCallbackEvent(Name* name, Address entry_point) {
1037 354 : CallbackEventInternal("get ", name, entry_point);
1038 354 : }
1039 :
1040 :
1041 348 : void Logger::SetterCallbackEvent(Name* name, Address entry_point) {
1042 348 : CallbackEventInternal("set ", name, entry_point);
1043 348 : }
1044 :
1045 : namespace {
1046 :
1047 48753 : void AppendCodeCreateHeader(Log::MessageBuilder* msg,
1048 : CodeEventListener::LogEventsAndTags tag,
1049 : AbstractCode* code, base::ElapsedTimer* timer) {
1050 : DCHECK(msg);
1051 : msg->Append("%s,%s,%d,",
1052 : kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT],
1053 48753 : kLogEventsNames[tag], code->kind());
1054 : int timestamp = timer->IsStarted()
1055 : ? static_cast<int>(timer->Elapsed().InMicroseconds())
1056 48753 : : -1;
1057 48753 : msg->Append("%d,", timestamp);
1058 48753 : msg->AppendAddress(code->address());
1059 48753 : msg->Append(",%d,", code->ExecutableSize());
1060 48753 : }
1061 :
1062 : } // namespace
1063 :
1064 32939 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1065 : AbstractCode* code, const char* comment) {
1066 32939 : if (!is_logging_code_events()) return;
1067 65878 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1068 32939 : Log::MessageBuilder msg(log_);
1069 32939 : AppendCodeCreateHeader(&msg, tag, code, &timer_);
1070 32939 : msg.AppendDoubleQuotedString(comment);
1071 32939 : msg.WriteToLogFile();
1072 : }
1073 :
1074 0 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1075 : AbstractCode* code, Name* name) {
1076 0 : if (!is_logging_code_events()) return;
1077 0 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1078 0 : Log::MessageBuilder msg(log_);
1079 0 : AppendCodeCreateHeader(&msg, tag, code, &timer_);
1080 0 : if (name->IsString()) {
1081 0 : msg.Append('"');
1082 0 : msg.AppendDetailed(String::cast(name), false);
1083 0 : msg.Append('"');
1084 : } else {
1085 0 : msg.AppendSymbolName(Symbol::cast(name));
1086 : }
1087 0 : msg.WriteToLogFile();
1088 : }
1089 :
1090 15732 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1091 : AbstractCode* code, SharedFunctionInfo* shared,
1092 : Name* name) {
1093 15732 : if (!is_logging_code_events()) return;
1094 31464 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1095 15732 : if (code == AbstractCode::cast(
1096 15732 : isolate_->builtins()->builtin(Builtins::kCompileLazy))) {
1097 : return;
1098 : }
1099 :
1100 15732 : Log::MessageBuilder msg(log_);
1101 15732 : AppendCodeCreateHeader(&msg, tag, code, &timer_);
1102 15732 : if (name->IsString()) {
1103 : std::unique_ptr<char[]> str =
1104 15732 : String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1105 15732 : msg.Append("\"%s\"", str.get());
1106 : } else {
1107 0 : msg.AppendSymbolName(Symbol::cast(name));
1108 : }
1109 15732 : msg.Append(',');
1110 15732 : msg.AppendAddress(shared->address());
1111 15732 : msg.Append(",%s", ComputeMarker(shared, code));
1112 15732 : msg.WriteToLogFile();
1113 : }
1114 :
1115 :
1116 : // Although, it is possible to extract source and line from
1117 : // the SharedFunctionInfo object, we left it to caller
1118 : // to leave logging functions free from heap allocations.
1119 82 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1120 : AbstractCode* code, SharedFunctionInfo* shared,
1121 : Name* source, int line, int column) {
1122 82 : if (!is_logging_code_events()) return;
1123 164 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1124 82 : Log::MessageBuilder msg(log_);
1125 82 : AppendCodeCreateHeader(&msg, tag, code, &timer_);
1126 : std::unique_ptr<char[]> name =
1127 82 : shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1128 82 : msg.Append("\"%s ", name.get());
1129 82 : if (source->IsString()) {
1130 : std::unique_ptr<char[]> sourcestr = String::cast(source)->ToCString(
1131 82 : DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1132 82 : msg.Append("%s", sourcestr.get());
1133 : } else {
1134 0 : msg.AppendSymbolName(Symbol::cast(source));
1135 : }
1136 82 : msg.Append(":%d:%d\",", line, column);
1137 82 : msg.AppendAddress(shared->address());
1138 82 : msg.Append(",%s", ComputeMarker(shared, code));
1139 82 : msg.WriteToLogFile();
1140 : }
1141 :
1142 0 : void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
1143 : AbstractCode* code, int args_count) {
1144 0 : if (!is_logging_code_events()) return;
1145 0 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1146 0 : Log::MessageBuilder msg(log_);
1147 0 : AppendCodeCreateHeader(&msg, tag, code, &timer_);
1148 0 : msg.Append("\"args_count: %d\"", args_count);
1149 0 : msg.WriteToLogFile();
1150 : }
1151 :
1152 0 : void Logger::CodeDisableOptEvent(AbstractCode* code,
1153 : SharedFunctionInfo* shared) {
1154 0 : if (!is_logging_code_events()) return;
1155 0 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1156 0 : Log::MessageBuilder msg(log_);
1157 0 : msg.Append("%s,", kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT]);
1158 : std::unique_ptr<char[]> name =
1159 0 : shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
1160 0 : msg.Append("\"%s\",", name.get());
1161 0 : msg.Append("\"%s\"", GetBailoutReason(shared->disable_optimization_reason()));
1162 0 : msg.WriteToLogFile();
1163 : }
1164 :
1165 :
1166 0 : void Logger::CodeMovingGCEvent() {
1167 0 : if (!is_logging_code_events()) return;
1168 0 : if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1169 0 : base::OS::SignalCodeMovingGC();
1170 : }
1171 :
1172 0 : void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) {
1173 0 : if (!is_logging_code_events()) return;
1174 0 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1175 0 : Log::MessageBuilder msg(log_);
1176 0 : AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code, &timer_);
1177 0 : msg.Append('"');
1178 0 : msg.AppendDetailed(source, false);
1179 0 : msg.Append('"');
1180 0 : msg.WriteToLogFile();
1181 : }
1182 :
1183 0 : void Logger::CodeMoveEvent(AbstractCode* from, Address to) {
1184 0 : if (!is_logging_code_events()) return;
1185 0 : MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(), to);
1186 : }
1187 :
1188 349 : void Logger::CodeLinePosInfoRecordEvent(AbstractCode* code,
1189 : ByteArray* source_position_table) {
1190 349 : if (jit_logger_) {
1191 325 : void* jit_handler_data = jit_logger_->StartCodePosInfoEvent();
1192 3895 : for (SourcePositionTableIterator iter(source_position_table); !iter.done();
1193 3245 : iter.Advance()) {
1194 3245 : if (iter.is_statement()) {
1195 : jit_logger_->AddCodeLinePosInfoEvent(
1196 : jit_handler_data, iter.code_offset(),
1197 999 : iter.source_position().ScriptOffset(),
1198 999 : JitCodeEvent::STATEMENT_POSITION);
1199 : }
1200 : jit_logger_->AddCodeLinePosInfoEvent(
1201 : jit_handler_data, iter.code_offset(),
1202 6490 : iter.source_position().ScriptOffset(), JitCodeEvent::POSITION);
1203 : }
1204 325 : jit_logger_->EndCodePosInfoEvent(code, jit_handler_data);
1205 : }
1206 349 : }
1207 :
1208 0 : void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
1209 0 : if (code_name == NULL) return; // Not a code object.
1210 0 : Log::MessageBuilder msg(log_);
1211 : msg.Append("%s,%d,",
1212 0 : kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT], pos);
1213 0 : msg.AppendDoubleQuotedString(code_name);
1214 0 : msg.WriteToLogFile();
1215 : }
1216 :
1217 :
1218 1413 : void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
1219 2826 : if (!is_logging_code_events()) return;
1220 1413 : MoveEventInternal(CodeEventListener::SHARED_FUNC_MOVE_EVENT, from, to);
1221 : }
1222 :
1223 1413 : void Logger::MoveEventInternal(CodeEventListener::LogEventsAndTags event,
1224 : Address from, Address to) {
1225 2826 : if (!FLAG_log_code || !log_->IsEnabled()) return;
1226 0 : Log::MessageBuilder msg(log_);
1227 0 : msg.Append("%s,", kLogEventsNames[event]);
1228 0 : msg.AppendAddress(from);
1229 0 : msg.Append(',');
1230 0 : msg.AppendAddress(to);
1231 0 : msg.WriteToLogFile();
1232 : }
1233 :
1234 :
1235 0 : void Logger::ResourceEvent(const char* name, const char* tag) {
1236 0 : if (!log_->IsEnabled() || !FLAG_log) return;
1237 0 : Log::MessageBuilder msg(log_);
1238 0 : msg.Append("%s,%s,", name, tag);
1239 :
1240 : uint32_t sec, usec;
1241 0 : if (base::OS::GetUserTime(&sec, &usec) != -1) {
1242 0 : msg.Append("%d,%d,", sec, usec);
1243 : }
1244 0 : msg.Append("%.0f", base::OS::TimeCurrentMillis());
1245 0 : msg.WriteToLogFile();
1246 : }
1247 :
1248 :
1249 0 : void Logger::SuspectReadEvent(Name* name, Object* obj) {
1250 0 : if (!log_->IsEnabled() || !FLAG_log_suspect) return;
1251 0 : Log::MessageBuilder msg(log_);
1252 : String* class_name = obj->IsJSObject()
1253 : ? JSObject::cast(obj)->class_name()
1254 0 : : isolate_->heap()->empty_string();
1255 0 : msg.Append("suspect-read,");
1256 0 : msg.Append(class_name);
1257 0 : msg.Append(',');
1258 0 : if (name->IsString()) {
1259 0 : msg.Append('"');
1260 0 : msg.Append(String::cast(name));
1261 0 : msg.Append('"');
1262 : } else {
1263 0 : msg.AppendSymbolName(Symbol::cast(name));
1264 : }
1265 0 : msg.WriteToLogFile();
1266 : }
1267 :
1268 :
1269 0 : void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
1270 0 : if (!log_->IsEnabled() || !FLAG_log_gc) return;
1271 0 : Log::MessageBuilder msg(log_);
1272 : // Using non-relative system time in order to be able to synchronize with
1273 : // external memory profiling events (e.g. DOM memory size).
1274 : msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f", space, kind,
1275 0 : base::OS::TimeCurrentMillis());
1276 0 : msg.WriteToLogFile();
1277 : }
1278 :
1279 :
1280 0 : void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1281 0 : if (!log_->IsEnabled() || !FLAG_log_gc) return;
1282 0 : Log::MessageBuilder msg(log_);
1283 0 : msg.Append("heap-sample-end,\"%s\",\"%s\"", space, kind);
1284 0 : msg.WriteToLogFile();
1285 : }
1286 :
1287 :
1288 0 : void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1289 0 : if (!log_->IsEnabled() || !FLAG_log_gc) return;
1290 0 : Log::MessageBuilder msg(log_);
1291 0 : msg.Append("heap-sample-item,%s,%d,%d", type, number, bytes);
1292 0 : msg.WriteToLogFile();
1293 : }
1294 :
1295 :
1296 0 : void Logger::RuntimeCallTimerEvent() {
1297 0 : RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats();
1298 0 : RuntimeCallCounter* counter = stats->current_counter();
1299 0 : if (counter == nullptr) return;
1300 0 : Log::MessageBuilder msg(log_);
1301 0 : msg.Append("active-runtime-timer,");
1302 0 : msg.AppendDoubleQuotedString(counter->name());
1303 0 : msg.WriteToLogFile();
1304 : }
1305 :
1306 0 : void Logger::TickEvent(v8::TickSample* sample, bool overflow) {
1307 0 : if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
1308 0 : if (V8_UNLIKELY(FLAG_runtime_stats ==
1309 : v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE)) {
1310 0 : RuntimeCallTimerEvent();
1311 : }
1312 0 : Log::MessageBuilder msg(log_);
1313 0 : msg.Append("%s,", kLogEventsNames[CodeEventListener::TICK_EVENT]);
1314 0 : msg.AppendAddress(reinterpret_cast<Address>(sample->pc));
1315 0 : msg.Append(",%d", static_cast<int>(timer_.Elapsed().InMicroseconds()));
1316 0 : if (sample->has_external_callback) {
1317 0 : msg.Append(",1,");
1318 : msg.AppendAddress(
1319 0 : reinterpret_cast<Address>(sample->external_callback_entry));
1320 : } else {
1321 0 : msg.Append(",0,");
1322 0 : msg.AppendAddress(reinterpret_cast<Address>(sample->tos));
1323 : }
1324 0 : msg.Append(",%d", static_cast<int>(sample->state));
1325 0 : if (overflow) {
1326 0 : msg.Append(",overflow");
1327 : }
1328 0 : for (unsigned i = 0; i < sample->frames_count; ++i) {
1329 0 : msg.Append(',');
1330 0 : msg.AppendAddress(reinterpret_cast<Address>(sample->stack[i]));
1331 : }
1332 0 : msg.WriteToLogFile();
1333 : }
1334 :
1335 0 : void Logger::ICEvent(const char* type, bool keyed, const Address pc, int line,
1336 : int column, Map* map, Object* key, char old_state,
1337 : char new_state, const char* modifier,
1338 : const char* slow_stub_reason) {
1339 0 : if (!log_->IsEnabled() || !FLAG_trace_ic) return;
1340 0 : Log::MessageBuilder msg(log_);
1341 0 : if (keyed) msg.Append("Keyed");
1342 0 : msg.Append("%s,", type);
1343 0 : msg.AppendAddress(pc);
1344 0 : msg.Append(",%d,%d,", line, column);
1345 0 : msg.Append(old_state);
1346 0 : msg.Append(",");
1347 0 : msg.Append(new_state);
1348 0 : msg.Append(",");
1349 0 : msg.AppendAddress(reinterpret_cast<Address>(map));
1350 0 : msg.Append(",");
1351 0 : if (key->IsSmi()) {
1352 0 : msg.Append("%d", Smi::cast(key)->value());
1353 0 : } else if (key->IsNumber()) {
1354 0 : msg.Append("%lf", key->Number());
1355 0 : } else if (key->IsString()) {
1356 0 : msg.AppendDetailed(String::cast(key), false);
1357 0 : } else if (key->IsSymbol()) {
1358 0 : msg.AppendSymbolName(Symbol::cast(key));
1359 : }
1360 0 : msg.Append(",%s,", modifier);
1361 0 : if (slow_stub_reason != nullptr) {
1362 0 : msg.AppendDoubleQuotedString(slow_stub_reason);
1363 : }
1364 0 : msg.WriteToLogFile();
1365 : }
1366 :
1367 0 : void Logger::CompareIC(const Address pc, int line, int column, Code* stub,
1368 : const char* op, const char* old_left,
1369 : const char* old_right, const char* old_state,
1370 : const char* new_left, const char* new_right,
1371 : const char* new_state) {
1372 0 : if (!log_->IsEnabled() || !FLAG_trace_ic) return;
1373 0 : Log::MessageBuilder msg(log_);
1374 0 : msg.Append("CompareIC,");
1375 0 : msg.AppendAddress(pc);
1376 0 : msg.Append(",%d,%d,", line, column);
1377 0 : msg.AppendAddress(reinterpret_cast<Address>(stub));
1378 : msg.Append(",%s,%s,%s,%s,%s,%s,%s", op, old_left, old_right, old_state,
1379 0 : new_left, new_right, new_state);
1380 0 : msg.WriteToLogFile();
1381 : }
1382 :
1383 0 : void Logger::BinaryOpIC(const Address pc, int line, int column, Code* stub,
1384 : const char* old_state, const char* new_state,
1385 : AllocationSite* allocation_site) {
1386 0 : if (!log_->IsEnabled() || !FLAG_trace_ic) return;
1387 0 : Log::MessageBuilder msg(log_);
1388 0 : msg.Append("BinaryOpIC,");
1389 0 : msg.AppendAddress(pc);
1390 0 : msg.Append(",%d,%d,", line, column);
1391 0 : msg.AppendAddress(reinterpret_cast<Address>(stub));
1392 0 : msg.Append(",%s,%s,", old_state, new_state);
1393 0 : if (allocation_site != nullptr) {
1394 0 : msg.AppendAddress(reinterpret_cast<Address>(allocation_site));
1395 : }
1396 0 : msg.WriteToLogFile();
1397 : }
1398 :
1399 0 : void Logger::ToBooleanIC(const Address pc, int line, int column, Code* stub,
1400 : const char* old_state, const char* new_state) {
1401 0 : if (!log_->IsEnabled() || !FLAG_trace_ic) return;
1402 0 : Log::MessageBuilder msg(log_);
1403 0 : msg.Append("ToBooleanIC,");
1404 0 : msg.AppendAddress(pc);
1405 0 : msg.Append(",%d,%d,", line, column);
1406 0 : msg.AppendAddress(reinterpret_cast<Address>(stub));
1407 0 : msg.Append(",%s,%s,", old_state, new_state);
1408 0 : msg.WriteToLogFile();
1409 : }
1410 :
1411 0 : void Logger::PatchIC(const Address pc, const Address test, int delta) {
1412 0 : if (!log_->IsEnabled() || !FLAG_trace_ic) return;
1413 0 : Log::MessageBuilder msg(log_);
1414 0 : msg.Append("PatchIC,");
1415 0 : msg.AppendAddress(pc);
1416 0 : msg.Append(",");
1417 0 : msg.AppendAddress(test);
1418 0 : msg.Append(",");
1419 0 : msg.Append("%d,", delta);
1420 0 : msg.WriteToLogFile();
1421 : }
1422 :
1423 0 : void Logger::StopProfiler() {
1424 0 : if (!log_->IsEnabled()) return;
1425 0 : if (profiler_ != NULL) {
1426 : profiler_->pause();
1427 0 : is_logging_ = false;
1428 0 : removeCodeEventListener(this);
1429 : }
1430 : }
1431 :
1432 :
1433 : // This function can be called when Log's mutex is acquired,
1434 : // either from main or Profiler's thread.
1435 0 : void Logger::LogFailure() {
1436 0 : StopProfiler();
1437 0 : }
1438 :
1439 320994 : static void AddFunctionAndCode(SharedFunctionInfo* sfi,
1440 : AbstractCode* code_object,
1441 : Handle<SharedFunctionInfo>* sfis,
1442 : Handle<AbstractCode>* code_objects, int offset) {
1443 320994 : if (sfis != NULL) {
1444 320994 : sfis[offset] = Handle<SharedFunctionInfo>(sfi);
1445 : }
1446 320994 : if (code_objects != NULL) {
1447 320994 : code_objects[offset] = Handle<AbstractCode>(code_object);
1448 : }
1449 320994 : }
1450 :
1451 684 : class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1452 : public:
1453 : EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1454 : Handle<AbstractCode>* code_objects,
1455 : int* count)
1456 684 : : sfis_(sfis), code_objects_(code_objects), count_(count) {}
1457 :
1458 844 : virtual void VisitFunction(JSFunction* function) {
1459 : SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
1460 : Object* maybe_script = sfi->script();
1461 844 : if (maybe_script->IsScript()
1462 1688 : && !Script::cast(maybe_script)->HasValidSource()) return;
1463 :
1464 : DCHECK(function->abstract_code()->kind() ==
1465 : AbstractCode::OPTIMIZED_FUNCTION);
1466 : AddFunctionAndCode(sfi, function->abstract_code(), sfis_, code_objects_,
1467 1680 : *count_);
1468 840 : *count_ = *count_ + 1;
1469 : }
1470 :
1471 : private:
1472 : Handle<SharedFunctionInfo>* sfis_;
1473 : Handle<AbstractCode>* code_objects_;
1474 : int* count_;
1475 : };
1476 :
1477 684 : static int EnumerateCompiledFunctions(Heap* heap,
1478 : Handle<SharedFunctionInfo>* sfis,
1479 : Handle<AbstractCode>* code_objects) {
1480 684 : HeapIterator iterator(heap);
1481 : DisallowHeapAllocation no_gc;
1482 684 : int compiled_funcs_count = 0;
1483 :
1484 : // Iterate the heap to find shared function info objects and record
1485 : // the unoptimized code for them.
1486 6556534 : for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1487 6555850 : if (!obj->IsSharedFunctionInfo()) continue;
1488 : SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1489 572860 : if (sfi->is_compiled()
1490 893038 : && (!sfi->script()->IsScript()
1491 4208 : || Script::cast(sfi->script())->HasValidSource())) {
1492 : // In some cases, an SFI might have (and have executing!) both bytecode
1493 : // and baseline code, so check for both and add them both if needed.
1494 320154 : if (sfi->HasBytecodeArray()) {
1495 : AddFunctionAndCode(sfi, AbstractCode::cast(sfi->bytecode_array()), sfis,
1496 4872 : code_objects, compiled_funcs_count);
1497 2436 : ++compiled_funcs_count;
1498 : }
1499 :
1500 320154 : if (!sfi->IsInterpreted()) {
1501 : AddFunctionAndCode(sfi, AbstractCode::cast(sfi->code()), sfis,
1502 635436 : code_objects, compiled_funcs_count);
1503 317718 : ++compiled_funcs_count;
1504 : }
1505 : }
1506 : }
1507 :
1508 : // Iterate all optimized functions in all contexts.
1509 : EnumerateOptimizedFunctionsVisitor visitor(sfis,
1510 : code_objects,
1511 : &compiled_funcs_count);
1512 684 : Deoptimizer::VisitAllOptimizedFunctions(heap->isolate(), &visitor);
1513 :
1514 1368 : return compiled_funcs_count;
1515 : }
1516 :
1517 :
1518 83387 : void Logger::LogCodeObject(Object* object) {
1519 : AbstractCode* code_object = AbstractCode::cast(object);
1520 : CodeEventListener::LogEventsAndTags tag = CodeEventListener::STUB_TAG;
1521 : const char* description = "Unknown code from the snapshot";
1522 83387 : switch (code_object->kind()) {
1523 : case AbstractCode::FUNCTION:
1524 : case AbstractCode::INTERPRETED_FUNCTION:
1525 : case AbstractCode::OPTIMIZED_FUNCTION:
1526 : return; // We log this later using LogCompiledFunctions.
1527 : case AbstractCode::BYTECODE_HANDLER:
1528 : return; // We log it later by walking the dispatch table.
1529 : case AbstractCode::BINARY_OP_IC: // fall through
1530 : case AbstractCode::COMPARE_IC: // fall through
1531 : case AbstractCode::TO_BOOLEAN_IC: // fall through
1532 :
1533 : case AbstractCode::STUB:
1534 : description =
1535 17157 : CodeStub::MajorName(CodeStub::GetMajorKey(code_object->GetCode()));
1536 17157 : if (description == NULL)
1537 : description = "A stub from the snapshot";
1538 : tag = CodeEventListener::STUB_TAG;
1539 : break;
1540 : case AbstractCode::REGEXP:
1541 : description = "Regular expression code";
1542 : tag = CodeEventListener::REG_EXP_TAG;
1543 0 : break;
1544 : case AbstractCode::BUILTIN:
1545 : description =
1546 37698 : isolate_->builtins()->name(code_object->GetCode()->builtin_index());
1547 : tag = CodeEventListener::BUILTIN_TAG;
1548 37698 : break;
1549 : case AbstractCode::HANDLER:
1550 : description = "An IC handler from the snapshot";
1551 : tag = CodeEventListener::HANDLER_TAG;
1552 1220 : break;
1553 : case AbstractCode::KEYED_LOAD_IC:
1554 : description = "A keyed load IC from the snapshot";
1555 : tag = CodeEventListener::KEYED_LOAD_IC_TAG;
1556 122 : break;
1557 : case AbstractCode::LOAD_IC:
1558 : description = "A load IC from the snapshot";
1559 : tag = CodeEventListener::LOAD_IC_TAG;
1560 122 : break;
1561 : case AbstractCode::LOAD_GLOBAL_IC:
1562 : description = "A load global IC from the snapshot";
1563 : tag = Logger::LOAD_GLOBAL_IC_TAG;
1564 244 : break;
1565 : case AbstractCode::STORE_IC:
1566 : description = "A store IC from the snapshot";
1567 : tag = CodeEventListener::STORE_IC_TAG;
1568 244 : break;
1569 : case AbstractCode::STORE_GLOBAL_IC:
1570 : description = "A store global IC from the snapshot";
1571 : tag = CodeEventListener::STORE_GLOBAL_IC_TAG;
1572 0 : break;
1573 : case AbstractCode::KEYED_STORE_IC:
1574 : description = "A keyed store IC from the snapshot";
1575 : tag = CodeEventListener::KEYED_STORE_IC_TAG;
1576 244 : break;
1577 : case AbstractCode::WASM_FUNCTION:
1578 : description = "A Wasm function";
1579 : tag = CodeEventListener::STUB_TAG;
1580 0 : break;
1581 : case AbstractCode::JS_TO_WASM_FUNCTION:
1582 : description = "A JavaScript to Wasm adapter";
1583 : tag = CodeEventListener::STUB_TAG;
1584 0 : break;
1585 : case AbstractCode::WASM_TO_JS_FUNCTION:
1586 : description = "A Wasm to JavaScript adapter";
1587 : tag = CodeEventListener::STUB_TAG;
1588 0 : break;
1589 : case AbstractCode::WASM_INTERPRETER_ENTRY:
1590 : description = "A Wasm to Interpreter adapter";
1591 : tag = CodeEventListener::STUB_TAG;
1592 0 : break;
1593 : case AbstractCode::NUMBER_OF_KINDS:
1594 0 : UNIMPLEMENTED();
1595 : }
1596 114102 : PROFILE(isolate_, CodeCreateEvent(tag, code_object, description));
1597 : }
1598 :
1599 :
1600 61 : void Logger::LogCodeObjects() {
1601 61 : Heap* heap = isolate_->heap();
1602 61 : HeapIterator iterator(heap);
1603 : DisallowHeapAllocation no_gc;
1604 519565 : for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1605 519504 : if (obj->IsCode()) LogCodeObject(obj);
1606 519504 : if (obj->IsBytecodeArray()) LogCodeObject(obj);
1607 61 : }
1608 61 : }
1609 :
1610 24 : void Logger::LogBytecodeHandlers() {
1611 : const interpreter::OperandScale kOperandScales[] = {
1612 : #define VALUE(Name, _) interpreter::OperandScale::k##Name,
1613 : OPERAND_SCALE_LIST(VALUE)
1614 : #undef VALUE
1615 24 : };
1616 :
1617 : const int last_index = static_cast<int>(interpreter::Bytecode::kLast);
1618 24 : interpreter::Interpreter* interpreter = isolate_->interpreter();
1619 96 : for (auto operand_scale : kOperandScales) {
1620 11952 : for (int index = 0; index <= last_index; ++index) {
1621 11880 : interpreter::Bytecode bytecode = interpreter::Bytecodes::FromByte(index);
1622 11880 : if (interpreter::Bytecodes::BytecodeHasHandler(bytecode, operand_scale)) {
1623 10488 : Code* code = interpreter->GetBytecodeHandler(bytecode, operand_scale);
1624 : std::string bytecode_name =
1625 10488 : interpreter::Bytecodes::ToString(bytecode, operand_scale);
1626 20976 : PROFILE(isolate_, CodeCreateEvent(
1627 : CodeEventListener::BYTECODE_HANDLER_TAG,
1628 : AbstractCode::cast(code), bytecode_name.c_str()));
1629 : }
1630 : }
1631 : }
1632 24 : }
1633 :
1634 160497 : void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
1635 : Handle<AbstractCode> code) {
1636 160497 : if (shared->script()->IsScript()) {
1637 : Handle<Script> script(Script::cast(shared->script()));
1638 2512 : int line_num = Script::GetLineNumber(script, shared->start_position()) + 1;
1639 : int column_num =
1640 2512 : Script::GetColumnNumber(script, shared->start_position()) + 1;
1641 2512 : if (script->name()->IsString()) {
1642 : Handle<String> script_name(String::cast(script->name()));
1643 1233 : if (line_num > 0) {
1644 2466 : PROFILE(isolate_,
1645 : CodeCreateEvent(
1646 : Logger::ToNativeByScript(
1647 : CodeEventListener::LAZY_COMPILE_TAG, *script),
1648 : *code, *shared, *script_name, line_num, column_num));
1649 : } else {
1650 : // Can't distinguish eval and script here, so always use Script.
1651 0 : PROFILE(isolate_,
1652 : CodeCreateEvent(Logger::ToNativeByScript(
1653 : CodeEventListener::SCRIPT_TAG, *script),
1654 : *code, *shared, *script_name));
1655 : }
1656 : } else {
1657 2558 : PROFILE(isolate_,
1658 : CodeCreateEvent(Logger::ToNativeByScript(
1659 : CodeEventListener::LAZY_COMPILE_TAG, *script),
1660 : *code, *shared, isolate_->heap()->empty_string(),
1661 : line_num, column_num));
1662 : }
1663 157985 : } else if (shared->IsApiFunction()) {
1664 : // API function.
1665 : FunctionTemplateInfo* fun_data = shared->get_api_func_data();
1666 : Object* raw_call_data = fun_data->call_code();
1667 14868 : if (!raw_call_data->IsUndefined(isolate_)) {
1668 : CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1669 : Object* callback_obj = call_data->callback();
1670 : Address entry_point = v8::ToCData<Address>(callback_obj);
1671 : #if USES_FUNCTION_DESCRIPTORS
1672 : entry_point = *FUNCTION_ENTRYPOINT_ADDRESS(entry_point);
1673 : #endif
1674 14680 : PROFILE(isolate_, CallbackEvent(shared->DebugName(), entry_point));
1675 : }
1676 : } else {
1677 301102 : PROFILE(isolate_,
1678 : CodeCreateEvent(CodeEventListener::LAZY_COMPILE_TAG, *code, *shared,
1679 : isolate_->heap()->empty_string()));
1680 : }
1681 160497 : }
1682 :
1683 :
1684 342 : void Logger::LogCompiledFunctions() {
1685 342 : Heap* heap = isolate_->heap();
1686 : HandleScope scope(isolate_);
1687 342 : const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL);
1688 : ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
1689 : ScopedVector<Handle<AbstractCode> > code_objects(compiled_funcs_count);
1690 342 : EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start());
1691 :
1692 : // During iteration, there can be heap allocation due to
1693 : // GetScriptLineNumber call.
1694 160839 : for (int i = 0; i < compiled_funcs_count; ++i) {
1695 320994 : if (code_objects[i].is_identical_to(isolate_->builtins()->CompileLazy()))
1696 : continue;
1697 160497 : LogExistingFunction(sfis[i], code_objects[i]);
1698 : }
1699 342 : }
1700 :
1701 :
1702 300 : void Logger::LogAccessorCallbacks() {
1703 300 : Heap* heap = isolate_->heap();
1704 300 : HeapIterator iterator(heap);
1705 : DisallowHeapAllocation no_gc;
1706 2954949 : for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1707 2954649 : if (!obj->IsAccessorInfo()) continue;
1708 : AccessorInfo* ai = AccessorInfo::cast(obj);
1709 17796 : if (!ai->name()->IsName()) continue;
1710 : Address getter_entry = v8::ToCData<Address>(ai->getter());
1711 : Name* name = Name::cast(ai->name());
1712 17796 : if (getter_entry != 0) {
1713 : #if USES_FUNCTION_DESCRIPTORS
1714 : getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(getter_entry);
1715 : #endif
1716 35592 : PROFILE(isolate_, GetterCallbackEvent(name, getter_entry));
1717 : }
1718 : Address setter_entry = v8::ToCData<Address>(ai->setter());
1719 17796 : if (setter_entry != 0) {
1720 : #if USES_FUNCTION_DESCRIPTORS
1721 : setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(setter_entry);
1722 : #endif
1723 35580 : PROFILE(isolate_, SetterCallbackEvent(name, setter_entry));
1724 : }
1725 300 : }
1726 300 : }
1727 :
1728 :
1729 60782 : static void AddIsolateIdIfNeeded(std::ostream& os, // NOLINT
1730 : Isolate* isolate) {
1731 92083 : if (FLAG_logfile_per_isolate) os << "isolate-" << isolate << "-";
1732 60782 : }
1733 :
1734 :
1735 60782 : static void PrepareLogFileName(std::ostream& os, // NOLINT
1736 : Isolate* isolate, const char* file_name) {
1737 : int dir_separator_count = 0;
1738 425354 : for (const char* p = file_name; *p; p++) {
1739 364572 : if (base::OS::isDirectorySeparator(*p)) dir_separator_count++;
1740 : }
1741 :
1742 364572 : for (const char* p = file_name; *p; p++) {
1743 364572 : if (dir_separator_count == 0) {
1744 60782 : AddIsolateIdIfNeeded(os, isolate);
1745 60782 : dir_separator_count--;
1746 : }
1747 364572 : if (*p == '%') {
1748 0 : p++;
1749 0 : switch (*p) {
1750 : case '\0':
1751 : // If there's a % at the end of the string we back up
1752 : // one character so we can escape the loop properly.
1753 : p--;
1754 : break;
1755 : case 'p':
1756 0 : os << base::OS::GetCurrentProcessId();
1757 0 : break;
1758 : case 't':
1759 : // %t expands to the current time in milliseconds.
1760 0 : os << static_cast<int64_t>(base::OS::TimeCurrentMillis());
1761 : break;
1762 : case '%':
1763 : // %% expands (contracts really) to %.
1764 : os << '%';
1765 : break;
1766 : default:
1767 : // All other %'s expand to themselves.
1768 : os << '%' << *p;
1769 : break;
1770 : }
1771 : } else {
1772 364572 : if (base::OS::isDirectorySeparator(*p)) dir_separator_count--;
1773 364572 : os << *p;
1774 : }
1775 : }
1776 60782 : }
1777 :
1778 :
1779 60782 : bool Logger::SetUp(Isolate* isolate) {
1780 : // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
1781 60782 : if (is_initialized_) return true;
1782 60782 : is_initialized_ = true;
1783 :
1784 60782 : std::ostringstream log_file_name;
1785 60782 : PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
1786 121564 : log_->Initialize(log_file_name.str().c_str());
1787 :
1788 60782 : if (FLAG_perf_basic_prof) {
1789 0 : perf_basic_logger_ = new PerfBasicLogger();
1790 : addCodeEventListener(perf_basic_logger_);
1791 : }
1792 :
1793 60782 : if (FLAG_perf_prof) {
1794 0 : perf_jit_logger_ = new PerfJitLogger();
1795 : addCodeEventListener(perf_jit_logger_);
1796 : }
1797 :
1798 60782 : if (FLAG_ll_prof) {
1799 0 : ll_logger_ = new LowLevelLogger(log_file_name.str().c_str());
1800 0 : addCodeEventListener(ll_logger_);
1801 : }
1802 :
1803 60782 : ticker_ = new Ticker(isolate, FLAG_prof_sampling_interval);
1804 :
1805 60782 : if (Log::InitLogAtStart()) {
1806 24 : is_logging_ = true;
1807 : }
1808 :
1809 60782 : if (FLAG_log_internal_timer_events || FLAG_prof_cpp) timer_.Start();
1810 :
1811 60782 : if (FLAG_prof_cpp) {
1812 0 : profiler_ = new Profiler(isolate);
1813 0 : is_logging_ = true;
1814 0 : profiler_->Engage();
1815 : }
1816 :
1817 : profiler_listener_.reset();
1818 :
1819 60782 : if (is_logging_) {
1820 24 : addCodeEventListener(this);
1821 : }
1822 :
1823 60782 : return true;
1824 : }
1825 :
1826 :
1827 72 : void Logger::SetCodeEventHandler(uint32_t options,
1828 : JitCodeEventHandler event_handler) {
1829 72 : if (jit_logger_) {
1830 : removeCodeEventListener(jit_logger_);
1831 33 : delete jit_logger_;
1832 33 : jit_logger_ = NULL;
1833 : }
1834 :
1835 72 : if (event_handler) {
1836 39 : jit_logger_ = new JitLogger(event_handler);
1837 : addCodeEventListener(jit_logger_);
1838 39 : if (options & kJitCodeEventEnumExisting) {
1839 6 : HandleScope scope(isolate_);
1840 6 : LogCodeObjects();
1841 6 : LogCompiledFunctions();
1842 : }
1843 : }
1844 72 : }
1845 :
1846 294 : void Logger::SetUpProfilerListener() {
1847 588 : if (!is_initialized_) return;
1848 294 : if (profiler_listener_.get() == nullptr) {
1849 258 : profiler_listener_.reset(new ProfilerListener(isolate_));
1850 : }
1851 : addCodeEventListener(profiler_listener_.get());
1852 : }
1853 :
1854 294 : void Logger::TearDownProfilerListener() {
1855 588 : if (profiler_listener_->HasObservers()) return;
1856 : removeCodeEventListener(profiler_listener_.get());
1857 : }
1858 :
1859 59283 : sampler::Sampler* Logger::sampler() {
1860 59283 : return ticker_;
1861 : }
1862 :
1863 :
1864 59327 : FILE* Logger::TearDown() {
1865 59327 : if (!is_initialized_) return NULL;
1866 59285 : is_initialized_ = false;
1867 :
1868 : // Stop the profiler before closing the file.
1869 59285 : if (profiler_ != NULL) {
1870 0 : profiler_->Disengage();
1871 0 : delete profiler_;
1872 0 : profiler_ = NULL;
1873 : }
1874 :
1875 59285 : delete ticker_;
1876 59285 : ticker_ = NULL;
1877 :
1878 59285 : if (perf_basic_logger_) {
1879 : removeCodeEventListener(perf_basic_logger_);
1880 0 : delete perf_basic_logger_;
1881 0 : perf_basic_logger_ = NULL;
1882 : }
1883 :
1884 59285 : if (perf_jit_logger_) {
1885 : removeCodeEventListener(perf_jit_logger_);
1886 0 : delete perf_jit_logger_;
1887 0 : perf_jit_logger_ = NULL;
1888 : }
1889 :
1890 59285 : if (ll_logger_) {
1891 : removeCodeEventListener(ll_logger_);
1892 0 : delete ll_logger_;
1893 0 : ll_logger_ = NULL;
1894 : }
1895 :
1896 59285 : if (jit_logger_) {
1897 : removeCodeEventListener(jit_logger_);
1898 6 : delete jit_logger_;
1899 6 : jit_logger_ = NULL;
1900 : }
1901 :
1902 59285 : if (profiler_listener_.get() != nullptr) {
1903 : removeCodeEventListener(profiler_listener_.get());
1904 : }
1905 :
1906 59285 : return log_->Close();
1907 : }
1908 :
1909 : } // namespace internal
1910 : } // namespace v8
|
