// Copyright 2006-2009 the V8 project authors. All rights reserved. // Redistribution and use in source and binary forms, with or without // modification, are permitted provided that the following conditions are // met: // // * Redistributions of source code must retain the above copyright // notice, this list of conditions and the following disclaimer. // * Redistributions in binary form must reproduce the above // copyright notice, this list of conditions and the following // disclaimer in the documentation and/or other materials provided // with the distribution. // * Neither the name of Google Inc. nor the names of its // contributors may be used to endorse or promote products derived // from this software without specific prior written permission. // // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS // "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT // LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR // A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT // OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, // SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT // LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, // DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY // THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. // // Tests of logging functions from log.h #ifdef __linux__ #include #include #include #include #endif // __linux__ #include #include "src/api.h" #include "src/log-utils.h" #include "src/log.h" #include "src/objects-inl.h" #include "src/profiler/cpu-profiler.h" #include "src/snapshot/natives.h" #include "src/utils.h" #include "src/v8.h" #include "src/v8threads.h" #include "src/version.h" #include "src/vm-state-inl.h" #include "test/cctest/cctest.h" using v8::internal::Address; using v8::internal::EmbeddedVector; using v8::internal::Logger; using v8::internal::StrLength; namespace { #define SETUP_FLAGS() \ bool saved_log = i::FLAG_log; \ bool saved_prof = i::FLAG_prof; \ i::FLAG_log = true; \ i::FLAG_prof = true; \ i::FLAG_logfile = i::Log::kLogToTemporaryFile; \ i::FLAG_logfile_per_isolate = false static const char* StrNStr(const char* s1, const char* s2, size_t n) { CHECK_EQ(s1[n], '\0'); return strstr(s1, s2); } // Look for a log line which starts with {prefix} and ends with {suffix}. 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; } class ScopedLoggerInitializer { public: ScopedLoggerInitializer(bool saved_log, bool saved_prof, v8::Isolate* isolate) : saved_log_(saved_log), saved_prof_(saved_prof), temp_file_(nullptr), isolate_(isolate), isolate_scope_(isolate), scope_(isolate), env_(v8::Context::New(isolate)), logger_(reinterpret_cast(isolate)->logger()) { env_->Enter(); } ~ScopedLoggerInitializer() { env_->Exit(); logger_->TearDown(); if (temp_file_ != nullptr) fclose(temp_file_); i::FLAG_prof = saved_prof_; i::FLAG_log = saved_log_; log_.Dispose(); } v8::Local& env() { return env_; } v8::Isolate* isolate() { return isolate_; } Logger* logger() { return logger_; } void PrintLog(int nofLines = 0) { if (nofLines <= 0) { printf("%s", log_.start()); return; } // Try to print the last {nofLines} of the log. const char* start = log_.start(); const char* current = log_.end(); while (current > start && nofLines > 0) { current--; if (*current == '\n') nofLines--; } printf( "======================================================\n" "Last log lines:\n...%s\n" "======================================================\n", current); } v8::Local GetLogString() { return v8::String::NewFromUtf8(isolate_, log_.start(), v8::NewStringType::kNormal, log_.length()) .ToLocalChecked(); } void StopLogging() { bool exists = false; log_ = i::ReadFile(StopLoggingGetTempFile(), &exists, true); CHECK(exists); } const char* FindLine(const char* prefix, const char* suffix = nullptr, const char* start = nullptr) { // Make sure that StopLogging() has been called before. CHECK(log_.size()); if (start == nullptr) start = log_.start(); const char* end = log_.start() + log_.length(); return FindLogLine(start, end, prefix, suffix); } // Find all log lines specified by the {prefix, suffix} pairs and ensure they // occurr in the specified order. void FindLogLines(const char* pairs[][2], size_t limit, 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(50); V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s", prefix, suffix); } CHECK(last_position); for (size_t i = 1; i < limit; i++) { prefix = pairs[i][0]; suffix = pairs[i][1]; const char* position = FindLine(prefix, suffix, start); if (position == nullptr) { PrintLog(50); V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s", prefix, suffix); } // Check that all string positions are in order. if (position <= last_position) { PrintLog(50); V8_Fatal(__FILE__, __LINE__, "Log statements not in expected order (prev=%p, current=%p): " "%s ... %s", reinterpret_cast(last_position), reinterpret_cast(position), prefix, suffix); } last_position = position; } } void LogCompiledFunctions() { logger_->LogCompiledFunctions(); } void StringEvent(const char* name, const char* value) { logger_->StringEvent(name, value); } void ExtractAllAddresses(std::unordered_set* map, const char* prefix, int field_index) { // Make sure that StopLogging() has been called before. CHECK(log_.size()); const char* current = log_.start(); 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: FILE* StopLoggingGetTempFile() { temp_file_ = logger_->TearDown(); CHECK(temp_file_); fflush(temp_file_); rewind(temp_file_); return temp_file_; } const bool saved_log_; const bool saved_prof_; FILE* temp_file_; v8::Isolate* isolate_; v8::Isolate::Scope isolate_scope_; v8::HandleScope scope_; v8::Local env_; Logger* logger_; i::Vector log_; DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); }; } // 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 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. // Heap can contain scripts with already disposed external sources. // We need to verify that LogCompiledFunctions doesn't crash on them. namespace { class SimpleExternalString : public v8::String::ExternalStringResource { public: explicit SimpleExternalString(const char* source) : utf_source_(StrLength(source)) { for (int i = 0; i < utf_source_.length(); ++i) utf_source_[i] = source[i]; } virtual ~SimpleExternalString() {} virtual size_t length() const { return utf_source_.length(); } virtual const uint16_t* data() const { return utf_source_.start(); } private: i::ScopedVector utf_source_; }; } // namespace TEST(Issue23768) { v8::HandleScope scope(CcTest::isolate()); v8::Local env = v8::Context::New(CcTest::isolate()); env->Enter(); SimpleExternalString source_ext_str("(function ext() {})();"); v8::Local source = v8::String::NewExternalTwoByte(CcTest::isolate(), &source_ext_str) .ToLocalChecked(); // Script needs to have a name in order to trigger InitLineEnds execution. v8::Local origin = v8::String::NewFromUtf8(CcTest::isolate(), "issue-23768-test", v8::NewStringType::kNormal) .ToLocalChecked(); v8::Local evil_script = CompileWithOrigin(source, origin); CHECK(!evil_script.IsEmpty()); CHECK(!evil_script->Run(env).IsEmpty()); i::Handle i_source( i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source))); // This situation can happen if source was an external string disposed // by its owner. i_source->set_resource(nullptr); // Must not crash. CcTest::i_isolate()->logger()->LogCompiledFunctions(); } static void ObjMethod1(const v8::FunctionCallbackInfo& args) { } TEST(LogCallbacks) { SETUP_FLAGS(); v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); v8::Local obj = v8::Local::New( isolate, v8::FunctionTemplate::New(isolate)); obj->SetClassName(v8_str("Obj")); v8::Local proto = obj->PrototypeTemplate(); v8::Local signature = v8::Signature::New(isolate, obj); proto->Set(v8_str("method1"), v8::FunctionTemplate::New(isolate, ObjMethod1, v8::Local(), signature), static_cast(v8::DontDelete)); logger.env() ->Global() ->Set(logger.env(), v8_str("Obj"), obj->GetFunction(logger.env()).ToLocalChecked()) .FromJust(); CompileRun("Obj.prototype.method1.toString();"); logger.LogCompiledFunctions(); logger.StopLogging(); Address ObjMethod1_entry = reinterpret_cast
(ObjMethod1); #if USES_FUNCTION_DESCRIPTORS ObjMethod1_entry = *FUNCTION_ENTRYPOINT_ADDRESS(ObjMethod1_entry); #endif i::EmbeddedVector ref_data; i::SNPrintF(ref_data, ",0x%" V8PRIxPTR ",1,method1", reinterpret_cast(ObjMethod1_entry)); CHECK(logger.FindLine("code-creation,Callback,-2,", ref_data.start())); } isolate->Dispose(); } static void Prop1Getter(v8::Local property, const v8::PropertyCallbackInfo& info) { } static void Prop1Setter(v8::Local property, v8::Local value, const v8::PropertyCallbackInfo& info) { } static void Prop2Getter(v8::Local property, const v8::PropertyCallbackInfo& info) { } TEST(LogAccessorCallbacks) { SETUP_FLAGS(); v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); v8::Local obj = v8::Local::New( isolate, v8::FunctionTemplate::New(isolate)); obj->SetClassName(v8_str("Obj")); v8::Local inst = obj->InstanceTemplate(); inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter); inst->SetAccessor(v8_str("prop2"), Prop2Getter); logger.logger()->LogAccessorCallbacks(); logger.StopLogging(); Address Prop1Getter_entry = reinterpret_cast
(Prop1Getter); #if USES_FUNCTION_DESCRIPTORS Prop1Getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop1Getter_entry); #endif EmbeddedVector prop1_getter_record; i::SNPrintF(prop1_getter_record, ",0x%" V8PRIxPTR ",1,get prop1", reinterpret_cast(Prop1Getter_entry)); CHECK(logger.FindLine("code-creation,Callback,-2,", prop1_getter_record.start())); Address Prop1Setter_entry = reinterpret_cast
(Prop1Setter); #if USES_FUNCTION_DESCRIPTORS Prop1Setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop1Setter_entry); #endif EmbeddedVector prop1_setter_record; i::SNPrintF(prop1_setter_record, ",0x%" V8PRIxPTR ",1,set prop1", reinterpret_cast(Prop1Setter_entry)); CHECK(logger.FindLine("code-creation,Callback,-2,", prop1_setter_record.start())); Address Prop2Getter_entry = reinterpret_cast
(Prop2Getter); #if USES_FUNCTION_DESCRIPTORS Prop2Getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop2Getter_entry); #endif EmbeddedVector prop2_getter_record; i::SNPrintF(prop2_getter_record, ",0x%" V8PRIxPTR ",1,get prop2", reinterpret_cast(Prop2Getter_entry)); CHECK(logger.FindLine("code-creation,Callback,-2,", prop2_getter_record.start())); } isolate->Dispose(); } // Test that logging of code create / move events is equivalent to traversal of // a resulting heap. TEST(EquivalenceOfLoggingAndTraversal) { // This test needs to be run on a "clean" V8 to ensure that snapshot log // is loaded. This is always true when running using tools/test.py because // it launches a new cctest instance for every test. To be sure that launching // cctest manually also works, please be sure that no tests below // are using V8. // Start with profiling to capture all code events from the beginning. SETUP_FLAGS(); v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); // Compile and run a function that creates other functions. CompileRun( "(function f(obj) {\n" " obj.test =\n" " (function a(j) { return function b() { return j; } })(100);\n" "})(this);"); logger.logger()->StopProfiler(); reinterpret_cast(isolate)->heap()->CollectAllGarbage( i::Heap::kMakeHeapIterableMask, i::GarbageCollectionReason::kTesting); logger.StringEvent("test-logging-done", ""); // Iterate heap to find compiled functions, will write to log. logger.LogCompiledFunctions(); logger.StringEvent("test-traversal-done", ""); logger.StopLogging(); v8::Local log_str = logger.GetLogString(); logger.env() ->Global() ->Set(logger.env(), v8_str("_log"), log_str) .FromJust(); // Load the Test snapshot's sources, see log-eq-of-logging-and-traversal.js i::Vector source = i::NativesCollection::GetScriptsSource(); v8::Local source_str = v8::String::NewFromUtf8(isolate, source.start(), v8::NewStringType::kNormal, source.length()) .ToLocalChecked(); v8::TryCatch try_catch(isolate); v8::Local script = CompileWithOrigin(source_str, ""); if (script.IsEmpty()) { v8::String::Utf8Value exception(isolate, try_catch.Exception()); FATAL("compile: %s\n", *exception); } v8::Local result; if (!script->Run(logger.env()).ToLocal(&result)) { v8::String::Utf8Value exception(isolate, try_catch.Exception()); FATAL("run: %s\n", *exception); } // The result either be the "true" literal or problem description. if (!result->IsTrue()) { v8::Local s = result->ToString(logger.env()).ToLocalChecked(); i::ScopedVector data(s->Utf8Length() + 1); CHECK(data.start()); s->WriteUtf8(data.start()); FATAL("%s\n", data.start()); } } isolate->Dispose(); } TEST(LogVersion) { SETUP_FLAGS(); v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); logger.StopLogging(); i::EmbeddedVector ref_data; i::SNPrintF(ref_data, "%d,%d,%d,%d,%d", i::Version::GetMajor(), i::Version::GetMinor(), i::Version::GetBuild(), i::Version::GetPatch(), i::Version::IsCandidate()); CHECK(logger.FindLine("v8-version,", ref_data.start())); } isolate->Dispose(); } // https://crbug.com/539892 // CodeCreateEvents with really large names should not crash. TEST(Issue539892) { class : public i::CodeEventLogger { public: void CodeMoveEvent(i::AbstractCode* from, Address to) override {} void CodeDisableOptEvent(i::AbstractCode* code, i::SharedFunctionInfo* shared) override {} private: void LogRecordedBuffer(i::AbstractCode* code, i::SharedFunctionInfo* shared, const char* name, int length) override {} } code_event_logger; SETUP_FLAGS(); v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); logger.logger()->addCodeEventListener(&code_event_logger); // Function with a really large name. const char* source_text = "(function " "baaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaac" "(){})();"; CompileRun(source_text); // Must not crash. logger.LogCompiledFunctions(); } isolate->Dispose(); } TEST(LogAll) { SETUP_FLAGS(); i::FLAG_log_all = true; v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); // Function that will const char* source_text = "function testAddFn(a,b) { return a + b };" "let result;" "for (let i = 0; i < 100000; i++) { result = testAddFn(i, i); };" "testAddFn('1', 1);" "for (let i = 0; i < 100000; i++) { result = testAddFn('1', i); }"; CompileRun(source_text); logger.StopLogging(); // We should find at least one code-creation even for testAddFn(); CHECK(logger.FindLine("api,v8::Context::New")); CHECK(logger.FindLine("timer-event-start", "V8.CompileCode")); CHECK(logger.FindLine("timer-event-end", "V8.CompileCode")); CHECK(logger.FindLine("code-creation,Script", ":1:1")); CHECK(logger.FindLine("api,v8::Script::Run")); CHECK(logger.FindLine("code-creation,LazyCompile,", "testAddFn")); if (i::FLAG_opt && !i::FLAG_always_opt) { CHECK(logger.FindLine("code-deopt,", "soft")); CHECK(logger.FindLine("timer-event-start", "V8.DeoptimizeCode")); CHECK(logger.FindLine("timer-event-end", "V8.DeoptimizeCode")); } } isolate->Dispose(); } TEST(TraceMaps) { SETUP_FLAGS(); i::FLAG_trace_maps = true; v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); // Try to create many different kind of maps to make sure the logging won't // crash. More detailed tests are implemented separately. const char* source_text = "let a = {};" "for (let i = 0; i < 500; i++) { a['p'+i] = i };" "class Test { constructor(i) { this.a = 1; this['p'+i] = 1; }};" "let t = new Test();" "t.b = 1; t.c = 1; t.d = 3;" "for (let i = 0; i < 100; i++) { t = new Test(i) };" "t.b = {};"; CompileRun(source_text); logger.StopLogging(); // Mostly superficial checks. CHECK(logger.FindLine("map,InitialMap", ",0x")); CHECK(logger.FindLine("map,Transition", ",0x")); CHECK(logger.FindLine("map-details", ",0x")); } i::FLAG_trace_maps = false; isolate->Dispose(); } TEST(LogMaps) { // Test that all Map details from Maps in the snapshot are logged properly. SETUP_FLAGS(); i::FLAG_trace_maps = true; v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); logger.StopLogging(); // Extract all the map-detail entry addresses from the log. std::unordered_set map_addresses; logger.ExtractAllAddresses(&map_addresses, "map-details", 2); i::Heap* heap = reinterpret_cast(isolate)->heap(); i::HeapIterator iterator(heap); i::DisallowHeapAllocation no_gc; // Iterate over all maps on the heap. size_t i = 0; for (i::HeapObject* obj = iterator.next(); obj != nullptr; obj = iterator.next()) { i++; if (!obj->IsMap()) continue; uintptr_t address = reinterpret_cast(obj); if (map_addresses.find(address) != map_addresses.end()) continue; logger.PrintLog(200); i::Map::cast(obj)->Print(); V8_Fatal(__FILE__, __LINE__, "Map (%p, #%zu) was not logged during startup with --trace-maps!" "\n# Expected Log Line: map_details, ... %p" "\n# Use logger::PrintLog() for more details.", reinterpret_cast(obj), i, reinterpret_cast(obj)); } logger.PrintLog(200); } i::FLAG_log_function_events = false; isolate->Dispose(); } TEST(ConsoleTimeEvents) { SETUP_FLAGS(); v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); // Test that console time events are properly logged const char* source_text = "console.time();" "console.timeEnd();" "console.timeStamp();" "console.time('timerEvent1');" "console.timeEnd('timerEvent1');" "console.timeStamp('timerEvent2');" "console.timeStamp('timerEvent3');"; CompileRun(source_text); logger.StopLogging(); const char* pairs[][2] = {{"timer-event-start,default,", nullptr}, {"timer-event-end,default,", nullptr}, {"timer-event,default,", nullptr}, {"timer-event-start,timerEvent1,", nullptr}, {"timer-event-end,timerEvent1,", nullptr}, {"timer-event,timerEvent2,", nullptr}, {"timer-event,timerEvent3,", nullptr}}; logger.FindLogLines(pairs, arraysize(pairs)); } isolate->Dispose(); } TEST(LogFunctionEvents) { // Always opt and stress opt will break the fine-grained log order. if (i::FLAG_always_opt) return; SETUP_FLAGS(); i::FLAG_log_function_events = true; v8::Isolate::CreateParams create_params; create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); v8::Isolate* isolate = v8::Isolate::New(create_params); { ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); const char* source_text = "function lazyNotExecutedFunction() { return 'lazy' };" "function lazyFunction() { " " function lazyInnerFunction() { return 'lazy' };" " return lazyInnerFunction;" "};" "let innerFn = lazyFunction();" "innerFn();" "(function eagerFunction(){ return 'eager' })();" "function Foo() { this.foo = function(){}; };" "let i = new Foo(); i.foo();"; CompileRun(source_text); logger.StopLogging(); // TODO(cbruni): Extend with first-execution log statements. CHECK_NULL( logger.FindLine("function,compile-lazy,", ",lazyNotExecutedFunction")); // Only consider the log starting from the first preparse statement on. const char* start = logger.FindLine("function,preparse-", ",lazyNotExecutedFunction"); const char* pairs[][2] = { // Step 1: parsing top-level script, preparsing functions {"function,preparse-", ",lazyNotExecutedFunction"}, // Missing name for preparsing lazyInnerFunction // {"function,preparse-", nullptr}, {"function,preparse-", ",lazyFunction"}, {"function,full-parse,", ",eagerFunction"}, {"function,preparse-", ",Foo"}, // Missing name for inner preparsing of Foo.foo // {"function,preparse-", nullptr}, // Missing name for top-level script. {"function,parse-script,", nullptr}, // Step 2: compiling top-level script and eager functions // - Compiling script without name. {"function,compile,,", nullptr}, {"function,compile,", ",eagerFunction"}, // Step 3: start executing script // Step 4. - lazy parse, lazy compiling and execute skipped functions // - execute eager functions. {"function,parse-function,", ",lazyFunction"}, {"function,compile-lazy,", ",lazyFunction"}, {"function,first-execution,", ",lazyFunction"}, {"function,parse-function,", ",lazyInnerFunction"}, {"function,compile-lazy,", ",lazyInnerFunction"}, {"function,first-execution,", ",lazyInnerFunction"}, {"function,first-execution,", ",eagerFunction"}, {"function,parse-function,", ",Foo"}, {"function,compile-lazy,", ",Foo"}, {"function,first-execution,", ",Foo"}, {"function,parse-function,", ",Foo.foo"}, {"function,compile-lazy,", ",Foo.foo"}, {"function,first-execution,", ",Foo.foo"}, }; logger.FindLogLines(pairs, arraysize(pairs), start); } i::FLAG_log_function_events = false; isolate->Dispose(); }