blob: 6991f3d58c3708014343423a8a16838336568e28 [file] [log] [blame]
Steve Blocka7e24c12009-10-30 11:49:00 +00001// Copyright 2009 the V8 project authors. All rights reserved.
2// Redistribution and use in source and binary forms, with or without
3// modification, are permitted provided that the following conditions are
4// met:
5//
6// * Redistributions of source code must retain the above copyright
7// notice, this list of conditions and the following disclaimer.
8// * Redistributions in binary form must reproduce the above
9// copyright notice, this list of conditions and the following
10// disclaimer in the documentation and/or other materials provided
11// with the distribution.
12// * Neither the name of Google Inc. nor the names of its
13// contributors may be used to endorse or promote products derived
14// from this software without specific prior written permission.
15//
16// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
17// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
18// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
19// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
20// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
21// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
22// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
23// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
24// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
25// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
26// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
27
28#include <stdarg.h>
29
30#include "v8.h"
31
32#include "bootstrapper.h"
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
46#ifdef ENABLE_LOGGING_AND_PROFILING
47
48//
49// Sliding state window. Updates counters to keep track of the last
50// window of kBufferSize states. This is useful to track where we
51// spent our time.
52//
53class SlidingStateWindow {
54 public:
Steve Block44f0eee2011-05-26 01:26:41 +010055 explicit SlidingStateWindow(Isolate* isolate);
Steve Blocka7e24c12009-10-30 11:49:00 +000056 ~SlidingStateWindow();
57 void AddState(StateTag state);
58
59 private:
60 static const int kBufferSize = 256;
Steve Block44f0eee2011-05-26 01:26:41 +010061 Counters* counters_;
Steve Blocka7e24c12009-10-30 11:49:00 +000062 int current_index_;
63 bool is_full_;
64 byte buffer_[kBufferSize];
65
66
67 void IncrementStateCounter(StateTag state) {
Steve Block44f0eee2011-05-26 01:26:41 +010068 counters_->state_counters(state)->Increment();
Steve Blocka7e24c12009-10-30 11:49:00 +000069 }
70
71
72 void DecrementStateCounter(StateTag state) {
Steve Block44f0eee2011-05-26 01:26:41 +010073 counters_->state_counters(state)->Decrement();
Steve Blocka7e24c12009-10-30 11:49:00 +000074 }
75};
76
77
78//
79// The Profiler samples pc and sp values for the main thread.
80// Each sample is appended to a circular buffer.
81// An independent thread removes data and writes it to the log.
82// This design minimizes the time spent in the sampler.
83//
84class Profiler: public Thread {
85 public:
Steve Block44f0eee2011-05-26 01:26:41 +010086 explicit Profiler(Isolate* isolate);
Steve Blocka7e24c12009-10-30 11:49:00 +000087 void Engage();
88 void Disengage();
89
90 // Inserts collected profiling data into buffer.
91 void Insert(TickSample* sample) {
92 if (paused_)
93 return;
94
95 if (Succ(head_) == tail_) {
96 overflow_ = true;
97 } else {
98 buffer_[head_] = *sample;
99 head_ = Succ(head_);
100 buffer_semaphore_->Signal(); // Tell we have an element.
101 }
102 }
103
104 // Waits for a signal and removes profiling data.
105 bool Remove(TickSample* sample) {
106 buffer_semaphore_->Wait(); // Wait for an element.
107 *sample = buffer_[tail_];
108 bool result = overflow_;
109 tail_ = Succ(tail_);
110 overflow_ = false;
111 return result;
112 }
113
114 void Run();
115
116 // Pause and Resume TickSample data collection.
Steve Block44f0eee2011-05-26 01:26:41 +0100117 bool paused() const { return paused_; }
118 void pause() { paused_ = true; }
119 void resume() { paused_ = false; }
Steve Blocka7e24c12009-10-30 11:49:00 +0000120
121 private:
122 // Returns the next index in the cyclic buffer.
123 int Succ(int index) { return (index + 1) % kBufferSize; }
124
125 // Cyclic buffer for communicating profiling samples
126 // between the signal handler and the worker thread.
127 static const int kBufferSize = 128;
128 TickSample buffer_[kBufferSize]; // Buffer storage.
129 int head_; // Index to the buffer head.
130 int tail_; // Index to the buffer tail.
131 bool overflow_; // Tell whether a buffer overflow has occurred.
132 Semaphore* buffer_semaphore_; // Sempahore used for buffer synchronization.
133
Steve Blockd0582a62009-12-15 09:54:21 +0000134 // Tells whether profiler is engaged, that is, processing thread is stated.
135 bool engaged_;
136
Steve Blocka7e24c12009-10-30 11:49:00 +0000137 // Tells whether worker thread should continue running.
138 bool running_;
139
140 // Tells whether we are currently recording tick samples.
Steve Block44f0eee2011-05-26 01:26:41 +0100141 bool paused_;
Steve Blocka7e24c12009-10-30 11:49:00 +0000142};
143
Steve Blocka7e24c12009-10-30 11:49:00 +0000144
145//
146// StackTracer implementation
147//
Steve Block44f0eee2011-05-26 01:26:41 +0100148void StackTracer::Trace(Isolate* isolate, TickSample* sample) {
149 ASSERT(isolate->IsInitialized());
150
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100151 sample->tos = NULL;
Steve Block6ded16b2010-05-10 14:33:55 +0100152 sample->frames_count = 0;
153
Ben Murdochb0fe1622011-05-05 13:52:32 +0100154 // Avoid collecting traces while doing GC.
Steve Block6ded16b2010-05-10 14:33:55 +0100155 if (sample->state == GC) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000156
Steve Block44f0eee2011-05-26 01:26:41 +0100157 const Address js_entry_sp =
158 Isolate::js_entry_sp(isolate->thread_local_top());
Steve Blocka7e24c12009-10-30 11:49:00 +0000159 if (js_entry_sp == 0) {
160 // Not executing JS now.
Steve Blocka7e24c12009-10-30 11:49:00 +0000161 return;
162 }
163
Steve Block44f0eee2011-05-26 01:26:41 +0100164 const Address callback = isolate->external_callback();
165 if (callback != NULL) {
166 sample->external_callback = callback;
167 sample->has_external_callback = true;
168 } else {
169 // Sample potential return address value for frameless invocation of
170 // stubs (we'll figure out later, if this value makes sense).
171 sample->tos = Memory::Address_at(sample->sp);
172 sample->has_external_callback = false;
Steve Blockd0582a62009-12-15 09:54:21 +0000173 }
174
Steve Block44f0eee2011-05-26 01:26:41 +0100175 SafeStackTraceFrameIterator it(isolate,
176 sample->fp, sample->sp,
Leon Clarked91b9f72010-01-27 17:25:45 +0000177 sample->sp, js_entry_sp);
Steve Block44f0eee2011-05-26 01:26:41 +0100178 int i = 0;
Steve Blocka7e24c12009-10-30 11:49:00 +0000179 while (!it.done() && i < TickSample::kMaxFramesCount) {
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100180 sample->stack[i++] = it.frame()->pc();
Steve Blocka7e24c12009-10-30 11:49:00 +0000181 it.Advance();
182 }
183 sample->frames_count = i;
184}
185
186
187//
188// Ticker used to provide ticks to the profiler and the sliding state
189// window.
190//
191class Ticker: public Sampler {
192 public:
Steve Block44f0eee2011-05-26 01:26:41 +0100193 explicit Ticker(Isolate* isolate, int interval):
194 Sampler(isolate, interval),
Ben Murdochb0fe1622011-05-05 13:52:32 +0100195 window_(NULL),
196 profiler_(NULL) {}
Steve Blocka7e24c12009-10-30 11:49:00 +0000197
198 ~Ticker() { if (IsActive()) Stop(); }
199
Ben Murdochf87a2032010-10-22 12:50:53 +0100200 virtual void Tick(TickSample* sample) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000201 if (profiler_) profiler_->Insert(sample);
202 if (window_) window_->AddState(sample->state);
203 }
204
205 void SetWindow(SlidingStateWindow* window) {
206 window_ = window;
207 if (!IsActive()) Start();
208 }
209
210 void ClearWindow() {
211 window_ = NULL;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100212 if (!profiler_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
Steve Blocka7e24c12009-10-30 11:49:00 +0000213 }
214
215 void SetProfiler(Profiler* profiler) {
Ben Murdochb0fe1622011-05-05 13:52:32 +0100216 ASSERT(profiler_ == NULL);
Steve Blocka7e24c12009-10-30 11:49:00 +0000217 profiler_ = profiler;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100218 IncreaseProfilingDepth();
Steve Blocka7e24c12009-10-30 11:49:00 +0000219 if (!FLAG_prof_lazy && !IsActive()) Start();
220 }
221
222 void ClearProfiler() {
Ben Murdochb0fe1622011-05-05 13:52:32 +0100223 DecreaseProfilingDepth();
Steve Blocka7e24c12009-10-30 11:49:00 +0000224 profiler_ = NULL;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100225 if (!window_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
Steve Blocka7e24c12009-10-30 11:49:00 +0000226 }
227
Shimeng (Simon) Wang8a31eba2010-12-06 19:01:33 -0800228 protected:
229 virtual void DoSampleStack(TickSample* sample) {
Steve Block44f0eee2011-05-26 01:26:41 +0100230 StackTracer::Trace(isolate(), sample);
Shimeng (Simon) Wang8a31eba2010-12-06 19:01:33 -0800231 }
232
Steve Blocka7e24c12009-10-30 11:49:00 +0000233 private:
234 SlidingStateWindow* window_;
235 Profiler* profiler_;
236};
237
238
239//
240// SlidingStateWindow implementation.
241//
Steve Block44f0eee2011-05-26 01:26:41 +0100242SlidingStateWindow::SlidingStateWindow(Isolate* isolate)
243 : counters_(isolate->counters()), current_index_(0), is_full_(false) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000244 for (int i = 0; i < kBufferSize; i++) {
245 buffer_[i] = static_cast<byte>(OTHER);
246 }
Steve Block44f0eee2011-05-26 01:26:41 +0100247 isolate->logger()->ticker_->SetWindow(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000248}
249
250
251SlidingStateWindow::~SlidingStateWindow() {
Steve Block44f0eee2011-05-26 01:26:41 +0100252 LOGGER->ticker_->ClearWindow();
Steve Blocka7e24c12009-10-30 11:49:00 +0000253}
254
255
256void SlidingStateWindow::AddState(StateTag state) {
257 if (is_full_) {
258 DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
259 } else if (current_index_ == kBufferSize - 1) {
260 is_full_ = true;
261 }
262 buffer_[current_index_] = static_cast<byte>(state);
263 IncrementStateCounter(state);
264 ASSERT(IsPowerOf2(kBufferSize));
265 current_index_ = (current_index_ + 1) & (kBufferSize - 1);
266}
267
268
269//
270// Profiler implementation.
271//
Steve Block44f0eee2011-05-26 01:26:41 +0100272Profiler::Profiler(Isolate* isolate)
273 : Thread(isolate, "v8:Profiler"),
Steve Block9fac8402011-05-12 15:51:54 +0100274 head_(0),
Steve Blockd0582a62009-12-15 09:54:21 +0000275 tail_(0),
276 overflow_(false),
277 buffer_semaphore_(OS::CreateSemaphore(0)),
278 engaged_(false),
Steve Block44f0eee2011-05-26 01:26:41 +0100279 running_(false),
280 paused_(false) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000281}
282
283
284void Profiler::Engage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000285 if (engaged_) return;
286 engaged_ = true;
287
288 // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
289 // http://code.google.com/p/v8/issues/detail?id=487
290 if (!FLAG_prof_lazy) {
291 OS::LogSharedLibraryAddresses();
292 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000293
294 // Start thread processing the profiler buffer.
295 running_ = true;
296 Start();
297
298 // Register to get ticks.
Steve Block44f0eee2011-05-26 01:26:41 +0100299 LOGGER->ticker_->SetProfiler(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000300
Steve Block44f0eee2011-05-26 01:26:41 +0100301 LOGGER->ProfilerBeginEvent();
Steve Blocka7e24c12009-10-30 11:49:00 +0000302}
303
304
305void Profiler::Disengage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000306 if (!engaged_) return;
307
Steve Blocka7e24c12009-10-30 11:49:00 +0000308 // Stop receiving ticks.
Steve Block44f0eee2011-05-26 01:26:41 +0100309 LOGGER->ticker_->ClearProfiler();
Steve Blocka7e24c12009-10-30 11:49:00 +0000310
311 // Terminate the worker thread by setting running_ to false,
312 // inserting a fake element in the queue and then wait for
313 // the thread to terminate.
314 running_ = false;
315 TickSample sample;
316 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
317 resume();
318 Insert(&sample);
319 Join();
320
Steve Block44f0eee2011-05-26 01:26:41 +0100321 LOG(ISOLATE, UncheckedStringEvent("profiler", "end"));
Steve Blocka7e24c12009-10-30 11:49:00 +0000322}
323
324
325void Profiler::Run() {
326 TickSample sample;
Steve Block8defd9f2010-07-08 12:39:36 +0100327 bool overflow = Remove(&sample);
Steve Block44f0eee2011-05-26 01:26:41 +0100328 i::Isolate* isolate = ISOLATE;
Steve Blocka7e24c12009-10-30 11:49:00 +0000329 while (running_) {
Steve Block44f0eee2011-05-26 01:26:41 +0100330 LOG(isolate, TickEvent(&sample, overflow));
Steve Block8defd9f2010-07-08 12:39:36 +0100331 overflow = Remove(&sample);
Steve Blocka7e24c12009-10-30 11:49:00 +0000332 }
333}
334
335
336//
337// Logger class implementation.
338//
Steve Block44f0eee2011-05-26 01:26:41 +0100339
340Logger::Logger()
341 : ticker_(NULL),
342 profiler_(NULL),
343 sliding_state_window_(NULL),
344 log_events_(NULL),
345 logging_nesting_(0),
346 cpu_profiler_nesting_(0),
347 heap_profiler_nesting_(0),
348 log_(new Log(this)),
349 is_initialized_(false),
350 last_address_(NULL),
351 prev_sp_(NULL),
352 prev_function_(NULL),
353 prev_to_(NULL),
354 prev_code_(NULL) {
355}
356
357Logger::~Logger() {
358 delete log_;
359}
Steve Blocka7e24c12009-10-30 11:49:00 +0000360
Ben Murdochb0fe1622011-05-05 13:52:32 +0100361#define DECLARE_EVENT(ignore1, name) name,
Steve Block44f0eee2011-05-26 01:26:41 +0100362static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
Ben Murdochb0fe1622011-05-05 13:52:32 +0100363 LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
Steve Blocka7e24c12009-10-30 11:49:00 +0000364};
Ben Murdochb0fe1622011-05-05 13:52:32 +0100365#undef DECLARE_EVENT
Steve Blocka7e24c12009-10-30 11:49:00 +0000366
367
368void Logger::ProfilerBeginEvent() {
Steve Block44f0eee2011-05-26 01:26:41 +0100369 if (!log_->IsEnabled()) return;
370 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000371 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
Steve Blocka7e24c12009-10-30 11:49:00 +0000372 msg.WriteToLogFile();
373}
374
375#endif // ENABLE_LOGGING_AND_PROFILING
376
377
Steve Blocka7e24c12009-10-30 11:49:00 +0000378void Logger::StringEvent(const char* name, const char* value) {
379#ifdef ENABLE_LOGGING_AND_PROFILING
380 if (FLAG_log) UncheckedStringEvent(name, value);
381#endif
382}
383
384
385#ifdef ENABLE_LOGGING_AND_PROFILING
386void Logger::UncheckedStringEvent(const char* name, const char* value) {
Steve Block44f0eee2011-05-26 01:26:41 +0100387 if (!log_->IsEnabled()) return;
388 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000389 msg.Append("%s,\"%s\"\n", name, value);
390 msg.WriteToLogFile();
391}
392#endif
393
394
395void Logger::IntEvent(const char* name, int value) {
396#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block6ded16b2010-05-10 14:33:55 +0100397 if (FLAG_log) UncheckedIntEvent(name, value);
398#endif
399}
400
401
Ben Murdochf87a2032010-10-22 12:50:53 +0100402void Logger::IntPtrTEvent(const char* name, intptr_t value) {
403#ifdef ENABLE_LOGGING_AND_PROFILING
404 if (FLAG_log) UncheckedIntPtrTEvent(name, value);
405#endif
406}
407
408
Steve Block6ded16b2010-05-10 14:33:55 +0100409#ifdef ENABLE_LOGGING_AND_PROFILING
410void Logger::UncheckedIntEvent(const char* name, int value) {
Steve Block44f0eee2011-05-26 01:26:41 +0100411 if (!log_->IsEnabled()) return;
412 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000413 msg.Append("%s,%d\n", name, value);
414 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000415}
Steve Block6ded16b2010-05-10 14:33:55 +0100416#endif
Steve Blocka7e24c12009-10-30 11:49:00 +0000417
418
Ben Murdochf87a2032010-10-22 12:50:53 +0100419#ifdef ENABLE_LOGGING_AND_PROFILING
420void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
Steve Block44f0eee2011-05-26 01:26:41 +0100421 if (!log_->IsEnabled()) return;
422 LogMessageBuilder msg(this);
Ben Murdochf87a2032010-10-22 12:50:53 +0100423 msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
424 msg.WriteToLogFile();
425}
426#endif
427
428
Steve Blocka7e24c12009-10-30 11:49:00 +0000429void Logger::HandleEvent(const char* name, Object** location) {
430#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100431 if (!log_->IsEnabled() || !FLAG_log_handles) return;
432 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000433 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
434 msg.WriteToLogFile();
435#endif
436}
437
438
439#ifdef ENABLE_LOGGING_AND_PROFILING
440// ApiEvent is private so all the calls come from the Logger class. It is the
441// caller's responsibility to ensure that log is enabled and that
442// FLAG_log_api is true.
443void Logger::ApiEvent(const char* format, ...) {
Steve Block44f0eee2011-05-26 01:26:41 +0100444 ASSERT(log_->IsEnabled() && FLAG_log_api);
445 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000446 va_list ap;
447 va_start(ap, format);
448 msg.AppendVA(format, ap);
449 va_end(ap);
450 msg.WriteToLogFile();
451}
452#endif
453
454
455void Logger::ApiNamedSecurityCheck(Object* key) {
456#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100457 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000458 if (key->IsString()) {
459 SmartPointer<char> str =
460 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
461 ApiEvent("api,check-security,\"%s\"\n", *str);
462 } else if (key->IsUndefined()) {
463 ApiEvent("api,check-security,undefined\n");
464 } else {
465 ApiEvent("api,check-security,['no-name']\n");
466 }
467#endif
468}
469
470
471void Logger::SharedLibraryEvent(const char* library_path,
472 uintptr_t start,
473 uintptr_t end) {
474#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100475 if (!log_->IsEnabled() || !FLAG_prof) return;
476 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000477 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
478 library_path,
479 start,
480 end);
481 msg.WriteToLogFile();
482#endif
483}
484
485
486void Logger::SharedLibraryEvent(const wchar_t* library_path,
487 uintptr_t start,
488 uintptr_t end) {
489#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100490 if (!log_->IsEnabled() || !FLAG_prof) return;
491 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000492 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
493 library_path,
494 start,
495 end);
496 msg.WriteToLogFile();
497#endif
498}
499
500
501#ifdef ENABLE_LOGGING_AND_PROFILING
502void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
503 // Prints "/" + re.source + "/" +
504 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
Steve Block44f0eee2011-05-26 01:26:41 +0100505 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000506
507 Handle<Object> source = GetProperty(regexp, "source");
508 if (!source->IsString()) {
509 msg.Append("no source");
510 return;
511 }
512
513 switch (regexp->TypeTag()) {
514 case JSRegExp::ATOM:
515 msg.Append('a');
516 break;
517 default:
518 break;
519 }
520 msg.Append('/');
521 msg.AppendDetailed(*Handle<String>::cast(source), false);
522 msg.Append('/');
523
524 // global flag
525 Handle<Object> global = GetProperty(regexp, "global");
526 if (global->IsTrue()) {
527 msg.Append('g');
528 }
529 // ignorecase flag
530 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
531 if (ignorecase->IsTrue()) {
532 msg.Append('i');
533 }
534 // multiline flag
535 Handle<Object> multiline = GetProperty(regexp, "multiline");
536 if (multiline->IsTrue()) {
537 msg.Append('m');
538 }
539
540 msg.WriteToLogFile();
541}
542#endif // ENABLE_LOGGING_AND_PROFILING
543
544
545void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
546#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100547 if (!log_->IsEnabled() || !FLAG_log_regexp) return;
548 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000549 msg.Append("regexp-compile,");
550 LogRegExpSource(regexp);
551 msg.Append(in_cache ? ",hit\n" : ",miss\n");
552 msg.WriteToLogFile();
553#endif
554}
555
556
557void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
558#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100559 if (!log_->IsEnabled() || !FLAG_log_runtime) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000560 HandleScope scope;
Steve Block44f0eee2011-05-26 01:26:41 +0100561 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000562 for (int i = 0; i < format.length(); i++) {
563 char c = format[i];
564 if (c == '%' && i <= format.length() - 2) {
565 i++;
566 ASSERT('0' <= format[i] && format[i] <= '9');
John Reck59135872010-11-02 12:39:01 -0700567 MaybeObject* maybe = args->GetElement(format[i] - '0');
568 Object* obj;
569 if (!maybe->ToObject(&obj)) {
570 msg.Append("<exception>");
571 continue;
572 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000573 i++;
574 switch (format[i]) {
575 case 's':
576 msg.AppendDetailed(String::cast(obj), false);
577 break;
578 case 'S':
579 msg.AppendDetailed(String::cast(obj), true);
580 break;
581 case 'r':
582 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
583 break;
584 case 'x':
585 msg.Append("0x%x", Smi::cast(obj)->value());
586 break;
587 case 'i':
588 msg.Append("%i", Smi::cast(obj)->value());
589 break;
590 default:
591 UNREACHABLE();
592 }
593 } else {
594 msg.Append(c);
595 }
596 }
597 msg.Append('\n');
598 msg.WriteToLogFile();
599#endif
600}
601
602
603void Logger::ApiIndexedSecurityCheck(uint32_t index) {
604#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100605 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000606 ApiEvent("api,check-security,%u\n", index);
607#endif
608}
609
610
611void Logger::ApiNamedPropertyAccess(const char* tag,
612 JSObject* holder,
613 Object* name) {
614#ifdef ENABLE_LOGGING_AND_PROFILING
615 ASSERT(name->IsString());
Steve Block44f0eee2011-05-26 01:26:41 +0100616 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000617 String* class_name_obj = holder->class_name();
618 SmartPointer<char> class_name =
619 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
620 SmartPointer<char> property_name =
621 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Steve Block44f0eee2011-05-26 01:26:41 +0100622 ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
Steve Blocka7e24c12009-10-30 11:49:00 +0000623#endif
624}
625
626void Logger::ApiIndexedPropertyAccess(const char* tag,
627 JSObject* holder,
628 uint32_t index) {
629#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100630 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000631 String* class_name_obj = holder->class_name();
632 SmartPointer<char> class_name =
633 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Steve Block44f0eee2011-05-26 01:26:41 +0100634 ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
Steve Blocka7e24c12009-10-30 11:49:00 +0000635#endif
636}
637
638void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
639#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100640 if (!log_->IsEnabled() || !FLAG_log_api) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000641 String* class_name_obj = object->class_name();
642 SmartPointer<char> class_name =
643 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Steve Block44f0eee2011-05-26 01:26:41 +0100644 ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
Steve Blocka7e24c12009-10-30 11:49:00 +0000645#endif
646}
647
648
649void Logger::ApiEntryCall(const char* name) {
650#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100651 if (!log_->IsEnabled() || !FLAG_log_api) return;
652 ApiEvent("api,%s\n", name);
Steve Blocka7e24c12009-10-30 11:49:00 +0000653#endif
654}
655
656
657void Logger::NewEvent(const char* name, void* object, size_t size) {
658#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100659 if (!log_->IsEnabled() || !FLAG_log) return;
660 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000661 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
662 static_cast<unsigned int>(size));
663 msg.WriteToLogFile();
664#endif
665}
666
667
668void Logger::DeleteEvent(const char* name, void* object) {
669#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100670 if (!log_->IsEnabled() || !FLAG_log) return;
671 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000672 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
673 msg.WriteToLogFile();
674#endif
675}
676
677
Steve Block44f0eee2011-05-26 01:26:41 +0100678void Logger::NewEventStatic(const char* name, void* object, size_t size) {
679 LOGGER->NewEvent(name, object, size);
680}
681
682
683void Logger::DeleteEventStatic(const char* name, void* object) {
684 LOGGER->DeleteEvent(name, object);
685}
686
Steve Blocka7e24c12009-10-30 11:49:00 +0000687#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Blockd0582a62009-12-15 09:54:21 +0000688void Logger::CallbackEventInternal(const char* prefix, const char* name,
689 Address entry_point) {
Steve Block44f0eee2011-05-26 01:26:41 +0100690 if (!log_->IsEnabled() || !FLAG_log_code) return;
691 LogMessageBuilder msg(this);
Steve Blockd0582a62009-12-15 09:54:21 +0000692 msg.Append("%s,%s,",
Ben Murdochb0fe1622011-05-05 13:52:32 +0100693 kLogEventsNames[CODE_CREATION_EVENT],
694 kLogEventsNames[CALLBACK_TAG]);
Steve Blockd0582a62009-12-15 09:54:21 +0000695 msg.AppendAddress(entry_point);
696 msg.Append(",1,\"%s%s\"", prefix, name);
Steve Blockd0582a62009-12-15 09:54:21 +0000697 msg.Append('\n');
698 msg.WriteToLogFile();
699}
700#endif
701
702
703void Logger::CallbackEvent(String* name, Address entry_point) {
704#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100705 if (!log_->IsEnabled() || !FLAG_log_code) return;
Steve Blockd0582a62009-12-15 09:54:21 +0000706 SmartPointer<char> str =
707 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
708 CallbackEventInternal("", *str, entry_point);
709#endif
710}
711
712
713void Logger::GetterCallbackEvent(String* name, Address entry_point) {
714#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100715 if (!log_->IsEnabled() || !FLAG_log_code) return;
Steve Blockd0582a62009-12-15 09:54:21 +0000716 SmartPointer<char> str =
717 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
718 CallbackEventInternal("get ", *str, entry_point);
719#endif
720}
721
722
723void Logger::SetterCallbackEvent(String* name, Address entry_point) {
724#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100725 if (!log_->IsEnabled() || !FLAG_log_code) return;
Steve Blockd0582a62009-12-15 09:54:21 +0000726 SmartPointer<char> str =
727 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
728 CallbackEventInternal("set ", *str, entry_point);
729#endif
730}
731
732
Steve Blocka7e24c12009-10-30 11:49:00 +0000733void Logger::CodeCreateEvent(LogEventsAndTags tag,
734 Code* code,
735 const char* comment) {
736#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100737 if (!log_->IsEnabled() || !FLAG_log_code) return;
738 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100739 msg.Append("%s,%s,",
740 kLogEventsNames[CODE_CREATION_EVENT],
741 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000742 msg.AppendAddress(code->address());
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100743 msg.Append(",%d,\"", code->ExecutableSize());
Steve Blocka7e24c12009-10-30 11:49:00 +0000744 for (const char* p = comment; *p != '\0'; p++) {
745 if (*p == '"') {
746 msg.Append('\\');
747 }
748 msg.Append(*p);
749 }
750 msg.Append('"');
Ben Murdochf87a2032010-10-22 12:50:53 +0100751 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000752 msg.Append('\n');
753 msg.WriteToLogFile();
754#endif
755}
756
757
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100758void Logger::CodeCreateEvent(LogEventsAndTags tag,
759 Code* code,
760 String* name) {
761#ifdef ENABLE_LOGGING_AND_PROFILING
762 if (name != NULL) {
763 SmartPointer<char> str =
764 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
765 CodeCreateEvent(tag, code, *str);
766 } else {
767 CodeCreateEvent(tag, code, "");
768 }
769#endif
770}
771
772
773#ifdef ENABLE_LOGGING_AND_PROFILING
774// ComputeMarker must only be used when SharedFunctionInfo is known.
775static const char* ComputeMarker(Code* code) {
776 switch (code->kind()) {
777 case Code::FUNCTION: return code->optimizable() ? "~" : "";
778 case Code::OPTIMIZED_FUNCTION: return "*";
779 default: return "";
780 }
781}
782#endif
783
784
785void Logger::CodeCreateEvent(LogEventsAndTags tag,
786 Code* code,
787 SharedFunctionInfo* shared,
788 String* name) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000789#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100790 if (!log_->IsEnabled() || !FLAG_log_code) return;
791 if (code == Isolate::Current()->builtins()->builtin(
792 Builtins::kLazyCompile))
793 return;
794
795 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000796 SmartPointer<char> str =
797 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100798 msg.Append("%s,%s,",
799 kLogEventsNames[CODE_CREATION_EVENT],
800 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000801 msg.AppendAddress(code->address());
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100802 msg.Append(",%d,\"%s\",", code->ExecutableSize(), *str);
803 msg.AppendAddress(shared->address());
804 msg.Append(",%s", ComputeMarker(code));
Ben Murdochf87a2032010-10-22 12:50:53 +0100805 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000806 msg.Append('\n');
807 msg.WriteToLogFile();
808#endif
809}
810
811
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100812// Although, it is possible to extract source and line from
813// the SharedFunctionInfo object, we left it to caller
814// to leave logging functions free from heap allocations.
Steve Blocka7e24c12009-10-30 11:49:00 +0000815void Logger::CodeCreateEvent(LogEventsAndTags tag,
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100816 Code* code,
817 SharedFunctionInfo* shared,
Steve Blocka7e24c12009-10-30 11:49:00 +0000818 String* source, int line) {
819#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100820 if (!log_->IsEnabled() || !FLAG_log_code) return;
821 LogMessageBuilder msg(this);
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100822 SmartPointer<char> name =
823 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Steve Blocka7e24c12009-10-30 11:49:00 +0000824 SmartPointer<char> sourcestr =
825 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100826 msg.Append("%s,%s,",
827 kLogEventsNames[CODE_CREATION_EVENT],
828 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000829 msg.AppendAddress(code->address());
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100830 msg.Append(",%d,\"%s %s:%d\",",
Ben Murdochb0fe1622011-05-05 13:52:32 +0100831 code->ExecutableSize(),
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100832 *name,
Ben Murdochb0fe1622011-05-05 13:52:32 +0100833 *sourcestr,
834 line);
Ben Murdoche0cee9b2011-05-25 10:26:03 +0100835 msg.AppendAddress(shared->address());
836 msg.Append(",%s", ComputeMarker(code));
Ben Murdochf87a2032010-10-22 12:50:53 +0100837 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000838 msg.Append('\n');
839 msg.WriteToLogFile();
840#endif
841}
842
843
844void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
845#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100846 if (!log_->IsEnabled() || !FLAG_log_code) return;
847 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100848 msg.Append("%s,%s,",
849 kLogEventsNames[CODE_CREATION_EVENT],
850 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000851 msg.AppendAddress(code->address());
852 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
Ben Murdochf87a2032010-10-22 12:50:53 +0100853 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000854 msg.Append('\n');
855 msg.WriteToLogFile();
856#endif
857}
858
859
Ben Murdochf87a2032010-10-22 12:50:53 +0100860void Logger::CodeMovingGCEvent() {
861#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100862 if (!log_->IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
863 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100864 msg.Append("%s\n", kLogEventsNames[CODE_MOVING_GC]);
Ben Murdochf87a2032010-10-22 12:50:53 +0100865 msg.WriteToLogFile();
866 OS::SignalCodeMovingGC();
867#endif
868}
869
870
Steve Blocka7e24c12009-10-30 11:49:00 +0000871void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
872#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100873 if (!log_->IsEnabled() || !FLAG_log_code) return;
874 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000875 msg.Append("%s,%s,",
Ben Murdochb0fe1622011-05-05 13:52:32 +0100876 kLogEventsNames[CODE_CREATION_EVENT],
877 kLogEventsNames[REG_EXP_TAG]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000878 msg.AppendAddress(code->address());
879 msg.Append(",%d,\"", code->ExecutableSize());
880 msg.AppendDetailed(source, false);
881 msg.Append('\"');
Ben Murdochf87a2032010-10-22 12:50:53 +0100882 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000883 msg.Append('\n');
884 msg.WriteToLogFile();
885#endif
886}
887
888
889void Logger::CodeMoveEvent(Address from, Address to) {
890#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000891 MoveEventInternal(CODE_MOVE_EVENT, from, to);
Steve Blocka7e24c12009-10-30 11:49:00 +0000892#endif
893}
894
895
896void Logger::CodeDeleteEvent(Address from) {
897#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000898 DeleteEventInternal(CODE_DELETE_EVENT, from);
Steve Blocka7e24c12009-10-30 11:49:00 +0000899#endif
900}
901
902
Leon Clarkee46be812010-01-19 14:06:41 +0000903void Logger::SnapshotPositionEvent(Address addr, int pos) {
904#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100905 if (!log_->IsEnabled() || !FLAG_log_snapshot_positions) return;
906 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100907 msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
Leon Clarkee46be812010-01-19 14:06:41 +0000908 msg.AppendAddress(addr);
909 msg.Append(",%d", pos);
Leon Clarkee46be812010-01-19 14:06:41 +0000910 msg.Append('\n');
911 msg.WriteToLogFile();
912#endif
913}
914
915
Steve Block44f0eee2011-05-26 01:26:41 +0100916void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
Leon Clarked91b9f72010-01-27 17:25:45 +0000917#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100918 MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to);
Leon Clarked91b9f72010-01-27 17:25:45 +0000919#endif
920}
921
922
923#ifdef ENABLE_LOGGING_AND_PROFILING
924void Logger::MoveEventInternal(LogEventsAndTags event,
925 Address from,
926 Address to) {
Steve Block44f0eee2011-05-26 01:26:41 +0100927 if (!log_->IsEnabled() || !FLAG_log_code) return;
928 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100929 msg.Append("%s,", kLogEventsNames[event]);
Leon Clarked91b9f72010-01-27 17:25:45 +0000930 msg.AppendAddress(from);
931 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +0100932 msg.AppendAddress(to);
Leon Clarked91b9f72010-01-27 17:25:45 +0000933 msg.Append('\n');
934 msg.WriteToLogFile();
935}
936#endif
937
938
939#ifdef ENABLE_LOGGING_AND_PROFILING
940void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
Steve Block44f0eee2011-05-26 01:26:41 +0100941 if (!log_->IsEnabled() || !FLAG_log_code) return;
942 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100943 msg.Append("%s,", kLogEventsNames[event]);
Leon Clarked91b9f72010-01-27 17:25:45 +0000944 msg.AppendAddress(from);
Leon Clarked91b9f72010-01-27 17:25:45 +0000945 msg.Append('\n');
946 msg.WriteToLogFile();
947}
948#endif
949
950
Steve Blocka7e24c12009-10-30 11:49:00 +0000951void Logger::ResourceEvent(const char* name, const char* tag) {
952#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100953 if (!log_->IsEnabled() || !FLAG_log) return;
954 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000955 msg.Append("%s,%s,", name, tag);
956
957 uint32_t sec, usec;
958 if (OS::GetUserTime(&sec, &usec) != -1) {
959 msg.Append("%d,%d,", sec, usec);
960 }
961 msg.Append("%.0f", OS::TimeCurrentMillis());
962
963 msg.Append('\n');
964 msg.WriteToLogFile();
965#endif
966}
967
968
969void Logger::SuspectReadEvent(String* name, Object* obj) {
970#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100971 if (!log_->IsEnabled() || !FLAG_log_suspect) return;
972 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000973 String* class_name = obj->IsJSObject()
974 ? JSObject::cast(obj)->class_name()
Steve Block44f0eee2011-05-26 01:26:41 +0100975 : HEAP->empty_string();
Steve Blocka7e24c12009-10-30 11:49:00 +0000976 msg.Append("suspect-read,");
977 msg.Append(class_name);
978 msg.Append(',');
979 msg.Append('"');
980 msg.Append(name);
981 msg.Append('"');
982 msg.Append('\n');
983 msg.WriteToLogFile();
984#endif
985}
986
987
988void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
989#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +0100990 if (!log_->IsEnabled() || !FLAG_log_gc) return;
991 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +0000992 // Using non-relative system time in order to be able to synchronize with
993 // external memory profiling events (e.g. DOM memory size).
994 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
995 space, kind, OS::TimeCurrentMillis());
996 msg.WriteToLogFile();
997#endif
998}
999
1000
1001void Logger::HeapSampleStats(const char* space, const char* kind,
Ben Murdochf87a2032010-10-22 12:50:53 +01001002 intptr_t capacity, intptr_t used) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001003#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001004 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1005 LogMessageBuilder msg(this);
Ben Murdochf87a2032010-10-22 12:50:53 +01001006 msg.Append("heap-sample-stats,\"%s\",\"%s\","
1007 "%" V8_PTR_PREFIX "d,%" V8_PTR_PREFIX "d\n",
Steve Blocka7e24c12009-10-30 11:49:00 +00001008 space, kind, capacity, used);
1009 msg.WriteToLogFile();
1010#endif
1011}
1012
1013
1014void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
1015#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001016 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1017 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001018 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1019 msg.WriteToLogFile();
1020#endif
1021}
1022
1023
1024void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1025#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001026 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1027 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001028 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1029 msg.WriteToLogFile();
1030#endif
1031}
1032
1033
1034void Logger::HeapSampleJSConstructorEvent(const char* constructor,
1035 int number, int bytes) {
1036#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001037 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1038 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001039 msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
1040 msg.WriteToLogFile();
1041#endif
1042}
1043
Steve Block44f0eee2011-05-26 01:26:41 +01001044// Event starts with comma, so we don't have it in the format string.
1045static const char kEventText[] = "heap-js-ret-item,%s";
1046// We take placeholder strings into account, but it's OK to be conservative.
1047static const int kEventTextLen = sizeof(kEventText)/sizeof(kEventText[0]);
Steve Blocka7e24c12009-10-30 11:49:00 +00001048
1049void Logger::HeapSampleJSRetainersEvent(
1050 const char* constructor, const char* event) {
1051#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001052 if (!log_->IsEnabled() || !FLAG_log_gc) return;
Steve Blockd0582a62009-12-15 09:54:21 +00001053 const int cons_len = StrLength(constructor);
1054 const int event_len = StrLength(event);
Steve Blocka7e24c12009-10-30 11:49:00 +00001055 int pos = 0;
1056 // Retainer lists can be long. We may need to split them into multiple events.
1057 do {
Steve Block44f0eee2011-05-26 01:26:41 +01001058 LogMessageBuilder msg(this);
1059 msg.Append(kEventText, constructor);
Steve Blocka7e24c12009-10-30 11:49:00 +00001060 int to_write = event_len - pos;
Steve Block44f0eee2011-05-26 01:26:41 +01001061 if (to_write > Log::kMessageBufferSize - (cons_len + kEventTextLen)) {
1062 int cut_pos = pos + Log::kMessageBufferSize - (cons_len + kEventTextLen);
Steve Blocka7e24c12009-10-30 11:49:00 +00001063 ASSERT(cut_pos < event_len);
1064 while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
1065 if (event[cut_pos] != ',') {
1066 // Crash in debug mode, skip in release mode.
1067 ASSERT(false);
1068 return;
1069 }
1070 // Append a piece of event that fits, without trailing comma.
1071 msg.AppendStringPart(event + pos, cut_pos - pos);
1072 // Start next piece with comma.
1073 pos = cut_pos;
1074 } else {
1075 msg.Append("%s", event + pos);
1076 pos += event_len;
1077 }
1078 msg.Append('\n');
1079 msg.WriteToLogFile();
1080 } while (pos < event_len);
1081#endif
1082}
1083
1084
Steve Block3ce2e202009-11-05 08:53:23 +00001085void Logger::HeapSampleJSProducerEvent(const char* constructor,
1086 Address* stack) {
1087#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001088 if (!log_->IsEnabled() || !FLAG_log_gc) return;
1089 LogMessageBuilder msg(this);
Steve Block3ce2e202009-11-05 08:53:23 +00001090 msg.Append("heap-js-prod-item,%s", constructor);
1091 while (*stack != NULL) {
1092 msg.Append(",0x%" V8PRIxPTR, *stack++);
1093 }
1094 msg.Append("\n");
1095 msg.WriteToLogFile();
1096#endif
1097}
1098
1099
Steve Blocka7e24c12009-10-30 11:49:00 +00001100void Logger::DebugTag(const char* call_site_tag) {
1101#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001102 if (!log_->IsEnabled() || !FLAG_log) return;
1103 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001104 msg.Append("debug-tag,%s\n", call_site_tag);
1105 msg.WriteToLogFile();
1106#endif
1107}
1108
1109
1110void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1111#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001112 if (!log_->IsEnabled() || !FLAG_log) return;
Steve Blocka7e24c12009-10-30 11:49:00 +00001113 StringBuilder s(parameter.length() + 1);
1114 for (int i = 0; i < parameter.length(); ++i) {
1115 s.AddCharacter(static_cast<char>(parameter[i]));
1116 }
1117 char* parameter_string = s.Finalize();
Steve Block44f0eee2011-05-26 01:26:41 +01001118 LogMessageBuilder msg(this);
Steve Blocka7e24c12009-10-30 11:49:00 +00001119 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1120 event_type,
1121 OS::TimeCurrentMillis(),
1122 parameter_string);
1123 DeleteArray(parameter_string);
1124 msg.WriteToLogFile();
1125#endif
1126}
1127
1128
1129#ifdef ENABLE_LOGGING_AND_PROFILING
1130void Logger::TickEvent(TickSample* sample, bool overflow) {
Steve Block44f0eee2011-05-26 01:26:41 +01001131 if (!log_->IsEnabled() || !FLAG_prof) return;
1132 LogMessageBuilder msg(this);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001133 msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
1134 msg.AppendAddress(sample->pc);
Steve Blocka7e24c12009-10-30 11:49:00 +00001135 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +01001136 msg.AppendAddress(sample->sp);
Steve Block44f0eee2011-05-26 01:26:41 +01001137 if (sample->has_external_callback) {
1138 msg.Append(",1,");
1139 msg.AppendAddress(sample->external_callback);
1140 } else {
1141 msg.Append(",0,");
1142 msg.AppendAddress(sample->tos);
1143 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001144 msg.Append(",%d", static_cast<int>(sample->state));
1145 if (overflow) {
1146 msg.Append(",overflow");
1147 }
1148 for (int i = 0; i < sample->frames_count; ++i) {
1149 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +01001150 msg.AppendAddress(sample->stack[i]);
Steve Blocka7e24c12009-10-30 11:49:00 +00001151 }
1152 msg.Append('\n');
1153 msg.WriteToLogFile();
1154}
1155
1156
1157int Logger::GetActiveProfilerModules() {
1158 int result = PROFILER_MODULE_NONE;
Steve Block8defd9f2010-07-08 12:39:36 +01001159 if (profiler_ != NULL && !profiler_->paused()) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001160 result |= PROFILER_MODULE_CPU;
1161 }
1162 if (FLAG_log_gc) {
1163 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1164 }
1165 return result;
1166}
1167
1168
Andrei Popescu402d9372010-02-26 13:31:12 +00001169void Logger::PauseProfiler(int flags, int tag) {
Steve Block44f0eee2011-05-26 01:26:41 +01001170 if (!log_->IsEnabled()) return;
Steve Block8defd9f2010-07-08 12:39:36 +01001171 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001172 // It is OK to have negative nesting.
1173 if (--cpu_profiler_nesting_ == 0) {
1174 profiler_->pause();
1175 if (FLAG_prof_lazy) {
Ben Murdochb0fe1622011-05-05 13:52:32 +01001176 if (!FLAG_sliding_state_window && !RuntimeProfiler::IsEnabled()) {
1177 ticker_->Stop();
1178 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001179 FLAG_log_code = false;
1180 // Must be the same message as Log::kDynamicBufferSeal.
Steve Block44f0eee2011-05-26 01:26:41 +01001181 LOG(ISOLATE, UncheckedStringEvent("profiler", "pause"));
Andrei Popescu402d9372010-02-26 13:31:12 +00001182 }
Steve Block6ded16b2010-05-10 14:33:55 +01001183 --logging_nesting_;
Steve Blocka7e24c12009-10-30 11:49:00 +00001184 }
1185 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001186 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001187 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001188 if (--heap_profiler_nesting_ == 0) {
1189 FLAG_log_gc = false;
Steve Block6ded16b2010-05-10 14:33:55 +01001190 --logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001191 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001192 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001193 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001194 UncheckedIntEvent("close-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001195 }
1196}
1197
1198
Andrei Popescu402d9372010-02-26 13:31:12 +00001199void Logger::ResumeProfiler(int flags, int tag) {
Steve Block44f0eee2011-05-26 01:26:41 +01001200 if (!log_->IsEnabled()) return;
Andrei Popescu402d9372010-02-26 13:31:12 +00001201 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001202 UncheckedIntEvent("open-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001203 }
Steve Block8defd9f2010-07-08 12:39:36 +01001204 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001205 if (cpu_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001206 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001207 if (FLAG_prof_lazy) {
1208 profiler_->Engage();
Steve Block44f0eee2011-05-26 01:26:41 +01001209 LOG(ISOLATE, UncheckedStringEvent("profiler", "resume"));
Andrei Popescu402d9372010-02-26 13:31:12 +00001210 FLAG_log_code = true;
1211 LogCompiledFunctions();
Andrei Popescu402d9372010-02-26 13:31:12 +00001212 LogAccessorCallbacks();
Ben Murdochb0fe1622011-05-05 13:52:32 +01001213 if (!FLAG_sliding_state_window && !ticker_->IsActive()) {
1214 ticker_->Start();
1215 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001216 }
1217 profiler_->resume();
Steve Blocka7e24c12009-10-30 11:49:00 +00001218 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001219 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001220 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001221 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001222 if (heap_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001223 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001224 FLAG_log_gc = true;
1225 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001226 }
1227}
1228
1229
1230// This function can be called when Log's mutex is acquired,
1231// either from main or Profiler's thread.
Steve Block44f0eee2011-05-26 01:26:41 +01001232void Logger::LogFailure() {
Andrei Popescu402d9372010-02-26 13:31:12 +00001233 PauseProfiler(PROFILER_MODULE_CPU, 0);
Steve Blocka7e24c12009-10-30 11:49:00 +00001234}
1235
1236
1237bool Logger::IsProfilerSamplerActive() {
1238 return ticker_->IsActive();
1239}
1240
1241
1242int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
Steve Block44f0eee2011-05-26 01:26:41 +01001243 return log_->GetLogLines(from_pos, dest_buf, max_size);
Steve Blocka7e24c12009-10-30 11:49:00 +00001244}
1245
1246
Ben Murdochb0fe1622011-05-05 13:52:32 +01001247class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1248 public:
1249 EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1250 Handle<Code>* code_objects,
1251 int* count)
1252 : sfis_(sfis), code_objects_(code_objects), count_(count) { }
1253
1254 virtual void EnterContext(Context* context) {}
1255 virtual void LeaveContext(Context* context) {}
1256
1257 virtual void VisitFunction(JSFunction* function) {
1258 if (sfis_ != NULL) {
1259 sfis_[*count_] = Handle<SharedFunctionInfo>(function->shared());
1260 }
1261 if (code_objects_ != NULL) {
1262 ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
1263 code_objects_[*count_] = Handle<Code>(function->code());
1264 }
1265 *count_ = *count_ + 1;
1266 }
1267
1268 private:
1269 Handle<SharedFunctionInfo>* sfis_;
1270 Handle<Code>* code_objects_;
1271 int* count_;
1272};
1273
1274
1275static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis,
1276 Handle<Code>* code_objects) {
Steve Block3ce2e202009-11-05 08:53:23 +00001277 AssertNoAllocation no_alloc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001278 int compiled_funcs_count = 0;
Ben Murdochb0fe1622011-05-05 13:52:32 +01001279
1280 // Iterate the heap to find shared function info objects and record
1281 // the unoptimized code for them.
Steve Block3ce2e202009-11-05 08:53:23 +00001282 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001283 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Block3ce2e202009-11-05 08:53:23 +00001284 if (!obj->IsSharedFunctionInfo()) continue;
1285 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1286 if (sfi->is_compiled()
1287 && (!sfi->script()->IsScript()
1288 || Script::cast(sfi->script())->HasValidSource())) {
Ben Murdochb0fe1622011-05-05 13:52:32 +01001289 if (sfis != NULL) {
Steve Block3ce2e202009-11-05 08:53:23 +00001290 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001291 }
1292 if (code_objects != NULL) {
1293 code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
1294 }
Steve Block3ce2e202009-11-05 08:53:23 +00001295 ++compiled_funcs_count;
Steve Blocka7e24c12009-10-30 11:49:00 +00001296 }
1297 }
Ben Murdochb0fe1622011-05-05 13:52:32 +01001298
1299 // Iterate all optimized functions in all contexts.
1300 EnumerateOptimizedFunctionsVisitor visitor(sfis,
1301 code_objects,
1302 &compiled_funcs_count);
1303 Deoptimizer::VisitAllOptimizedFunctions(&visitor);
1304
Steve Block3ce2e202009-11-05 08:53:23 +00001305 return compiled_funcs_count;
1306}
1307
1308
Steve Blockd0582a62009-12-15 09:54:21 +00001309void Logger::LogCodeObject(Object* object) {
1310 if (FLAG_log_code) {
1311 Code* code_object = Code::cast(object);
1312 LogEventsAndTags tag = Logger::STUB_TAG;
1313 const char* description = "Unknown code from the snapshot";
1314 switch (code_object->kind()) {
1315 case Code::FUNCTION:
Ben Murdochb0fe1622011-05-05 13:52:32 +01001316 case Code::OPTIMIZED_FUNCTION:
Steve Blockd0582a62009-12-15 09:54:21 +00001317 return; // We log this later using LogCompiledFunctions.
Ben Murdochb0fe1622011-05-05 13:52:32 +01001318 case Code::BINARY_OP_IC: // fall through
1319 case Code::TYPE_RECORDING_BINARY_OP_IC: // fall through
1320 case Code::COMPARE_IC: // fall through
Steve Blockd0582a62009-12-15 09:54:21 +00001321 case Code::STUB:
Kristian Monsen80d68ea2010-09-08 11:05:35 +01001322 description =
1323 CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
Andrei Popescu31002712010-02-23 13:46:05 +00001324 if (description == NULL)
1325 description = "A stub from the snapshot";
Steve Blockd0582a62009-12-15 09:54:21 +00001326 tag = Logger::STUB_TAG;
1327 break;
1328 case Code::BUILTIN:
1329 description = "A builtin from the snapshot";
1330 tag = Logger::BUILTIN_TAG;
1331 break;
1332 case Code::KEYED_LOAD_IC:
1333 description = "A keyed load IC from the snapshot";
1334 tag = Logger::KEYED_LOAD_IC_TAG;
1335 break;
Steve Block44f0eee2011-05-26 01:26:41 +01001336 case Code::KEYED_EXTERNAL_ARRAY_LOAD_IC:
1337 description = "A keyed external array load IC from the snapshot";
1338 tag = Logger::KEYED_EXTERNAL_ARRAY_LOAD_IC_TAG;
1339 break;
Steve Blockd0582a62009-12-15 09:54:21 +00001340 case Code::LOAD_IC:
1341 description = "A load IC from the snapshot";
1342 tag = Logger::LOAD_IC_TAG;
1343 break;
1344 case Code::STORE_IC:
1345 description = "A store IC from the snapshot";
1346 tag = Logger::STORE_IC_TAG;
1347 break;
1348 case Code::KEYED_STORE_IC:
1349 description = "A keyed store IC from the snapshot";
1350 tag = Logger::KEYED_STORE_IC_TAG;
1351 break;
Steve Block44f0eee2011-05-26 01:26:41 +01001352 case Code::KEYED_EXTERNAL_ARRAY_STORE_IC:
1353 description = "A keyed external array store IC from the snapshot";
1354 tag = Logger::KEYED_EXTERNAL_ARRAY_STORE_IC_TAG;
1355 break;
Steve Blockd0582a62009-12-15 09:54:21 +00001356 case Code::CALL_IC:
1357 description = "A call IC from the snapshot";
1358 tag = Logger::CALL_IC_TAG;
1359 break;
Ben Murdoch7f4d5bd2010-06-15 11:15:29 +01001360 case Code::KEYED_CALL_IC:
1361 description = "A keyed call IC from the snapshot";
1362 tag = Logger::KEYED_CALL_IC_TAG;
1363 break;
Steve Blockd0582a62009-12-15 09:54:21 +00001364 }
Steve Block44f0eee2011-05-26 01:26:41 +01001365 PROFILE(ISOLATE, CodeCreateEvent(tag, code_object, description));
Steve Blockd0582a62009-12-15 09:54:21 +00001366 }
1367}
1368
1369
Ben Murdochf87a2032010-10-22 12:50:53 +01001370void Logger::LogCodeInfo() {
1371#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001372 if (!log_->IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
Ben Murdochf87a2032010-10-22 12:50:53 +01001373#if V8_TARGET_ARCH_IA32
1374 const char arch[] = "ia32";
1375#elif V8_TARGET_ARCH_X64
1376 const char arch[] = "x64";
1377#elif V8_TARGET_ARCH_ARM
1378 const char arch[] = "arm";
1379#else
1380 const char arch[] = "unknown";
1381#endif
Steve Block44f0eee2011-05-26 01:26:41 +01001382 LogMessageBuilder msg(this);
Ben Murdochf87a2032010-10-22 12:50:53 +01001383 msg.Append("code-info,%s,%d\n", arch, Code::kHeaderSize);
1384 msg.WriteToLogFile();
1385#endif // ENABLE_LOGGING_AND_PROFILING
1386}
1387
1388
1389void Logger::LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg) {
Steve Block44f0eee2011-05-26 01:26:41 +01001390 if (!FLAG_ll_prof || log_->output_code_handle_ == NULL) return;
1391 int pos = static_cast<int>(ftell(log_->output_code_handle_));
John Reck59135872010-11-02 12:39:01 -07001392 size_t rv = fwrite(code->instruction_start(), 1, code->instruction_size(),
Steve Block44f0eee2011-05-26 01:26:41 +01001393 log_->output_code_handle_);
John Reck59135872010-11-02 12:39:01 -07001394 ASSERT(static_cast<size_t>(code->instruction_size()) == rv);
1395 USE(rv);
Ben Murdochf87a2032010-10-22 12:50:53 +01001396 msg->Append(",%d", pos);
1397}
1398
1399
Andrei Popescu31002712010-02-23 13:46:05 +00001400void Logger::LogCodeObjects() {
1401 AssertNoAllocation no_alloc;
1402 HeapIterator iterator;
1403 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1404 if (obj->IsCode()) LogCodeObject(obj);
1405 }
1406}
1407
1408
Steve Block3ce2e202009-11-05 08:53:23 +00001409void Logger::LogCompiledFunctions() {
1410 HandleScope scope;
Ben Murdochb0fe1622011-05-05 13:52:32 +01001411 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL, NULL);
Kristian Monsen25f61362010-05-21 11:50:48 +01001412 ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001413 ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
1414 EnumerateCompiledFunctions(sfis.start(), code_objects.start());
Steve Blocka7e24c12009-10-30 11:49:00 +00001415
1416 // During iteration, there can be heap allocation due to
1417 // GetScriptLineNumber call.
1418 for (int i = 0; i < compiled_funcs_count; ++i) {
Steve Block44f0eee2011-05-26 01:26:41 +01001419 if (*code_objects[i] == Isolate::Current()->builtins()->builtin(
1420 Builtins::kLazyCompile))
1421 continue;
Steve Blocka7e24c12009-10-30 11:49:00 +00001422 Handle<SharedFunctionInfo> shared = sfis[i];
Ben Murdoche0cee9b2011-05-25 10:26:03 +01001423 Handle<String> func_name(shared->DebugName());
Steve Blocka7e24c12009-10-30 11:49:00 +00001424 if (shared->script()->IsScript()) {
1425 Handle<Script> script(Script::cast(shared->script()));
1426 if (script->name()->IsString()) {
1427 Handle<String> script_name(String::cast(script->name()));
1428 int line_num = GetScriptLineNumber(script, shared->start_position());
1429 if (line_num > 0) {
Steve Block44f0eee2011-05-26 01:26:41 +01001430 PROFILE(ISOLATE,
1431 CodeCreateEvent(
1432 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1433 *code_objects[i], *shared,
1434 *script_name, line_num + 1));
Steve Blocka7e24c12009-10-30 11:49:00 +00001435 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001436 // Can't distinguish eval and script here, so always use Script.
Steve Block44f0eee2011-05-26 01:26:41 +01001437 PROFILE(ISOLATE,
1438 CodeCreateEvent(
1439 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
1440 *code_objects[i], *shared, *script_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001441 }
Steve Blockd0582a62009-12-15 09:54:21 +00001442 } else {
Steve Block44f0eee2011-05-26 01:26:41 +01001443 PROFILE(ISOLATE,
1444 CodeCreateEvent(
1445 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
1446 *code_objects[i], *shared, *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001447 }
Steve Block6ded16b2010-05-10 14:33:55 +01001448 } else if (shared->IsApiFunction()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001449 // API function.
Steve Block6ded16b2010-05-10 14:33:55 +01001450 FunctionTemplateInfo* fun_data = shared->get_api_func_data();
Steve Blockd0582a62009-12-15 09:54:21 +00001451 Object* raw_call_data = fun_data->call_code();
1452 if (!raw_call_data->IsUndefined()) {
1453 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1454 Object* callback_obj = call_data->callback();
1455 Address entry_point = v8::ToCData<Address>(callback_obj);
Steve Block44f0eee2011-05-26 01:26:41 +01001456 PROFILE(ISOLATE, CallbackEvent(*func_name, entry_point));
Steve Blockd0582a62009-12-15 09:54:21 +00001457 }
1458 } else {
Steve Block44f0eee2011-05-26 01:26:41 +01001459 PROFILE(ISOLATE,
1460 CodeCreateEvent(
1461 Logger::LAZY_COMPILE_TAG, *code_objects[i],
1462 *shared, *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001463 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001464 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001465}
1466
Steve Blockd0582a62009-12-15 09:54:21 +00001467
1468void Logger::LogAccessorCallbacks() {
1469 AssertNoAllocation no_alloc;
1470 HeapIterator iterator;
Steve Block44f0eee2011-05-26 01:26:41 +01001471 i::Isolate* isolate = ISOLATE;
Leon Clarked91b9f72010-01-27 17:25:45 +00001472 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001473 if (!obj->IsAccessorInfo()) continue;
1474 AccessorInfo* ai = AccessorInfo::cast(obj);
1475 if (!ai->name()->IsString()) continue;
1476 String* name = String::cast(ai->name());
1477 Address getter_entry = v8::ToCData<Address>(ai->getter());
1478 if (getter_entry != 0) {
Steve Block44f0eee2011-05-26 01:26:41 +01001479 PROFILE(isolate, GetterCallbackEvent(name, getter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001480 }
1481 Address setter_entry = v8::ToCData<Address>(ai->setter());
1482 if (setter_entry != 0) {
Steve Block44f0eee2011-05-26 01:26:41 +01001483 PROFILE(isolate, SetterCallbackEvent(name, setter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001484 }
1485 }
1486}
1487
Steve Blocka7e24c12009-10-30 11:49:00 +00001488#endif
1489
1490
1491bool Logger::Setup() {
1492#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001493 // Tests and EnsureInitialize() can call this twice in a row. It's harmless.
1494 if (is_initialized_) return true;
1495 is_initialized_ = true;
Steve Blocka7e24c12009-10-30 11:49:00 +00001496
Ben Murdochf87a2032010-10-22 12:50:53 +01001497 // --ll-prof implies --log-code and --log-snapshot-positions.
1498 if (FLAG_ll_prof) {
1499 FLAG_log_code = true;
1500 FLAG_log_snapshot_positions = true;
1501 }
1502
Steve Blocka7e24c12009-10-30 11:49:00 +00001503 // --prof_lazy controls --log-code, implies --noprof_auto.
1504 if (FLAG_prof_lazy) {
1505 FLAG_log_code = false;
1506 FLAG_prof_auto = false;
1507 }
1508
Steve Block44f0eee2011-05-26 01:26:41 +01001509 // TODO(isolates): this assert introduces cyclic dependency (logger
1510 // -> thread local top -> heap -> logger).
1511 // ASSERT(VMState::is_outermost_external());
Steve Blocka7e24c12009-10-30 11:49:00 +00001512
Steve Block44f0eee2011-05-26 01:26:41 +01001513 log_->Initialize();
Steve Blocka7e24c12009-10-30 11:49:00 +00001514
Ben Murdochf87a2032010-10-22 12:50:53 +01001515 if (FLAG_ll_prof) LogCodeInfo();
1516
Steve Block44f0eee2011-05-26 01:26:41 +01001517 ticker_ = new Ticker(Isolate::Current(), kSamplingIntervalMs);
Steve Blocka7e24c12009-10-30 11:49:00 +00001518
Steve Block44f0eee2011-05-26 01:26:41 +01001519 Isolate* isolate = Isolate::Current();
Steve Blocka7e24c12009-10-30 11:49:00 +00001520 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
Steve Block44f0eee2011-05-26 01:26:41 +01001521 sliding_state_window_ = new SlidingStateWindow(isolate);
Steve Blocka7e24c12009-10-30 11:49:00 +00001522 }
1523
Steve Block44f0eee2011-05-26 01:26:41 +01001524 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1525 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1526 || FLAG_log_regexp || FLAG_log_state_changes;
1527
Steve Block6ded16b2010-05-10 14:33:55 +01001528 if (start_logging) {
1529 logging_nesting_ = 1;
1530 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001531
1532 if (FLAG_prof) {
Steve Block44f0eee2011-05-26 01:26:41 +01001533 profiler_ = new Profiler(isolate);
Steve Blocka7e24c12009-10-30 11:49:00 +00001534 if (!FLAG_prof_auto) {
1535 profiler_->pause();
1536 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001537 logging_nesting_ = 1;
Steve Blocka7e24c12009-10-30 11:49:00 +00001538 }
Steve Blockd0582a62009-12-15 09:54:21 +00001539 if (!FLAG_prof_lazy) {
1540 profiler_->Engage();
1541 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001542 }
1543
Steve Blocka7e24c12009-10-30 11:49:00 +00001544 return true;
1545
1546#else
1547 return false;
1548#endif
1549}
1550
1551
Steve Block44f0eee2011-05-26 01:26:41 +01001552Sampler* Logger::sampler() {
1553 return ticker_;
1554}
1555
1556
Ben Murdochb0fe1622011-05-05 13:52:32 +01001557void Logger::EnsureTickerStarted() {
1558#ifdef ENABLE_LOGGING_AND_PROFILING
1559 ASSERT(ticker_ != NULL);
1560 if (!ticker_->IsActive()) ticker_->Start();
1561#endif
1562}
1563
1564
1565void Logger::EnsureTickerStopped() {
1566#ifdef ENABLE_LOGGING_AND_PROFILING
1567 if (ticker_ != NULL && ticker_->IsActive()) ticker_->Stop();
1568#endif
1569}
1570
1571
Steve Blocka7e24c12009-10-30 11:49:00 +00001572void Logger::TearDown() {
1573#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block44f0eee2011-05-26 01:26:41 +01001574 if (!is_initialized_) return;
1575 is_initialized_ = false;
Steve Blocka7e24c12009-10-30 11:49:00 +00001576
1577 // Stop the profiler before closing the file.
1578 if (profiler_ != NULL) {
1579 profiler_->Disengage();
1580 delete profiler_;
1581 profiler_ = NULL;
1582 }
1583
Steve Blocka7e24c12009-10-30 11:49:00 +00001584 delete sliding_state_window_;
1585 sliding_state_window_ = NULL;
1586
1587 delete ticker_;
1588 ticker_ = NULL;
1589
Steve Block44f0eee2011-05-26 01:26:41 +01001590 log_->Close();
Steve Blocka7e24c12009-10-30 11:49:00 +00001591#endif
1592}
1593
1594
1595void Logger::EnableSlidingStateWindow() {
1596#ifdef ENABLE_LOGGING_AND_PROFILING
1597 // If the ticker is NULL, Logger::Setup has not been called yet. In
1598 // that case, we set the sliding_state_window flag so that the
1599 // sliding window computation will be started when Logger::Setup is
1600 // called.
1601 if (ticker_ == NULL) {
1602 FLAG_sliding_state_window = true;
1603 return;
1604 }
1605 // Otherwise, if the sliding state window computation has not been
1606 // started we do it now.
1607 if (sliding_state_window_ == NULL) {
Steve Block44f0eee2011-05-26 01:26:41 +01001608 sliding_state_window_ = new SlidingStateWindow(Isolate::Current());
Steve Blocka7e24c12009-10-30 11:49:00 +00001609 }
1610#endif
1611}
1612
Steve Block44f0eee2011-05-26 01:26:41 +01001613
1614Mutex* SamplerRegistry::mutex_ = OS::CreateMutex();
1615List<Sampler*>* SamplerRegistry::active_samplers_ = NULL;
1616
1617
1618bool SamplerRegistry::IterateActiveSamplers(VisitSampler func, void* param) {
1619 ScopedLock lock(mutex_);
1620 for (int i = 0;
1621 ActiveSamplersExist() && i < active_samplers_->length();
1622 ++i) {
1623 func(active_samplers_->at(i), param);
1624 }
1625 return ActiveSamplersExist();
1626}
1627
1628
1629static void ComputeCpuProfiling(Sampler* sampler, void* flag_ptr) {
1630 bool* flag = reinterpret_cast<bool*>(flag_ptr);
1631 *flag |= sampler->IsProfiling();
1632}
1633
1634
1635SamplerRegistry::State SamplerRegistry::GetState() {
1636 bool flag = false;
1637 if (!IterateActiveSamplers(&ComputeCpuProfiling, &flag)) {
1638 return HAS_NO_SAMPLERS;
1639 }
1640 return flag ? HAS_CPU_PROFILING_SAMPLERS : HAS_SAMPLERS;
1641}
1642
1643
1644void SamplerRegistry::AddActiveSampler(Sampler* sampler) {
1645 ASSERT(sampler->IsActive());
1646 ScopedLock lock(mutex_);
1647 if (active_samplers_ == NULL) {
1648 active_samplers_ = new List<Sampler*>;
1649 } else {
1650 ASSERT(!active_samplers_->Contains(sampler));
1651 }
1652 active_samplers_->Add(sampler);
1653}
1654
1655
1656void SamplerRegistry::RemoveActiveSampler(Sampler* sampler) {
1657 ASSERT(sampler->IsActive());
1658 ScopedLock lock(mutex_);
1659 ASSERT(active_samplers_ != NULL);
1660 bool removed = active_samplers_->RemoveElement(sampler);
1661 ASSERT(removed);
1662 USE(removed);
1663}
1664
Steve Blocka7e24c12009-10-30 11:49:00 +00001665} } // namespace v8::internal