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 #define V8_DISABLE_DEPRECATIONS 1 31 #ifdef __linux__ 32 #include <pthread.h> 33 #include <signal.h> 34 #include <unistd.h> 35 #include <cmath> 36 #endif // __linux__ 37 38 #include "v8.h" 39 #include "log.h" 40 #include "log-utils.h" 41 #include "cpu-profiler.h" 42 #include "natives.h" 43 #include "v8threads.h" 44 #include "v8utils.h" 45 #include "cctest.h" 46 #include "vm-state-inl.h" 47 #undef V8_DISABLE_DEPRECATIONS 48 49 using v8::internal::Address; 50 using v8::internal::EmbeddedVector; 51 using v8::internal::Logger; 52 using v8::internal::StrLength; 53 54 namespace { 55 56 57 class ScopedLoggerInitializer { 58 public: 59 explicit ScopedLoggerInitializer(bool prof_lazy) 60 : saved_log_(i::FLAG_log), 61 saved_prof_lazy_(i::FLAG_prof_lazy), 62 saved_prof_(i::FLAG_prof), 63 temp_file_(NULL), 64 // Need to run this prior to creating the scope. 65 trick_to_run_init_flags_(init_flags_(prof_lazy)), 66 scope_(v8::Isolate::GetCurrent()), 67 env_(v8::Context::New(v8::Isolate::GetCurrent())), 68 logger_(i::Isolate::Current()->logger()) { 69 env_->Enter(); 70 } 71 72 ~ScopedLoggerInitializer() { 73 env_->Exit(); 74 logger_->TearDown(); 75 if (temp_file_ != NULL) fclose(temp_file_); 76 i::FLAG_prof_lazy = saved_prof_lazy_; 77 i::FLAG_prof = saved_prof_; 78 i::FLAG_log = saved_log_; 79 } 80 81 v8::Handle<v8::Context>& env() { return env_; } 82 83 Logger* logger() { return logger_; } 84 85 FILE* StopLoggingGetTempFile() { 86 temp_file_ = logger_->TearDown(); 87 CHECK_NE(NULL, temp_file_); 88 fflush(temp_file_); 89 rewind(temp_file_); 90 return temp_file_; 91 } 92 93 private: 94 static bool init_flags_(bool prof_lazy) { 95 i::FLAG_log = true; 96 i::FLAG_prof = true; 97 i::FLAG_prof_lazy = prof_lazy; 98 i::FLAG_logfile = i::Log::kLogToTemporaryFile; 99 return prof_lazy; 100 } 101 102 const bool saved_log_; 103 const bool saved_prof_lazy_; 104 const bool saved_prof_; 105 FILE* temp_file_; 106 const bool trick_to_run_init_flags_; 107 v8::HandleScope scope_; 108 v8::Handle<v8::Context> env_; 109 Logger* logger_; 110 111 DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); 112 }; 113 114 } // namespace 115 116 117 static const char* StrNStr(const char* s1, const char* s2, int n) { 118 if (s1[n] == '\0') return strstr(s1, s2); 119 i::ScopedVector<char> str(n + 1); 120 i::OS::StrNCpy(str, s1, static_cast<size_t>(n)); 121 str[n] = '\0'; 122 char* found = strstr(str.start(), s2); 123 return found != NULL ? s1 + (found - str.start()) : NULL; 124 } 125 126 127 TEST(ProfLazyMode) { 128 ScopedLoggerInitializer initialize_logger(true); 129 Logger* logger = initialize_logger.logger(); 130 131 if (!i::V8::UseCrankshaft()) return; 132 133 logger->StringEvent("test-start", ""); 134 CompileRun("var a = (function(x) { return x + 1; })(10);"); 135 logger->StringEvent("test-profiler-start", ""); 136 v8::V8::ResumeProfiler(); 137 CompileRun( 138 "var b = (function(x) { return x + 2; })(10);\n" 139 "var c = (function(x) { return x + 3; })(10);\n" 140 "var d = (function(x) { return x + 4; })(10);\n" 141 "var e = (function(x) { return x + 5; })(10);"); 142 v8::V8::PauseProfiler(); 143 logger->StringEvent("test-profiler-stop", ""); 144 CompileRun("var f = (function(x) { return x + 6; })(10);"); 145 // Check that profiling can be resumed again. 146 logger->StringEvent("test-profiler-start-2", ""); 147 v8::V8::ResumeProfiler(); 148 CompileRun( 149 "var g = (function(x) { return x + 7; })(10);\n" 150 "var h = (function(x) { return x + 8; })(10);\n" 151 "var i = (function(x) { return x + 9; })(10);\n" 152 "var j = (function(x) { return x + 10; })(10);"); 153 v8::V8::PauseProfiler(); 154 logger->StringEvent("test-profiler-stop-2", ""); 155 logger->StringEvent("test-stop", ""); 156 157 bool exists = false; 158 i::Vector<const char> log( 159 i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); 160 CHECK(exists); 161 162 const char* test_start_position = 163 StrNStr(log.start(), "test-start,", log.length()); 164 CHECK_NE(NULL, test_start_position); 165 const char* test_profiler_start_position = 166 StrNStr(log.start(), "test-profiler-start,", log.length()); 167 CHECK_NE(NULL, test_profiler_start_position); 168 CHECK_GT(test_profiler_start_position, test_start_position); 169 const char* test_profiler_stop_position = 170 StrNStr(log.start(), "test-profiler-stop,", log.length()); 171 CHECK_NE(NULL, test_profiler_stop_position); 172 CHECK_GT(test_profiler_stop_position, test_profiler_start_position); 173 const char* test_profiler_start_2_position = 174 StrNStr(log.start(), "test-profiler-start-2,", log.length()); 175 CHECK_NE(NULL, test_profiler_start_2_position); 176 CHECK_GT(test_profiler_start_2_position, test_profiler_stop_position); 177 178 // Nothing must be logged until profiling is resumed. 179 CHECK_EQ(NULL, StrNStr(test_start_position, 180 "code-creation,", 181 static_cast<int>(test_profiler_start_position - 182 test_start_position))); 183 // Nothing must be logged while profiling is suspended. 184 CHECK_EQ(NULL, StrNStr(test_profiler_stop_position, 185 "code-creation,", 186 static_cast<int>(test_profiler_start_2_position - 187 test_profiler_stop_position))); 188 } 189 190 191 // BUG(913). Need to implement support for profiling multiple VM threads. 192 #if 0 193 194 namespace { 195 196 class LoopingThread : public v8::internal::Thread { 197 public: 198 explicit LoopingThread(v8::internal::Isolate* isolate) 199 : v8::internal::Thread(isolate), 200 semaphore_(v8::internal::OS::CreateSemaphore(0)), 201 run_(true) { 202 } 203 204 virtual ~LoopingThread() { delete semaphore_; } 205 206 void Run() { 207 self_ = pthread_self(); 208 RunLoop(); 209 } 210 211 void SendSigProf() { pthread_kill(self_, SIGPROF); } 212 213 void Stop() { run_ = false; } 214 215 bool WaitForRunning() { return semaphore_->Wait(1000000); } 216 217 protected: 218 bool IsRunning() { return run_; } 219 220 virtual void RunLoop() = 0; 221 222 void SetV8ThreadId() { 223 v8_thread_id_ = v8::V8::GetCurrentThreadId(); 224 } 225 226 void SignalRunning() { semaphore_->Signal(); } 227 228 private: 229 v8::internal::Semaphore* semaphore_; 230 bool run_; 231 pthread_t self_; 232 int v8_thread_id_; 233 }; 234 235 236 class LoopingJsThread : public LoopingThread { 237 public: 238 explicit LoopingJsThread(v8::internal::Isolate* isolate) 239 : LoopingThread(isolate) { } 240 void RunLoop() { 241 v8::Locker locker; 242 CHECK(i::Isolate::Current() != NULL); 243 CHECK_GT(i::Isolate::Current()->thread_manager()->CurrentId(), 0); 244 SetV8ThreadId(); 245 while (IsRunning()) { 246 v8::HandleScope scope; 247 v8::Persistent<v8::Context> context = v8::Context::New(); 248 CHECK(!context.IsEmpty()); 249 { 250 v8::Context::Scope context_scope(context); 251 SignalRunning(); 252 CompileRun( 253 "var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }"); 254 } 255 context.Dispose(); 256 i::OS::Sleep(1); 257 } 258 } 259 }; 260 261 262 class LoopingNonJsThread : public LoopingThread { 263 public: 264 explicit LoopingNonJsThread(v8::internal::Isolate* isolate) 265 : LoopingThread(isolate) { } 266 void RunLoop() { 267 v8::Locker locker; 268 v8::Unlocker unlocker; 269 // Now thread has V8's id, but will not run VM code. 270 CHECK(i::Isolate::Current() != NULL); 271 CHECK_GT(i::Isolate::Current()->thread_manager()->CurrentId(), 0); 272 double i = 10; 273 SignalRunning(); 274 while (IsRunning()) { 275 i = sin(i); 276 i::OS::Sleep(1); 277 } 278 } 279 }; 280 281 282 class TestSampler : public v8::internal::Sampler { 283 public: 284 explicit TestSampler(v8::internal::Isolate* isolate) 285 : Sampler(isolate, 0, true, true), 286 semaphore_(v8::internal::OS::CreateSemaphore(0)), 287 was_sample_stack_called_(false) { 288 } 289 290 ~TestSampler() { delete semaphore_; } 291 292 void SampleStack(v8::internal::TickSample*) { 293 was_sample_stack_called_ = true; 294 } 295 296 void Tick(v8::internal::TickSample*) { semaphore_->Signal(); } 297 298 bool WaitForTick() { return semaphore_->Wait(1000000); } 299 300 void Reset() { was_sample_stack_called_ = false; } 301 302 bool WasSampleStackCalled() { return was_sample_stack_called_; } 303 304 private: 305 v8::internal::Semaphore* semaphore_; 306 bool was_sample_stack_called_; 307 }; 308 309 310 } // namespace 311 312 TEST(ProfMultipleThreads) { 313 TestSampler* sampler = NULL; 314 { 315 v8::Locker locker; 316 sampler = new TestSampler(v8::internal::Isolate::Current()); 317 sampler->Start(); 318 CHECK(sampler->IsActive()); 319 } 320 321 LoopingJsThread jsThread(v8::internal::Isolate::Current()); 322 jsThread.Start(); 323 LoopingNonJsThread nonJsThread(v8::internal::Isolate::Current()); 324 nonJsThread.Start(); 325 326 CHECK(!sampler->WasSampleStackCalled()); 327 jsThread.WaitForRunning(); 328 jsThread.SendSigProf(); 329 CHECK(sampler->WaitForTick()); 330 CHECK(sampler->WasSampleStackCalled()); 331 sampler->Reset(); 332 CHECK(!sampler->WasSampleStackCalled()); 333 nonJsThread.WaitForRunning(); 334 nonJsThread.SendSigProf(); 335 CHECK(!sampler->WaitForTick()); 336 CHECK(!sampler->WasSampleStackCalled()); 337 sampler->Stop(); 338 339 jsThread.Stop(); 340 nonJsThread.Stop(); 341 jsThread.Join(); 342 nonJsThread.Join(); 343 344 delete sampler; 345 } 346 347 #endif // __linux__ 348 349 350 // Test for issue http://crbug.com/23768 in Chromium. 351 // Heap can contain scripts with already disposed external sources. 352 // We need to verify that LogCompiledFunctions doesn't crash on them. 353 namespace { 354 355 class SimpleExternalString : public v8::String::ExternalStringResource { 356 public: 357 explicit SimpleExternalString(const char* source) 358 : utf_source_(StrLength(source)) { 359 for (int i = 0; i < utf_source_.length(); ++i) 360 utf_source_[i] = source[i]; 361 } 362 virtual ~SimpleExternalString() {} 363 virtual size_t length() const { return utf_source_.length(); } 364 virtual const uint16_t* data() const { return utf_source_.start(); } 365 private: 366 i::ScopedVector<uint16_t> utf_source_; 367 }; 368 369 } // namespace 370 371 TEST(Issue23768) { 372 v8::HandleScope scope(v8::Isolate::GetCurrent()); 373 v8::Handle<v8::Context> env = v8::Context::New(v8::Isolate::GetCurrent()); 374 env->Enter(); 375 376 SimpleExternalString source_ext_str("(function ext() {})();"); 377 v8::Local<v8::String> source = v8::String::NewExternal(&source_ext_str); 378 // Script needs to have a name in order to trigger InitLineEnds execution. 379 v8::Handle<v8::String> origin = v8::String::New("issue-23768-test"); 380 v8::Handle<v8::Script> evil_script = v8::Script::Compile(source, origin); 381 CHECK(!evil_script.IsEmpty()); 382 CHECK(!evil_script->Run().IsEmpty()); 383 i::Handle<i::ExternalTwoByteString> i_source( 384 i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source))); 385 // This situation can happen if source was an external string disposed 386 // by its owner. 387 i_source->set_resource(NULL); 388 389 // Must not crash. 390 i::Isolate::Current()->logger()->LogCompiledFunctions(); 391 } 392 393 394 static void ObjMethod1(const v8::FunctionCallbackInfo<v8::Value>& args) { 395 } 396 397 398 TEST(LogCallbacks) { 399 ScopedLoggerInitializer initialize_logger(false); 400 Logger* logger = initialize_logger.logger(); 401 402 v8::Local<v8::FunctionTemplate> obj = 403 v8::Local<v8::FunctionTemplate>::New(v8::Isolate::GetCurrent(), 404 v8::FunctionTemplate::New()); 405 obj->SetClassName(v8_str("Obj")); 406 v8::Handle<v8::ObjectTemplate> proto = obj->PrototypeTemplate(); 407 v8::Local<v8::Signature> signature = v8::Signature::New(obj); 408 proto->Set(v8_str("method1"), 409 v8::FunctionTemplate::New(ObjMethod1, 410 v8::Handle<v8::Value>(), 411 signature), 412 static_cast<v8::PropertyAttribute>(v8::DontDelete)); 413 414 initialize_logger.env()->Global()->Set(v8_str("Obj"), obj->GetFunction()); 415 CompileRun("Obj.prototype.method1.toString();"); 416 417 logger->LogCompiledFunctions(); 418 419 bool exists = false; 420 i::Vector<const char> log( 421 i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); 422 CHECK(exists); 423 424 i::EmbeddedVector<char, 100> ref_data; 425 i::OS::SNPrintF(ref_data, 426 "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"method1\"\0", 427 ObjMethod1); 428 429 CHECK_NE(NULL, StrNStr(log.start(), ref_data.start(), log.length())); 430 } 431 432 433 static void Prop1Getter(v8::Local<v8::String> property, 434 const v8::PropertyCallbackInfo<v8::Value>& info) { 435 } 436 437 static void Prop1Setter(v8::Local<v8::String> property, 438 v8::Local<v8::Value> value, 439 const v8::PropertyCallbackInfo<void>& info) { 440 } 441 442 static void Prop2Getter(v8::Local<v8::String> property, 443 const v8::PropertyCallbackInfo<v8::Value>& info) { 444 } 445 446 447 TEST(LogAccessorCallbacks) { 448 ScopedLoggerInitializer initialize_logger(false); 449 Logger* logger = initialize_logger.logger(); 450 451 v8::Local<v8::FunctionTemplate> obj = 452 v8::Local<v8::FunctionTemplate>::New(v8::Isolate::GetCurrent(), 453 v8::FunctionTemplate::New()); 454 obj->SetClassName(v8_str("Obj")); 455 v8::Handle<v8::ObjectTemplate> inst = obj->InstanceTemplate(); 456 inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter); 457 inst->SetAccessor(v8_str("prop2"), Prop2Getter); 458 459 logger->LogAccessorCallbacks(); 460 461 bool exists = false; 462 i::Vector<const char> log( 463 i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); 464 CHECK(exists); 465 466 EmbeddedVector<char, 100> prop1_getter_record; 467 i::OS::SNPrintF(prop1_getter_record, 468 "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"get prop1\"", 469 Prop1Getter); 470 CHECK_NE(NULL, 471 StrNStr(log.start(), prop1_getter_record.start(), log.length())); 472 473 EmbeddedVector<char, 100> prop1_setter_record; 474 i::OS::SNPrintF(prop1_setter_record, 475 "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"set prop1\"", 476 Prop1Setter); 477 CHECK_NE(NULL, 478 StrNStr(log.start(), prop1_setter_record.start(), log.length())); 479 480 EmbeddedVector<char, 100> prop2_getter_record; 481 i::OS::SNPrintF(prop2_getter_record, 482 "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"get prop2\"", 483 Prop2Getter); 484 CHECK_NE(NULL, 485 StrNStr(log.start(), prop2_getter_record.start(), log.length())); 486 } 487 488 489 TEST(IsLoggingPreserved) { 490 ScopedLoggerInitializer initialize_logger(false); 491 Logger* logger = initialize_logger.logger(); 492 493 CHECK(logger->is_logging()); 494 logger->ResumeProfiler(); 495 CHECK(logger->is_logging()); 496 logger->PauseProfiler(); 497 CHECK(logger->is_logging()); 498 } 499 500 501 typedef i::NativesCollection<i::TEST> TestSources; 502 503 504 // Test that logging of code create / move events is equivalent to traversal of 505 // a resulting heap. 506 TEST(EquivalenceOfLoggingAndTraversal) { 507 // This test needs to be run on a "clean" V8 to ensure that snapshot log 508 // is loaded. This is always true when running using tools/test.py because 509 // it launches a new cctest instance for every test. To be sure that launching 510 // cctest manually also works, please be sure that no tests below 511 // are using V8. 512 // 513 // P.S. No, V8 can't be re-initialized after disposal, see include/v8.h. 514 CHECK(!i::V8::IsRunning()); 515 516 // Start with profiling to capture all code events from the beginning. 517 ScopedLoggerInitializer initialize_logger(false); 518 Logger* logger = initialize_logger.logger(); 519 520 // Compile and run a function that creates other functions. 521 CompileRun( 522 "(function f(obj) {\n" 523 " obj.test =\n" 524 " (function a(j) { return function b() { return j; } })(100);\n" 525 "})(this);"); 526 v8::V8::PauseProfiler(); 527 HEAP->CollectAllGarbage(i::Heap::kMakeHeapIterableMask); 528 logger->StringEvent("test-logging-done", ""); 529 530 // Iterate heap to find compiled functions, will write to log. 531 logger->LogCompiledFunctions(); 532 logger->StringEvent("test-traversal-done", ""); 533 534 bool exists = false; 535 i::Vector<const char> log( 536 i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true)); 537 CHECK(exists); 538 v8::Handle<v8::String> log_str = v8::String::New(log.start(), log.length()); 539 initialize_logger.env()->Global()->Set(v8_str("_log"), log_str); 540 541 i::Vector<const unsigned char> source = TestSources::GetScriptsSource(); 542 v8::Handle<v8::String> source_str = v8::String::New( 543 reinterpret_cast<const char*>(source.start()), source.length()); 544 v8::TryCatch try_catch; 545 v8::Handle<v8::Script> script = v8::Script::Compile(source_str, v8_str("")); 546 if (script.IsEmpty()) { 547 v8::String::Utf8Value exception(try_catch.Exception()); 548 printf("compile: %s\n", *exception); 549 CHECK(false); 550 } 551 v8::Handle<v8::Value> result = script->Run(); 552 if (result.IsEmpty()) { 553 v8::String::Utf8Value exception(try_catch.Exception()); 554 printf("run: %s\n", *exception); 555 CHECK(false); 556 } 557 // The result either be a "true" literal or problem description. 558 if (!result->IsTrue()) { 559 v8::Local<v8::String> s = result->ToString(); 560 i::ScopedVector<char> data(s->Utf8Length() + 1); 561 CHECK_NE(NULL, data.start()); 562 s->WriteUtf8(data.start()); 563 printf("%s\n", data.start()); 564 // Make sure that our output is written prior crash due to CHECK failure. 565 fflush(stdout); 566 CHECK(false); 567 } 568 } 569