blob: db9ff7a1f1e550d7bc357bdada508e2e7be4b88e [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:
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) {
91 if (paused_)
92 return;
93
94 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
115 // 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
120 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
Steve Blockd0582a62009-12-15 09:54:21 +0000133 // Tells whether profiler is engaged, that is, processing thread is stated.
134 bool engaged_;
135
Steve Blocka7e24c12009-10-30 11:49:00 +0000136 // Tells whether worker thread should continue running.
137 bool running_;
138
139 // Tells whether we are currently recording tick samples.
140 static bool paused_;
141};
142
143bool Profiler::paused_ = false;
144
145
146//
147// StackTracer implementation
148//
149void StackTracer::Trace(TickSample* sample) {
Steve Block6ded16b2010-05-10 14:33:55 +0100150 sample->function = NULL;
151 sample->frames_count = 0;
152
Ben Murdochb0fe1622011-05-05 13:52:32 +0100153 // Avoid collecting traces while doing GC.
Steve Block6ded16b2010-05-10 14:33:55 +0100154 if (sample->state == GC) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000155
156 const Address js_entry_sp = Top::js_entry_sp(Top::GetCurrentThread());
157 if (js_entry_sp == 0) {
158 // Not executing JS now.
Steve Blocka7e24c12009-10-30 11:49:00 +0000159 return;
160 }
161
Ben Murdochb0fe1622011-05-05 13:52:32 +0100162 const Address function_address =
Leon Clarked91b9f72010-01-27 17:25:45 +0000163 sample->fp + JavaScriptFrameConstants::kFunctionOffset;
164 if (SafeStackFrameIterator::IsWithinBounds(sample->sp, js_entry_sp,
Ben Murdochb0fe1622011-05-05 13:52:32 +0100165 function_address)) {
166 Object* object = Memory::Object_at(function_address);
167 if (object->IsHeapObject()) {
168 sample->function = HeapObject::cast(object)->address();
169 }
Leon Clarked91b9f72010-01-27 17:25:45 +0000170 }
171
Steve Blockd0582a62009-12-15 09:54:21 +0000172 int i = 0;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100173 const Address callback = Top::external_callback();
Teng-Hui Zhu3e5fa292010-11-09 16:16:48 -0800174 // 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) {
Steve Blockd0582a62009-12-15 09:54:21 +0000178 sample->stack[i++] = callback;
179 }
180
Leon Clarked91b9f72010-01-27 17:25:45 +0000181 SafeStackTraceFrameIterator it(sample->fp, sample->sp,
182 sample->sp, js_entry_sp);
Steve Blocka7e24c12009-10-30 11:49:00 +0000183 while (!it.done() && i < TickSample::kMaxFramesCount) {
Ben Murdochb0fe1622011-05-05 13:52:32 +0100184 Object* object = it.frame()->function_slot_object();
185 if (object->IsHeapObject()) {
186 sample->stack[i++] = HeapObject::cast(object)->address();
187 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000188 it.Advance();
189 }
190 sample->frames_count = i;
191}
192
193
194//
195// Ticker used to provide ticks to the profiler and the sliding state
196// window.
197//
198class Ticker: public Sampler {
199 public:
Ben Murdochb0fe1622011-05-05 13:52:32 +0100200 explicit Ticker(int interval) :
201 Sampler(interval),
202 window_(NULL),
203 profiler_(NULL) {}
Steve Blocka7e24c12009-10-30 11:49:00 +0000204
205 ~Ticker() { if (IsActive()) Stop(); }
206
Ben Murdochf87a2032010-10-22 12:50:53 +0100207 virtual void Tick(TickSample* sample) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000208 if (profiler_) profiler_->Insert(sample);
209 if (window_) window_->AddState(sample->state);
210 }
211
212 void SetWindow(SlidingStateWindow* window) {
213 window_ = window;
214 if (!IsActive()) Start();
215 }
216
217 void ClearWindow() {
218 window_ = NULL;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100219 if (!profiler_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
Steve Blocka7e24c12009-10-30 11:49:00 +0000220 }
221
222 void SetProfiler(Profiler* profiler) {
Ben Murdochb0fe1622011-05-05 13:52:32 +0100223 ASSERT(profiler_ == NULL);
Steve Blocka7e24c12009-10-30 11:49:00 +0000224 profiler_ = profiler;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100225 IncreaseProfilingDepth();
Steve Blocka7e24c12009-10-30 11:49:00 +0000226 if (!FLAG_prof_lazy && !IsActive()) Start();
227 }
228
229 void ClearProfiler() {
Ben Murdochb0fe1622011-05-05 13:52:32 +0100230 DecreaseProfilingDepth();
Steve Blocka7e24c12009-10-30 11:49:00 +0000231 profiler_ = NULL;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100232 if (!window_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
Steve Blocka7e24c12009-10-30 11:49:00 +0000233 }
234
Shimeng (Simon) Wang8a31eba2010-12-06 19:01:33 -0800235 protected:
236 virtual void DoSampleStack(TickSample* sample) {
Shimeng (Simon) Wang8a31eba2010-12-06 19:01:33 -0800237 StackTracer::Trace(sample);
238 }
239
Steve Blocka7e24c12009-10-30 11:49:00 +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//
Steve Blockd0582a62009-12-15 09:54:21 +0000278Profiler::Profiler()
279 : head_(0),
280 tail_(0),
281 overflow_(false),
282 buffer_semaphore_(OS::CreateSemaphore(0)),
283 engaged_(false),
284 running_(false) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000285}
286
287
288void Profiler::Engage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000289 if (engaged_) return;
290 engaged_ = true;
291
292 // TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
293 // http://code.google.com/p/v8/issues/detail?id=487
294 if (!FLAG_prof_lazy) {
295 OS::LogSharedLibraryAddresses();
296 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000297
298 // Start thread processing the profiler buffer.
299 running_ = true;
300 Start();
301
302 // Register to get ticks.
303 Logger::ticker_->SetProfiler(this);
304
305 Logger::ProfilerBeginEvent();
Steve Blocka7e24c12009-10-30 11:49:00 +0000306}
307
308
309void Profiler::Disengage() {
Steve Blockd0582a62009-12-15 09:54:21 +0000310 if (!engaged_) return;
311
Steve Blocka7e24c12009-10-30 11:49:00 +0000312 // Stop receiving ticks.
313 Logger::ticker_->ClearProfiler();
314
315 // Terminate the worker thread by setting running_ to false,
316 // inserting a fake element in the queue and then wait for
317 // the thread to terminate.
318 running_ = false;
319 TickSample sample;
320 // Reset 'paused_' flag, otherwise semaphore may not be signalled.
321 resume();
322 Insert(&sample);
323 Join();
324
325 LOG(UncheckedStringEvent("profiler", "end"));
326}
327
328
329void Profiler::Run() {
330 TickSample sample;
Steve Block8defd9f2010-07-08 12:39:36 +0100331 bool overflow = Remove(&sample);
Steve Blocka7e24c12009-10-30 11:49:00 +0000332 while (running_) {
333 LOG(TickEvent(&sample, overflow));
Steve Block8defd9f2010-07-08 12:39:36 +0100334 overflow = Remove(&sample);
Steve Blocka7e24c12009-10-30 11:49:00 +0000335 }
336}
337
338
339//
340// Logger class implementation.
341//
342Ticker* Logger::ticker_ = NULL;
343Profiler* Logger::profiler_ = NULL;
Steve Blocka7e24c12009-10-30 11:49:00 +0000344SlidingStateWindow* Logger::sliding_state_window_ = NULL;
Steve Block6ded16b2010-05-10 14:33:55 +0100345int Logger::logging_nesting_ = 0;
Andrei Popescu402d9372010-02-26 13:31:12 +0000346int Logger::cpu_profiler_nesting_ = 0;
347int Logger::heap_profiler_nesting_ = 0;
Steve Blocka7e24c12009-10-30 11:49:00 +0000348
Ben Murdochb0fe1622011-05-05 13:52:32 +0100349#define DECLARE_EVENT(ignore1, name) name,
350const char* kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
351 LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
Steve Blocka7e24c12009-10-30 11:49:00 +0000352};
Ben Murdochb0fe1622011-05-05 13:52:32 +0100353#undef DECLARE_EVENT
Steve Blocka7e24c12009-10-30 11:49:00 +0000354
355
356void Logger::ProfilerBeginEvent() {
357 if (!Log::IsEnabled()) return;
358 LogMessageBuilder msg;
359 msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
Steve Blocka7e24c12009-10-30 11:49:00 +0000360 msg.WriteToLogFile();
361}
362
363#endif // ENABLE_LOGGING_AND_PROFILING
364
365
Steve Blocka7e24c12009-10-30 11:49:00 +0000366void Logger::StringEvent(const char* name, const char* value) {
367#ifdef ENABLE_LOGGING_AND_PROFILING
368 if (FLAG_log) UncheckedStringEvent(name, value);
369#endif
370}
371
372
373#ifdef ENABLE_LOGGING_AND_PROFILING
374void Logger::UncheckedStringEvent(const char* name, const char* value) {
375 if (!Log::IsEnabled()) return;
376 LogMessageBuilder msg;
377 msg.Append("%s,\"%s\"\n", name, value);
378 msg.WriteToLogFile();
379}
380#endif
381
382
383void Logger::IntEvent(const char* name, int value) {
384#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Block6ded16b2010-05-10 14:33:55 +0100385 if (FLAG_log) UncheckedIntEvent(name, value);
386#endif
387}
388
389
Ben Murdochf87a2032010-10-22 12:50:53 +0100390void Logger::IntPtrTEvent(const char* name, intptr_t value) {
391#ifdef ENABLE_LOGGING_AND_PROFILING
392 if (FLAG_log) UncheckedIntPtrTEvent(name, value);
393#endif
394}
395
396
Steve Block6ded16b2010-05-10 14:33:55 +0100397#ifdef ENABLE_LOGGING_AND_PROFILING
398void Logger::UncheckedIntEvent(const char* name, int value) {
399 if (!Log::IsEnabled()) return;
Steve Blocka7e24c12009-10-30 11:49:00 +0000400 LogMessageBuilder msg;
401 msg.Append("%s,%d\n", name, value);
402 msg.WriteToLogFile();
Steve Blocka7e24c12009-10-30 11:49:00 +0000403}
Steve Block6ded16b2010-05-10 14:33:55 +0100404#endif
Steve Blocka7e24c12009-10-30 11:49:00 +0000405
406
Ben Murdochf87a2032010-10-22 12:50:53 +0100407#ifdef ENABLE_LOGGING_AND_PROFILING
408void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
409 if (!Log::IsEnabled()) return;
410 LogMessageBuilder msg;
411 msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
412 msg.WriteToLogFile();
413}
414#endif
415
416
Steve Blocka7e24c12009-10-30 11:49:00 +0000417void Logger::HandleEvent(const char* name, Object** location) {
418#ifdef ENABLE_LOGGING_AND_PROFILING
419 if (!Log::IsEnabled() || !FLAG_log_handles) return;
420 LogMessageBuilder msg;
421 msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
422 msg.WriteToLogFile();
423#endif
424}
425
426
427#ifdef ENABLE_LOGGING_AND_PROFILING
428// ApiEvent is private so all the calls come from the Logger class. It is the
429// caller's responsibility to ensure that log is enabled and that
430// FLAG_log_api is true.
431void Logger::ApiEvent(const char* format, ...) {
432 ASSERT(Log::IsEnabled() && FLAG_log_api);
433 LogMessageBuilder msg;
434 va_list ap;
435 va_start(ap, format);
436 msg.AppendVA(format, ap);
437 va_end(ap);
438 msg.WriteToLogFile();
439}
440#endif
441
442
443void Logger::ApiNamedSecurityCheck(Object* key) {
444#ifdef ENABLE_LOGGING_AND_PROFILING
445 if (!Log::IsEnabled() || !FLAG_log_api) return;
446 if (key->IsString()) {
447 SmartPointer<char> str =
448 String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
449 ApiEvent("api,check-security,\"%s\"\n", *str);
450 } else if (key->IsUndefined()) {
451 ApiEvent("api,check-security,undefined\n");
452 } else {
453 ApiEvent("api,check-security,['no-name']\n");
454 }
455#endif
456}
457
458
459void Logger::SharedLibraryEvent(const char* library_path,
460 uintptr_t start,
461 uintptr_t end) {
462#ifdef ENABLE_LOGGING_AND_PROFILING
463 if (!Log::IsEnabled() || !FLAG_prof) return;
464 LogMessageBuilder msg;
465 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
466 library_path,
467 start,
468 end);
469 msg.WriteToLogFile();
470#endif
471}
472
473
474void Logger::SharedLibraryEvent(const wchar_t* library_path,
475 uintptr_t start,
476 uintptr_t end) {
477#ifdef ENABLE_LOGGING_AND_PROFILING
478 if (!Log::IsEnabled() || !FLAG_prof) return;
479 LogMessageBuilder msg;
480 msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
481 library_path,
482 start,
483 end);
484 msg.WriteToLogFile();
485#endif
486}
487
488
489#ifdef ENABLE_LOGGING_AND_PROFILING
490void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
491 // Prints "/" + re.source + "/" +
492 // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
493 LogMessageBuilder msg;
494
495 Handle<Object> source = GetProperty(regexp, "source");
496 if (!source->IsString()) {
497 msg.Append("no source");
498 return;
499 }
500
501 switch (regexp->TypeTag()) {
502 case JSRegExp::ATOM:
503 msg.Append('a');
504 break;
505 default:
506 break;
507 }
508 msg.Append('/');
509 msg.AppendDetailed(*Handle<String>::cast(source), false);
510 msg.Append('/');
511
512 // global flag
513 Handle<Object> global = GetProperty(regexp, "global");
514 if (global->IsTrue()) {
515 msg.Append('g');
516 }
517 // ignorecase flag
518 Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
519 if (ignorecase->IsTrue()) {
520 msg.Append('i');
521 }
522 // multiline flag
523 Handle<Object> multiline = GetProperty(regexp, "multiline");
524 if (multiline->IsTrue()) {
525 msg.Append('m');
526 }
527
528 msg.WriteToLogFile();
529}
530#endif // ENABLE_LOGGING_AND_PROFILING
531
532
533void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
534#ifdef ENABLE_LOGGING_AND_PROFILING
535 if (!Log::IsEnabled() || !FLAG_log_regexp) return;
536 LogMessageBuilder msg;
537 msg.Append("regexp-compile,");
538 LogRegExpSource(regexp);
539 msg.Append(in_cache ? ",hit\n" : ",miss\n");
540 msg.WriteToLogFile();
541#endif
542}
543
544
545void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
546#ifdef ENABLE_LOGGING_AND_PROFILING
547 if (!Log::IsEnabled() || !FLAG_log_runtime) return;
548 HandleScope scope;
549 LogMessageBuilder msg;
550 for (int i = 0; i < format.length(); i++) {
551 char c = format[i];
552 if (c == '%' && i <= format.length() - 2) {
553 i++;
554 ASSERT('0' <= format[i] && format[i] <= '9');
John Reck59135872010-11-02 12:39:01 -0700555 MaybeObject* maybe = args->GetElement(format[i] - '0');
556 Object* obj;
557 if (!maybe->ToObject(&obj)) {
558 msg.Append("<exception>");
559 continue;
560 }
Steve Blocka7e24c12009-10-30 11:49:00 +0000561 i++;
562 switch (format[i]) {
563 case 's':
564 msg.AppendDetailed(String::cast(obj), false);
565 break;
566 case 'S':
567 msg.AppendDetailed(String::cast(obj), true);
568 break;
569 case 'r':
570 Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
571 break;
572 case 'x':
573 msg.Append("0x%x", Smi::cast(obj)->value());
574 break;
575 case 'i':
576 msg.Append("%i", Smi::cast(obj)->value());
577 break;
578 default:
579 UNREACHABLE();
580 }
581 } else {
582 msg.Append(c);
583 }
584 }
585 msg.Append('\n');
586 msg.WriteToLogFile();
587#endif
588}
589
590
591void Logger::ApiIndexedSecurityCheck(uint32_t index) {
592#ifdef ENABLE_LOGGING_AND_PROFILING
593 if (!Log::IsEnabled() || !FLAG_log_api) return;
594 ApiEvent("api,check-security,%u\n", index);
595#endif
596}
597
598
599void Logger::ApiNamedPropertyAccess(const char* tag,
600 JSObject* holder,
601 Object* name) {
602#ifdef ENABLE_LOGGING_AND_PROFILING
603 ASSERT(name->IsString());
604 if (!Log::IsEnabled() || !FLAG_log_api) return;
605 String* class_name_obj = holder->class_name();
606 SmartPointer<char> class_name =
607 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
608 SmartPointer<char> property_name =
609 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
610 Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
611#endif
612}
613
614void Logger::ApiIndexedPropertyAccess(const char* tag,
615 JSObject* holder,
616 uint32_t index) {
617#ifdef ENABLE_LOGGING_AND_PROFILING
618 if (!Log::IsEnabled() || !FLAG_log_api) return;
619 String* class_name_obj = holder->class_name();
620 SmartPointer<char> class_name =
621 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
622 Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
623#endif
624}
625
626void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
627#ifdef ENABLE_LOGGING_AND_PROFILING
628 if (!Log::IsEnabled() || !FLAG_log_api) return;
629 String* class_name_obj = object->class_name();
630 SmartPointer<char> class_name =
631 class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
632 Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
633#endif
634}
635
636
637void Logger::ApiEntryCall(const char* name) {
638#ifdef ENABLE_LOGGING_AND_PROFILING
639 if (!Log::IsEnabled() || !FLAG_log_api) return;
640 Logger::ApiEvent("api,%s\n", name);
641#endif
642}
643
644
645void Logger::NewEvent(const char* name, void* object, size_t size) {
646#ifdef ENABLE_LOGGING_AND_PROFILING
647 if (!Log::IsEnabled() || !FLAG_log) return;
648 LogMessageBuilder msg;
649 msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
650 static_cast<unsigned int>(size));
651 msg.WriteToLogFile();
652#endif
653}
654
655
656void Logger::DeleteEvent(const char* name, void* object) {
657#ifdef ENABLE_LOGGING_AND_PROFILING
658 if (!Log::IsEnabled() || !FLAG_log) return;
659 LogMessageBuilder msg;
660 msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
661 msg.WriteToLogFile();
662#endif
663}
664
665
666#ifdef ENABLE_LOGGING_AND_PROFILING
Steve Blockd0582a62009-12-15 09:54:21 +0000667void Logger::CallbackEventInternal(const char* prefix, const char* name,
668 Address entry_point) {
669 if (!Log::IsEnabled() || !FLAG_log_code) return;
670 LogMessageBuilder msg;
671 msg.Append("%s,%s,",
Ben Murdochb0fe1622011-05-05 13:52:32 +0100672 kLogEventsNames[CODE_CREATION_EVENT],
673 kLogEventsNames[CALLBACK_TAG]);
Steve Blockd0582a62009-12-15 09:54:21 +0000674 msg.AppendAddress(entry_point);
675 msg.Append(",1,\"%s%s\"", prefix, name);
Steve Blockd0582a62009-12-15 09:54:21 +0000676 msg.Append('\n');
677 msg.WriteToLogFile();
678}
679#endif
680
681
682void Logger::CallbackEvent(String* name, Address entry_point) {
683#ifdef ENABLE_LOGGING_AND_PROFILING
684 if (!Log::IsEnabled() || !FLAG_log_code) return;
685 SmartPointer<char> str =
686 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
687 CallbackEventInternal("", *str, entry_point);
688#endif
689}
690
691
692void Logger::GetterCallbackEvent(String* name, Address entry_point) {
693#ifdef ENABLE_LOGGING_AND_PROFILING
694 if (!Log::IsEnabled() || !FLAG_log_code) return;
695 SmartPointer<char> str =
696 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
697 CallbackEventInternal("get ", *str, entry_point);
698#endif
699}
700
701
702void Logger::SetterCallbackEvent(String* name, Address entry_point) {
703#ifdef ENABLE_LOGGING_AND_PROFILING
704 if (!Log::IsEnabled() || !FLAG_log_code) return;
705 SmartPointer<char> str =
706 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
707 CallbackEventInternal("set ", *str, entry_point);
708#endif
709}
710
711
Ben Murdochb0fe1622011-05-05 13:52:32 +0100712#ifdef ENABLE_LOGGING_AND_PROFILING
713static const char* ComputeMarker(Code* code) {
714 switch (code->kind()) {
715 case Code::FUNCTION: return code->optimizable() ? "~" : "";
716 case Code::OPTIMIZED_FUNCTION: return "*";
717 default: return "";
718 }
719}
720#endif
721
722
Steve Blocka7e24c12009-10-30 11:49:00 +0000723void Logger::CodeCreateEvent(LogEventsAndTags tag,
724 Code* code,
725 const char* comment) {
726#ifdef ENABLE_LOGGING_AND_PROFILING
727 if (!Log::IsEnabled() || !FLAG_log_code) return;
728 LogMessageBuilder msg;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100729 msg.Append("%s,%s,",
730 kLogEventsNames[CODE_CREATION_EVENT],
731 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000732 msg.AppendAddress(code->address());
Ben Murdochb0fe1622011-05-05 13:52:32 +0100733 msg.Append(",%d,\"%s", code->ExecutableSize(), ComputeMarker(code));
Steve Blocka7e24c12009-10-30 11:49:00 +0000734 for (const char* p = comment; *p != '\0'; p++) {
735 if (*p == '"') {
736 msg.Append('\\');
737 }
738 msg.Append(*p);
739 }
740 msg.Append('"');
Ben Murdochf87a2032010-10-22 12:50:53 +0100741 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000742 msg.Append('\n');
743 msg.WriteToLogFile();
744#endif
745}
746
747
748void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
749#ifdef ENABLE_LOGGING_AND_PROFILING
750 if (!Log::IsEnabled() || !FLAG_log_code) return;
751 LogMessageBuilder msg;
752 SmartPointer<char> str =
753 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100754 msg.Append("%s,%s,",
755 kLogEventsNames[CODE_CREATION_EVENT],
756 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000757 msg.AppendAddress(code->address());
Ben Murdochb0fe1622011-05-05 13:52:32 +0100758 msg.Append(",%d,\"%s%s\"", code->ExecutableSize(), ComputeMarker(code), *str);
Ben Murdochf87a2032010-10-22 12:50:53 +0100759 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000760 msg.Append('\n');
761 msg.WriteToLogFile();
762#endif
763}
764
765
766void Logger::CodeCreateEvent(LogEventsAndTags tag,
767 Code* code, String* name,
768 String* source, int line) {
769#ifdef ENABLE_LOGGING_AND_PROFILING
770 if (!Log::IsEnabled() || !FLAG_log_code) return;
771 LogMessageBuilder msg;
772 SmartPointer<char> str =
773 name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
774 SmartPointer<char> sourcestr =
775 source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
Ben Murdochb0fe1622011-05-05 13:52:32 +0100776 msg.Append("%s,%s,",
777 kLogEventsNames[CODE_CREATION_EVENT],
778 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000779 msg.AppendAddress(code->address());
Ben Murdochb0fe1622011-05-05 13:52:32 +0100780 msg.Append(",%d,\"%s%s %s:%d\"",
781 code->ExecutableSize(),
782 ComputeMarker(code),
783 *str,
784 *sourcestr,
785 line);
Ben Murdochf87a2032010-10-22 12:50:53 +0100786 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000787 msg.Append('\n');
788 msg.WriteToLogFile();
789#endif
790}
791
792
793void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
794#ifdef ENABLE_LOGGING_AND_PROFILING
795 if (!Log::IsEnabled() || !FLAG_log_code) return;
796 LogMessageBuilder msg;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100797 msg.Append("%s,%s,",
798 kLogEventsNames[CODE_CREATION_EVENT],
799 kLogEventsNames[tag]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000800 msg.AppendAddress(code->address());
801 msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
Ben Murdochf87a2032010-10-22 12:50:53 +0100802 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000803 msg.Append('\n');
804 msg.WriteToLogFile();
805#endif
806}
807
808
Ben Murdochf87a2032010-10-22 12:50:53 +0100809void Logger::CodeMovingGCEvent() {
810#ifdef ENABLE_LOGGING_AND_PROFILING
811 if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
812 LogMessageBuilder msg;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100813 msg.Append("%s\n", kLogEventsNames[CODE_MOVING_GC]);
Ben Murdochf87a2032010-10-22 12:50:53 +0100814 msg.WriteToLogFile();
815 OS::SignalCodeMovingGC();
816#endif
817}
818
819
Steve Blocka7e24c12009-10-30 11:49:00 +0000820void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
821#ifdef ENABLE_LOGGING_AND_PROFILING
822 if (!Log::IsEnabled() || !FLAG_log_code) return;
823 LogMessageBuilder msg;
824 msg.Append("%s,%s,",
Ben Murdochb0fe1622011-05-05 13:52:32 +0100825 kLogEventsNames[CODE_CREATION_EVENT],
826 kLogEventsNames[REG_EXP_TAG]);
Steve Blocka7e24c12009-10-30 11:49:00 +0000827 msg.AppendAddress(code->address());
828 msg.Append(",%d,\"", code->ExecutableSize());
829 msg.AppendDetailed(source, false);
830 msg.Append('\"');
Ben Murdochf87a2032010-10-22 12:50:53 +0100831 LowLevelCodeCreateEvent(code, &msg);
Steve Blocka7e24c12009-10-30 11:49:00 +0000832 msg.Append('\n');
833 msg.WriteToLogFile();
834#endif
835}
836
837
838void Logger::CodeMoveEvent(Address from, Address to) {
839#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000840 MoveEventInternal(CODE_MOVE_EVENT, from, to);
Steve Blocka7e24c12009-10-30 11:49:00 +0000841#endif
842}
843
844
845void Logger::CodeDeleteEvent(Address from) {
846#ifdef ENABLE_LOGGING_AND_PROFILING
Leon Clarked91b9f72010-01-27 17:25:45 +0000847 DeleteEventInternal(CODE_DELETE_EVENT, from);
Steve Blocka7e24c12009-10-30 11:49:00 +0000848#endif
849}
850
851
Leon Clarkee46be812010-01-19 14:06:41 +0000852void Logger::SnapshotPositionEvent(Address addr, int pos) {
853#ifdef ENABLE_LOGGING_AND_PROFILING
854 if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return;
855 LogMessageBuilder msg;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100856 msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
Leon Clarkee46be812010-01-19 14:06:41 +0000857 msg.AppendAddress(addr);
858 msg.Append(",%d", pos);
Leon Clarkee46be812010-01-19 14:06:41 +0000859 msg.Append('\n');
860 msg.WriteToLogFile();
861#endif
862}
863
864
Leon Clarked91b9f72010-01-27 17:25:45 +0000865void Logger::FunctionCreateEvent(JSFunction* function) {
866#ifdef ENABLE_LOGGING_AND_PROFILING
Kristian Monsen0d5e1162010-09-30 15:31:59 +0100867 // This function can be called from GC iterators (during Scavenge,
868 // MC, and MS), so marking bits can be set on objects. That's
869 // why unchecked accessors are used here.
Leon Clarked91b9f72010-01-27 17:25:45 +0000870 if (!Log::IsEnabled() || !FLAG_log_code) return;
871 LogMessageBuilder msg;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100872 msg.Append("%s,", kLogEventsNames[FUNCTION_CREATION_EVENT]);
Leon Clarked91b9f72010-01-27 17:25:45 +0000873 msg.AppendAddress(function->address());
874 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +0100875 msg.AppendAddress(function->unchecked_code()->address());
Leon Clarked91b9f72010-01-27 17:25:45 +0000876 msg.Append('\n');
877 msg.WriteToLogFile();
878#endif
879}
880
881
Ben Murdochf87a2032010-10-22 12:50:53 +0100882void Logger::FunctionCreateEventFromMove(JSFunction* function) {
Kristian Monsen0d5e1162010-09-30 15:31:59 +0100883#ifdef ENABLE_LOGGING_AND_PROFILING
884 if (function->unchecked_code() != Builtins::builtin(Builtins::LazyCompile)) {
885 FunctionCreateEvent(function);
886 }
887#endif
888}
889
890
Leon Clarked91b9f72010-01-27 17:25:45 +0000891void Logger::FunctionMoveEvent(Address from, Address to) {
892#ifdef ENABLE_LOGGING_AND_PROFILING
893 MoveEventInternal(FUNCTION_MOVE_EVENT, from, to);
894#endif
895}
896
897
898void Logger::FunctionDeleteEvent(Address from) {
899#ifdef ENABLE_LOGGING_AND_PROFILING
900 DeleteEventInternal(FUNCTION_DELETE_EVENT, from);
901#endif
902}
903
904
905#ifdef ENABLE_LOGGING_AND_PROFILING
906void Logger::MoveEventInternal(LogEventsAndTags event,
907 Address from,
908 Address to) {
Leon Clarked91b9f72010-01-27 17:25:45 +0000909 if (!Log::IsEnabled() || !FLAG_log_code) return;
910 LogMessageBuilder msg;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100911 msg.Append("%s,", kLogEventsNames[event]);
Leon Clarked91b9f72010-01-27 17:25:45 +0000912 msg.AppendAddress(from);
913 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +0100914 msg.AppendAddress(to);
Leon Clarked91b9f72010-01-27 17:25:45 +0000915 msg.Append('\n');
916 msg.WriteToLogFile();
917}
918#endif
919
920
921#ifdef ENABLE_LOGGING_AND_PROFILING
922void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
923 if (!Log::IsEnabled() || !FLAG_log_code) return;
924 LogMessageBuilder msg;
Ben Murdochb0fe1622011-05-05 13:52:32 +0100925 msg.Append("%s,", kLogEventsNames[event]);
Leon Clarked91b9f72010-01-27 17:25:45 +0000926 msg.AppendAddress(from);
Leon Clarked91b9f72010-01-27 17:25:45 +0000927 msg.Append('\n');
928 msg.WriteToLogFile();
929}
930#endif
931
932
Steve Blocka7e24c12009-10-30 11:49:00 +0000933void Logger::ResourceEvent(const char* name, const char* tag) {
934#ifdef ENABLE_LOGGING_AND_PROFILING
935 if (!Log::IsEnabled() || !FLAG_log) return;
936 LogMessageBuilder msg;
937 msg.Append("%s,%s,", name, tag);
938
939 uint32_t sec, usec;
940 if (OS::GetUserTime(&sec, &usec) != -1) {
941 msg.Append("%d,%d,", sec, usec);
942 }
943 msg.Append("%.0f", OS::TimeCurrentMillis());
944
945 msg.Append('\n');
946 msg.WriteToLogFile();
947#endif
948}
949
950
951void Logger::SuspectReadEvent(String* name, Object* obj) {
952#ifdef ENABLE_LOGGING_AND_PROFILING
953 if (!Log::IsEnabled() || !FLAG_log_suspect) return;
954 LogMessageBuilder msg;
955 String* class_name = obj->IsJSObject()
956 ? JSObject::cast(obj)->class_name()
957 : Heap::empty_string();
958 msg.Append("suspect-read,");
959 msg.Append(class_name);
960 msg.Append(',');
961 msg.Append('"');
962 msg.Append(name);
963 msg.Append('"');
964 msg.Append('\n');
965 msg.WriteToLogFile();
966#endif
967}
968
969
970void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
971#ifdef ENABLE_LOGGING_AND_PROFILING
972 if (!Log::IsEnabled() || !FLAG_log_gc) return;
973 LogMessageBuilder msg;
974 // Using non-relative system time in order to be able to synchronize with
975 // external memory profiling events (e.g. DOM memory size).
976 msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
977 space, kind, OS::TimeCurrentMillis());
978 msg.WriteToLogFile();
979#endif
980}
981
982
983void Logger::HeapSampleStats(const char* space, const char* kind,
Ben Murdochf87a2032010-10-22 12:50:53 +0100984 intptr_t capacity, intptr_t used) {
Steve Blocka7e24c12009-10-30 11:49:00 +0000985#ifdef ENABLE_LOGGING_AND_PROFILING
986 if (!Log::IsEnabled() || !FLAG_log_gc) return;
987 LogMessageBuilder msg;
Ben Murdochf87a2032010-10-22 12:50:53 +0100988 msg.Append("heap-sample-stats,\"%s\",\"%s\","
989 "%" V8_PTR_PREFIX "d,%" V8_PTR_PREFIX "d\n",
Steve Blocka7e24c12009-10-30 11:49:00 +0000990 space, kind, capacity, used);
991 msg.WriteToLogFile();
992#endif
993}
994
995
996void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
997#ifdef ENABLE_LOGGING_AND_PROFILING
998 if (!Log::IsEnabled() || !FLAG_log_gc) return;
999 LogMessageBuilder msg;
1000 msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
1001 msg.WriteToLogFile();
1002#endif
1003}
1004
1005
1006void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
1007#ifdef ENABLE_LOGGING_AND_PROFILING
1008 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1009 LogMessageBuilder msg;
1010 msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
1011 msg.WriteToLogFile();
1012#endif
1013}
1014
1015
1016void Logger::HeapSampleJSConstructorEvent(const char* constructor,
1017 int number, int bytes) {
1018#ifdef ENABLE_LOGGING_AND_PROFILING
1019 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1020 LogMessageBuilder msg;
1021 msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
1022 msg.WriteToLogFile();
1023#endif
1024}
1025
1026
1027void Logger::HeapSampleJSRetainersEvent(
1028 const char* constructor, const char* event) {
1029#ifdef ENABLE_LOGGING_AND_PROFILING
1030 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1031 // Event starts with comma, so we don't have it in the format string.
1032 static const char* event_text = "heap-js-ret-item,%s";
1033 // We take placeholder strings into account, but it's OK to be conservative.
Steve Blockd0582a62009-12-15 09:54:21 +00001034 static const int event_text_len = StrLength(event_text);
1035 const int cons_len = StrLength(constructor);
1036 const int event_len = StrLength(event);
Steve Blocka7e24c12009-10-30 11:49:00 +00001037 int pos = 0;
1038 // Retainer lists can be long. We may need to split them into multiple events.
1039 do {
1040 LogMessageBuilder msg;
1041 msg.Append(event_text, constructor);
1042 int to_write = event_len - pos;
1043 if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) {
1044 int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len);
1045 ASSERT(cut_pos < event_len);
1046 while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
1047 if (event[cut_pos] != ',') {
1048 // Crash in debug mode, skip in release mode.
1049 ASSERT(false);
1050 return;
1051 }
1052 // Append a piece of event that fits, without trailing comma.
1053 msg.AppendStringPart(event + pos, cut_pos - pos);
1054 // Start next piece with comma.
1055 pos = cut_pos;
1056 } else {
1057 msg.Append("%s", event + pos);
1058 pos += event_len;
1059 }
1060 msg.Append('\n');
1061 msg.WriteToLogFile();
1062 } while (pos < event_len);
1063#endif
1064}
1065
1066
Steve Block3ce2e202009-11-05 08:53:23 +00001067void Logger::HeapSampleJSProducerEvent(const char* constructor,
1068 Address* stack) {
1069#ifdef ENABLE_LOGGING_AND_PROFILING
1070 if (!Log::IsEnabled() || !FLAG_log_gc) return;
1071 LogMessageBuilder msg;
1072 msg.Append("heap-js-prod-item,%s", constructor);
1073 while (*stack != NULL) {
1074 msg.Append(",0x%" V8PRIxPTR, *stack++);
1075 }
1076 msg.Append("\n");
1077 msg.WriteToLogFile();
1078#endif
1079}
1080
1081
Steve Blocka7e24c12009-10-30 11:49:00 +00001082void Logger::DebugTag(const char* call_site_tag) {
1083#ifdef ENABLE_LOGGING_AND_PROFILING
1084 if (!Log::IsEnabled() || !FLAG_log) return;
1085 LogMessageBuilder msg;
1086 msg.Append("debug-tag,%s\n", call_site_tag);
1087 msg.WriteToLogFile();
1088#endif
1089}
1090
1091
1092void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
1093#ifdef ENABLE_LOGGING_AND_PROFILING
1094 if (!Log::IsEnabled() || !FLAG_log) return;
1095 StringBuilder s(parameter.length() + 1);
1096 for (int i = 0; i < parameter.length(); ++i) {
1097 s.AddCharacter(static_cast<char>(parameter[i]));
1098 }
1099 char* parameter_string = s.Finalize();
1100 LogMessageBuilder msg;
1101 msg.Append("debug-queue-event,%s,%15.3f,%s\n",
1102 event_type,
1103 OS::TimeCurrentMillis(),
1104 parameter_string);
1105 DeleteArray(parameter_string);
1106 msg.WriteToLogFile();
1107#endif
1108}
1109
1110
1111#ifdef ENABLE_LOGGING_AND_PROFILING
1112void Logger::TickEvent(TickSample* sample, bool overflow) {
1113 if (!Log::IsEnabled() || !FLAG_prof) return;
Steve Blocka7e24c12009-10-30 11:49:00 +00001114 LogMessageBuilder msg;
Ben Murdochb0fe1622011-05-05 13:52:32 +01001115 msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
1116 msg.AppendAddress(sample->pc);
Steve Blocka7e24c12009-10-30 11:49:00 +00001117 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +01001118 msg.AppendAddress(sample->sp);
Leon Clarked91b9f72010-01-27 17:25:45 +00001119 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +01001120 msg.AppendAddress(sample->function);
Steve Blocka7e24c12009-10-30 11:49:00 +00001121 msg.Append(",%d", static_cast<int>(sample->state));
1122 if (overflow) {
1123 msg.Append(",overflow");
1124 }
1125 for (int i = 0; i < sample->frames_count; ++i) {
1126 msg.Append(',');
Ben Murdochb0fe1622011-05-05 13:52:32 +01001127 msg.AppendAddress(sample->stack[i]);
Steve Blocka7e24c12009-10-30 11:49:00 +00001128 }
1129 msg.Append('\n');
1130 msg.WriteToLogFile();
1131}
1132
1133
1134int Logger::GetActiveProfilerModules() {
1135 int result = PROFILER_MODULE_NONE;
Steve Block8defd9f2010-07-08 12:39:36 +01001136 if (profiler_ != NULL && !profiler_->paused()) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001137 result |= PROFILER_MODULE_CPU;
1138 }
1139 if (FLAG_log_gc) {
1140 result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
1141 }
1142 return result;
1143}
1144
1145
Andrei Popescu402d9372010-02-26 13:31:12 +00001146void Logger::PauseProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001147 if (!Log::IsEnabled()) return;
Steve Block8defd9f2010-07-08 12:39:36 +01001148 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001149 // It is OK to have negative nesting.
1150 if (--cpu_profiler_nesting_ == 0) {
1151 profiler_->pause();
1152 if (FLAG_prof_lazy) {
Ben Murdochb0fe1622011-05-05 13:52:32 +01001153 if (!FLAG_sliding_state_window && !RuntimeProfiler::IsEnabled()) {
1154 ticker_->Stop();
1155 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001156 FLAG_log_code = false;
1157 // Must be the same message as Log::kDynamicBufferSeal.
1158 LOG(UncheckedStringEvent("profiler", "pause"));
1159 }
Steve Block6ded16b2010-05-10 14:33:55 +01001160 --logging_nesting_;
Steve Blocka7e24c12009-10-30 11:49:00 +00001161 }
1162 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001163 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001164 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001165 if (--heap_profiler_nesting_ == 0) {
1166 FLAG_log_gc = false;
Steve Block6ded16b2010-05-10 14:33:55 +01001167 --logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001168 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001169 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001170 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001171 UncheckedIntEvent("close-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001172 }
1173}
1174
1175
Andrei Popescu402d9372010-02-26 13:31:12 +00001176void Logger::ResumeProfiler(int flags, int tag) {
Steve Blocka7e24c12009-10-30 11:49:00 +00001177 if (!Log::IsEnabled()) return;
Andrei Popescu402d9372010-02-26 13:31:12 +00001178 if (tag != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001179 UncheckedIntEvent("open-tag", tag);
Steve Blocka7e24c12009-10-30 11:49:00 +00001180 }
Steve Block8defd9f2010-07-08 12:39:36 +01001181 if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001182 if (cpu_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001183 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001184 if (FLAG_prof_lazy) {
1185 profiler_->Engage();
1186 LOG(UncheckedStringEvent("profiler", "resume"));
1187 FLAG_log_code = true;
1188 LogCompiledFunctions();
1189 LogFunctionObjects();
1190 LogAccessorCallbacks();
Ben Murdochb0fe1622011-05-05 13:52:32 +01001191 if (!FLAG_sliding_state_window && !ticker_->IsActive()) {
1192 ticker_->Start();
1193 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001194 }
1195 profiler_->resume();
Steve Blocka7e24c12009-10-30 11:49:00 +00001196 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001197 }
Andrei Popescu402d9372010-02-26 13:31:12 +00001198 if (flags &
Steve Blocka7e24c12009-10-30 11:49:00 +00001199 (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
Andrei Popescu402d9372010-02-26 13:31:12 +00001200 if (heap_profiler_nesting_++ == 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001201 ++logging_nesting_;
Andrei Popescu402d9372010-02-26 13:31:12 +00001202 FLAG_log_gc = true;
1203 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001204 }
1205}
1206
1207
1208// This function can be called when Log's mutex is acquired,
1209// either from main or Profiler's thread.
1210void Logger::StopLoggingAndProfiling() {
1211 Log::stop();
Andrei Popescu402d9372010-02-26 13:31:12 +00001212 PauseProfiler(PROFILER_MODULE_CPU, 0);
Steve Blocka7e24c12009-10-30 11:49:00 +00001213}
1214
1215
1216bool Logger::IsProfilerSamplerActive() {
1217 return ticker_->IsActive();
1218}
1219
1220
1221int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
1222 return Log::GetLogLines(from_pos, dest_buf, max_size);
1223}
1224
1225
Ben Murdochb0fe1622011-05-05 13:52:32 +01001226class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
1227 public:
1228 EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
1229 Handle<Code>* code_objects,
1230 int* count)
1231 : sfis_(sfis), code_objects_(code_objects), count_(count) { }
1232
1233 virtual void EnterContext(Context* context) {}
1234 virtual void LeaveContext(Context* context) {}
1235
1236 virtual void VisitFunction(JSFunction* function) {
1237 if (sfis_ != NULL) {
1238 sfis_[*count_] = Handle<SharedFunctionInfo>(function->shared());
1239 }
1240 if (code_objects_ != NULL) {
1241 ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
1242 code_objects_[*count_] = Handle<Code>(function->code());
1243 }
1244 *count_ = *count_ + 1;
1245 }
1246
1247 private:
1248 Handle<SharedFunctionInfo>* sfis_;
1249 Handle<Code>* code_objects_;
1250 int* count_;
1251};
1252
1253
1254static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis,
1255 Handle<Code>* code_objects) {
Steve Block3ce2e202009-11-05 08:53:23 +00001256 AssertNoAllocation no_alloc;
Steve Blocka7e24c12009-10-30 11:49:00 +00001257 int compiled_funcs_count = 0;
Ben Murdochb0fe1622011-05-05 13:52:32 +01001258
1259 // Iterate the heap to find shared function info objects and record
1260 // the unoptimized code for them.
Steve Block3ce2e202009-11-05 08:53:23 +00001261 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001262 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Block3ce2e202009-11-05 08:53:23 +00001263 if (!obj->IsSharedFunctionInfo()) continue;
1264 SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
1265 if (sfi->is_compiled()
1266 && (!sfi->script()->IsScript()
1267 || Script::cast(sfi->script())->HasValidSource())) {
Ben Murdochb0fe1622011-05-05 13:52:32 +01001268 if (sfis != NULL) {
Steve Block3ce2e202009-11-05 08:53:23 +00001269 sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001270 }
1271 if (code_objects != NULL) {
1272 code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
1273 }
Steve Block3ce2e202009-11-05 08:53:23 +00001274 ++compiled_funcs_count;
Steve Blocka7e24c12009-10-30 11:49:00 +00001275 }
1276 }
Ben Murdochb0fe1622011-05-05 13:52:32 +01001277
1278 // Iterate all optimized functions in all contexts.
1279 EnumerateOptimizedFunctionsVisitor visitor(sfis,
1280 code_objects,
1281 &compiled_funcs_count);
1282 Deoptimizer::VisitAllOptimizedFunctions(&visitor);
1283
Steve Block3ce2e202009-11-05 08:53:23 +00001284 return compiled_funcs_count;
1285}
1286
1287
Steve Blockd0582a62009-12-15 09:54:21 +00001288void Logger::LogCodeObject(Object* object) {
1289 if (FLAG_log_code) {
1290 Code* code_object = Code::cast(object);
1291 LogEventsAndTags tag = Logger::STUB_TAG;
1292 const char* description = "Unknown code from the snapshot";
1293 switch (code_object->kind()) {
1294 case Code::FUNCTION:
Ben Murdochb0fe1622011-05-05 13:52:32 +01001295 case Code::OPTIMIZED_FUNCTION:
Steve Blockd0582a62009-12-15 09:54:21 +00001296 return; // We log this later using LogCompiledFunctions.
Ben Murdochb0fe1622011-05-05 13:52:32 +01001297 case Code::BINARY_OP_IC: // fall through
1298 case Code::TYPE_RECORDING_BINARY_OP_IC: // fall through
1299 case Code::COMPARE_IC: // fall through
Steve Blockd0582a62009-12-15 09:54:21 +00001300 case Code::STUB:
Kristian Monsen80d68ea2010-09-08 11:05:35 +01001301 description =
1302 CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
Andrei Popescu31002712010-02-23 13:46:05 +00001303 if (description == NULL)
1304 description = "A stub from the snapshot";
Steve Blockd0582a62009-12-15 09:54:21 +00001305 tag = Logger::STUB_TAG;
1306 break;
1307 case Code::BUILTIN:
1308 description = "A builtin from the snapshot";
1309 tag = Logger::BUILTIN_TAG;
1310 break;
1311 case Code::KEYED_LOAD_IC:
1312 description = "A keyed load IC from the snapshot";
1313 tag = Logger::KEYED_LOAD_IC_TAG;
1314 break;
1315 case Code::LOAD_IC:
1316 description = "A load IC from the snapshot";
1317 tag = Logger::LOAD_IC_TAG;
1318 break;
1319 case Code::STORE_IC:
1320 description = "A store IC from the snapshot";
1321 tag = Logger::STORE_IC_TAG;
1322 break;
1323 case Code::KEYED_STORE_IC:
1324 description = "A keyed store IC from the snapshot";
1325 tag = Logger::KEYED_STORE_IC_TAG;
1326 break;
1327 case Code::CALL_IC:
1328 description = "A call IC from the snapshot";
1329 tag = Logger::CALL_IC_TAG;
1330 break;
Ben Murdoch7f4d5bd2010-06-15 11:15:29 +01001331 case Code::KEYED_CALL_IC:
1332 description = "A keyed call IC from the snapshot";
1333 tag = Logger::KEYED_CALL_IC_TAG;
1334 break;
Steve Blockd0582a62009-12-15 09:54:21 +00001335 }
Steve Block6ded16b2010-05-10 14:33:55 +01001336 PROFILE(CodeCreateEvent(tag, code_object, description));
Steve Blockd0582a62009-12-15 09:54:21 +00001337 }
1338}
1339
1340
Ben Murdochf87a2032010-10-22 12:50:53 +01001341void Logger::LogCodeInfo() {
1342#ifdef ENABLE_LOGGING_AND_PROFILING
1343 if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
1344#if V8_TARGET_ARCH_IA32
1345 const char arch[] = "ia32";
1346#elif V8_TARGET_ARCH_X64
1347 const char arch[] = "x64";
1348#elif V8_TARGET_ARCH_ARM
1349 const char arch[] = "arm";
1350#else
1351 const char arch[] = "unknown";
1352#endif
1353 LogMessageBuilder msg;
1354 msg.Append("code-info,%s,%d\n", arch, Code::kHeaderSize);
1355 msg.WriteToLogFile();
1356#endif // ENABLE_LOGGING_AND_PROFILING
1357}
1358
1359
1360void Logger::LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg) {
1361 if (!FLAG_ll_prof || Log::output_code_handle_ == NULL) return;
1362 int pos = static_cast<int>(ftell(Log::output_code_handle_));
John Reck59135872010-11-02 12:39:01 -07001363 size_t rv = fwrite(code->instruction_start(), 1, code->instruction_size(),
1364 Log::output_code_handle_);
1365 ASSERT(static_cast<size_t>(code->instruction_size()) == rv);
1366 USE(rv);
Ben Murdochf87a2032010-10-22 12:50:53 +01001367 msg->Append(",%d", pos);
1368}
1369
1370
Andrei Popescu31002712010-02-23 13:46:05 +00001371void Logger::LogCodeObjects() {
1372 AssertNoAllocation no_alloc;
1373 HeapIterator iterator;
1374 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1375 if (obj->IsCode()) LogCodeObject(obj);
1376 }
1377}
1378
1379
Steve Block3ce2e202009-11-05 08:53:23 +00001380void Logger::LogCompiledFunctions() {
1381 HandleScope scope;
Ben Murdochb0fe1622011-05-05 13:52:32 +01001382 const int compiled_funcs_count = EnumerateCompiledFunctions(NULL, NULL);
Kristian Monsen25f61362010-05-21 11:50:48 +01001383 ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
Ben Murdochb0fe1622011-05-05 13:52:32 +01001384 ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
1385 EnumerateCompiledFunctions(sfis.start(), code_objects.start());
Steve Blocka7e24c12009-10-30 11:49:00 +00001386
1387 // During iteration, there can be heap allocation due to
1388 // GetScriptLineNumber call.
1389 for (int i = 0; i < compiled_funcs_count; ++i) {
1390 Handle<SharedFunctionInfo> shared = sfis[i];
1391 Handle<String> name(String::cast(shared->name()));
1392 Handle<String> func_name(name->length() > 0 ?
1393 *name : shared->inferred_name());
1394 if (shared->script()->IsScript()) {
1395 Handle<Script> script(Script::cast(shared->script()));
1396 if (script->name()->IsString()) {
1397 Handle<String> script_name(String::cast(script->name()));
1398 int line_num = GetScriptLineNumber(script, shared->start_position());
1399 if (line_num > 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001400 PROFILE(CodeCreateEvent(
1401 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
Ben Murdochb0fe1622011-05-05 13:52:32 +01001402 *code_objects[i], *func_name,
Steve Block6ded16b2010-05-10 14:33:55 +01001403 *script_name, line_num + 1));
Steve Blocka7e24c12009-10-30 11:49:00 +00001404 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001405 // Can't distinguish eval and script here, so always use Script.
1406 PROFILE(CodeCreateEvent(
1407 Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
Ben Murdochb0fe1622011-05-05 13:52:32 +01001408 *code_objects[i], *script_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001409 }
Steve Blockd0582a62009-12-15 09:54:21 +00001410 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001411 PROFILE(CodeCreateEvent(
1412 Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
Ben Murdochb0fe1622011-05-05 13:52:32 +01001413 *code_objects[i], *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001414 }
Steve Block6ded16b2010-05-10 14:33:55 +01001415 } else if (shared->IsApiFunction()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001416 // API function.
Steve Block6ded16b2010-05-10 14:33:55 +01001417 FunctionTemplateInfo* fun_data = shared->get_api_func_data();
Steve Blockd0582a62009-12-15 09:54:21 +00001418 Object* raw_call_data = fun_data->call_code();
1419 if (!raw_call_data->IsUndefined()) {
1420 CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
1421 Object* callback_obj = call_data->callback();
1422 Address entry_point = v8::ToCData<Address>(callback_obj);
Steve Block6ded16b2010-05-10 14:33:55 +01001423 PROFILE(CallbackEvent(*func_name, entry_point));
Steve Blockd0582a62009-12-15 09:54:21 +00001424 }
1425 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001426 PROFILE(CodeCreateEvent(
Ben Murdochb0fe1622011-05-05 13:52:32 +01001427 Logger::LAZY_COMPILE_TAG, *code_objects[i], *func_name));
Steve Blocka7e24c12009-10-30 11:49:00 +00001428 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001429 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001430}
1431
Steve Blockd0582a62009-12-15 09:54:21 +00001432
Leon Clarked91b9f72010-01-27 17:25:45 +00001433void Logger::LogFunctionObjects() {
1434 AssertNoAllocation no_alloc;
1435 HeapIterator iterator;
1436 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
1437 if (!obj->IsJSFunction()) continue;
1438 JSFunction* jsf = JSFunction::cast(obj);
1439 if (!jsf->is_compiled()) continue;
Steve Block6ded16b2010-05-10 14:33:55 +01001440 PROFILE(FunctionCreateEvent(jsf));
Leon Clarked91b9f72010-01-27 17:25:45 +00001441 }
1442}
1443
1444
Steve Blockd0582a62009-12-15 09:54:21 +00001445void Logger::LogAccessorCallbacks() {
1446 AssertNoAllocation no_alloc;
1447 HeapIterator iterator;
Leon Clarked91b9f72010-01-27 17:25:45 +00001448 for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
Steve Blockd0582a62009-12-15 09:54:21 +00001449 if (!obj->IsAccessorInfo()) continue;
1450 AccessorInfo* ai = AccessorInfo::cast(obj);
1451 if (!ai->name()->IsString()) continue;
1452 String* name = String::cast(ai->name());
1453 Address getter_entry = v8::ToCData<Address>(ai->getter());
1454 if (getter_entry != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001455 PROFILE(GetterCallbackEvent(name, getter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001456 }
1457 Address setter_entry = v8::ToCData<Address>(ai->setter());
1458 if (setter_entry != 0) {
Steve Block6ded16b2010-05-10 14:33:55 +01001459 PROFILE(SetterCallbackEvent(name, setter_entry));
Steve Blockd0582a62009-12-15 09:54:21 +00001460 }
1461 }
1462}
1463
Steve Blocka7e24c12009-10-30 11:49:00 +00001464#endif
1465
1466
1467bool Logger::Setup() {
1468#ifdef ENABLE_LOGGING_AND_PROFILING
1469 // --log-all enables all the log flags.
1470 if (FLAG_log_all) {
1471 FLAG_log_runtime = true;
1472 FLAG_log_api = true;
1473 FLAG_log_code = true;
1474 FLAG_log_gc = true;
1475 FLAG_log_suspect = true;
1476 FLAG_log_handles = true;
1477 FLAG_log_regexp = true;
1478 }
1479
1480 // --prof implies --log-code.
1481 if (FLAG_prof) FLAG_log_code = true;
1482
Ben Murdochf87a2032010-10-22 12:50:53 +01001483 // --ll-prof implies --log-code and --log-snapshot-positions.
1484 if (FLAG_ll_prof) {
1485 FLAG_log_code = true;
1486 FLAG_log_snapshot_positions = true;
1487 }
1488
Steve Blocka7e24c12009-10-30 11:49:00 +00001489 // --prof_lazy controls --log-code, implies --noprof_auto.
1490 if (FLAG_prof_lazy) {
1491 FLAG_log_code = false;
1492 FLAG_prof_auto = false;
1493 }
1494
1495 bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
1496 || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
1497 || FLAG_log_regexp || FLAG_log_state_changes;
1498
1499 bool open_log_file = start_logging || FLAG_prof_lazy;
1500
1501 // If we're logging anything, we need to open the log file.
1502 if (open_log_file) {
1503 if (strcmp(FLAG_logfile, "-") == 0) {
1504 Log::OpenStdout();
1505 } else if (strcmp(FLAG_logfile, "*") == 0) {
1506 Log::OpenMemoryBuffer();
1507 } else if (strchr(FLAG_logfile, '%') != NULL) {
1508 // If there's a '%' in the log file name we have to expand
1509 // placeholders.
1510 HeapStringAllocator allocator;
1511 StringStream stream(&allocator);
1512 for (const char* p = FLAG_logfile; *p; p++) {
1513 if (*p == '%') {
1514 p++;
1515 switch (*p) {
1516 case '\0':
1517 // If there's a % at the end of the string we back up
1518 // one character so we can escape the loop properly.
1519 p--;
1520 break;
1521 case 't': {
1522 // %t expands to the current time in milliseconds.
1523 double time = OS::TimeCurrentMillis();
1524 stream.Add("%.0f", FmtElm(time));
1525 break;
1526 }
1527 case '%':
1528 // %% expands (contracts really) to %.
1529 stream.Put('%');
1530 break;
1531 default:
1532 // All other %'s expand to themselves.
1533 stream.Put('%');
1534 stream.Put(*p);
1535 break;
1536 }
1537 } else {
1538 stream.Put(*p);
1539 }
1540 }
1541 SmartPointer<const char> expanded = stream.ToCString();
1542 Log::OpenFile(*expanded);
1543 } else {
1544 Log::OpenFile(FLAG_logfile);
1545 }
1546 }
1547
Ben Murdochf87a2032010-10-22 12:50:53 +01001548 if (FLAG_ll_prof) LogCodeInfo();
1549
Steve Blocka7e24c12009-10-30 11:49:00 +00001550 ticker_ = new Ticker(kSamplingIntervalMs);
1551
1552 if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
1553 sliding_state_window_ = new SlidingStateWindow();
1554 }
1555
Steve Block6ded16b2010-05-10 14:33:55 +01001556 if (start_logging) {
1557 logging_nesting_ = 1;
1558 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001559
1560 if (FLAG_prof) {
1561 profiler_ = new Profiler();
1562 if (!FLAG_prof_auto) {
1563 profiler_->pause();
1564 } else {
Steve Block6ded16b2010-05-10 14:33:55 +01001565 logging_nesting_ = 1;
Steve Blocka7e24c12009-10-30 11:49:00 +00001566 }
Steve Blockd0582a62009-12-15 09:54:21 +00001567 if (!FLAG_prof_lazy) {
1568 profiler_->Engage();
1569 }
Steve Blocka7e24c12009-10-30 11:49:00 +00001570 }
1571
1572 LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
Steve Blocka7e24c12009-10-30 11:49:00 +00001573 return true;
1574
1575#else
1576 return false;
1577#endif
1578}
1579
1580
Ben Murdochb0fe1622011-05-05 13:52:32 +01001581void Logger::EnsureTickerStarted() {
1582#ifdef ENABLE_LOGGING_AND_PROFILING
1583 ASSERT(ticker_ != NULL);
1584 if (!ticker_->IsActive()) ticker_->Start();
1585#endif
1586}
1587
1588
1589void Logger::EnsureTickerStopped() {
1590#ifdef ENABLE_LOGGING_AND_PROFILING
1591 if (ticker_ != NULL && ticker_->IsActive()) ticker_->Stop();
1592#endif
1593}
1594
1595
Steve Blocka7e24c12009-10-30 11:49:00 +00001596void Logger::TearDown() {
1597#ifdef ENABLE_LOGGING_AND_PROFILING
1598 LogMessageBuilder::set_write_failure_handler(NULL);
1599
1600 // Stop the profiler before closing the file.
1601 if (profiler_ != NULL) {
1602 profiler_->Disengage();
1603 delete profiler_;
1604 profiler_ = NULL;
1605 }
1606
Steve Blocka7e24c12009-10-30 11:49:00 +00001607 delete sliding_state_window_;
1608 sliding_state_window_ = NULL;
1609
1610 delete ticker_;
1611 ticker_ = NULL;
1612
1613 Log::Close();
1614#endif
1615}
1616
1617
1618void Logger::EnableSlidingStateWindow() {
1619#ifdef ENABLE_LOGGING_AND_PROFILING
1620 // If the ticker is NULL, Logger::Setup has not been called yet. In
1621 // that case, we set the sliding_state_window flag so that the
1622 // sliding window computation will be started when Logger::Setup is
1623 // called.
1624 if (ticker_ == NULL) {
1625 FLAG_sliding_state_window = true;
1626 return;
1627 }
1628 // Otherwise, if the sliding state window computation has not been
1629 // started we do it now.
1630 if (sliding_state_window_ == NULL) {
1631 sliding_state_window_ = new SlidingStateWindow();
1632 }
1633#endif
1634}
1635
Steve Blocka7e24c12009-10-30 11:49:00 +00001636} } // namespace v8::internal