// 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 <pthread.h> #include <signal.h> #include <unistd.h> #include <cmath> #endif // __linux__ #include "src/v8.h" #include "src/cpu-profiler.h" #include "src/log.h" #include "src/log-utils.h" #include "src/snapshot/natives.h" #include "src/utils.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 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<i::Isolate*>(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_; } v8::Handle<v8::Context>& env() { return env_; } v8::Isolate* isolate() { return isolate_; } Logger* logger() { return logger_; } FILE* StopLoggingGetTempFile() { temp_file_ = logger_->TearDown(); CHECK(temp_file_); fflush(temp_file_); rewind(temp_file_); return temp_file_; } private: const bool saved_log_; const bool saved_prof_; FILE* temp_file_; v8::Isolate* isolate_; v8::Isolate::Scope isolate_scope_; v8::HandleScope scope_; v8::Handle<v8::Context> env_; Logger* logger_; DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); }; } // namespace static const char* StrNStr(const char* s1, const char* s2, int n) { if (s1[n] == '\0') return strstr(s1, s2); i::ScopedVector<char> str(n + 1); i::StrNCpy(str, s1, static_cast<size_t>(n)); str[n] = '\0'; char* found = strstr(str.start(), s2); return found != NULL ? s1 + (found - str.start()) : NULL; } // 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<v8::Context> context = v8::Context::New(); CHECK(!context.IsEmpty()); { v8::Context::Scope context_scope(context); SignalRunning(); CompileRun( "var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }"); } context.Dispose(); i::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(1)); } } }; class LoopingNonJsThread : public LoopingThread { public: explicit LoopingNonJsThread(v8::internal::Isolate* isolate) : LoopingThread(isolate) { } void RunLoop() { v8::Locker locker; v8::Unlocker unlocker; // Now thread has V8's id, but will not run VM code. CHECK(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<uint16_t> utf_source_; }; } // namespace TEST(Issue23768) { v8::HandleScope scope(CcTest::isolate()); v8::Handle<v8::Context> env = v8::Context::New(CcTest::isolate()); env->Enter(); SimpleExternalString source_ext_str("(function ext() {})();"); v8::Local<v8::String> source = v8::String::NewExternal(CcTest::isolate(), &source_ext_str); // Script needs to have a name in order to trigger InitLineEnds execution. v8::Handle<v8::String> origin = v8::String::NewFromUtf8(CcTest::isolate(), "issue-23768-test"); v8::Handle<v8::Script> evil_script = CompileWithOrigin(source, origin); CHECK(!evil_script.IsEmpty()); CHECK(!evil_script->Run().IsEmpty()); i::Handle<i::ExternalTwoByteString> 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<v8::Value>& 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 initialize_logger(saved_log, saved_prof, isolate); Logger* logger = initialize_logger.logger(); v8::Local<v8::FunctionTemplate> obj = v8::Local<v8::FunctionTemplate>::New( isolate, v8::FunctionTemplate::New(isolate)); obj->SetClassName(v8_str("Obj")); v8::Handle<v8::ObjectTemplate> proto = obj->PrototypeTemplate(); v8::Local<v8::Signature> signature = v8::Signature::New(isolate, obj); proto->Set(v8_str("method1"), v8::FunctionTemplate::New(isolate, ObjMethod1, v8::Handle<v8::Value>(), signature), static_cast<v8::PropertyAttribute>(v8::DontDelete)); initialize_logger.env()->Global()->Set(v8_str("Obj"), obj->GetFunction()); CompileRun("Obj.prototype.method1.toString();"); logger->LogCompiledFunctions(); bool exists = false; i::Vector<const char> log( i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); CHECK(exists); i::EmbeddedVector<char, 100> ref_data; i::SNPrintF(ref_data, "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"method1\"", reinterpret_cast<intptr_t>(ObjMethod1)); CHECK(StrNStr(log.start(), ref_data.start(), log.length())); log.Dispose(); } isolate->Dispose(); } static void Prop1Getter(v8::Local<v8::String> property, const v8::PropertyCallbackInfo<v8::Value>& info) { } static void Prop1Setter(v8::Local<v8::String> property, v8::Local<v8::Value> value, const v8::PropertyCallbackInfo<void>& info) { } static void Prop2Getter(v8::Local<v8::String> property, const v8::PropertyCallbackInfo<v8::Value>& 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 initialize_logger(saved_log, saved_prof, isolate); Logger* logger = initialize_logger.logger(); v8::Local<v8::FunctionTemplate> obj = v8::Local<v8::FunctionTemplate>::New( isolate, v8::FunctionTemplate::New(isolate)); obj->SetClassName(v8_str("Obj")); v8::Handle<v8::ObjectTemplate> inst = obj->InstanceTemplate(); inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter); inst->SetAccessor(v8_str("prop2"), Prop2Getter); logger->LogAccessorCallbacks(); bool exists = false; i::Vector<const char> log( i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); CHECK(exists); EmbeddedVector<char, 100> prop1_getter_record; i::SNPrintF(prop1_getter_record, "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"get prop1\"", reinterpret_cast<intptr_t>(Prop1Getter)); CHECK(StrNStr(log.start(), prop1_getter_record.start(), log.length())); EmbeddedVector<char, 100> prop1_setter_record; i::SNPrintF(prop1_setter_record, "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"set prop1\"", reinterpret_cast<intptr_t>(Prop1Setter)); CHECK(StrNStr(log.start(), prop1_setter_record.start(), log.length())); EmbeddedVector<char, 100> prop2_getter_record; i::SNPrintF(prop2_getter_record, "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"get prop2\"", reinterpret_cast<intptr_t>(Prop2Getter)); CHECK(StrNStr(log.start(), prop2_getter_record.start(), log.length())); log.Dispose(); } isolate->Dispose(); } typedef i::NativesCollection<i::TEST> TestSources; // 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 initialize_logger(saved_log, saved_prof, isolate); Logger* logger = initialize_logger.logger(); // 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->StopProfiler(); reinterpret_cast<i::Isolate*>(isolate)->heap()->CollectAllGarbage( i::Heap::kMakeHeapIterableMask); logger->StringEvent("test-logging-done", ""); // Iterate heap to find compiled functions, will write to log. logger->LogCompiledFunctions(); logger->StringEvent("test-traversal-done", ""); bool exists = false; i::Vector<const char> log( i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); CHECK(exists); v8::Handle<v8::String> log_str = v8::String::NewFromUtf8( isolate, log.start(), v8::String::kNormalString, log.length()); initialize_logger.env()->Global()->Set(v8_str("_log"), log_str); i::Vector<const char> source = TestSources::GetScriptsSource(); v8::Handle<v8::String> source_str = v8::String::NewFromUtf8( isolate, source.start(), v8::String::kNormalString, source.length()); v8::TryCatch try_catch(isolate); v8::Handle<v8::Script> script = CompileWithOrigin(source_str, ""); if (script.IsEmpty()) { v8::String::Utf8Value exception(try_catch.Exception()); printf("compile: %s\n", *exception); CHECK(false); } v8::Handle<v8::Value> result = script->Run(); if (result.IsEmpty()) { v8::String::Utf8Value exception(try_catch.Exception()); printf("run: %s\n", *exception); CHECK(false); } // The result either be a "true" literal or problem description. if (!result->IsTrue()) { v8::Local<v8::String> s = result->ToString(isolate); i::ScopedVector<char> 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 initialize_logger(saved_log, saved_prof, isolate); bool exists = false; i::Vector<const char> log( i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); CHECK(exists); i::EmbeddedVector<char, 100> ref_data; i::SNPrintF(ref_data, "v8-version,%d,%d,%d,%d,%d", i::Version::GetMajor(), i::Version::GetMinor(), i::Version::GetBuild(), i::Version::GetPatch(), i::Version::IsCandidate()); CHECK(StrNStr(log.start(), ref_data.start(), log.length())); log.Dispose(); } isolate->Dispose(); }