// 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 "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(i::Vector* log, const char* prefix, const char* suffix) { const char* start = log->start(); const char* end = start + log->length(); 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 = StrNStr(start, prefix, (end - start)); if (!prefixResult) return NULL; 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_(NULL), 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_ != NULL) 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_; } 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) { return FindLogLine(&log_, prefix, suffix); } void LogCompiledFunctions() { logger_->LogCompiledFunctions(); } void StringEvent(const char* name, const char* value) { logger_->StringEvent(name, value); } 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"; // Make sure the vector contains the terminating \0 character. i::Vector log(string, strlen(string)); CHECK(FindLogLine(&log, "prefix1", "suffix1")); CHECK(FindLogLine(&log, "prefix1", "suffix1")); CHECK(!FindLogLine(&log, "prefix2", "suffix2")); CHECK(!FindLogLine(&log, "prefix1", "suffix2")); CHECK(!FindLogLine(&log, "prefix1", "suffix3")); CHECK(FindLogLine(&log, "prefix3", "suffix3")); CHECK(FindLogLine(&log, "prefix4", "suffix4")); CHECK(!FindLogLine(&log, "prefix4", "suffix4XXXXXXXXXXXX")); CHECK(!FindLogLine(&log, "prefix4XXXXXXXXXXXXXXXXXXXXXXxxx", "suffix4")); CHECK(!FindLogLine(&log, "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(CcTest::i_isolate() != NULL); 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(CcTest::i_isolate() != NULL); 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 = NULL; { 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(NULL); // 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()); printf("compile: %s\n", *exception); CHECK(false); } v8::Local result; if (!script->Run(logger.env()).ToLocal(&result)) { v8::String::Utf8Value exception(isolate, try_catch.Exception()); printf("run: %s\n", *exception); CHECK(false); } // 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()); printf("%s\n", data.start()); // Make sure that our output is written prior crash due to CHECK failure. fflush(stdout); CHECK(false); } } 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(); }