1// Copyright 2006-2009 the V8 project authors. All rights reserved. 2// Redistribution and use in source and binary forms, with or without 3// modification, are permitted provided that the following conditions are 4// met: 5// 6// * Redistributions of source code must retain the above copyright 7// notice, this list of conditions and the following disclaimer. 8// * Redistributions in binary form must reproduce the above 9// copyright notice, this list of conditions and the following 10// disclaimer in the documentation and/or other materials provided 11// with the distribution. 12// * Neither the name of Google Inc. nor the names of its 13// contributors may be used to endorse or promote products derived 14// from this software without specific prior written permission. 15// 16// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS 17// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT 18// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR 19// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT 20// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, 21// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT 22// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, 23// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY 24// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT 25// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE 26// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. 27// 28// Tests of logging functions from log.h 29 30#ifdef __linux__ 31#include <pthread.h> 32#include <signal.h> 33#include <unistd.h> 34#include <cmath> 35#endif // __linux__ 36 37#include "v8.h" 38#include "log.h" 39#include "log-utils.h" 40#include "cpu-profiler.h" 41#include "natives.h" 42#include "v8threads.h" 43#include "v8utils.h" 44#include "cctest.h" 45#include "vm-state-inl.h" 46 47using v8::internal::Address; 48using v8::internal::EmbeddedVector; 49using v8::internal::Logger; 50using v8::internal::StrLength; 51 52namespace { 53 54 55class ScopedLoggerInitializer { 56 public: 57 ScopedLoggerInitializer() 58 : saved_log_(i::FLAG_log), 59 saved_prof_(i::FLAG_prof), 60 temp_file_(NULL), 61 // Need to run this prior to creating the scope. 62 trick_to_run_init_flags_(init_flags_()), 63 scope_(CcTest::isolate()), 64 env_(v8::Context::New(CcTest::isolate())), 65 logger_(CcTest::i_isolate()->logger()) { 66 env_->Enter(); 67 } 68 69 ~ScopedLoggerInitializer() { 70 env_->Exit(); 71 logger_->TearDown(); 72 if (temp_file_ != NULL) fclose(temp_file_); 73 i::FLAG_prof = saved_prof_; 74 i::FLAG_log = saved_log_; 75 } 76 77 v8::Handle<v8::Context>& env() { return env_; } 78 79 Logger* logger() { return logger_; } 80 81 FILE* StopLoggingGetTempFile() { 82 temp_file_ = logger_->TearDown(); 83 CHECK_NE(NULL, temp_file_); 84 fflush(temp_file_); 85 rewind(temp_file_); 86 return temp_file_; 87 } 88 89 private: 90 static bool init_flags_() { 91 i::FLAG_log = true; 92 i::FLAG_prof = true; 93 i::FLAG_logfile = i::Log::kLogToTemporaryFile; 94 i::FLAG_logfile_per_isolate = false; 95 return false; 96 } 97 98 const bool saved_log_; 99 const bool saved_prof_; 100 FILE* temp_file_; 101 const bool trick_to_run_init_flags_; 102 v8::HandleScope scope_; 103 v8::Handle<v8::Context> env_; 104 Logger* logger_; 105 106 DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); 107}; 108 109} // namespace 110 111 112static const char* StrNStr(const char* s1, const char* s2, int n) { 113 if (s1[n] == '\0') return strstr(s1, s2); 114 i::ScopedVector<char> str(n + 1); 115 i::OS::StrNCpy(str, s1, static_cast<size_t>(n)); 116 str[n] = '\0'; 117 char* found = strstr(str.start(), s2); 118 return found != NULL ? s1 + (found - str.start()) : NULL; 119} 120 121 122// BUG(913). Need to implement support for profiling multiple VM threads. 123#if 0 124 125namespace { 126 127class LoopingThread : public v8::internal::Thread { 128 public: 129 explicit LoopingThread(v8::internal::Isolate* isolate) 130 : v8::internal::Thread(isolate), 131 semaphore_(new v8::internal::Semaphore(0)), 132 run_(true) { 133 } 134 135 virtual ~LoopingThread() { delete semaphore_; } 136 137 void Run() { 138 self_ = pthread_self(); 139 RunLoop(); 140 } 141 142 void SendSigProf() { pthread_kill(self_, SIGPROF); } 143 144 void Stop() { run_ = false; } 145 146 bool WaitForRunning() { return semaphore_->Wait(1000000); } 147 148 protected: 149 bool IsRunning() { return run_; } 150 151 virtual void RunLoop() = 0; 152 153 void SetV8ThreadId() { 154 v8_thread_id_ = v8::V8::GetCurrentThreadId(); 155 } 156 157 void SignalRunning() { semaphore_->Signal(); } 158 159 private: 160 v8::internal::Semaphore* semaphore_; 161 bool run_; 162 pthread_t self_; 163 int v8_thread_id_; 164}; 165 166 167class LoopingJsThread : public LoopingThread { 168 public: 169 explicit LoopingJsThread(v8::internal::Isolate* isolate) 170 : LoopingThread(isolate) { } 171 void RunLoop() { 172 v8::Locker locker; 173 CHECK(CcTest::i_isolate() != NULL); 174 CHECK_GT(CcTest::i_isolate()->thread_manager()->CurrentId(), 0); 175 SetV8ThreadId(); 176 while (IsRunning()) { 177 v8::HandleScope scope; 178 v8::Persistent<v8::Context> context = v8::Context::New(); 179 CHECK(!context.IsEmpty()); 180 { 181 v8::Context::Scope context_scope(context); 182 SignalRunning(); 183 CompileRun( 184 "var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }"); 185 } 186 context.Dispose(); 187 i::OS::Sleep(1); 188 } 189 } 190}; 191 192 193class LoopingNonJsThread : public LoopingThread { 194 public: 195 explicit LoopingNonJsThread(v8::internal::Isolate* isolate) 196 : LoopingThread(isolate) { } 197 void RunLoop() { 198 v8::Locker locker; 199 v8::Unlocker unlocker; 200 // Now thread has V8's id, but will not run VM code. 201 CHECK(CcTest::i_isolate() != NULL); 202 CHECK_GT(CcTest::i_isolate()->thread_manager()->CurrentId(), 0); 203 double i = 10; 204 SignalRunning(); 205 while (IsRunning()) { 206 i = sin(i); 207 i::OS::Sleep(1); 208 } 209 } 210}; 211 212 213class TestSampler : public v8::internal::Sampler { 214 public: 215 explicit TestSampler(v8::internal::Isolate* isolate) 216 : Sampler(isolate, 0, true, true), 217 semaphore_(new v8::internal::Semaphore(0)), 218 was_sample_stack_called_(false) { 219 } 220 221 ~TestSampler() { delete semaphore_; } 222 223 void SampleStack(v8::internal::TickSample*) { 224 was_sample_stack_called_ = true; 225 } 226 227 void Tick(v8::internal::TickSample*) { semaphore_->Signal(); } 228 229 bool WaitForTick() { return semaphore_->Wait(1000000); } 230 231 void Reset() { was_sample_stack_called_ = false; } 232 233 bool WasSampleStackCalled() { return was_sample_stack_called_; } 234 235 private: 236 v8::internal::Semaphore* semaphore_; 237 bool was_sample_stack_called_; 238}; 239 240 241} // namespace 242 243TEST(ProfMultipleThreads) { 244 TestSampler* sampler = NULL; 245 { 246 v8::Locker locker; 247 sampler = new TestSampler(CcTest::i_isolate()); 248 sampler->Start(); 249 CHECK(sampler->IsActive()); 250 } 251 252 LoopingJsThread jsThread(CcTest::i_isolate()); 253 jsThread.Start(); 254 LoopingNonJsThread nonJsThread(CcTest::i_isolate()); 255 nonJsThread.Start(); 256 257 CHECK(!sampler->WasSampleStackCalled()); 258 jsThread.WaitForRunning(); 259 jsThread.SendSigProf(); 260 CHECK(sampler->WaitForTick()); 261 CHECK(sampler->WasSampleStackCalled()); 262 sampler->Reset(); 263 CHECK(!sampler->WasSampleStackCalled()); 264 nonJsThread.WaitForRunning(); 265 nonJsThread.SendSigProf(); 266 CHECK(!sampler->WaitForTick()); 267 CHECK(!sampler->WasSampleStackCalled()); 268 sampler->Stop(); 269 270 jsThread.Stop(); 271 nonJsThread.Stop(); 272 jsThread.Join(); 273 nonJsThread.Join(); 274 275 delete sampler; 276} 277 278#endif // __linux__ 279 280 281// Test for issue http://crbug.com/23768 in Chromium. 282// Heap can contain scripts with already disposed external sources. 283// We need to verify that LogCompiledFunctions doesn't crash on them. 284namespace { 285 286class SimpleExternalString : public v8::String::ExternalStringResource { 287 public: 288 explicit SimpleExternalString(const char* source) 289 : utf_source_(StrLength(source)) { 290 for (int i = 0; i < utf_source_.length(); ++i) 291 utf_source_[i] = source[i]; 292 } 293 virtual ~SimpleExternalString() {} 294 virtual size_t length() const { return utf_source_.length(); } 295 virtual const uint16_t* data() const { return utf_source_.start(); } 296 private: 297 i::ScopedVector<uint16_t> utf_source_; 298}; 299 300} // namespace 301 302TEST(Issue23768) { 303 v8::HandleScope scope(CcTest::isolate()); 304 v8::Handle<v8::Context> env = v8::Context::New(CcTest::isolate()); 305 env->Enter(); 306 307 SimpleExternalString source_ext_str("(function ext() {})();"); 308 v8::Local<v8::String> source = 309 v8::String::NewExternal(CcTest::isolate(), &source_ext_str); 310 // Script needs to have a name in order to trigger InitLineEnds execution. 311 v8::Handle<v8::String> origin = 312 v8::String::NewFromUtf8(CcTest::isolate(), "issue-23768-test"); 313 v8::Handle<v8::Script> evil_script = v8::Script::Compile(source, origin); 314 CHECK(!evil_script.IsEmpty()); 315 CHECK(!evil_script->Run().IsEmpty()); 316 i::Handle<i::ExternalTwoByteString> i_source( 317 i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source))); 318 // This situation can happen if source was an external string disposed 319 // by its owner. 320 i_source->set_resource(NULL); 321 322 // Must not crash. 323 CcTest::i_isolate()->logger()->LogCompiledFunctions(); 324} 325 326 327static void ObjMethod1(const v8::FunctionCallbackInfo<v8::Value>& args) { 328} 329 330 331TEST(LogCallbacks) { 332 ScopedLoggerInitializer initialize_logger; 333 Logger* logger = initialize_logger.logger(); 334 335 v8::Local<v8::FunctionTemplate> obj = 336 v8::Local<v8::FunctionTemplate>::New(CcTest::isolate(), 337 v8::FunctionTemplate::New()); 338 obj->SetClassName(v8_str("Obj")); 339 v8::Handle<v8::ObjectTemplate> proto = obj->PrototypeTemplate(); 340 v8::Local<v8::Signature> signature = 341 v8::Signature::New(CcTest::isolate(), obj); 342 proto->Set(v8_str("method1"), 343 v8::FunctionTemplate::New(ObjMethod1, 344 v8::Handle<v8::Value>(), 345 signature), 346 static_cast<v8::PropertyAttribute>(v8::DontDelete)); 347 348 initialize_logger.env()->Global()->Set(v8_str("Obj"), obj->GetFunction()); 349 CompileRun("Obj.prototype.method1.toString();"); 350 351 logger->LogCompiledFunctions(); 352 353 bool exists = false; 354 i::Vector<const char> log( 355 i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); 356 CHECK(exists); 357 358 i::EmbeddedVector<char, 100> ref_data; 359 i::OS::SNPrintF(ref_data, 360 "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"method1\"\0", 361 ObjMethod1); 362 363 CHECK_NE(NULL, StrNStr(log.start(), ref_data.start(), log.length())); 364} 365 366 367static void Prop1Getter(v8::Local<v8::String> property, 368 const v8::PropertyCallbackInfo<v8::Value>& info) { 369} 370 371static void Prop1Setter(v8::Local<v8::String> property, 372 v8::Local<v8::Value> value, 373 const v8::PropertyCallbackInfo<void>& info) { 374} 375 376static void Prop2Getter(v8::Local<v8::String> property, 377 const v8::PropertyCallbackInfo<v8::Value>& info) { 378} 379 380 381TEST(LogAccessorCallbacks) { 382 ScopedLoggerInitializer initialize_logger; 383 Logger* logger = initialize_logger.logger(); 384 385 v8::Local<v8::FunctionTemplate> obj = 386 v8::Local<v8::FunctionTemplate>::New(CcTest::isolate(), 387 v8::FunctionTemplate::New()); 388 obj->SetClassName(v8_str("Obj")); 389 v8::Handle<v8::ObjectTemplate> inst = obj->InstanceTemplate(); 390 inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter); 391 inst->SetAccessor(v8_str("prop2"), Prop2Getter); 392 393 logger->LogAccessorCallbacks(); 394 395 bool exists = false; 396 i::Vector<const char> log( 397 i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); 398 CHECK(exists); 399 400 EmbeddedVector<char, 100> prop1_getter_record; 401 i::OS::SNPrintF(prop1_getter_record, 402 "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"get prop1\"", 403 Prop1Getter); 404 CHECK_NE(NULL, 405 StrNStr(log.start(), prop1_getter_record.start(), log.length())); 406 407 EmbeddedVector<char, 100> prop1_setter_record; 408 i::OS::SNPrintF(prop1_setter_record, 409 "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"set prop1\"", 410 Prop1Setter); 411 CHECK_NE(NULL, 412 StrNStr(log.start(), prop1_setter_record.start(), log.length())); 413 414 EmbeddedVector<char, 100> prop2_getter_record; 415 i::OS::SNPrintF(prop2_getter_record, 416 "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"get prop2\"", 417 Prop2Getter); 418 CHECK_NE(NULL, 419 StrNStr(log.start(), prop2_getter_record.start(), log.length())); 420} 421 422 423typedef i::NativesCollection<i::TEST> TestSources; 424 425 426// Test that logging of code create / move events is equivalent to traversal of 427// a resulting heap. 428TEST(EquivalenceOfLoggingAndTraversal) { 429 // This test needs to be run on a "clean" V8 to ensure that snapshot log 430 // is loaded. This is always true when running using tools/test.py because 431 // it launches a new cctest instance for every test. To be sure that launching 432 // cctest manually also works, please be sure that no tests below 433 // are using V8. 434 435 // Start with profiling to capture all code events from the beginning. 436 ScopedLoggerInitializer initialize_logger; 437 Logger* logger = initialize_logger.logger(); 438 439 // Compile and run a function that creates other functions. 440 CompileRun( 441 "(function f(obj) {\n" 442 " obj.test =\n" 443 " (function a(j) { return function b() { return j; } })(100);\n" 444 "})(this);"); 445 logger->StopProfiler(); 446 CcTest::heap()->CollectAllGarbage(i::Heap::kMakeHeapIterableMask); 447 logger->StringEvent("test-logging-done", ""); 448 449 // Iterate heap to find compiled functions, will write to log. 450 logger->LogCompiledFunctions(); 451 logger->StringEvent("test-traversal-done", ""); 452 453 bool exists = false; 454 i::Vector<const char> log( 455 i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); 456 CHECK(exists); 457 v8::Handle<v8::String> log_str = v8::String::NewFromUtf8( 458 CcTest::isolate(), log.start(), v8::String::kNormalString, log.length()); 459 initialize_logger.env()->Global()->Set(v8_str("_log"), log_str); 460 461 i::Vector<const unsigned char> source = TestSources::GetScriptsSource(); 462 v8::Handle<v8::String> source_str = v8::String::NewFromUtf8( 463 CcTest::isolate(), reinterpret_cast<const char*>(source.start()), 464 v8::String::kNormalString, source.length()); 465 v8::TryCatch try_catch; 466 v8::Handle<v8::Script> script = v8::Script::Compile(source_str, v8_str("")); 467 if (script.IsEmpty()) { 468 v8::String::Utf8Value exception(try_catch.Exception()); 469 printf("compile: %s\n", *exception); 470 CHECK(false); 471 } 472 v8::Handle<v8::Value> result = script->Run(); 473 if (result.IsEmpty()) { 474 v8::String::Utf8Value exception(try_catch.Exception()); 475 printf("run: %s\n", *exception); 476 CHECK(false); 477 } 478 // The result either be a "true" literal or problem description. 479 if (!result->IsTrue()) { 480 v8::Local<v8::String> s = result->ToString(); 481 i::ScopedVector<char> data(s->Utf8Length() + 1); 482 CHECK_NE(NULL, data.start()); 483 s->WriteUtf8(data.start()); 484 printf("%s\n", data.start()); 485 // Make sure that our output is written prior crash due to CHECK failure. 486 fflush(stdout); 487 CHECK(false); 488 } 489} 490