Skip to content

V
V8
Commit 6bf31c72 authored by Bret Sepulveda's avatar Bret Sepulveda Committed by Commit Bot
Browse files
Options

Refactor test-log.cc. 

This patch splits the log file into a vector of std::strings when
logging is stopped, so verifying that lines are present can be done in
terms of std library functions. Verifications are now done by simple
substring matching instead of via a prefix or suffix, in preparation for
a new test that needs to match the middle of a line.

This patch also deletes some dead/debugging code.

Change-Id: I5c6b75b0807c41312d35208deda26546dc0f7216
Reviewed-on: https://chromium-review.googlesource.com/1183187Reviewed-by: 's avatarCamillo Bruni <cbruni@chromium.org>
Commit-Queue: Bret Sepulveda <bsep@chromium.org>
Cr-Commit-Position: refs/heads/master@{#55281}
parent 1b3b808a
Show whitespace changes
Inline Side-by-side
Showing with 111 additions and 369 deletions
test/cctest/test-log.cc
View file @ 6bf31c72
...@@ -27,13 +27,6 @@ ...@@ -27,13 +27,6 @@
// //
// Tests of logging functions from log.h // Tests of logging functions from log.h
#ifdef __linux__
#include <pthread.h>
#include <signal.h>
#include <unistd.h>
#include <cmath>
#endif // __linux__
#include <unordered_set> #include <unordered_set>
#include <vector> #include <vector>
#include "src/api-inl.h" #include "src/api-inl.h"
...@@ -42,9 +35,7 @@ ...@@ -42,9 +35,7 @@
#include "src/objects-inl.h" #include "src/objects-inl.h"
#include "src/profiler/cpu-profiler.h" #include "src/profiler/cpu-profiler.h"
#include "src/snapshot/natives.h" #include "src/snapshot/natives.h"
#include "src/utils.h"
#include "src/v8.h" #include "src/v8.h"
#include "src/v8threads.h"
#include "src/version.h" #include "src/version.h"
#include "src/vm-state-inl.h" #include "src/vm-state-inl.h"
#include "test/cctest/cctest.h" #include "test/cctest/cctest.h"
...@@ -65,35 +56,14 @@ namespace { ...@@ -65,35 +56,14 @@ namespace {
i::FLAG_logfile = i::Log::kLogToTemporaryFile; \ i::FLAG_logfile = i::Log::kLogToTemporaryFile; \
i::FLAG_logfile_per_isolate = false i::FLAG_logfile_per_isolate = false
static const char* StrNStr(const char* s1, const char* s2, size_t n) { static std::vector<std::string> Split(const std::string& s, char delimiter) {
CHECK_EQ(s1[n], '\0'); std::vector<std::string> result;
return strstr(s1, s2); std::string line;
} std::istringstream stream(s);
while (std::getline(stream, line, delimiter)) {
// Look for a log line which starts with {prefix} and ends with {suffix}. result.push_back(line);
static const char* FindLogLine(const char* start, const char* end,
const char* prefix,
const char* suffix = nullptr) {
CHECK_LT(start, end);
CHECK_EQ(end[0], '\0');
size_t prefixLength = strlen(prefix);
// Loop through the input until we find /{prefix}[^\n]+{suffix}/.
while (start < end) {
const char* prefixResult = strstr(start, prefix);
if (!prefixResult) return NULL;
if (suffix == nullptr) return prefixResult;
const char* suffixResult =
StrNStr(prefixResult, suffix, (end - prefixResult));
if (!suffixResult) return NULL;
// Check that there are no newlines in between the {prefix} and the {suffix}
// results.
const char* newlineResult =
StrNStr(prefixResult, "\n", (end - prefixResult));
if (!newlineResult) return prefixResult;
if (newlineResult > suffixResult) return prefixResult;
start = prefixResult + prefixLength;
} }
return NULL; return result;
} }
class ScopedLoggerInitializer { class ScopedLoggerInitializer {
...@@ -126,85 +96,72 @@ class ScopedLoggerInitializer { ...@@ -126,85 +96,72 @@ class ScopedLoggerInitializer {
Logger* logger() { return logger_; } Logger* logger() { return logger_; }
void PrintLog(int requested_nof_lines = 0, const char* start = nullptr) {
if (requested_nof_lines <= 0) {
printf("%s", log_.c_str());
return;
}
// Try to print the last {requested_nof_lines} of the log.
if (start == nullptr) start = log_.c_str();
const char* current = start + log_.length();
int nof_lines = requested_nof_lines;
while (current > start && nof_lines > 0) {
current--;
if (*current == '\n') nof_lines--;
}
printf(
"======================================================\n"
"Last %i log lines:\n"
"======================================================\n"
"...\n%s\n"
"======================================================\n",
requested_nof_lines, current);
}
v8::Local<v8::String> GetLogString() { v8::Local<v8::String> GetLogString() {
int length = static_cast<int>(log_.size()); int length = static_cast<int>(raw_log_.size());
return v8::String::NewFromUtf8(isolate_, log_.c_str(), return v8::String::NewFromUtf8(isolate_, raw_log_.c_str(),
v8::NewStringType::kNormal, length) v8::NewStringType::kNormal, length)
.ToLocalChecked(); .ToLocalChecked();
} }
void StopLogging() { void StopLogging() {
bool exists = false; bool exists = false;
log_ = i::ReadFile(StopLoggingGetTempFile(), &exists, true); raw_log_ = i::ReadFile(StopLoggingGetTempFile(), &exists, true);
log_ = Split(raw_log_, '\n');
CHECK(exists); CHECK(exists);
} }
const char* GetEndPosition() { return log_.c_str() + log_.size(); } // Searches |log_| for a line which contains all the strings in |search_terms|
// as substrings, starting from the index |start|, and returns the index of
const char* FindLine(const char* prefix, const char* suffix = nullptr, // the found line. Returns std::string::npos if no line is found.
const char* start = nullptr) { size_t IndexOfLine(const std::vector<std::string>& search_terms,
// Make sure that StopLogging() has been called before. size_t start = 0) {
CHECK(log_.size()); for (size_t i = start; i < log_.size(); ++i) {
if (start == nullptr) start = log_.c_str(); const std::string& line = log_.at(i);
const char* end = GetEndPosition(); bool all_terms_found = true;
return FindLogLine(start, end, prefix, suffix); for (const std::string& term : search_terms) {
all_terms_found &= line.find(term) != std::string::npos;
}
if (all_terms_found) return i;
}
return std::string::npos;
} }
// Find all log lines specified by the {prefix, suffix} pairs and ensure they bool ContainsLine(const std::vector<std::string>& search_terms,
// occurr in the specified order. size_t start = 0) {
void FindLogLines(const char* pairs[][2], size_t limit, return IndexOfLine(search_terms, start) != std::string::npos;
const char* start = nullptr) {
const char* prefix = pairs[0][0];
const char* suffix = pairs[0][1];
const char* last_position = FindLine(prefix, suffix, start);
if (last_position == nullptr) {
PrintLog(100, start);
V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s", prefix,
suffix);
} }
CHECK(last_position);
for (size_t i = 1; i < limit; i++) { // Calls IndexOfLine for each set of substring terms in
prefix = pairs[i][0]; // |all_line_search_terms|, in order. Returns true if they're all found.
suffix = pairs[i][1]; bool ContainsLinesInOrder(
const char* position = FindLine(prefix, suffix, start); const std::vector<std::vector<std::string>>& all_line_search_terms,
if (position == nullptr) { size_t start = 0) {
PrintLog(100, start); CHECK_GT(log_.size(), 0);
V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s", for (auto& search_terms : all_line_search_terms) {
prefix, suffix); start = IndexOfLine(search_terms, start);
if (start == std::string::npos) return false;
++start; // Skip the found line.
} }
// Check that all string positions are in order. return true;
if (position <= last_position) {
PrintLog(100, start);
V8_Fatal(__FILE__, __LINE__,
"Log statements not in expected order (prev=%p, current=%p): "
"%s ... %s",
reinterpret_cast<const void*>(last_position),
reinterpret_cast<const void*>(position), prefix, suffix);
} }
last_position = position;
std::unordered_set<uintptr_t> ExtractAllAddresses(std::string search_term,
size_t address_column) {
CHECK_GT(log_.size(), 0);
std::unordered_set<uintptr_t> result;
size_t start = 0;
while (true) {
start = IndexOfLine({search_term}, start);
if (start == std::string::npos) break;
std::vector<std::string> columns = Split(log_.at(start), ',');
CHECK_LT(address_column, columns.size());
uintptr_t address =
strtoll(columns.at(address_column).c_str(), nullptr, 16);
CHECK_GT(address, 0);
result.insert(address);
++start; // Skip the found line.
} }
return result;
} }
void LogCompiledFunctions() { logger_->LogCompiledFunctions(); } void LogCompiledFunctions() { logger_->LogCompiledFunctions(); }
...@@ -213,30 +170,6 @@ class ScopedLoggerInitializer { ...@@ -213,30 +170,6 @@ class ScopedLoggerInitializer {
logger_->StringEvent(name, value); logger_->StringEvent(name, value);
} }
void ExtractAllAddresses(std::unordered_set<uintptr_t>* map,
const char* prefix, int field_index) {
// Make sure that StopLogging() has been called before.
CHECK(log_.size());
const char* current = log_.c_str();
while (current != nullptr) {
current = FindLine(prefix, nullptr, current);
if (current == nullptr) return;
// Find token number {index}.
const char* previous;
for (int i = 0; i <= field_index; i++) {
previous = current;
current = strchr(current + 1, ',');
if (current == nullptr) break;
// Skip the comma.
current++;
}
if (current == nullptr) break;
uintptr_t address = strtoll(previous, nullptr, 16);
CHECK_LT(0, address);
map->insert(address);
}
}
private: private:
FILE* StopLoggingGetTempFile() { FILE* StopLoggingGetTempFile() {
temp_file_ = logger_->TearDown(); temp_file_ = logger_->TearDown();
...@@ -254,7 +187,9 @@ class ScopedLoggerInitializer { ...@@ -254,7 +187,9 @@ class ScopedLoggerInitializer {
v8::HandleScope scope_; v8::HandleScope scope_;
v8::Local<v8::Context> env_; v8::Local<v8::Context> env_;
Logger* logger_; Logger* logger_;
std::string log_;
std::string raw_log_;
std::vector<std::string> log_;
DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer);
}; };
...@@ -265,10 +200,10 @@ class TestCodeEventHandler : public v8::CodeEventHandler { ...@@ -265,10 +200,10 @@ class TestCodeEventHandler : public v8::CodeEventHandler {
: v8::CodeEventHandler(isolate), isolate_(isolate) {} : v8::CodeEventHandler(isolate), isolate_(isolate) {}
size_t CountLines(std::string prefix, std::string suffix = std::string()) { size_t CountLines(std::string prefix, std::string suffix = std::string()) {
if (log_.empty()) return 0; if (event_log_.empty()) return 0;
size_t match = 0; size_t match = 0;
for (const std::string& line : log_) { for (const std::string& line : event_log_) {
size_t prefix_pos = line.find(prefix); size_t prefix_pos = line.find(prefix);
if (prefix_pos == std::string::npos) continue; if (prefix_pos == std::string::npos) continue;
size_t suffix_pos = line.rfind(suffix); size_t suffix_pos = line.rfind(suffix);
...@@ -286,7 +221,7 @@ class TestCodeEventHandler : public v8::CodeEventHandler { ...@@ -286,7 +221,7 @@ class TestCodeEventHandler : public v8::CodeEventHandler {
log_line += v8::CodeEvent::GetCodeEventTypeName(code_event->GetCodeType()); log_line += v8::CodeEvent::GetCodeEventTypeName(code_event->GetCodeType());
log_line += " "; log_line += " ";
log_line += FormatName(code_event); log_line += FormatName(code_event);
log_.push_back(log_line); event_log_.push_back(log_line);
} }
private: private:
...@@ -304,195 +239,12 @@ class TestCodeEventHandler : public v8::CodeEventHandler { ...@@ -304,195 +239,12 @@ class TestCodeEventHandler : public v8::CodeEventHandler {
return name; return name;
} }
std::vector<std::string> log_; std::vector<std::string> event_log_;
v8::Isolate* isolate_; v8::Isolate* isolate_;
}; };
} // namespace } // namespace
TEST(FindLogLine) {
const char* string =
"prefix1, stuff, suffix1\n"
"prefix2, stuff\n, suffix2\n"
"prefix3suffix3\n"
"prefix4 suffix4";
const char* end = string + strlen(string);
// Make sure the vector contains the terminating \0 character.
CHECK(FindLogLine(string, end, "prefix1, stuff, suffix1"));
CHECK(FindLogLine(string, end, "prefix1, stuff"));
CHECK(FindLogLine(string, end, "prefix1"));
CHECK(FindLogLine(string, end, "prefix1", "suffix1"));
CHECK(FindLogLine(string, end, "prefix1", "suffix1"));
CHECK(!FindLogLine(string, end, "prefix2", "suffix2"));
CHECK(!FindLogLine(string, end, "prefix1", "suffix2"));
CHECK(!FindLogLine(string, end, "prefix1", "suffix3"));
CHECK(FindLogLine(string, end, "prefix3", "suffix3"));
CHECK(FindLogLine(string, end, "prefix4", "suffix4"));
CHECK(!FindLogLine(string, end, "prefix4", "suffix4XXXXXXXXXXXX"));
CHECK(
!FindLogLine(string, end, "prefix4XXXXXXXXXXXXXXXXXXXXXXxxx", "suffix4"));
CHECK(!FindLogLine(string, end, "suffix", "suffix5XXXXXXXXXXXXXXXXXXXX"));
}
// BUG(913). Need to implement support for profiling multiple VM threads.
#if 0
namespace {
class LoopingThread : public v8::internal::Thread {
public:
explicit LoopingThread(v8::internal::Isolate* isolate)
: v8::internal::Thread(isolate),
semaphore_(new v8::internal::Semaphore(0)),
run_(true) {
}
virtual ~LoopingThread() { delete semaphore_; }
void Run() {
self_ = pthread_self();
RunLoop();
}
void SendSigProf() { pthread_kill(self_, SIGPROF); }
void Stop() { run_ = false; }
bool WaitForRunning() { return semaphore_->Wait(1000000); }
protected:
bool IsRunning() { return run_; }
virtual void RunLoop() = 0;
void SetV8ThreadId() {
v8_thread_id_ = v8::V8::GetCurrentThreadId();
}
void SignalRunning() { semaphore_->Signal(); }
private:
v8::internal::Semaphore* semaphore_;
bool run_;
pthread_t self_;
int v8_thread_id_;
};
class LoopingJsThread : public LoopingThread {
public:
explicit LoopingJsThread(v8::internal::Isolate* isolate)
: LoopingThread(isolate) { }
void RunLoop() {
v8::Locker locker;
CHECK_NOT_NULL(CcTest::i_isolate());
CHECK_GT(CcTest::i_isolate()->thread_manager()->CurrentId(), 0);
SetV8ThreadId();
while (IsRunning()) {
v8::HandleScope scope;
v8::Persistent<v8::Context> context = v8::Context::New();
CHECK(!context.IsEmpty());
{
v8::Context::Scope context_scope(context);
SignalRunning();
CompileRun(
"var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }");
}
context.Dispose();
i::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(1));
}
}
};
class LoopingNonJsThread : public LoopingThread {
public:
explicit LoopingNonJsThread(v8::internal::Isolate* isolate)
: LoopingThread(isolate) { }
void RunLoop() {
v8::Locker locker;
v8::Unlocker unlocker;
// Now thread has V8's id, but will not run VM code.
CHECK_NOT_NULL(CcTest::i_isolate());
CHECK_GT(CcTest::i_isolate()->thread_manager()->CurrentId(), 0);
double i = 10;
SignalRunning();
while (IsRunning()) {
i = std::sin(i);
i::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(1));
}
}
};
class TestSampler : public v8::internal::Sampler {
public:
explicit TestSampler(v8::internal::Isolate* isolate)
: Sampler(isolate, 0, true, true),
semaphore_(new v8::internal::Semaphore(0)),
was_sample_stack_called_(false) {
}
~TestSampler() { delete semaphore_; }
void SampleStack(v8::internal::TickSample*) {
was_sample_stack_called_ = true;
}
void Tick(v8::internal::TickSample*) { semaphore_->Signal(); }
bool WaitForTick() { return semaphore_->Wait(1000000); }
void Reset() { was_sample_stack_called_ = false; }
bool WasSampleStackCalled() { return was_sample_stack_called_; }
private:
v8::internal::Semaphore* semaphore_;
bool was_sample_stack_called_;
};
} // namespace
TEST(ProfMultipleThreads) {
TestSampler* sampler = nullptr;
{
v8::Locker locker;
sampler = new TestSampler(CcTest::i_isolate());
sampler->Start();
CHECK(sampler->IsActive());
}
LoopingJsThread jsThread(CcTest::i_isolate());
jsThread.Start();
LoopingNonJsThread nonJsThread(CcTest::i_isolate());
nonJsThread.Start();
CHECK(!sampler->WasSampleStackCalled());
jsThread.WaitForRunning();
jsThread.SendSigProf();
CHECK(sampler->WaitForTick());
CHECK(sampler->WasSampleStackCalled());
sampler->Reset();
CHECK(!sampler->WasSampleStackCalled());
nonJsThread.WaitForRunning();
nonJsThread.SendSigProf();
CHECK(!sampler->WaitForTick());
CHECK(!sampler->WasSampleStackCalled());
sampler->Stop();
jsThread.Stop();
nonJsThread.Stop();
jsThread.Join();
nonJsThread.Join();
delete sampler;
}
#endif // __linux__
// Test for issue http://crbug.com/23768 in Chromium. // Test for issue http://crbug.com/23768 in Chromium.
// Heap can contain scripts with already disposed external sources. // Heap can contain scripts with already disposed external sources.
// We need to verify that LogCompiledFunctions doesn't crash on them. // We need to verify that LogCompiledFunctions doesn't crash on them.
...@@ -542,11 +294,9 @@ TEST(Issue23768) { ...@@ -542,11 +294,9 @@ TEST(Issue23768) {
CcTest::i_isolate()->logger()->LogCompiledFunctions(); CcTest::i_isolate()->logger()->LogCompiledFunctions();
} }
static void ObjMethod1(const v8::FunctionCallbackInfo<v8::Value>& args) { static void ObjMethod1(const v8::FunctionCallbackInfo<v8::Value>& args) {
} }
TEST(LogCallbacks) { TEST(LogCallbacks) {
SETUP_FLAGS(); SETUP_FLAGS();
v8::Isolate::CreateParams create_params; v8::Isolate::CreateParams create_params;
...@@ -573,21 +323,20 @@ TEST(LogCallbacks) { ...@@ -573,21 +323,20 @@ TEST(LogCallbacks) {
CompileRun("Obj.prototype.method1.toString();"); CompileRun("Obj.prototype.method1.toString();");
logger.LogCompiledFunctions(); logger.LogCompiledFunctions();
logger.StopLogging(); logger.StopLogging();
Address ObjMethod1_entry = reinterpret_cast<Address>(ObjMethod1); Address ObjMethod1_entry = reinterpret_cast<Address>(ObjMethod1);
#if USES_FUNCTION_DESCRIPTORS #if USES_FUNCTION_DESCRIPTORS
ObjMethod1_entry = *FUNCTION_ENTRYPOINT_ADDRESS(ObjMethod1_entry); ObjMethod1_entry = *FUNCTION_ENTRYPOINT_ADDRESS(ObjMethod1_entry);
#endif #endif
i::EmbeddedVector<char, 100> ref_data; i::EmbeddedVector<char, 100> suffix_buffer;
i::SNPrintF(ref_data, ",0x%" V8PRIxPTR ",1,method1", ObjMethod1_entry); i::SNPrintF(suffix_buffer, ",0x%" V8PRIxPTR ",1,method1", ObjMethod1_entry);
CHECK(logger.FindLine("code-creation,Callback,-2,", ref_data.start())); CHECK(logger.ContainsLine(
{"code-creation,Callback,-2,", std::string(suffix_buffer.start())}));
} }
isolate->Dispose(); isolate->Dispose();
} }
static void Prop1Getter(v8::Local<v8::String> property, static void Prop1Getter(v8::Local<v8::String> property,
const v8::PropertyCallbackInfo<v8::Value>& info) { const v8::PropertyCallbackInfo<v8::Value>& info) {
} }
...@@ -601,7 +350,6 @@ static void Prop2Getter(v8::Local<v8::String> property, ...@@ -601,7 +350,6 @@ static void Prop2Getter(v8::Local<v8::String> property,
const v8::PropertyCallbackInfo<v8::Value>& info) { const v8::PropertyCallbackInfo<v8::Value>& info) {
} }
TEST(LogAccessorCallbacks) { TEST(LogAccessorCallbacks) {
SETUP_FLAGS(); SETUP_FLAGS();
v8::Isolate::CreateParams create_params; v8::Isolate::CreateParams create_params;
...@@ -628,8 +376,8 @@ TEST(LogAccessorCallbacks) { ...@@ -628,8 +376,8 @@ TEST(LogAccessorCallbacks) {
EmbeddedVector<char, 100> prop1_getter_record; 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",
Prop1Getter_entry); Prop1Getter_entry);
CHECK(logger.FindLine("code-creation,Callback,-2,", CHECK(logger.ContainsLine({"code-creation,Callback,-2,",
prop1_getter_record.start())); std::string(prop1_getter_record.start())}));
Address Prop1Setter_entry = reinterpret_cast<Address>(Prop1Setter); Address Prop1Setter_entry = reinterpret_cast<Address>(Prop1Setter);
#if USES_FUNCTION_DESCRIPTORS #if USES_FUNCTION_DESCRIPTORS
...@@ -638,8 +386,8 @@ TEST(LogAccessorCallbacks) { ...@@ -638,8 +386,8 @@ TEST(LogAccessorCallbacks) {
EmbeddedVector<char, 100> prop1_setter_record; 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",
Prop1Setter_entry); Prop1Setter_entry);
CHECK(logger.FindLine("code-creation,Callback,-2,", CHECK(logger.ContainsLine({"code-creation,Callback,-2,",
prop1_setter_record.start())); std::string(prop1_setter_record.start())}));
Address Prop2Getter_entry = reinterpret_cast<Address>(Prop2Getter); Address Prop2Getter_entry = reinterpret_cast<Address>(Prop2Getter);
#if USES_FUNCTION_DESCRIPTORS #if USES_FUNCTION_DESCRIPTORS
...@@ -648,8 +396,8 @@ TEST(LogAccessorCallbacks) { ...@@ -648,8 +396,8 @@ TEST(LogAccessorCallbacks) {
EmbeddedVector<char, 100> prop2_getter_record; 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",
Prop2Getter_entry); Prop2Getter_entry);
CHECK(logger.FindLine("code-creation,Callback,-2,", CHECK(logger.ContainsLine({"code-creation,Callback,-2,",
prop2_getter_record.start())); std::string(prop2_getter_record.start())}));
} }
isolate->Dispose(); isolate->Dispose();
} }
...@@ -734,11 +482,12 @@ TEST(LogVersion) { ...@@ -734,11 +482,12 @@ TEST(LogVersion) {
ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
logger.StopLogging(); logger.StopLogging();
i::EmbeddedVector<char, 100> ref_data; i::EmbeddedVector<char, 100> line_buffer;
i::SNPrintF(ref_data, "%d,%d,%d,%d,%d", i::Version::GetMajor(), i::SNPrintF(line_buffer, "%d,%d,%d,%d,%d", i::Version::GetMajor(),
i::Version::GetMinor(), i::Version::GetBuild(), i::Version::GetMinor(), i::Version::GetBuild(),
i::Version::GetPatch(), i::Version::IsCandidate()); i::Version::GetPatch(), i::Version::IsCandidate());
CHECK(logger.FindLine("v8-version,", ref_data.start())); CHECK(
logger.ContainsLine({"v8-version,", std::string(line_buffer.start())}));
} }
isolate->Dispose(); isolate->Dispose();
} }
...@@ -811,7 +560,6 @@ TEST(LogAll) { ...@@ -811,7 +560,6 @@ TEST(LogAll) {
{ {
ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
// Function that will
const char* source_text = const char* source_text =
"function testAddFn(a,b) { return a + b };" "function testAddFn(a,b) { return a + b };"
"let result;" "let result;"
...@@ -823,16 +571,16 @@ TEST(LogAll) { ...@@ -823,16 +571,16 @@ TEST(LogAll) {
logger.StopLogging(); logger.StopLogging();
// We should find at least one code-creation even for testAddFn(); // We should find at least one code-creation even for testAddFn();
CHECK(logger.FindLine("api,v8::Context::New")); CHECK(logger.ContainsLine({"api,v8::Context::New"}));
CHECK(logger.FindLine("timer-event-start", "V8.CompileCode")); CHECK(logger.ContainsLine({"timer-event-start", "V8.CompileCode"}));
CHECK(logger.FindLine("timer-event-end", "V8.CompileCode")); CHECK(logger.ContainsLine({"timer-event-end", "V8.CompileCode"}));
CHECK(logger.FindLine("code-creation,Script", ":1:1")); CHECK(logger.ContainsLine({"code-creation,Script", ":1:1"}));
CHECK(logger.FindLine("api,v8::Script::Run")); CHECK(logger.ContainsLine({"api,v8::Script::Run"}));
CHECK(logger.FindLine("code-creation,LazyCompile,", "testAddFn")); CHECK(logger.ContainsLine({"code-creation,LazyCompile,", "testAddFn"}));
if (i::FLAG_opt && !i::FLAG_always_opt) { if (i::FLAG_opt && !i::FLAG_always_opt) {
CHECK(logger.FindLine("code-deopt,", "soft")); CHECK(logger.ContainsLine({"code-deopt,", "soft"}));
CHECK(logger.FindLine("timer-event-start", "V8.DeoptimizeCode")); CHECK(logger.ContainsLine({"timer-event-start", "V8.DeoptimizeCode"}));
CHECK(logger.FindLine("timer-event-end", "V8.DeoptimizeCode")); CHECK(logger.ContainsLine({"timer-event-end", "V8.DeoptimizeCode"}));
} }
} }
isolate->Dispose(); isolate->Dispose();
...@@ -855,8 +603,8 @@ TEST(LogInterpretedFramesNativeStack) { ...@@ -855,8 +603,8 @@ TEST(LogInterpretedFramesNativeStack) {
logger.StopLogging(); logger.StopLogging();
CHECK(logger.FindLine("InterpretedFunction", CHECK(logger.ContainsLine(
"testLogInterpretedFramesNativeStack")); {"InterpretedFunction", "testLogInterpretedFramesNativeStack"}));
} }
isolate->Dispose(); isolate->Dispose();
} }
...@@ -979,9 +727,9 @@ TEST(TraceMaps) { ...@@ -979,9 +727,9 @@ TEST(TraceMaps) {
logger.StopLogging(); logger.StopLogging();
// Mostly superficial checks. // Mostly superficial checks.
CHECK(logger.FindLine("map,InitialMap", ",0x")); CHECK(logger.ContainsLine({"map,InitialMap", ",0x"}));
CHECK(logger.FindLine("map,Transition", ",0x")); CHECK(logger.ContainsLine({"map,Transition", ",0x"}));
CHECK(logger.FindLine("map-details", ",0x")); CHECK(logger.ContainsLine({"map-details", ",0x"}));
} }
i::FLAG_trace_maps = false; i::FLAG_trace_maps = false;
isolate->Dispose(); isolate->Dispose();
...@@ -997,9 +745,8 @@ TEST(LogMaps) { ...@@ -997,9 +745,8 @@ TEST(LogMaps) {
{ {
ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
logger.StopLogging(); logger.StopLogging();
// Extract all the map-detail entry addresses from the log. std::unordered_set<uintptr_t> map_addresses =
std::unordered_set<uintptr_t> map_addresses; logger.ExtractAllAddresses("map-details", 2);
logger.ExtractAllAddresses(&map_addresses, "map-details", 2);
i::Heap* heap = reinterpret_cast<i::Isolate*>(isolate)->heap(); i::Heap* heap = reinterpret_cast<i::Isolate*>(isolate)->heap();
i::HeapIterator iterator(heap); i::HeapIterator iterator(heap);
i::DisallowHeapAllocation no_gc; i::DisallowHeapAllocation no_gc;
...@@ -1012,15 +759,12 @@ TEST(LogMaps) { ...@@ -1012,15 +759,12 @@ TEST(LogMaps) {
if (!obj->IsMap()) continue; if (!obj->IsMap()) continue;
uintptr_t address = reinterpret_cast<uintptr_t>(obj); uintptr_t address = reinterpret_cast<uintptr_t>(obj);
if (map_addresses.find(address) != map_addresses.end()) continue; if (map_addresses.find(address) != map_addresses.end()) continue;
logger.PrintLog(200);
i::Map::cast(obj)->Print(); i::Map::cast(obj)->Print();
V8_Fatal(__FILE__, __LINE__, V8_Fatal(__FILE__, __LINE__,
"Map (%p, #%zu) was not logged during startup with --trace-maps!" "Map (%p, #%zu) was not logged during startup with --trace-maps!"
"\n# Expected Log Line: map_details, ... %p" "\n# Expected Log Line: map_details, ... %p",
"\n# Use logger::PrintLog() for more details.",
reinterpret_cast<void*>(obj), i, reinterpret_cast<void*>(obj)); reinterpret_cast<void*>(obj), i, reinterpret_cast<void*>(obj));
} }
logger.PrintLog(200);
} }
i::FLAG_log_function_events = false; i::FLAG_log_function_events = false;
isolate->Dispose(); isolate->Dispose();
...@@ -1046,14 +790,12 @@ TEST(ConsoleTimeEvents) { ...@@ -1046,14 +790,12 @@ TEST(ConsoleTimeEvents) {
logger.StopLogging(); logger.StopLogging();
const char* pairs[][2] = {{"timer-event-start,default,", nullptr}, std::vector<std::vector<std::string>> lines = {
{"timer-event-end,default,", nullptr}, {"timer-event-start,default,"}, {"timer-event-end,default,"},
{"timer-event,default,", nullptr}, {"timer-event,default,"}, {"timer-event-start,timerEvent1,"},
{"timer-event-start,timerEvent1,", nullptr}, {"timer-event-end,timerEvent1,"}, {"timer-event,timerEvent2,"},
{"timer-event-end,timerEvent1,", nullptr}, {"timer-event,timerEvent3,"}};
{"timer-event,timerEvent2,", nullptr}, CHECK(logger.ContainsLinesInOrder(lines));
{"timer-event,timerEvent3,", nullptr}};
logger.FindLogLines(pairs, arraysize(pairs));
} }
isolate->Dispose(); isolate->Dispose();
...@@ -1097,13 +839,13 @@ TEST(LogFunctionEvents) { ...@@ -1097,13 +839,13 @@ TEST(LogFunctionEvents) {
logger.StopLogging(); logger.StopLogging();
// Ignore all the log entries that happened before warmup // Ignore all the log entries that happened before warmup
const char* start = size_t start = logger.IndexOfLine(
logger.FindLine("function,first-execution", "warmUpEndMarkerFunction"); {"function,first-execution", "warmUpEndMarkerFunction"});
CHECK_NOT_NULL(start); CHECK(start != std::string::npos);
const char* pairs[][2] = { std::vector<std::vector<std::string>> lines = {
// Create a new script // Create a new script
{"script,create", nullptr}, {"script,create"},
{"script-details", nullptr}, {"script-details"},
// Step 1: parsing top-level script, preparsing functions // Step 1: parsing top-level script, preparsing functions
{"function,preparse-", ",lazyNotExecutedFunction"}, {"function,preparse-", ",lazyNotExecutedFunction"},
// Missing name for preparsing lazyInnerFunction // Missing name for preparsing lazyInnerFunction
...@@ -1114,11 +856,11 @@ TEST(LogFunctionEvents) { ...@@ -1114,11 +856,11 @@ TEST(LogFunctionEvents) {
// Missing name for inner preparsing of Foo.foo // Missing name for inner preparsing of Foo.foo
// {"function,preparse-", nullptr}, // {"function,preparse-", nullptr},
// Missing name for top-level script. // Missing name for top-level script.
{"function,parse-script,", nullptr}, {"function,parse-script,"},
// Step 2: compiling top-level script and eager functions // Step 2: compiling top-level script and eager functions
// - Compiling script without name. // - Compiling script without name.
{"function,compile,", nullptr}, {"function,compile,"},
{"function,compile,", ",eagerFunction"}, {"function,compile,", ",eagerFunction"},
// Step 3: start executing script // Step 3: start executing script
...@@ -1142,7 +884,7 @@ TEST(LogFunctionEvents) { ...@@ -1142,7 +884,7 @@ TEST(LogFunctionEvents) {
{"function,compile-lazy,", ",Foo.foo"}, {"function,compile-lazy,", ",Foo.foo"},
{"function,first-execution,", ",Foo.foo"}, {"function,first-execution,", ",Foo.foo"},
}; };
logger.FindLogLines(pairs, arraysize(pairs), start); CHECK(logger.ContainsLinesInOrder(lines, start));
} }
i::FLAG_log_function_events = false; i::FLAG_log_function_events = false;
isolate->Dispose(); isolate->Dispose();
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment