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"
|
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"
|
|
|
|
#include "serialize.h"
|
2008-10-15 08:50:22 +00:00
|
|
|
#include "string-stream.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) {
|
2009-03-03 11:56:44 +00:00
|
|
|
if (sample->state == GC) {
|
2009-03-06 13:07:57 +00:00
|
|
|
sample->frames_count = 0;
|
2009-03-03 11:56:44 +00:00
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
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.
|
|
|
|
sample->frames_count = 0;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
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
|
|
|
const Address functionAddr =
|
|
|
|
sample->fp + JavaScriptFrameConstants::kFunctionOffset;
|
|
|
|
if (SafeStackFrameIterator::IsWithinBounds(sample->sp, js_entry_sp,
|
|
|
|
functionAddr)) {
|
|
|
|
sample->function = Memory::Address_at(functionAddr) - kHeapObjectTag;
|
|
|
|
}
|
|
|
|
|
2009-11-23 14:43:00 +00:00
|
|
|
int i = 0;
|
|
|
|
const Address callback = Logger::current_state_ != NULL ?
|
|
|
|
Logger::current_state_->external_callback() : NULL;
|
|
|
|
if (callback != NULL) {
|
|
|
|
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) {
|
|
|
|
sample->stack[i++] = it.frame()->pc();
|
|
|
|
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:
|
2009-06-02 09:33:17 +00:00
|
|
|
explicit Ticker(int interval):
|
|
|
|
Sampler(interval, FLAG_prof), window_(NULL), profiler_(NULL) {}
|
2008-07-03 15:10:15 +00:00
|
|
|
|
|
|
|
~Ticker() { if (IsActive()) Stop(); }
|
|
|
|
|
2009-07-01 08:46:59 +00:00
|
|
|
void SampleStack(TickSample* sample) {
|
|
|
|
StackTracer::Trace(sample);
|
|
|
|
}
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
void Tick(TickSample* sample) {
|
|
|
|
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;
|
|
|
|
if (!profiler_ && IsActive()) Stop();
|
|
|
|
}
|
|
|
|
|
|
|
|
void SetProfiler(Profiler* profiler) {
|
|
|
|
profiler_ = profiler;
|
2009-05-25 08:25:36 +00:00
|
|
|
if (!FLAG_prof_lazy && !IsActive()) Start();
|
2008-07-03 15:10:15 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
void ClearProfiler() {
|
|
|
|
profiler_ = NULL;
|
|
|
|
if (!window_ && IsActive()) Stop();
|
|
|
|
}
|
|
|
|
|
|
|
|
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();
|
2009-06-08 13:39:48 +00:00
|
|
|
Logger::LogAliases();
|
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;
|
|
|
|
bool overflow = Logger::profiler_->Remove(&sample);
|
|
|
|
while (running_) {
|
|
|
|
LOG(TickEvent(&sample, overflow));
|
|
|
|
overflow = Logger::profiler_->Remove(&sample);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
//
|
|
|
|
// Logger class implementation.
|
|
|
|
//
|
|
|
|
Ticker* Logger::ticker_ = NULL;
|
|
|
|
Profiler* Logger::profiler_ = NULL;
|
|
|
|
VMState* Logger::current_state_ = NULL;
|
2009-03-30 13:32:28 +00:00
|
|
|
VMState Logger::bottom_state_(EXTERNAL);
|
2008-07-03 15:10:15 +00:00
|
|
|
SlidingStateWindow* Logger::sliding_state_window_ = NULL;
|
2009-06-08 13:39:48 +00:00
|
|
|
const char** Logger::log_events_ = NULL;
|
2009-06-15 09:37:50 +00:00
|
|
|
CompressionHelper* Logger::compression_helper_ = NULL;
|
2009-06-24 13:09:34 +00:00
|
|
|
bool Logger::is_logging_ = false;
|
2009-06-08 13:39:48 +00:00
|
|
|
|
|
|
|
#define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name,
|
|
|
|
const char* kLongLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
|
|
|
|
LOG_EVENTS_AND_TAGS_LIST(DECLARE_LONG_EVENT)
|
|
|
|
};
|
|
|
|
#undef DECLARE_LONG_EVENT
|
|
|
|
|
|
|
|
#define DECLARE_SHORT_EVENT(ignore1, ignore2, short_name) short_name,
|
|
|
|
const char* kCompressedLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
|
|
|
|
LOG_EVENTS_AND_TAGS_LIST(DECLARE_SHORT_EVENT)
|
|
|
|
};
|
|
|
|
#undef DECLARE_SHORT_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-11 14:08:34 +00:00
|
|
|
if (FLAG_compress_log) {
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append("profiler,\"compression\",%d\n", kCompressionWindowSize);
|
2009-06-11 14:08:34 +00:00
|
|
|
}
|
2009-05-29 06:56:23 +00:00
|
|
|
msg.WriteToLogFile();
|
|
|
|
}
|
|
|
|
|
2009-06-08 13:39:48 +00:00
|
|
|
|
|
|
|
void Logger::LogAliases() {
|
|
|
|
if (!Log::IsEnabled() || !FLAG_compress_log) return;
|
|
|
|
LogMessageBuilder msg;
|
|
|
|
for (int i = 0; i < NUMBER_OF_LOG_EVENTS; ++i) {
|
|
|
|
msg.Append("alias,%s,%s\n",
|
|
|
|
kCompressedLogEventsNames[i], kLongLogEventsNames[i]);
|
|
|
|
}
|
|
|
|
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::Preamble(const char* content) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
2009-05-25 08:39:22 +00:00
|
|
|
if (!Log::IsEnabled() || !FLAG_log_code) return;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-03-31 09:06:37 +00:00
|
|
|
msg.WriteCStringToLogFile(content);
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
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
|
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,%d\n", name, value);
|
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
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');
|
|
|
|
Object* obj = args->GetElement(format[i] - '0');
|
|
|
|
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-06-18 07:59:13 +00:00
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
|
|
|
|
// A class that contains all common code dealing with record compression.
|
|
|
|
class CompressionHelper {
|
|
|
|
public:
|
|
|
|
explicit CompressionHelper(int window_size)
|
|
|
|
: compressor_(window_size), repeat_count_(0) { }
|
|
|
|
|
|
|
|
// Handles storing message in compressor, retrieving the previous one and
|
|
|
|
// prefixing it with repeat count, if needed.
|
|
|
|
// Returns true if message needs to be written to log.
|
|
|
|
bool HandleMessage(LogMessageBuilder* msg) {
|
|
|
|
if (!msg->StoreInCompressor(&compressor_)) {
|
|
|
|
// Current message repeats the previous one, don't write it.
|
|
|
|
++repeat_count_;
|
|
|
|
return false;
|
|
|
|
}
|
|
|
|
if (repeat_count_ == 0) {
|
|
|
|
return msg->RetrieveCompressedPrevious(&compressor_);
|
|
|
|
}
|
|
|
|
OS::SNPrintF(prefix_, "%s,%d,",
|
|
|
|
Logger::log_events_[Logger::REPEAT_META_EVENT],
|
|
|
|
repeat_count_ + 1);
|
|
|
|
repeat_count_ = 0;
|
|
|
|
return msg->RetrieveCompressedPrevious(&compressor_, prefix_.start());
|
|
|
|
}
|
|
|
|
|
|
|
|
private:
|
|
|
|
LogRecordCompressor compressor_;
|
|
|
|
int repeat_count_;
|
|
|
|
EmbeddedVector<char, 20> prefix_;
|
|
|
|
};
|
|
|
|
|
|
|
|
#endif // ENABLE_LOGGING_AND_PROFILING
|
|
|
|
|
|
|
|
|
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,",
|
|
|
|
log_events_[CODE_CREATION_EVENT], log_events_[CALLBACK_TAG]);
|
|
|
|
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
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
|
|
|
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
|
|
|
|
}
|
|
|
|
|
|
|
|
|
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;
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
|
|
|
|
msg.AppendAddress(code->address());
|
|
|
|
msg.Append(",%d,\"", code->ExecutableSize());
|
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('"');
|
2009-06-18 07:59:13 +00:00
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
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);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
|
|
|
|
msg.AppendAddress(code->address());
|
2009-06-18 07:59:13 +00:00
|
|
|
msg.Append(",%d,\"%s\"", code->ExecutableSize(), *str);
|
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
|
|
|
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);
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
|
|
|
|
msg.AppendAddress(code->address());
|
2009-06-18 07:59:13 +00:00
|
|
|
msg.Append(",%d,\"%s %s:%d\"",
|
2009-06-15 09:37:50 +00:00
|
|
|
code->ExecutableSize(), *str, *sourcestr, line);
|
2009-06-18 07:59:13 +00:00
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
|
|
|
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;
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
|
|
|
|
msg.AppendAddress(code->address());
|
2009-06-18 07:59:13 +00:00
|
|
|
msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
|
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
|
|
|
msg.Append('\n');
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#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,",
|
|
|
|
log_events_[CODE_CREATION_EVENT], log_events_[REG_EXP_TAG]);
|
|
|
|
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('\"');
|
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
|
|
|
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;
|
|
|
|
msg.Append("%s,", log_events_[SNAPSHOT_POSITION_EVENT]);
|
|
|
|
msg.AppendAddress(addr);
|
|
|
|
msg.Append(",%d", pos);
|
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
|
|
|
msg.Append('\n');
|
|
|
|
msg.WriteToLogFile();
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
void Logger::FunctionCreateEvent(JSFunction* function) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
static Address prev_code = NULL;
|
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;
|
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("%s,", log_events_[FUNCTION_CREATION_EVENT]);
|
|
|
|
msg.AppendAddress(function->address());
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append(',');
|
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->code()->address(), prev_code);
|
|
|
|
prev_code = function->code()->address();
|
2009-06-15 09:37:50 +00:00
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
|
|
|
msg.Append('\n');
|
2009-02-17 08:21:24 +00:00
|
|
|
msg.WriteToLogFile();
|
2008-07-03 15:10:15 +00:00
|
|
|
#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) {
|
|
|
|
static Address prev_to_ = NULL;
|
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;
|
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("%s,", log_events_[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(',');
|
|
|
|
msg.AppendAddress(to, prev_to_);
|
|
|
|
prev_to_ = to;
|
2009-06-15 09:37:50 +00:00
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
|
|
|
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;
|
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("%s,", log_events_[event]);
|
|
|
|
msg.AppendAddress(from);
|
2010-01-18 16:04:25 +00:00
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
|
|
|
}
|
|
|
|
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,
|
|
|
|
int capacity, int used) {
|
|
|
|
#ifdef ENABLE_LOGGING_AND_PROFILING
|
|
|
|
if (!Log::IsEnabled() || !FLAG_log_gc) return;
|
|
|
|
LogMessageBuilder msg;
|
|
|
|
msg.Append("heap-sample-stats,\"%s\",\"%s\",%d,%d\n",
|
|
|
|
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-06-15 09:37:50 +00:00
|
|
|
static Address prev_sp = NULL;
|
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
|
|
|
static Address prev_function = NULL;
|
2009-02-17 12:49:35 +00:00
|
|
|
LogMessageBuilder msg;
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.Append("%s,", log_events_[TICK_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
|
|
|
Address prev_addr = sample->pc;
|
2009-06-15 09:37:50 +00:00
|
|
|
msg.AppendAddress(prev_addr);
|
|
|
|
msg.Append(',');
|
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(sample->sp, prev_sp);
|
|
|
|
prev_sp = sample->sp;
|
|
|
|
msg.Append(',');
|
|
|
|
msg.AppendAddress(sample->function, prev_function);
|
|
|
|
prev_function = 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(',');
|
|
|
|
msg.AppendAddress(sample->stack[i], prev_addr);
|
|
|
|
prev_addr = sample->stack[i];
|
2009-02-17 14:45:45 +00:00
|
|
|
}
|
2009-06-15 09:37:50 +00:00
|
|
|
if (FLAG_compress_log) {
|
|
|
|
ASSERT(compression_helper_ != NULL);
|
|
|
|
if (!compression_helper_->HandleMessage(&msg)) return;
|
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;
|
|
|
|
if (!profiler_->paused()) {
|
|
|
|
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
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-08-04 14:14:01 +00:00
|
|
|
void Logger::PauseProfiler(int flags) {
|
|
|
|
if (!Log::IsEnabled()) return;
|
|
|
|
const int active_modules = GetActiveProfilerModules();
|
|
|
|
const int modules_to_disable = active_modules & flags;
|
|
|
|
if (modules_to_disable == PROFILER_MODULE_NONE) return;
|
|
|
|
|
|
|
|
if (modules_to_disable & PROFILER_MODULE_CPU) {
|
|
|
|
profiler_->pause();
|
|
|
|
if (FLAG_prof_lazy) {
|
|
|
|
if (!FLAG_sliding_state_window) ticker_->Stop();
|
|
|
|
FLAG_log_code = false;
|
|
|
|
// Must be the same message as Log::kDynamicBufferSeal.
|
|
|
|
LOG(UncheckedStringEvent("profiler", "pause"));
|
|
|
|
}
|
2009-05-29 06:56:23 +00:00
|
|
|
}
|
2009-08-04 14:14:01 +00:00
|
|
|
if (modules_to_disable &
|
|
|
|
(PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
|
|
|
|
FLAG_log_gc = false;
|
|
|
|
}
|
|
|
|
// Turn off logging if no active modules remain.
|
2009-08-05 07:35:05 +00:00
|
|
|
if ((active_modules & ~flags) == PROFILER_MODULE_NONE) {
|
2009-08-04 14:14:01 +00:00
|
|
|
is_logging_ = false;
|
2009-05-25 08:25:36 +00:00
|
|
|
}
|
2009-01-29 19:47:00 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-08-04 14:14:01 +00:00
|
|
|
void Logger::ResumeProfiler(int flags) {
|
|
|
|
if (!Log::IsEnabled()) return;
|
|
|
|
const int modules_to_enable = ~GetActiveProfilerModules() & flags;
|
|
|
|
if (modules_to_enable != PROFILER_MODULE_NONE) {
|
|
|
|
is_logging_ = true;
|
|
|
|
}
|
|
|
|
if (modules_to_enable & PROFILER_MODULE_CPU) {
|
|
|
|
if (FLAG_prof_lazy) {
|
2009-10-28 09:13:11 +00:00
|
|
|
profiler_->Engage();
|
2009-08-04 14:14:01 +00:00
|
|
|
LOG(UncheckedStringEvent("profiler", "resume"));
|
|
|
|
FLAG_log_code = true;
|
|
|
|
LogCompiledFunctions();
|
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
|
|
|
LogFunctionObjects();
|
2009-11-25 16:39:18 +00:00
|
|
|
LogAccessorCallbacks();
|
2009-08-04 14:14:01 +00:00
|
|
|
if (!FLAG_sliding_state_window) ticker_->Start();
|
|
|
|
}
|
|
|
|
profiler_->resume();
|
2009-05-29 06:56:23 +00:00
|
|
|
}
|
2009-08-04 14:14:01 +00:00
|
|
|
if (modules_to_enable &
|
|
|
|
(PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
|
|
|
|
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();
|
2009-08-04 14:14:01 +00:00
|
|
|
PauseProfiler(PROFILER_MODULE_CPU);
|
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
|
|
|
|
2009-10-07 12:20:02 +00:00
|
|
|
static int EnumerateCompiledFunctions(Handle<SharedFunctionInfo>* sfis) {
|
|
|
|
AssertNoAllocation no_alloc;
|
2009-05-20 09:04:13 +00:00
|
|
|
int compiled_funcs_count = 0;
|
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())) {
|
|
|
|
if (sfis != NULL)
|
|
|
|
sfis[compiled_funcs_count] = Handle<SharedFunctionInfo>(sfi);
|
|
|
|
++compiled_funcs_count;
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
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:
|
|
|
|
return; // We log this later using LogCompiledFunctions.
|
|
|
|
case Code::STUB:
|
|
|
|
description = CodeStub::MajorName(code_object->major_key());
|
|
|
|
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;
|
|
|
|
}
|
|
|
|
LOG(CodeCreateEvent(tag, code_object, description));
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
|
2009-10-07 12:20:02 +00:00
|
|
|
void Logger::LogCompiledFunctions() {
|
|
|
|
HandleScope scope;
|
|
|
|
const int compiled_funcs_count = EnumerateCompiledFunctions(NULL);
|
|
|
|
Handle<SharedFunctionInfo>* sfis =
|
|
|
|
NewArray< Handle<SharedFunctionInfo> >(compiled_funcs_count);
|
|
|
|
EnumerateCompiledFunctions(sfis);
|
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) {
|
2009-06-08 13:39:48 +00:00
|
|
|
LOG(CodeCreateEvent(Logger::LAZY_COMPILE_TAG,
|
|
|
|
shared->code(), *func_name,
|
2009-06-22 07:22:09 +00:00
|
|
|
*script_name, line_num + 1));
|
2009-05-20 09:04:13 +00:00
|
|
|
} else {
|
|
|
|
// Can't distinguish enum and script here, so always use Script.
|
2009-06-08 13:39:48 +00:00
|
|
|
LOG(CodeCreateEvent(Logger::SCRIPT_TAG,
|
|
|
|
shared->code(), *script_name));
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
2009-11-23 09:19:24 +00:00
|
|
|
} else {
|
|
|
|
LOG(CodeCreateEvent(
|
|
|
|
Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
|
|
|
|
}
|
|
|
|
} else if (shared->function_data()->IsFunctionTemplateInfo()) {
|
|
|
|
// API function.
|
|
|
|
FunctionTemplateInfo* fun_data =
|
|
|
|
FunctionTemplateInfo::cast(shared->function_data());
|
|
|
|
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);
|
|
|
|
LOG(CallbackEvent(*func_name, entry_point));
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
2009-11-23 09:19:24 +00:00
|
|
|
} else {
|
|
|
|
LOG(CodeCreateEvent(
|
|
|
|
Logger::LAZY_COMPILE_TAG, shared->code(), *func_name));
|
2009-05-20 09:04:13 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
DeleteArray(sfis);
|
|
|
|
}
|
|
|
|
|
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;
|
|
|
|
LOG(FunctionCreateEvent(jsf));
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
|
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) {
|
|
|
|
LOG(GetterCallbackEvent(name, getter_entry));
|
|
|
|
}
|
|
|
|
Address setter_entry = v8::ToCData<Address>(ai->setter());
|
|
|
|
if (setter_entry != 0) {
|
|
|
|
LOG(SetterCallbackEvent(name, setter_entry));
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
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;
|
|
|
|
|
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
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2009-03-27 00:24:49 +00:00
|
|
|
current_state_ = &bottom_state_;
|
2008-07-03 15:10:15 +00:00
|
|
|
|
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();
|
|
|
|
}
|
|
|
|
|
2009-06-15 09:37:50 +00:00
|
|
|
log_events_ = FLAG_compress_log ?
|
|
|
|
kCompressedLogEventsNames : kLongLogEventsNames;
|
|
|
|
if (FLAG_compress_log) {
|
|
|
|
compression_helper_ = new CompressionHelper(kCompressionWindowSize);
|
|
|
|
}
|
|
|
|
|
2009-06-24 13:09:34 +00:00
|
|
|
is_logging_ = start_logging;
|
|
|
|
|
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 {
|
|
|
|
is_logging_ = true;
|
|
|
|
}
|
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
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
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;
|
|
|
|
}
|
|
|
|
|
2009-06-15 09:37:50 +00:00
|
|
|
delete compression_helper_;
|
|
|
|
compression_helper_ = NULL;
|
|
|
|
|
2008-07-03 15:10:15 +00:00
|
|
|
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
|