Revision: 3889
Author: [email protected]
Date: Wed Feb 17 05:23:46 2010
Log: Implement tagging of profiler log event blocks.
This change allows to associate integer tags with blocks of profiler
log events, and repeat calls to 'ResumeProfiler' / 'PauseProfiler' in
order to establsh nested (not necessary properly nested) blocks. By
supporting this, we will be able to match WebInspector's CPU profiler
abilities in DevTools.
I also refactored some testing code.
Review URL: http://codereview.chromium.org/619004
http://code.google.com/p/v8/source/detail?r=3889
Modified:
/branches/bleeding_edge/include/v8.h
/branches/bleeding_edge/src/api.cc
/branches/bleeding_edge/src/checks.h
/branches/bleeding_edge/src/debug-delay.js
/branches/bleeding_edge/src/log.cc
/branches/bleeding_edge/src/log.h
/branches/bleeding_edge/src/runtime.cc
/branches/bleeding_edge/src/runtime.h
/branches/bleeding_edge/test/cctest/test-log.cc
=======================================
--- /branches/bleeding_edge/include/v8.h Tue Feb 16 07:15:31 2010
+++ /branches/bleeding_edge/include/v8.h Wed Feb 17 05:23:46 2010
@@ -2349,22 +2349,30 @@
static bool IsProfilerPaused();
/**
- * Resumes specified profiler modules.
+ * Resumes specified profiler modules. Can be called several times to
+ * mark the opening of a profiler events block with the given tag.
+ *
* "ResumeProfiler" is equivalent
to "ResumeProfilerEx(PROFILER_MODULE_CPU)".
* See ProfilerModules enum.
*
* \param flags Flags specifying profiler modules.
+ * \param tag Profile tag.
*/
- static void ResumeProfilerEx(int flags);
+ static void ResumeProfilerEx(int flags, int tag = 0);
/**
- * Pauses specified profiler modules.
+ * Pauses specified profiler modules. Each call to "PauseProfilerEx"
closes
+ * a block of profiler events opened by a call to "ResumeProfilerEx"
with the
+ * same tag value. There is no need for blocks to be properly nested.
+ * The profiler is paused when the last opened block is closed.
+ *
* "PauseProfiler" is equivalent
to "PauseProfilerEx(PROFILER_MODULE_CPU)".
* See ProfilerModules enum.
*
* \param flags Flags specifying profiler modules.
+ * \param tag Profile tag.
*/
- static void PauseProfilerEx(int flags);
+ static void PauseProfilerEx(int flags, int tag = 0);
/**
* Returns active (resumed) profiler modules.
=======================================
--- /branches/bleeding_edge/src/api.cc Tue Feb 16 10:56:07 2010
+++ /branches/bleeding_edge/src/api.cc Wed Feb 17 05:23:46 2010
@@ -3469,14 +3469,14 @@
void V8::PauseProfiler() {
#ifdef ENABLE_LOGGING_AND_PROFILING
- i::Logger::PauseProfiler(PROFILER_MODULE_CPU);
+ PauseProfilerEx(PROFILER_MODULE_CPU);
#endif
}
void V8::ResumeProfiler() {
#ifdef ENABLE_LOGGING_AND_PROFILING
- i::Logger::ResumeProfiler(PROFILER_MODULE_CPU);
+ ResumeProfilerEx(PROFILER_MODULE_CPU);
#endif
}
@@ -3490,7 +3490,7 @@
}
-void V8::ResumeProfilerEx(int flags) {
+void V8::ResumeProfilerEx(int flags, int tag) {
#ifdef ENABLE_LOGGING_AND_PROFILING
if (flags & PROFILER_MODULE_HEAP_SNAPSHOT) {
// Snapshot mode: resume modules, perform GC, then pause only
@@ -3500,19 +3500,19 @@
// Reset snapshot flag and CPU module flags.
flags &= ~(PROFILER_MODULE_HEAP_SNAPSHOT | PROFILER_MODULE_CPU);
const int current_flags = i::Logger::GetActiveProfilerModules();
- i::Logger::ResumeProfiler(flags);
+ i::Logger::ResumeProfiler(flags, tag);
i::Heap::CollectAllGarbage(false);
- i::Logger::PauseProfiler(~current_flags & flags);
+ i::Logger::PauseProfiler(~current_flags & flags, tag);
} else {
- i::Logger::ResumeProfiler(flags);
+ i::Logger::ResumeProfiler(flags, tag);
}
#endif
}
-void V8::PauseProfilerEx(int flags) {
+void V8::PauseProfilerEx(int flags, int tag) {
#ifdef ENABLE_LOGGING_AND_PROFILING
- i::Logger::PauseProfiler(flags);
+ i::Logger::PauseProfiler(flags, tag);
#endif
}
=======================================
--- /branches/bleeding_edge/src/checks.h Thu Oct 8 05:54:29 2009
+++ /branches/bleeding_edge/src/checks.h Wed Feb 17 05:23:46 2010
@@ -125,7 +125,9 @@
const char* expected,
const char* value_source,
const char* value) {
- if (strcmp(expected, value) != 0) {
+ if ((expected == NULL && value != NULL) ||
+ (expected != NULL && value == NULL) ||
+ (expected != NULL && value != NULL && strcmp(expected, value) != 0))
{
V8_Fatal(file, line,
"CHECK_EQ(%s, %s) failed\n# Expected: %s\n# Found: %s",
expected_source, value_source, expected, value);
=======================================
--- /branches/bleeding_edge/src/debug-delay.js Thu Jan 21 09:41:17 2010
+++ /branches/bleeding_edge/src/debug-delay.js Wed Feb 17 05:23:46 2010
@@ -1934,10 +1934,14 @@
if (isNaN(modules)) {
return response.failed('Modules is not an integer');
}
+ var tag = parseInt(request.arguments.tag);
+ if (isNaN(tag)) {
+ tag = 0;
+ }
if (request.arguments.command == 'resume') {
- %ProfilerResume(modules);
+ %ProfilerResume(modules, tag);
} else if (request.arguments.command == 'pause') {
- %ProfilerPause(modules);
+ %ProfilerPause(modules, tag);
} else {
return response.failed('Unknown command');
}
=======================================
--- /branches/bleeding_edge/src/log.cc Fri Feb 5 05:07:00 2010
+++ /branches/bleeding_edge/src/log.cc Wed Feb 17 05:23:46 2010
@@ -330,6 +330,8 @@
const char** Logger::log_events_ = NULL;
CompressionHelper* Logger::compression_helper_ = NULL;
bool Logger::is_logging_ = false;
+int Logger::cpu_profiler_nesting_ = 0;
+int Logger::heap_profiler_nesting_ = 0;
#define DECLARE_LONG_EVENT(ignore1, long_name, ignore2) long_name,
const char* kLongLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = {
@@ -1164,53 +1166,61 @@
}
-void Logger::PauseProfiler(int flags) {
+void Logger::PauseProfiler(int flags, int tag) {
if (!Log::IsEnabled()) return;
- const int active_modules = GetActiveProfilerModules();
- const int modules_to_disable = active_modules & flags;
- if (modules_to_disable == PROFILER_MODULE_NONE) return;
-
- if (modules_to_disable & PROFILER_MODULE_CPU) {
- profiler_->pause();
- if (FLAG_prof_lazy) {
- if (!FLAG_sliding_state_window) ticker_->Stop();
- FLAG_log_code = false;
- // Must be the same message as Log::kDynamicBufferSeal.
- LOG(UncheckedStringEvent("profiler", "pause"));
+ if (flags & PROFILER_MODULE_CPU) {
+ // It is OK to have negative nesting.
+ if (--cpu_profiler_nesting_ == 0) {
+ profiler_->pause();
+ if (FLAG_prof_lazy) {
+ if (!FLAG_sliding_state_window) ticker_->Stop();
+ FLAG_log_code = false;
+ // Must be the same message as Log::kDynamicBufferSeal.
+ LOG(UncheckedStringEvent("profiler", "pause"));
+ }
}
}
- if (modules_to_disable &
+ if (flags &
(PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
- FLAG_log_gc = false;
- }
- // Turn off logging if no active modules remain.
- if ((active_modules & ~flags) == PROFILER_MODULE_NONE) {
+ if (--heap_profiler_nesting_ == 0) {
+ FLAG_log_gc = false;
+ }
+ }
+ if (tag != 0) {
+ IntEvent("close-tag", tag);
+ }
+ if (GetActiveProfilerModules() == PROFILER_MODULE_NONE) {
is_logging_ = false;
}
}
-void Logger::ResumeProfiler(int flags) {
+void Logger::ResumeProfiler(int flags, int tag) {
if (!Log::IsEnabled()) return;
- const int modules_to_enable = ~GetActiveProfilerModules() & flags;
- if (modules_to_enable != PROFILER_MODULE_NONE) {
- is_logging_ = true;
- }
- if (modules_to_enable & PROFILER_MODULE_CPU) {
- if (FLAG_prof_lazy) {
- profiler_->Engage();
- LOG(UncheckedStringEvent("profiler", "resume"));
- FLAG_log_code = true;
- LogCompiledFunctions();
- LogFunctionObjects();
- LogAccessorCallbacks();
- if (!FLAG_sliding_state_window) ticker_->Start();
- }
- profiler_->resume();
- }
- if (modules_to_enable &
+ if (tag != 0) {
+ IntEvent("open-tag", tag);
+ }
+ if (flags & PROFILER_MODULE_CPU) {
+ if (cpu_profiler_nesting_++ == 0) {
+ is_logging_ = true;
+ if (FLAG_prof_lazy) {
+ profiler_->Engage();
+ LOG(UncheckedStringEvent("profiler", "resume"));
+ FLAG_log_code = true;
+ LogCompiledFunctions();
+ LogFunctionObjects();
+ LogAccessorCallbacks();
+ if (!FLAG_sliding_state_window) ticker_->Start();
+ }
+ profiler_->resume();
+ }
+ }
+ if (flags &
(PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
- FLAG_log_gc = true;
+ if (heap_profiler_nesting_++ == 0) {
+ is_logging_ = true;
+ FLAG_log_gc = true;
+ }
}
}
@@ -1219,7 +1229,7 @@
// either from main or Profiler's thread.
void Logger::StopLoggingAndProfiling() {
Log::stop();
- PauseProfiler(PROFILER_MODULE_CPU);
+ PauseProfiler(PROFILER_MODULE_CPU, 0);
}
=======================================
--- /branches/bleeding_edge/src/log.h Thu Feb 4 13:34:03 2010
+++ /branches/bleeding_edge/src/log.h Wed Feb 17 05:23:46 2010
@@ -277,8 +277,8 @@
// Pause/Resume collection of profiling data.
// When data collection is paused, CPU Tick events are discarded until
// data collection is Resumed.
- static void PauseProfiler(int flags);
- static void ResumeProfiler(int flags);
+ static void PauseProfiler(int flags, int tag);
+ static void ResumeProfiler(int flags, int tag);
static int GetActiveProfilerModules();
// If logging is performed into a memory buffer, allows to
@@ -379,6 +379,8 @@
friend class LoggerTestHelper;
static bool is_logging_;
+ static int cpu_profiler_nesting_;
+ static int heap_profiler_nesting_;
#else
static bool is_logging() { return false; }
#endif
=======================================
--- /branches/bleeding_edge/src/runtime.cc Wed Feb 17 03:26:00 2010
+++ /branches/bleeding_edge/src/runtime.cc Wed Feb 17 05:23:46 2010
@@ -7917,20 +7917,22 @@
static Object* Runtime_ProfilerResume(Arguments args) {
NoHandleAllocation ha;
- ASSERT(args.length() == 1);
+ ASSERT(args.length() == 2);
CONVERT_CHECKED(Smi, smi_modules, args[0]);
- v8::V8::ResumeProfilerEx(smi_modules->value());
+ CONVERT_CHECKED(Smi, smi_tag, args[1]);
+ v8::V8::ResumeProfilerEx(smi_modules->value(), smi_tag->value());
return Heap::undefined_value();
}
static Object* Runtime_ProfilerPause(Arguments args) {
NoHandleAllocation ha;
- ASSERT(args.length() == 1);
+ ASSERT(args.length() == 2);
CONVERT_CHECKED(Smi, smi_modules, args[0]);
- v8::V8::PauseProfilerEx(smi_modules->value());
+ CONVERT_CHECKED(Smi, smi_tag, args[1]);
+ v8::V8::PauseProfilerEx(smi_modules->value(), smi_tag->value());
return Heap::undefined_value();
}
=======================================
--- /branches/bleeding_edge/src/runtime.h Wed Feb 17 03:26:00 2010
+++ /branches/bleeding_edge/src/runtime.h Wed Feb 17 05:23:46 2010
@@ -328,8 +328,8 @@
#ifdef ENABLE_LOGGING_AND_PROFILING
#define RUNTIME_FUNCTION_LIST_PROFILER_SUPPORT(F) \
- F(ProfilerResume, 1, 1) \
- F(ProfilerPause, 1, 1)
+ F(ProfilerResume, 2, 1) \
+ F(ProfilerPause, 2, 1)
#else
#define RUNTIME_FUNCTION_LIST_PROFILER_SUPPORT(F)
#endif
=======================================
--- /branches/bleeding_edge/test/cctest/test-log.cc Thu Jan 21 08:42:41 2010
+++ /branches/bleeding_edge/test/cctest/test-log.cc Wed Feb 17 05:23:46 2010
@@ -170,21 +170,110 @@
#endif // __linux__
-static int CheckThatProfilerWorks(int log_pos) {
- Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU);
+namespace {
+
+class ScopedLoggerInitializer {
+ public:
+ explicit ScopedLoggerInitializer(bool log, bool prof_lazy)
+ : saved_log_(i::FLAG_log),
+ saved_prof_lazy_(i::FLAG_prof_lazy),
+ saved_prof_(i::FLAG_prof),
+ saved_prof_auto_(i::FLAG_prof_auto),
+ trick_to_run_init_flags_(init_flags_(log, prof_lazy)),
+ need_to_set_up_logger_(i::V8::IsRunning()),
+ scope_(),
+ env_(v8::Context::New()) {
+ if (need_to_set_up_logger_) Logger::Setup();
+ env_->Enter();
+ }
+
+ ~ScopedLoggerInitializer() {
+ env_->Exit();
+ Logger::TearDown();
+ i::FLAG_prof_lazy = saved_prof_lazy_;
+ i::FLAG_prof = saved_prof_;
+ i::FLAG_prof_auto = saved_prof_auto_;
+ i::FLAG_log = saved_log_;
+ }
+
+ v8::Handle<v8::Context>& env() { return env_; }
+
+ private:
+ static bool init_flags_(bool log, bool prof_lazy) {
+ i::FLAG_log = log;
+ i::FLAG_prof = true;
+ i::FLAG_prof_lazy = prof_lazy;
+ i::FLAG_prof_auto = false;
+ i::FLAG_logfile = "*";
+ return prof_lazy;
+ }
+
+ const bool saved_log_;
+ const bool saved_prof_lazy_;
+ const bool saved_prof_;
+ const bool saved_prof_auto_;
+ const bool trick_to_run_init_flags_;
+ const bool need_to_set_up_logger_;
+ v8::HandleScope scope_;
+ v8::Handle<v8::Context> env_;
+
+ DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer);
+};
+
+
+class LogBufferMatcher {
+ public:
+ LogBufferMatcher() {
+ // Skip all initially logged stuff.
+ log_pos_ = GetLogLines(0, &buffer_);
+ }
+
+ int log_pos() { return log_pos_; }
+
+ int GetNextChunk() {
+ int chunk_size = GetLogLines(log_pos_, &buffer_);
+ CHECK_GT(buffer_.length(), chunk_size);
+ buffer_[chunk_size] = '\0';
+ log_pos_ += chunk_size;
+ return chunk_size;
+ }
+
+ const char* Find(const char* substr) {
+ return strstr(buffer_.start(), substr);
+ }
+
+ const char* Find(const i::Vector<char>& substr) {
+ return Find(substr.start());
+ }
+
+ bool IsInSequence(const char* s1, const char* s2) {
+ const char* s1_pos = Find(s1);
+ const char* s2_pos = Find(s2);
+ CHECK_NE(NULL, s1_pos);
+ CHECK_NE(NULL, s2_pos);
+ return s1_pos < s2_pos;
+ }
+
+ void PrintBuffer() {
+ puts(buffer_.start());
+ }
+
+ private:
+ EmbeddedVector<char, 102400> buffer_;
+ int log_pos_;
+};
+
+} // namespace
+
+
+static void CheckThatProfilerWorks(LogBufferMatcher* matcher) {
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 0);
CHECK(LoggerTestHelper::IsSamplerActive());
// Verify that the current map of compiled functions has been logged.
- EmbeddedVector<char, 102400> buffer;
- int map_log_size = GetLogLines(log_pos, &buffer);
- printf("map_log_size: %d\n", map_log_size);
- CHECK_GT(map_log_size, 0);
- CHECK_GT(buffer.length(), map_log_size);
- log_pos += map_log_size;
- // Check buffer contents.
- buffer[map_log_size] = '\0';
+ CHECK_GT(matcher->GetNextChunk(), 0);
const char* code_creation = "\ncode-creation,"; // eq. to
/^code-creation,/
- CHECK_NE(NULL, strstr(buffer.start(), code_creation));
+ CHECK_NE(NULL, matcher->Find(code_creation));
#ifdef __linux__
// Intercept SIGPROF handler to make sure that the test process
@@ -204,7 +293,7 @@
i::OS::SNPrintF(script_src,
"function f%d(x) { return %d * x; }"
"for (var i = 0; i < 10000; ++i) { f%d(i); }",
- log_pos, log_pos, log_pos);
+ matcher->log_pos(), matcher->log_pos(),
matcher->log_pos());
// Run code for 200 msecs to get some ticks.
const double end_time = i::OS::TimeCurrentMillis() + 200;
while (i::OS::TimeCurrentMillis() < end_time) {
@@ -213,7 +302,7 @@
i::OS::Sleep(1);
}
- Logger::PauseProfiler(v8::PROFILER_MODULE_CPU);
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 0);
CHECK(!LoggerTestHelper::IsSamplerActive());
// Wait 50 msecs to allow Profiler thread to process the last
@@ -221,68 +310,39 @@
i::OS::Sleep(50);
// Now we must have compiler and tick records.
- int log_size = GetLogLines(log_pos, &buffer);
- printf("log_size: %d\n", log_size);
- CHECK_GT(log_size, 0);
- CHECK_GT(buffer.length(), log_size);
- log_pos += log_size;
- // Check buffer contents.
- buffer[log_size] = '\0';
- printf("%s", buffer.start());
+ CHECK_GT(matcher->GetNextChunk(), 0);
+ matcher->PrintBuffer();
+ CHECK_NE(NULL, matcher->Find(code_creation));
const char* tick = "\ntick,";
- CHECK_NE(NULL, strstr(buffer.start(), code_creation));
- const bool ticks_found = strstr(buffer.start(), tick) != NULL;
+ const bool ticks_found = matcher->Find(tick) != NULL;
CHECK_EQ(was_sigprof_received, ticks_found);
-
- return log_pos;
}
TEST(ProfLazyMode) {
- const bool saved_prof_lazy = i::FLAG_prof_lazy;
- const bool saved_prof = i::FLAG_prof;
- const bool saved_prof_auto = i::FLAG_prof_auto;
- i::FLAG_prof = true;
- i::FLAG_prof_lazy = true;
- i::FLAG_prof_auto = false;
- i::FLAG_logfile = "*";
-
- // If tests are being run manually, V8 will be already initialized
- // by the bottom test.
- const bool need_to_set_up_logger = i::V8::IsRunning();
- v8::HandleScope scope;
- v8::Handle<v8::Context> env = v8::Context::New();
- if (need_to_set_up_logger) Logger::Setup();
- env->Enter();
+ ScopedLoggerInitializer initialize_logger(false, true);
// No sampling should happen prior to resuming profiler.
CHECK(!LoggerTestHelper::IsSamplerActive());
- EmbeddedVector<char, 102400> buffer;
+ LogBufferMatcher matcher;
// Nothing must be logged until profiling is resumed.
- int log_pos = GetLogLines(0, &buffer);
- CHECK_EQ(0, log_pos);
+ CHECK_EQ(0, matcher.log_pos());
CompileAndRunScript("var a = (function(x) { return x + 1; })(10);");
// Nothing must be logged while profiling is suspended.
- CHECK_EQ(0, GetLogLines(log_pos, &buffer));
-
- log_pos = CheckThatProfilerWorks(log_pos);
+ CHECK_EQ(0, matcher.GetNextChunk());
+
+ CheckThatProfilerWorks(&matcher);
CompileAndRunScript("var a = (function(x) { return x + 1; })(10);");
// No new data beyond last retrieved position.
- CHECK_EQ(0, GetLogLines(log_pos, &buffer));
+ CHECK_EQ(0, matcher.GetNextChunk());
// Check that profiling can be resumed again.
- CheckThatProfilerWorks(log_pos);
-
- env->Exit();
- Logger::TearDown();
- i::FLAG_prof_lazy = saved_prof_lazy;
- i::FLAG_prof = saved_prof;
- i::FLAG_prof_auto = saved_prof_auto;
+ CheckThatProfilerWorks(&matcher);
}
@@ -480,25 +540,8 @@
}
TEST(LogCallbacks) {
- const bool saved_prof_lazy = i::FLAG_prof_lazy;
- const bool saved_prof = i::FLAG_prof;
- const bool saved_prof_auto = i::FLAG_prof_auto;
- i::FLAG_prof = true;
- i::FLAG_prof_lazy = false;
- i::FLAG_prof_auto = false;
- i::FLAG_logfile = "*";
-
- // If tests are being run manually, V8 will be already initialized
- // by the bottom test.
- const bool need_to_set_up_logger = i::V8::IsRunning();
- v8::HandleScope scope;
- v8::Handle<v8::Context> env = v8::Context::New();
- if (need_to_set_up_logger) Logger::Setup();
- env->Enter();
-
- // Skip all initially logged stuff.
- EmbeddedVector<char, 102400> buffer;
- int log_pos = GetLogLines(0, &buffer);
+ ScopedLoggerInitializer initialize_logger(false, false);
+ LogBufferMatcher matcher;
v8::Persistent<v8::FunctionTemplate> obj =
v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New());
@@ -511,16 +554,14 @@
signature),
static_cast<v8::PropertyAttribute>(v8::DontDelete));
- env->Global()->Set(v8_str("Obj"), obj->GetFunction());
+ initialize_logger.env()->Global()->Set(v8_str("Obj"),
obj->GetFunction());
CompileAndRunScript("Obj.prototype.method1.toString();");
i::Logger::LogCompiledFunctions();
- log_pos = GetLogLines(log_pos, &buffer);
- CHECK_GT(log_pos, 0);
- buffer[log_pos] = 0;
+ CHECK_GT(matcher.GetNextChunk(), 0);
const char* callback_rec = "code-creation,Callback,";
- char* pos = strstr(buffer.start(), callback_rec);
+ char* pos = const_cast<char*>(matcher.Find(callback_rec));
CHECK_NE(NULL, pos);
pos += strlen(callback_rec);
EmbeddedVector<char, 100> ref_data;
@@ -530,12 +571,6 @@
CHECK_EQ(ref_data.start(), pos);
obj.Dispose();
-
- env->Exit();
- Logger::TearDown();
- i::FLAG_prof_lazy = saved_prof_lazy;
- i::FLAG_prof = saved_prof;
- i::FLAG_prof_auto = saved_prof_auto;
}
@@ -555,25 +590,8 @@
}
TEST(LogAccessorCallbacks) {
- const bool saved_prof_lazy = i::FLAG_prof_lazy;
- const bool saved_prof = i::FLAG_prof;
- const bool saved_prof_auto = i::FLAG_prof_auto;
- i::FLAG_prof = true;
- i::FLAG_prof_lazy = false;
- i::FLAG_prof_auto = false;
- i::FLAG_logfile = "*";
-
- // If tests are being run manually, V8 will be already initialized
- // by the bottom test.
- const bool need_to_set_up_logger = i::V8::IsRunning();
- v8::HandleScope scope;
- v8::Handle<v8::Context> env = v8::Context::New();
- if (need_to_set_up_logger) Logger::Setup();
- env->Enter();
-
- // Skip all initially logged stuff.
- EmbeddedVector<char, 102400> buffer;
- int log_pos = GetLogLines(0, &buffer);
+ ScopedLoggerInitializer initialize_logger(false, false);
+ LogBufferMatcher matcher;
v8::Persistent<v8::FunctionTemplate> obj =
v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New());
@@ -583,34 +601,112 @@
inst->SetAccessor(v8::String::New("prop2"), Prop2Getter);
i::Logger::LogAccessorCallbacks();
- log_pos = GetLogLines(log_pos, &buffer);
- CHECK_GT(log_pos, 0);
- buffer[log_pos] = 0;
- printf("%s", buffer.start());
+ CHECK_GT(matcher.GetNextChunk(), 0);
+ matcher.PrintBuffer();
EmbeddedVector<char, 100> prop1_getter_record;
i::OS::SNPrintF(prop1_getter_record,
"code-creation,Callback,0x%" V8PRIxPTR ",1,\"get
prop1\"",
Prop1Getter);
- CHECK_NE(NULL, strstr(buffer.start(), prop1_getter_record.start()));
+ CHECK_NE(NULL, matcher.Find(prop1_getter_record));
EmbeddedVector<char, 100> prop1_setter_record;
i::OS::SNPrintF(prop1_setter_record,
"code-creation,Callback,0x%" V8PRIxPTR ",1,\"set
prop1\"",
Prop1Setter);
- CHECK_NE(NULL, strstr(buffer.start(), prop1_setter_record.start()));
+ CHECK_NE(NULL, matcher.Find(prop1_setter_record));
EmbeddedVector<char, 100> prop2_getter_record;
i::OS::SNPrintF(prop2_getter_record,
"code-creation,Callback,0x%" V8PRIxPTR ",1,\"get
prop2\"",
Prop2Getter);
- CHECK_NE(NULL, strstr(buffer.start(), prop2_getter_record.start()));
+ CHECK_NE(NULL, matcher.Find(prop2_getter_record));
obj.Dispose();
-
- env->Exit();
- Logger::TearDown();
- i::FLAG_prof_lazy = saved_prof_lazy;
- i::FLAG_prof = saved_prof;
- i::FLAG_prof_auto = saved_prof_auto;
+}
+
+
+TEST(LogTags) {
+ ScopedLoggerInitializer initialize_logger(true, false);
+ LogBufferMatcher matcher;
+
+ const char* open_tag = "open-tag,";
+ const char* close_tag = "close-tag,";
+
+ // Check compatibility with the old style behavior.
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 0);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 0);
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ CHECK_EQ(NULL, matcher.Find(open_tag));
+ CHECK_EQ(NULL, matcher.Find(close_tag));
+
+ const char* open_tag1 = "open-tag,1\n";
+ const char* close_tag1 = "close-tag,1\n";
+
+ // Check non-nested tag case.
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 1);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 1);
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ CHECK_GT(matcher.GetNextChunk(), 0);
+ CHECK(matcher.IsInSequence(open_tag1, close_tag1));
+
+ const char* open_tag2 = "open-tag,2\n";
+ const char* close_tag2 = "close-tag,2\n";
+
+ // Check nested tags case.
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 1);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 2);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 2);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 1);
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ CHECK_GT(matcher.GetNextChunk(), 0);
+ // open_tag1 < open_tag2 < close_tag2 < close_tag1
+ CHECK(matcher.IsInSequence(open_tag1, open_tag2));
+ CHECK(matcher.IsInSequence(open_tag2, close_tag2));
+ CHECK(matcher.IsInSequence(close_tag2, close_tag1));
+
+ // Check overlapped tags case.
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 1);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 2);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 1);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 2);
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ CHECK_GT(matcher.GetNextChunk(), 0);
+ // open_tag1 < open_tag2 < close_tag1 < close_tag2
+ CHECK(matcher.IsInSequence(open_tag1, open_tag2));
+ CHECK(matcher.IsInSequence(open_tag2, close_tag1));
+ CHECK(matcher.IsInSequence(close_tag1, close_tag2));
+
+ const char* open_tag3 = "open-tag,3\n";
+ const char* close_tag3 = "close-tag,3\n";
+
+ // Check pausing overflow case.
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 1);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 2);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 2);
+ CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules());
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 1);
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 3);
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 3);
+ CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules());
+ // Must be no tags, because logging must be disabled.
+ CHECK_EQ(NULL, matcher.Find(open_tag3));
+ CHECK_EQ(NULL, matcher.Find(close_tag3));
}
--
v8-dev mailing list
[email protected]
http://groups.google.com/group/v8-dev
