[log] Consistently escape log entries

Implicitly escape all output that is passed to Log::MessageBuilder.
We escape non-printable characters and the log field separator ','
using the \x00 and \u0000 escape sequences.

Example:
Before: event-foo,"space: ","comma: ,","double quotes: """
After:  event-foo,space: ,comma: \x2C,double quotes: "

This might slightly impact human readability of the log files in
extreme cases. However, most strings do not contain any escaped
characters.

Bug: 
Change-Id: Ic78f6d9932367d02f9f3c3f70b41b5c283bdf880
Reviewed-on: https://chromium-review.googlesource.com/728332
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Adam Klein <adamk@chromium.org>
Cr-Commit-Position: refs/heads/master@{#48805}
This commit is contained in:
Camillo Bruni 2017-10-20 16:14:23 -07:00 committed by Commit Bot
parent 761b4719d3
commit d06cb58685
10 changed files with 2804 additions and 2806 deletions

View File

@ -51,19 +51,17 @@ Log::Log(Logger* logger, const char* file_name)
// --prof implies --log-code.
if (FLAG_prof) FLAG_log_code = true;
if (output_handle_ != nullptr) {
Log::MessageBuilder msg(this);
if (strlen(Version::GetEmbedder()) == 0) {
msg.Append("v8-version,%d,%d,%d,%d,%d", Version::GetMajor(),
Version::GetMinor(), Version::GetBuild(), Version::GetPatch(),
Version::IsCandidate());
} else {
msg.Append("v8-version,%d,%d,%d,%d,%s,%d", Version::GetMajor(),
Version::GetMinor(), Version::GetBuild(), Version::GetPatch(),
Version::GetEmbedder(), Version::IsCandidate());
}
msg.WriteToLogFile();
if (output_handle_ == nullptr) return;
Log::MessageBuilder msg(this);
LogSeparator kNext = LogSeparator::kSeparator;
msg << "v8-version" << kNext << Version::GetMajor() << kNext
<< Version::GetMinor() << kNext << Version::GetBuild() << kNext
<< Version::GetPatch();
if (strlen(Version::GetEmbedder()) != 0) {
msg << kNext << Version::GetEmbedder();
}
msg << kNext << Version::IsCandidate();
msg.WriteToLogFile();
}
FILE* Log::Close() {
@ -102,38 +100,16 @@ void Log::MessageBuilder::AppendVA(const char* format, va_list args) {
Vector<char> buf(log_->format_buffer_, Log::kMessageBufferSize);
int length = v8::internal::VSNPrintF(buf, format, args);
// {length} is -1 if output was truncated.
if (length == -1) {
length = Log::kMessageBufferSize;
}
if (length == -1) length = Log::kMessageBufferSize;
DCHECK_LE(length, Log::kMessageBufferSize);
AppendStringPart(log_->format_buffer_, length);
}
void Log::MessageBuilder::AppendDoubleQuotedString(const char* string) {
OFStream& os = log_->os_;
// TODO(cbruni): unify escaping.
os << '"';
for (const char* p = string; *p != '\0'; p++) {
if (*p == '"') os << '\\';
os << *p;
}
os << '"';
}
void Log::MessageBuilder::AppendDoubleQuotedString(String* string) {
OFStream& os = log_->os_;
os << '"';
// TODO(cbruni): unify escaping.
AppendEscapedString(string);
os << '"';
}
void Log::MessageBuilder::Append(String* string) {
DisallowHeapAllocation no_gc; // Ensure string stay valid.
std::unique_ptr<char[]> characters =
string->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
log_->os_ << characters.get();
AppendString(characters.get());
}
void Log::MessageBuilder::AppendAddress(Address addr) {
@ -152,59 +128,115 @@ void Log::MessageBuilder::AppendSymbolName(Symbol* symbol) {
os << "hash " << std::hex << symbol->Hash() << std::dec << ")";
}
void Log::MessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
if (str == nullptr) return;
DisallowHeapAllocation no_gc; // Ensure string stay valid.
OFStream& os = log_->os_;
int len = str->length();
if (len > 0x1000) len = 0x1000;
int limit = str->length();
if (limit > 0x1000) limit = 0x1000;
if (show_impl_info) {
os << (str->IsOneByteRepresentation() ? 'a' : '2');
if (StringShape(str).IsExternal()) os << 'e';
if (StringShape(str).IsInternalized()) os << '#';
os << ':' << str->length() << ':';
}
AppendEscapedString(str, len);
AppendStringPart(str, limit);
}
void Log::MessageBuilder::AppendEscapedString(String* str) {
void Log::MessageBuilder::AppendString(String* str) {
if (str == nullptr) return;
int len = str->length();
AppendEscapedString(str, len);
AppendStringPart(str, len);
}
void Log::MessageBuilder::AppendEscapedString(String* str, int len) {
void Log::MessageBuilder::AppendString(const char* string) {
for (const char* p = string; *p != '\0'; p++) {
this->AppendCharacter(*p);
}
}
void Log::MessageBuilder::AppendStringPart(String* str, int len) {
DCHECK_LE(len, str->length());
DisallowHeapAllocation no_gc; // Ensure string stay valid.
OFStream& os = log_->os_;
// TODO(cbruni): unify escaping.
for (int i = 0; i < len; i++) {
uc32 c = str->Get(i);
if (c >= 32 && c <= 126) {
if (c == '\"') {
os << "\"\"";
} else if (c == '\\') {
os << "\\\\";
} else if (c == ',') {
os << "\\,";
} else {
os << static_cast<char>(c);
}
} else if (c > 0xff) {
Append("\\u%04x", c);
if (c <= 0xff) {
AppendCharacter(static_cast<char>(c));
} else {
DCHECK(c < 32 || (c > 126 && c <= 0xff));
Append("\\x%02x", c);
// Escape any non-ascii range characters.
Append("\\u%04x", c);
}
}
}
void Log::MessageBuilder::AppendStringPart(const char* str, int len) {
log_->os_.write(str, len);
for (int i = 0; i < len; i++) {
DCHECK_NE(str[i], '\0');
this->AppendCharacter(str[i]);
}
}
void Log::MessageBuilder::AppendCharacter(char c) {
OFStream& os = log_->os_;
// A log entry (separate by commas) cannot contain commas or line-brakes.
if (c >= 32 && c <= 126) {
if (c == ',') {
// Escape commas directly.
os << "\x2c";
} else {
// Directly append any printable ascii character.
os << c;
}
} else {
// Escape any non-printable haracters.
Append("\\x%02x", c);
}
}
void Log::MessageBuilder::WriteToLogFile() { log_->os_ << std::endl; }
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<const char*>(
const char* string) {
this->AppendString(string);
return *this;
}
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<char>(char c) {
this->AppendCharacter(c);
return *this;
}
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<String*>(String* string) {
this->AppendString(string);
return *this;
}
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<Symbol*>(Symbol* symbol) {
this->AppendSymbolName(symbol);
return *this;
}
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<Name*>(Name* name) {
if (name->IsString()) {
this->AppendString(String::cast(name));
} else {
this->AppendSymbolName(Symbol::cast(name));
}
return *this;
}
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<LogSeparator>(
LogSeparator separator) {
log_->os_ << ',';
return *this;
}
} // namespace internal
} // namespace v8

View File

@ -20,11 +20,12 @@ namespace internal {
class Logger;
enum class LogSeparator { kSeparator };
// Functions and data for performing output of log messages.
class Log {
public:
Log(Logger* log, const char* log_file_name);
// Disables logging, but preserves acquired resources.
void stop() { is_stopped_ = true; }
@ -66,10 +67,6 @@ class Log {
// Append string data to the log message.
void PRINTF_FORMAT(2, 0) AppendVA(const char* format, va_list args);
// Append double quoted string to the log message.
void AppendDoubleQuotedString(const char* string);
void AppendDoubleQuotedString(String* string);
// Append a heap string.
void Append(String* str);
@ -80,16 +77,18 @@ class Log {
void AppendDetailed(String* str, bool show_impl_info);
// Append a portion of a string.
// Append and escape a full string.
void AppendString(String* source);
void AppendString(const char* string);
// Append and escpae a portion of a string.
void AppendStringPart(String* source, int len);
void AppendStringPart(const char* str, int len);
// Helpers for appending char, C-string and heap string without
// buffering. This is useful for entries that can exceed the 2kB
// limit.
void AppendEscapedString(String* source);
void AppendEscapedString(String* source, int len);
void AppendCharacter(const char character);
// Delegate insertion to the underlying {log_}.
// All appened srings are escaped to maintain one-line log entries.
template <typename T>
MessageBuilder& operator<<(T value) {
log_->os_ << value;
@ -136,6 +135,20 @@ class Log {
friend class Logger;
};
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<LogSeparator>(
LogSeparator separator);
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<const char*>(
const char* string);
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<char>(char c);
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<String*>(String* string);
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<Symbol*>(Symbol* symbol);
template <>
Log::MessageBuilder& Log::MessageBuilder::operator<<<Name*>(Name* name);
} // namespace internal
} // namespace v8

View File

@ -20,7 +20,6 @@
#include "src/interpreter/interpreter.h"
#include "src/libsampler/sampler.h"
#include "src/log-inl.h"
#include "src/log-utils.h"
#include "src/macro-assembler.h"
#include "src/perf-jit.h"
#include "src/profiler/profiler-listener.h"
@ -32,6 +31,9 @@
#include "src/unicode-inl.h"
#include "src/vm-state-inl.h"
#include "src/utils.h"
#include "src/version.h"
namespace v8 {
namespace internal {
@ -749,7 +751,7 @@ void Logger::removeCodeEventListener(CodeEventListener* listener) {
void Logger::ProfilerBeginEvent() {
if (!log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
msg << "profiler,\"begin\"," << FLAG_prof_sampling_interval;
msg << "profiler" << kNext << "begin" << kNext << FLAG_prof_sampling_interval;
msg.WriteToLogFile();
}
@ -762,7 +764,7 @@ void Logger::StringEvent(const char* name, const char* value) {
void Logger::UncheckedStringEvent(const char* name, const char* value) {
if (!log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
msg << name << ",\"" << value << "\"";
msg << name << kNext << value;
msg.WriteToLogFile();
}
@ -780,7 +782,7 @@ void Logger::IntPtrTEvent(const char* name, intptr_t value) {
void Logger::UncheckedIntEvent(const char* name, int value) {
if (!log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
msg << name << "," << value;
msg << name << kNext << value;
msg.WriteToLogFile();
}
@ -788,7 +790,8 @@ void Logger::UncheckedIntEvent(const char* name, int value) {
void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
if (!log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
msg.Append("%s,%" V8PRIdPTR, name, value);
msg << name << kNext;
msg.Append("%" V8PRIdPTR, value);
msg.WriteToLogFile();
}
@ -796,28 +799,16 @@ void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
void Logger::HandleEvent(const char* name, Object** location) {
if (!log_->IsEnabled() || !FLAG_log_handles) return;
Log::MessageBuilder msg(log_);
msg << name << "," << static_cast<void*>(location);
msg.WriteToLogFile();
}
// ApiEvent is private so all the calls come from the Logger class. It is the
// caller's responsibility to ensure that log is enabled and that
// FLAG_log_api is true.
void Logger::ApiEvent(const char* format, ...) {
DCHECK(log_->IsEnabled() && FLAG_log_api);
Log::MessageBuilder msg(log_);
va_list ap;
va_start(ap, format);
msg.AppendVA(format, ap);
va_end(ap);
msg << name << kNext << static_cast<void*>(location);
msg.WriteToLogFile();
}
void Logger::ApiSecurityCheck() {
if (!log_->IsEnabled() || !FLAG_log_api) return;
ApiEvent("api,check-security");
Log::MessageBuilder msg(log_);
msg << "api" << kNext << "check-security";
msg.WriteToLogFile();
}
void Logger::SharedLibraryEvent(const std::string& library_path,
@ -825,9 +816,9 @@ void Logger::SharedLibraryEvent(const std::string& library_path,
intptr_t aslr_slide) {
if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
Log::MessageBuilder msg(log_);
msg << "shared-library,\"" << library_path.c_str() << "\","
<< reinterpret_cast<void*>(start) << "," << reinterpret_cast<void*>(end)
<< "," << aslr_slide;
msg << "shared-library" << kNext << library_path.c_str() << kNext
<< reinterpret_cast<void*>(start) << kNext << reinterpret_cast<void*>(end)
<< kNext << aslr_slide;
msg.WriteToLogFile();
}
@ -836,8 +827,8 @@ void Logger::CodeDeoptEvent(Code* code, DeoptKind kind, Address pc,
if (!log_->IsEnabled()) return;
Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc);
Log::MessageBuilder msg(log_);
int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
msg << "code-deopt," << since_epoch << "," << code->CodeSize() << ",";
msg << "code-deopt" << kNext << timer_.Elapsed().InMicroseconds() << kNext
<< code->CodeSize() << kNext;
msg.AppendAddress(code->instruction_start());
// Deoptimization position.
@ -851,21 +842,20 @@ void Logger::CodeDeoptEvent(Code* code, DeoptKind kind, Address pc,
} else {
deopt_location << "<unknown>";
}
msg << "," << inlining_id << "," << script_offset << ",";
msg << kNext << inlining_id << kNext << script_offset << kNext;
switch (kind) {
case kLazy:
msg << "\"lazy\",";
msg << "lazy" << kNext;
break;
case kSoft:
msg << "\"soft\",";
msg << "soft" << kNext;
break;
case kEager:
msg << "\"eager\",";
msg << "eager" << kNext;
break;
}
msg.AppendDoubleQuotedString(deopt_location.str().c_str());
msg << ",";
msg.AppendDoubleQuotedString(DeoptimizeReasonToString(info.deopt_reason));
msg << deopt_location.str().c_str() << kNext
<< DeoptimizeReasonToString(info.deopt_reason);
msg.WriteToLogFile();
}
@ -874,8 +864,7 @@ void Logger::CurrentTimeEvent() {
if (!log_->IsEnabled()) return;
DCHECK(FLAG_log_internal_timer_events);
Log::MessageBuilder msg(log_);
int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
msg << "current-time," << since_epoch;
msg << "current-time" << kNext << timer_.Elapsed().InMicroseconds();
msg.WriteToLogFile();
}
@ -893,10 +882,7 @@ void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
case STAMP:
msg << "timer-event";
}
msg << ",";
int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
msg.AppendDoubleQuotedString(name);
msg << "," << since_epoch;
msg << kNext << name << kNext << timer_.Elapsed().InMicroseconds();
msg.WriteToLogFile();
}
@ -923,64 +909,47 @@ void Logger::LeaveExternal(Isolate* isolate) {
TIMER_EVENTS_LIST(V)
#undef V
void Logger::ApiNamedPropertyAccess(const char* tag,
JSObject* holder,
Object* name) {
DCHECK(name->IsName());
void Logger::ApiNamedPropertyAccess(const char* tag, JSObject* holder,
Object* property_name) {
DCHECK(property_name->IsName());
if (!log_->IsEnabled() || !FLAG_log_api) return;
String* class_name_obj = holder->class_name();
std::unique_ptr<char[]> class_name =
class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
if (name->IsString()) {
std::unique_ptr<char[]> property_name =
String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
ApiEvent("api,%s,\"%s\",\"%s\"", tag, class_name.get(),
property_name.get());
} else {
Symbol* symbol = Symbol::cast(name);
uint32_t hash = symbol->Hash();
if (symbol->name()->IsUndefined(symbol->GetIsolate())) {
ApiEvent("api,%s,\"%s\",symbol(hash %x)", tag, class_name.get(), hash);
} else {
std::unique_ptr<char[]> str =
String::cast(symbol->name())
->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)", tag, class_name.get(),
str.get(), hash);
}
}
Log::MessageBuilder msg(log_);
msg << "api" << kNext << tag << kNext << holder->class_name() << kNext
<< Name::cast(property_name);
msg.WriteToLogFile();
}
void Logger::ApiIndexedPropertyAccess(const char* tag,
JSObject* holder,
uint32_t index) {
if (!log_->IsEnabled() || !FLAG_log_api) return;
String* class_name_obj = holder->class_name();
std::unique_ptr<char[]> class_name =
class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
ApiEvent("api,%s,\"%s\",%u", tag, class_name.get(), index);
Log::MessageBuilder msg(log_);
msg << "api" << kNext << tag << kNext << holder->class_name() << kNext
<< index;
msg.WriteToLogFile();
}
void Logger::ApiObjectAccess(const char* tag, JSObject* object) {
if (!log_->IsEnabled() || !FLAG_log_api) return;
String* class_name_obj = object->class_name();
std::unique_ptr<char[]> class_name =
class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
ApiEvent("api,%s,\"%s\"", tag, class_name.get());
Log::MessageBuilder msg(log_);
msg << "api" << kNext << tag << kNext << object->class_name();
msg.WriteToLogFile();
}
void Logger::ApiEntryCall(const char* name) {
if (!log_->IsEnabled() || !FLAG_log_api) return;
ApiEvent("api,%s", name);
Log::MessageBuilder msg(log_);
msg << "api" << kNext << name;
msg.WriteToLogFile();
}
void Logger::NewEvent(const char* name, void* object, size_t size) {
if (!log_->IsEnabled() || !FLAG_log) return;
Log::MessageBuilder msg(log_);
msg << "new," << name << "," << object << ","
msg << "new" << kNext << name << kNext << object << kNext
<< static_cast<unsigned int>(size);
msg.WriteToLogFile();
}
@ -989,7 +958,7 @@ void Logger::NewEvent(const char* name, void* object, size_t size) {
void Logger::DeleteEvent(const char* name, void* object) {
if (!log_->IsEnabled() || !FLAG_log) return;
Log::MessageBuilder msg(log_);
msg << "delete," << name << "," << object;
msg << "delete" << kNext << name << kNext << object;
msg.WriteToLogFile();
}
@ -998,20 +967,11 @@ void Logger::CallbackEventInternal(const char* prefix, Name* name,
Address entry_point) {
if (!FLAG_log_code || !log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << ","
<< kLogEventsNames[CodeEventListener::CALLBACK_TAG] << ",-2,";
int timestamp = static_cast<int>(timer_.Elapsed().InMicroseconds());
msg << timestamp << ",";
msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << kNext
<< kLogEventsNames[CodeEventListener::CALLBACK_TAG] << kNext << -2
<< kNext << timer_.Elapsed().InMicroseconds() << kNext;
msg.AppendAddress(entry_point);
if (name->IsString()) {
msg << ",1,\"" << prefix;
msg.AppendEscapedString(String::cast(name));
msg << "\"";
} else {
Symbol* symbol = Symbol::cast(name);
msg << ",1,";
msg.AppendSymbolName(symbol);
}
msg << kNext << 1 << kNext << prefix << name;
msg.WriteToLogFile();
}
@ -1035,12 +995,11 @@ namespace {
void AppendCodeCreateHeader(Log::MessageBuilder& msg,
CodeEventListener::LogEventsAndTags tag,
AbstractCode* code, base::ElapsedTimer* timer) {
msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << ","
<< kLogEventsNames[tag] << "," << code->kind();
int timestamp = static_cast<int>(timer->Elapsed().InMicroseconds());
msg << "," << timestamp << ",";
msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT]
<< Logger::kNext << kLogEventsNames[tag] << Logger::kNext << code->kind()
<< Logger::kNext << timer->Elapsed().InMicroseconds() << Logger::kNext;
msg.AppendAddress(code->instruction_start());
msg << "," << code->instruction_size() << ",";
msg << Logger::kNext << code->instruction_size() << Logger::kNext;
}
} // namespace
@ -1051,7 +1010,7 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
if (!FLAG_log_code || !log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
AppendCodeCreateHeader(msg, tag, code, &timer_);
msg.AppendDoubleQuotedString(comment);
msg << comment;
msg.WriteToLogFile();
}
@ -1061,11 +1020,7 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
if (!FLAG_log_code || !log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
AppendCodeCreateHeader(msg, tag, code, &timer_);
if (name->IsString()) {
msg.AppendDoubleQuotedString(String::cast(name));
} else {
msg.AppendSymbolName(Symbol::cast(name));
}
msg << name;
msg.WriteToLogFile();
}
@ -1081,14 +1036,9 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
Log::MessageBuilder msg(log_);
AppendCodeCreateHeader(msg, tag, code, &timer_);
if (name->IsString()) {
msg.AppendDoubleQuotedString(String::cast(name));
} else {
msg.AppendSymbolName(Symbol::cast(name));
}
msg << ',';
msg << name << kNext;
msg.AppendAddress(shared->address());
msg << "," << ComputeMarker(shared, code);
msg << kNext << ComputeMarker(shared, code);
msg.WriteToLogFile();
}
@ -1104,17 +1054,10 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
Log::MessageBuilder msg(log_);
AppendCodeCreateHeader(msg, tag, code, &timer_);
msg << "\"";
msg.AppendEscapedString(shared->DebugName());
msg << " ";
if (source->IsString()) {
msg.AppendEscapedString(String::cast(source));
} else {
msg.AppendSymbolName(Symbol::cast(source));
}
msg << ":" << line << ":" << column << "\",";
msg << shared->DebugName() << " " << source << ":" << line << ":" << column
<< kNext;
msg.AppendAddress(shared->address());
msg << "," << ComputeMarker(shared, code);
msg << kNext << ComputeMarker(shared, code);
msg.WriteToLogFile();
if (!FLAG_log_source_code) return;
@ -1132,19 +1075,17 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
Object* source_object = script->source();
if (source_object->IsString()) {
String* source_code = String::cast(source_object);
msg << "script," << script_id << ",\"";
msg << "script" << kNext << script_id << kNext;
// Log the script name.
if (script->name()->IsString()) {
msg.AppendEscapedString(String::cast(script->name()));
msg << "\",\"";
msg << String::cast(script->name()) << kNext;
} else {
msg << "<unknown>\",\"";
msg << "<unknown>" << kNext;
}
// Log the source code.
msg.AppendEscapedString(source_code);
msg << "\"";
msg << source_code;
msg.WriteToLogFile();
}
@ -1169,9 +1110,10 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
// <function-id> is an index into the <fns> function table
// <fns> is the function table encoded as a sequence of strings
// S<shared-function-info-address>
msg << "code-source-info," << static_cast<void*>(code->instruction_start())
<< "," << script_id << "," << shared->start_position() << ","
<< shared->end_position() << ",";
msg << "code-source-info" << kNext
<< static_cast<void*>(code->instruction_start()) << kNext << script_id
<< kNext << shared->start_position() << kNext << shared->end_position()
<< kNext;
SourcePositionTableIterator iterator(code->source_position_table());
bool is_first = true;
@ -1187,7 +1129,7 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
hasInlined = true;
}
}
msg << ",";
msg << kNext;
int maxInlinedId = -1;
if (hasInlined) {
PodArray<InliningPosition>* inlining_positions =
@ -1209,7 +1151,7 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
}
}
}
msg << ",";
msg << kNext;
if (hasInlined) {
DeoptimizationData* deopt_data =
DeoptimizationData::cast(Code::cast(code)->deoptimization_data());
@ -1229,11 +1171,9 @@ void Logger::CodeDisableOptEvent(AbstractCode* code,
if (!is_logging_code_events()) return;
if (!FLAG_log_code || !log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
msg << kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT] << ",";
msg.AppendDoubleQuotedString(shared->DebugName());
msg << ",";
msg.AppendDoubleQuotedString(
GetBailoutReason(shared->disable_optimization_reason()));
msg << kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT] << kNext
<< shared->DebugName() << kNext
<< GetBailoutReason(shared->disable_optimization_reason());
msg.WriteToLogFile();
}
@ -1249,9 +1189,7 @@ void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) {
if (!FLAG_log_code || !log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
AppendCodeCreateHeader(msg, CodeEventListener::REG_EXP_TAG, code, &timer_);
msg << '"';
msg.AppendDetailed(source, false);
msg << '"';
msg << source;
msg.WriteToLogFile();
}
@ -1262,7 +1200,7 @@ void Logger::CodeMoveEvent(AbstractCode* from, Address to) {
void Logger::CodeLinePosInfoRecordEvent(AbstractCode* code,
ByteArray* source_position_table) {
if (jit_logger_ && source_position_table->length() > 0) {
if (jit_logger_) {
void* jit_handler_data = jit_logger_->StartCodePosInfoEvent();
for (SourcePositionTableIterator iter(source_position_table); !iter.done();
iter.Advance()) {
@ -1283,9 +1221,8 @@ void Logger::CodeLinePosInfoRecordEvent(AbstractCode* code,
void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
if (code_name == nullptr) return; // Not a code object.
Log::MessageBuilder msg(log_);
msg << kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT] << ","
<< pos;
msg.AppendDoubleQuotedString(code_name);
msg << kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT] << kNext
<< pos << kNext << code_name;
msg.WriteToLogFile();
}
@ -1299,9 +1236,9 @@ void Logger::MoveEventInternal(CodeEventListener::LogEventsAndTags event,
Address from, Address to) {
if (!FLAG_log_code || !log_->IsEnabled()) return;
Log::MessageBuilder msg(log_);
msg << kLogEventsNames[event] << ",";
msg << kLogEventsNames[event] << kNext;
msg.AppendAddress(from);
msg << ",";
msg << kNext;
msg.AppendAddress(to);
msg.WriteToLogFile();
}
@ -1310,11 +1247,11 @@ void Logger::MoveEventInternal(CodeEventListener::LogEventsAndTags event,
void Logger::ResourceEvent(const char* name, const char* tag) {
if (!log_->IsEnabled() || !FLAG_log) return;
Log::MessageBuilder msg(log_);
msg << name << "," << tag << ",";
msg << name << kNext << tag << kNext;
uint32_t sec, usec;
if (base::OS::GetUserTime(&sec, &usec) != -1) {
msg << sec << "," << usec << ",";
msg << sec << kNext << usec << kNext;
}
msg.Append("%.0f", V8::GetCurrentPlatform()->CurrentClockTimeMillis());
msg.WriteToLogFile();
@ -1327,12 +1264,7 @@ void Logger::SuspectReadEvent(Name* name, Object* obj) {
String* class_name = obj->IsJSObject()
? JSObject::cast(obj)->class_name()
: isolate_->heap()->empty_string();
msg << "suspect-read," << class_name << ",";
if (name->IsString()) {
msg.AppendDoubleQuotedString(String::cast(name));
} else {
msg.AppendSymbolName(Symbol::cast(name));
}
msg << "suspect-read" << kNext << class_name << kNext << name;
msg.WriteToLogFile();
}
@ -1342,7 +1274,7 @@ void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
Log::MessageBuilder msg(log_);
// Using non-relative system time in order to be able to synchronize with
// external memory profiling events (e.g. DOM memory size).
msg << "heap-sample-begin,\"" << space << "\",\"" << kind << "\",";
msg << "heap-sample-begin" << kNext << space << kNext << kind << kNext;
msg.Append("%.0f", V8::GetCurrentPlatform()->CurrentClockTimeMillis());
msg.WriteToLogFile();
}
@ -1351,7 +1283,7 @@ void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
if (!log_->IsEnabled() || !FLAG_log_gc) return;
Log::MessageBuilder msg(log_);
msg << "heap-sample-end,\"" << space << "\",\"" << kind << "\"";
msg << "heap-sample-end" << kNext << space << kNext << kind;
msg.WriteToLogFile();
}
@ -1359,7 +1291,8 @@ void Logger::HeapSampleEndEvent(const char* space, const char* kind) {
void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) {
if (!log_->IsEnabled() || !FLAG_log_gc) return;
Log::MessageBuilder msg(log_);
msg << "heap-sample-item,\"" << type << "\"," << number << "," << bytes;
msg << "heap-sample-item" << kNext << type << kNext << number << kNext
<< bytes;
msg.WriteToLogFile();
}
@ -1369,8 +1302,7 @@ void Logger::RuntimeCallTimerEvent() {
RuntimeCallCounter* counter = stats->current_counter();
if (counter == nullptr) return;
Log::MessageBuilder msg(log_);
msg << "active-runtime-timer,";
msg.AppendDoubleQuotedString(counter->name());
msg << "active-runtime-timer" << kNext << counter->name();
msg.WriteToLogFile();
}
@ -1381,20 +1313,19 @@ void Logger::TickEvent(v8::TickSample* sample, bool overflow) {
RuntimeCallTimerEvent();
}
Log::MessageBuilder msg(log_);
msg << kLogEventsNames[CodeEventListener::TICK_EVENT] << ','
<< reinterpret_cast<void*>(sample->pc) << ','
<< static_cast<int>(timer_.Elapsed().InMicroseconds());
msg << kLogEventsNames[CodeEventListener::TICK_EVENT] << kNext
<< reinterpret_cast<void*>(sample->pc) << kNext
<< timer_.Elapsed().InMicroseconds();
if (sample->has_external_callback) {
msg << ",1," << reinterpret_cast<void*>(sample->external_callback_entry);
msg << kNext << 1 << kNext
<< reinterpret_cast<void*>(sample->external_callback_entry);
} else {
msg << ",0," << reinterpret_cast<void*>(sample->tos);
}
msg << ',' << static_cast<int>(sample->state);
if (overflow) {
msg << ",overflow";
msg << kNext << 0 << kNext << reinterpret_cast<void*>(sample->tos);
}
msg << kNext << static_cast<int>(sample->state);
if (overflow) msg << kNext << "overflow";
for (unsigned i = 0; i < sample->frames_count; ++i) {
msg << ',' << reinterpret_cast<void*>(sample->stack[i]);
msg << kNext << reinterpret_cast<void*>(sample->stack[i]);
}
msg.WriteToLogFile();
}
@ -1406,22 +1337,20 @@ void Logger::ICEvent(const char* type, bool keyed, const Address pc, int line,
if (!log_->IsEnabled() || !FLAG_trace_ic) return;
Log::MessageBuilder msg(log_);
if (keyed) msg << "Keyed";
msg << type << ",";
msg << type << kNext;
msg.AppendAddress(pc);
msg << "," << line << "," << column << "," << old_state << "," << new_state
<< "," << reinterpret_cast<void*>(map) << ",";
msg << kNext << line << kNext << column << kNext << old_state << kNext
<< new_state << kNext << reinterpret_cast<void*>(map) << kNext;
if (key->IsSmi()) {
msg << Smi::ToInt(key);
} else if (key->IsNumber()) {
msg << key->Number();
} else if (key->IsString()) {
msg.AppendDetailed(String::cast(key), false);
} else if (key->IsSymbol()) {
msg.AppendSymbolName(Symbol::cast(key));
} else if (key->IsName()) {
msg << Name::cast(key);
}
msg << "," << modifier << ",";
msg << kNext << modifier << kNext;
if (slow_stub_reason != nullptr) {
msg.AppendDoubleQuotedString(slow_stub_reason);
msg << slow_stub_reason;
}
msg.WriteToLogFile();
}

View File

@ -14,6 +14,7 @@
#include "src/base/platform/platform.h"
#include "src/code-events.h"
#include "src/isolate.h"
#include "src/log-utils.h"
#include "src/objects.h"
namespace v8 {
@ -95,6 +96,9 @@ class Logger : public CodeEventListener {
public:
enum StartEnd { START = 0, END = 1, STAMP = 2 };
// The separator is used to write an unescaped "," into the log.
static const LogSeparator kNext = LogSeparator::kSeparator;
// Acquires resources for logging if the right flags are set.
bool SetUp(Isolate* isolate);
@ -277,8 +281,6 @@ class Logger : public CodeEventListener {
void TickEvent(TickSample* sample, bool overflow);
void RuntimeCallTimerEvent();
PRINTF_FORMAT(2, 3) void ApiEvent(const char* format, ...);
// Logs a StringEvent regardless of whether FLAG_log is true.
void UncheckedStringEvent(const char* name, const char* value);

View File

@ -440,7 +440,7 @@ TEST(LogCallbacks) {
ObjMethod1_entry = *FUNCTION_ENTRYPOINT_ADDRESS(ObjMethod1_entry);
#endif
i::EmbeddedVector<char, 100> ref_data;
i::SNPrintF(ref_data, ",0x%" V8PRIxPTR ",1,\"method1\"",
i::SNPrintF(ref_data, ",0x%" V8PRIxPTR ",1,method1",
reinterpret_cast<intptr_t>(ObjMethod1_entry));
CHECK(logger.FindLine("code-creation,Callback,-2,", ref_data.start()));
}
@ -486,7 +486,7 @@ TEST(LogAccessorCallbacks) {
Prop1Getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop1Getter_entry);
#endif
EmbeddedVector<char, 100> prop1_getter_record;
i::SNPrintF(prop1_getter_record, ",0x%" V8PRIxPTR ",1,\"get prop1\"",
i::SNPrintF(prop1_getter_record, ",0x%" V8PRIxPTR ",1,get prop1",
reinterpret_cast<intptr_t>(Prop1Getter_entry));
CHECK(logger.FindLine("code-creation,Callback,-2,",
prop1_getter_record.start()));
@ -496,7 +496,7 @@ TEST(LogAccessorCallbacks) {
Prop1Setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop1Setter_entry);
#endif
EmbeddedVector<char, 100> prop1_setter_record;
i::SNPrintF(prop1_setter_record, ",0x%" V8PRIxPTR ",1,\"set prop1\"",
i::SNPrintF(prop1_setter_record, ",0x%" V8PRIxPTR ",1,set prop1",
reinterpret_cast<intptr_t>(Prop1Setter_entry));
CHECK(logger.FindLine("code-creation,Callback,-2,",
prop1_setter_record.start()));
@ -506,7 +506,7 @@ TEST(LogAccessorCallbacks) {
Prop2Getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop2Getter_entry);
#endif
EmbeddedVector<char, 100> prop2_getter_record;
i::SNPrintF(prop2_getter_record, ",0x%" V8PRIxPTR ",1,\"get prop2\"",
i::SNPrintF(prop2_getter_record, ",0x%" V8PRIxPTR ",1,get prop2",
reinterpret_cast<intptr_t>(Prop2Getter_entry));
CHECK(logger.FindLine("code-creation,Callback,-2,",
prop2_getter_record.start()));

View File

@ -43,41 +43,44 @@ assertEquals(
parser.parseLine('1997,Ford,E350'));
assertEquals(
['1997','Ford','E350'],
parser.parseLine('"1997","Ford","E350"'));
['"', '\'', ',', '\n'],
parser.parseLine('",\',\\x2c,\\x0a'));
assertEquals(
['1997','Ford','E350','Super, luxurious truck'],
parser.parseLine('1997,Ford,E350,"Super, luxurious truck"'));
['"1997"','Ford','E350'],
parser.parseLine('"1997",Ford,E350'));
assertEquals(
['1997', 'Ford', 'E350', 'Super', ' luxurious truck'],
parser.parseLine('1997,Ford,E350,Super, luxurious truck'));
assertEquals(
['1997','Ford','E350','Super "luxurious" truck'],
parser.parseLine('1997,Ford,E350,"Super ""luxurious"" truck"'));
parser.parseLine('1997,Ford,E350,Super "luxurious" truck'));
assertEquals(
['1997','Ford','E350','Super "luxurious" "truck"'],
parser.parseLine('1997,Ford,E350,"Super ""luxurious"" ""truck"""'));
parser.parseLine('1997,Ford,E350,Super "luxurious" "truck"'));
assertEquals(
['1997','Ford','E350','Super "luxurious""truck"'],
parser.parseLine('1997,Ford,E350,"Super ""luxurious""""truck"""'));
parser.parseLine('1997,Ford,E350,Super "luxurious""truck"'));
assertEquals(
['shared-library','/lib/ld-2.3.6.so','0x489a2000','0x489b7000'],
parser.parseLine('shared-library,"/lib/ld-2.3.6.so",0x489a2000,0x489b7000'));
parser.parseLine('shared-library,/lib/ld-2.3.6.so,0x489a2000,0x489b7000'));
assertEquals(
['code-creation','LazyCompile','0xf6fe2d20','1201','APPLY_PREPARE native runtime.js:165'],
parser.parseLine('code-creation,LazyCompile,0xf6fe2d20,1201,"APPLY_PREPARE native runtime.js:165"'));
parser.parseLine('code-creation,LazyCompile,0xf6fe2d20,1201,APPLY_PREPARE native runtime.js:165'));
assertEquals(
['code-creation','LazyCompile','0xf6fe4bc0','282',' native v8natives.js:69'],
parser.parseLine('code-creation,LazyCompile,0xf6fe4bc0,282," native v8natives.js:69"'));
parser.parseLine('code-creation,LazyCompile,0xf6fe4bc0,282, native v8natives.js:69'));
assertEquals(
['code-creation','RegExp','0xf6c21c00','826','NccyrJroXvg\\/([^,]*)'],
parser.parseLine('code-creation,RegExp,0xf6c21c00,826,"NccyrJroXvg\\/([^,]*)"'));
parser.parseLine('code-creation,RegExp,0xf6c21c00,826,NccyrJroXvg\\x5C/([^\\x2C]*)'));
assertEquals(
['code-creation','Function','0x42f0a0','163',''],
['code-creation','Function','0x42f0a0','163','""'],
parser.parseLine('code-creation,Function,0x42f0a0,163,""'));

File diff suppressed because it is too large Load Diff

View File

@ -1,11 +1,11 @@
shared-library,"shell",0x08048000,0x081ee000,0
shared-library,"/lib32/libm-2.7.so",0xf7db6000,0xf7dd9000,0
shared-library,"ffffe000-fffff000",0xffffe000,0xfffff000,0
profiler,"begin",1
code-creation,Stub,0,100,0x424260,348,"CompareStub_GE"
code-creation,LazyCompile,0,101,0x2a8100,18535,"DrawQube 3d-cube.js:188",0xf43abcac,
code-creation,LazyCompile,0,102,0x480100,3908,"DrawLine 3d-cube.js:17",0xf43abc50,
shared-library,shell,0x08048000,0x081ee000,0
shared-library,/lib32/libm-2.7.so,0xf7db6000,0xf7dd9000,0
shared-library,ffffe000-fffff000,0xffffe000,0xfffff000,0
profiler,begin,1
code-creation,Stub,0,100,0x424260,348,CompareStub_GE
code-creation,LazyCompile,0,101,0x2a8100,18535,DrawQube 3d-cube.js:188,0xf43abcac,
code-creation,LazyCompile,0,102,0x480100,3908,DrawLine 3d-cube.js:17,0xf43abc50,
tick,0x424284,0,0,0x480600,0,0x2aaaa5
tick,0x42429f,0,0,0x480600,0,0x2aacb4
tick,0x48063d,0,0,0x2d0f7c,0,0x2aaec6
profiler,"end"
profiler,end

View File

@ -1,14 +1,14 @@
shared-library,"shell",0x08048000,0x081ee000,0
shared-library,"/lib32/libm-2.7.so",0xf7db6000,0xf7dd9000,0
shared-library,"ffffe000-fffff000",0xffffe000,0xfffff000,0
profiler,"begin",1
code-creation,Stub,0,100,0xf540a100,474,"CEntryStub"
code-creation,Script,0,101,0xf541cd80,736,"exp.js"
code-creation,Stub,0,102,0xf541d0e0,47,"RuntimeStub_Math_exp"
code-creation,LazyCompile,0,103,0xf541d120,145,"exp native math.js:41"
shared-library,shell,0x08048000,0x081ee000,0
shared-library,/lib32/libm-2.7.so,0xf7db6000,0xf7dd9000,0
shared-library,ffffe000-fffff000,0xffffe000,0xfffff000,0
profiler,begin,1
code-creation,Stub,0,100,0xf540a100,474,CEntryStub
code-creation,Script,0,101,0xf541cd80,736,exp.js
code-creation,Stub,0,102,0xf541d0e0,47,RuntimeStub_Math_exp
code-creation,LazyCompile,0,103,0xf541d120,145,exp native math.js:41
function-creation,0xf441d280,0xf541d120
code-creation,LoadIC,0,104,0xf541d280,117,"j"
code-creation,LoadIC,0,105,0xf541d360,63,"i"
code-creation,LoadIC,0,104,0xf541d280,117,j
code-creation,LoadIC,0,105,0xf541d360,63,i
tick,0x80f82d1,0,0,0,0,0xf541ce5c
tick,0x80f89a1,0,0,0,0,0xf541ce5c
tick,0x8123b5c,0,0,0,0,0xf541d1a1,0xf541ceea
@ -22,4 +22,4 @@ tick,0xf7dbc508,0,0,0,0,0xf541d1a1,0xf541ceea
tick,0xf7dbff21,0,0,0,0,0xf541d1a1,0xf541ceea
tick,0xf7edec90,0,0,0,0,0xf541d1a1,0xf541ceea
tick,0xffffe402,0,0,0,0
profiler,"end"
profiler,end

View File

@ -29,50 +29,69 @@
/**
* Creates a CSV lines parser.
*/
function CsvParser() {
};
class CsvParser {
/**
* Converts \x00 and \u0000 escape sequences in the given string.
*
* @param {string} input field.
**/
escapeField(string) {
let nextPos = string.indexOf("\\");
if (nextPos === -1) return string;
/**
* A regex for matching a CSV field.
* @private
*/
CsvParser.CSV_FIELD_RE_ = /^"((?:[^"]|"")*)"|([^,]*)/;
/**
* A regex for matching a double quote.
* @private
*/
CsvParser.DOUBLE_QUOTE_RE_ = /""/g;
/**
* Parses a line of CSV-encoded values. Returns an array of fields.
*
* @param {string} line Input line.
*/
CsvParser.prototype.parseLine = function(line) {
var fieldRe = CsvParser.CSV_FIELD_RE_;
var doubleQuoteRe = CsvParser.DOUBLE_QUOTE_RE_;
var pos = 0;
var endPos = line.length;
var fields = [];
if (endPos > 0) {
do {
var fieldMatch = fieldRe.exec(line.substr(pos));
if (typeof fieldMatch[1] === "string") {
var field = fieldMatch[1];
pos += field.length + 3; // Skip comma and quotes.
fields.push(field.replace(doubleQuoteRe, '"'));
let result = string.substring(0, nextPos);
// Escape sequences of the form \x00 and \u0000;
let endPos = string.length;
let pos = 0;
while (nextPos !== -1) {
let escapeIdentifier = string.charAt(nextPos + 1);
pos = nextPos + 2;
if (escapeIdentifier == 'x') {
// \x00 ascii range escapes consume 2 chars.
nextPos = pos + 2;
} else {
// The second field pattern will match anything, thus
// in the worst case the match will be an empty string.
var field = fieldMatch[2];
pos += field.length + 1; // Skip comma.
fields.push(field);
// \u0000 unicode range escapes consume 4 chars.
nextPos = pos + 4;
}
} while (pos <= endPos);
// Convert the selected escape sequence to a single character.
let escapeChars = string.substring(pos, nextPos);
result += String.fromCharCode(parseInt(escapeChars, 16));
// Continue looking for the next escape sequence.
pos = nextPos;
nextPos = string.indexOf("\\", pos);
// If there are no more escape sequences consume the rest of the string.
if (nextPos === -1) {
result += string.substr(pos);
} else if (pos != nextPos) {
result += string.substring(pos, nextPos);
}
}
return result;
}
return fields;
};
/**
* Parses a line of CSV-encoded values. Returns an array of fields.
*
* @param {string} line Input line.
*/
parseLine(line) {
var pos = 0;
var endPos = line.length;
var fields = [];
if (endPos == 0) return fields;
let nextPos = 0;
while(nextPos !== -1) {
nextPos = line.indexOf(',', pos);
let field;
if (nextPos === -1) {
field = line.substr(pos);
} else {
field = line.substring(pos, nextPos);
}
fields.push(this.escapeField(field));
pos = nextPos + 1;
};
return fields
}
}