2009-03-30 13:32:28 +00:00
|
|
|
// Copyright 2009 the V8 project authors. All rights reserved.
|
2008-07-03 15:10:15 +00:00
|
|
|
// Redistribution and use in source and binary forms, with or without
|
|
|
|
// modification, are permitted provided that the following conditions are
|
|
|
|
// met:
|
|
|
|
//
|
|
|
|
// * Redistributions of source code must retain the above copyright
|
|
|
|
// notice, this list of conditions and the following disclaimer.
|
|
|
|
// * Redistributions in binary form must reproduce the above
|
|
|
|
// copyright notice, this list of conditions and the following
|
|
|
|
// disclaimer in the documentation and/or other materials provided
|
|
|
|
// with the distribution.
|
|
|
|
// * Neither the name of Google Inc. nor the names of its
|
|
|
|
// contributors may be used to endorse or promote products derived
|
|
|
|
// from this software without specific prior written permission.
|
|
|
|
//
|
|
|
|
// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
|
|
|
|
// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
|
|
|
|
// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
|
|
|
|
// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
|
|
|
|
// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
|
|
|
|
// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
|
|
|
|
// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
|
|
|
|
// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
|
|
|
|
// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
|
|
|
|
// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
|
|
|
|
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
|
|
|
|
|
|
|
|
#include <stdarg.h>
|
|
|
|
|
|
|
|
#include "v8.h"
|
|
|
|
|
2009-03-24 12:47:53 +00:00
|
|
|
#include "bootstrapper.h"
|
2010-08-30 11:48:07 +00:00
|
|
|
#include "code-stubs.h"
|
2010-12-07 11:31:57 +00:00
|
|
|
#include "deoptimizer.h"
|
2009-11-20 12:15:46 +00:00
|
|
|
#include "global-handles.h"
|
2008-07-03 15:10:15 +00:00
|
|
|
#include "log.h"
|
2009-03-24 12:47:53 +00:00
|
|
|
#include "macro-assembler.h"
|
2010-12-07 11:31:57 +00:00
|
|
|
#include "runtime-profiler.h"
|
2009-03-24 12:47:53 +00:00
|
|
|
#include "serialize.h"
|
2008-10-15 08:50:22 +00:00
|
|
|
#include "string-stream.h"
|
2010-12-07 11:31:57 +00:00
|
|
|
#include "vm-state-inl.h"
|
2008-07-03 15:10:15 +00:00
|
|
|
|
2009-05-25 10:05:56 +00:00
|
|
|
namespace v8 {
|
|
|
|
namespace internal {
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
|
|
|
|
//
|
|
|
|
// Sliding state window. Updates counters to keep track of the last
|
|
|
|
// window of kBufferSize states. This is useful to track where we
|
|
|
|
// spent our time.
|
|
|
|
//
|
|
|
|
class SlidingStateWindow {
|
|
|
|
public:
|
|
|
|
SlidingStateWindow();
|
|
|
|
~SlidingStateWindow();
|
|
|
|
void AddState(StateTag state);
|
|
|
|
|
|
|
|
private:
|
|
|
|
static const int kBufferSize = 256;
|
|
|
|
int current_index_;
|
|
|
|
bool is_full_;
|
|
|
|
byte buffer_[kBufferSize];
|
|
|
|
|
|
|
|
|
|
|
|
void IncrementStateCounter(StateTag state) {
|
|
|
|
Counters::state_counters[state].Increment();
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void DecrementStateCounter(StateTag state) {
|
|
|
|
Counters::state_counters[state].Decrement();
|
|
|
|
}
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
|
|
//
|
|
|
|
// The Profiler samples pc and sp values for the main thread.
|
|
|
|
// Each sample is appended to a circular buffer.
|
|
|
|
// An independent thread removes data and writes it to the log.
|
|
|
|
// This design minimizes the time spent in the sampler.
|
|
|
|
//
|
|
|
|
class Profiler: public Thread {
|
|
|
|
public:
|
|
|
|
Profiler();
|
|
|
|
void Engage();
|
|
|
|
void Disengage();
|
|
|
|
|
|
|
|
// Inserts collected profiling data into buffer.
|
|
|
|
void Insert(TickSample* sample) {
|
2009-01-29 19:47:00 +00:00
|
|
|
if (paused_)
|
|
|
|
return;
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
if (Succ(head_) == tail_) {
|
|
|
|
overflow_ = true;
|
|
|
|
} else {
|
|
|
|
buffer_[head_] = *sample;
|
|
|
|
head_ = Succ(head_);
|
|
|
|
buffer_semaphore_->Signal(); // Tell we have an element.
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
// Waits for a signal and removes profiling data.
|
|
|
|
bool Remove(TickSample* sample) {
|
|
|
|
buffer_semaphore_->Wait(); // Wait for an element.
|
|
|
|
*sample = buffer_[tail_];
|
|
|
|
bool result = overflow_;
|
|
|
|
tail_ = Succ(tail_);
|
|
|
|
overflow_ = false;
|
|
|
|
return result;
|
|
|
|
}
|
|
|
|
|
|
|
|
void Run();
|
|
|
|
|
2009-01-29 19:47:00 +00:00
|
|
|
// Pause and Resume TickSample data collection.
|
|
|
|
static bool paused() { return paused_; }
|
|
|
|
static void pause() { paused_ = true; }
|
|
|
|
static void resume() { paused_ = false; }
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
private:
|
|
|
|
// Returns the next index in the cyclic buffer.
|
|
|
|
int Succ(int index) { return (index + 1) % kBufferSize; }
|
|
|
|
|
|
|
|
// Cyclic buffer for communicating profiling samples
|
|
|
|
// between the signal handler and the worker thread.
|
|
|
|
static const int kBufferSize = 128;
|
|
|
|
TickSample buffer_[kBufferSize]; // Buffer storage.
|
|
|
|
int head_; // Index to the buffer head.
|
|
|
|
int tail_; // Index to the buffer tail.
|
|
|
|
bool overflow_; // Tell whether a buffer overflow has occurred.
|
|
|
|
Semaphore* buffer_semaphore_; // Sempahore used for buffer synchronization.
|
|
|
|
|
2009-10-28 09:13:11 +00:00
|
|
|
// Tells whether profiler is engaged, that is, processing thread is stated.
|
|
|
|
bool engaged_;
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
// Tells whether worker thread should continue running.
|
|
|
|
bool running_;
|
2009-01-29 19:47:00 +00:00
|
|
|
|
|
|
|
// Tells whether we are currently recording tick samples.
|
|
|
|
static bool paused_;
|
2008-07-03 15:10:15 +00:00
|
|
|
};
|
|
|
|
|
2009-01-29 19:47:00 +00:00
|
|
|
bool Profiler::paused_ = false;
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
|
2009-02-25 16:00:21 +00:00
|
|
|
//
|
|
|
|
// StackTracer implementation
|
|
|
|
//
|
|
|
|
void StackTracer::Trace(TickSample* sample) {
|
2010-04-06 10:36:38 +00:00
|
|
|
sample->function = NULL;
|
|
|
|
sample->frames_count = 0;
|
|
|
|
|
2010-12-07 11:31:57 +00:00
|
|
|
// Avoid collecting traces while doing GC.
|
2010-04-06 10:36:38 +00:00
|
|
|
if (sample->state == GC) return;
|
2009-03-03 11:56:44 +00:00
|
|
|
|
2009-06-02 09:33:17 +00:00
|
|
|
const Address js_entry_sp = Top::js_entry_sp(Top::GetCurrentThread());
|
|
|
|
if (js_entry_sp == 0) {
|
|
|
|
// Not executing JS now.
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2010-12-07 11:31:57 +00:00
|
|
|
const Address function_address =
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
sample->fp + JavaScriptFrameConstants::kFunctionOffset;
|
|
|
|
if (SafeStackFrameIterator::IsWithinBounds(sample->sp, js_entry_sp,
|
2010-12-07 11:31:57 +00:00
|
|
|
function_address)) {
|
|
|
|
Object* object = Memory::Object_at(function_address);
|
|
|
|
if (object->IsHeapObject()) {
|
|
|
|
sample->function = HeapObject::cast(object)->address();
|
|
|
|
}
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
}
|
|
|
|
|
2009-11-23 14:43:00 +00:00
|
|
|
int i = 0;
|
2010-12-07 11:31:57 +00:00
|
|
|
const Address callback = Top::external_callback();
|
2010-10-27 17:03:01 +00:00
|
|
|
// Surprisingly, PC can point _exactly_ to callback start, with good
|
|
|
|
// probability, and this will result in reporting fake nested
|
|
|
|
// callback call.
|
|
|
|
if (callback != NULL && callback != sample->pc) {
|
2009-11-23 14:43:00 +00:00
|
|
|
sample->stack[i++] = callback;
|
|
|
|
}
|
|
|
|
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
SafeStackTraceFrameIterator it(sample->fp, sample->sp,
|
|
|
|
sample->sp, js_entry_sp);
|
2009-03-20 14:49:12 +00:00
|
|
|
while (!it.done() && i < TickSample::kMaxFramesCount) {
|
2010-12-07 11:31:57 +00:00
|
|
|
Object* object = it.frame()->function_slot_object();
|
|
|
|
if (object->IsHeapObject()) {
|
|
|
|
sample->stack[i++] = HeapObject::cast(object)->address();
|
|
|
|
}
|
2009-03-20 14:49:12 +00:00
|
|
|
it.Advance();
|
2009-02-25 16:00:21 +00:00
|
|
|
}
|
2009-03-20 14:49:12 +00:00
|
|
|
sample->frames_count = i;
|
2009-02-25 16:00:21 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
//
|
|
|
|
// Ticker used to provide ticks to the profiler and the sliding state
|
|
|
|
// window.
|
|
|
|
//
|
2008-08-22 13:33:59 +00:00
|
|
|
class Ticker: public Sampler {
|
2008-07-03 15:10:15 +00:00
|
|
|
public:
|
2010-12-07 11:31:57 +00:00
|
|
|
explicit Ticker(int interval) :
|
|
|
|
Sampler(interval),
|
|
|
|
window_(NULL),
|
|
|
|
profiler_(NULL) {}
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
~Ticker() { if (IsActive()) Stop(); }
|
|
|
|
|
2010-10-18 12:37:07 +00:00
|
|
|
virtual void Tick(TickSample* sample) {
|
2008-07-03 15:10:15 +00:00
|
|
|
if (profiler_) profiler_->Insert(sample);
|
2008-08-22 13:33:59 +00:00
|
|
|
if (window_) window_->AddState(sample->state);
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
void SetWindow(SlidingStateWindow* window) {
|
|
|
|
window_ = window;
|
|
|
|
if (!IsActive()) Start();
|
|
|
|
}
|
|
|
|
|
|
|
|
void ClearWindow() {
|
|
|
|
window_ = NULL;
|
2010-12-07 11:31:57 +00:00
|
|
|
if (!profiler_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
void SetProfiler(Profiler* profiler) {
|
2010-12-07 11:31:57 +00:00
|
|
|
ASSERT(profiler_ == NULL);
|
2008-07-03 15:10:15 +00:00
|
|
|
profiler_ = profiler;
|
2010-12-07 11:31:57 +00:00
|
|
|
IncreaseProfilingDepth();
|
2009-05-25 08:25:36 +00:00
|
|
|
if (!FLAG_prof_lazy && !IsActive()) Start();
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
void ClearProfiler() {
|
2010-12-07 11:31:57 +00:00
|
|
|
DecreaseProfilingDepth();
|
2008-07-03 15:10:15 +00:00
|
|
|
profiler_ = NULL;
|
2010-12-07 11:31:57 +00:00
|
|
|
if (!window_ && IsActive() && !RuntimeProfiler::IsEnabled()) Stop();
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
2010-11-25 15:54:52 +00:00
|
|
|
protected:
|
|
|
|
virtual void DoSampleStack(TickSample* sample) {
|
|
|
|
StackTracer::Trace(sample);
|
|
|
|
}
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
private:
|
|
|
|
SlidingStateWindow* window_;
|
|
|
|
Profiler* profiler_;
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
|
|
//
|
|
|
|
// SlidingStateWindow implementation.
|
|
|
|
//
|
|
|
|
SlidingStateWindow::SlidingStateWindow(): current_index_(0), is_full_(false) {
|
|
|
|
for (int i = 0; i < kBufferSize; i++) {
|
|
|
|
buffer_[i] = static_cast<byte>(OTHER);
|
|
|
|
}
|
|
|
|
Logger::ticker_->SetWindow(this);
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
SlidingStateWindow::~SlidingStateWindow() {
|
|
|
|
Logger::ticker_->ClearWindow();
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void SlidingStateWindow::AddState(StateTag state) {
|
|
|
|
if (is_full_) {
|
|
|
|
DecrementStateCounter(static_cast<StateTag>(buffer_[current_index_]));
|
|
|
|
} else if (current_index_ == kBufferSize - 1) {
|
|
|
|
is_full_ = true;
|
|
|
|
}
|
|
|
|
buffer_[current_index_] = static_cast<byte>(state);
|
|
|
|
IncrementStateCounter(state);
|
|
|
|
ASSERT(IsPowerOf2(kBufferSize));
|
|
|
|
current_index_ = (current_index_ + 1) & (kBufferSize - 1);
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
//
|
|
|
|
// Profiler implementation.
|
|
|
|
//
|
2009-10-28 09:13:11 +00:00
|
|
|
Profiler::Profiler()
|
|
|
|
: head_(0),
|
|
|
|
tail_(0),
|
|
|
|
overflow_(false),
|
|
|
|
buffer_semaphore_(OS::CreateSemaphore(0)),
|
|
|
|
engaged_(false),
|
|
|
|
running_(false) {
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Profiler::Engage() {
|
2009-10-28 09:13:11 +00:00
|
|
|
if (engaged_) return;
|
|
|
|
engaged_ = true;
|
|
|
|
|
|
|
|
// TODO(mnaganov): This is actually "Chromium" mode. Flags need to be revised.
|
|
|
|
// http://code.google.com/p/v8/issues/detail?id=487
|
|
|
|
if (!FLAG_prof_lazy) {
|
|
|
|
OS::LogSharedLibraryAddresses();
|
|
|
|
}
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
// Start thread processing the profiler buffer.
|
|
|
|
running_ = true;
|
|
|
|
Start();
|
|
|
|
|
|
|
|
// Register to get ticks.
|
|
|
|
Logger::ticker_->SetProfiler(this);
|
|
|
|
|
2009-05-29 06:56:23 +00:00
|
|
|
Logger::ProfilerBeginEvent();
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Profiler::Disengage() {
|
2009-10-28 09:13:11 +00:00
|
|
|
if (!engaged_) return;
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
// Stop receiving ticks.
|
|
|
|
Logger::ticker_->ClearProfiler();
|
|
|
|
|
|
|
|
// Terminate the worker thread by setting running_ to false,
|
|
|
|
// inserting a fake element in the queue and then wait for
|
|
|
|
// the thread to terminate.
|
|
|
|
running_ = false;
|
|
|
|
TickSample sample;
|
2009-05-25 08:25:36 +00:00
|
|
|
// Reset 'paused_' flag, otherwise semaphore may not be signalled.
|
|
|
|
resume();
|
2008-07-03 15:10:15 +00:00
|
|
|
Insert(&sample);
|
|
|
|
Join();
|
|
|
|
|
2009-02-11 07:38:31 +00:00
|
|
|
LOG(UncheckedStringEvent("profiler", "end"));
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Profiler::Run() {
|
|
|
|
TickSample sample;
|
2010-06-25 15:57:30 +00:00
|
|
|
bool overflow = Remove(&sample);
|
2008-07-03 15:10:15 +00:00
|
|
|
while (running_) {
|
|
|
|
LOG(TickEvent(&sample, overflow));
|
2010-06-25 15:57:30 +00:00
|
|
|
overflow = Remove(&sample);
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
//
|
|
|
|
// Logger class implementation.
|
|
|
|
//
|
|
|
|
Ticker* Logger::ticker_ = NULL;
|
|
|
|
Profiler* Logger::profiler_ = NULL;
|
|
|
|
SlidingStateWindow* Logger::sliding_state_window_ = NULL;
|
2010-03-01 10:41:34 +00:00
|
|
|
int Logger::logging_nesting_ = 0;
|
2010-02-17 13:23:46 +00:00
|
|
|
int Logger::cpu_profiler_nesting_ = 0;
|
|
|
|
int Logger::heap_profiler_nesting_ = 0;
|
2009-06-08 13:39:48 +00:00
|
|
|
|
2010-12-07 13:24:22 +00:00
|
|
|
#define DECLARE_EVENT(ignore1, name) name,
|
|
|
|
const char* kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
|
|
|
|
LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)
|
2009-06-08 13:39:48 +00:00
|
|
|
};
|
2010-12-07 13:24:22 +00:00
|
|
|
#undef DECLARE_EVENT
|
2008-07-03 15:10:15 +00:00
|
|
|
|
2009-05-05 15:57:47 +00:00
|
|
|
|
2009-05-29 06:56:23 +00:00
|
|
|
void Logger::ProfilerBeginEvent() {
|
|
|
|
if (!Log::IsEnabled()) return;
|
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("profiler,\"begin\",%d\n", kSamplingIntervalMs);
|
2009-06-08 13:39:48 +00:00
|
|
|
msg.WriteToLogFile();
|
|
|
|
}
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif // ENABLE_LOGGING_AND_PROFILING
|
|
|
|
|
2009-02-17 08:21:24 +00:00
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
void Logger::StringEvent(const char* name, const char* value) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-02-11 07:38:31 +00:00
|
|
|
if (FLAG_log) UncheckedStringEvent(name, value);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
void Logger::UncheckedStringEvent(const char* name, const char* value) {
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled()) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("%s,\"%s\"\n", name, value);
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
2009-02-11 07:38:31 +00:00
|
|
|
#endif
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
|
|
|
|
void Logger::IntEvent(const char* name, int value) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2010-03-01 10:41:34 +00:00
|
|
|
if (FLAG_log) UncheckedIntEvent(name, value);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-09-30 07:22:53 +00:00
|
|
|
void Logger::IntPtrTEvent(const char* name, intptr_t value) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (FLAG_log) UncheckedIntPtrTEvent(name, value);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-03-01 10:41:34 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
void Logger::UncheckedIntEvent(const char* name, int value) {
|
|
|
|
if (!Log::IsEnabled()) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("%s,%d\n", name, value);
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
2010-03-01 10:41:34 +00:00
|
|
|
#endif
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
|
2010-09-30 07:22:53 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
|
|
|
|
if (!Log::IsEnabled()) return;
|
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("%s,%" V8_PTR_PREFIX "d\n", name, value);
|
|
|
|
msg.WriteToLogFile();
|
|
|
|
}
|
|
|
|
#endif
|
|
|
|
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
void Logger::HandleEvent(const char* name, Object** location) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_handles) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-05-15 09:58:40 +00:00
|
|
|
msg.Append("%s,0x%" V8PRIxPTR "\n", name, location);
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
// ApiEvent is private so all the calls come from the Logger class. It is the
|
2009-05-05 15:57:47 +00:00
|
|
|
// caller's responsibility to ensure that log is enabled and that
|
2008-07-03 15:10:15 +00:00
|
|
|
// FLAG_log_api is true.
|
|
|
|
void Logger::ApiEvent(const char* format, ...) {
|
2009-05-25 08:39:22 +00:00
|
|
|
ASSERT(Log::IsEnabled() && FLAG_log_api);
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2008-07-03 15:10:15 +00:00
|
|
|
va_list ap;
|
|
|
|
va_start(ap, format);
|
2009-06-15 15:49:03 +00:00
|
|
|
msg.AppendVA(format, ap);
|
2009-02-17 12:49:35 +00:00
|
|
|
va_end(ap);
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
#endif
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::ApiNamedSecurityCheck(Object* key) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_api) return;
|
2008-07-03 15:10:15 +00:00
|
|
|
if (key->IsString()) {
|
|
|
|
SmartPointer<char> str =
|
|
|
|
String::cast(key)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
|
|
|
ApiEvent("api,check-security,\"%s\"\n", *str);
|
|
|
|
} else if (key->IsUndefined()) {
|
|
|
|
ApiEvent("api,check-security,undefined\n");
|
|
|
|
} else {
|
|
|
|
ApiEvent("api,check-security,['no-name']\n");
|
|
|
|
}
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::SharedLibraryEvent(const char* library_path,
|
2009-06-16 12:52:02 +00:00
|
|
|
uintptr_t start,
|
|
|
|
uintptr_t end) {
|
2008-07-03 15:10:15 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_prof) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-06-16 12:52:02 +00:00
|
|
|
msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
|
|
|
|
library_path,
|
|
|
|
start,
|
|
|
|
end);
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::SharedLibraryEvent(const wchar_t* library_path,
|
2009-06-16 12:52:02 +00:00
|
|
|
uintptr_t start,
|
|
|
|
uintptr_t end) {
|
2008-07-03 15:10:15 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_prof) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-06-16 12:52:02 +00:00
|
|
|
msg.Append("shared-library,\"%ls\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR "\n",
|
|
|
|
library_path,
|
|
|
|
start,
|
|
|
|
end);
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
2008-09-12 17:25:38 +00:00
|
|
|
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2008-09-23 11:45:43 +00:00
|
|
|
void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
|
2008-09-11 12:57:27 +00:00
|
|
|
// Prints "/" + re.source + "/" +
|
2008-09-11 11:24:45 +00:00
|
|
|
// (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2008-09-11 11:24:45 +00:00
|
|
|
|
|
|
|
Handle<Object> source = GetProperty(regexp, "source");
|
|
|
|
if (!source->IsString()) {
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append("no source");
|
2008-09-11 11:24:45 +00:00
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2008-10-24 08:40:02 +00:00
|
|
|
switch (regexp->TypeTag()) {
|
2008-10-02 15:35:28 +00:00
|
|
|
case JSRegExp::ATOM:
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append('a');
|
2008-10-02 15:35:28 +00:00
|
|
|
break;
|
|
|
|
default:
|
|
|
|
break;
|
|
|
|
}
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append('/');
|
|
|
|
msg.AppendDetailed(*Handle<String>::cast(source), false);
|
|
|
|
msg.Append('/');
|
2008-09-11 11:24:45 +00:00
|
|
|
|
|
|
|
// global flag
|
|
|
|
Handle<Object> global = GetProperty(regexp, "global");
|
|
|
|
if (global->IsTrue()) {
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append('g');
|
2008-09-11 11:24:45 +00:00
|
|
|
}
|
|
|
|
// ignorecase flag
|
|
|
|
Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
|
|
|
|
if (ignorecase->IsTrue()) {
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append('i');
|
2008-09-11 11:24:45 +00:00
|
|
|
}
|
|
|
|
// multiline flag
|
|
|
|
Handle<Object> multiline = GetProperty(regexp, "multiline");
|
|
|
|
if (multiline->IsTrue()) {
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append('m');
|
2008-09-11 11:24:45 +00:00
|
|
|
}
|
2009-02-17 12:49:35 +00:00
|
|
|
|
|
|
|
msg.WriteToLogFile();
|
2008-09-11 11:24:45 +00:00
|
|
|
}
|
2008-09-12 17:25:38 +00:00
|
|
|
#endif // ENABLE_LOGGING_AND_PROFILING
|
2008-09-11 11:24:45 +00:00
|
|
|
|
|
|
|
|
2008-10-24 08:40:02 +00:00
|
|
|
void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
|
2008-09-11 11:24:45 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_regexp) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("regexp-compile,");
|
2008-09-11 11:24:45 +00:00
|
|
|
LogRegExpSource(regexp);
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append(in_cache ? ",hit\n" : ",miss\n");
|
|
|
|
msg.WriteToLogFile();
|
2008-09-11 11:24:45 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-01-06 13:24:52 +00:00
|
|
|
void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
|
2009-01-07 14:24:08 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_runtime) return;
|
2009-01-06 13:24:52 +00:00
|
|
|
HandleScope scope;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-01-06 13:24:52 +00:00
|
|
|
for (int i = 0; i < format.length(); i++) {
|
|
|
|
char c = format[i];
|
|
|
|
if (c == '%' && i <= format.length() - 2) {
|
|
|
|
i++;
|
|
|
|
ASSERT('0' <= format[i] && format[i] <= '9');
|
2010-10-25 15:22:03 +00:00
|
|
|
MaybeObject* maybe = args->GetElement(format[i] - '0');
|
|
|
|
Object* obj;
|
|
|
|
if (!maybe->ToObject(&obj)) {
|
|
|
|
msg.Append("<exception>");
|
|
|
|
continue;
|
|
|
|
}
|
2009-01-06 13:24:52 +00:00
|
|
|
i++;
|
|
|
|
switch (format[i]) {
|
|
|
|
case 's':
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.AppendDetailed(String::cast(obj), false);
|
2009-01-06 13:24:52 +00:00
|
|
|
break;
|
|
|
|
case 'S':
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.AppendDetailed(String::cast(obj), true);
|
2009-01-06 13:24:52 +00:00
|
|
|
break;
|
|
|
|
case 'r':
|
|
|
|
Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
|
|
|
|
break;
|
|
|
|
case 'x':
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append("0x%x", Smi::cast(obj)->value());
|
2009-01-06 13:24:52 +00:00
|
|
|
break;
|
|
|
|
case 'i':
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append("%i", Smi::cast(obj)->value());
|
2009-01-06 13:24:52 +00:00
|
|
|
break;
|
|
|
|
default:
|
|
|
|
UNREACHABLE();
|
|
|
|
}
|
|
|
|
} else {
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append(c);
|
2009-01-06 13:24:52 +00:00
|
|
|
}
|
|
|
|
}
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
2009-01-07 14:24:08 +00:00
|
|
|
#endif
|
2008-09-11 11:24:45 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
void Logger::ApiIndexedSecurityCheck(uint32_t index) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_api) return;
|
2008-07-03 15:10:15 +00:00
|
|
|
ApiEvent("api,check-security,%u\n", index);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::ApiNamedPropertyAccess(const char* tag,
|
|
|
|
JSObject* holder,
|
|
|
|
Object* name) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
ASSERT(name->IsString());
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_api) return;
|
2008-07-03 15:10:15 +00:00
|
|
|
String* class_name_obj = holder->class_name();
|
|
|
|
SmartPointer<char> class_name =
|
|
|
|
class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
|
|
|
SmartPointer<char> property_name =
|
|
|
|
String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
|
|
|
Logger::ApiEvent("api,%s,\"%s\",\"%s\"\n", tag, *class_name, *property_name);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
void Logger::ApiIndexedPropertyAccess(const char* tag,
|
|
|
|
JSObject* holder,
|
|
|
|
uint32_t index) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_api) return;
|
2008-07-03 15:10:15 +00:00
|
|
|
String* class_name_obj = holder->class_name();
|
|
|
|
SmartPointer<char> class_name =
|
|
|
|
class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
|
|
|
Logger::ApiEvent("api,%s,\"%s\",%u\n", tag, *class_name, index);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_api) return;
|
2008-07-03 15:10:15 +00:00
|
|
|
String* class_name_obj = object->class_name();
|
|
|
|
SmartPointer<char> class_name =
|
|
|
|
class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
|
|
|
Logger::ApiEvent("api,%s,\"%s\"\n", tag, *class_name);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::ApiEntryCall(const char* name) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_api) return;
|
2008-07-03 15:10:15 +00:00
|
|
|
Logger::ApiEvent("api,%s\n", name);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::NewEvent(const char* name, void* object, size_t size) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-05-15 09:58:40 +00:00
|
|
|
msg.Append("new,%s,0x%" V8PRIxPTR ",%u\n", name, object,
|
2009-02-17 12:49:35 +00:00
|
|
|
static_cast<unsigned int>(size));
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::DeleteEvent(const char* name, void* object) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-05-15 09:58:40 +00:00
|
|
|
msg.Append("delete,%s,0x%" V8PRIxPTR "\n", name, object);
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-11-23 09:19:24 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-11-25 16:39:18 +00:00
|
|
|
void Logger::CallbackEventInternal(const char* prefix, const char* name,
|
|
|
|
Address entry_point) {
|
2009-11-23 09:19:24 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("%s,%s,",
|
2010-12-07 13:24:22 +00:00
|
|
|
kLogEventsNames[CODE_CREATION_EVENT],
|
|
|
|
kLogEventsNames[CALLBACK_TAG]);
|
2009-11-23 09:19:24 +00:00
|
|
|
msg.AppendAddress(entry_point);
|
2009-11-25 16:39:18 +00:00
|
|
|
msg.Append(",1,\"%s%s\"", prefix, name);
|
2009-11-23 09:19:24 +00:00
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
2009-11-25 16:39:18 +00:00
|
|
|
}
|
|
|
|
#endif
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::CallbackEvent(String* name, Address entry_point) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
|
|
|
SmartPointer<char> str =
|
|
|
|
name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
|
|
|
CallbackEventInternal("", *str, entry_point);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::GetterCallbackEvent(String* name, Address entry_point) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
|
|
|
SmartPointer<char> str =
|
|
|
|
name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
|
|
|
CallbackEventInternal("get ", *str, entry_point);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::SetterCallbackEvent(String* name, Address entry_point) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
|
|
|
SmartPointer<char> str =
|
|
|
|
name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
|
|
|
CallbackEventInternal("set ", *str, entry_point);
|
2009-11-23 09:19:24 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-12-16 12:14:56 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2010-12-07 11:31:57 +00:00
|
|
|
static const char* ComputeMarker(Code* code) {
|
|
|
|
switch (code->kind()) {
|
|
|
|
case Code::FUNCTION: return code->optimizable() ? "~" : "";
|
|
|
|
case Code::OPTIMIZED_FUNCTION: return "*";
|
|
|
|
default: return "";
|
|
|
|
}
|
|
|
|
}
|
2010-12-16 12:14:56 +00:00
|
|
|
#endif
|
2010-12-07 11:31:57 +00:00
|
|
|
|
|
|
|
|
2009-06-08 13:39:48 +00:00
|
|
|
void Logger::CodeCreateEvent(LogEventsAndTags tag,
|
|
|
|
Code* code,
|
|
|
|
const char* comment) {
|
2008-07-03 15:10:15 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
2009-02-17 08:21:24 +00:00
|
|
|
LogMessageBuilder msg;
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s,%s,",
|
|
|
|
kLogEventsNames[CODE_CREATION_EVENT],
|
|
|
|
kLogEventsNames[tag]);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.AppendAddress(code->address());
|
2010-12-07 11:31:57 +00:00
|
|
|
msg.Append(",%d,\"%s", code->ExecutableSize(), ComputeMarker(code));
|
2008-07-03 15:10:15 +00:00
|
|
|
for (const char* p = comment; *p != '\0'; p++) {
|
2009-02-17 12:49:35 +00:00
|
|
|
if (*p == '"') {
|
|
|
|
msg.Append('\\');
|
|
|
|
}
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.Append(*p);
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.Append('"');
|
2010-10-19 16:45:11 +00:00
|
|
|
LowLevelCodeCreateEvent(code, &msg);
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-06-08 13:39:48 +00:00
|
|
|
void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
|
2008-07-03 15:10:15 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
2009-02-17 08:21:24 +00:00
|
|
|
LogMessageBuilder msg;
|
2008-07-03 15:10:15 +00:00
|
|
|
SmartPointer<char> str =
|
|
|
|
name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s,%s,",
|
|
|
|
kLogEventsNames[CODE_CREATION_EVENT],
|
|
|
|
kLogEventsNames[tag]);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.AppendAddress(code->address());
|
2010-12-07 11:31:57 +00:00
|
|
|
msg.Append(",%d,\"%s%s\"", code->ExecutableSize(), ComputeMarker(code), *str);
|
2010-10-19 16:45:11 +00:00
|
|
|
LowLevelCodeCreateEvent(code, &msg);
|
2009-06-18 07:59:13 +00:00
|
|
|
msg.Append('\n');
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-06-08 13:39:48 +00:00
|
|
|
void Logger::CodeCreateEvent(LogEventsAndTags tag,
|
|
|
|
Code* code, String* name,
|
2009-02-03 10:52:02 +00:00
|
|
|
String* source, int line) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
2009-02-17 08:21:24 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-02-03 10:52:02 +00:00
|
|
|
SmartPointer<char> str =
|
|
|
|
name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
|
|
|
SmartPointer<char> sourcestr =
|
|
|
|
source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s,%s,",
|
|
|
|
kLogEventsNames[CODE_CREATION_EVENT],
|
|
|
|
kLogEventsNames[tag]);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.AppendAddress(code->address());
|
2010-12-07 11:31:57 +00:00
|
|
|
msg.Append(",%d,\"%s%s %s:%d\"",
|
|
|
|
code->ExecutableSize(),
|
|
|
|
ComputeMarker(code),
|
|
|
|
*str,
|
|
|
|
*sourcestr,
|
|
|
|
line);
|
2010-10-19 16:45:11 +00:00
|
|
|
LowLevelCodeCreateEvent(code, &msg);
|
2009-06-18 07:59:13 +00:00
|
|
|
msg.Append('\n');
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.WriteToLogFile();
|
2009-02-03 10:52:02 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-06-08 13:39:48 +00:00
|
|
|
void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
|
2008-07-03 15:10:15 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
2009-02-17 08:21:24 +00:00
|
|
|
LogMessageBuilder msg;
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s,%s,",
|
|
|
|
kLogEventsNames[CODE_CREATION_EVENT],
|
|
|
|
kLogEventsNames[tag]);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.AppendAddress(code->address());
|
2009-06-18 07:59:13 +00:00
|
|
|
msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
|
2010-10-19 16:45:11 +00:00
|
|
|
LowLevelCodeCreateEvent(code, &msg);
|
2009-06-18 07:59:13 +00:00
|
|
|
msg.Append('\n');
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-10-19 16:45:11 +00:00
|
|
|
void Logger::CodeMovingGCEvent() {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
|
|
|
|
LogMessageBuilder msg;
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s\n", kLogEventsNames[CODE_MOVING_GC]);
|
2010-10-19 16:45:11 +00:00
|
|
|
msg.WriteToLogFile();
|
|
|
|
OS::SignalCodeMovingGC();
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-03-31 09:06:37 +00:00
|
|
|
void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
2009-03-31 09:06:37 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append("%s,%s,",
|
2010-12-07 13:24:22 +00:00
|
|
|
kLogEventsNames[CODE_CREATION_EVENT],
|
|
|
|
kLogEventsNames[REG_EXP_TAG]);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.AppendAddress(code->address());
|
|
|
|
msg.Append(",%d,\"", code->ExecutableSize());
|
2009-03-31 09:06:37 +00:00
|
|
|
msg.AppendDetailed(source, false);
|
2009-06-18 07:59:13 +00:00
|
|
|
msg.Append('\"');
|
2010-10-19 16:45:11 +00:00
|
|
|
LowLevelCodeCreateEvent(code, &msg);
|
2009-06-18 07:59:13 +00:00
|
|
|
msg.Append('\n');
|
2009-03-31 09:06:37 +00:00
|
|
|
msg.WriteToLogFile();
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
void Logger::CodeMoveEvent(Address from, Address to) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
MoveEventInternal(CODE_MOVE_EVENT, from, to);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::CodeDeleteEvent(Address from) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
DeleteEventInternal(CODE_DELETE_EVENT, from);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::SnapshotPositionEvent(Address addr, int pos) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_snapshot_positions) return;
|
|
|
|
LogMessageBuilder msg;
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
msg.AppendAddress(addr);
|
|
|
|
msg.Append(",%d", pos);
|
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::FunctionCreateEvent(JSFunction* function) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2010-09-24 11:45:12 +00:00
|
|
|
// This function can be called from GC iterators (during Scavenge,
|
|
|
|
// MC, and MS), so marking bits can be set on objects. That's
|
|
|
|
// why unchecked accessors are used here.
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
2009-02-17 08:21:24 +00:00
|
|
|
LogMessageBuilder msg;
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s,", kLogEventsNames[FUNCTION_CREATION_EVENT]);
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
msg.AppendAddress(function->address());
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append(',');
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.AppendAddress(function->unchecked_code()->address());
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append('\n');
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-10-20 08:32:24 +00:00
|
|
|
void Logger::FunctionCreateEventFromMove(JSFunction* function) {
|
2010-09-24 11:45:12 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (function->unchecked_code() != Builtins::builtin(Builtins::LazyCompile)) {
|
|
|
|
FunctionCreateEvent(function);
|
|
|
|
}
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
void Logger::FunctionMoveEvent(Address from, Address to) {
|
2008-07-03 15:10:15 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
MoveEventInternal(FUNCTION_MOVE_EVENT, from, to);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::FunctionDeleteEvent(Address from) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
DeleteEventInternal(FUNCTION_DELETE_EVENT, from);
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-01-27 17:10:28 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
void Logger::MoveEventInternal(LogEventsAndTags event,
|
|
|
|
Address from,
|
|
|
|
Address to) {
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
2009-02-17 08:21:24 +00:00
|
|
|
LogMessageBuilder msg;
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s,", kLogEventsNames[event]);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.AppendAddress(from);
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
msg.Append(',');
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.AppendAddress(to);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append('\n');
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-12-19 13:12:43 +00:00
|
|
|
}
|
2010-01-27 17:10:28 +00:00
|
|
|
#endif
|
2008-12-19 13:12:43 +00:00
|
|
|
|
|
|
|
|
2010-01-18 16:04:25 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2010-01-27 17:10:28 +00:00
|
|
|
void Logger::DeleteEventInternal(LogEventsAndTags event, Address from) {
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
2010-01-18 16:04:25 +00:00
|
|
|
LogMessageBuilder msg;
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s,", kLogEventsNames[event]);
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
msg.AppendAddress(from);
|
2010-01-18 16:04:25 +00:00
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
|
|
|
}
|
2010-01-27 17:10:28 +00:00
|
|
|
#endif
|
2010-01-18 16:04:25 +00:00
|
|
|
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
void Logger::ResourceEvent(const char* name, const char* tag) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("%s,%s,", name, tag);
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
uint32_t sec, usec;
|
|
|
|
if (OS::GetUserTime(&sec, &usec) != -1) {
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append("%d,%d,", sec, usec);
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append("%.0f", OS::TimeCurrentMillis());
|
2008-07-03 15:10:15 +00:00
|
|
|
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2008-12-09 09:19:02 +00:00
|
|
|
void Logger::SuspectReadEvent(String* name, Object* obj) {
|
2008-07-03 15:10:15 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_suspect) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2008-12-09 09:19:02 +00:00
|
|
|
String* class_name = obj->IsJSObject()
|
|
|
|
? JSObject::cast(obj)->class_name()
|
|
|
|
: Heap::empty_string();
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append("suspect-read,");
|
|
|
|
msg.Append(class_name);
|
|
|
|
msg.Append(',');
|
|
|
|
msg.Append('"');
|
|
|
|
msg.Append(name);
|
|
|
|
msg.Append('"');
|
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_gc) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-07-20 09:38:44 +00:00
|
|
|
// Using non-relative system time in order to be able to synchronize with
|
|
|
|
// external memory profiling events (e.g. DOM memory size).
|
|
|
|
msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f\n",
|
|
|
|
space, kind, OS::TimeCurrentMillis());
|
|
|
|
msg.WriteToLogFile();
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::HeapSampleStats(const char* space, const char* kind,
|
2010-09-30 07:22:53 +00:00
|
|
|
intptr_t capacity, intptr_t used) {
|
2009-07-20 09:38:44 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_gc) return;
|
|
|
|
LogMessageBuilder msg;
|
2010-09-30 07:22:53 +00:00
|
|
|
msg.Append("heap-sample-stats,\"%s\",\"%s\","
|
|
|
|
"%" V8_PTR_PREFIX "d,%" V8_PTR_PREFIX "d\n",
|
2009-07-20 09:38:44 +00:00
|
|
|
space, kind, capacity, used);
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_gc) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_gc) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-07-29 08:10:19 +00:00
|
|
|
void Logger::HeapSampleJSConstructorEvent(const char* constructor,
|
|
|
|
int number, int bytes) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_gc) return;
|
|
|
|
LogMessageBuilder msg;
|
2009-09-18 12:05:18 +00:00
|
|
|
msg.Append("heap-js-cons-item,%s,%d,%d\n", constructor, number, bytes);
|
2009-07-29 08:10:19 +00:00
|
|
|
msg.WriteToLogFile();
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-09-18 12:05:18 +00:00
|
|
|
void Logger::HeapSampleJSRetainersEvent(
|
|
|
|
const char* constructor, const char* event) {
|
2009-09-16 13:41:24 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_gc) return;
|
2009-09-18 12:05:18 +00:00
|
|
|
// Event starts with comma, so we don't have it in the format string.
|
|
|
|
static const char* event_text = "heap-js-ret-item,%s";
|
|
|
|
// We take placeholder strings into account, but it's OK to be conservative.
|
2009-11-11 09:50:06 +00:00
|
|
|
static const int event_text_len = StrLength(event_text);
|
|
|
|
const int cons_len = StrLength(constructor);
|
|
|
|
const int event_len = StrLength(event);
|
2009-09-18 12:05:18 +00:00
|
|
|
int pos = 0;
|
|
|
|
// Retainer lists can be long. We may need to split them into multiple events.
|
|
|
|
do {
|
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append(event_text, constructor);
|
|
|
|
int to_write = event_len - pos;
|
|
|
|
if (to_write > Log::kMessageBufferSize - (cons_len + event_text_len)) {
|
|
|
|
int cut_pos = pos + Log::kMessageBufferSize - (cons_len + event_text_len);
|
|
|
|
ASSERT(cut_pos < event_len);
|
|
|
|
while (cut_pos > pos && event[cut_pos] != ',') --cut_pos;
|
|
|
|
if (event[cut_pos] != ',') {
|
|
|
|
// Crash in debug mode, skip in release mode.
|
|
|
|
ASSERT(false);
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
// Append a piece of event that fits, without trailing comma.
|
|
|
|
msg.AppendStringPart(event + pos, cut_pos - pos);
|
|
|
|
// Start next piece with comma.
|
|
|
|
pos = cut_pos;
|
|
|
|
} else {
|
|
|
|
msg.Append("%s", event + pos);
|
|
|
|
pos += event_len;
|
|
|
|
}
|
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
|
|
|
} while (pos < event_len);
|
2009-09-16 13:41:24 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-10-15 07:50:23 +00:00
|
|
|
void Logger::HeapSampleJSProducerEvent(const char* constructor,
|
|
|
|
Address* stack) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_gc) return;
|
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("heap-js-prod-item,%s", constructor);
|
|
|
|
while (*stack != NULL) {
|
|
|
|
msg.Append(",0x%" V8PRIxPTR, *stack++);
|
|
|
|
}
|
|
|
|
msg.Append("\n");
|
|
|
|
msg.WriteToLogFile();
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2008-08-06 10:02:49 +00:00
|
|
|
void Logger::DebugTag(const char* call_site_tag) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("debug-tag,%s\n", call_site_tag);
|
|
|
|
msg.WriteToLogFile();
|
2008-08-06 10:02:49 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log) return;
|
2008-08-06 10:02:49 +00:00
|
|
|
StringBuilder s(parameter.length() + 1);
|
|
|
|
for (int i = 0; i < parameter.length(); ++i) {
|
|
|
|
s.AddCharacter(static_cast<char>(parameter[i]));
|
|
|
|
}
|
|
|
|
char* parameter_string = s.Finalize();
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("debug-queue-event,%s,%15.3f,%s\n",
|
|
|
|
event_type,
|
|
|
|
OS::TimeCurrentMillis(),
|
|
|
|
parameter_string);
|
2008-08-06 10:02:49 +00:00
|
|
|
DeleteArray(parameter_string);
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-08-06 10:02:49 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
void Logger::TickEvent(TickSample* sample, bool overflow) {
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_prof) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
|
|
|
|
msg.AppendAddress(sample->pc);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append(',');
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.AppendAddress(sample->sp);
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
msg.Append(',');
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.AppendAddress(sample->function);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append(",%d", static_cast<int>(sample->state));
|
2009-02-17 12:49:35 +00:00
|
|
|
if (overflow) {
|
|
|
|
msg.Append(",overflow");
|
|
|
|
}
|
2009-03-06 13:07:57 +00:00
|
|
|
for (int i = 0; i < sample->frames_count; ++i) {
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append(',');
|
2010-12-07 13:24:22 +00:00
|
|
|
msg.AppendAddress(sample->stack[i]);
|
2009-06-11 14:08:34 +00:00
|
|
|
}
|
2009-02-17 12:49:35 +00:00
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
2009-01-29 19:47:00 +00:00
|
|
|
|
|
|
|
|
2009-08-04 14:14:01 +00:00
|
|
|
int Logger::GetActiveProfilerModules() {
|
|
|
|
int result = PROFILER_MODULE_NONE;
|
2010-06-25 15:57:30 +00:00
|
|
|
if (profiler_ != NULL && !profiler_->paused()) {
|
2009-08-04 14:14:01 +00:00
|
|
|
result |= PROFILER_MODULE_CPU;
|
|
|
|
}
|
|
|
|
if (FLAG_log_gc) {
|
|
|
|
result |= PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS;
|
|
|
|
}
|
|
|
|
return result;
|
2009-01-29 19:47:00 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-02-17 13:23:46 +00:00
|
|
|
void Logger::PauseProfiler(int flags, int tag) {
|
2009-08-04 14:14:01 +00:00
|
|
|
if (!Log::IsEnabled()) return;
|
2010-06-25 15:57:30 +00:00
|
|
|
if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
|
2010-02-17 13:23:46 +00:00
|
|
|
// It is OK to have negative nesting.
|
|
|
|
if (--cpu_profiler_nesting_ == 0) {
|
|
|
|
profiler_->pause();
|
|
|
|
if (FLAG_prof_lazy) {
|
2010-12-07 11:31:57 +00:00
|
|
|
if (!FLAG_sliding_state_window && !RuntimeProfiler::IsEnabled()) {
|
|
|
|
ticker_->Stop();
|
|
|
|
}
|
2010-02-17 13:23:46 +00:00
|
|
|
FLAG_log_code = false;
|
|
|
|
// Must be the same message as Log::kDynamicBufferSeal.
|
|
|
|
LOG(UncheckedStringEvent("profiler", "pause"));
|
|
|
|
}
|
2010-03-01 10:41:34 +00:00
|
|
|
--logging_nesting_;
|
2009-08-04 14:14:01 +00:00
|
|
|
}
|
2009-05-29 06:56:23 +00:00
|
|
|
}
|
2010-02-17 13:23:46 +00:00
|
|
|
if (flags &
|
2009-08-04 14:14:01 +00:00
|
|
|
(PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
|
2010-02-17 13:23:46 +00:00
|
|
|
if (--heap_profiler_nesting_ == 0) {
|
|
|
|
FLAG_log_gc = false;
|
2010-03-01 10:41:34 +00:00
|
|
|
--logging_nesting_;
|
2010-02-17 13:23:46 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
if (tag != 0) {
|
2010-03-01 10:41:34 +00:00
|
|
|
UncheckedIntEvent("close-tag", tag);
|
2009-05-25 08:25:36 +00:00
|
|
|
}
|
2009-01-29 19:47:00 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-02-17 13:23:46 +00:00
|
|
|
void Logger::ResumeProfiler(int flags, int tag) {
|
2009-08-04 14:14:01 +00:00
|
|
|
if (!Log::IsEnabled()) return;
|
2010-02-17 13:23:46 +00:00
|
|
|
if (tag != 0) {
|
2010-03-01 10:41:34 +00:00
|
|
|
UncheckedIntEvent("open-tag", tag);
|
2009-08-04 14:14:01 +00:00
|
|
|
}
|
2010-06-25 15:57:30 +00:00
|
|
|
if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
|
2010-02-17 13:23:46 +00:00
|
|
|
if (cpu_profiler_nesting_++ == 0) {
|
2010-03-01 10:41:34 +00:00
|
|
|
++logging_nesting_;
|
2010-02-17 13:23:46 +00:00
|
|
|
if (FLAG_prof_lazy) {
|
|
|
|
profiler_->Engage();
|
|
|
|
LOG(UncheckedStringEvent("profiler", "resume"));
|
|
|
|
FLAG_log_code = true;
|
|
|
|
LogCompiledFunctions();
|
|
|
|
LogFunctionObjects();
|
|
|
|
LogAccessorCallbacks();
|
2010-12-07 11:31:57 +00:00
|
|
|
if (!FLAG_sliding_state_window && !ticker_->IsActive()) {
|
|
|
|
ticker_->Start();
|
|
|
|
}
|
2010-02-17 13:23:46 +00:00
|
|
|
}
|
|
|
|
profiler_->resume();
|
2009-08-04 14:14:01 +00:00
|
|
|
}
|
2009-05-29 06:56:23 +00:00
|
|
|
}
|
2010-02-17 13:23:46 +00:00
|
|
|
if (flags &
|
2009-08-04 14:14:01 +00:00
|
|
|
(PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
|
2010-02-17 13:23:46 +00:00
|
|
|
if (heap_profiler_nesting_++ == 0) {
|
2010-03-01 10:41:34 +00:00
|
|
|
++logging_nesting_;
|
2010-02-17 13:23:46 +00:00
|
|
|
FLAG_log_gc = true;
|
|
|
|
}
|
2009-05-25 08:25:36 +00:00
|
|
|
}
|
2009-01-29 19:47:00 +00:00
|
|
|
}
|
2009-05-05 15:57:47 +00:00
|
|
|
|
|
|
|
|
2009-05-28 13:56:32 +00:00
|
|
|
// This function can be called when Log's mutex is acquired,
|
|
|
|
// either from main or Profiler's thread.
|
|
|
|
void Logger::StopLoggingAndProfiling() {
|
|
|
|
Log::stop();
|
2010-02-17 13:23:46 +00:00
|
|
|
PauseProfiler(PROFILER_MODULE_CPU, 0);
|
2009-05-28 13:56:32 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-05-25 08:25:36 +00:00
|
|
|
bool Logger::IsProfilerSamplerActive() {
|
|
|
|
return ticker_->IsActive();
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-05-05 15:57:47 +00:00
|
|
|
int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
|
|
|
|
return Log::GetLogLines(from_pos, dest_buf, max_size);
|
|
|
|
}
|
|
|
|
|
2009-05-20 09:04:13 +00:00
|
|
|
|
2010-12-07 11:31:57 +00:00
|
|
|
class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor {
|
|
|
|
public:
|
|
|
|
EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis,
|
|
|
|
Handle<Code>* code_objects,
|
|
|
|
int* count)
|
|
|
|
: sfis_(sfis), code_objects_(code_objects), count_(count) { }
|
|
|
|
|
|
|
|
virtual void EnterContext(Context* context) {}
|
|
|
|
virtual void LeaveContext(Context* context) {}
|
|
|
|
|
|
|
|
virtual void VisitFunction(JSFunction* function) {
|
|
|
|
if (sfis_ != NULL) {
|
|
|
|
sfis_[*count_] = Handle<SharedFunctionInfo>(function->shared());
|
|
|
|
}
|
|
|
|
if (code_objects_ != NULL) {
|
|
|
|
ASSERT(function->code()->kind() == Code::OPTIMIZED_FUNCTION);
|
|
|
|
code_objects_[*count_] = Handle<Code>(function->code());
|
|
|
|
}
|
|
|
|
*count_ = *count_ + 1;
|
|
|
|
}
|
|
|
|
|
|
|
|
private:
|
|
|
|
Handle<SharedFunctionInfo>* sfis_;
|
|
|
|
Handle<Code>* code_objects_;
|
|
|
|
int* count_;
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
|
|
static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis,
|
|
|
|
Handle<Code>* code_objects) {
|
2009-10-07 12:20:02 +00:00
|
|
|
AssertNoAllocation no_alloc;
|
2009-05-20 09:04:13 +00:00
|
|
|
int compiled_funcs_count = 0;
|
2010-12-07 11:31:57 +00:00
|
|
|
|
|
|
|
// Iterate the heap to find shared function info objects and record
|
|
|
|
// the unoptimized code for them.
|
2009-10-07 12:20:02 +00:00
|
|
|
HeapIterator iterator;
|
2010-01-25 22:53:18 +00:00
|
|
|
for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
|
2009-10-07 12:20:02 +00:00
|
|
|
if (!obj->IsSharedFunctionInfo()) continue;
|
|
|
|
SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj);
|
|
|
|
if (sfi->is_compiled()
|
|
|
|
&& (!sfi->script()->IsScript()
|
|
|
|
|| Script::cast(sfi->script())->HasValidSource())) {
|
2010-12-07 11:31:57 +00:00
|
|
|
if (sfis != NULL) {
|
2009-10-07 12:20:02 +00:00
|
|
|
sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
|
2010-12-07 11:31:57 +00:00
|
|
|
}
|
|
|
|
if (code_objects != NULL) {
|
|
|
|
code_objects[compiled_funcs_count] = Handle<Code>(sfi->code());
|
|
|
|
}
|
2009-10-07 12:20:02 +00:00
|
|
|
++compiled_funcs_count;
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
2009-10-07 12:20:02 +00:00
|
|
|
}
|
2010-12-07 11:31:57 +00:00
|
|
|
|
|
|
|
// Iterate all optimized functions in all contexts.
|
|
|
|
EnumerateOptimizedFunctionsVisitor visitor(sfis,
|
|
|
|
code_objects,
|
|
|
|
&compiled_funcs_count);
|
|
|
|
Deoptimizer::VisitAllOptimizedFunctions(&visitor);
|
|
|
|
|
2009-10-07 12:20:02 +00:00
|
|
|
return compiled_funcs_count;
|
|
|
|
}
|
2009-05-20 09:04:13 +00:00
|
|
|
|
|
|
|
|
2009-11-11 12:35:50 +00:00
|
|
|
void Logger::LogCodeObject(Object* object) {
|
|
|
|
if (FLAG_log_code) {
|
|
|
|
Code* code_object = Code::cast(object);
|
|
|
|
LogEventsAndTags tag = Logger::STUB_TAG;
|
|
|
|
const char* description = "Unknown code from the snapshot";
|
|
|
|
switch (code_object->kind()) {
|
|
|
|
case Code::FUNCTION:
|
2010-12-07 11:31:57 +00:00
|
|
|
case Code::OPTIMIZED_FUNCTION:
|
2009-11-11 12:35:50 +00:00
|
|
|
return; // We log this later using LogCompiledFunctions.
|
2010-12-07 11:31:57 +00:00
|
|
|
case Code::BINARY_OP_IC: // fall through
|
|
|
|
case Code::TYPE_RECORDING_BINARY_OP_IC: // fall through
|
|
|
|
case Code::COMPARE_IC: // fall through
|
2009-11-11 12:35:50 +00:00
|
|
|
case Code::STUB:
|
2010-08-30 11:48:07 +00:00
|
|
|
description =
|
|
|
|
CodeStub::MajorName(CodeStub::GetMajorKey(code_object), true);
|
2010-02-05 13:07:00 +00:00
|
|
|
if (description == NULL)
|
|
|
|
description = "A stub from the snapshot";
|
2009-11-11 12:35:50 +00:00
|
|
|
tag = Logger::STUB_TAG;
|
|
|
|
break;
|
|
|
|
case Code::BUILTIN:
|
|
|
|
description = "A builtin from the snapshot";
|
|
|
|
tag = Logger::BUILTIN_TAG;
|
|
|
|
break;
|
|
|
|
case Code::KEYED_LOAD_IC:
|
|
|
|
description = "A keyed load IC from the snapshot";
|
|
|
|
tag = Logger::KEYED_LOAD_IC_TAG;
|
|
|
|
break;
|
|
|
|
case Code::LOAD_IC:
|
|
|
|
description = "A load IC from the snapshot";
|
|
|
|
tag = Logger::LOAD_IC_TAG;
|
|
|
|
break;
|
|
|
|
case Code::STORE_IC:
|
|
|
|
description = "A store IC from the snapshot";
|
|
|
|
tag = Logger::STORE_IC_TAG;
|
|
|
|
break;
|
|
|
|
case Code::KEYED_STORE_IC:
|
|
|
|
description = "A keyed store IC from the snapshot";
|
|
|
|
tag = Logger::KEYED_STORE_IC_TAG;
|
|
|
|
break;
|
|
|
|
case Code::CALL_IC:
|
|
|
|
description = "A call IC from the snapshot";
|
|
|
|
tag = Logger::CALL_IC_TAG;
|
|
|
|
break;
|
2010-06-07 08:27:32 +00:00
|
|
|
case Code::KEYED_CALL_IC:
|
|
|
|
description = "A keyed call IC from the snapshot";
|
|
|
|
tag = Logger::KEYED_CALL_IC_TAG;
|
|
|
|
break;
|
2009-11-11 12:35:50 +00:00
|
|
|
}
|
2010-04-06 10:36:38 +00:00
|
|
|
PROFILE(CodeCreateEvent(tag, code_object, description));
|
2009-11-11 12:35:50 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-10-19 16:45:11 +00:00
|
|
|
void Logger::LogCodeInfo() {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
|
|
|
|
#if V8_TARGET_ARCH_IA32
|
|
|
|
const char arch[] = "ia32";
|
|
|
|
#elif V8_TARGET_ARCH_X64
|
|
|
|
const char arch[] = "x64";
|
|
|
|
#elif V8_TARGET_ARCH_ARM
|
|
|
|
const char arch[] = "arm";
|
|
|
|
#else
|
|
|
|
const char arch[] = "unknown";
|
|
|
|
#endif
|
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("code-info,%s,%d\n", arch, Code::kHeaderSize);
|
|
|
|
msg.WriteToLogFile();
|
|
|
|
#endif // ENABLE_LOGGING_AND_PROFILING
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg) {
|
|
|
|
if (!FLAG_ll_prof || Log::output_code_handle_ == NULL) return;
|
|
|
|
int pos = static_cast<int>(ftell(Log::output_code_handle_));
|
2010-10-25 08:26:12 +00:00
|
|
|
size_t rv = fwrite(code->instruction_start(), 1, code->instruction_size(),
|
|
|
|
Log::output_code_handle_);
|
2010-10-25 08:22:23 +00:00
|
|
|
ASSERT(static_cast<size_t>(code->instruction_size()) == rv);
|
|
|
|
USE(rv);
|
2010-10-19 16:45:11 +00:00
|
|
|
msg->Append(",%d", pos);
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-02-04 21:34:03 +00:00
|
|
|
void Logger::LogCodeObjects() {
|
|
|
|
AssertNoAllocation no_alloc;
|
|
|
|
HeapIterator iterator;
|
|
|
|
for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
|
|
|
|
if (obj->IsCode()) LogCodeObject(obj);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-10-07 12:20:02 +00:00
|
|
|
void Logger::LogCompiledFunctions() {
|
|
|
|
HandleScope scope;
|
2010-12-07 11:31:57 +00:00
|
|
|
const int compiled_funcs_count = EnumerateCompiledFunctions(NULL, NULL);
|
2010-05-05 12:25:58 +00:00
|
|
|
ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
|
2010-12-07 11:31:57 +00:00
|
|
|
ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
|
|
|
|
EnumerateCompiledFunctions(sfis.start(), code_objects.start());
|
2009-05-20 09:04:13 +00:00
|
|
|
|
|
|
|
// During iteration, there can be heap allocation due to
|
|
|
|
// GetScriptLineNumber call.
|
|
|
|
for (int i = 0; i < compiled_funcs_count; ++i) {
|
|
|
|
Handle<SharedFunctionInfo> shared = sfis[i];
|
|
|
|
Handle<String> name(String::cast(shared->name()));
|
|
|
|
Handle<String> func_name(name->length() > 0 ?
|
|
|
|
*name : shared->inferred_name());
|
|
|
|
if (shared->script()->IsScript()) {
|
|
|
|
Handle<Script> script(Script::cast(shared->script()));
|
|
|
|
if (script->name()->IsString()) {
|
|
|
|
Handle<String> script_name(String::cast(script->name()));
|
|
|
|
int line_num = GetScriptLineNumber(script, shared->start_position());
|
|
|
|
if (line_num > 0) {
|
2010-04-07 14:18:26 +00:00
|
|
|
PROFILE(CodeCreateEvent(
|
|
|
|
Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
|
2010-12-07 11:31:57 +00:00
|
|
|
*code_objects[i], *func_name,
|
2010-04-07 14:18:26 +00:00
|
|
|
*script_name, line_num + 1));
|
2009-05-20 09:04:13 +00:00
|
|
|
} else {
|
2010-04-07 14:18:26 +00:00
|
|
|
// Can't distinguish eval and script here, so always use Script.
|
|
|
|
PROFILE(CodeCreateEvent(
|
|
|
|
Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
|
2010-12-07 11:31:57 +00:00
|
|
|
*code_objects[i], *script_name));
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
2009-11-23 09:19:24 +00:00
|
|
|
} else {
|
2010-04-06 10:36:38 +00:00
|
|
|
PROFILE(CodeCreateEvent(
|
2010-04-07 14:18:26 +00:00
|
|
|
Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
|
2010-12-07 11:31:57 +00:00
|
|
|
*code_objects[i], *func_name));
|
2009-11-23 09:19:24 +00:00
|
|
|
}
|
2010-03-11 16:24:31 +00:00
|
|
|
} else if (shared->IsApiFunction()) {
|
2009-11-23 09:19:24 +00:00
|
|
|
// API function.
|
2010-03-11 16:24:31 +00:00
|
|
|
FunctionTemplateInfo* fun_data = shared->get_api_func_data();
|
2009-11-23 09:19:24 +00:00
|
|
|
Object* raw_call_data = fun_data->call_code();
|
|
|
|
if (!raw_call_data->IsUndefined()) {
|
|
|
|
CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
|
|
|
|
Object* callback_obj = call_data->callback();
|
|
|
|
Address entry_point = v8::ToCData<Address>(callback_obj);
|
2010-04-06 10:36:38 +00:00
|
|
|
PROFILE(CallbackEvent(*func_name, entry_point));
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
2009-11-23 09:19:24 +00:00
|
|
|
} else {
|
2010-04-06 10:36:38 +00:00
|
|
|
PROFILE(CodeCreateEvent(
|
2010-12-07 11:31:57 +00:00
|
|
|
Logger::LAZY_COMPILE_TAG, *code_objects[i], *func_name));
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2009-11-25 16:39:18 +00:00
|
|
|
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
void Logger::LogFunctionObjects() {
|
|
|
|
AssertNoAllocation no_alloc;
|
|
|
|
HeapIterator iterator;
|
2010-01-25 22:53:18 +00:00
|
|
|
for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
if (!obj->IsJSFunction()) continue;
|
|
|
|
JSFunction* jsf = JSFunction::cast(obj);
|
|
|
|
if (!jsf->is_compiled()) continue;
|
2010-04-06 10:36:38 +00:00
|
|
|
PROFILE(FunctionCreateEvent(jsf));
|
Fix issue 553: function frame is skipped in profile when compare stub is called.
The problem appeared due to a fact that stubs doesn't create a stack
frame, reusing the stack frame of the caller function. When building
stack traces, the current function is retrieved from PC, and its
callees are retrieved by traversing the stack backwards. Thus, for
stubs, the stub itself was discovered via PC, and then stub's caller's
caller was retrieved from stack.
To fix this problem, a pointer to JSFunction object is now captured
from the topmost stack frame, and is saved into stack trace log
record. Then a simple heuristics is applied whether a referred
function should be added to decoded stack, or not, to avoid reporting
the same function twice (from PC and from the pointer.)
BUG=553
TEST=added to mjsunit/tools/tickprocessor
Review URL: http://codereview.chromium.org/546089
git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3673 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
2010-01-21 16:42:41 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-11-25 16:39:18 +00:00
|
|
|
void Logger::LogAccessorCallbacks() {
|
|
|
|
AssertNoAllocation no_alloc;
|
|
|
|
HeapIterator iterator;
|
2010-01-25 22:53:18 +00:00
|
|
|
for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
|
2009-11-25 16:39:18 +00:00
|
|
|
if (!obj->IsAccessorInfo()) continue;
|
|
|
|
AccessorInfo* ai = AccessorInfo::cast(obj);
|
|
|
|
if (!ai->name()->IsString()) continue;
|
|
|
|
String* name = String::cast(ai->name());
|
|
|
|
Address getter_entry = v8::ToCData<Address>(ai->getter());
|
|
|
|
if (getter_entry != 0) {
|
2010-04-06 10:36:38 +00:00
|
|
|
PROFILE(GetterCallbackEvent(name, getter_entry));
|
2009-11-25 16:39:18 +00:00
|
|
|
}
|
|
|
|
Address setter_entry = v8::ToCData<Address>(ai->setter());
|
|
|
|
if (setter_entry != 0) {
|
2010-04-06 10:36:38 +00:00
|
|
|
PROFILE(SetterCallbackEvent(name, setter_entry));
|
2009-11-25 16:39:18 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
|
|
|
|
|
|
|
|
bool Logger::Setup() {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
// --log-all enables all the log flags.
|
|
|
|
if (FLAG_log_all) {
|
2009-02-17 12:49:35 +00:00
|
|
|
FLAG_log_runtime = true;
|
2008-07-03 15:10:15 +00:00
|
|
|
FLAG_log_api = true;
|
|
|
|
FLAG_log_code = true;
|
|
|
|
FLAG_log_gc = true;
|
|
|
|
FLAG_log_suspect = true;
|
|
|
|
FLAG_log_handles = true;
|
2008-09-11 11:24:45 +00:00
|
|
|
FLAG_log_regexp = true;
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
// --prof implies --log-code.
|
|
|
|
if (FLAG_prof) FLAG_log_code = true;
|
|
|
|
|
2010-10-19 16:45:11 +00:00
|
|
|
// --ll-prof implies --log-code and --log-snapshot-positions.
|
|
|
|
if (FLAG_ll_prof) {
|
|
|
|
FLAG_log_code = true;
|
|
|
|
FLAG_log_snapshot_positions = true;
|
|
|
|
}
|
|
|
|
|
2009-05-25 08:25:36 +00:00
|
|
|
// --prof_lazy controls --log-code, implies --noprof_auto.
|
|
|
|
if (FLAG_prof_lazy) {
|
|
|
|
FLAG_log_code = false;
|
|
|
|
FLAG_prof_auto = false;
|
|
|
|
}
|
|
|
|
|
2009-06-24 13:09:34 +00:00
|
|
|
bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
|
2009-02-17 12:49:35 +00:00
|
|
|
|| FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
|
2009-06-24 13:09:34 +00:00
|
|
|
|| FLAG_log_regexp || FLAG_log_state_changes;
|
|
|
|
|
|
|
|
bool open_log_file = start_logging || FLAG_prof_lazy;
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
// If we're logging anything, we need to open the log file.
|
2008-10-02 15:35:28 +00:00
|
|
|
if (open_log_file) {
|
2008-07-03 15:10:15 +00:00
|
|
|
if (strcmp(FLAG_logfile, "-") == 0) {
|
2009-05-05 15:57:47 +00:00
|
|
|
Log::OpenStdout();
|
|
|
|
} else if (strcmp(FLAG_logfile, "*") == 0) {
|
|
|
|
Log::OpenMemoryBuffer();
|
2008-10-15 08:50:22 +00:00
|
|
|
} else if (strchr(FLAG_logfile, '%') != NULL) {
|
|
|
|
// If there's a '%' in the log file name we have to expand
|
|
|
|
// placeholders.
|
|
|
|
HeapStringAllocator allocator;
|
|
|
|
StringStream stream(&allocator);
|
|
|
|
for (const char* p = FLAG_logfile; *p; p++) {
|
|
|
|
if (*p == '%') {
|
|
|
|
p++;
|
|
|
|
switch (*p) {
|
|
|
|
case '\0':
|
|
|
|
// If there's a % at the end of the string we back up
|
|
|
|
// one character so we can escape the loop properly.
|
|
|
|
p--;
|
|
|
|
break;
|
|
|
|
case 't': {
|
|
|
|
// %t expands to the current time in milliseconds.
|
2009-08-05 08:53:02 +00:00
|
|
|
double time = OS::TimeCurrentMillis();
|
|
|
|
stream.Add("%.0f", FmtElm(time));
|
2008-10-15 08:50:22 +00:00
|
|
|
break;
|
|
|
|
}
|
2008-10-15 08:50:34 +00:00
|
|
|
case '%':
|
|
|
|
// %% expands (contracts really) to %.
|
|
|
|
stream.Put('%');
|
|
|
|
break;
|
2008-10-15 08:50:22 +00:00
|
|
|
default:
|
|
|
|
// All other %'s expand to themselves.
|
2008-10-15 08:50:34 +00:00
|
|
|
stream.Put('%');
|
2008-10-15 08:50:22 +00:00
|
|
|
stream.Put(*p);
|
|
|
|
break;
|
|
|
|
}
|
|
|
|
} else {
|
|
|
|
stream.Put(*p);
|
|
|
|
}
|
|
|
|
}
|
2008-11-11 14:16:24 +00:00
|
|
|
SmartPointer<const char> expanded = stream.ToCString();
|
2009-05-05 15:57:47 +00:00
|
|
|
Log::OpenFile(*expanded);
|
2008-07-03 15:10:15 +00:00
|
|
|
} else {
|
2009-05-05 15:57:47 +00:00
|
|
|
Log::OpenFile(FLAG_logfile);
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2010-10-19 16:45:11 +00:00
|
|
|
if (FLAG_ll_prof) LogCodeInfo();
|
|
|
|
|
2009-06-02 09:33:17 +00:00
|
|
|
ticker_ = new Ticker(kSamplingIntervalMs);
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
|
|
|
|
sliding_state_window_ = new SlidingStateWindow();
|
|
|
|
}
|
|
|
|
|
2010-03-01 10:41:34 +00:00
|
|
|
if (start_logging) {
|
|
|
|
logging_nesting_ = 1;
|
|
|
|
}
|
2009-06-24 13:09:34 +00:00
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
if (FLAG_prof) {
|
|
|
|
profiler_ = new Profiler();
|
2009-06-24 13:09:34 +00:00
|
|
|
if (!FLAG_prof_auto) {
|
2009-01-29 19:47:00 +00:00
|
|
|
profiler_->pause();
|
2009-06-24 13:09:34 +00:00
|
|
|
} else {
|
2010-03-01 10:41:34 +00:00
|
|
|
logging_nesting_ = 1;
|
2009-06-24 13:09:34 +00:00
|
|
|
}
|
2009-10-28 09:13:11 +00:00
|
|
|
if (!FLAG_prof_lazy) {
|
|
|
|
profiler_->Engage();
|
|
|
|
}
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
2009-05-28 13:56:32 +00:00
|
|
|
LogMessageBuilder::set_write_failure_handler(StopLoggingAndProfiling);
|
2008-07-03 15:10:15 +00:00
|
|
|
return true;
|
|
|
|
|
|
|
|
#else
|
|
|
|
return false;
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2010-12-07 11:31:57 +00:00
|
|
|
void Logger::EnsureTickerStarted() {
|
2010-12-16 12:14:56 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2010-12-07 11:31:57 +00:00
|
|
|
ASSERT(ticker_ != NULL);
|
|
|
|
if (!ticker_->IsActive()) ticker_->Start();
|
2010-12-16 12:14:56 +00:00
|
|
|
#endif
|
2010-12-07 11:31:57 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::EnsureTickerStopped() {
|
2010-12-16 12:14:56 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2010-12-07 11:31:57 +00:00
|
|
|
if (ticker_ != NULL && ticker_->IsActive()) ticker_->Stop();
|
2010-12-16 12:14:56 +00:00
|
|
|
#endif
|
2010-12-07 11:31:57 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
void Logger::TearDown() {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-28 13:56:32 +00:00
|
|
|
LogMessageBuilder::set_write_failure_handler(NULL);
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
// Stop the profiler before closing the file.
|
|
|
|
if (profiler_ != NULL) {
|
|
|
|
profiler_->Disengage();
|
|
|
|
delete profiler_;
|
|
|
|
profiler_ = NULL;
|
|
|
|
}
|
|
|
|
|
|
|
|
delete sliding_state_window_;
|
2009-05-25 08:25:36 +00:00
|
|
|
sliding_state_window_ = NULL;
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
delete ticker_;
|
2009-05-25 08:25:36 +00:00
|
|
|
ticker_ = NULL;
|
2008-07-03 15:10:15 +00:00
|
|
|
|
2009-05-05 15:57:47 +00:00
|
|
|
Log::Close();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::EnableSlidingStateWindow() {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
// If the ticker is NULL, Logger::Setup has not been called yet. In
|
|
|
|
// that case, we set the sliding_state_window flag so that the
|
|
|
|
// sliding window computation will be started when Logger::Setup is
|
|
|
|
// called.
|
|
|
|
if (ticker_ == NULL) {
|
|
|
|
FLAG_sliding_state_window = true;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
// Otherwise, if the sliding state window computation has not been
|
|
|
|
// started we do it now.
|
|
|
|
if (sliding_state_window_ == NULL) {
|
|
|
|
sliding_state_window_ = new SlidingStateWindow();
|
|
|
|
}
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
} } // namespace v8::internal
|