v8/src/log.cc

1161 lines
31 KiB
C++
Raw Normal View History

// Copyright 2006-2008 the V8 project authors. All rights reserved.
// 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"
#include "log.h"
#include "platform.h"
#include "string-stream.h"
#include "macro-assembler.h"
namespace v8 { namespace internal {
#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) {
if (paused_)
return;
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();
// Pause and Resume TickSample data collection.
static bool paused() { return paused_; }
static void pause() { paused_ = true; }
static void resume() { paused_ = false; }
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.
// Tells whether worker thread should continue running.
bool running_;
// Tells whether we are currently recording tick samples.
static bool paused_;
};
bool Profiler::paused_ = false;
//
// StackTracer implementation
//
void StackTracer::Trace(TickSample* sample) {
if (sample->state == GC) {
sample->InitStack(0);
return;
}
// If c_entry_fp is available, this means that we are inside a C++
// function and sample->fp value isn't reliable due to FPO
if (Top::c_entry_fp(Top::GetCurrentThread()) != NULL) {
SafeStackTraceFrameIterator it(
reinterpret_cast<Address>(sample->sp),
reinterpret_cast<Address>(low_stack_bound_));
// Pass 1: Calculate depth
int depth = 0;
while (!it.done() && depth <= kMaxStackFrames) {
++depth;
it.Advance();
}
// Pass 2: Save stack
sample->InitStack(depth);
if (depth > 0) {
it.Reset();
for (int i = 0; i < depth && !it.done(); ++i, it.Advance()) {
sample->stack[i] = it.frame()->pc();
}
}
} else if (sample->sp < sample->fp && sample->fp < low_stack_bound_) {
// The check assumes that stack grows from lower addresses
sample->InitStack(1);
sample->stack[0] = Memory::Address_at(
(Address)(sample->fp + StandardFrameConstants::kCallerPCOffset));
} else {
// FP seems to be in some intermediate state,
// better discard this sample
sample->InitStack(0);
}
}
//
// Ticker used to provide ticks to the profiler and the sliding state
// window.
//
class Ticker: public Sampler {
public:
explicit Ticker(int interval, unsigned int low_stack_bound):
Sampler(interval, FLAG_prof), window_(NULL), profiler_(NULL),
stack_tracer_(low_stack_bound) {}
~Ticker() { if (IsActive()) Stop(); }
void Tick(TickSample* sample) {
if (IsProfiling()) stack_tracer_.Trace(sample);
if (profiler_) profiler_->Insert(sample);
if (window_) window_->AddState(sample->state);
}
void SetWindow(SlidingStateWindow* window) {
window_ = window;
if (!IsActive()) Start();
}
void ClearWindow() {
window_ = NULL;
if (!profiler_ && IsActive()) Stop();
}
void SetProfiler(Profiler* profiler) {
profiler_ = profiler;
if (!IsActive()) Start();
}
void ClearProfiler() {
profiler_ = NULL;
if (!window_ && IsActive()) Stop();
}
private:
SlidingStateWindow* window_;
Profiler* profiler_;
StackTracer stack_tracer_;
};
//
// 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.
//
Profiler::Profiler() {
buffer_semaphore_ = OS::CreateSemaphore(0);
head_ = 0;
tail_ = 0;
overflow_ = false;
running_ = false;
}
void Profiler::Engage() {
OS::LogSharedLibraryAddresses();
// Start thread processing the profiler buffer.
running_ = true;
Start();
// Register to get ticks.
Logger::ticker_->SetProfiler(this);
LOG(UncheckedStringEvent("profiler", "begin"));
}
void Profiler::Disengage() {
// 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;
Insert(&sample);
Join();
LOG(UncheckedStringEvent("profiler", "end"));
}
void Profiler::Run() {
TickSample sample;
bool overflow = Logger::profiler_->Remove(&sample);
while (running_) {
LOG(TickEvent(&sample, overflow));
overflow = Logger::profiler_->Remove(&sample);
}
}
#ifdef ENABLE_LOGGING_AND_PROFILING
// Utility class for formatting log messages. It fills the message into the
// static buffer in Logger.
class LogMessageBuilder BASE_EMBEDDED {
public:
explicit LogMessageBuilder();
~LogMessageBuilder() { }
void Append(const char* format, ...);
void Append(const char* format, va_list args);
void Append(const char c);
void Append(String *str);
void AppendDetailed(String* str, bool show_impl_info);
void WriteToLogFile();
private:
ScopedLock sl;
int pos_;
};
// Create a message builder starting from position 0. This acquires the mutex
// in the logger as well.
LogMessageBuilder::LogMessageBuilder(): sl(Logger::mutex_), pos_(0) {
ASSERT(Logger::message_buffer_ != NULL);
}
// Append string data to the log message.
void LogMessageBuilder::Append(const char* format, ...) {
Vector<char> buf(Logger::message_buffer_ + pos_,
Logger::kMessageBufferSize - pos_);
va_list args;
va_start(args, format);
Append(format, args);
va_end(args);
ASSERT(pos_ <= Logger::kMessageBufferSize);
}
// Append string data to the log message.
void LogMessageBuilder::Append(const char* format, va_list args) {
Vector<char> buf(Logger::message_buffer_ + pos_,
Logger::kMessageBufferSize - pos_);
int result = v8::internal::OS::VSNPrintF(buf, format, args);
// Result is -1 if output was truncated.
if (result >= 0) {
pos_ += result;
} else {
pos_ = Logger::kMessageBufferSize;
}
ASSERT(pos_ <= Logger::kMessageBufferSize);
}
// Append a character to the log message.
void LogMessageBuilder::Append(const char c) {
if (pos_ < Logger::kMessageBufferSize) {
Logger::message_buffer_[pos_++] = c;
}
ASSERT(pos_ <= Logger::kMessageBufferSize);
}
// Append a heap string.
void LogMessageBuilder::Append(String* str) {
AssertNoAllocation no_heap_allocation; // Ensure string stay valid.
StringShape shape(str);
int length = str->length(shape);
for (int i = 0; i < length; i++) {
Append(static_cast<char>(str->Get(shape, i)));
}
}
void LogMessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
AssertNoAllocation no_heap_allocation; // Ensure string stay valid.
StringShape shape(str);
int len = str->length(shape);
if (len > 0x1000)
len = 0x1000;
if (show_impl_info) {
Append(shape.IsAsciiRepresentation() ? 'a' : '2');
if (shape.IsExternal())
Append('e');
if (shape.IsSymbol())
Append('#');
Append(":%i:", str->length());
}
for (int i = 0; i < len; i++) {
uc32 c = str->Get(shape, i);
if (c > 0xff) {
Append("\\u%04x", c);
} else if (c < 32 || c > 126) {
Append("\\x%02x", c);
} else if (c == ',') {
Append("\\,");
} else if (c == '\\') {
Append("\\\\");
} else {
Append("%lc", c);
}
}
}
// Write the log message to the log file currently opened.
void LogMessageBuilder::WriteToLogFile() {
ASSERT(pos_ <= Logger::kMessageBufferSize);
size_t rv = fwrite(Logger::message_buffer_, 1, pos_, Logger::logfile_);
ASSERT(rv == static_cast<size_t>(pos_));
USE(rv);
}
#endif
//
// Logger class implementation.
//
Ticker* Logger::ticker_ = NULL;
char* Logger::message_buffer_ = NULL;
FILE* Logger::logfile_ = NULL;
Profiler* Logger::profiler_ = NULL;
Mutex* Logger::mutex_ = NULL;
VMState* Logger::current_state_ = NULL;
SlidingStateWindow* Logger::sliding_state_window_ = NULL;
#endif // ENABLE_LOGGING_AND_PROFILING
void Logger::Preamble(const char* content) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
msg.Append("%s", content);
msg.WriteToLogFile();
#endif
}
void Logger::StringEvent(const char* name, const char* value) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (FLAG_log) UncheckedStringEvent(name, value);
#endif
}
#ifdef ENABLE_LOGGING_AND_PROFILING
void Logger::UncheckedStringEvent(const char* name, const char* value) {
if (logfile_ == NULL) return;
LogMessageBuilder msg;
msg.Append("%s,\"%s\"\n", name, value);
msg.WriteToLogFile();
}
#endif
void Logger::IntEvent(const char* name, int value) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log) return;
LogMessageBuilder msg;
msg.Append("%s,%d\n", name, value);
msg.WriteToLogFile();
#endif
}
void Logger::HandleEvent(const char* name, Object** location) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_handles) return;
LogMessageBuilder msg;
msg.Append("%s,0x%x\n", name,
reinterpret_cast<unsigned int>(location));
msg.WriteToLogFile();
#endif
}
#ifdef ENABLE_LOGGING_AND_PROFILING
// ApiEvent is private so all the calls come from the Logger class. It is the
// caller's responsibility to ensure that logfile_ is not NULL and that
// FLAG_log_api is true.
void Logger::ApiEvent(const char* format, ...) {
ASSERT(logfile_ != NULL && FLAG_log_api);
LogMessageBuilder msg;
va_list ap;
va_start(ap, format);
msg.Append(format, ap);
va_end(ap);
msg.WriteToLogFile();
}
#endif
void Logger::ApiNamedSecurityCheck(Object* key) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_api) return;
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,
unsigned start,
unsigned end) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_prof) return;
LogMessageBuilder msg;
msg.Append("shared-library,\"%s\",0x%08x,0x%08x\n", library_path,
start, end);
msg.WriteToLogFile();
#endif
}
void Logger::SharedLibraryEvent(const wchar_t* library_path,
unsigned start,
unsigned end) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_prof) return;
LogMessageBuilder msg;
msg.Append("shared-library,\"%ls\",0x%08x,0x%08x\n", library_path,
start, end);
msg.WriteToLogFile();
#endif
}
#ifdef ENABLE_LOGGING_AND_PROFILING
void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
// Prints "/" + re.source + "/" +
// (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
LogMessageBuilder msg;
Handle<Object> source = GetProperty(regexp, "source");
if (!source->IsString()) {
msg.Append("no source");
return;
}
switch (regexp->TypeTag()) {
case JSRegExp::ATOM:
msg.Append('a');
break;
default:
break;
}
msg.Append('/');
msg.AppendDetailed(*Handle<String>::cast(source), false);
msg.Append('/');
// global flag
Handle<Object> global = GetProperty(regexp, "global");
if (global->IsTrue()) {
msg.Append('g');
}
// ignorecase flag
Handle<Object> ignorecase = GetProperty(regexp, "ignoreCase");
if (ignorecase->IsTrue()) {
msg.Append('i');
}
// multiline flag
Handle<Object> multiline = GetProperty(regexp, "multiline");
if (multiline->IsTrue()) {
msg.Append('m');
}
msg.WriteToLogFile();
}
#endif // ENABLE_LOGGING_AND_PROFILING
void Logger::RegExpCompileEvent(Handle<JSRegExp> regexp, bool in_cache) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_regexp) return;
LogMessageBuilder msg;
msg.Append("regexp-compile,");
LogRegExpSource(regexp);
msg.Append(in_cache ? ",hit\n" : ",miss\n");
msg.WriteToLogFile();
#endif
}
void Logger::LogRuntime(Vector<const char> format, JSArray* args) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_runtime) return;
HandleScope scope;
LogMessageBuilder msg;
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':
msg.AppendDetailed(String::cast(obj), false);
break;
case 'S':
msg.AppendDetailed(String::cast(obj), true);
break;
case 'r':
Logger::LogRegExpSource(Handle<JSRegExp>(JSRegExp::cast(obj)));
break;
case 'x':
msg.Append("0x%x", Smi::cast(obj)->value());
break;
case 'i':
msg.Append("%i", Smi::cast(obj)->value());
break;
default:
UNREACHABLE();
}
} else {
msg.Append(c);
}
}
msg.Append('\n');
msg.WriteToLogFile();
#endif
}
void Logger::ApiIndexedSecurityCheck(uint32_t index) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_api) return;
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());
if (logfile_ == NULL || !FLAG_log_api) return;
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
if (logfile_ == NULL || !FLAG_log_api) return;
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
if (logfile_ == NULL || !FLAG_log_api) return;
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
if (logfile_ == NULL || !FLAG_log_api) return;
Logger::ApiEvent("api,%s\n", name);
#endif
}
void Logger::NewEvent(const char* name, void* object, size_t size) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log) return;
LogMessageBuilder msg;
msg.Append("new,%s,0x%x,%u\n", name,
reinterpret_cast<unsigned int>(object),
static_cast<unsigned int>(size));
msg.WriteToLogFile();
#endif
}
void Logger::DeleteEvent(const char* name, void* object) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log) return;
LogMessageBuilder msg;
msg.Append("delete,%s,0x%x\n", name,
reinterpret_cast<unsigned int>(object));
msg.WriteToLogFile();
#endif
}
void Logger::CodeCreateEvent(const char* tag, Code* code, const char* comment) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
msg.Append("code-creation,%s,0x%x,%d,\"", tag,
reinterpret_cast<unsigned int>(code->address()),
code->ExecutableSize());
for (const char* p = comment; *p != '\0'; p++) {
if (*p == '"') {
msg.Append('\\');
}
msg.Append(*p);
}
msg.Append('"');
msg.Append('\n');
msg.WriteToLogFile();
#endif
}
void Logger::CodeCreateEvent(const char* tag, Code* code, String* name) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
SmartPointer<char> str =
name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
msg.Append("code-creation,%s,0x%x,%d,\"%s\"\n", tag,
reinterpret_cast<unsigned int>(code->address()),
code->ExecutableSize(), *str);
msg.WriteToLogFile();
#endif
}
void Logger::CodeCreateEvent(const char* tag, Code* code, String* name,
String* source, int line) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
SmartPointer<char> str =
name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
SmartPointer<char> sourcestr =
source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
msg.Append("code-creation,%s,0x%x,%d,\"%s %s:%d\"\n", tag,
reinterpret_cast<unsigned int>(code->address()),
code->ExecutableSize(),
*str, *sourcestr, line);
msg.WriteToLogFile();
#endif
}
void Logger::CodeCreateEvent(const char* tag, Code* code, int args_count) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
msg.Append("code-creation,%s,0x%x,%d,\"args_count: %d\"\n", tag,
reinterpret_cast<unsigned int>(code->address()),
code->ExecutableSize(),
args_count);
msg.WriteToLogFile();
#endif
}
void Logger::CodeAllocateEvent(Code* code, Assembler* assem) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
msg.Append("code-allocate,0x%x,0x%x\n",
reinterpret_cast<unsigned int>(code->address()),
reinterpret_cast<unsigned int>(assem));
msg.WriteToLogFile();
#endif
}
void Logger::CodeMoveEvent(Address from, Address to) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
msg.Append("code-move,0x%x,0x%x\n",
reinterpret_cast<unsigned int>(from),
reinterpret_cast<unsigned int>(to));
msg.WriteToLogFile();
#endif
}
void Logger::CodeDeleteEvent(Address from) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
msg.Append("code-delete,0x%x\n", reinterpret_cast<unsigned int>(from));
msg.WriteToLogFile();
#endif
}
void Logger::BeginCodeRegionEvent(CodeRegion* region,
Assembler* masm,
const char* name) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
msg.Append("begin-code-region,0x%x,0x%x,0x%x,%s\n",
reinterpret_cast<unsigned int>(region),
reinterpret_cast<unsigned int>(masm),
masm->pc_offset(),
name);
msg.WriteToLogFile();
#endif
}
void Logger::EndCodeRegionEvent(CodeRegion* region, Assembler* masm) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_code) return;
LogMessageBuilder msg;
msg.Append("end-code-region,0x%x,0x%x,0x%x\n",
reinterpret_cast<unsigned int>(region),
reinterpret_cast<unsigned int>(masm),
masm->pc_offset());
msg.WriteToLogFile();
#endif
}
void Logger::ResourceEvent(const char* name, const char* tag) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log) return;
LogMessageBuilder msg;
msg.Append("%s,%s,", name, tag);
uint32_t sec, usec;
if (OS::GetUserTime(&sec, &usec) != -1) {
msg.Append("%d,%d,", sec, usec);
}
msg.Append("%.0f", OS::TimeCurrentMillis());
msg.Append('\n');
msg.WriteToLogFile();
#endif
}
void Logger::SuspectReadEvent(String* name, Object* obj) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_suspect) return;
LogMessageBuilder msg;
String* class_name = obj->IsJSObject()
? JSObject::cast(obj)->class_name()
: Heap::empty_string();
ScopedLock sl(mutex_);
msg.Append("suspect-read,");
msg.Append(class_name);
msg.Append(',');
msg.Append('"');
msg.Append(name);
msg.Append('"');
msg.Append('\n');
msg.WriteToLogFile();
#endif
}
void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_gc) return;
LogMessageBuilder msg;
msg.Append("heap-sample-begin,\"%s\",\"%s\"\n", space, kind);
msg.WriteToLogFile();
#endif
}
void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_gc) return;
LogMessageBuilder msg;
msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind);
msg.WriteToLogFile();
#endif
}
void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log_gc) return;
LogMessageBuilder msg;
msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes);
msg.WriteToLogFile();
#endif
}
void Logger::DebugTag(const char* call_site_tag) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log) return;
LogMessageBuilder msg;
msg.Append("debug-tag,%s\n", call_site_tag);
msg.WriteToLogFile();
#endif
}
void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (logfile_ == NULL || !FLAG_log) return;
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();
LogMessageBuilder msg;
msg.Append("debug-queue-event,%s,%15.3f,%s\n",
event_type,
OS::TimeCurrentMillis(),
parameter_string);
DeleteArray(parameter_string);
msg.WriteToLogFile();
#endif
}
#ifdef ENABLE_LOGGING_AND_PROFILING
void Logger::TickEvent(TickSample* sample, bool overflow) {
if (logfile_ == NULL || !FLAG_prof) return;
LogMessageBuilder msg;
msg.Append("tick,0x%x,0x%x,%d", sample->pc, sample->sp,
static_cast<int>(sample->state));
if (overflow) {
msg.Append(",overflow");
}
if (*(sample->stack)) {
for (size_t i = 0; sample->stack[i]; ++i) {
msg.Append(",0x%x", reinterpret_cast<unsigned int>(sample->stack[i]));
}
}
msg.Append('\n');
msg.WriteToLogFile();
}
bool Logger::IsProfilerPaused() {
return profiler_->paused();
}
void Logger::PauseProfiler() {
profiler_->pause();
}
void Logger::ResumeProfiler() {
profiler_->resume();
}
#endif
bool Logger::Setup() {
#ifdef ENABLE_LOGGING_AND_PROFILING
// --log-all enables all the log flags.
if (FLAG_log_all) {
FLAG_log_runtime = true;
FLAG_log_api = true;
FLAG_log_code = true;
FLAG_log_gc = true;
FLAG_log_suspect = true;
FLAG_log_handles = true;
FLAG_log_regexp = true;
}
// --prof implies --log-code.
if (FLAG_prof) FLAG_log_code = true;
bool open_log_file = FLAG_log || FLAG_log_runtime || FLAG_log_api
|| FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
|| FLAG_log_regexp || FLAG_log_state_changes;
// If we're logging anything, we need to open the log file.
if (open_log_file) {
if (strcmp(FLAG_logfile, "-") == 0) {
logfile_ = stdout;
} 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.
uint32_t time = static_cast<uint32_t>(OS::TimeCurrentMillis());
stream.Add("%u", time);
break;
}
case '%':
// %% expands (contracts really) to %.
stream.Put('%');
break;
default:
// All other %'s expand to themselves.
stream.Put('%');
stream.Put(*p);
break;
}
} else {
stream.Put(*p);
}
}
SmartPointer<const char> expanded = stream.ToCString();
logfile_ = OS::FOpen(*expanded, "w");
} else {
logfile_ = OS::FOpen(FLAG_logfile, "w");
}
message_buffer_ = NewArray<char>(kMessageBufferSize);
mutex_ = OS::CreateMutex();
}
current_state_ = new VMState(OTHER);
// as log is initialized early with V8, we can assume that JS execution
// frames can never reach this point on stack
int stack_var;
ticker_ = new Ticker(10, reinterpret_cast<unsigned int>(&stack_var));
if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {
sliding_state_window_ = new SlidingStateWindow();
}
if (FLAG_prof) {
profiler_ = new Profiler();
if (!FLAG_prof_auto)
profiler_->pause();
profiler_->Engage();
}
return true;
#else
return false;
#endif
}
void Logger::TearDown() {
#ifdef ENABLE_LOGGING_AND_PROFILING
// Stop the profiler before closing the file.
if (profiler_ != NULL) {
profiler_->Disengage();
delete profiler_;
profiler_ = NULL;
}
// Deleting the current_state_ has the side effect of assigning to it(!).
while (current_state_) delete current_state_;
delete sliding_state_window_;
delete ticker_;
if (logfile_ != NULL) {
fclose(logfile_);
logfile_ = NULL;
delete mutex_;
mutex_ = NULL;
DeleteArray(message_buffer_);
}
#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
}
//
// VMState class implementation. A simple stack of VM states held by the
// logger and partially threaded through the call stack. States are pushed by
// VMState construction and popped by destruction.
//
#ifdef ENABLE_LOGGING_AND_PROFILING
static const char* StateToString(StateTag state) {
switch (state) {
case JS:
return "JS";
case GC:
return "GC";
case COMPILER:
return "COMPILER";
case OTHER:
return "OTHER";
default:
UNREACHABLE();
return NULL;
}
}
VMState::VMState(StateTag state) {
state_ = state;
previous_ = Logger::current_state_;
Logger::current_state_ = this;
if (FLAG_log_state_changes) {
LOG(UncheckedStringEvent("Entering", StateToString(state_)));
if (previous_) {
LOG(UncheckedStringEvent("From", StateToString(previous_->state_)));
}
}
}
VMState::~VMState() {
Logger::current_state_ = previous_;
if (FLAG_log_state_changes) {
LOG(UncheckedStringEvent("Leaving", StateToString(state_)));
if (previous_) {
LOG(UncheckedStringEvent("To", StateToString(previous_->state_)));
}
}
}
#endif
} } // namespace v8::internal