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