From d13ad5be9bcc9e0d08b107f5d01b8a50d473ee43 Mon Sep 17 00:00:00 2001 From: "loislo@chromium.org" Date: Mon, 15 Jul 2013 11:35:39 +0000 Subject: [PATCH] Current logger code is messy. It mixes together four or even five different logging destinations. I think we can extract the code related to a destination into a separate class, do the same for the all destinations and have four classes with more or less simple common logging API BUG=none Meta-bug= https://code.google.com/p/chromium/issues/detail?id=260203 R=yangguo@chromium.org, yurys@chromium.org Review URL: https://codereview.chromium.org/18259024 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@15664 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/log-utils.cc | 80 +--------------- src/log-utils.h | 6 +- src/log.cc | 287 +++++++++++++++++++++++++++++++++++++++---------------- src/log.h | 24 +---- 4 files changed, 215 insertions(+), 182 deletions(-) diff --git a/src/log-utils.cc b/src/log-utils.cc index a733b52..a6fa6be 100644 --- a/src/log-utils.cc +++ b/src/log-utils.cc @@ -35,26 +35,19 @@ namespace internal { const char* const Log::kLogToTemporaryFile = "&"; +const char* const Log::kLogToConsole = "-"; Log::Log(Logger* logger) : is_stopped_(false), output_handle_(NULL), - ll_output_handle_(NULL), mutex_(NULL), message_buffer_(NULL), logger_(logger) { } -static void AddIsolateIdIfNeeded(StringStream* stream) { - Isolate* isolate = Isolate::Current(); - if (isolate->IsDefaultIsolate()) return; - stream->Add("isolate-%p-", isolate); -} - - -void Log::Initialize() { +void Log::Initialize(const char* log_file_name) { mutex_ = OS::CreateMutex(); message_buffer_ = NewArray(kMessageBufferSize); @@ -81,55 +74,12 @@ void Log::Initialize() { // If we're logging anything, we need to open the log file. if (Log::InitLogAtStart()) { - if (strcmp(FLAG_logfile, "-") == 0) { + if (strcmp(log_file_name, kLogToConsole) == 0) { OpenStdout(); - } else if (strcmp(FLAG_logfile, kLogToTemporaryFile) == 0) { + } else if (strcmp(log_file_name, kLogToTemporaryFile) == 0) { OpenTemporaryFile(); } else { - if (strchr(FLAG_logfile, '%') != NULL || - !Isolate::Current()->IsDefaultIsolate()) { - // If there's a '%' in the log file name we have to expand - // placeholders. - HeapStringAllocator allocator; - StringStream stream(&allocator); - AddIsolateIdIfNeeded(&stream); - 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 'p': - stream.Add("%d", OS::GetCurrentProcessId()); - break; - case 't': { - // %t expands to the current time in milliseconds. - double time = OS::TimeCurrentMillis(); - stream.Add("%.0f", FmtElm(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); - } - } - SmartArrayPointer expanded = stream.ToCString(); - OpenFile(*expanded); - } else { - OpenFile(FLAG_logfile); - } + OpenFile(log_file_name); } } } @@ -147,27 +97,9 @@ void Log::OpenTemporaryFile() { } -// Extension added to V8 log file name to get the low-level log name. -static const char kLowLevelLogExt[] = ".ll"; - -// File buffer size of the low-level log. We don't use the default to -// minimize the associated overhead. -static const int kLowLevelLogBufferSize = 2 * MB; - - void Log::OpenFile(const char* name) { ASSERT(!IsEnabled()); output_handle_ = OS::FOpen(name, OS::LogFileOpenMode); - if (FLAG_ll_prof) { - // Open the low-level log file. - size_t len = strlen(name); - ScopedVector ll_name(static_cast(len + sizeof(kLowLevelLogExt))); - OS::MemCopy(ll_name.start(), name, len); - OS::MemCopy(ll_name.start() + len, - kLowLevelLogExt, sizeof(kLowLevelLogExt)); - ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode); - setvbuf(ll_output_handle_, NULL, _IOFBF, kLowLevelLogBufferSize); - } } @@ -181,8 +113,6 @@ FILE* Log::Close() { } } output_handle_ = NULL; - if (ll_output_handle_ != NULL) fclose(ll_output_handle_); - ll_output_handle_ = NULL; DeleteArray(message_buffer_); message_buffer_ = NULL; diff --git a/src/log-utils.h b/src/log-utils.h index c499540..c0b863f 100644 --- a/src/log-utils.h +++ b/src/log-utils.h @@ -39,7 +39,7 @@ class Logger; class Log { public: // Performs process-wide initialization. - void Initialize(); + void Initialize(const char* log_file_name); // Disables logging, but preserves acquired resources. void stop() { is_stopped_ = true; } @@ -66,6 +66,7 @@ class Log { // This mode is only used in tests, as temporary files are automatically // deleted on close and thus can't be accessed afterwards. static const char* const kLogToTemporaryFile; + static const char* const kLogToConsole; private: explicit Log(Logger* logger); @@ -96,9 +97,6 @@ class Log { // destination. mutex_ should be acquired before using output_handle_. FILE* output_handle_; - // Used when low-level profiling is active. - FILE* ll_output_handle_; - // mutex_ is a Mutex used for enforcing exclusive // access to the formatting buffer and the log file or log memory buffer. Mutex* mutex_; diff --git a/src/log.cc b/src/log.cc index a44add6..843d128 100644 --- a/src/log.cc +++ b/src/log.cc @@ -45,6 +45,82 @@ namespace v8 { namespace internal { + +// Low-level logging support. +class LowLevelLogger { + public: + explicit LowLevelLogger(const char* file_name); + ~LowLevelLogger(); + + void CodeCreateEvent(Code* code, const char* name, int name_size); + void CodeMoveEvent(Address from, Address to); + void CodeDeleteEvent(Address from); + void SnapshotPositionEvent(Address addr, int pos); + void CodeMovingGCEvent(); + + private: + // Low-level profiling event structures. + + struct CodeCreateStruct { + static const char kTag = 'C'; + + int32_t name_size; + Address code_address; + int32_t code_size; + }; + + + struct CodeMoveStruct { + static const char kTag = 'M'; + + Address from_address; + Address to_address; + }; + + + struct CodeDeleteStruct { + static const char kTag = 'D'; + + Address address; + }; + + + struct SnapshotPositionStruct { + static const char kTag = 'P'; + + Address address; + int32_t position; + }; + + + static const char kCodeMovingGCTag = 'G'; + + + // Extension added to V8 log file name to get the low-level log name. + static const char kLogExt[]; + + // File buffer size of the low-level log. We don't use the default to + // minimize the associated overhead. + static const int kLogBufferSize = 2 * MB; + + void LogCodeInfo(); + void LogWriteBytes(const char* bytes, int size); + + template + void LogWriteStruct(const T& s) { + char tag = T::kTag; + LogWriteBytes(reinterpret_cast(&tag), sizeof(tag)); + LogWriteBytes(reinterpret_cast(&s), sizeof(s)); + } + + FILE* ll_output_handle_; +}; + +const char LowLevelLogger::kLogExt[] = ".ll"; + +#define LL_LOG(Call) if (ll_logger_) ll_logger_->Call; + + // 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. @@ -210,43 +286,6 @@ void Profiler::Run() { } -// Low-level profiling event structures. - -struct LowLevelCodeCreateStruct { - static const char kTag = 'C'; - - int32_t name_size; - Address code_address; - int32_t code_size; -}; - - -struct LowLevelCodeMoveStruct { - static const char kTag = 'M'; - - Address from_address; - Address to_address; -}; - - -struct LowLevelCodeDeleteStruct { - static const char kTag = 'D'; - - Address address; -}; - - -struct LowLevelSnapshotPositionStruct { - static const char kTag = 'P'; - - Address address; - int32_t position; -}; - - -static const char kCodeMovingGCTag = 'G'; - - // // Logger class implementation. // @@ -405,6 +444,7 @@ Logger::Logger(Isolate* isolate) logging_nesting_(0), cpu_profiler_nesting_(0), log_(new Log(this)), + ll_logger_(NULL), name_buffer_(new NameBuffer), address_to_name_map_(NULL), is_initialized_(false), @@ -952,9 +992,7 @@ void Logger::LogRecordedBuffer(Code* code, SharedFunctionInfo* shared) { name_buffer_->size()); } if (!log_->IsEnabled()) return; - if (FLAG_ll_prof) { - LowLevelCodeCreateEvent(code, name_buffer_->get(), name_buffer_->size()); - } + LL_LOG(CodeCreateEvent(code, name_buffer_->get(), name_buffer_->size())); if (Serializer::enabled()) { RegisterSnapshotCodeName(code, name_buffer_->get(), name_buffer_->size()); } @@ -1142,7 +1180,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) { void Logger::CodeMovingGCEvent() { if (!log_->IsEnabled() || !FLAG_ll_prof) return; - LowLevelLogWriteBytes(&kCodeMovingGCTag, sizeof(kCodeMovingGCTag)); + LL_LOG(CodeMovingGCEvent()); OS::SignalCodeMovingGC(); } @@ -1169,7 +1207,7 @@ void Logger::RegExpCodeCreateEvent(Code* code, String* source) { void Logger::CodeMoveEvent(Address from, Address to) { if (code_event_handler_ != NULL) IssueCodeMovedEvent(from, to); if (!log_->IsEnabled()) return; - if (FLAG_ll_prof) LowLevelCodeMoveEvent(from, to); + LL_LOG(CodeMoveEvent(from, to)); if (Serializer::enabled() && address_to_name_map_ != NULL) { address_to_name_map_->Move(from, to); } @@ -1180,7 +1218,7 @@ void Logger::CodeMoveEvent(Address from, Address to) { void Logger::CodeDeleteEvent(Address from) { if (code_event_handler_ != NULL) IssueCodeRemovedEvent(from); if (!log_->IsEnabled()) return; - if (FLAG_ll_prof) LowLevelCodeDeleteEvent(from); + LL_LOG(CodeDeleteEvent(from)); if (Serializer::enabled() && address_to_name_map_ != NULL) { address_to_name_map_->Remove(from); } @@ -1226,7 +1264,7 @@ void Logger::CodeEndLinePosInfoRecordEvent(Code* code, void Logger::SnapshotPositionEvent(Address addr, int pos) { if (!log_->IsEnabled()) return; - if (FLAG_ll_prof) LowLevelSnapshotPositionEvent(addr, pos); + LL_LOG(SnapshotPositionEvent(addr, pos)); if (Serializer::enabled() && address_to_name_map_ != NULL) { const char* code_name = address_to_name_map_->Lookup(addr); if (code_name == NULL) return; // Not a code object. @@ -1564,8 +1602,38 @@ void Logger::LogCodeObject(Object* object) { } -void Logger::LogCodeInfo() { - if (!log_->IsEnabled() || !FLAG_ll_prof) return; +void Logger::RegisterSnapshotCodeName(Code* code, + const char* name, + int name_size) { + ASSERT(Serializer::enabled()); + if (address_to_name_map_ == NULL) { + address_to_name_map_ = new NameMap; + } + address_to_name_map_->Insert(code->address(), name, name_size); +} + + +LowLevelLogger::LowLevelLogger(const char* name) + : ll_output_handle_(NULL) { + // Open the low-level log file. + size_t len = strlen(name); + ScopedVector ll_name(static_cast(len + sizeof(kLogExt))); + OS::MemCopy(ll_name.start(), name, len); + OS::MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt)); + ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode); + setvbuf(ll_output_handle_, NULL, _IOFBF, kLogBufferSize); + + LogCodeInfo(); +} + + +LowLevelLogger::~LowLevelLogger() { + fclose(ll_output_handle_); + ll_output_handle_ = NULL; +} + + +void LowLevelLogger::LogCodeInfo() { #if V8_TARGET_ARCH_IA32 const char arch[] = "ia32"; #elif V8_TARGET_ARCH_X64 @@ -1577,71 +1645,62 @@ void Logger::LogCodeInfo() { #else const char arch[] = "unknown"; #endif - LowLevelLogWriteBytes(arch, sizeof(arch)); -} - - -void Logger::RegisterSnapshotCodeName(Code* code, - const char* name, - int name_size) { - ASSERT(Serializer::enabled()); - if (address_to_name_map_ == NULL) { - address_to_name_map_ = new NameMap; - } - address_to_name_map_->Insert(code->address(), name, name_size); + LogWriteBytes(arch, sizeof(arch)); } - -void Logger::LowLevelCodeCreateEvent(Code* code, +void LowLevelLogger::CodeCreateEvent(Code* code, const char* name, int name_size) { - if (log_->ll_output_handle_ == NULL) return; - LowLevelCodeCreateStruct event; + CodeCreateStruct event; event.name_size = name_size; event.code_address = code->instruction_start(); ASSERT(event.code_address == code->address() + Code::kHeaderSize); event.code_size = code->instruction_size(); - LowLevelLogWriteStruct(event); - LowLevelLogWriteBytes(name, name_size); - LowLevelLogWriteBytes( + LogWriteStruct(event); + LogWriteBytes(name, name_size); + LogWriteBytes( reinterpret_cast(code->instruction_start()), code->instruction_size()); } -void Logger::LowLevelCodeMoveEvent(Address from, Address to) { - if (log_->ll_output_handle_ == NULL) return; - LowLevelCodeMoveStruct event; +void LowLevelLogger::CodeMoveEvent(Address from, Address to) { + CodeMoveStruct event; event.from_address = from + Code::kHeaderSize; event.to_address = to + Code::kHeaderSize; - LowLevelLogWriteStruct(event); + LogWriteStruct(event); } -void Logger::LowLevelCodeDeleteEvent(Address from) { - if (log_->ll_output_handle_ == NULL) return; - LowLevelCodeDeleteStruct event; +void LowLevelLogger::CodeDeleteEvent(Address from) { + CodeDeleteStruct event; event.address = from + Code::kHeaderSize; - LowLevelLogWriteStruct(event); + LogWriteStruct(event); } -void Logger::LowLevelSnapshotPositionEvent(Address addr, int pos) { - if (log_->ll_output_handle_ == NULL) return; - LowLevelSnapshotPositionStruct event; +void LowLevelLogger::SnapshotPositionEvent(Address addr, int pos) { + SnapshotPositionStruct event; event.address = addr + Code::kHeaderSize; event.position = pos; - LowLevelLogWriteStruct(event); + LogWriteStruct(event); } -void Logger::LowLevelLogWriteBytes(const char* bytes, int size) { - size_t rv = fwrite(bytes, 1, size, log_->ll_output_handle_); +void LowLevelLogger::LogWriteBytes(const char* bytes, int size) { + size_t rv = fwrite(bytes, 1, size, ll_output_handle_); ASSERT(static_cast(size) == rv); USE(rv); } +void LowLevelLogger::CodeMovingGCEvent() { + const char tag = kCodeMovingGCTag; + + LogWriteBytes(&tag, sizeof(tag)); +} + + void Logger::LogCodeObjects() { Heap* heap = isolate_->heap(); heap->CollectAllGarbage(Heap::kMakeHeapIterableMask, @@ -1744,6 +1803,63 @@ void Logger::LogAccessorCallbacks() { } +static void AddIsolateIdIfNeeded(StringStream* stream) { + Isolate* isolate = Isolate::Current(); + if (isolate->IsDefaultIsolate()) return; + stream->Add("isolate-%p-", isolate); +} + + +static SmartArrayPointer PrepareLogFileName(const char* file_name) { + if (strchr(file_name, '%') != NULL || + !Isolate::Current()->IsDefaultIsolate()) { + // If there's a '%' in the log file name we have to expand + // placeholders. + HeapStringAllocator allocator; + StringStream stream(&allocator); + AddIsolateIdIfNeeded(&stream); + for (const char* p = file_name; *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 'p': + stream.Add("%d", OS::GetCurrentProcessId()); + break; + case 't': { + // %t expands to the current time in milliseconds. + double time = OS::TimeCurrentMillis(); + stream.Add("%.0f", FmtElm(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); + } + } + return SmartArrayPointer(stream.ToCString()); + } + int length = StrLength(file_name); + char* str = NewArray(length + 1); + OS::MemCopy(str, file_name, length); + str[length] = '\0'; + return SmartArrayPointer(str); +} + + bool Logger::SetUp(Isolate* isolate) { // Tests and EnsureInitialize() can call this twice in a row. It's harmless. if (is_initialized_) return true; @@ -1760,9 +1876,13 @@ bool Logger::SetUp(Isolate* isolate) { FLAG_prof_auto = false; } - log_->Initialize(); + SmartArrayPointer log_file_name = + PrepareLogFileName(FLAG_logfile); + log_->Initialize(*log_file_name); - if (FLAG_ll_prof) LogCodeInfo(); + if (FLAG_ll_prof) { + ll_logger_ = new LowLevelLogger(*log_file_name); + } ticker_ = new Ticker(isolate, kSamplingIntervalMs); @@ -1819,6 +1939,11 @@ FILE* Logger::TearDown() { delete ticker_; ticker_ = NULL; + if (ll_logger_) { + delete ll_logger_; + ll_logger_ = NULL; + } + return log_->Close(); } diff --git a/src/log.h b/src/log.h index 07ecd0e..bb3dbd5 100644 --- a/src/log.h +++ b/src/log.h @@ -151,6 +151,7 @@ class CompilationInfo; // original tags when writing to the log. +class LowLevelLogger; class Sampler; @@ -430,30 +431,8 @@ class Logger { // Appends symbol for the name. void AppendSymbolName(LogMessageBuilder*, Symbol*); - // Emits general information about generated code. - void LogCodeInfo(); - void RegisterSnapshotCodeName(Code* code, const char* name, int name_size); - // Low-level logging support. - - void LowLevelCodeCreateEvent(Code* code, const char* name, int name_size); - - void LowLevelCodeMoveEvent(Address from, Address to); - - void LowLevelCodeDeleteEvent(Address from); - - void LowLevelSnapshotPositionEvent(Address addr, int pos); - - void LowLevelLogWriteBytes(const char* bytes, int size); - - template - void LowLevelLogWriteStruct(const T& s) { - char tag = T::kTag; - LowLevelLogWriteBytes(reinterpret_cast(&tag), sizeof(tag)); - LowLevelLogWriteBytes(reinterpret_cast(&s), sizeof(s)); - } - // Emits a profiler tick event. Used by the profiler thread. void TickEvent(TickSample* sample, bool overflow); @@ -495,6 +474,7 @@ class Logger { int cpu_profiler_nesting_; Log* log_; + LowLevelLogger* ll_logger_; NameBuffer* name_buffer_; -- 2.7.4