blob: 04fd22ef5c1bbd156dede764ade0ba6fcdc7fe5d [file] [log] [blame]
Ben Murdoch257744e2011-11-30 15:57:28 +00001// Copyright 2011 the V8 project authors. All rights reserved.
Steve Blocka7e24c12009-10-30 11:49:00 +00002// Redistribution and use in source and binary forms, with or without
3// modification, are permitted provided that the following conditions are
4// met:
5//
6// * Redistributions of source code must retain the above copyright
7// notice, this list of conditions and the following disclaimer.
8// * Redistributions in binary form must reproduce the above
9// copyright notice, this list of conditions and the following
10// disclaimer in the documentation and/or other materials provided
11// with the distribution.
12// * Neither the name of Google Inc. nor the names of its
13// contributors may be used to endorse or promote products derived
14// from this software without specific prior written permission.
15//
16// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
17// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
18// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
19// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
20// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
21// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
22// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
23// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
24// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
25// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
26// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
27
28#include <stdarg.h>
29
30#include "v8.h"
31
32#include "bootstrapper.h"
Kristian Monsen80d68ea2010-09-08 11:05:35 +010033#include "code-stubs.h"
Ben Murdochb0fe1622011-05-05 13:52:32 +010034#include "deoptimizer.h"
Steve Blockd0582a62009-12-15 09:54:21 +000035#include "global-handles.h"
Steve Blocka7e24c12009-10-30 11:49:00 +000036#include "log.h"
37#include "macro-assembler.h"
Ben Murdochb0fe1622011-05-05 13:52:32 +010038#include "runtime-profiler.h"
Steve Blocka7e24c12009-10-30 11:49:00 +000039#include "serialize.h"
40#include "string-stream.h"
Ben Murdochb0fe1622011-05-05 13:52:32 +010041#include "vm-state-inl.h"
Steve Blocka7e24c12009-10-30 11:49:00 +000042
43namespace v8 {
44namespace internal {
45
Steve Blocka7e24c12009-10-30 11:49:00 +000046//
47// Sliding state window. Updates counters to keep track of the last
48// window of kBufferSize states. This is useful to track where we
49// spent our time.
50//
51class SlidingStateWindow {
52 public:
Steve Block44f0eee2011-05-26 01:26:41 +010053 explicit SlidingStateWindow(Isolate* isolate);
Steve Blocka7e24c12009-10-30 11:49:00 +000054 ~SlidingStateWindow();
55 void AddState(StateTag state);
56
57 private:
58 static const int kBufferSize = 256;
Steve Block44f0eee2011-05-26 01:26:41 +010059 Counters* counters_;
Steve Blocka7e24c12009-10-30 11:49:00 +000060 int current_index_;
61 bool is_full_;
62 byte buffer_[kBufferSize];
63
64
65 void IncrementStateCounter(StateTag state) {
Steve Block44f0eee2011-05-26 01:26:41 +010066 counters_->state_counters(state)->Increment();
Steve Blocka7e24c12009-10-30 11:49:00 +000067 }
68
69
70 void DecrementStateCounter(StateTag state) {
Steve Block44f0eee2011-05-26 01:26:41 +010071 counters_->state_counters(state)->Decrement();
Steve Blocka7e24c12009-10-30 11:49:00 +000072 }
73};
74
75
76//
77// The Profiler samples pc and sp values for the main thread.
78// Each sample is appended to a circular buffer.
79// An independent thread removes data and writes it to the log.
80// This design minimizes the time spent in the sampler.
81//
82class Profiler: public Thread {
83 public:
Steve Block44f0eee2011-05-26 01:26:41 +010084 explicit Profiler(Isolate* isolate);
Steve Blocka7e24c12009-10-30 11:49:00 +000085 void Engage();
86 void Disengage();
87
88 // Inserts collected profiling data into buffer.
89 void Insert(TickSample* sample) {
90 if (paused_)
91 return;
92
93 if (Succ(head_) == tail_) {
94 overflow_ = true;
95 } else {
96 buffer_[head_] = *sample;
97 head_ = Succ(head_);
98 buffer_semaphore_->Signal(); // Tell we have an element.
99 }
100 }
101
102 // Waits for a signal and removes profiling data.
103 bool Remove(TickSample* sample) {
104 buffer_semaphore_->Wait(); // Wait for an element.
105 *sample = buffer_[tail_];
106 bool result = overflow_;
107 tail_ = Succ(tail_);
108 overflow_ = false;
109 return result;
110 }
111
112 void Run();
113
114 // Pause and Resume TickSample data collection.
Steve Block44f0eee2011-05-26 01:26:41 +0100115 bool paused() const { return paused_; }
116 void pause() { paused_ = true; }
117 void resume() { paused_ = false; }
Steve Blocka7e24c12009-10-30 11:49:00 +0000118
119 private:
120 // Returns the next index in the cyclic buffer.
121 int Succ(int index) { return (index + 1) % kBufferSize; }
122
Ben Murdoch3fb3ca82011-12-02 17:19:32 +0000123 Isolate* isolate_;
Steve Blocka7e24c12009-10-30 11:49:00 +0000124 // Cyclic buffer for communicating profiling samples
125 // between the signal handler and the worker thread.
126 static const int kBufferSize = 128;
127 TickSample buffer_[kBufferSize]; // Buffer storage.
128 int head_; // Index to the buffer head.
129 int tail_; // Index to the buffer tail.
130 bool overflow_; // Tell whether a buffer overflow has occurred.
131 Semaphore* buffer_semaphore_; // Sempahore used for buffer synchronization.
132
Steve Blockd0582a62009-12-15 09:54:21 +0000133 // Tells whether profiler is engaged, that is, processing thread is stated.
134 bool engaged_;
135
Steve Blocka7e24c12009-10-30 11:49:00 +0000136 // Tells whether worker thread should continue running.
137 bool running_;
138
139 // Tells whether we are currently recording tick samples.
Steve Block44f0eee2011-05-26 01:26:41 +0100140 bool paused_;
Steve Blocka7e24c12009-10-30 11:49:00 +0000141};
142
Steve Blocka7e24c12009-10-30 11:49:00 +0000143
144//
145// StackTracer implementation
146//
Steve Block44f0eee2011-05-26 01:26:41 +0100147void StackTracer::Trace(Isolate* isolate, TickSample* sample) {
148 ASSERT(isolate->IsInitialized());
149
Ben Murdochb0fe1622011-05-05 13:52:32 +0100150 // Avoid collecting traces while doing GC.
Steve Block6ded16b2010-05-10 14:33:55 +0100151 if (sample->state == GC) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000152
Steve Block44f0eee2011-05-26 01:26:41 +0100153 const Address js_entry_sp =
154 Isolate::js_entry_sp(isolate->thread_local_top());
Steve Blocka7e24c12009-10-30 11:49:00 +0000155 if (js_entry_sp == 0) {
156 // Not executing JS now.
Steve Blocka7e24c12009-10-30 11:49:00 +0000157 return;
158 }
159
Steve Block44f0eee2011-05-26 01:26:41 +0100160 const Address callback = isolate->external_callback();
161 if (callback != NULL) {
162 sample->external_callback = callback;
163 sample->has_external_callback = true;
164 } else {
165 // Sample potential return address value for frameless invocation of
166 // stubs (we'll figure out later, if this value makes sense).
167 sample->tos = Memory::Address_at(sample->sp);
168 sample->has_external_callback = false;
Steve Blockd0582a62009-12-15 09:54:21 +0000169 }
170
Steve Block44f0eee2011-05-26 01:26:41 +0100171 SafeStackTraceFrameIterator it(isolate,
172 sample->fp, sample->sp,
Leon Clarked91b9f72010-01-27 17:25:45 +0000173 sample->sp, js_entry_sp);
Steve Block44f0eee2011-05-26 01:26:41 +0100174 int i = 0;
Steve Blocka7e24c12009-10-30 11:49:00 +0000175 while (!it.done() && i < TickSample::kMaxFramesCount) {
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100176 sample->stack[i++] = it.frame()->pc();
Steve Blocka7e24c12009-10-30 11:49:00 +0000177 it.Advance();
178 }
179 sample->frames_count = i;
180}
181
182
183//
184// Ticker used to provide ticks to the profiler and the sliding state
185// window.
186//
187class Ticker: public Sampler {
188 public:
Ben Murdoch8b112d22011-06-08 16:22:53 +0100189 Ticker(Isolate* isolate, int interval):
Steve Block44f0eee2011-05-26 01:26:41 +0100190 Sampler(isolate, interval),
Ben Murdochb0fe1622011-05-05 13:52:32 +0100191 window_(NULL),
192 profiler_(NULL) {}
Steve Blocka7e24c12009-10-30 11:49:00 +0000193
194 ~Ticker() { if (IsActive()) Stop(); }
195
Ben Murdochf87a2032010-10-22 12:50:53 +0100196 virtual void Tick(TickSample* sample) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000197 if (profiler_) profiler_->Insert(sample);
198 if (window_) window_->AddState(sample->state);
199 }
200
201 void SetWindow(SlidingStateWindow* window) {
202 window_ = window;
203 if (!IsActive()) Start();
204 }
205
206 void ClearWindow() {
207 window_ = NULL;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100208 if (!profiler_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
Steve Blocka7e24c12009-10-30 11:49:00 +0000209 }
210
211 void SetProfiler(Profiler* profiler) {
Ben Murdochb0fe1622011-05-05 13:52:32 +0100212 ASSERT(profiler_ == NULL);
Steve Blocka7e24c12009-10-30 11:49:00 +0000213 profiler_ = profiler;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100214 IncreaseProfilingDepth();
Steve Blocka7e24c12009-10-30 11:49:00 +0000215 if (!FLAG_prof_lazy && !IsActive()) Start();
216 }
217
218 void ClearProfiler() {
Ben Murdochb0fe1622011-05-05 13:52:32 +0100219 DecreaseProfilingDepth();
Steve Blocka7e24c12009-10-30 11:49:00 +0000220 profiler_ = NULL;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100221 if (!window_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
Steve Blocka7e24c12009-10-30 11:49:00 +0000222 }
223
Shimeng (Simon) Wang8a31eba2010-12-06 19:01:33 -0800224 protected:
225 virtual void DoSampleStack(TickSample* sample) {
Steve Block44f0eee2011-05-26 01:26:41 +0100226 StackTracer::Trace(isolate(), sample);
Shimeng (Simon) Wang8a31eba2010-12-06 19:01:33 -0800227 }
228
Steve Blocka7e24c12009-10-30 11:49:00 +0000229 private:
230 SlidingStateWindow* window_;
231 Profiler* profiler_;
232};
233
234
235//
236// SlidingStateWindow implementation.
237//
Steve Block44f0eee2011-05-26 01:26:41 +0100238SlidingStateWindow::SlidingStateWindow(Isolate* isolate)
239 : counters_(isolate->counters()), current_index_(0), is_full_(false) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000240 for (int i = 0; i < kBufferSize; i++) {
241 buffer_[i] = static_cast<byte>(OTHER);
242 }
Steve Block44f0eee2011-05-26 01:26:41 +0100243 isolate->logger()->ticker_->SetWindow(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000244}
245
246
247SlidingStateWindow::~SlidingStateWindow() {
Steve Block44f0eee2011-05-26 01:26:41 +0100248 LOGGER->ticker_->ClearWindow();
Steve Blocka7e24c12009-10-30 11:49:00 +0000249}
250
251
252void SlidingStateWindow::AddState(StateTag state) {
253 if (is_full_) {
254 DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
255 } else if (current_index_ == kBufferSize - 1) {
256 is_full_ = true;
257 }
258 buffer_[current_index_] = static_cast<byte>(state);
259 IncrementStateCounter(state);
260 ASSERT(IsPowerOf2(kBufferSize));
261 current_index_ = (current_index_ + 1) & (kBufferSize - 1);
262}
263
264
265//
266// Profiler implementation.
267//
Steve Block44f0eee2011-05-26 01:26:41 +0100268Profiler::Profiler(Isolate* isolate)
Ben Murdoch3fb3ca82011-12-02 17:19:32 +0000269 : Thread("v8:Profiler"),
270 isolate_(isolate),
Steve Block9fac8402011-05-12 15:51:54 +0100271 head_(0),
Steve Blockd0582a62009-12-15 09:54:21 +0000272 tail_(0),
273 overflow_(false),
274 buffer_semaphore_(OS::CreateSemaphore(0)),
275 engaged_(false),
Steve Block44f0eee2011-05-26 01:26:41 +0100276 running_(false),
277 paused_(false) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000278}
279
280
281void Profiler::Engage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000282 if (engaged_) return;
283 engaged_ = true;
284
285 // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
286 // http://code.google.com/p/v8/issues/detail?id=487
287 if (!FLAG_prof_lazy) {
288 OS::LogSharedLibraryAddresses();
289 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000290
291 // Start thread processing the profiler buffer.
292 running_ = true;
293 Start();
294
295 // Register to get ticks.
Steve Block44f0eee2011-05-26 01:26:41 +0100296 LOGGER->ticker_->SetProfiler(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000297
Steve Block44f0eee2011-05-26 01:26:41 +0100298 LOGGER->ProfilerBeginEvent();
Steve Blocka7e24c12009-10-30 11:49:00 +0000299}
300
301
302void Profiler::Disengage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000303 if (!engaged_) return;
304
Steve Blocka7e24c12009-10-30 11:49:00 +0000305 // Stop receiving ticks.
Steve Block44f0eee2011-05-26 01:26:41 +0100306 LOGGER->ticker_->ClearProfiler();
Steve Blocka7e24c12009-10-30 11:49:00 +0000307
308 // Terminate the worker thread by setting running_ to false,
309 // inserting a fake element in the queue and then wait for
310 // the thread to terminate.
311 running_ = false;
312 TickSample sample;
313 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
314 resume();
315 Insert(&sample);
316 Join();
317
Steve Block44f0eee2011-05-26 01:26:41 +0100318 LOG(ISOLATE, UncheckedStringEvent("profiler", "end"));
Steve Blocka7e24c12009-10-30 11:49:00 +0000319}
320
321
322void Profiler::Run() {
323 TickSample sample;
Steve Block8defd9f2010-07-08 12:39:36 +0100324 bool overflow = Remove(&sample);
Steve Blocka7e24c12009-10-30 11:49:00 +0000325 while (running_) {
Ben Murdoch3fb3ca82011-12-02 17:19:32 +0000326 LOG(isolate_, TickEvent(&sample, overflow));
Steve Block8defd9f2010-07-08 12:39:36 +0100327 overflow = Remove(&sample);
Steve Blocka7e24c12009-10-30 11:49:00 +0000328 }
329}
330
331
Ben Murdoch257744e2011-11-30 15:57:28 +0000332// Low-level profiling event structures.
333
334struct LowLevelCodeCreateStruct {
335 static const char kTag = 'C';
336
337 int32_t name_size;
338 Address code_address;
339 int32_t code_size;
340};
341
342
343struct LowLevelCodeMoveStruct {
344 static const char kTag = 'M';
345
346 Address from_address;
347 Address to_address;
348};
349
350
351struct LowLevelCodeDeleteStruct {
352 static const char kTag = 'D';
353
354 Address address;
355};
356
357
358struct LowLevelSnapshotPositionStruct {
359 static const char kTag = 'P';
360
361 Address address;
362 int32_t position;
363};
364
365
366static const char kCodeMovingGCTag = 'G';
367
368
Steve Blocka7e24c12009-10-30 11:49:00 +0000369//
370// Logger class implementation.
371//
Steve Block44f0eee2011-05-26 01:26:41 +0100372
Ben Murdoch257744e2011-11-30 15:57:28 +0000373class Logger::NameMap {
374 public:
375 NameMap() : impl_(&PointerEquals) {}
376
377 ~NameMap() {
378 for (HashMap::Entry* p = impl_.Start(); p != NULL; p = impl_.Next(p)) {
379 DeleteArray(static_cast<const char*>(p->value));
380 }
381 }
382
383 void Insert(Address code_address, const char* name, int name_size) {
384 HashMap::Entry* entry = FindOrCreateEntry(code_address);
385 if (entry->value == NULL) {
386 entry->value = CopyName(name, name_size);
387 }
388 }
389
390 const char* Lookup(Address code_address) {
391 HashMap::Entry* entry = FindEntry(code_address);
392 return (entry != NULL) ? static_cast<const char*>(entry->value) : NULL;
393 }
394
395 void Remove(Address code_address) {
396 HashMap::Entry* entry = FindEntry(code_address);
Ben Murdoch3fb3ca82011-12-02 17:19:32 +0000397 if (entry != NULL) {
398 DeleteArray(static_cast<char*>(entry->value));
399 RemoveEntry(entry);
400 }
Ben Murdoch257744e2011-11-30 15:57:28 +0000401 }
402
403 void Move(Address from, Address to) {
404 if (from == to) return;
405 HashMap::Entry* from_entry = FindEntry(from);
406 ASSERT(from_entry != NULL);
407 void* value = from_entry->value;
408 RemoveEntry(from_entry);
409 HashMap::Entry* to_entry = FindOrCreateEntry(to);
410 ASSERT(to_entry->value == NULL);
411 to_entry->value = value;
412 }
413
414 private:
415 static bool PointerEquals(void* lhs, void* rhs) {
416 return lhs == rhs;
417 }
418
419 static char* CopyName(const char* name, int name_size) {
420 char* result = NewArray<char>(name_size + 1);
421 for (int i = 0; i < name_size; ++i) {
422 char c = name[i];
423 if (c == '\0') c = ' ';
424 result[i] = c;
425 }
426 result[name_size] = '\0';
427 return result;
428 }
429
430 HashMap::Entry* FindOrCreateEntry(Address code_address) {
431 return impl_.Lookup(code_address, ComputePointerHash(code_address), true);
432 }
433
434 HashMap::Entry* FindEntry(Address code_address) {
435 return impl_.Lookup(code_address, ComputePointerHash(code_address), false);
436 }
437
438 void RemoveEntry(HashMap::Entry* entry) {
439 impl_.Remove(entry->key, entry->hash);
440 }
441
442 HashMap impl_;
443
444 DISALLOW_COPY_AND_ASSIGN(NameMap);
445};
446
447
448class Logger::NameBuffer {
449 public:
450 NameBuffer() { Reset(); }
451
452 void Reset() {
453 utf8_pos_ = 0;
454 }
455
456 void AppendString(String* str) {
457 if (str == NULL) return;
458 if (str->HasOnlyAsciiChars()) {
459 int utf8_length = Min(str->length(), kUtf8BufferSize - utf8_pos_);
460 String::WriteToFlat(str, utf8_buffer_ + utf8_pos_, 0, utf8_length);
461 utf8_pos_ += utf8_length;
462 return;
463 }
464 int uc16_length = Min(str->length(), kUc16BufferSize);
465 String::WriteToFlat(str, uc16_buffer_, 0, uc16_length);
466 for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
467 uc16 c = uc16_buffer_[i];
468 if (c <= String::kMaxAsciiCharCodeU) {
469 utf8_buffer_[utf8_pos_++] = static_cast<char>(c);
470 } else {
471 int char_length = unibrow::Utf8::Length(c);
472 if (utf8_pos_ + char_length > kUtf8BufferSize) break;
473 unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c);
474 utf8_pos_ += char_length;
475 }
476 }
477 }
478
479 void AppendBytes(const char* bytes, int size) {
480 size = Min(size, kUtf8BufferSize - utf8_pos_);
481 memcpy(utf8_buffer_ + utf8_pos_, bytes, size);
482 utf8_pos_ += size;
483 }
484
485 void AppendBytes(const char* bytes) {
486 AppendBytes(bytes, StrLength(bytes));
487 }
488
489 void AppendByte(char c) {
490 if (utf8_pos_ >= kUtf8BufferSize) return;
491 utf8_buffer_[utf8_pos_++] = c;
492 }
493
494 void AppendInt(int n) {
495 Vector<char> buffer(utf8_buffer_ + utf8_pos_, kUtf8BufferSize - utf8_pos_);
496 int size = OS::SNPrintF(buffer, "%d", n);
497 if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) {
498 utf8_pos_ += size;
499 }
500 }
501
502 const char* get() { return utf8_buffer_; }
503 int size() const { return utf8_pos_; }
504
505 private:
506 static const int kUtf8BufferSize = 512;
507 static const int kUc16BufferSize = 128;
508
509 int utf8_pos_;
510 char utf8_buffer_[kUtf8BufferSize];
511 uc16 uc16_buffer_[kUc16BufferSize];
512};
513
514
Steve Block44f0eee2011-05-26 01:26:41 +0100515Logger::Logger()
516 : ticker_(NULL),
517 profiler_(NULL),
518 sliding_state_window_(NULL),
519 log_events_(NULL),
520 logging_nesting_(0),
521 cpu_profiler_nesting_(0),
Steve Block44f0eee2011-05-26 01:26:41 +0100522 log_(new Log(this)),
Ben Murdoch257744e2011-11-30 15:57:28 +0000523 name_buffer_(new NameBuffer),
524 address_to_name_map_(NULL),
Steve Block44f0eee2011-05-26 01:26:41 +0100525 is_initialized_(false),
526 last_address_(NULL),
527 prev_sp_(NULL),
528 prev_function_(NULL),
529 prev_to_(NULL),
530 prev_code_(NULL) {
531}
532
Ben Murdoch257744e2011-11-30 15:57:28 +0000533
Steve Block44f0eee2011-05-26 01:26:41 +0100534Logger::~Logger() {
Ben Murdoch257744e2011-11-30 15:57:28 +0000535 delete address_to_name_map_;
536 delete name_buffer_;
Steve Block44f0eee2011-05-26 01:26:41 +0100537 delete log_;
538}
Steve Blocka7e24c12009-10-30 11:49:00 +0000539
Ben Murdoch257744e2011-11-30 15:57:28 +0000540
Ben Murdochb0fe1622011-05-05 13:52:32 +0100541#define DECLARE_EVENT(ignore1, name) name,
Steve Block44f0eee2011-05-26 01:26:41 +0100542static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
Ben Murdochb0fe1622011-05-05 13:52:32 +0100543 LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
Steve Blocka7e24c12009-10-30 11:49:00 +0000544};
Ben Murdochb0fe1622011-05-05 13:52:32 +0100545#undef DECLARE_EVENT
Steve Blocka7e24c12009-10-30 11:49:00 +0000546
547
548void Logger::ProfilerBeginEvent() {
Steve Block44f0eee2011-05-26 01:26:41 +0100549 if (!log_->IsEnabled()) return;
550 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000551 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
Steve Blocka7e24c12009-10-30 11:49:00 +0000552 msg.WriteToLogFile();
553}
554
Steve Blocka7e24c12009-10-30 11:49:00 +0000555
Steve Blocka7e24c12009-10-30 11:49:00 +0000556void Logger::StringEvent(const char* name, const char* value) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000557 if (FLAG_log) UncheckedStringEvent(name, value);
Steve Blocka7e24c12009-10-30 11:49:00 +0000558}
559
560
Steve Blocka7e24c12009-10-30 11:49:00 +0000561void Logger::UncheckedStringEvent(const char* name, const char* value) {
Steve Block44f0eee2011-05-26 01:26:41 +0100562 if (!log_->IsEnabled()) return;
563 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000564 msg.Append("%s,\"%s\"\n", name, value);
565 msg.WriteToLogFile();
566}
Steve Blocka7e24c12009-10-30 11:49:00 +0000567
568
569void Logger::IntEvent(const char* name, int value) {
Steve Block6ded16b2010-05-10 14:33:55 +0100570 if (FLAG_log) UncheckedIntEvent(name, value);
Steve Block6ded16b2010-05-10 14:33:55 +0100571}
572
573
Ben Murdochf87a2032010-10-22 12:50:53 +0100574void Logger::IntPtrTEvent(const char* name, intptr_t value) {
Ben Murdochf87a2032010-10-22 12:50:53 +0100575 if (FLAG_log) UncheckedIntPtrTEvent(name, value);
Ben Murdochf87a2032010-10-22 12:50:53 +0100576}
577
578
Steve Block6ded16b2010-05-10 14:33:55 +0100579void Logger::UncheckedIntEvent(const char* name, int value) {
Steve Block44f0eee2011-05-26 01:26:41 +0100580 if (!log_->IsEnabled()) return;
581 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000582 msg.Append("%s,%d\n", name, value);
583 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000584}
585
586
Ben Murdochf87a2032010-10-22 12:50:53 +0100587void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
Steve Block44f0eee2011-05-26 01:26:41 +0100588 if (!log_->IsEnabled()) return;
589 LogMessageBuilder msg(this);
Ben Murdochf87a2032010-10-22 12:50:53 +0100590 msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
591 msg.WriteToLogFile();
592}
Ben Murdochf87a2032010-10-22 12:50:53 +0100593
594
Steve Blocka7e24c12009-10-30 11:49:00 +0000595void Logger::HandleEvent(const char* name, Object** location) {
Steve Block44f0eee2011-05-26 01:26:41 +0100596 if (!log_->IsEnabled() || !FLAG_log_handles) return;
597 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000598 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
599 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000600}
601
602
Steve Blocka7e24c12009-10-30 11:49:00 +0000603// ApiEvent is private so all the calls come from the Logger class. It is the
604// caller's responsibility to ensure that log is enabled and that
605// FLAG_log_api is true.
606void Logger::ApiEvent(const char* format, ...) {
Steve Block44f0eee2011-05-26 01:26:41 +0100607 ASSERT(log_->IsEnabled() && FLAG_log_api);
608 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000609 va_list ap;
610 va_start(ap, format);
611 msg.AppendVA(format, ap);
612 va_end(ap);
613 msg.WriteToLogFile();
614}
Steve Blocka7e24c12009-10-30 11:49:00 +0000615
616
617void Logger::ApiNamedSecurityCheck(Object* key) {
Steve Block44f0eee2011-05-26 01:26:41 +0100618 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000619 if (key->IsString()) {
620 SmartPointer<char> str =
621 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
622 ApiEvent("api,check-security,\"%s\"\n", *str);
623 } else if (key->IsUndefined()) {
624 ApiEvent("api,check-security,undefined\n");
625 } else {
626 ApiEvent("api,check-security,['no-name']\n");
627 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000628}
629
630
631void Logger::SharedLibraryEvent(const char* library_path,
632 uintptr_t start,
633 uintptr_t end) {
Steve Block44f0eee2011-05-26 01:26:41 +0100634 if (!log_->IsEnabled() || !FLAG_prof) return;
635 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000636 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
637 library_path,
638 start,
639 end);
640 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000641}
642
643
644void Logger::SharedLibraryEvent(const wchar_t* library_path,
645 uintptr_t start,
646 uintptr_t end) {
Steve Block44f0eee2011-05-26 01:26:41 +0100647 if (!log_->IsEnabled() || !FLAG_prof) return;
648 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000649 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
650 library_path,
651 start,
652 end);
653 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000654}
655
656
Steve Blocka7e24c12009-10-30 11:49:00 +0000657void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
658 // Prints "/" + re.source + "/" +
659 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
Steve Block44f0eee2011-05-26 01:26:41 +0100660 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000661
662 Handle<Object> source = GetProperty(regexp, "source");
663 if (!source->IsString()) {
664 msg.Append("no source");
665 return;
666 }
667
668 switch (regexp->TypeTag()) {
669 case JSRegExp::ATOM:
670 msg.Append('a');
671 break;
672 default:
673 break;
674 }
675 msg.Append('/');
676 msg.AppendDetailed(*Handle<String>::cast(source), false);
677 msg.Append('/');
678
679 // global flag
680 Handle<Object> global = GetProperty(regexp, "global");
681 if (global->IsTrue()) {
682 msg.Append('g');
683 }
684 // ignorecase flag
685 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
686 if (ignorecase->IsTrue()) {
687 msg.Append('i');
688 }
689 // multiline flag
690 Handle<Object> multiline = GetProperty(regexp, "multiline");
691 if (multiline->IsTrue()) {
692 msg.Append('m');
693 }
694
695 msg.WriteToLogFile();
696}
Steve Blocka7e24c12009-10-30 11:49:00 +0000697
698
699void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
Steve Block44f0eee2011-05-26 01:26:41 +0100700 if (!log_->IsEnabled() || !FLAG_log_regexp) return;
701 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000702 msg.Append("regexp-compile,");
703 LogRegExpSource(regexp);
704 msg.Append(in_cache ? ",hit\n" : ",miss\n");
705 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000706}
707
708
709void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
Steve Block44f0eee2011-05-26 01:26:41 +0100710 if (!log_->IsEnabled() || !FLAG_log_runtime) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000711 HandleScope scope;
Steve Block44f0eee2011-05-26 01:26:41 +0100712 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000713 for (int i = 0; i < format.length(); i++) {
714 char c = format[i];
715 if (c == '%' && i <= format.length() - 2) {
716 i++;
717 ASSERT('0' <= format[i] && format[i] <= '9');
John Reck59135872010-11-02 12:39:01 -0700718 MaybeObject* maybe = args->GetElement(format[i] - '0');
719 Object* obj;
720 if (!maybe->ToObject(&obj)) {
721 msg.Append("<exception>");
722 continue;
723 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000724 i++;
725 switch (format[i]) {
726 case 's':
727 msg.AppendDetailed(String::cast(obj), false);
728 break;
729 case 'S':
730 msg.AppendDetailed(String::cast(obj), true);
731 break;
732 case 'r':
733 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
734 break;
735 case 'x':
736 msg.Append("0x%x", Smi::cast(obj)->value());
737 break;
738 case 'i':
739 msg.Append("%i", Smi::cast(obj)->value());
740 break;
741 default:
742 UNREACHABLE();
743 }
744 } else {
745 msg.Append(c);
746 }
747 }
748 msg.Append('\n');
749 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000750}
751
752
753void Logger::ApiIndexedSecurityCheck(uint32_t index) {
Steve Block44f0eee2011-05-26 01:26:41 +0100754 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000755 ApiEvent("api,check-security,%u\n", index);
Steve Blocka7e24c12009-10-30 11:49:00 +0000756}
757
758
759void Logger::ApiNamedPropertyAccess(const char* tag,
760 JSObject* holder,
761 Object* name) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000762 ASSERT(name->IsString());
Steve Block44f0eee2011-05-26 01:26:41 +0100763 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000764 String* class_name_obj = holder->class_name();
765 SmartPointer<char> class_name =
766 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
767 SmartPointer<char> property_name =
768 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Steve Block44f0eee2011-05-26 01:26:41 +0100769 ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
Steve Blocka7e24c12009-10-30 11:49:00 +0000770}
771
772void Logger::ApiIndexedPropertyAccess(const char* tag,
773 JSObject* holder,
774 uint32_t index) {
Steve Block44f0eee2011-05-26 01:26:41 +0100775 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000776 String* class_name_obj = holder->class_name();
777 SmartPointer<char> class_name =
778 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Steve Block44f0eee2011-05-26 01:26:41 +0100779 ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
Steve Blocka7e24c12009-10-30 11:49:00 +0000780}
781
782void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
Steve Block44f0eee2011-05-26 01:26:41 +0100783 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000784 String* class_name_obj = object->class_name();
785 SmartPointer<char> class_name =
786 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Steve Block44f0eee2011-05-26 01:26:41 +0100787 ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
Steve Blocka7e24c12009-10-30 11:49:00 +0000788}
789
790
791void Logger::ApiEntryCall(const char* name) {
Steve Block44f0eee2011-05-26 01:26:41 +0100792 if (!log_->IsEnabled() || !FLAG_log_api) return;
793 ApiEvent("api,%s\n", name);
Steve Blocka7e24c12009-10-30 11:49:00 +0000794}
795
796
797void Logger::NewEvent(const char* name, void* object, size_t size) {
Steve Block44f0eee2011-05-26 01:26:41 +0100798 if (!log_->IsEnabled() || !FLAG_log) return;
799 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000800 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
801 static_cast<unsigned int>(size));
802 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000803}
804
805
806void Logger::DeleteEvent(const char* name, void* object) {
Steve Block44f0eee2011-05-26 01:26:41 +0100807 if (!log_->IsEnabled() || !FLAG_log) return;
808 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000809 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
810 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000811}
812
813
Steve Block44f0eee2011-05-26 01:26:41 +0100814void Logger::NewEventStatic(const char* name, void* object, size_t size) {
815 LOGGER->NewEvent(name, object, size);
816}
817
818
819void Logger::DeleteEventStatic(const char* name, void* object) {
820 LOGGER->DeleteEvent(name, object);
821}
822
Steve Blockd0582a62009-12-15 09:54:21 +0000823void Logger::CallbackEventInternal(const char* prefix, const char* name,
824 Address entry_point) {
Steve Block44f0eee2011-05-26 01:26:41 +0100825 if (!log_->IsEnabled() || !FLAG_log_code) return;
826 LogMessageBuilder msg(this);
Steve Blockd0582a62009-12-15 09:54:21 +0000827 msg.Append("%s,%s,",
Ben Murdochb0fe1622011-05-05 13:52:32 +0100828 kLogEventsNames[CODE_CREATION_EVENT],
829 kLogEventsNames[CALLBACK_TAG]);
Steve Blockd0582a62009-12-15 09:54:21 +0000830 msg.AppendAddress(entry_point);
831 msg.Append(",1,\"%s%s\"", prefix, name);
Steve Blockd0582a62009-12-15 09:54:21 +0000832 msg.Append('\n');
833 msg.WriteToLogFile();
834}
Steve Blockd0582a62009-12-15 09:54:21 +0000835
836
837void Logger::CallbackEvent(String* name, Address entry_point) {
Steve Block44f0eee2011-05-26 01:26:41 +0100838 if (!log_->IsEnabled() || !FLAG_log_code) return;
Steve Blockd0582a62009-12-15 09:54:21 +0000839 SmartPointer<char> str =
840 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
841 CallbackEventInternal("", *str, entry_point);
Steve Blockd0582a62009-12-15 09:54:21 +0000842}
843
844
845void Logger::GetterCallbackEvent(String* name, Address entry_point) {
Steve Block44f0eee2011-05-26 01:26:41 +0100846 if (!log_->IsEnabled() || !FLAG_log_code) return;
Steve Blockd0582a62009-12-15 09:54:21 +0000847 SmartPointer<char> str =
848 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
849 CallbackEventInternal("get ", *str, entry_point);
Steve Blockd0582a62009-12-15 09:54:21 +0000850}
851
852
853void Logger::SetterCallbackEvent(String* name, Address entry_point) {
Steve Block44f0eee2011-05-26 01:26:41 +0100854 if (!log_->IsEnabled() || !FLAG_log_code) return;
Steve Blockd0582a62009-12-15 09:54:21 +0000855 SmartPointer<char> str =
856 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
857 CallbackEventInternal("set ", *str, entry_point);
Steve Blockd0582a62009-12-15 09:54:21 +0000858}
859
860
Steve Blocka7e24c12009-10-30 11:49:00 +0000861void Logger::CodeCreateEvent(LogEventsAndTags tag,
862 Code* code,
863 const char* comment) {
Ben Murdoch257744e2011-11-30 15:57:28 +0000864 if (!log_->IsEnabled()) return;
865 if (FLAG_ll_prof || Serializer::enabled()) {
866 name_buffer_->Reset();
867 name_buffer_->AppendBytes(kLogEventsNames[tag]);
868 name_buffer_->AppendByte(':');
869 name_buffer_->AppendBytes(comment);
870 }
871 if (FLAG_ll_prof) {
872 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
873 }
874 if (Serializer::enabled()) {
875 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
876 }
877 if (!FLAG_log_code) return;
Steve Block44f0eee2011-05-26 01:26:41 +0100878 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100879 msg.Append("%s,%s,",
880 kLogEventsNames[CODE_CREATION_EVENT],
881 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000882 msg.AppendAddress(code->address());
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100883 msg.Append(",%d,\"", code->ExecutableSize());
Steve Blocka7e24c12009-10-30 11:49:00 +0000884 for (const char* p = comment; *p != '\0'; p++) {
885 if (*p == '"') {
886 msg.Append('\\');
887 }
888 msg.Append(*p);
889 }
890 msg.Append('"');
Steve Blocka7e24c12009-10-30 11:49:00 +0000891 msg.Append('\n');
892 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000893}
894
895
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100896void Logger::CodeCreateEvent(LogEventsAndTags tag,
897 Code* code,
898 String* name) {
Ben Murdoch257744e2011-11-30 15:57:28 +0000899 if (!log_->IsEnabled()) return;
900 if (FLAG_ll_prof || Serializer::enabled()) {
901 name_buffer_->Reset();
902 name_buffer_->AppendBytes(kLogEventsNames[tag]);
903 name_buffer_->AppendByte(':');
904 name_buffer_->AppendString(name);
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100905 }
Ben Murdoch257744e2011-11-30 15:57:28 +0000906 if (FLAG_ll_prof) {
907 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
908 }
909 if (Serializer::enabled()) {
910 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
911 }
912 if (!FLAG_log_code) return;
913 LogMessageBuilder msg(this);
914 msg.Append("%s,%s,",
915 kLogEventsNames[CODE_CREATION_EVENT],
916 kLogEventsNames[tag]);
917 msg.AppendAddress(code->address());
918 msg.Append(",%d,\"", code->ExecutableSize());
919 msg.AppendDetailed(name, false);
920 msg.Append('"');
921 msg.Append('\n');
922 msg.WriteToLogFile();
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100923}
924
925
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100926// ComputeMarker must only be used when SharedFunctionInfo is known.
927static const char* ComputeMarker(Code* code) {
928 switch (code->kind()) {
929 case Code::FUNCTION: return code->optimizable() ? "~" : "";
930 case Code::OPTIMIZED_FUNCTION: return "*";
931 default: return "";
932 }
933}
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100934
935
936void Logger::CodeCreateEvent(LogEventsAndTags tag,
937 Code* code,
938 SharedFunctionInfo* shared,
939 String* name) {
Ben Murdoch257744e2011-11-30 15:57:28 +0000940 if (!log_->IsEnabled()) return;
941 if (FLAG_ll_prof || Serializer::enabled()) {
942 name_buffer_->Reset();
943 name_buffer_->AppendBytes(kLogEventsNames[tag]);
944 name_buffer_->AppendByte(':');
945 name_buffer_->AppendBytes(ComputeMarker(code));
946 name_buffer_->AppendString(name);
947 }
948 if (FLAG_ll_prof) {
949 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
950 }
951 if (Serializer::enabled()) {
952 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
953 }
954 if (!FLAG_log_code) return;
Steve Block44f0eee2011-05-26 01:26:41 +0100955 if (code == Isolate::Current()->builtins()->builtin(
956 Builtins::kLazyCompile))
957 return;
958
959 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000960 SmartPointer<char> str =
961 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100962 msg.Append("%s,%s,",
963 kLogEventsNames[CODE_CREATION_EVENT],
964 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000965 msg.AppendAddress(code->address());
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100966 msg.Append(",%d,\"%s\",", code->ExecutableSize(), *str);
967 msg.AppendAddress(shared->address());
968 msg.Append(",%s", ComputeMarker(code));
Steve Blocka7e24c12009-10-30 11:49:00 +0000969 msg.Append('\n');
970 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000971}
972
973
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100974// Although, it is possible to extract source and line from
975// the SharedFunctionInfo object, we left it to caller
976// to leave logging functions free from heap allocations.
Steve Blocka7e24c12009-10-30 11:49:00 +0000977void Logger::CodeCreateEvent(LogEventsAndTags tag,
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100978 Code* code,
979 SharedFunctionInfo* shared,
Steve Blocka7e24c12009-10-30 11:49:00 +0000980 String* source, int line) {
Ben Murdoch257744e2011-11-30 15:57:28 +0000981 if (!log_->IsEnabled()) return;
982 if (FLAG_ll_prof || Serializer::enabled()) {
983 name_buffer_->Reset();
984 name_buffer_->AppendBytes(kLogEventsNames[tag]);
985 name_buffer_->AppendByte(':');
986 name_buffer_->AppendBytes(ComputeMarker(code));
987 name_buffer_->AppendString(shared->DebugName());
988 name_buffer_->AppendByte(' ');
989 name_buffer_->AppendString(source);
990 name_buffer_->AppendByte(':');
991 name_buffer_->AppendInt(line);
992 }
993 if (FLAG_ll_prof) {
994 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
995 }
996 if (Serializer::enabled()) {
997 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
998 }
999 if (!FLAG_log_code) return;
Steve Block44f0eee2011-05-26 01:26:41 +01001000 LogMessageBuilder msg(this);
Ben Murdoche0cee9b2011-05-25 10:26:03 +01001001 SmartPointer<char> name =
1002 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Steve Blocka7e24c12009-10-30 11:49:00 +00001003 SmartPointer<char> sourcestr =
1004 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001005 msg.Append("%s,%s,",
1006 kLogEventsNames[CODE_CREATION_EVENT],
1007 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +00001008 msg.AppendAddress(code->address());
Ben Murdoche0cee9b2011-05-25 10:26:03 +01001009 msg.Append(",%d,\"%s %s:%d\",",
Ben Murdochb0fe1622011-05-05 13:52:32 +01001010 code->ExecutableSize(),
Ben Murdoche0cee9b2011-05-25 10:26:03 +01001011 *name,
Ben Murdochb0fe1622011-05-05 13:52:32 +01001012 *sourcestr,
1013 line);
Ben Murdoche0cee9b2011-05-25 10:26:03 +01001014 msg.AppendAddress(shared->address());
1015 msg.Append(",%s", ComputeMarker(code));
Steve Blocka7e24c12009-10-30 11:49:00 +00001016 msg.Append('\n');
1017 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +00001018}
1019
1020
1021void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
Ben Murdoch257744e2011-11-30 15:57:28 +00001022 if (!log_->IsEnabled()) return;
1023 if (FLAG_ll_prof || Serializer::enabled()) {
1024 name_buffer_->Reset();
1025 name_buffer_->AppendBytes(kLogEventsNames[tag]);
1026 name_buffer_->AppendByte(':');
1027 name_buffer_->AppendInt(args_count);
1028 }
1029 if (FLAG_ll_prof) {
1030 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
1031 }
1032 if (Serializer::enabled()) {
1033 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
1034 }
1035 if (!FLAG_log_code) return;
Steve Block44f0eee2011-05-26 01:26:41 +01001036 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001037 msg.Append("%s,%s,",
1038 kLogEventsNames[CODE_CREATION_EVENT],
1039 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +00001040 msg.AppendAddress(code->address());
1041 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
Steve Blocka7e24c12009-10-30 11:49:00 +00001042 msg.Append('\n');
1043 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +00001044}
1045
1046
Ben Murdochf87a2032010-10-22 12:50:53 +01001047void Logger::CodeMovingGCEvent() {
Ben Murdoch257744e2011-11-30 15:57:28 +00001048 if (!log_->IsEnabled() || !FLAG_ll_prof) return;
1049 LowLevelLogWriteBytes(&kCodeMovingGCTag, sizeof(kCodeMovingGCTag));
Ben Murdochf87a2032010-10-22 12:50:53 +01001050 OS::SignalCodeMovingGC();
Ben Murdochf87a2032010-10-22 12:50:53 +01001051}
1052
1053
Steve Blocka7e24c12009-10-30 11:49:00 +00001054void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
Ben Murdoch257744e2011-11-30 15:57:28 +00001055 if (!log_->IsEnabled()) return;
1056 if (FLAG_ll_prof || Serializer::enabled()) {
1057 name_buffer_->Reset();
1058 name_buffer_->AppendBytes(kLogEventsNames[REG_EXP_TAG]);
1059 name_buffer_->AppendByte(':');
1060 name_buffer_->AppendString(source);
1061 }
1062 if (FLAG_ll_prof) {
1063 LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size());
1064 }
1065 if (Serializer::enabled()) {
1066 RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size());
1067 }
1068 if (!FLAG_log_code) return;
Steve Block44f0eee2011-05-26 01:26:41 +01001069 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001070 msg.Append("%s,%s,",
Ben Murdochb0fe1622011-05-05 13:52:32 +01001071 kLogEventsNames[CODE_CREATION_EVENT],
1072 kLogEventsNames[REG_EXP_TAG]);
Steve Blocka7e24c12009-10-30 11:49:00 +00001073 msg.AppendAddress(code->address());
1074 msg.Append(",%d,\"", code->ExecutableSize());
1075 msg.AppendDetailed(source, false);
1076 msg.Append('\"');
Steve Blocka7e24c12009-10-30 11:49:00 +00001077 msg.Append('\n');
1078 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +00001079}
1080
1081
1082void Logger::CodeMoveEvent(Address from, Address to) {
Ben Murdoch257744e2011-11-30 15:57:28 +00001083 if (!log_->IsEnabled()) return;
1084 if (FLAG_ll_prof) LowLevelCodeMoveEvent(from, to);
1085 if (Serializer::enabled() && address_to_name_map_ != NULL) {
1086 address_to_name_map_->Move(from, to);
1087 }
Leon Clarked91b9f72010-01-27 17:25:45 +00001088 MoveEventInternal(CODE_MOVE_EVENT, from, to);
Steve Blocka7e24c12009-10-30 11:49:00 +00001089}
1090
1091
1092void Logger::CodeDeleteEvent(Address from) {
Ben Murdoch257744e2011-11-30 15:57:28 +00001093 if (!log_->IsEnabled()) return;
1094 if (FLAG_ll_prof) LowLevelCodeDeleteEvent(from);
1095 if (Serializer::enabled() && address_to_name_map_ != NULL) {
1096 address_to_name_map_->Remove(from);
1097 }
Leon Clarked91b9f72010-01-27 17:25:45 +00001098 DeleteEventInternal(CODE_DELETE_EVENT, from);
Steve Blocka7e24c12009-10-30 11:49:00 +00001099}
1100
1101
Leon Clarkee46be812010-01-19 14:06:41 +00001102void Logger::SnapshotPositionEvent(Address addr, int pos) {
Ben Murdoch257744e2011-11-30 15:57:28 +00001103 if (!log_->IsEnabled()) return;
1104 if (FLAG_ll_prof) LowLevelSnapshotPositionEvent(addr, pos);
1105 if (Serializer::enabled() && address_to_name_map_ != NULL) {
1106 const char* code_name = address_to_name_map_->Lookup(addr);
1107 if (code_name == NULL) return; // Not a code object.
1108 LogMessageBuilder msg(this);
1109 msg.Append("%s,%d,\"", kLogEventsNames[SNAPSHOT_CODE_NAME_EVENT], pos);
1110 for (const char* p = code_name; *p != '\0'; ++p) {
1111 if (*p == '"') msg.Append('\\');
1112 msg.Append(*p);
1113 }
1114 msg.Append("\"\n");
1115 msg.WriteToLogFile();
1116 }
1117 if (!FLAG_log_snapshot_positions) return;
Steve Block44f0eee2011-05-26 01:26:41 +01001118 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001119 msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
Leon Clarkee46be812010-01-19 14:06:41 +00001120 msg.AppendAddress(addr);
1121 msg.Append(",%d", pos);
Leon Clarkee46be812010-01-19 14:06:41 +00001122 msg.Append('\n');
1123 msg.WriteToLogFile();
Leon Clarkee46be812010-01-19 14:06:41 +00001124}
1125
1126
Steve Block44f0eee2011-05-26 01:26:41 +01001127void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
Steve Block44f0eee2011-05-26 01:26:41 +01001128 MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to);
Leon Clarked91b9f72010-01-27 17:25:45 +00001129}
1130
1131
Leon Clarked91b9f72010-01-27 17:25:45 +00001132void Logger::MoveEventInternal(LogEventsAndTags event,
1133 Address from,
1134 Address to) {
Steve Block44f0eee2011-05-26 01:26:41 +01001135 if (!log_->IsEnabled() || !FLAG_log_code) return;
1136 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001137 msg.Append("%s,", kLogEventsNames[event]);
Leon Clarked91b9f72010-01-27 17:25:45 +00001138 msg.AppendAddress(from);
1139 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +01001140 msg.AppendAddress(to);
Leon Clarked91b9f72010-01-27 17:25:45 +00001141 msg.Append('\n');
1142 msg.WriteToLogFile();
1143}
Leon Clarked91b9f72010-01-27 17:25:45 +00001144
1145
Leon Clarked91b9f72010-01-27 17:25:45 +00001146void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
Steve Block44f0eee2011-05-26 01:26:41 +01001147 if (!log_->IsEnabled() || !FLAG_log_code) return;
1148 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001149 msg.Append("%s,", kLogEventsNames[event]);
Leon Clarked91b9f72010-01-27 17:25:45 +00001150 msg.AppendAddress(from);
Leon Clarked91b9f72010-01-27 17:25:45 +00001151 msg.Append('\n');
1152 msg.WriteToLogFile();
1153}
Leon Clarked91b9f72010-01-27 17:25:45 +00001154
1155
Steve Blocka7e24c12009-10-30 11:49:00 +00001156void Logger::ResourceEvent(const char* name, const char* tag) {
Steve Block44f0eee2011-05-26 01:26:41 +01001157 if (!log_->IsEnabled() || !FLAG_log) return;
1158 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001159 msg.Append("%s,%s,", name, tag);
1160
1161 uint32_t sec, usec;
1162 if (OS::GetUserTime(&sec, &usec) != -1) {
1163 msg.Append("%d,%d,", sec, usec);
1164 }
1165 msg.Append("%.0f", OS::TimeCurrentMillis());
1166
1167 msg.Append('\n');
1168 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +00001169}
1170
1171
1172void Logger::SuspectReadEvent(String* name, Object* obj) {
Steve Block44f0eee2011-05-26 01:26:41 +01001173 if (!log_->IsEnabled() || !FLAG_log_suspect) return;
1174 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001175 String* class_name = obj->IsJSObject()
1176 ? JSObject::cast(obj)->class_name()
Steve Block44f0eee2011-05-26 01:26:41 +01001177 : HEAP->empty_string();
Steve Blocka7e24c12009-10-30 11:49:00 +00001178 msg.Append("suspect-read,");
1179 msg.Append(class_name);
1180 msg.Append(',');
1181 msg.Append('"');
1182 msg.Append(name);
1183 msg.Append('"');
1184 msg.Append('\n');
1185 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +00001186}
1187
1188
1189void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
Steve Block44f0eee2011-05-26 01:26:41 +01001190 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1191 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001192 // Using non-relative system time in order to be able to synchronize with
1193 // external memory profiling events (e.g. DOM memory size).
1194 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
1195 space, kind, OS::TimeCurrentMillis());
1196 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +00001197}
1198
1199
1200void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
Steve Block44f0eee2011-05-26 01:26:41 +01001201 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1202 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001203 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1204 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +00001205}
1206
1207
1208void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
Steve Block44f0eee2011-05-26 01:26:41 +01001209 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1210 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001211 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1212 msg.WriteToLogFile();
Steve Block3ce2e202009-11-05 08:53:23 +00001213}
1214
1215
Steve Blocka7e24c12009-10-30 11:49:00 +00001216void Logger::DebugTag(const char* call_site_tag) {
Steve Block44f0eee2011-05-26 01:26:41 +01001217 if (!log_->IsEnabled() || !FLAG_log) return;
1218 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001219 msg.Append("debug-tag,%s\n", call_site_tag);
1220 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +00001221}
1222
1223
1224void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
Steve Block44f0eee2011-05-26 01:26:41 +01001225 if (!log_->IsEnabled() || !FLAG_log) return;
Steve Blocka7e24c12009-10-30 11:49:00 +00001226 StringBuilder s(parameter.length() + 1);
1227 for (int i = 0; i < parameter.length(); ++i) {
1228 s.AddCharacter(static_cast<char>(parameter[i]));
1229 }
1230 char* parameter_string = s.Finalize();
Steve Block44f0eee2011-05-26 01:26:41 +01001231 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001232 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1233 event_type,
1234 OS::TimeCurrentMillis(),
1235 parameter_string);
1236 DeleteArray(parameter_string);
1237 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +00001238}
1239
1240
Steve Blocka7e24c12009-10-30 11:49:00 +00001241void Logger::TickEvent(TickSample* sample, bool overflow) {
Steve Block44f0eee2011-05-26 01:26:41 +01001242 if (!log_->IsEnabled() || !FLAG_prof) return;
1243 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001244 msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
1245 msg.AppendAddress(sample->pc);
Steve Blocka7e24c12009-10-30 11:49:00 +00001246 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +01001247 msg.AppendAddress(sample->sp);
Steve Block44f0eee2011-05-26 01:26:41 +01001248 if (sample->has_external_callback) {
1249 msg.Append(",1,");
1250 msg.AppendAddress(sample->external_callback);
1251 } else {
1252 msg.Append(",0,");
1253 msg.AppendAddress(sample->tos);
1254 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001255 msg.Append(",%d", static_cast<int>(sample->state));
1256 if (overflow) {
1257 msg.Append(",overflow");
1258 }
1259 for (int i = 0; i < sample->frames_count; ++i) {
1260 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +01001261 msg.AppendAddress(sample->stack[i]);
Steve Blocka7e24c12009-10-30 11:49:00 +00001262 }
1263 msg.Append('\n');
1264 msg.WriteToLogFile();
1265}
1266
1267
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001268bool Logger::IsProfilerPaused() {
1269 return profiler_ == NULL || profiler_->paused();
Steve Blocka7e24c12009-10-30 11:49:00 +00001270}
1271
1272
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001273void Logger::PauseProfiler() {
Steve Block44f0eee2011-05-26 01:26:41 +01001274 if (!log_->IsEnabled()) return;
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001275 if (profiler_ != NULL) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001276 // It is OK to have negative nesting.
1277 if (--cpu_profiler_nesting_ == 0) {
1278 profiler_->pause();
1279 if (FLAG_prof_lazy) {
Ben Murdochb0fe1622011-05-05 13:52:32 +01001280 if (!FLAG_sliding_state_window && !RuntimeProfiler::IsEnabled()) {
1281 ticker_->Stop();
1282 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001283 FLAG_log_code = false;
Steve Block44f0eee2011-05-26 01:26:41 +01001284 LOG(ISOLATE, UncheckedStringEvent("profiler", "pause"));
Andrei Popescu402d9372010-02-26 13:31:12 +00001285 }
Steve Block6ded16b2010-05-10 14:33:55 +01001286 --logging_nesting_;
Steve Blocka7e24c12009-10-30 11:49:00 +00001287 }
1288 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001289}
1290
1291
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001292void Logger::ResumeProfiler() {
Steve Block44f0eee2011-05-26 01:26:41 +01001293 if (!log_->IsEnabled()) return;
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001294 if (profiler_ != NULL) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001295 if (cpu_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001296 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001297 if (FLAG_prof_lazy) {
1298 profiler_->Engage();
Steve Block44f0eee2011-05-26 01:26:41 +01001299 LOG(ISOLATE, UncheckedStringEvent("profiler", "resume"));
Andrei Popescu402d9372010-02-26 13:31:12 +00001300 FLAG_log_code = true;
1301 LogCompiledFunctions();
Andrei Popescu402d9372010-02-26 13:31:12 +00001302 LogAccessorCallbacks();
Ben Murdochb0fe1622011-05-05 13:52:32 +01001303 if (!FLAG_sliding_state_window && !ticker_->IsActive()) {
1304 ticker_->Start();
1305 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001306 }
1307 profiler_->resume();
Steve Blocka7e24c12009-10-30 11:49:00 +00001308 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001309 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001310}
1311
1312
1313// This function can be called when Log's mutex is acquired,
1314// either from main or Profiler's thread.
Steve Block44f0eee2011-05-26 01:26:41 +01001315void Logger::LogFailure() {
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001316 PauseProfiler();
Steve Blocka7e24c12009-10-30 11:49:00 +00001317}
1318
1319
1320bool Logger::IsProfilerSamplerActive() {
1321 return ticker_->IsActive();
1322}
1323
1324
Ben Murdochb0fe1622011-05-05 13:52:32 +01001325class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1326 public:
1327 EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1328 Handle<Code>* code_objects,
1329 int* count)
1330 : sfis_(sfis), code_objects_(code_objects), count_(count) { }
1331
1332 virtual void EnterContext(Context* context) {}
1333 virtual void LeaveContext(Context* context) {}
1334
1335 virtual void VisitFunction(JSFunction* function) {
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001336 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared());
1337 Object* maybe_script = sfi->script();
1338 if (maybe_script->IsScript()
1339 && !Script::cast(maybe_script)->HasValidSource()) return;
Ben Murdochb0fe1622011-05-05 13:52:32 +01001340 if (sfis_ != NULL) {
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001341 sfis_[*count_] = Handle<SharedFunctionInfo>(sfi);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001342 }
1343 if (code_objects_ != NULL) {
1344 ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
1345 code_objects_[*count_] = Handle<Code>(function->code());
1346 }
1347 *count_ = *count_ + 1;
1348 }
1349
1350 private:
1351 Handle<SharedFunctionInfo>* sfis_;
1352 Handle<Code>* code_objects_;
1353 int* count_;
1354};
1355
1356
1357static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis,
1358 Handle<Code>* code_objects) {
Steve Block3ce2e202009-11-05 08:53:23 +00001359 AssertNoAllocation no_alloc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001360 int compiled_funcs_count = 0;
Ben Murdochb0fe1622011-05-05 13:52:32 +01001361
1362 // Iterate the heap to find shared function info objects and record
1363 // the unoptimized code for them.
Steve Block3ce2e202009-11-05 08:53:23 +00001364 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001365 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Block3ce2e202009-11-05 08:53:23 +00001366 if (!obj->IsSharedFunctionInfo()) continue;
1367 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1368 if (sfi->is_compiled()
1369 && (!sfi->script()->IsScript()
1370 || Script::cast(sfi->script())->HasValidSource())) {
Ben Murdochb0fe1622011-05-05 13:52:32 +01001371 if (sfis != NULL) {
Steve Block3ce2e202009-11-05 08:53:23 +00001372 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001373 }
1374 if (code_objects != NULL) {
1375 code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
1376 }
Steve Block3ce2e202009-11-05 08:53:23 +00001377 ++compiled_funcs_count;
Steve Blocka7e24c12009-10-30 11:49:00 +00001378 }
1379 }
Ben Murdochb0fe1622011-05-05 13:52:32 +01001380
1381 // Iterate all optimized functions in all contexts.
1382 EnumerateOptimizedFunctionsVisitor visitor(sfis,
1383 code_objects,
1384 &compiled_funcs_count);
1385 Deoptimizer::VisitAllOptimizedFunctions(&visitor);
1386
Steve Block3ce2e202009-11-05 08:53:23 +00001387 return compiled_funcs_count;
1388}
1389
1390
Steve Blockd0582a62009-12-15 09:54:21 +00001391void Logger::LogCodeObject(Object* object) {
Ben Murdoch257744e2011-11-30 15:57:28 +00001392 if (FLAG_log_code || FLAG_ll_prof) {
Steve Blockd0582a62009-12-15 09:54:21 +00001393 Code* code_object = Code::cast(object);
1394 LogEventsAndTags tag = Logger::STUB_TAG;
1395 const char* description = "Unknown code from the snapshot";
1396 switch (code_object->kind()) {
1397 case Code::FUNCTION:
Ben Murdochb0fe1622011-05-05 13:52:32 +01001398 case Code::OPTIMIZED_FUNCTION:
Steve Blockd0582a62009-12-15 09:54:21 +00001399 return; // We log this later using LogCompiledFunctions.
Ben Murdoch257744e2011-11-30 15:57:28 +00001400 case Code::UNARY_OP_IC: // fall through
1401 case Code::BINARY_OP_IC: // fall through
Ben Murdochb0fe1622011-05-05 13:52:32 +01001402 case Code::COMPARE_IC: // fall through
Steve Blockd0582a62009-12-15 09:54:21 +00001403 case Code::STUB:
Kristian Monsen80d68ea2010-09-08 11:05:35 +01001404 description =
1405 CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
Andrei Popescu31002712010-02-23 13:46:05 +00001406 if (description == NULL)
1407 description = "A stub from the snapshot";
Steve Blockd0582a62009-12-15 09:54:21 +00001408 tag = Logger::STUB_TAG;
1409 break;
1410 case Code::BUILTIN:
1411 description = "A builtin from the snapshot";
1412 tag = Logger::BUILTIN_TAG;
1413 break;
1414 case Code::KEYED_LOAD_IC:
1415 description = "A keyed load IC from the snapshot";
1416 tag = Logger::KEYED_LOAD_IC_TAG;
1417 break;
1418 case Code::LOAD_IC:
1419 description = "A load IC from the snapshot";
1420 tag = Logger::LOAD_IC_TAG;
1421 break;
1422 case Code::STORE_IC:
1423 description = "A store IC from the snapshot";
1424 tag = Logger::STORE_IC_TAG;
1425 break;
1426 case Code::KEYED_STORE_IC:
1427 description = "A keyed store IC from the snapshot";
1428 tag = Logger::KEYED_STORE_IC_TAG;
1429 break;
1430 case Code::CALL_IC:
1431 description = "A call IC from the snapshot";
1432 tag = Logger::CALL_IC_TAG;
1433 break;
Ben Murdoch7f4d5bd2010-06-15 11:15:29 +01001434 case Code::KEYED_CALL_IC:
1435 description = "A keyed call IC from the snapshot";
1436 tag = Logger::KEYED_CALL_IC_TAG;
1437 break;
Steve Blockd0582a62009-12-15 09:54:21 +00001438 }
Steve Block44f0eee2011-05-26 01:26:41 +01001439 PROFILE(ISOLATE, CodeCreateEvent(tag, code_object, description));
Steve Blockd0582a62009-12-15 09:54:21 +00001440 }
1441}
1442
1443
Ben Murdochf87a2032010-10-22 12:50:53 +01001444void Logger::LogCodeInfo() {
Ben Murdoch257744e2011-11-30 15:57:28 +00001445 if (!log_->IsEnabled() || !FLAG_ll_prof) return;
Ben Murdochf87a2032010-10-22 12:50:53 +01001446#if V8_TARGET_ARCH_IA32
1447 const char arch[] = "ia32";
1448#elif V8_TARGET_ARCH_X64
1449 const char arch[] = "x64";
1450#elif V8_TARGET_ARCH_ARM
1451 const char arch[] = "arm";
1452#else
1453 const char arch[] = "unknown";
1454#endif
Ben Murdoch257744e2011-11-30 15:57:28 +00001455 LowLevelLogWriteBytes(arch, sizeof(arch));
Ben Murdochf87a2032010-10-22 12:50:53 +01001456}
1457
1458
Ben Murdoch257744e2011-11-30 15:57:28 +00001459void Logger::RegisterSnapshotCodeName(Code* code,
1460 const char* name,
1461 int name_size) {
1462 ASSERT(Serializer::enabled());
1463 if (address_to_name_map_ == NULL) {
1464 address_to_name_map_ = new NameMap;
1465 }
1466 address_to_name_map_->Insert(code->address(), name, name_size);
1467}
1468
1469
1470void Logger::LowLevelCodeCreateEvent(Code* code,
1471 const char* name,
1472 int name_size) {
1473 if (log_->ll_output_handle_ == NULL) return;
1474 LowLevelCodeCreateStruct event;
1475 event.name_size = name_size;
1476 event.code_address = code->instruction_start();
1477 ASSERT(event.code_address == code->address() + Code::kHeaderSize);
1478 event.code_size = code->instruction_size();
1479 LowLevelLogWriteStruct(event);
1480 LowLevelLogWriteBytes(name, name_size);
1481 LowLevelLogWriteBytes(
1482 reinterpret_cast<const char*>(code->instruction_start()),
1483 code->instruction_size());
1484}
1485
1486
1487void Logger::LowLevelCodeMoveEvent(Address from, Address to) {
1488 if (log_->ll_output_handle_ == NULL) return;
1489 LowLevelCodeMoveStruct event;
1490 event.from_address = from + Code::kHeaderSize;
1491 event.to_address = to + Code::kHeaderSize;
1492 LowLevelLogWriteStruct(event);
1493}
1494
1495
1496void Logger::LowLevelCodeDeleteEvent(Address from) {
1497 if (log_->ll_output_handle_ == NULL) return;
1498 LowLevelCodeDeleteStruct event;
1499 event.address = from + Code::kHeaderSize;
1500 LowLevelLogWriteStruct(event);
1501}
1502
1503
1504void Logger::LowLevelSnapshotPositionEvent(Address addr, int pos) {
1505 if (log_->ll_output_handle_ == NULL) return;
1506 LowLevelSnapshotPositionStruct event;
1507 event.address = addr + Code::kHeaderSize;
1508 event.position = pos;
1509 LowLevelLogWriteStruct(event);
1510}
1511
1512
1513void Logger::LowLevelLogWriteBytes(const char* bytes, int size) {
1514 size_t rv = fwrite(bytes, 1, size, log_->ll_output_handle_);
1515 ASSERT(static_cast<size_t>(size) == rv);
John Reck59135872010-11-02 12:39:01 -07001516 USE(rv);
Ben Murdochf87a2032010-10-22 12:50:53 +01001517}
1518
1519
Andrei Popescu31002712010-02-23 13:46:05 +00001520void Logger::LogCodeObjects() {
1521 AssertNoAllocation no_alloc;
1522 HeapIterator iterator;
1523 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1524 if (obj->IsCode()) LogCodeObject(obj);
1525 }
1526}
1527
1528
Steve Block3ce2e202009-11-05 08:53:23 +00001529void Logger::LogCompiledFunctions() {
1530 HandleScope scope;
Ben Murdochb0fe1622011-05-05 13:52:32 +01001531 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL, NULL);
Kristian Monsen25f61362010-05-21 11:50:48 +01001532 ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001533 ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
1534 EnumerateCompiledFunctions(sfis.start(), code_objects.start());
Steve Blocka7e24c12009-10-30 11:49:00 +00001535
1536 // During iteration, there can be heap allocation due to
1537 // GetScriptLineNumber call.
1538 for (int i = 0; i < compiled_funcs_count; ++i) {
Steve Block44f0eee2011-05-26 01:26:41 +01001539 if (*code_objects[i] == Isolate::Current()->builtins()->builtin(
1540 Builtins::kLazyCompile))
1541 continue;
Steve Blocka7e24c12009-10-30 11:49:00 +00001542 Handle<SharedFunctionInfo> shared = sfis[i];
Ben Murdoche0cee9b2011-05-25 10:26:03 +01001543 Handle<String> func_name(shared->DebugName());
Steve Blocka7e24c12009-10-30 11:49:00 +00001544 if (shared->script()->IsScript()) {
1545 Handle<Script> script(Script::cast(shared->script()));
1546 if (script->name()->IsString()) {
1547 Handle<String> script_name(String::cast(script->name()));
1548 int line_num = GetScriptLineNumber(script, shared->start_position());
1549 if (line_num > 0) {
Steve Block44f0eee2011-05-26 01:26:41 +01001550 PROFILE(ISOLATE,
1551 CodeCreateEvent(
1552 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1553 *code_objects[i], *shared,
1554 *script_name, line_num + 1));
Steve Blocka7e24c12009-10-30 11:49:00 +00001555 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001556 // Can't distinguish eval and script here, so always use Script.
Steve Block44f0eee2011-05-26 01:26:41 +01001557 PROFILE(ISOLATE,
1558 CodeCreateEvent(
1559 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1560 *code_objects[i], *shared, *script_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001561 }
Steve Blockd0582a62009-12-15 09:54:21 +00001562 } else {
Steve Block44f0eee2011-05-26 01:26:41 +01001563 PROFILE(ISOLATE,
1564 CodeCreateEvent(
1565 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1566 *code_objects[i], *shared, *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001567 }
Steve Block6ded16b2010-05-10 14:33:55 +01001568 } else if (shared->IsApiFunction()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001569 // API function.
Steve Block6ded16b2010-05-10 14:33:55 +01001570 FunctionTemplateInfo* fun_data = shared->get_api_func_data();
Steve Blockd0582a62009-12-15 09:54:21 +00001571 Object* raw_call_data = fun_data->call_code();
1572 if (!raw_call_data->IsUndefined()) {
1573 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1574 Object* callback_obj = call_data->callback();
1575 Address entry_point = v8::ToCData<Address>(callback_obj);
Steve Block44f0eee2011-05-26 01:26:41 +01001576 PROFILE(ISOLATE, CallbackEvent(*func_name, entry_point));
Steve Blockd0582a62009-12-15 09:54:21 +00001577 }
1578 } else {
Steve Block44f0eee2011-05-26 01:26:41 +01001579 PROFILE(ISOLATE,
1580 CodeCreateEvent(
1581 Logger::LAZY_COMPILE_TAG, *code_objects[i],
1582 *shared, *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001583 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001584 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001585}
1586
Steve Blockd0582a62009-12-15 09:54:21 +00001587
1588void Logger::LogAccessorCallbacks() {
1589 AssertNoAllocation no_alloc;
1590 HeapIterator iterator;
Steve Block44f0eee2011-05-26 01:26:41 +01001591 i::Isolate* isolate = ISOLATE;
Leon Clarked91b9f72010-01-27 17:25:45 +00001592 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001593 if (!obj->IsAccessorInfo()) continue;
1594 AccessorInfo* ai = AccessorInfo::cast(obj);
1595 if (!ai->name()->IsString()) continue;
1596 String* name = String::cast(ai->name());
1597 Address getter_entry = v8::ToCData<Address>(ai->getter());
1598 if (getter_entry != 0) {
Steve Block44f0eee2011-05-26 01:26:41 +01001599 PROFILE(isolate, GetterCallbackEvent(name, getter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001600 }
1601 Address setter_entry = v8::ToCData<Address>(ai->setter());
1602 if (setter_entry != 0) {
Steve Block44f0eee2011-05-26 01:26:41 +01001603 PROFILE(isolate, SetterCallbackEvent(name, setter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001604 }
1605 }
1606}
1607
Steve Blocka7e24c12009-10-30 11:49:00 +00001608
1609bool Logger::Setup() {
Steve Block44f0eee2011-05-26 01:26:41 +01001610 // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
1611 if (is_initialized_) return true;
1612 is_initialized_ = true;
Steve Blocka7e24c12009-10-30 11:49:00 +00001613
Ben Murdochf87a2032010-10-22 12:50:53 +01001614 // --ll-prof implies --log-code and --log-snapshot-positions.
1615 if (FLAG_ll_prof) {
Ben Murdochf87a2032010-10-22 12:50:53 +01001616 FLAG_log_snapshot_positions = true;
1617 }
1618
Steve Blocka7e24c12009-10-30 11:49:00 +00001619 // --prof_lazy controls --log-code, implies --noprof_auto.
1620 if (FLAG_prof_lazy) {
1621 FLAG_log_code = false;
1622 FLAG_prof_auto = false;
1623 }
1624
Steve Block44f0eee2011-05-26 01:26:41 +01001625 // TODO(isolates): this assert introduces cyclic dependency (logger
1626 // -> thread local top -> heap -> logger).
1627 // ASSERT(VMState::is_outermost_external());
Steve Blocka7e24c12009-10-30 11:49:00 +00001628
Steve Block44f0eee2011-05-26 01:26:41 +01001629 log_->Initialize();
Steve Blocka7e24c12009-10-30 11:49:00 +00001630
Ben Murdochf87a2032010-10-22 12:50:53 +01001631 if (FLAG_ll_prof) LogCodeInfo();
1632
Steve Block44f0eee2011-05-26 01:26:41 +01001633 Isolate* isolate = Isolate::Current();
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001634 ticker_ = new Ticker(isolate, kSamplingIntervalMs);
1635
Steve Blocka7e24c12009-10-30 11:49:00 +00001636 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
Steve Block44f0eee2011-05-26 01:26:41 +01001637 sliding_state_window_ = new SlidingStateWindow(isolate);
Steve Blocka7e24c12009-10-30 11:49:00 +00001638 }
1639
Steve Block44f0eee2011-05-26 01:26:41 +01001640 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1641 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
Ben Murdoch257744e2011-11-30 15:57:28 +00001642 || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof;
Steve Block44f0eee2011-05-26 01:26:41 +01001643
Steve Block6ded16b2010-05-10 14:33:55 +01001644 if (start_logging) {
1645 logging_nesting_ = 1;
1646 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001647
1648 if (FLAG_prof) {
Steve Block44f0eee2011-05-26 01:26:41 +01001649 profiler_ = new Profiler(isolate);
Steve Blocka7e24c12009-10-30 11:49:00 +00001650 if (!FLAG_prof_auto) {
1651 profiler_->pause();
1652 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001653 logging_nesting_ = 1;
Steve Blocka7e24c12009-10-30 11:49:00 +00001654 }
Steve Blockd0582a62009-12-15 09:54:21 +00001655 if (!FLAG_prof_lazy) {
1656 profiler_->Engage();
1657 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001658 }
1659
Steve Blocka7e24c12009-10-30 11:49:00 +00001660 return true;
Steve Blocka7e24c12009-10-30 11:49:00 +00001661}
1662
1663
Steve Block44f0eee2011-05-26 01:26:41 +01001664Sampler* Logger::sampler() {
1665 return ticker_;
1666}
1667
1668
Ben Murdochb0fe1622011-05-05 13:52:32 +01001669void Logger::EnsureTickerStarted() {
Ben Murdochb0fe1622011-05-05 13:52:32 +01001670 ASSERT(ticker_ != NULL);
1671 if (!ticker_->IsActive()) ticker_->Start();
Ben Murdochb0fe1622011-05-05 13:52:32 +01001672}
1673
1674
1675void Logger::EnsureTickerStopped() {
Ben Murdochb0fe1622011-05-05 13:52:32 +01001676 if (ticker_ != NULL && ticker_->IsActive()) ticker_->Stop();
Ben Murdochb0fe1622011-05-05 13:52:32 +01001677}
1678
1679
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001680FILE* Logger::TearDown() {
1681 if (!is_initialized_) return NULL;
Steve Block44f0eee2011-05-26 01:26:41 +01001682 is_initialized_ = false;
Steve Blocka7e24c12009-10-30 11:49:00 +00001683
1684 // Stop the profiler before closing the file.
1685 if (profiler_ != NULL) {
1686 profiler_->Disengage();
1687 delete profiler_;
1688 profiler_ = NULL;
1689 }
1690
Steve Blocka7e24c12009-10-30 11:49:00 +00001691 delete sliding_state_window_;
1692 sliding_state_window_ = NULL;
1693
1694 delete ticker_;
1695 ticker_ = NULL;
1696
Ben Murdoch3fb3ca82011-12-02 17:19:32 +00001697 return log_->Close();
Steve Blocka7e24c12009-10-30 11:49:00 +00001698}
1699
1700
1701void Logger::EnableSlidingStateWindow() {
Steve Blocka7e24c12009-10-30 11:49:00 +00001702 // If the ticker is NULL, Logger::Setup has not been called yet. In
1703 // that case, we set the sliding_state_window flag so that the
1704 // sliding window computation will be started when Logger::Setup is
1705 // called.
1706 if (ticker_ == NULL) {
1707 FLAG_sliding_state_window = true;
1708 return;
1709 }
1710 // Otherwise, if the sliding state window computation has not been
1711 // started we do it now.
1712 if (sliding_state_window_ == NULL) {
Steve Block44f0eee2011-05-26 01:26:41 +01001713 sliding_state_window_ = new SlidingStateWindow(Isolate::Current());
Steve Blocka7e24c12009-10-30 11:49:00 +00001714 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001715}
1716
Steve Block44f0eee2011-05-26 01:26:41 +01001717
1718Mutex* SamplerRegistry::mutex_ = OS::CreateMutex();
1719List<Sampler*>* SamplerRegistry::active_samplers_ = NULL;
1720
1721
1722bool SamplerRegistry::IterateActiveSamplers(VisitSampler func, void* param) {
1723 ScopedLock lock(mutex_);
1724 for (int i = 0;
1725 ActiveSamplersExist() && i < active_samplers_->length();
1726 ++i) {
1727 func(active_samplers_->at(i), param);
1728 }
1729 return ActiveSamplersExist();
1730}
1731
1732
1733static void ComputeCpuProfiling(Sampler* sampler, void* flag_ptr) {
1734 bool* flag = reinterpret_cast<bool*>(flag_ptr);
1735 *flag |= sampler->IsProfiling();
1736}
1737
1738
1739SamplerRegistry::State SamplerRegistry::GetState() {
1740 bool flag = false;
1741 if (!IterateActiveSamplers(&ComputeCpuProfiling, &flag)) {
1742 return HAS_NO_SAMPLERS;
1743 }
1744 return flag ? HAS_CPU_PROFILING_SAMPLERS : HAS_SAMPLERS;
1745}
1746
1747
1748void SamplerRegistry::AddActiveSampler(Sampler* sampler) {
1749 ASSERT(sampler->IsActive());
1750 ScopedLock lock(mutex_);
1751 if (active_samplers_ == NULL) {
1752 active_samplers_ = new List<Sampler*>;
1753 } else {
1754 ASSERT(!active_samplers_->Contains(sampler));
1755 }
1756 active_samplers_->Add(sampler);
1757}
1758
1759
1760void SamplerRegistry::RemoveActiveSampler(Sampler* sampler) {
1761 ASSERT(sampler->IsActive());
1762 ScopedLock lock(mutex_);
1763 ASSERT(active_samplers_ != NULL);
1764 bool removed = active_samplers_->RemoveElement(sampler);
1765 ASSERT(removed);
1766 USE(removed);
1767}
1768
Steve Blocka7e24c12009-10-30 11:49:00 +00001769} } // namespace v8::internal