// 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 "v8.h" #include "log.h" #include "cpu-profiler.h" #include "natives.h" #include "v8threads.h" #include "v8utils.h" #include "cctest.h" #include "vm-state-inl.h" using v8::internal::Address; using v8::internal::EmbeddedVector; using v8::internal::Logger; using v8::internal::StrLength; namespace { class ScopedLoggerInitializer { public: explicit ScopedLoggerInitializer(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), temp_file_(NULL), // Need to run this prior to creating the scope. trick_to_run_init_flags_(init_flags_(prof_lazy)), scope_(v8::Isolate::GetCurrent()), env_(v8::Context::New()), logger_(i::Isolate::Current()->logger()) { env_->Enter(); } ~ScopedLoggerInitializer() { env_->Exit(); logger_->TearDown(); if (temp_file_ != NULL) fclose(temp_file_); 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& env() { return env_; } Logger* logger() { return logger_; } FILE* StopLoggingGetTempFile() { temp_file_ = logger_->TearDown(); CHECK_NE(NULL, temp_file_); fflush(temp_file_); rewind(temp_file_); return temp_file_; } private: static bool init_flags_(bool prof_lazy) { i::FLAG_log = true; i::FLAG_prof = true; i::FLAG_prof_lazy = prof_lazy; i::FLAG_prof_auto = false; i::FLAG_logfile = i::Log::kLogToTemporaryFile; return prof_lazy; } const bool saved_log_; const bool saved_prof_lazy_; const bool saved_prof_; const bool saved_prof_auto_; FILE* temp_file_; const bool trick_to_run_init_flags_; v8::HandleScope scope_; v8::Handle 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 str(n + 1); i::OS::StrNCpy(str, s1, static_cast(n)); str[n] = '\0'; char* found = strstr(str.start(), s2); return found != NULL ? s1 + (found - str.start()) : NULL; } TEST(ProfLazyMode) { ScopedLoggerInitializer initialize_logger(true); Logger* logger = initialize_logger.logger(); if (!i::V8::UseCrankshaft()) return; logger->StringEvent("test-start", ""); CompileRun("var a = (function(x) { return x + 1; })(10);"); logger->StringEvent("test-profiler-start", ""); v8::V8::ResumeProfiler(); CompileRun( "var b = (function(x) { return x + 2; })(10);\n" "var c = (function(x) { return x + 3; })(10);\n" "var d = (function(x) { return x + 4; })(10);\n" "var e = (function(x) { return x + 5; })(10);"); v8::V8::PauseProfiler(); logger->StringEvent("test-profiler-stop", ""); CompileRun("var f = (function(x) { return x + 6; })(10);"); // Check that profiling can be resumed again. logger->StringEvent("test-profiler-start-2", ""); v8::V8::ResumeProfiler(); CompileRun( "var g = (function(x) { return x + 7; })(10);\n" "var h = (function(x) { return x + 8; })(10);\n" "var i = (function(x) { return x + 9; })(10);\n" "var j = (function(x) { return x + 10; })(10);"); v8::V8::PauseProfiler(); logger->StringEvent("test-profiler-stop-2", ""); logger->StringEvent("test-stop", ""); bool exists = false; i::Vector log( i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); CHECK(exists); const char* test_start_position = StrNStr(log.start(), "test-start,", log.length()); CHECK_NE(NULL, test_start_position); const char* test_profiler_start_position = StrNStr(log.start(), "test-profiler-start,", log.length()); CHECK_NE(NULL, test_profiler_start_position); CHECK_GT(test_profiler_start_position, test_start_position); const char* test_profiler_stop_position = StrNStr(log.start(), "test-profiler-stop,", log.length()); CHECK_NE(NULL, test_profiler_stop_position); CHECK_GT(test_profiler_stop_position, test_profiler_start_position); const char* test_profiler_start_2_position = StrNStr(log.start(), "test-profiler-start-2,", log.length()); CHECK_NE(NULL, test_profiler_start_2_position); CHECK_GT(test_profiler_start_2_position, test_profiler_stop_position); // Nothing must be logged until profiling is resumed. CHECK_EQ(NULL, StrNStr(test_start_position, "code-creation,", static_cast(test_profiler_start_position - test_start_position))); // Nothing must be logged while profiling is suspended. CHECK_EQ(NULL, StrNStr(test_profiler_stop_position, "code-creation,", static_cast(test_profiler_start_2_position - test_profiler_stop_position))); } // 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_(v8::internal::OS::CreateSemaphore(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(i::Isolate::Current() != NULL); CHECK_GT(i::Isolate::Current()->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(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(i::Isolate::Current() != NULL); CHECK_GT(i::Isolate::Current()->thread_manager()->CurrentId(), 0); double i = 10; SignalRunning(); while (IsRunning()) { i = sin(i); i::OS::Sleep(1); } } }; class TestSampler : public v8::internal::Sampler { public: explicit TestSampler(v8::internal::Isolate* isolate) : Sampler(isolate, 0, true, true), semaphore_(v8::internal::OS::CreateSemaphore(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(v8::internal::Isolate::Current()); sampler->Start(); CHECK(sampler->IsActive()); } LoopingJsThread jsThread(v8::internal::Isolate::Current()); jsThread.Start(); LoopingNonJsThread nonJsThread(v8::internal::Isolate::Current()); 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(v8::Isolate::GetCurrent()); v8::Handle env = v8::Context::New(); env->Enter(); SimpleExternalString source_ext_str("(function ext() {})();"); v8::Local source = v8::String::NewExternal(&source_ext_str); // Script needs to have a name in order to trigger InitLineEnds execution. v8::Handle origin = v8::String::New("issue-23768-test"); v8::Handle evil_script = v8::Script::Compile(source, origin); CHECK(!evil_script.IsEmpty()); CHECK(!evil_script->Run().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. i::Isolate::Current()->logger()->LogCompiledFunctions(); } static v8::Handle ObjMethod1(const v8::Arguments& args) { return v8::Handle(); } TEST(LogCallbacks) { ScopedLoggerInitializer initialize_logger(false); Logger* logger = initialize_logger.logger(); v8::Persistent obj = v8::Persistent::New(v8::Isolate::GetCurrent(), v8::FunctionTemplate::New()); obj->SetClassName(v8_str("Obj")); v8::Handle proto = obj->PrototypeTemplate(); v8::Local signature = v8::Signature::New(obj); proto->Set(v8_str("method1"), v8::FunctionTemplate::New(ObjMethod1, v8::Handle(), signature), static_cast(v8::DontDelete)); initialize_logger.env()->Global()->Set(v8_str("Obj"), obj->GetFunction()); CompileRun("Obj.prototype.method1.toString();"); logger->LogCompiledFunctions(); bool exists = false; i::Vector log( i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); CHECK(exists); i::EmbeddedVector ref_data; i::OS::SNPrintF(ref_data, "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"method1\"\0", ObjMethod1); CHECK_NE(NULL, StrNStr(log.start(), ref_data.start(), log.length())); obj.Dispose(v8::Isolate::GetCurrent()); } static v8::Handle Prop1Getter(v8::Local property, const v8::AccessorInfo& info) { return v8::Handle(); } static void Prop1Setter(v8::Local property, v8::Local value, const v8::AccessorInfo& info) { } static v8::Handle Prop2Getter(v8::Local property, const v8::AccessorInfo& info) { return v8::Handle(); } TEST(LogAccessorCallbacks) { ScopedLoggerInitializer initialize_logger(false); Logger* logger = initialize_logger.logger(); v8::Persistent obj = v8::Persistent::New(v8::Isolate::GetCurrent(), v8::FunctionTemplate::New()); obj->SetClassName(v8_str("Obj")); v8::Handle inst = obj->InstanceTemplate(); inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter); inst->SetAccessor(v8_str("prop2"), Prop2Getter); logger->LogAccessorCallbacks(); bool exists = false; i::Vector log( i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); CHECK(exists); EmbeddedVector prop1_getter_record; i::OS::SNPrintF(prop1_getter_record, "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"get prop1\"", Prop1Getter); CHECK_NE(NULL, StrNStr(log.start(), prop1_getter_record.start(), log.length())); EmbeddedVector prop1_setter_record; i::OS::SNPrintF(prop1_setter_record, "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"set prop1\"", Prop1Setter); CHECK_NE(NULL, StrNStr(log.start(), prop1_setter_record.start(), log.length())); EmbeddedVector prop2_getter_record; i::OS::SNPrintF(prop2_getter_record, "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"get prop2\"", Prop2Getter); CHECK_NE(NULL, StrNStr(log.start(), prop2_getter_record.start(), log.length())); obj.Dispose(v8::Isolate::GetCurrent()); } TEST(IsLoggingPreserved) { ScopedLoggerInitializer initialize_logger(false); Logger* logger = initialize_logger.logger(); CHECK(logger->is_logging()); logger->ResumeProfiler(); CHECK(logger->is_logging()); logger->PauseProfiler(); CHECK(logger->is_logging()); } typedef i::NativesCollection 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. // // P.S. No, V8 can't be re-initialized after disposal, see include/v8.h. CHECK(!i::V8::IsRunning()); // Start with profiling to capture all code events from the beginning. ScopedLoggerInitializer initialize_logger(false); 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);"); v8::V8::PauseProfiler(); 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 log( i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); CHECK(exists); v8::Handle log_str = v8::String::New(log.start(), log.length()); initialize_logger.env()->Global()->Set(v8_str("_log"), log_str); i::Vector source = TestSources::GetScriptsSource(); v8::Handle source_str = v8::String::New( reinterpret_cast(source.start()), source.length()); v8::TryCatch try_catch; v8::Handle script = v8::Script::Compile(source_str, v8_str("")); if (script.IsEmpty()) { v8::String::Utf8Value exception(try_catch.Exception()); printf("compile: %s\n", *exception); CHECK(false); } v8::Handle 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 s = result->ToString(); i::ScopedVector data(s->Length() + 1); CHECK_NE(NULL, data.start()); s->WriteAscii(data.start()); printf("%s\n", data.start()); // Make sure that our output is written prior crash due to CHECK failure. fflush(stdout); CHECK(false); } }