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 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3889 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
This commit is contained in:
mikhail.naganov@gmail.com
parent
1b526cc700
commit
39e63f0aec
16
include/v8.h
16
include/v8.h
@ -2349,22 +2349,30 @@ class V8EXPORT V8 {
|
||||
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.
|
||||
|
||||
16
src/api.cc
16
src/api.cc
@ -3469,14 +3469,14 @@ void V8::SetGlobalGCEpilogueCallback(GCCallback callback) {
|
||||
|
||||
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 @@ bool V8::IsProfilerPaused() {
|
||||
}
|
||||
|
||||
|
||||
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 @@ void V8::ResumeProfilerEx(int flags) {
|
||||
// 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
|
||||
}
|
||||
|
||||
|
||||
@ -125,7 +125,9 @@ static inline void CheckEqualsHelper(const char* file,
|
||||
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);
|
||||
|
||||
@ -1934,10 +1934,14 @@ DebugCommandProcessor.prototype.profileRequest_ = function(request, response) {
|
||||
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');
|
||||
}
|
||||
|
||||
76
src/log.cc
76
src/log.cc
@ -330,6 +330,8 @@ SlidingStateWindow* Logger::sliding_state_window_ = NULL;
|
||||
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 @@ int Logger::GetActiveProfilerModules() {
|
||||
}
|
||||
|
||||
|
||||
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;
|
||||
if (--heap_profiler_nesting_ == 0) {
|
||||
FLAG_log_gc = false;
|
||||
}
|
||||
}
|
||||
// Turn off logging if no active modules remain.
|
||||
if ((active_modules & ~flags) == PROFILER_MODULE_NONE) {
|
||||
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 (tag != 0) {
|
||||
IntEvent("open-tag", tag);
|
||||
}
|
||||
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();
|
||||
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();
|
||||
}
|
||||
profiler_->resume();
|
||||
}
|
||||
if (modules_to_enable &
|
||||
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 @@ void Logger::ResumeProfiler(int flags) {
|
||||
// either from main or Profiler's thread.
|
||||
void Logger::StopLoggingAndProfiling() {
|
||||
Log::stop();
|
||||
PauseProfiler(PROFILER_MODULE_CPU);
|
||||
PauseProfiler(PROFILER_MODULE_CPU, 0);
|
||||
}
|
||||
|
||||
|
||||
|
||||
@ -277,8 +277,8 @@ class Logger {
|
||||
// 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 @@ class Logger {
|
||||
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
|
||||
|
||||
@ -7917,20 +7917,22 @@ static Object* Runtime_FunctionGetInferredName(Arguments args) {
|
||||
|
||||
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();
|
||||
}
|
||||
|
||||
|
||||
@ -328,8 +328,8 @@ namespace internal {
|
||||
|
||||
#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
|
||||
|
||||
@ -170,21 +170,110 @@ static void SigProfSignalHandler(int signal, siginfo_t* info, void* context) {
|
||||
#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 @@ static int CheckThatProfilerWorks(int log_pos) {
|
||||
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 @@ static int CheckThatProfilerWorks(int log_pos) {
|
||||
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 @@ static int CheckThatProfilerWorks(int log_pos) {
|
||||
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));
|
||||
CHECK_EQ(0, matcher.GetNextChunk());
|
||||
|
||||
log_pos = CheckThatProfilerWorks(log_pos);
|
||||
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 @@ static v8::Handle<v8::Value> ObjMethod1(const v8::Arguments& args) {
|
||||
}
|
||||
|
||||
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 @@ TEST(LogCallbacks) {
|
||||
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 @@ TEST(LogCallbacks) {
|
||||
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 @@ static v8::Handle<v8::Value> Prop2Getter(v8::Local<v8::String> property,
|
||||
}
|
||||
|
||||
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 @@ TEST(LogAccessorCallbacks) {
|
||||
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));
|
||||
}
|
||||
|
||||
|
||||
|
||||
Loading…
Reference in New Issue
Block a user