From 969d43e785c62b31aabb66392a13b4b8fd017745 Mon Sep 17 00:00:00 2001 From: "sgjesse@chromium.org" Date: Tue, 17 Feb 2009 12:49:35 +0000 Subject: [PATCH] Changed all log messages to be handled through the LogMessageBuilder instead of through fprintf directly to the log file. Added a flag for the runtime %Log call and fixed its arguments checking. Use of %Log is only for debugging. Review URL: http://codereview.chromium.org/21406 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@1290 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/flag-definitions.h | 1 + src/log.cc | 263 +++++++++++++++++++++++++---------------- src/log.h | 2 - src/runtime.cc | 4 +- 4 files changed, 161 insertions(+), 109 deletions(-) diff --git a/src/flag-definitions.h b/src/flag-definitions.h index 9894bc89d2..344470eb18 100644 --- a/src/flag-definitions.h +++ b/src/flag-definitions.h @@ -315,6 +315,7 @@ DEFINE_bool(trace_regexp_assembler, false, DEFINE_bool(log, false, "Minimal logging (no API, code, GC, suspect, or handles samples).") DEFINE_bool(log_all, false, "Log all events to the log file.") +DEFINE_bool(log_runtime, false, "Activate runtime system %Log call.") DEFINE_bool(log_api, false, "Log API events to the log file.") DEFINE_bool(log_code, false, "Log code events to the log file without profiling.") diff --git a/src/log.cc b/src/log.cc index 1d8e43fcdd..a5c89b9b7d 100644 --- a/src/log.cc +++ b/src/log.cc @@ -268,7 +268,10 @@ class LogMessageBuilder BASE_EMBEDDED { ~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(); @@ -291,8 +294,17 @@ void LogMessageBuilder::Append(const char* format, ...) { Logger::kMessageBufferSize - pos_); va_list args; va_start(args, format); - int result = v8::internal::OS::VSNPrintF(buf, format, args); + 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 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) { @@ -313,6 +325,46 @@ void LogMessageBuilder::Append(const char c) { } +// 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(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); @@ -338,8 +390,9 @@ SlidingStateWindow* Logger::sliding_state_window_ = NULL; void Logger::Preamble(const char* content) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log_code) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "%s", content); + LogMessageBuilder msg; + msg.Append("%s", content); + msg.WriteToLogFile(); #endif } @@ -354,8 +407,9 @@ void Logger::StringEvent(const char* name, const char* value) { #ifdef ENABLE_LOGGING_AND_PROFILING void Logger::UncheckedStringEvent(const char* name, const char* value) { if (logfile_ == NULL) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "%s,\"%s\"\n", name, value); + LogMessageBuilder msg; + msg.Append("%s,\"%s\"\n", name, value); + msg.WriteToLogFile(); } #endif @@ -363,8 +417,9 @@ void Logger::UncheckedStringEvent(const char* name, const char* value) { void Logger::IntEvent(const char* name, int value) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "%s,%d\n", name, value); + LogMessageBuilder msg; + msg.Append("%s,%d\n", name, value); + msg.WriteToLogFile(); #endif } @@ -372,9 +427,10 @@ void Logger::IntEvent(const char* name, int value) { void Logger::HandleEvent(const char* name, Object** location) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log_handles) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "%s,0x%x\n", name, - reinterpret_cast(location)); + LogMessageBuilder msg; + msg.Append("%s,0x%x\n", name, + reinterpret_cast(location)); + msg.WriteToLogFile(); #endif } @@ -385,10 +441,12 @@ void Logger::HandleEvent(const char* name, Object** location) { // FLAG_log_api is true. void Logger::ApiEvent(const char* format, ...) { ASSERT(logfile_ != NULL && FLAG_log_api); - ScopedLock sl(mutex_); + LogMessageBuilder msg; va_list ap; va_start(ap, format); - vfprintf(logfile_, format, ap); + msg.Append(format, ap); + va_end(ap); + msg.WriteToLogFile(); } #endif @@ -414,9 +472,10 @@ void Logger::SharedLibraryEvent(const char* library_path, unsigned end) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_prof) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "shared-library,\"%s\",0x%08x,0x%08x\n", library_path, - start, end); + LogMessageBuilder msg; + msg.Append("shared-library,\"%s\",0x%08x,0x%08x\n", library_path, + start, end); + msg.WriteToLogFile(); #endif } @@ -426,79 +485,54 @@ void Logger::SharedLibraryEvent(const wchar_t* library_path, unsigned end) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_prof) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "shared-library,\"%ls\",0x%08x,0x%08x\n", library_path, - start, end); + 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::LogString(Handle str, bool show_impl_info) { - StringShape shape(*str); - int len = str->length(shape); - if (len > 0x1000) - len = 0x1000; - if (show_impl_info) { - fputc(shape.IsAsciiRepresentation() ? 'a' : '2', logfile_); - if (shape.IsExternal()) - fputc('e', logfile_); - if (shape.IsSymbol()) - fputc('#', logfile_); - fprintf(logfile_, ":%i:", str->length()); - } - for (int i = 0; i < len; i++) { - uc32 c = str->Get(shape, i); - if (c > 0xff) { - fprintf(logfile_, "\\u%04x", c); - } else if (c < 32 || c > 126) { - fprintf(logfile_, "\\x%02x", c); - } else if (c == ',') { - fprintf(logfile_, "\\,"); - } else if (c == '\\') { - fprintf(logfile_, "\\\\"); - } else { - fprintf(logfile_, "%lc", c); - } - } -} - void Logger::LogRegExpSource(Handle regexp) { // Prints "/" + re.source + "/" + // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"") + LogMessageBuilder msg; Handle source = GetProperty(regexp, "source"); if (!source->IsString()) { - fprintf(logfile_, "no source"); + msg.Append("no source"); return; } switch (regexp->TypeTag()) { case JSRegExp::ATOM: - fprintf(logfile_, "a"); + msg.Append('a'); break; default: break; } - fprintf(logfile_, "/"); - LogString(Handle::cast(source), false); - fprintf(logfile_, "/"); + msg.Append('/'); + msg.AppendDetailed(*Handle::cast(source), false); + msg.Append('/'); // global flag Handle global = GetProperty(regexp, "global"); if (global->IsTrue()) { - fprintf(logfile_, "g"); + msg.Append('g'); } // ignorecase flag Handle ignorecase = GetProperty(regexp, "ignoreCase"); if (ignorecase->IsTrue()) { - fprintf(logfile_, "i"); + msg.Append('i'); } // multiline flag Handle multiline = GetProperty(regexp, "multiline"); if (multiline->IsTrue()) { - fprintf(logfile_, "m"); + msg.Append('m'); } + + msg.WriteToLogFile(); } #endif // ENABLE_LOGGING_AND_PROFILING @@ -506,19 +540,20 @@ void Logger::LogRegExpSource(Handle regexp) { void Logger::RegExpCompileEvent(Handle regexp, bool in_cache) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log_regexp) return; - ScopedLock sl(mutex_); - - fprintf(logfile_, "regexp-compile,"); + LogMessageBuilder msg; + msg.Append("regexp-compile,"); LogRegExpSource(regexp); - fprintf(logfile_, in_cache ? ",hit\n" : ",miss\n"); + msg.Append(in_cache ? ",hit\n" : ",miss\n"); + msg.WriteToLogFile(); #endif } void Logger::LogRuntime(Vector format, JSArray* args) { #ifdef ENABLE_LOGGING_AND_PROFILING - ScopedLock sl(mutex_); + 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) { @@ -528,28 +563,29 @@ void Logger::LogRuntime(Vector format, JSArray* args) { i++; switch (format[i]) { case 's': - Logger::LogString(Handle(String::cast(obj)), false); + msg.AppendDetailed(String::cast(obj), false); break; case 'S': - Logger::LogString(Handle(String::cast(obj)), true); + msg.AppendDetailed(String::cast(obj), true); break; case 'r': Logger::LogRegExpSource(Handle(JSRegExp::cast(obj))); break; case 'x': - fprintf(logfile_, "0x%x", Smi::cast(obj)->value()); + msg.Append("0x%x", Smi::cast(obj)->value()); break; case 'i': - fprintf(logfile_, "%i", Smi::cast(obj)->value()); + msg.Append("%i", Smi::cast(obj)->value()); break; default: UNREACHABLE(); } } else { - fputc(c, logfile_); + msg.Append(c); } } - fputc('\n', logfile_); + msg.Append('\n'); + msg.WriteToLogFile(); #endif } @@ -611,10 +647,11 @@ void Logger::ApiEntryCall(const char* name) { void Logger::NewEvent(const char* name, void* object, size_t size) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "new,%s,0x%x,%u\n", name, - reinterpret_cast(object), - static_cast(size)); + LogMessageBuilder msg; + msg.Append("new,%s,0x%x,%u\n", name, + reinterpret_cast(object), + static_cast(size)); + msg.WriteToLogFile(); #endif } @@ -622,9 +659,10 @@ void Logger::NewEvent(const char* name, void* object, size_t size) { void Logger::DeleteEvent(const char* name, void* object) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "delete,%s,0x%x\n", name, - reinterpret_cast(object)); + LogMessageBuilder msg; + msg.Append("delete,%s,0x%x\n", name, + reinterpret_cast(object)); + msg.WriteToLogFile(); #endif } @@ -637,7 +675,9 @@ void Logger::CodeCreateEvent(const char* tag, Code* code, const char* comment) { reinterpret_cast(code->address()), code->instruction_size()); for (const char* p = comment; *p != '\0'; p++) { - if (*p == '\"') fprintf(logfile_, "\\"); + if (*p == '"') { + msg.Append('\\'); + } msg.Append(*p); } msg.Append('"'); @@ -757,16 +797,17 @@ void Logger::EndCodeRegionEvent(CodeRegion* region, Assembler* masm) { void Logger::ResourceEvent(const char* name, const char* tag) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "%s,%s,", name, tag); + LogMessageBuilder msg; + msg.Append("%s,%s,", name, tag); uint32_t sec, usec; if (OS::GetUserTime(&sec, &usec) != -1) { - fprintf(logfile_, "%d,%d,", sec, usec); + msg.Append("%d,%d,", sec, usec); } - fprintf(logfile_, "%.0f", OS::TimeCurrentMillis()); + msg.Append("%.0f", OS::TimeCurrentMillis()); - fprintf(logfile_, "\n"); + msg.Append('\n'); + msg.WriteToLogFile(); #endif } @@ -774,15 +815,19 @@ void Logger::ResourceEvent(const char* name, const char* tag) { 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_); - fprintf(logfile_, "suspect-read,"); - class_name->PrintOn(logfile_); - fprintf(logfile_, ",\""); - name->PrintOn(logfile_); - fprintf(logfile_, "\"\n"); + msg.Append("suspect-read,"); + msg.Append(class_name); + msg.Append(','); + msg.Append('"'); + msg.Append(name); + msg.Append('"'); + msg.Append('\n'); + msg.WriteToLogFile(); #endif } @@ -790,8 +835,9 @@ void Logger::SuspectReadEvent(String* name, Object* obj) { void Logger::HeapSampleBeginEvent(const char* space, const char* kind) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log_gc) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "heap-sample-begin,\"%s\",\"%s\"\n", space, kind); + LogMessageBuilder msg; + msg.Append("heap-sample-begin,\"%s\",\"%s\"\n", space, kind); + msg.WriteToLogFile(); #endif } @@ -799,8 +845,9 @@ void Logger::HeapSampleBeginEvent(const char* space, const char* kind) { void Logger::HeapSampleEndEvent(const char* space, const char* kind) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log_gc) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "heap-sample-end,\"%s\",\"%s\"\n", space, kind); + LogMessageBuilder msg; + msg.Append("heap-sample-end,\"%s\",\"%s\"\n", space, kind); + msg.WriteToLogFile(); #endif } @@ -808,8 +855,9 @@ void Logger::HeapSampleEndEvent(const char* space, const char* kind) { void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log_gc) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "heap-sample-item,%s,%d,%d\n", type, number, bytes); + LogMessageBuilder msg; + msg.Append("heap-sample-item,%s,%d,%d\n", type, number, bytes); + msg.WriteToLogFile(); #endif } @@ -817,8 +865,9 @@ void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) { void Logger::DebugTag(const char* call_site_tag) { #ifdef ENABLE_LOGGING_AND_PROFILING if (logfile_ == NULL || !FLAG_log) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "debug-tag,%s\n", call_site_tag); + LogMessageBuilder msg; + msg.Append("debug-tag,%s\n", call_site_tag); + msg.WriteToLogFile(); #endif } @@ -831,13 +880,13 @@ void Logger::DebugEvent(const char* event_type, Vector parameter) { s.AddCharacter(static_cast(parameter[i])); } char* parameter_string = s.Finalize(); - ScopedLock sl(mutex_); - fprintf(logfile_, - "debug-queue-event,%s,%15.3f,%s\n", - event_type, - OS::TimeCurrentMillis(), - parameter_string); + LogMessageBuilder msg; + msg.Append("debug-queue-event,%s,%15.3f,%s\n", + event_type, + OS::TimeCurrentMillis(), + parameter_string); DeleteArray(parameter_string); + msg.WriteToLogFile(); #endif } @@ -845,11 +894,14 @@ void Logger::DebugEvent(const char* event_type, Vector parameter) { #ifdef ENABLE_LOGGING_AND_PROFILING void Logger::TickEvent(TickSample* sample, bool overflow) { if (logfile_ == NULL || !FLAG_prof) return; - ScopedLock sl(mutex_); - fprintf(logfile_, "tick,0x%x,0x%x,%d", sample->pc, sample->sp, - static_cast(sample->state)); - if (overflow) fprintf(logfile_, ",overflow"); - fprintf(logfile_, "\n"); + LogMessageBuilder msg; + msg.Append("tick,0x%x,0x%x,%d", sample->pc, sample->sp, + static_cast(sample->state)); + if (overflow) { + msg.Append(",overflow"); + } + msg.Append('\n'); + msg.WriteToLogFile(); } @@ -873,6 +925,7 @@ 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; @@ -884,8 +937,8 @@ bool Logger::Setup() { // --prof implies --log-code. if (FLAG_prof) FLAG_log_code = true; - bool open_log_file = FLAG_log || FLAG_log_api || FLAG_log_code - || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect + 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. diff --git a/src/log.h b/src/log.h index 246b2708e1..984ea5476c 100644 --- a/src/log.h +++ b/src/log.h @@ -218,8 +218,6 @@ class Logger { // Emits the source code of a regexp. Used by regexp events. static void LogRegExpSource(Handle regexp); - static void LogString(Handle str, bool show_impl_info); - // Emits a profiler tick event. Used by the profiler thread. static void TickEvent(TickSample* sample, bool overflow); diff --git a/src/runtime.cc b/src/runtime.cc index db758fe1d3..db291e200d 100644 --- a/src/runtime.cc +++ b/src/runtime.cc @@ -6037,9 +6037,9 @@ static Object* Runtime_ListNatives(Arguments args) { static Object* Runtime_Log(Arguments args) { ASSERT(args.length() == 2); - String* format = String::cast(args[0]); + CONVERT_CHECKED(String, format, args[0]); + CONVERT_CHECKED(JSArray, elms, args[1]); Vector chars = format->ToAsciiVector(); - JSArray* elms = JSArray::cast(args[1]); Logger::LogRuntime(chars, elms); return Heap::undefined_value(); }