blob: 6eb3c9b0ba6ca6b36c911195aa98abf0ff1a95e6 [file] [log] [blame]
ager@chromium.org71daaf62009-04-01 07:22:49 +00001// Copyright 2009 the V8 project authors. All rights reserved.
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +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
kasperl@chromium.orgf5aa8372009-03-24 14:47:14 +000032#include "bootstrapper.h"
ricow@chromium.orgd236f4d2010-09-01 06:52:08 +000033#include "code-stubs.h"
kasperl@chromium.orga5551262010-12-07 12:49:48 +000034#include "deoptimizer.h"
ager@chromium.org01beca72009-11-24 14:29:16 +000035#include "global-handles.h"
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +000036#include "log.h"
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +000037#include "macro-assembler.h"
kasperl@chromium.orga5551262010-12-07 12:49:48 +000038#include "runtime-profiler.h"
kasperl@chromium.orgf5aa8372009-03-24 14:47:14 +000039#include "serialize.h"
40#include "string-stream.h"
kasperl@chromium.orga5551262010-12-07 12:49:48 +000041#include "vm-state-inl.h"
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +000042
kasperl@chromium.org71affb52009-05-26 05:44:31 +000043namespace v8 {
44namespace internal {
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +000045
46#ifdef ENABLE_LOGGING_AND_PROFILING
47
48//
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +000049// 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:
55 SlidingStateWindow();
56 ~SlidingStateWindow();
57 void AddState(StateTag state);
58
59 private:
60 static const int kBufferSize = 256;
61 int current_index_;
62 bool is_full_;
63 byte buffer_[kBufferSize];
64
65
66 void IncrementStateCounter(StateTag state) {
67 Counters::state_counters[state].Increment();
68 }
69
70
71 void DecrementStateCounter(StateTag state) {
72 Counters::state_counters[state].Decrement();
73 }
74};
75
76
77//
78// The Profiler samples pc and sp values for the main thread.
79// Each sample is appended to a circular buffer.
80// An independent thread removes data and writes it to the log.
81// This design minimizes the time spent in the sampler.
82//
83class Profiler: public Thread {
84 public:
85 Profiler();
86 void Engage();
87 void Disengage();
88
89 // Inserts collected profiling data into buffer.
90 void Insert(TickSample* sample) {
iposva@chromium.org245aa852009-02-10 00:49:54 +000091 if (paused_)
92 return;
93
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +000094 if (Succ(head_) == tail_) {
95 overflow_ = true;
96 } else {
97 buffer_[head_] = *sample;
98 head_ = Succ(head_);
99 buffer_semaphore_->Signal(); // Tell we have an element.
100 }
101 }
102
103 // Waits for a signal and removes profiling data.
104 bool Remove(TickSample* sample) {
105 buffer_semaphore_->Wait(); // Wait for an element.
106 *sample = buffer_[tail_];
107 bool result = overflow_;
108 tail_ = Succ(tail_);
109 overflow_ = false;
110 return result;
111 }
112
113 void Run();
114
iposva@chromium.org245aa852009-02-10 00:49:54 +0000115 // Pause and Resume TickSample data collection.
116 static bool paused() { return paused_; }
117 static void pause() { paused_ = true; }
118 static void resume() { paused_ = false; }
119
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000120 private:
121 // Returns the next index in the cyclic buffer.
122 int Succ(int index) { return (index + 1) % kBufferSize; }
123
124 // 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
ager@chromium.org3811b432009-10-28 14:53:37 +0000133 // Tells whether profiler is engaged, that is, processing thread is stated.
134 bool engaged_;
135
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000136 // Tells whether worker thread should continue running.
137 bool running_;
iposva@chromium.org245aa852009-02-10 00:49:54 +0000138
139 // Tells whether we are currently recording tick samples.
140 static bool paused_;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000141};
142
iposva@chromium.org245aa852009-02-10 00:49:54 +0000143bool Profiler::paused_ = false;
144
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000145
146//
kasperl@chromium.org061ef742009-02-27 12:16:20 +0000147// StackTracer implementation
148//
149void StackTracer::Trace(TickSample* sample) {
lrn@chromium.org25156de2010-04-06 13:10:27 +0000150 sample->function = NULL;
151 sample->frames_count = 0;
152
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000153 // Avoid collecting traces while doing GC.
lrn@chromium.org25156de2010-04-06 13:10:27 +0000154 if (sample->state == GC) return;
kasperl@chromium.org7be3c992009-03-12 07:19:55 +0000155
ager@chromium.orge2902be2009-06-08 12:21:35 +0000156 const Address js_entry_sp = Top::js_entry_sp(Top::GetCurrentThread());
157 if (js_entry_sp == 0) {
158 // Not executing JS now.
ager@chromium.orge2902be2009-06-08 12:21:35 +0000159 return;
160 }
161
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000162 const Address function_address =
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000163 sample->fp + JavaScriptFrameConstants::kFunctionOffset;
164 if (SafeStackFrameIterator::IsWithinBounds(sample->sp, js_entry_sp,
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000165 function_address)) {
166 Object* object = Memory::Object_at(function_address);
167 if (object->IsHeapObject()) {
168 sample->function = HeapObject::cast(object)->address();
169 }
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000170 }
171
ager@chromium.org01beca72009-11-24 14:29:16 +0000172 int i = 0;
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000173 const Address callback = Top::external_callback();
fschneider@chromium.orge03fb642010-11-01 12:34:09 +0000174 // Surprisingly, PC can point _exactly_ to callback start, with good
175 // probability, and this will result in reporting fake nested
176 // callback call.
177 if (callback != NULL && callback != sample->pc) {
ager@chromium.org01beca72009-11-24 14:29:16 +0000178 sample->stack[i++] = callback;
179 }
180
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000181 SafeStackTraceFrameIterator it(sample->fp, sample->sp,
182 sample->sp, js_entry_sp);
ager@chromium.orgbb29dc92009-03-24 13:25:23 +0000183 while (!it.done() && i < TickSample::kMaxFramesCount) {
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000184 Object* object = it.frame()->function_slot_object();
185 if (object->IsHeapObject()) {
186 sample->stack[i++] = HeapObject::cast(object)->address();
187 }
ager@chromium.orgbb29dc92009-03-24 13:25:23 +0000188 it.Advance();
kasperl@chromium.org061ef742009-02-27 12:16:20 +0000189 }
ager@chromium.orgbb29dc92009-03-24 13:25:23 +0000190 sample->frames_count = i;
kasperl@chromium.org061ef742009-02-27 12:16:20 +0000191}
192
193
194//
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000195// Ticker used to provide ticks to the profiler and the sliding state
196// window.
197//
mads.s.ager@gmail.com9a4089a2008-09-01 08:55:01 +0000198class Ticker: public Sampler {
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000199 public:
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000200 explicit Ticker(int interval) :
201 Sampler(interval),
202 window_(NULL),
203 profiler_(NULL) {}
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000204
205 ~Ticker() { if (IsActive()) Stop(); }
206
whesse@chromium.org4a5224e2010-10-20 12:37:07 +0000207 virtual void Tick(TickSample* sample) {
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000208 if (profiler_) profiler_->Insert(sample);
mads.s.ager@gmail.com9a4089a2008-09-01 08:55:01 +0000209 if (window_) window_->AddState(sample->state);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000210 }
211
212 void SetWindow(SlidingStateWindow* window) {
213 window_ = window;
214 if (!IsActive()) Start();
215 }
216
217 void ClearWindow() {
218 window_ = NULL;
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000219 if (!profiler_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000220 }
221
222 void SetProfiler(Profiler* profiler) {
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000223 ASSERT(profiler_ == NULL);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000224 profiler_ = profiler;
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000225 IncreaseProfilingDepth();
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000226 if (!FLAG_prof_lazy && !IsActive()) Start();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000227 }
228
229 void ClearProfiler() {
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000230 DecreaseProfilingDepth();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000231 profiler_ = NULL;
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000232 if (!window_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000233 }
234
ager@chromium.orgbeb25712010-11-29 08:02:25 +0000235 protected:
236 virtual void DoSampleStack(TickSample* sample) {
ager@chromium.orgbeb25712010-11-29 08:02:25 +0000237 StackTracer::Trace(sample);
238 }
239
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000240 private:
241 SlidingStateWindow* window_;
242 Profiler* profiler_;
243};
244
245
246//
247// SlidingStateWindow implementation.
248//
249SlidingStateWindow::SlidingStateWindow(): current_index_(0), is_full_(false) {
250 for (int i = 0; i < kBufferSize; i++) {
251 buffer_[i] = static_cast<byte>(OTHER);
252 }
253 Logger::ticker_->SetWindow(this);
254}
255
256
257SlidingStateWindow::~SlidingStateWindow() {
258 Logger::ticker_->ClearWindow();
259}
260
261
262void SlidingStateWindow::AddState(StateTag state) {
263 if (is_full_) {
264 DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
265 } else if (current_index_ == kBufferSize - 1) {
266 is_full_ = true;
267 }
268 buffer_[current_index_] = static_cast<byte>(state);
269 IncrementStateCounter(state);
270 ASSERT(IsPowerOf2(kBufferSize));
271 current_index_ = (current_index_ + 1) & (kBufferSize - 1);
272}
273
274
275//
276// Profiler implementation.
277//
ager@chromium.org3811b432009-10-28 14:53:37 +0000278Profiler::Profiler()
lrn@chromium.org5d00b602011-01-05 09:51:43 +0000279 : Thread("v8:Profiler"),
280 head_(0),
ager@chromium.org3811b432009-10-28 14:53:37 +0000281 tail_(0),
282 overflow_(false),
283 buffer_semaphore_(OS::CreateSemaphore(0)),
284 engaged_(false),
285 running_(false) {
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000286}
287
288
289void Profiler::Engage() {
ager@chromium.org3811b432009-10-28 14:53:37 +0000290 if (engaged_) return;
291 engaged_ = true;
292
293 // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
294 // http://code.google.com/p/v8/issues/detail?id=487
295 if (!FLAG_prof_lazy) {
296 OS::LogSharedLibraryAddresses();
297 }
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000298
299 // Start thread processing the profiler buffer.
300 running_ = true;
301 Start();
302
303 // Register to get ticks.
304 Logger::ticker_->SetProfiler(this);
305
sgjesse@chromium.org755c5b12009-05-29 11:04:38 +0000306 Logger::ProfilerBeginEvent();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000307}
308
309
310void Profiler::Disengage() {
ager@chromium.org3811b432009-10-28 14:53:37 +0000311 if (!engaged_) return;
312
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000313 // Stop receiving ticks.
314 Logger::ticker_->ClearProfiler();
315
316 // Terminate the worker thread by setting running_ to false,
317 // inserting a fake element in the queue and then wait for
318 // the thread to terminate.
319 running_ = false;
320 TickSample sample;
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000321 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
322 resume();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000323 Insert(&sample);
324 Join();
325
ager@chromium.org6f10e412009-02-13 10:11:16 +0000326 LOG(UncheckedStringEvent("profiler", "end"));
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000327}
328
329
330void Profiler::Run() {
331 TickSample sample;
fschneider@chromium.org40b9da32010-06-28 11:29:21 +0000332 bool overflow = Remove(&sample);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000333 while (running_) {
334 LOG(TickEvent(&sample, overflow));
fschneider@chromium.org40b9da32010-06-28 11:29:21 +0000335 overflow = Remove(&sample);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000336 }
337}
338
339
340//
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000341// Logger class implementation.
342//
343Ticker* Logger::ticker_ = NULL;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000344Profiler* Logger::profiler_ = NULL;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000345SlidingStateWindow* Logger::sliding_state_window_ = NULL;
ager@chromium.orgce5e87b2010-03-10 10:24:18 +0000346int Logger::logging_nesting_ = 0;
ager@chromium.org5c838252010-02-19 08:53:10 +0000347int Logger::cpu_profiler_nesting_ = 0;
348int Logger::heap_profiler_nesting_ = 0;
ager@chromium.orgeadaf222009-06-16 09:43:10 +0000349
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000350#define DECLARE_EVENT(ignore1, name) name,
351const char* kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
352 LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
ager@chromium.orgeadaf222009-06-16 09:43:10 +0000353};
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000354#undef DECLARE_EVENT
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000355
ager@chromium.org9085a012009-05-11 19:22:57 +0000356
sgjesse@chromium.org755c5b12009-05-29 11:04:38 +0000357void Logger::ProfilerBeginEvent() {
358 if (!Log::IsEnabled()) return;
359 LogMessageBuilder msg;
360 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
361 msg.WriteToLogFile();
362}
363
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000364#endif // ENABLE_LOGGING_AND_PROFILING
365
ager@chromium.org381abbb2009-02-25 13:23:22 +0000366
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000367void Logger::StringEvent(const char* name, const char* value) {
368#ifdef ENABLE_LOGGING_AND_PROFILING
ager@chromium.org6f10e412009-02-13 10:11:16 +0000369 if (FLAG_log) UncheckedStringEvent(name, value);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000370#endif
371}
372
373
ager@chromium.org6f10e412009-02-13 10:11:16 +0000374#ifdef ENABLE_LOGGING_AND_PROFILING
375void Logger::UncheckedStringEvent(const char* name, const char* value) {
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000376 if (!Log::IsEnabled()) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000377 LogMessageBuilder msg;
378 msg.Append("%s,\"%s\"\n", name, value);
379 msg.WriteToLogFile();
ager@chromium.org6f10e412009-02-13 10:11:16 +0000380}
381#endif
382
383
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000384void Logger::IntEvent(const char* name, int value) {
385#ifdef ENABLE_LOGGING_AND_PROFILING
ager@chromium.orgce5e87b2010-03-10 10:24:18 +0000386 if (FLAG_log) UncheckedIntEvent(name, value);
387#endif
388}
389
390
kmillikin@chromium.orgf05f2912010-09-30 10:07:24 +0000391void Logger::IntPtrTEvent(const char* name, intptr_t value) {
392#ifdef ENABLE_LOGGING_AND_PROFILING
393 if (FLAG_log) UncheckedIntPtrTEvent(name, value);
394#endif
395}
396
397
ager@chromium.orgce5e87b2010-03-10 10:24:18 +0000398#ifdef ENABLE_LOGGING_AND_PROFILING
399void Logger::UncheckedIntEvent(const char* name, int value) {
400 if (!Log::IsEnabled()) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000401 LogMessageBuilder msg;
402 msg.Append("%s,%d\n", name, value);
403 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000404}
ager@chromium.orgce5e87b2010-03-10 10:24:18 +0000405#endif
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000406
407
kmillikin@chromium.orgf05f2912010-09-30 10:07:24 +0000408#ifdef ENABLE_LOGGING_AND_PROFILING
409void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
410 if (!Log::IsEnabled()) return;
411 LogMessageBuilder msg;
412 msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
413 msg.WriteToLogFile();
414}
415#endif
416
417
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000418void Logger::HandleEvent(const char* name, Object** location) {
419#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000420 if (!Log::IsEnabled() || !FLAG_log_handles) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000421 LogMessageBuilder msg;
kasperl@chromium.orgb3284ad2009-05-18 06:12:45 +0000422 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
ager@chromium.org381abbb2009-02-25 13:23:22 +0000423 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000424#endif
425}
426
427
428#ifdef ENABLE_LOGGING_AND_PROFILING
429// ApiEvent is private so all the calls come from the Logger class. It is the
ager@chromium.org9085a012009-05-11 19:22:57 +0000430// caller's responsibility to ensure that log is enabled and that
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000431// FLAG_log_api is true.
432void Logger::ApiEvent(const char* format, ...) {
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000433 ASSERT(Log::IsEnabled() && FLAG_log_api);
ager@chromium.org381abbb2009-02-25 13:23:22 +0000434 LogMessageBuilder msg;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000435 va_list ap;
436 va_start(ap, format);
ager@chromium.orgeadaf222009-06-16 09:43:10 +0000437 msg.AppendVA(format, ap);
ager@chromium.org381abbb2009-02-25 13:23:22 +0000438 va_end(ap);
439 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000440}
441#endif
442
443
444void Logger::ApiNamedSecurityCheck(Object* key) {
445#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000446 if (!Log::IsEnabled() || !FLAG_log_api) return;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000447 if (key->IsString()) {
448 SmartPointer<char> str =
449 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
450 ApiEvent("api,check-security,\"%s\"\n", *str);
451 } else if (key->IsUndefined()) {
452 ApiEvent("api,check-security,undefined\n");
453 } else {
454 ApiEvent("api,check-security,['no-name']\n");
455 }
456#endif
457}
458
459
460void Logger::SharedLibraryEvent(const char* library_path,
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000461 uintptr_t start,
462 uintptr_t end) {
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000463#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000464 if (!Log::IsEnabled() || !FLAG_prof) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000465 LogMessageBuilder msg;
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000466 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
467 library_path,
468 start,
469 end);
ager@chromium.org381abbb2009-02-25 13:23:22 +0000470 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000471#endif
472}
473
474
475void Logger::SharedLibraryEvent(const wchar_t* library_path,
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000476 uintptr_t start,
477 uintptr_t end) {
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000478#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000479 if (!Log::IsEnabled() || !FLAG_prof) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000480 LogMessageBuilder msg;
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000481 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
482 library_path,
483 start,
484 end);
ager@chromium.org381abbb2009-02-25 13:23:22 +0000485 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000486#endif
487}
488
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000489
490#ifdef ENABLE_LOGGING_AND_PROFILING
ager@chromium.org236ad962008-09-25 09:45:57 +0000491void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000492 // Prints "/" + re.source + "/" +
493 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
ager@chromium.org381abbb2009-02-25 13:23:22 +0000494 LogMessageBuilder msg;
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000495
496 Handle<Object> source = GetProperty(regexp, "source");
497 if (!source->IsString()) {
ager@chromium.org381abbb2009-02-25 13:23:22 +0000498 msg.Append("no source");
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000499 return;
500 }
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000501
kasperl@chromium.org9fe21c62008-10-28 08:53:51 +0000502 switch (regexp->TypeTag()) {
kasperl@chromium.org41044eb2008-10-06 08:24:46 +0000503 case JSRegExp::ATOM:
ager@chromium.org381abbb2009-02-25 13:23:22 +0000504 msg.Append('a');
kasperl@chromium.org41044eb2008-10-06 08:24:46 +0000505 break;
506 default:
507 break;
kasperl@chromium.org41044eb2008-10-06 08:24:46 +0000508 }
ager@chromium.org381abbb2009-02-25 13:23:22 +0000509 msg.Append('/');
510 msg.AppendDetailed(*Handle<String>::cast(source), false);
511 msg.Append('/');
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000512
513 // global flag
514 Handle<Object> global = GetProperty(regexp, "global");
515 if (global->IsTrue()) {
ager@chromium.org381abbb2009-02-25 13:23:22 +0000516 msg.Append('g');
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000517 }
518 // ignorecase flag
519 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
520 if (ignorecase->IsTrue()) {
ager@chromium.org381abbb2009-02-25 13:23:22 +0000521 msg.Append('i');
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000522 }
523 // multiline flag
524 Handle<Object> multiline = GetProperty(regexp, "multiline");
525 if (multiline->IsTrue()) {
ager@chromium.org381abbb2009-02-25 13:23:22 +0000526 msg.Append('m');
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000527 }
ager@chromium.org381abbb2009-02-25 13:23:22 +0000528
529 msg.WriteToLogFile();
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000530}
531#endif // ENABLE_LOGGING_AND_PROFILING
532
533
kasperl@chromium.org9fe21c62008-10-28 08:53:51 +0000534void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000535#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000536 if (!Log::IsEnabled() || !FLAG_log_regexp) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000537 LogMessageBuilder msg;
538 msg.Append("regexp-compile,");
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000539 LogRegExpSource(regexp);
ager@chromium.org381abbb2009-02-25 13:23:22 +0000540 msg.Append(in_cache ? ",hit\n" : ",miss\n");
541 msg.WriteToLogFile();
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000542#endif
543}
544
545
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000546void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
christian.plesner.hansen@gmail.comaca49682009-01-07 14:29:04 +0000547#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000548 if (!Log::IsEnabled() || !FLAG_log_runtime) return;
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000549 HandleScope scope;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000550 LogMessageBuilder msg;
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000551 for (int i = 0; i < format.length(); i++) {
552 char c = format[i];
553 if (c == '%' && i <= format.length() - 2) {
554 i++;
555 ASSERT('0' <= format[i] && format[i] <= '9');
lrn@chromium.org303ada72010-10-27 09:33:13 +0000556 MaybeObject* maybe = args->GetElement(format[i] - '0');
557 Object* obj;
558 if (!maybe->ToObject(&obj)) {
559 msg.Append("<exception>");
560 continue;
561 }
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000562 i++;
563 switch (format[i]) {
564 case 's':
ager@chromium.org381abbb2009-02-25 13:23:22 +0000565 msg.AppendDetailed(String::cast(obj), false);
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000566 break;
567 case 'S':
ager@chromium.org381abbb2009-02-25 13:23:22 +0000568 msg.AppendDetailed(String::cast(obj), true);
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000569 break;
570 case 'r':
571 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
572 break;
573 case 'x':
ager@chromium.org381abbb2009-02-25 13:23:22 +0000574 msg.Append("0x%x", Smi::cast(obj)->value());
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000575 break;
576 case 'i':
ager@chromium.org381abbb2009-02-25 13:23:22 +0000577 msg.Append("%i", Smi::cast(obj)->value());
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000578 break;
579 default:
580 UNREACHABLE();
581 }
582 } else {
ager@chromium.org381abbb2009-02-25 13:23:22 +0000583 msg.Append(c);
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000584 }
585 }
ager@chromium.org381abbb2009-02-25 13:23:22 +0000586 msg.Append('\n');
587 msg.WriteToLogFile();
christian.plesner.hansen@gmail.comaca49682009-01-07 14:29:04 +0000588#endif
kasperl@chromium.orgb9123622008-09-17 14:05:56 +0000589}
590
591
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000592void Logger::ApiIndexedSecurityCheck(uint32_t index) {
593#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000594 if (!Log::IsEnabled() || !FLAG_log_api) return;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000595 ApiEvent("api,check-security,%u\n", index);
596#endif
597}
598
599
600void Logger::ApiNamedPropertyAccess(const char* tag,
601 JSObject* holder,
602 Object* name) {
603#ifdef ENABLE_LOGGING_AND_PROFILING
604 ASSERT(name->IsString());
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000605 if (!Log::IsEnabled() || !FLAG_log_api) return;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000606 String* class_name_obj = holder->class_name();
607 SmartPointer<char> class_name =
608 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
609 SmartPointer<char> property_name =
610 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
611 Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
612#endif
613}
614
615void Logger::ApiIndexedPropertyAccess(const char* tag,
616 JSObject* holder,
617 uint32_t index) {
618#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000619 if (!Log::IsEnabled() || !FLAG_log_api) return;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000620 String* class_name_obj = holder->class_name();
621 SmartPointer<char> class_name =
622 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
623 Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
624#endif
625}
626
627void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
628#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000629 if (!Log::IsEnabled() || !FLAG_log_api) return;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000630 String* class_name_obj = object->class_name();
631 SmartPointer<char> class_name =
632 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
633 Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
634#endif
635}
636
637
638void Logger::ApiEntryCall(const char* name) {
639#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000640 if (!Log::IsEnabled() || !FLAG_log_api) return;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000641 Logger::ApiEvent("api,%s\n", name);
642#endif
643}
644
645
646void Logger::NewEvent(const char* name, void* object, size_t size) {
647#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000648 if (!Log::IsEnabled() || !FLAG_log) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000649 LogMessageBuilder msg;
kasperl@chromium.orgb3284ad2009-05-18 06:12:45 +0000650 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
ager@chromium.org381abbb2009-02-25 13:23:22 +0000651 static_cast<unsigned int>(size));
652 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000653#endif
654}
655
656
657void Logger::DeleteEvent(const char* name, void* object) {
658#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000659 if (!Log::IsEnabled() || !FLAG_log) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000660 LogMessageBuilder msg;
kasperl@chromium.orgb3284ad2009-05-18 06:12:45 +0000661 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
ager@chromium.org381abbb2009-02-25 13:23:22 +0000662 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000663#endif
664}
665
666
christian.plesner.hansen@gmail.com37abdec2009-01-06 14:43:28 +0000667#ifdef ENABLE_LOGGING_AND_PROFILING
sgjesse@chromium.orgac6aa172009-12-04 12:29:05 +0000668void Logger::CallbackEventInternal(const char* prefix, const char* name,
669 Address entry_point) {
ager@chromium.org01beca72009-11-24 14:29:16 +0000670 if (!Log::IsEnabled() || !FLAG_log_code) return;
671 LogMessageBuilder msg;
672 msg.Append("%s,%s,",
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000673 kLogEventsNames[CODE_CREATION_EVENT],
674 kLogEventsNames[CALLBACK_TAG]);
ager@chromium.org01beca72009-11-24 14:29:16 +0000675 msg.AppendAddress(entry_point);
sgjesse@chromium.orgac6aa172009-12-04 12:29:05 +0000676 msg.Append(",1,\"%s%s\"", prefix, name);
ager@chromium.org01beca72009-11-24 14:29:16 +0000677 msg.Append('\n');
678 msg.WriteToLogFile();
sgjesse@chromium.orgac6aa172009-12-04 12:29:05 +0000679}
680#endif
681
682
683void Logger::CallbackEvent(String* name, Address entry_point) {
684#ifdef ENABLE_LOGGING_AND_PROFILING
685 if (!Log::IsEnabled() || !FLAG_log_code) return;
686 SmartPointer<char> str =
687 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
688 CallbackEventInternal("", *str, entry_point);
689#endif
690}
691
692
693void Logger::GetterCallbackEvent(String* name, Address entry_point) {
694#ifdef ENABLE_LOGGING_AND_PROFILING
695 if (!Log::IsEnabled() || !FLAG_log_code) return;
696 SmartPointer<char> str =
697 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
698 CallbackEventInternal("get ", *str, entry_point);
699#endif
700}
701
702
703void Logger::SetterCallbackEvent(String* name, Address entry_point) {
704#ifdef ENABLE_LOGGING_AND_PROFILING
705 if (!Log::IsEnabled() || !FLAG_log_code) return;
706 SmartPointer<char> str =
707 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
708 CallbackEventInternal("set ", *str, entry_point);
ager@chromium.org01beca72009-11-24 14:29:16 +0000709#endif
710}
711
712
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000713#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000714static const char* ComputeMarker(Code* code) {
715 switch (code->kind()) {
716 case Code::FUNCTION: return code->optimizable() ? "~" : "";
717 case Code::OPTIMIZED_FUNCTION: return "*";
718 default: return "";
719 }
720}
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000721#endif
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000722
723
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000724void Logger::CodeCreateEvent(LogEventsAndTags tag,
725 Code* code,
726 const char* comment) {
727#ifdef ENABLE_LOGGING_AND_PROFILING
728 if (!Log::IsEnabled() || !FLAG_log_code) return;
729 LogMessageBuilder msg;
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000730 msg.Append("%s,%s,",
731 kLogEventsNames[CODE_CREATION_EVENT],
732 kLogEventsNames[tag]);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000733 msg.AppendAddress(code->address());
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000734 msg.Append(",%d,\"%s", code->ExecutableSize(), ComputeMarker(code));
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000735 for (const char* p = comment; *p != '\0'; p++) {
736 if (*p == '"') {
737 msg.Append('\\');
738 }
739 msg.Append(*p);
740 }
741 msg.Append('"');
whesse@chromium.org4a5224e2010-10-20 12:37:07 +0000742 LowLevelCodeCreateEvent(code, &msg);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000743 msg.Append('\n');
744 msg.WriteToLogFile();
745#endif
746}
747
748
749void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
750#ifdef ENABLE_LOGGING_AND_PROFILING
751 if (!Log::IsEnabled() || !FLAG_log_code) return;
752 LogMessageBuilder msg;
753 SmartPointer<char> str =
754 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000755 msg.Append("%s,%s,",
756 kLogEventsNames[CODE_CREATION_EVENT],
757 kLogEventsNames[tag]);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000758 msg.AppendAddress(code->address());
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000759 msg.Append(",%d,\"%s%s\"", code->ExecutableSize(), ComputeMarker(code), *str);
whesse@chromium.org4a5224e2010-10-20 12:37:07 +0000760 LowLevelCodeCreateEvent(code, &msg);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000761 msg.Append('\n');
762 msg.WriteToLogFile();
763#endif
764}
765
766
767void Logger::CodeCreateEvent(LogEventsAndTags tag,
768 Code* code, String* name,
769 String* source, int line) {
770#ifdef ENABLE_LOGGING_AND_PROFILING
771 if (!Log::IsEnabled() || !FLAG_log_code) return;
772 LogMessageBuilder msg;
773 SmartPointer<char> str =
774 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
775 SmartPointer<char> sourcestr =
776 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000777 msg.Append("%s,%s,",
778 kLogEventsNames[CODE_CREATION_EVENT],
779 kLogEventsNames[tag]);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000780 msg.AppendAddress(code->address());
kasperl@chromium.orga5551262010-12-07 12:49:48 +0000781 msg.Append(",%d,\"%s%s %s:%d\"",
782 code->ExecutableSize(),
783 ComputeMarker(code),
784 *str,
785 *sourcestr,
786 line);
whesse@chromium.org4a5224e2010-10-20 12:37:07 +0000787 LowLevelCodeCreateEvent(code, &msg);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000788 msg.Append('\n');
789 msg.WriteToLogFile();
790#endif
791}
792
793
794void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
795#ifdef ENABLE_LOGGING_AND_PROFILING
796 if (!Log::IsEnabled() || !FLAG_log_code) return;
797 LogMessageBuilder msg;
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000798 msg.Append("%s,%s,",
799 kLogEventsNames[CODE_CREATION_EVENT],
800 kLogEventsNames[tag]);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000801 msg.AppendAddress(code->address());
802 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
whesse@chromium.org4a5224e2010-10-20 12:37:07 +0000803 LowLevelCodeCreateEvent(code, &msg);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000804 msg.Append('\n');
805 msg.WriteToLogFile();
806#endif
807}
808
809
whesse@chromium.org4a5224e2010-10-20 12:37:07 +0000810void Logger::CodeMovingGCEvent() {
811#ifdef ENABLE_LOGGING_AND_PROFILING
812 if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
813 LogMessageBuilder msg;
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000814 msg.Append("%s\n", kLogEventsNames[CODE_MOVING_GC]);
whesse@chromium.org4a5224e2010-10-20 12:37:07 +0000815 msg.WriteToLogFile();
816 OS::SignalCodeMovingGC();
817#endif
818}
819
820
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000821void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
822#ifdef ENABLE_LOGGING_AND_PROFILING
823 if (!Log::IsEnabled() || !FLAG_log_code) return;
824 LogMessageBuilder msg;
825 msg.Append("%s,%s,",
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000826 kLogEventsNames[CODE_CREATION_EVENT],
827 kLogEventsNames[REG_EXP_TAG]);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000828 msg.AppendAddress(code->address());
829 msg.Append(",%d,\"", code->ExecutableSize());
830 msg.AppendDetailed(source, false);
831 msg.Append('\"');
whesse@chromium.org4a5224e2010-10-20 12:37:07 +0000832 LowLevelCodeCreateEvent(code, &msg);
ager@chromium.org5aa501c2009-06-23 07:57:28 +0000833 msg.Append('\n');
834 msg.WriteToLogFile();
835#endif
836}
837
838
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000839void Logger::CodeMoveEvent(Address from, Address to) {
840#ifdef ENABLE_LOGGING_AND_PROFILING
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000841 MoveEventInternal(CODE_MOVE_EVENT, from, to);
842#endif
843}
844
845
846void Logger::CodeDeleteEvent(Address from) {
847#ifdef ENABLE_LOGGING_AND_PROFILING
848 DeleteEventInternal(CODE_DELETE_EVENT, from);
849#endif
850}
851
852
853void Logger::SnapshotPositionEvent(Address addr, int pos) {
854#ifdef ENABLE_LOGGING_AND_PROFILING
855 if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return;
856 LogMessageBuilder msg;
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000857 msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000858 msg.AppendAddress(addr);
859 msg.Append(",%d", pos);
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000860 msg.Append('\n');
861 msg.WriteToLogFile();
862#endif
863}
864
865
866void Logger::FunctionCreateEvent(JSFunction* function) {
867#ifdef ENABLE_LOGGING_AND_PROFILING
whesse@chromium.org4a1fe7d2010-09-27 12:32:04 +0000868 // This function can be called from GC iterators (during Scavenge,
869 // MC, and MS), so marking bits can be set on objects. That's
870 // why unchecked accessors are used here.
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000871 if (!Log::IsEnabled() || !FLAG_log_code) return;
872 LogMessageBuilder msg;
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000873 msg.Append("%s,", kLogEventsNames[FUNCTION_CREATION_EVENT]);
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000874 msg.AppendAddress(function->address());
875 msg.Append(',');
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000876 msg.AppendAddress(function->unchecked_code()->address());
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000877 msg.Append('\n');
878 msg.WriteToLogFile();
879#endif
880}
881
882
whesse@chromium.org4a5224e2010-10-20 12:37:07 +0000883void Logger::FunctionCreateEventFromMove(JSFunction* function) {
whesse@chromium.org4a1fe7d2010-09-27 12:32:04 +0000884#ifdef ENABLE_LOGGING_AND_PROFILING
885 if (function->unchecked_code() != Builtins::builtin(Builtins::LazyCompile)) {
886 FunctionCreateEvent(function);
887 }
888#endif
889}
890
891
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000892void Logger::FunctionMoveEvent(Address from, Address to) {
893#ifdef ENABLE_LOGGING_AND_PROFILING
894 MoveEventInternal(FUNCTION_MOVE_EVENT, from, to);
895#endif
896}
897
898
899void Logger::FunctionDeleteEvent(Address from) {
900#ifdef ENABLE_LOGGING_AND_PROFILING
901 DeleteEventInternal(FUNCTION_DELETE_EVENT, from);
902#endif
903}
904
905
906#ifdef ENABLE_LOGGING_AND_PROFILING
907void Logger::MoveEventInternal(LogEventsAndTags event,
908 Address from,
909 Address to) {
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000910 if (!Log::IsEnabled() || !FLAG_log_code) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000911 LogMessageBuilder msg;
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000912 msg.Append("%s,", kLogEventsNames[event]);
ager@chromium.orgeadaf222009-06-16 09:43:10 +0000913 msg.AppendAddress(from);
914 msg.Append(',');
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000915 msg.AppendAddress(to);
ager@chromium.orgeadaf222009-06-16 09:43:10 +0000916 msg.Append('\n');
ager@chromium.org381abbb2009-02-25 13:23:22 +0000917 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000918}
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000919#endif
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000920
921
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000922#ifdef ENABLE_LOGGING_AND_PROFILING
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000923void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000924 if (!Log::IsEnabled() || !FLAG_log_code) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000925 LogMessageBuilder msg;
ager@chromium.org5f0c45f2010-12-17 08:51:21 +0000926 msg.Append("%s,", kLogEventsNames[event]);
ager@chromium.orgeadaf222009-06-16 09:43:10 +0000927 msg.AppendAddress(from);
ager@chromium.orgeadaf222009-06-16 09:43:10 +0000928 msg.Append('\n');
ager@chromium.org381abbb2009-02-25 13:23:22 +0000929 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000930}
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +0000931#endif
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000932
933
934void Logger::ResourceEvent(const char* name, const char* tag) {
935#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000936 if (!Log::IsEnabled() || !FLAG_log) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000937 LogMessageBuilder msg;
938 msg.Append("%s,%s,", name, tag);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000939
940 uint32_t sec, usec;
941 if (OS::GetUserTime(&sec, &usec) != -1) {
ager@chromium.org381abbb2009-02-25 13:23:22 +0000942 msg.Append("%d,%d,", sec, usec);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000943 }
ager@chromium.org381abbb2009-02-25 13:23:22 +0000944 msg.Append("%.0f", OS::TimeCurrentMillis());
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000945
ager@chromium.org381abbb2009-02-25 13:23:22 +0000946 msg.Append('\n');
947 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000948#endif
949}
950
951
ager@chromium.org8bb60582008-12-11 12:02:20 +0000952void Logger::SuspectReadEvent(String* name, Object* obj) {
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000953#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000954 if (!Log::IsEnabled() || !FLAG_log_suspect) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000955 LogMessageBuilder msg;
ager@chromium.org8bb60582008-12-11 12:02:20 +0000956 String* class_name = obj->IsJSObject()
957 ? JSObject::cast(obj)->class_name()
958 : Heap::empty_string();
ager@chromium.org381abbb2009-02-25 13:23:22 +0000959 msg.Append("suspect-read,");
960 msg.Append(class_name);
961 msg.Append(',');
962 msg.Append('"');
963 msg.Append(name);
964 msg.Append('"');
965 msg.Append('\n');
966 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000967#endif
968}
969
970
971void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
972#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000973 if (!Log::IsEnabled() || !FLAG_log_gc) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +0000974 LogMessageBuilder msg;
kasperl@chromium.orge959c182009-07-27 08:59:04 +0000975 // Using non-relative system time in order to be able to synchronize with
976 // external memory profiling events (e.g. DOM memory size).
977 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
978 space, kind, OS::TimeCurrentMillis());
979 msg.WriteToLogFile();
980#endif
981}
982
983
984void Logger::HeapSampleStats(const char* space, const char* kind,
kmillikin@chromium.orgf05f2912010-09-30 10:07:24 +0000985 intptr_t capacity, intptr_t used) {
kasperl@chromium.orge959c182009-07-27 08:59:04 +0000986#ifdef ENABLE_LOGGING_AND_PROFILING
987 if (!Log::IsEnabled() || !FLAG_log_gc) return;
988 LogMessageBuilder msg;
kmillikin@chromium.orgf05f2912010-09-30 10:07:24 +0000989 msg.Append("heap-sample-stats,\"%s\",\"%s\","
990 "%" V8_PTR_PREFIX "d,%" V8_PTR_PREFIX "d\n",
kasperl@chromium.orge959c182009-07-27 08:59:04 +0000991 space, kind, capacity, used);
ager@chromium.org381abbb2009-02-25 13:23:22 +0000992 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +0000993#endif
994}
995
996
997void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
998#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +0000999 if (!Log::IsEnabled() || !FLAG_log_gc) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +00001000 LogMessageBuilder msg;
1001 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1002 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001003#endif
1004}
1005
1006
1007void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1008#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001009 if (!Log::IsEnabled() || !FLAG_log_gc) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +00001010 LogMessageBuilder msg;
1011 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1012 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001013#endif
1014}
1015
1016
sgjesse@chromium.org0b6db592009-07-30 14:48:31 +00001017void Logger::HeapSampleJSConstructorEvent(const char* constructor,
1018 int number, int bytes) {
1019#ifdef ENABLE_LOGGING_AND_PROFILING
1020 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1021 LogMessageBuilder msg;
christian.plesner.hansen@gmail.com2bc58ef2009-09-22 10:00:30 +00001022 msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
sgjesse@chromium.org0b6db592009-07-30 14:48:31 +00001023 msg.WriteToLogFile();
1024#endif
1025}
1026
1027
christian.plesner.hansen@gmail.com2bc58ef2009-09-22 10:00:30 +00001028void Logger::HeapSampleJSRetainersEvent(
1029 const char* constructor, const char* event) {
1030#ifdef ENABLE_LOGGING_AND_PROFILING
1031 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1032 // Event starts with comma, so we don't have it in the format string.
1033 static const char* event_text = "heap-js-ret-item,%s";
1034 // We take placeholder strings into account, but it's OK to be conservative.
ager@chromium.orgc4c92722009-11-18 14:12:51 +00001035 static const int event_text_len = StrLength(event_text);
1036 const int cons_len = StrLength(constructor);
1037 const int event_len = StrLength(event);
christian.plesner.hansen@gmail.com2bc58ef2009-09-22 10:00:30 +00001038 int pos = 0;
1039 // Retainer lists can be long. We may need to split them into multiple events.
1040 do {
1041 LogMessageBuilder msg;
1042 msg.Append(event_text, constructor);
1043 int to_write = event_len - pos;
1044 if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) {
1045 int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len);
1046 ASSERT(cut_pos < event_len);
1047 while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
1048 if (event[cut_pos] != ',') {
1049 // Crash in debug mode, skip in release mode.
1050 ASSERT(false);
1051 return;
1052 }
1053 // Append a piece of event that fits, without trailing comma.
1054 msg.AppendStringPart(event + pos, cut_pos - pos);
1055 // Start next piece with comma.
1056 pos = cut_pos;
1057 } else {
1058 msg.Append("%s", event + pos);
1059 pos += event_len;
1060 }
1061 msg.Append('\n');
1062 msg.WriteToLogFile();
1063 } while (pos < event_len);
1064#endif
1065}
1066
1067
christian.plesner.hansen@gmail.com9d58c2b2009-10-16 11:48:38 +00001068void Logger::HeapSampleJSProducerEvent(const char* constructor,
1069 Address* stack) {
1070#ifdef ENABLE_LOGGING_AND_PROFILING
1071 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1072 LogMessageBuilder msg;
1073 msg.Append("heap-js-prod-item,%s", constructor);
1074 while (*stack != NULL) {
1075 msg.Append(",0x%" V8PRIxPTR, *stack++);
1076 }
1077 msg.Append("\n");
1078 msg.WriteToLogFile();
1079#endif
1080}
1081
1082
mads.s.ager@gmail.com769cc962008-08-06 10:02:49 +00001083void Logger::DebugTag(const char* call_site_tag) {
1084#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001085 if (!Log::IsEnabled() || !FLAG_log) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +00001086 LogMessageBuilder msg;
1087 msg.Append("debug-tag,%s\n", call_site_tag);
1088 msg.WriteToLogFile();
mads.s.ager@gmail.com769cc962008-08-06 10:02:49 +00001089#endif
1090}
1091
1092
1093void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1094#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001095 if (!Log::IsEnabled() || !FLAG_log) return;
mads.s.ager@gmail.com769cc962008-08-06 10:02:49 +00001096 StringBuilder s(parameter.length() + 1);
1097 for (int i = 0; i < parameter.length(); ++i) {
1098 s.AddCharacter(static_cast<char>(parameter[i]));
1099 }
1100 char* parameter_string = s.Finalize();
ager@chromium.org381abbb2009-02-25 13:23:22 +00001101 LogMessageBuilder msg;
1102 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1103 event_type,
1104 OS::TimeCurrentMillis(),
1105 parameter_string);
mads.s.ager@gmail.com769cc962008-08-06 10:02:49 +00001106 DeleteArray(parameter_string);
ager@chromium.org381abbb2009-02-25 13:23:22 +00001107 msg.WriteToLogFile();
mads.s.ager@gmail.com769cc962008-08-06 10:02:49 +00001108#endif
1109}
1110
1111
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001112#ifdef ENABLE_LOGGING_AND_PROFILING
1113void Logger::TickEvent(TickSample* sample, bool overflow) {
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001114 if (!Log::IsEnabled() || !FLAG_prof) return;
ager@chromium.org381abbb2009-02-25 13:23:22 +00001115 LogMessageBuilder msg;
ager@chromium.org5f0c45f2010-12-17 08:51:21 +00001116 msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
1117 msg.AppendAddress(sample->pc);
ager@chromium.orgeadaf222009-06-16 09:43:10 +00001118 msg.Append(',');
ager@chromium.org5f0c45f2010-12-17 08:51:21 +00001119 msg.AppendAddress(sample->sp);
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +00001120 msg.Append(',');
ager@chromium.org5f0c45f2010-12-17 08:51:21 +00001121 msg.AppendAddress(sample->function);
ager@chromium.orgeadaf222009-06-16 09:43:10 +00001122 msg.Append(",%d", static_cast<int>(sample->state));
ager@chromium.org381abbb2009-02-25 13:23:22 +00001123 if (overflow) {
1124 msg.Append(",overflow");
1125 }
kasperl@chromium.org7be3c992009-03-12 07:19:55 +00001126 for (int i = 0; i < sample->frames_count; ++i) {
ager@chromium.orgeadaf222009-06-16 09:43:10 +00001127 msg.Append(',');
ager@chromium.org5f0c45f2010-12-17 08:51:21 +00001128 msg.AppendAddress(sample->stack[i]);
ager@chromium.org381abbb2009-02-25 13:23:22 +00001129 }
1130 msg.Append('\n');
1131 msg.WriteToLogFile();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001132}
iposva@chromium.org245aa852009-02-10 00:49:54 +00001133
1134
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001135int Logger::GetActiveProfilerModules() {
1136 int result = PROFILER_MODULE_NONE;
fschneider@chromium.org40b9da32010-06-28 11:29:21 +00001137 if (profiler_ != NULL && !profiler_->paused()) {
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001138 result |= PROFILER_MODULE_CPU;
1139 }
1140 if (FLAG_log_gc) {
1141 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1142 }
1143 return result;
iposva@chromium.org245aa852009-02-10 00:49:54 +00001144}
1145
1146
ager@chromium.org5c838252010-02-19 08:53:10 +00001147void Logger::PauseProfiler(int flags, int tag) {
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001148 if (!Log::IsEnabled()) return;
fschneider@chromium.org40b9da32010-06-28 11:29:21 +00001149 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
ager@chromium.org5c838252010-02-19 08:53:10 +00001150 // It is OK to have negative nesting.
1151 if (--cpu_profiler_nesting_ == 0) {
1152 profiler_->pause();
1153 if (FLAG_prof_lazy) {
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001154 if (!FLAG_sliding_state_window && !RuntimeProfiler::IsEnabled()) {
1155 ticker_->Stop();
1156 }
ager@chromium.org5c838252010-02-19 08:53:10 +00001157 FLAG_log_code = false;
1158 // Must be the same message as Log::kDynamicBufferSeal.
1159 LOG(UncheckedStringEvent("profiler", "pause"));
1160 }
ager@chromium.orgce5e87b2010-03-10 10:24:18 +00001161 --logging_nesting_;
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001162 }
sgjesse@chromium.org755c5b12009-05-29 11:04:38 +00001163 }
ager@chromium.org5c838252010-02-19 08:53:10 +00001164 if (flags &
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001165 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
ager@chromium.org5c838252010-02-19 08:53:10 +00001166 if (--heap_profiler_nesting_ == 0) {
1167 FLAG_log_gc = false;
ager@chromium.orgce5e87b2010-03-10 10:24:18 +00001168 --logging_nesting_;
ager@chromium.org5c838252010-02-19 08:53:10 +00001169 }
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001170 }
ager@chromium.org5c838252010-02-19 08:53:10 +00001171 if (tag != 0) {
ager@chromium.orgce5e87b2010-03-10 10:24:18 +00001172 UncheckedIntEvent("close-tag", tag);
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001173 }
iposva@chromium.org245aa852009-02-10 00:49:54 +00001174}
1175
1176
ager@chromium.org5c838252010-02-19 08:53:10 +00001177void Logger::ResumeProfiler(int flags, int tag) {
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001178 if (!Log::IsEnabled()) return;
ager@chromium.org5c838252010-02-19 08:53:10 +00001179 if (tag != 0) {
ager@chromium.orgce5e87b2010-03-10 10:24:18 +00001180 UncheckedIntEvent("open-tag", tag);
sgjesse@chromium.org755c5b12009-05-29 11:04:38 +00001181 }
fschneider@chromium.org40b9da32010-06-28 11:29:21 +00001182 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
ager@chromium.org5c838252010-02-19 08:53:10 +00001183 if (cpu_profiler_nesting_++ == 0) {
ager@chromium.orgce5e87b2010-03-10 10:24:18 +00001184 ++logging_nesting_;
ager@chromium.org5c838252010-02-19 08:53:10 +00001185 if (FLAG_prof_lazy) {
1186 profiler_->Engage();
1187 LOG(UncheckedStringEvent("profiler", "resume"));
1188 FLAG_log_code = true;
1189 LogCompiledFunctions();
1190 LogFunctionObjects();
1191 LogAccessorCallbacks();
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001192 if (!FLAG_sliding_state_window && !ticker_->IsActive()) {
1193 ticker_->Start();
1194 }
ager@chromium.org5c838252010-02-19 08:53:10 +00001195 }
1196 profiler_->resume();
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001197 }
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001198 }
ager@chromium.org5c838252010-02-19 08:53:10 +00001199 if (flags &
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001200 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
ager@chromium.org5c838252010-02-19 08:53:10 +00001201 if (heap_profiler_nesting_++ == 0) {
ager@chromium.orgce5e87b2010-03-10 10:24:18 +00001202 ++logging_nesting_;
ager@chromium.org5c838252010-02-19 08:53:10 +00001203 FLAG_log_gc = true;
1204 }
sgjesse@chromium.orgb9d7da12009-08-05 08:38:10 +00001205 }
iposva@chromium.org245aa852009-02-10 00:49:54 +00001206}
ager@chromium.org9085a012009-05-11 19:22:57 +00001207
1208
sgjesse@chromium.org755c5b12009-05-29 11:04:38 +00001209// This function can be called when Log's mutex is acquired,
1210// either from main or Profiler's thread.
1211void Logger::StopLoggingAndProfiling() {
1212 Log::stop();
ager@chromium.org5c838252010-02-19 08:53:10 +00001213 PauseProfiler(PROFILER_MODULE_CPU, 0);
sgjesse@chromium.org755c5b12009-05-29 11:04:38 +00001214}
1215
1216
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001217bool Logger::IsProfilerSamplerActive() {
1218 return ticker_->IsActive();
1219}
1220
1221
ager@chromium.org9085a012009-05-11 19:22:57 +00001222int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1223 return Log::GetLogLines(from_pos, dest_buf, max_size);
1224}
1225
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001226
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001227class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1228 public:
1229 EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1230 Handle<Code>* code_objects,
1231 int* count)
1232 : sfis_(sfis), code_objects_(code_objects), count_(count) { }
1233
1234 virtual void EnterContext(Context* context) {}
1235 virtual void LeaveContext(Context* context) {}
1236
1237 virtual void VisitFunction(JSFunction* function) {
1238 if (sfis_ != NULL) {
1239 sfis_[*count_] = Handle<SharedFunctionInfo>(function->shared());
1240 }
1241 if (code_objects_ != NULL) {
1242 ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
1243 code_objects_[*count_] = Handle<Code>(function->code());
1244 }
1245 *count_ = *count_ + 1;
1246 }
1247
1248 private:
1249 Handle<SharedFunctionInfo>* sfis_;
1250 Handle<Code>* code_objects_;
1251 int* count_;
1252};
1253
1254
1255static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis,
1256 Handle<Code>* code_objects) {
sgjesse@chromium.org152a0b02009-10-07 13:50:16 +00001257 AssertNoAllocation no_alloc;
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001258 int compiled_funcs_count = 0;
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001259
1260 // Iterate the heap to find shared function info objects and record
1261 // the unoptimized code for them.
sgjesse@chromium.org152a0b02009-10-07 13:50:16 +00001262 HeapIterator iterator;
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +00001263 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
sgjesse@chromium.org152a0b02009-10-07 13:50:16 +00001264 if (!obj->IsSharedFunctionInfo()) continue;
1265 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1266 if (sfi->is_compiled()
1267 && (!sfi->script()->IsScript()
1268 || Script::cast(sfi->script())->HasValidSource())) {
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001269 if (sfis != NULL) {
sgjesse@chromium.org152a0b02009-10-07 13:50:16 +00001270 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001271 }
1272 if (code_objects != NULL) {
1273 code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
1274 }
sgjesse@chromium.org152a0b02009-10-07 13:50:16 +00001275 ++compiled_funcs_count;
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001276 }
1277 }
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001278
1279 // Iterate all optimized functions in all contexts.
1280 EnumerateOptimizedFunctionsVisitor visitor(sfis,
1281 code_objects,
1282 &compiled_funcs_count);
1283 Deoptimizer::VisitAllOptimizedFunctions(&visitor);
1284
sgjesse@chromium.org152a0b02009-10-07 13:50:16 +00001285 return compiled_funcs_count;
1286}
1287
1288
ager@chromium.orgc4c92722009-11-18 14:12:51 +00001289void Logger::LogCodeObject(Object* object) {
1290 if (FLAG_log_code) {
1291 Code* code_object = Code::cast(object);
1292 LogEventsAndTags tag = Logger::STUB_TAG;
1293 const char* description = "Unknown code from the snapshot";
1294 switch (code_object->kind()) {
1295 case Code::FUNCTION:
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001296 case Code::OPTIMIZED_FUNCTION:
ager@chromium.orgc4c92722009-11-18 14:12:51 +00001297 return; // We log this later using LogCompiledFunctions.
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001298 case Code::BINARY_OP_IC: // fall through
1299 case Code::TYPE_RECORDING_BINARY_OP_IC: // fall through
1300 case Code::COMPARE_IC: // fall through
ager@chromium.orgc4c92722009-11-18 14:12:51 +00001301 case Code::STUB:
ricow@chromium.orgd236f4d2010-09-01 06:52:08 +00001302 description =
1303 CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
ager@chromium.org5c838252010-02-19 08:53:10 +00001304 if (description == NULL)
1305 description = "A stub from the snapshot";
ager@chromium.orgc4c92722009-11-18 14:12:51 +00001306 tag = Logger::STUB_TAG;
1307 break;
1308 case Code::BUILTIN:
1309 description = "A builtin from the snapshot";
1310 tag = Logger::BUILTIN_TAG;
1311 break;
1312 case Code::KEYED_LOAD_IC:
1313 description = "A keyed load IC from the snapshot";
1314 tag = Logger::KEYED_LOAD_IC_TAG;
1315 break;
1316 case Code::LOAD_IC:
1317 description = "A load IC from the snapshot";
1318 tag = Logger::LOAD_IC_TAG;
1319 break;
1320 case Code::STORE_IC:
1321 description = "A store IC from the snapshot";
1322 tag = Logger::STORE_IC_TAG;
1323 break;
1324 case Code::KEYED_STORE_IC:
1325 description = "A keyed store IC from the snapshot";
1326 tag = Logger::KEYED_STORE_IC_TAG;
1327 break;
1328 case Code::CALL_IC:
1329 description = "A call IC from the snapshot";
1330 tag = Logger::CALL_IC_TAG;
1331 break;
lrn@chromium.org1af7e1b2010-06-07 11:12:01 +00001332 case Code::KEYED_CALL_IC:
1333 description = "A keyed call IC from the snapshot";
1334 tag = Logger::KEYED_CALL_IC_TAG;
1335 break;
ager@chromium.orgc4c92722009-11-18 14:12:51 +00001336 }
lrn@chromium.org25156de2010-04-06 13:10:27 +00001337 PROFILE(CodeCreateEvent(tag, code_object, description));
ager@chromium.orgc4c92722009-11-18 14:12:51 +00001338 }
1339}
1340
1341
whesse@chromium.org4a5224e2010-10-20 12:37:07 +00001342void Logger::LogCodeInfo() {
1343#ifdef ENABLE_LOGGING_AND_PROFILING
1344 if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
1345#if V8_TARGET_ARCH_IA32
1346 const char arch[] = "ia32";
1347#elif V8_TARGET_ARCH_X64
1348 const char arch[] = "x64";
1349#elif V8_TARGET_ARCH_ARM
1350 const char arch[] = "arm";
1351#else
1352 const char arch[] = "unknown";
1353#endif
1354 LogMessageBuilder msg;
1355 msg.Append("code-info,%s,%d\n", arch, Code::kHeaderSize);
1356 msg.WriteToLogFile();
1357#endif // ENABLE_LOGGING_AND_PROFILING
1358}
1359
1360
1361void Logger::LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg) {
1362 if (!FLAG_ll_prof || Log::output_code_handle_ == NULL) return;
1363 int pos = static_cast<int>(ftell(Log::output_code_handle_));
lrn@chromium.org303ada72010-10-27 09:33:13 +00001364 size_t rv = fwrite(code->instruction_start(), 1, code->instruction_size(),
1365 Log::output_code_handle_);
1366 ASSERT(static_cast<size_t>(code->instruction_size()) == rv);
1367 USE(rv);
whesse@chromium.org4a5224e2010-10-20 12:37:07 +00001368 msg->Append(",%d", pos);
1369}
1370
1371
ager@chromium.org5c838252010-02-19 08:53:10 +00001372void Logger::LogCodeObjects() {
1373 AssertNoAllocation no_alloc;
1374 HeapIterator iterator;
1375 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1376 if (obj->IsCode()) LogCodeObject(obj);
1377 }
1378}
1379
1380
sgjesse@chromium.org152a0b02009-10-07 13:50:16 +00001381void Logger::LogCompiledFunctions() {
1382 HandleScope scope;
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001383 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL, NULL);
sgjesse@chromium.org720dc0b2010-05-10 09:25:39 +00001384 ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001385 ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
1386 EnumerateCompiledFunctions(sfis.start(), code_objects.start());
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001387
1388 // During iteration, there can be heap allocation due to
1389 // GetScriptLineNumber call.
1390 for (int i = 0; i < compiled_funcs_count; ++i) {
1391 Handle<SharedFunctionInfo> shared = sfis[i];
1392 Handle<String> name(String::cast(shared->name()));
1393 Handle<String> func_name(name->length() > 0 ?
1394 *name : shared->inferred_name());
1395 if (shared->script()->IsScript()) {
1396 Handle<Script> script(Script::cast(shared->script()));
1397 if (script->name()->IsString()) {
1398 Handle<String> script_name(String::cast(script->name()));
1399 int line_num = GetScriptLineNumber(script, shared->start_position());
1400 if (line_num > 0) {
ager@chromium.org357bf652010-04-12 11:30:10 +00001401 PROFILE(CodeCreateEvent(
1402 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001403 *code_objects[i], *func_name,
ager@chromium.org357bf652010-04-12 11:30:10 +00001404 *script_name, line_num + 1));
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001405 } else {
ager@chromium.org357bf652010-04-12 11:30:10 +00001406 // Can't distinguish eval and script here, so always use Script.
1407 PROFILE(CodeCreateEvent(
1408 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001409 *code_objects[i], *script_name));
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001410 }
ager@chromium.org01beca72009-11-24 14:29:16 +00001411 } else {
lrn@chromium.org25156de2010-04-06 13:10:27 +00001412 PROFILE(CodeCreateEvent(
ager@chromium.org357bf652010-04-12 11:30:10 +00001413 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001414 *code_objects[i], *func_name));
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001415 }
vegorov@chromium.orgf8372902010-03-15 10:26:20 +00001416 } else if (shared->IsApiFunction()) {
ager@chromium.org01beca72009-11-24 14:29:16 +00001417 // API function.
vegorov@chromium.orgf8372902010-03-15 10:26:20 +00001418 FunctionTemplateInfo* fun_data = shared->get_api_func_data();
ager@chromium.org01beca72009-11-24 14:29:16 +00001419 Object* raw_call_data = fun_data->call_code();
1420 if (!raw_call_data->IsUndefined()) {
1421 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1422 Object* callback_obj = call_data->callback();
1423 Address entry_point = v8::ToCData<Address>(callback_obj);
lrn@chromium.org25156de2010-04-06 13:10:27 +00001424 PROFILE(CallbackEvent(*func_name, entry_point));
ager@chromium.org01beca72009-11-24 14:29:16 +00001425 }
1426 } else {
lrn@chromium.org25156de2010-04-06 13:10:27 +00001427 PROFILE(CodeCreateEvent(
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001428 Logger::LAZY_COMPILE_TAG, *code_objects[i], *func_name));
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001429 }
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001430 }
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001431}
1432
sgjesse@chromium.orgac6aa172009-12-04 12:29:05 +00001433
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +00001434void Logger::LogFunctionObjects() {
1435 AssertNoAllocation no_alloc;
1436 HeapIterator iterator;
1437 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1438 if (!obj->IsJSFunction()) continue;
1439 JSFunction* jsf = JSFunction::cast(obj);
1440 if (!jsf->is_compiled()) continue;
lrn@chromium.org25156de2010-04-06 13:10:27 +00001441 PROFILE(FunctionCreateEvent(jsf));
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +00001442 }
1443}
1444
1445
sgjesse@chromium.orgac6aa172009-12-04 12:29:05 +00001446void Logger::LogAccessorCallbacks() {
1447 AssertNoAllocation no_alloc;
1448 HeapIterator iterator;
sgjesse@chromium.orgb302e562010-02-03 11:26:59 +00001449 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
sgjesse@chromium.orgac6aa172009-12-04 12:29:05 +00001450 if (!obj->IsAccessorInfo()) continue;
1451 AccessorInfo* ai = AccessorInfo::cast(obj);
1452 if (!ai->name()->IsString()) continue;
1453 String* name = String::cast(ai->name());
1454 Address getter_entry = v8::ToCData<Address>(ai->getter());
1455 if (getter_entry != 0) {
lrn@chromium.org25156de2010-04-06 13:10:27 +00001456 PROFILE(GetterCallbackEvent(name, getter_entry));
sgjesse@chromium.orgac6aa172009-12-04 12:29:05 +00001457 }
1458 Address setter_entry = v8::ToCData<Address>(ai->setter());
1459 if (setter_entry != 0) {
lrn@chromium.org25156de2010-04-06 13:10:27 +00001460 PROFILE(SetterCallbackEvent(name, setter_entry));
sgjesse@chromium.orgac6aa172009-12-04 12:29:05 +00001461 }
1462 }
1463}
1464
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001465#endif
1466
1467
1468bool Logger::Setup() {
1469#ifdef ENABLE_LOGGING_AND_PROFILING
1470 // --log-all enables all the log flags.
1471 if (FLAG_log_all) {
ager@chromium.org381abbb2009-02-25 13:23:22 +00001472 FLAG_log_runtime = true;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001473 FLAG_log_api = true;
1474 FLAG_log_code = true;
1475 FLAG_log_gc = true;
1476 FLAG_log_suspect = true;
1477 FLAG_log_handles = true;
kasperl@chromium.orgb9123622008-09-17 14:05:56 +00001478 FLAG_log_regexp = true;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001479 }
1480
1481 // --prof implies --log-code.
1482 if (FLAG_prof) FLAG_log_code = true;
1483
whesse@chromium.org4a5224e2010-10-20 12:37:07 +00001484 // --ll-prof implies --log-code and --log-snapshot-positions.
1485 if (FLAG_ll_prof) {
1486 FLAG_log_code = true;
1487 FLAG_log_snapshot_positions = true;
1488 }
1489
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001490 // --prof_lazy controls --log-code, implies --noprof_auto.
1491 if (FLAG_prof_lazy) {
1492 FLAG_log_code = false;
1493 FLAG_prof_auto = false;
1494 }
1495
ager@chromium.org3e875802009-06-29 08:26:34 +00001496 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
ager@chromium.org381abbb2009-02-25 13:23:22 +00001497 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
ager@chromium.org3e875802009-06-29 08:26:34 +00001498 || FLAG_log_regexp || FLAG_log_state_changes;
1499
1500 bool open_log_file = start_logging || FLAG_prof_lazy;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001501
1502 // If we're logging anything, we need to open the log file.
kasperl@chromium.org41044eb2008-10-06 08:24:46 +00001503 if (open_log_file) {
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001504 if (strcmp(FLAG_logfile, "-") == 0) {
ager@chromium.org9085a012009-05-11 19:22:57 +00001505 Log::OpenStdout();
1506 } else if (strcmp(FLAG_logfile, "*") == 0) {
1507 Log::OpenMemoryBuffer();
ager@chromium.org7c537e22008-10-16 08:43:32 +00001508 } else if (strchr(FLAG_logfile, '%') != NULL) {
1509 // If there's a '%' in the log file name we have to expand
1510 // placeholders.
1511 HeapStringAllocator allocator;
1512 StringStream stream(&allocator);
1513 for (const char* p = FLAG_logfile; *p; p++) {
1514 if (*p == '%') {
1515 p++;
1516 switch (*p) {
1517 case '\0':
1518 // If there's a % at the end of the string we back up
1519 // one character so we can escape the loop properly.
1520 p--;
1521 break;
1522 case 't': {
1523 // %t expands to the current time in milliseconds.
christian.plesner.hansen@gmail.com5a6af922009-08-12 14:20:51 +00001524 double time = OS::TimeCurrentMillis();
1525 stream.Add("%.0f", FmtElm(time));
ager@chromium.org7c537e22008-10-16 08:43:32 +00001526 break;
1527 }
1528 case '%':
1529 // %% expands (contracts really) to %.
1530 stream.Put('%');
1531 break;
1532 default:
1533 // All other %'s expand to themselves.
1534 stream.Put('%');
1535 stream.Put(*p);
1536 break;
1537 }
1538 } else {
1539 stream.Put(*p);
1540 }
1541 }
ager@chromium.org3bf7b912008-11-17 09:09:45 +00001542 SmartPointer<const char> expanded = stream.ToCString();
ager@chromium.org9085a012009-05-11 19:22:57 +00001543 Log::OpenFile(*expanded);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001544 } else {
ager@chromium.org9085a012009-05-11 19:22:57 +00001545 Log::OpenFile(FLAG_logfile);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001546 }
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001547 }
1548
whesse@chromium.org4a5224e2010-10-20 12:37:07 +00001549 if (FLAG_ll_prof) LogCodeInfo();
1550
ager@chromium.orge2902be2009-06-08 12:21:35 +00001551 ticker_ = new Ticker(kSamplingIntervalMs);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001552
1553 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1554 sliding_state_window_ = new SlidingStateWindow();
1555 }
1556
ager@chromium.orgce5e87b2010-03-10 10:24:18 +00001557 if (start_logging) {
1558 logging_nesting_ = 1;
1559 }
ager@chromium.org3e875802009-06-29 08:26:34 +00001560
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001561 if (FLAG_prof) {
1562 profiler_ = new Profiler();
ager@chromium.org3e875802009-06-29 08:26:34 +00001563 if (!FLAG_prof_auto) {
iposva@chromium.org245aa852009-02-10 00:49:54 +00001564 profiler_->pause();
ager@chromium.org3e875802009-06-29 08:26:34 +00001565 } else {
ager@chromium.orgce5e87b2010-03-10 10:24:18 +00001566 logging_nesting_ = 1;
ager@chromium.org3e875802009-06-29 08:26:34 +00001567 }
ager@chromium.org3811b432009-10-28 14:53:37 +00001568 if (!FLAG_prof_lazy) {
1569 profiler_->Engage();
1570 }
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001571 }
1572
sgjesse@chromium.org755c5b12009-05-29 11:04:38 +00001573 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001574 return true;
1575
1576#else
1577 return false;
1578#endif
1579}
1580
1581
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001582void Logger::EnsureTickerStarted() {
ager@chromium.org5f0c45f2010-12-17 08:51:21 +00001583#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001584 ASSERT(ticker_ != NULL);
1585 if (!ticker_->IsActive()) ticker_->Start();
ager@chromium.org5f0c45f2010-12-17 08:51:21 +00001586#endif
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001587}
1588
1589
1590void Logger::EnsureTickerStopped() {
ager@chromium.org5f0c45f2010-12-17 08:51:21 +00001591#ifdef ENABLE_LOGGING_AND_PROFILING
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001592 if (ticker_ != NULL && ticker_->IsActive()) ticker_->Stop();
ager@chromium.org5f0c45f2010-12-17 08:51:21 +00001593#endif
kasperl@chromium.orga5551262010-12-07 12:49:48 +00001594}
1595
1596
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001597void Logger::TearDown() {
1598#ifdef ENABLE_LOGGING_AND_PROFILING
sgjesse@chromium.org755c5b12009-05-29 11:04:38 +00001599 LogMessageBuilder::set_write_failure_handler(NULL);
1600
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001601 // Stop the profiler before closing the file.
1602 if (profiler_ != NULL) {
1603 profiler_->Disengage();
1604 delete profiler_;
1605 profiler_ = NULL;
1606 }
1607
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001608 delete sliding_state_window_;
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001609 sliding_state_window_ = NULL;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001610
1611 delete ticker_;
kasperl@chromium.org71affb52009-05-26 05:44:31 +00001612 ticker_ = NULL;
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001613
ager@chromium.org9085a012009-05-11 19:22:57 +00001614 Log::Close();
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001615#endif
1616}
1617
1618
1619void Logger::EnableSlidingStateWindow() {
1620#ifdef ENABLE_LOGGING_AND_PROFILING
1621 // If the ticker is NULL, Logger::Setup has not been called yet. In
1622 // that case, we set the sliding_state_window flag so that the
1623 // sliding window computation will be started when Logger::Setup is
1624 // called.
1625 if (ticker_ == NULL) {
1626 FLAG_sliding_state_window = true;
1627 return;
1628 }
1629 // Otherwise, if the sliding state window computation has not been
1630 // started we do it now.
1631 if (sliding_state_window_ == NULL) {
1632 sliding_state_window_ = new SlidingStateWindow();
1633 }
1634#endif
1635}
1636
christian.plesner.hansen43d26ec2008-07-03 15:10:15 +00001637} } // namespace v8::internal