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> |
| 9 #include <pthread.h> |
8 #include <signal.h> | 10 #include <signal.h> |
9 #include <unistd.h> | 11 #include <unistd.h> |
10 #endif | 12 #endif // __linux__ |
11 | 13 |
12 #include "v8.h" | 14 #include "v8.h" |
13 #include "log.h" | 15 #include "log.h" |
| 16 #include "v8threads.h" |
14 #include "cctest.h" | 17 #include "cctest.h" |
15 | 18 |
16 using v8::internal::Address; | 19 using v8::internal::Address; |
17 using v8::internal::EmbeddedVector; | 20 using v8::internal::EmbeddedVector; |
18 using v8::internal::Logger; | 21 using v8::internal::Logger; |
19 | 22 |
20 namespace i = v8::internal; | 23 namespace i = v8::internal; |
21 | 24 |
22 static void SetUp() { | 25 static void SetUp() { |
23 // Log to memory buffer. | 26 // Log to memory buffer. |
(...skipping 124 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
148 using v8::internal::LoggerTestHelper; | 151 using v8::internal::LoggerTestHelper; |
149 | 152 |
150 | 153 |
151 // Under Linux, we need to check if signals were delivered to avoid false | 154 // Under Linux, we need to check if signals were delivered to avoid false |
152 // positives. Under other platforms profiling is done via a high-priority | 155 // positives. Under other platforms profiling is done via a high-priority |
153 // thread, so this case never happen. | 156 // thread, so this case never happen. |
154 static bool was_sigprof_received = true; | 157 static bool was_sigprof_received = true; |
155 #ifdef __linux__ | 158 #ifdef __linux__ |
156 | 159 |
157 struct sigaction old_sigprof_handler; | 160 struct sigaction old_sigprof_handler; |
| 161 pthread_t our_thread; |
158 | 162 |
159 static void SigProfSignalHandler(int signal, siginfo_t* info, void* context) { | 163 static void SigProfSignalHandler(int signal, siginfo_t* info, void* context) { |
160 if (signal != SIGPROF) return; | 164 if (signal != SIGPROF || !pthread_equal(pthread_self(), our_thread)) return; |
161 was_sigprof_received = true; | 165 was_sigprof_received = true; |
162 old_sigprof_handler.sa_sigaction(signal, info, context); | 166 old_sigprof_handler.sa_sigaction(signal, info, context); |
163 } | 167 } |
164 | 168 |
165 #endif // __linux__ | 169 #endif // __linux__ |
166 | 170 |
167 | 171 |
168 static int CheckThatProfilerWorks(int log_pos) { | 172 static int CheckThatProfilerWorks(int log_pos) { |
169 Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU); | 173 Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU); |
170 CHECK(LoggerTestHelper::IsSamplerActive()); | 174 CHECK(LoggerTestHelper::IsSamplerActive()); |
171 | 175 |
172 // Verify that the current map of compiled functions has been logged. | 176 // Verify that the current map of compiled functions has been logged. |
173 EmbeddedVector<char, 102400> buffer; | 177 EmbeddedVector<char, 102400> buffer; |
174 int map_log_size = GetLogLines(log_pos, &buffer); | 178 int map_log_size = GetLogLines(log_pos, &buffer); |
175 printf("map_log_size: %d\n", map_log_size); | 179 printf("map_log_size: %d\n", map_log_size); |
176 CHECK_GT(map_log_size, 0); | 180 CHECK_GT(map_log_size, 0); |
177 CHECK_GT(buffer.length(), map_log_size); | 181 CHECK_GT(buffer.length(), map_log_size); |
178 log_pos += map_log_size; | 182 log_pos += map_log_size; |
179 // Check buffer contents. | 183 // Check buffer contents. |
180 buffer[map_log_size] = '\0'; | 184 buffer[map_log_size] = '\0'; |
181 const char* code_creation = "\ncode-creation,"; // eq. to /^code-creation,/ | 185 const char* code_creation = "\ncode-creation,"; // eq. to /^code-creation,/ |
182 CHECK_NE(NULL, strstr(buffer.start(), code_creation)); | 186 CHECK_NE(NULL, strstr(buffer.start(), code_creation)); |
183 | 187 |
184 #ifdef __linux__ | 188 #ifdef __linux__ |
185 // Intercept SIGPROF handler to make sure that the test process | 189 // Intercept SIGPROF handler to make sure that the test process |
186 // had received it. Under load, system can defer it causing test failure. | 190 // had received it. Under load, system can defer it causing test failure. |
187 // It is important to execute this after 'ResumeProfiler'. | 191 // It is important to execute this after 'ResumeProfiler'. |
| 192 our_thread = pthread_self(); |
188 was_sigprof_received = false; | 193 was_sigprof_received = false; |
189 struct sigaction sa; | 194 struct sigaction sa; |
190 sa.sa_sigaction = SigProfSignalHandler; | 195 sa.sa_sigaction = SigProfSignalHandler; |
191 sigemptyset(&sa.sa_mask); | 196 sigemptyset(&sa.sa_mask); |
192 sa.sa_flags = SA_SIGINFO; | 197 sa.sa_flags = SA_SIGINFO; |
193 CHECK_EQ(0, sigaction(SIGPROF, &sa, &old_sigprof_handler)); | 198 CHECK_EQ(0, sigaction(SIGPROF, &sa, &old_sigprof_handler)); |
194 #endif // __linux__ | 199 #endif // __linux__ |
195 | 200 |
196 // Force compiler to generate new code by parametrizing source. | 201 // Force compiler to generate new code by parametrizing source. |
197 EmbeddedVector<char, 100> script_src; | 202 EmbeddedVector<char, 100> script_src; |
(...skipping 75 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
273 CheckThatProfilerWorks(log_pos); | 278 CheckThatProfilerWorks(log_pos); |
274 | 279 |
275 env->Exit(); | 280 env->Exit(); |
276 Logger::TearDown(); | 281 Logger::TearDown(); |
277 i::FLAG_prof_lazy = saved_prof_lazy; | 282 i::FLAG_prof_lazy = saved_prof_lazy; |
278 i::FLAG_prof = saved_prof; | 283 i::FLAG_prof = saved_prof; |
279 i::FLAG_prof_auto = saved_prof_auto; | 284 i::FLAG_prof_auto = saved_prof_auto; |
280 } | 285 } |
281 | 286 |
282 | 287 |
| 288 // Profiling multiple threads that use V8 is currently only available on Linux. |
| 289 #ifdef __linux__ |
| 290 |
| 291 namespace { |
| 292 |
| 293 class LoopingThread : public v8::internal::Thread { |
| 294 public: |
| 295 LoopingThread() |
| 296 : v8::internal::Thread(), |
| 297 semaphore_(v8::internal::OS::CreateSemaphore(0)), |
| 298 run_(true) { |
| 299 } |
| 300 |
| 301 virtual ~LoopingThread() { delete semaphore_; } |
| 302 |
| 303 void Run() { |
| 304 self_ = pthread_self(); |
| 305 RunLoop(); |
| 306 } |
| 307 |
| 308 void SendSigProf() { pthread_kill(self_, SIGPROF); } |
| 309 |
| 310 void Stop() { run_ = false; } |
| 311 |
| 312 bool WaitForRunning() { return semaphore_->Wait(1000000); } |
| 313 |
| 314 protected: |
| 315 bool IsRunning() { return run_; } |
| 316 |
| 317 virtual void RunLoop() = 0; |
| 318 |
| 319 void SetV8ThreadId() { |
| 320 v8_thread_id_ = v8::V8::GetCurrentThreadId(); |
| 321 } |
| 322 |
| 323 void SignalRunning() { semaphore_->Signal(); } |
| 324 |
| 325 private: |
| 326 v8::internal::Semaphore* semaphore_; |
| 327 bool run_; |
| 328 pthread_t self_; |
| 329 int v8_thread_id_; |
| 330 }; |
| 331 |
| 332 |
| 333 class LoopingJsThread : public LoopingThread { |
| 334 public: |
| 335 void RunLoop() { |
| 336 { |
| 337 v8::Locker locker; |
| 338 CHECK(v8::internal::ThreadManager::HasId()); |
| 339 SetV8ThreadId(); |
| 340 } |
| 341 while (IsRunning()) { |
| 342 v8::Locker locker; |
| 343 v8::HandleScope scope; |
| 344 v8::Persistent<v8::Context> context = v8::Context::New(); |
| 345 v8::Context::Scope context_scope(context); |
| 346 SignalRunning(); |
| 347 CompileAndRunScript( |
| 348 "var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }"); |
| 349 context.Dispose(); |
| 350 i::OS::Sleep(1); |
| 351 } |
| 352 } |
| 353 }; |
| 354 |
| 355 |
| 356 class LoopingNonJsThread : public LoopingThread { |
| 357 public: |
| 358 void RunLoop() { |
| 359 v8::Locker locker; |
| 360 v8::Unlocker unlocker; |
| 361 // Now thread has V8's id, but will not run VM code. |
| 362 CHECK(v8::internal::ThreadManager::HasId()); |
| 363 double i = 10; |
| 364 SignalRunning(); |
| 365 while (IsRunning()) { |
| 366 i = sin(i); |
| 367 i::OS::Sleep(1); |
| 368 } |
| 369 } |
| 370 }; |
| 371 |
| 372 |
| 373 class TestSampler : public v8::internal::Sampler { |
| 374 public: |
| 375 TestSampler() |
| 376 : Sampler(0, true), |
| 377 semaphore_(v8::internal::OS::CreateSemaphore(0)), |
| 378 was_sample_stack_called_(false) { |
| 379 } |
| 380 |
| 381 ~TestSampler() { delete semaphore_; } |
| 382 |
| 383 void SampleStack(v8::internal::TickSample*) { |
| 384 was_sample_stack_called_ = true; |
| 385 } |
| 386 |
| 387 void Tick(v8::internal::TickSample*) { semaphore_->Signal(); } |
| 388 |
| 389 bool WaitForTick() { return semaphore_->Wait(1000000); } |
| 390 |
| 391 void Reset() { was_sample_stack_called_ = false; } |
| 392 |
| 393 bool WasSampleStackCalled() { return was_sample_stack_called_; } |
| 394 |
| 395 private: |
| 396 v8::internal::Semaphore* semaphore_; |
| 397 bool was_sample_stack_called_; |
| 398 }; |
| 399 |
| 400 |
| 401 } // namespace |
| 402 |
| 403 TEST(ProfMultipleThreads) { |
| 404 // V8 needs to be initialized before the first Locker |
| 405 // instantiation. Otherwise, Top::Initialize will reset |
| 406 // thread_id_ in ThreadTopLocal. |
| 407 v8::HandleScope scope; |
| 408 v8::Handle<v8::Context> env = v8::Context::New(); |
| 409 env->Enter(); |
| 410 |
| 411 LoopingJsThread jsThread; |
| 412 jsThread.Start(); |
| 413 LoopingNonJsThread nonJsThread; |
| 414 nonJsThread.Start(); |
| 415 |
| 416 TestSampler sampler; |
| 417 sampler.Start(); |
| 418 CHECK(!sampler.WasSampleStackCalled()); |
| 419 jsThread.WaitForRunning(); |
| 420 jsThread.SendSigProf(); |
| 421 CHECK(sampler.WaitForTick()); |
| 422 CHECK(sampler.WasSampleStackCalled()); |
| 423 sampler.Reset(); |
| 424 CHECK(!sampler.WasSampleStackCalled()); |
| 425 nonJsThread.WaitForRunning(); |
| 426 nonJsThread.SendSigProf(); |
| 427 CHECK(sampler.WaitForTick()); |
| 428 CHECK(!sampler.WasSampleStackCalled()); |
| 429 sampler.Stop(); |
| 430 |
| 431 jsThread.Stop(); |
| 432 nonJsThread.Stop(); |
| 433 jsThread.Join(); |
| 434 nonJsThread.Join(); |
| 435 } |
| 436 |
| 437 #endif // __linux__ |
| 438 |
| 439 |
283 static inline bool IsStringEqualTo(const char* r, const char* s) { | 440 static inline bool IsStringEqualTo(const char* r, const char* s) { |
284 return strncmp(r, s, strlen(r)) == 0; | 441 return strncmp(r, s, strlen(r)) == 0; |
285 } | 442 } |
286 | 443 |
287 | 444 |
288 static bool Consume(const char* str, char** buf) { | 445 static bool Consume(const char* str, char** buf) { |
289 if (IsStringEqualTo(str, *buf)) { | 446 if (IsStringEqualTo(str, *buf)) { |
290 *buf += strlen(str); | 447 *buf += strlen(str); |
291 return true; | 448 return true; |
292 } | 449 } |
(...skipping 446 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
739 // Make sure that all log data is written prior crash due to CHECK failure. | 896 // Make sure that all log data is written prior crash due to CHECK failure. |
740 fflush(stdout); | 897 fflush(stdout); |
741 CHECK(results_equal); | 898 CHECK(results_equal); |
742 | 899 |
743 env->Exit(); | 900 env->Exit(); |
744 Logger::TearDown(); | 901 Logger::TearDown(); |
745 i::FLAG_always_compact = saved_always_compact; | 902 i::FLAG_always_compact = saved_always_compact; |
746 } | 903 } |
747 | 904 |
748 #endif // ENABLE_LOGGING_AND_PROFILING | 905 #endif // ENABLE_LOGGING_AND_PROFILING |
OLD | NEW |