| OLD | NEW |
| 1 // Copyright 2006-2009 the V8 project authors. All rights reserved. | 1 // Copyright 2006-2009 the V8 project authors. All rights reserved. |
| 2 // | 2 // |
| 3 // Tests of logging functions from log.h | 3 // Tests of logging functions from log.h |
| 4 | 4 |
| 5 #ifdef ENABLE_LOGGING_AND_PROFILING | 5 #ifdef ENABLE_LOGGING_AND_PROFILING |
| 6 | 6 |
| 7 #ifdef __linux__ | 7 #ifdef __linux__ |
| 8 #include <math.h> | 8 #include <math.h> |
| 9 #include <pthread.h> | 9 #include <pthread.h> |
| 10 #include <signal.h> | 10 #include <signal.h> |
| 11 #include <unistd.h> | 11 #include <unistd.h> |
| 12 #endif // __linux__ | 12 #endif // __linux__ |
| 13 | 13 |
| 14 #include "v8.h" | 14 #include "v8.h" |
| 15 #include "log.h" | 15 #include "log.h" |
| 16 #include "cpu-profiler.h" | 16 #include "cpu-profiler.h" |
| 17 #include "v8threads.h" | 17 #include "v8threads.h" |
| 18 #include "cctest.h" | 18 #include "cctest.h" |
| 19 #include "vm-state-inl.h" |
| 19 | 20 |
| 20 using v8::internal::Address; | 21 using v8::internal::Address; |
| 21 using v8::internal::EmbeddedVector; | 22 using v8::internal::EmbeddedVector; |
| 22 using v8::internal::Logger; | 23 using v8::internal::Logger; |
| 23 using v8::internal::StrLength; | 24 using v8::internal::StrLength; |
| 24 | 25 |
| 25 namespace i = v8::internal; | 26 namespace i = v8::internal; |
| 26 | 27 |
| 27 static void SetUp() { | 28 static void SetUp() { |
| 28 // Log to memory buffer. | 29 // Log to memory buffer. |
| (...skipping 210 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 239 | 240 |
| 240 private: | 241 private: |
| 241 EmbeddedVector<char, 102400> buffer_; | 242 EmbeddedVector<char, 102400> buffer_; |
| 242 int log_pos_; | 243 int log_pos_; |
| 243 }; | 244 }; |
| 244 | 245 |
| 245 } // namespace | 246 } // namespace |
| 246 | 247 |
| 247 | 248 |
| 248 static void CheckThatProfilerWorks(LogBufferMatcher* matcher) { | 249 static void CheckThatProfilerWorks(LogBufferMatcher* matcher) { |
| 249 CHECK(!LoggerTestHelper::IsSamplerActive()); | 250 CHECK(i::RuntimeProfiler::IsEnabled() || |
| 251 !LoggerTestHelper::IsSamplerActive()); |
| 250 LoggerTestHelper::ResetSamplesTaken(); | 252 LoggerTestHelper::ResetSamplesTaken(); |
| 251 | 253 |
| 252 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 0); | 254 LOGGER->ResumeProfiler(v8::PROFILER_MODULE_CPU, 0); |
| 253 CHECK(LoggerTestHelper::IsSamplerActive()); | 255 CHECK(LoggerTestHelper::IsSamplerActive()); |
| 254 | 256 |
| 255 // Verify that the current map of compiled functions has been logged. | 257 // Verify that the current map of compiled functions has been logged. |
| 256 CHECK_GT(matcher->GetNextChunk(), 0); | 258 CHECK_GT(matcher->GetNextChunk(), 0); |
| 257 const char* code_creation = "\ncode-creation,"; // eq. to /^code-creation,/ | 259 const char* code_creation = "\ncode-creation,"; // eq. to /^code-creation,/ |
| 258 CHECK_NE(NULL, matcher->Find(code_creation)); | 260 CHECK_NE(NULL, matcher->Find(code_creation)); |
| 259 | 261 |
| 260 // Force compiler to generate new code by parametrizing source. | 262 // Force compiler to generate new code by parametrizing source. |
| 261 EmbeddedVector<char, 100> script_src; | 263 EmbeddedVector<char, 100> script_src; |
| 262 i::OS::SNPrintF(script_src, | 264 i::OS::SNPrintF(script_src, |
| 263 "function f%d(x) { return %d * x; }" | 265 "function f%d(x) { return %d * x; }" |
| 264 "for (var i = 0; i < 10000; ++i) { f%d(i); }", | 266 "for (var i = 0; i < 10000; ++i) { f%d(i); }", |
| 265 matcher->log_pos(), matcher->log_pos(), matcher->log_pos()); | 267 matcher->log_pos(), matcher->log_pos(), matcher->log_pos()); |
| 266 // Run code for 200 msecs to get some ticks. | 268 // Run code for 200 msecs to get some ticks. |
| 267 const double end_time = i::OS::TimeCurrentMillis() + 200; | 269 const double end_time = i::OS::TimeCurrentMillis() + 200; |
| 268 while (i::OS::TimeCurrentMillis() < end_time) { | 270 while (i::OS::TimeCurrentMillis() < end_time) { |
| 269 CompileAndRunScript(script_src.start()); | 271 CompileAndRunScript(script_src.start()); |
| 270 // Yield CPU to give Profiler thread a chance to process ticks. | 272 // Yield CPU to give Profiler thread a chance to process ticks. |
| 271 i::OS::Sleep(1); | 273 i::OS::Sleep(1); |
| 272 } | 274 } |
| 273 | 275 |
| 274 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 0); | 276 LOGGER->PauseProfiler(v8::PROFILER_MODULE_CPU, 0); |
| 275 CHECK(!LoggerTestHelper::IsSamplerActive()); | 277 CHECK(i::RuntimeProfiler::IsEnabled() || |
| 278 !LoggerTestHelper::IsSamplerActive()); |
| 276 | 279 |
| 277 // Wait 50 msecs to allow Profiler thread to process the last | 280 // Wait 50 msecs to allow Profiler thread to process the last |
| 278 // tick sample it has got. | 281 // tick sample it has got. |
| 279 i::OS::Sleep(50); | 282 i::OS::Sleep(50); |
| 280 | 283 |
| 281 // Now we must have compiler and tick records. | 284 // Now we must have compiler and tick records. |
| 282 CHECK_GT(matcher->GetNextChunk(), 0); | 285 CHECK_GT(matcher->GetNextChunk(), 0); |
| 283 matcher->PrintBuffer(); | 286 matcher->PrintBuffer(); |
| 284 CHECK_NE(NULL, matcher->Find(code_creation)); | 287 CHECK_NE(NULL, matcher->Find(code_creation)); |
| 285 const char* tick = "\ntick,"; | 288 const char* tick = "\ntick,"; |
| 286 const bool ticks_found = matcher->Find(tick) != NULL; | 289 const bool ticks_found = matcher->Find(tick) != NULL; |
| 287 CHECK_EQ(LoggerTestHelper::has_samples_taken(), ticks_found); | 290 CHECK_EQ(LoggerTestHelper::has_samples_taken(), ticks_found); |
| 288 } | 291 } |
| 289 | 292 |
| 290 | 293 |
| 291 TEST(ProfLazyMode) { | 294 TEST(ProfLazyMode) { |
| 292 ScopedLoggerInitializer initialize_logger(true); | 295 ScopedLoggerInitializer initialize_logger(true); |
| 293 | 296 |
| 294 // No sampling should happen prior to resuming profiler. | 297 if (!i::V8::UseCrankshaft()) return; |
| 295 CHECK(!LoggerTestHelper::IsSamplerActive()); | 298 |
| 299 // No sampling should happen prior to resuming profiler unless we |
| 300 // are runtime profiling. |
| 301 CHECK(i::RuntimeProfiler::IsEnabled() || |
| 302 !LoggerTestHelper::IsSamplerActive()); |
| 296 | 303 |
| 297 LogBufferMatcher matcher; | 304 LogBufferMatcher matcher; |
| 298 // Nothing must be logged until profiling is resumed. | 305 // Nothing must be logged until profiling is resumed. |
| 299 CHECK_EQ(0, matcher.log_pos()); | 306 CHECK_EQ(0, matcher.log_pos()); |
| 300 | 307 |
| 301 CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); | 308 CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); |
| 302 | 309 |
| 303 // Nothing must be logged while profiling is suspended. | 310 // Nothing must be logged while profiling is suspended. |
| 304 CHECK_EQ(0, matcher.GetNextChunk()); | 311 CHECK_EQ(0, matcher.GetNextChunk()); |
| 305 | 312 |
| (...skipping 96 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 402 i = sin(i); | 409 i = sin(i); |
| 403 i::OS::Sleep(1); | 410 i::OS::Sleep(1); |
| 404 } | 411 } |
| 405 } | 412 } |
| 406 }; | 413 }; |
| 407 | 414 |
| 408 | 415 |
| 409 class TestSampler : public v8::internal::Sampler { | 416 class TestSampler : public v8::internal::Sampler { |
| 410 public: | 417 public: |
| 411 explicit TestSampler(v8::internal::Isolate* isolate) | 418 explicit TestSampler(v8::internal::Isolate* isolate) |
| 412 : Sampler(isolate, 0, true), | 419 : Sampler(isolate, 0, true, true), |
| 413 semaphore_(v8::internal::OS::CreateSemaphore(0)), | 420 semaphore_(v8::internal::OS::CreateSemaphore(0)), |
| 414 was_sample_stack_called_(false) { | 421 was_sample_stack_called_(false) { |
| 415 } | 422 } |
| 416 | 423 |
| 417 ~TestSampler() { delete semaphore_; } | 424 ~TestSampler() { delete semaphore_; } |
| 418 | 425 |
| 419 void SampleStack(v8::internal::TickSample*) { | 426 void SampleStack(v8::internal::TickSample*) { |
| 420 was_sample_stack_called_ = true; | 427 was_sample_stack_called_ = true; |
| 421 } | 428 } |
| 422 | 429 |
| 423 void Tick(v8::internal::TickSample*) { semaphore_->Signal(); } | 430 void Tick(v8::internal::TickSample*) { semaphore_->Signal(); } |
| 424 | 431 |
| 425 bool WaitForTick() { return semaphore_->Wait(1000000); } | 432 bool WaitForTick() { return semaphore_->Wait(1000000); } |
| 426 | 433 |
| 427 void Reset() { was_sample_stack_called_ = false; } | 434 void Reset() { was_sample_stack_called_ = false; } |
| 428 | 435 |
| 429 bool WasSampleStackCalled() { return was_sample_stack_called_; } | 436 bool WasSampleStackCalled() { return was_sample_stack_called_; } |
| 430 | 437 |
| 431 private: | 438 private: |
| 432 v8::internal::Semaphore* semaphore_; | 439 v8::internal::Semaphore* semaphore_; |
| 433 bool was_sample_stack_called_; | 440 bool was_sample_stack_called_; |
| 434 }; | 441 }; |
| 435 | 442 |
| 436 | 443 |
| 437 } // namespace | 444 } // namespace |
| 438 | 445 |
| 439 TEST(ProfMultipleThreads) { | 446 TEST(ProfMultipleThreads) { |
| 447 TestSampler* sampler = NULL; |
| 448 { |
| 449 v8::Locker locker; |
| 450 sampler = new TestSampler(v8::internal::Isolate::Current()); |
| 451 sampler->Start(); |
| 452 CHECK(sampler->IsActive()); |
| 453 } |
| 454 |
| 440 LoopingJsThread jsThread(v8::internal::Isolate::Current()); | 455 LoopingJsThread jsThread(v8::internal::Isolate::Current()); |
| 441 jsThread.Start(); | 456 jsThread.Start(); |
| 442 LoopingNonJsThread nonJsThread(v8::internal::Isolate::Current()); | 457 LoopingNonJsThread nonJsThread(v8::internal::Isolate::Current()); |
| 443 nonJsThread.Start(); | 458 nonJsThread.Start(); |
| 444 | 459 |
| 445 TestSampler sampler(v8::internal::Isolate::Current()); | 460 CHECK(!sampler->WasSampleStackCalled()); |
| 446 sampler.Start(); | |
| 447 CHECK(!sampler.WasSampleStackCalled()); | |
| 448 jsThread.WaitForRunning(); | 461 jsThread.WaitForRunning(); |
| 449 jsThread.SendSigProf(); | 462 jsThread.SendSigProf(); |
| 450 CHECK(sampler.WaitForTick()); | 463 CHECK(sampler->WaitForTick()); |
| 451 CHECK(sampler.WasSampleStackCalled()); | 464 CHECK(sampler->WasSampleStackCalled()); |
| 452 sampler.Reset(); | 465 sampler->Reset(); |
| 453 CHECK(!sampler.WasSampleStackCalled()); | 466 CHECK(!sampler->WasSampleStackCalled()); |
| 454 nonJsThread.WaitForRunning(); | 467 nonJsThread.WaitForRunning(); |
| 455 nonJsThread.SendSigProf(); | 468 nonJsThread.SendSigProf(); |
| 456 CHECK(!sampler.WaitForTick()); | 469 CHECK(!sampler->WaitForTick()); |
| 457 CHECK(!sampler.WasSampleStackCalled()); | 470 CHECK(!sampler->WasSampleStackCalled()); |
| 458 sampler.Stop(); | 471 sampler->Stop(); |
| 459 | 472 |
| 460 jsThread.Stop(); | 473 jsThread.Stop(); |
| 461 nonJsThread.Stop(); | 474 nonJsThread.Stop(); |
| 462 jsThread.Join(); | 475 jsThread.Join(); |
| 463 nonJsThread.Join(); | 476 nonJsThread.Join(); |
| 477 |
| 478 delete sampler; |
| 464 } | 479 } |
| 465 | 480 |
| 466 #endif // __linux__ | 481 #endif // __linux__ |
| 467 | 482 |
| 468 | 483 |
| 469 // Test for issue http://crbug.com/23768 in Chromium. | 484 // Test for issue http://crbug.com/23768 in Chromium. |
| 470 // Heap can contain scripts with already disposed external sources. | 485 // Heap can contain scripts with already disposed external sources. |
| 471 // We need to verify that LogCompiledFunctions doesn't crash on them. | 486 // We need to verify that LogCompiledFunctions doesn't crash on them. |
| 472 namespace { | 487 namespace { |
| 473 | 488 |
| (...skipping 699 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 1173 // Make sure that all log data is written prior crash due to CHECK failure. | 1188 // Make sure that all log data is written prior crash due to CHECK failure. |
| 1174 fflush(stdout); | 1189 fflush(stdout); |
| 1175 CHECK(results_equal); | 1190 CHECK(results_equal); |
| 1176 | 1191 |
| 1177 env->Exit(); | 1192 env->Exit(); |
| 1178 LOGGER->TearDown(); | 1193 LOGGER->TearDown(); |
| 1179 i::FLAG_always_compact = saved_always_compact; | 1194 i::FLAG_always_compact = saved_always_compact; |
| 1180 } | 1195 } |
| 1181 | 1196 |
| 1182 #endif // ENABLE_LOGGING_AND_PROFILING | 1197 #endif // ENABLE_LOGGING_AND_PROFILING |
| OLD | NEW |