Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 1 | // Copyright 2006-2009 the V8 project authors. All rights reserved. |
| 2 | // |
| 3 | // Tests of logging functions from log.h |
| 4 | |
| 5 | #ifdef ENABLE_LOGGING_AND_PROFILING |
| 6 | |
| 7 | #ifdef __linux__ |
| 8 | #include <math.h> |
| 9 | #include <pthread.h> |
| 10 | #include <signal.h> |
| 11 | #include <unistd.h> |
| 12 | #endif // __linux__ |
| 13 | |
| 14 | #include "v8.h" |
| 15 | #include "log.h" |
| 16 | #include "v8threads.h" |
| 17 | #include "cctest.h" |
| 18 | |
| 19 | using v8::internal::Address; |
| 20 | using v8::internal::EmbeddedVector; |
| 21 | using v8::internal::Logger; |
| 22 | |
| 23 | namespace i = v8::internal; |
| 24 | |
| 25 | static void SetUp() { |
| 26 | // Log to memory buffer. |
| 27 | i::FLAG_logfile = "*"; |
| 28 | i::FLAG_log = true; |
| 29 | Logger::Setup(); |
| 30 | } |
| 31 | |
| 32 | static void TearDown() { |
| 33 | Logger::TearDown(); |
| 34 | } |
| 35 | |
| 36 | |
| 37 | TEST(EmptyLog) { |
| 38 | SetUp(); |
| 39 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 0)); |
| 40 | CHECK_EQ(0, Logger::GetLogLines(100, NULL, 0)); |
| 41 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 100)); |
| 42 | CHECK_EQ(0, Logger::GetLogLines(100, NULL, 100)); |
| 43 | TearDown(); |
| 44 | } |
| 45 | |
| 46 | |
| 47 | TEST(GetMessages) { |
| 48 | SetUp(); |
| 49 | Logger::StringEvent("aaa", "bbb"); |
| 50 | Logger::StringEvent("cccc", "dddd"); |
| 51 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 0)); |
| 52 | char log_lines[100]; |
| 53 | memset(log_lines, 0, sizeof(log_lines)); |
| 54 | // Requesting data size which is smaller than first log message length. |
| 55 | CHECK_EQ(0, Logger::GetLogLines(0, log_lines, 3)); |
| 56 | // See Logger::StringEvent. |
| 57 | const char* line_1 = "aaa,\"bbb\"\n"; |
| 58 | const int line_1_len = strlen(line_1); |
| 59 | // Still smaller than log message length. |
| 60 | CHECK_EQ(0, Logger::GetLogLines(0, log_lines, line_1_len - 1)); |
| 61 | // The exact size. |
| 62 | CHECK_EQ(line_1_len, Logger::GetLogLines(0, log_lines, line_1_len)); |
| 63 | CHECK_EQ(line_1, log_lines); |
| 64 | memset(log_lines, 0, sizeof(log_lines)); |
| 65 | // A bit more than the first line length. |
| 66 | CHECK_EQ(line_1_len, Logger::GetLogLines(0, log_lines, line_1_len + 3)); |
| 67 | log_lines[line_1_len] = '\0'; |
| 68 | CHECK_EQ(line_1, log_lines); |
| 69 | memset(log_lines, 0, sizeof(log_lines)); |
| 70 | const char* line_2 = "cccc,\"dddd\"\n"; |
| 71 | const int line_2_len = strlen(line_2); |
| 72 | // Now start with line_2 beginning. |
| 73 | CHECK_EQ(0, Logger::GetLogLines(line_1_len, log_lines, 0)); |
| 74 | CHECK_EQ(0, Logger::GetLogLines(line_1_len, log_lines, 3)); |
| 75 | CHECK_EQ(0, Logger::GetLogLines(line_1_len, log_lines, line_2_len - 1)); |
| 76 | CHECK_EQ(line_2_len, Logger::GetLogLines(line_1_len, log_lines, line_2_len)); |
| 77 | CHECK_EQ(line_2, log_lines); |
| 78 | memset(log_lines, 0, sizeof(log_lines)); |
| 79 | CHECK_EQ(line_2_len, |
| 80 | Logger::GetLogLines(line_1_len, log_lines, line_2_len + 3)); |
| 81 | CHECK_EQ(line_2, log_lines); |
| 82 | memset(log_lines, 0, sizeof(log_lines)); |
| 83 | // Now get entire buffer contents. |
| 84 | const char* all_lines = "aaa,\"bbb\"\ncccc,\"dddd\"\n"; |
| 85 | const int all_lines_len = strlen(all_lines); |
| 86 | CHECK_EQ(all_lines_len, Logger::GetLogLines(0, log_lines, all_lines_len)); |
| 87 | CHECK_EQ(all_lines, log_lines); |
| 88 | memset(log_lines, 0, sizeof(log_lines)); |
| 89 | CHECK_EQ(all_lines_len, Logger::GetLogLines(0, log_lines, all_lines_len + 3)); |
| 90 | CHECK_EQ(all_lines, log_lines); |
| 91 | memset(log_lines, 0, sizeof(log_lines)); |
| 92 | TearDown(); |
| 93 | } |
| 94 | |
| 95 | |
| 96 | static int GetLogLines(int start_pos, i::Vector<char>* buffer) { |
| 97 | return Logger::GetLogLines(start_pos, buffer->start(), buffer->length()); |
| 98 | } |
| 99 | |
| 100 | |
| 101 | TEST(BeyondWritePosition) { |
| 102 | SetUp(); |
| 103 | Logger::StringEvent("aaa", "bbb"); |
| 104 | Logger::StringEvent("cccc", "dddd"); |
| 105 | // See Logger::StringEvent. |
| 106 | const char* all_lines = "aaa,\"bbb\"\ncccc,\"dddd\"\n"; |
| 107 | const int all_lines_len = strlen(all_lines); |
| 108 | EmbeddedVector<char, 100> buffer; |
| 109 | const int beyond_write_pos = all_lines_len; |
| 110 | CHECK_EQ(0, Logger::GetLogLines(beyond_write_pos, buffer.start(), 1)); |
| 111 | CHECK_EQ(0, GetLogLines(beyond_write_pos, &buffer)); |
| 112 | CHECK_EQ(0, Logger::GetLogLines(beyond_write_pos + 1, buffer.start(), 1)); |
| 113 | CHECK_EQ(0, GetLogLines(beyond_write_pos + 1, &buffer)); |
| 114 | CHECK_EQ(0, Logger::GetLogLines(beyond_write_pos + 100, buffer.start(), 1)); |
| 115 | CHECK_EQ(0, GetLogLines(beyond_write_pos + 100, &buffer)); |
| 116 | CHECK_EQ(0, Logger::GetLogLines(10 * 1024 * 1024, buffer.start(), 1)); |
| 117 | CHECK_EQ(0, GetLogLines(10 * 1024 * 1024, &buffer)); |
| 118 | TearDown(); |
| 119 | } |
| 120 | |
| 121 | |
| 122 | TEST(MemoryLoggingTurnedOff) { |
| 123 | // Log to stdout |
| 124 | i::FLAG_logfile = "-"; |
| 125 | i::FLAG_log = true; |
| 126 | Logger::Setup(); |
| 127 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 0)); |
| 128 | CHECK_EQ(0, Logger::GetLogLines(100, NULL, 0)); |
| 129 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 100)); |
| 130 | CHECK_EQ(0, Logger::GetLogLines(100, NULL, 100)); |
| 131 | Logger::TearDown(); |
| 132 | } |
| 133 | |
| 134 | |
| 135 | static void CompileAndRunScript(const char *src) { |
| 136 | v8::Script::Compile(v8::String::New(src))->Run(); |
| 137 | } |
| 138 | |
| 139 | |
| 140 | namespace v8 { |
| 141 | namespace internal { |
| 142 | |
| 143 | class LoggerTestHelper : public AllStatic { |
| 144 | public: |
| 145 | static bool IsSamplerActive() { return Logger::IsProfilerSamplerActive(); } |
| 146 | }; |
| 147 | |
| 148 | } // namespace v8::internal |
| 149 | } // namespace v8 |
| 150 | |
| 151 | using v8::internal::LoggerTestHelper; |
| 152 | |
| 153 | |
| 154 | // Under Linux, we need to check if signals were delivered to avoid false |
| 155 | // positives. Under other platforms profiling is done via a high-priority |
| 156 | // thread, so this case never happen. |
| 157 | static bool was_sigprof_received = true; |
| 158 | #ifdef __linux__ |
| 159 | |
| 160 | struct sigaction old_sigprof_handler; |
| 161 | pthread_t our_thread; |
| 162 | |
| 163 | static void SigProfSignalHandler(int signal, siginfo_t* info, void* context) { |
| 164 | if (signal != SIGPROF || !pthread_equal(pthread_self(), our_thread)) return; |
| 165 | was_sigprof_received = true; |
| 166 | old_sigprof_handler.sa_sigaction(signal, info, context); |
| 167 | } |
| 168 | |
| 169 | #endif // __linux__ |
| 170 | |
| 171 | |
| 172 | static int CheckThatProfilerWorks(int log_pos) { |
| 173 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU); |
| 174 | CHECK(LoggerTestHelper::IsSamplerActive()); |
| 175 | |
| 176 | // Verify that the current map of compiled functions has been logged. |
| 177 | EmbeddedVector<char, 102400> buffer; |
| 178 | int map_log_size = GetLogLines(log_pos, &buffer); |
| 179 | printf("map_log_size: %d\n", map_log_size); |
| 180 | CHECK_GT(map_log_size, 0); |
| 181 | CHECK_GT(buffer.length(), map_log_size); |
| 182 | log_pos += map_log_size; |
| 183 | // Check buffer contents. |
| 184 | buffer[map_log_size] = '\0'; |
| 185 | const char* code_creation = "\ncode-creation,"; // eq. to /^code-creation,/ |
| 186 | CHECK_NE(NULL, strstr(buffer.start(), code_creation)); |
| 187 | |
| 188 | #ifdef __linux__ |
| 189 | // Intercept SIGPROF handler to make sure that the test process |
| 190 | // had received it. Under load, system can defer it causing test failure. |
| 191 | // It is important to execute this after 'ResumeProfiler'. |
| 192 | our_thread = pthread_self(); |
| 193 | was_sigprof_received = false; |
| 194 | struct sigaction sa; |
| 195 | sa.sa_sigaction = SigProfSignalHandler; |
| 196 | sigemptyset(&sa.sa_mask); |
| 197 | sa.sa_flags = SA_SIGINFO; |
| 198 | CHECK_EQ(0, sigaction(SIGPROF, &sa, &old_sigprof_handler)); |
| 199 | #endif // __linux__ |
| 200 | |
| 201 | // Force compiler to generate new code by parametrizing source. |
| 202 | EmbeddedVector<char, 100> script_src; |
| 203 | i::OS::SNPrintF(script_src, |
| 204 | "for (var i = 0; i < 1000; ++i) { " |
| 205 | "(function(x) { return %d * x; })(i); }", |
| 206 | log_pos); |
| 207 | // Run code for 200 msecs to get some ticks. |
| 208 | const double end_time = i::OS::TimeCurrentMillis() + 200; |
| 209 | while (i::OS::TimeCurrentMillis() < end_time) { |
| 210 | CompileAndRunScript(script_src.start()); |
| 211 | // Yield CPU to give Profiler thread a chance to process ticks. |
| 212 | i::OS::Sleep(1); |
| 213 | } |
| 214 | |
| 215 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU); |
| 216 | CHECK(!LoggerTestHelper::IsSamplerActive()); |
| 217 | |
| 218 | // Wait 50 msecs to allow Profiler thread to process the last |
| 219 | // tick sample it has got. |
| 220 | i::OS::Sleep(50); |
| 221 | |
| 222 | // Now we must have compiler and tick records. |
| 223 | int log_size = GetLogLines(log_pos, &buffer); |
| 224 | printf("log_size: %d\n", log_size); |
| 225 | CHECK_GT(log_size, 0); |
| 226 | CHECK_GT(buffer.length(), log_size); |
| 227 | log_pos += log_size; |
| 228 | // Check buffer contents. |
| 229 | buffer[log_size] = '\0'; |
| 230 | const char* tick = "\ntick,"; |
| 231 | CHECK_NE(NULL, strstr(buffer.start(), code_creation)); |
| 232 | const bool ticks_found = strstr(buffer.start(), tick) != NULL; |
| 233 | CHECK_EQ(was_sigprof_received, ticks_found); |
| 234 | |
| 235 | return log_pos; |
| 236 | } |
| 237 | |
| 238 | |
| 239 | TEST(ProfLazyMode) { |
| 240 | const bool saved_prof_lazy = i::FLAG_prof_lazy; |
| 241 | const bool saved_prof = i::FLAG_prof; |
| 242 | const bool saved_prof_auto = i::FLAG_prof_auto; |
| 243 | i::FLAG_prof = true; |
| 244 | i::FLAG_prof_lazy = true; |
| 245 | i::FLAG_prof_auto = false; |
| 246 | i::FLAG_logfile = "*"; |
| 247 | |
| 248 | // If tests are being run manually, V8 will be already initialized |
| 249 | // by the test below. |
| 250 | const bool need_to_set_up_logger = i::V8::IsRunning(); |
| 251 | v8::HandleScope scope; |
| 252 | v8::Handle<v8::Context> env = v8::Context::New(); |
| 253 | if (need_to_set_up_logger) Logger::Setup(); |
| 254 | env->Enter(); |
| 255 | |
| 256 | // No sampling should happen prior to resuming profiler. |
| 257 | CHECK(!LoggerTestHelper::IsSamplerActive()); |
| 258 | |
| 259 | // Read initial logged data (static libs map). |
| 260 | EmbeddedVector<char, 102400> buffer; |
| 261 | int log_pos = GetLogLines(0, &buffer); |
| 262 | CHECK_GT(log_pos, 0); |
| 263 | CHECK_GT(buffer.length(), log_pos); |
| 264 | |
| 265 | CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); |
| 266 | |
| 267 | // Nothing must be logged while profiling is suspended. |
| 268 | CHECK_EQ(0, GetLogLines(log_pos, &buffer)); |
| 269 | |
| 270 | log_pos = CheckThatProfilerWorks(log_pos); |
| 271 | |
| 272 | CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); |
| 273 | |
| 274 | // No new data beyond last retrieved position. |
| 275 | CHECK_EQ(0, GetLogLines(log_pos, &buffer)); |
| 276 | |
| 277 | // Check that profiling can be resumed again. |
| 278 | CheckThatProfilerWorks(log_pos); |
| 279 | |
| 280 | env->Exit(); |
| 281 | Logger::TearDown(); |
| 282 | i::FLAG_prof_lazy = saved_prof_lazy; |
| 283 | i::FLAG_prof = saved_prof; |
| 284 | i::FLAG_prof_auto = saved_prof_auto; |
| 285 | } |
| 286 | |
| 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 | LoopingJsThread jsThread; |
| 405 | jsThread.Start(); |
| 406 | LoopingNonJsThread nonJsThread; |
| 407 | nonJsThread.Start(); |
| 408 | |
| 409 | TestSampler sampler; |
| 410 | sampler.Start(); |
| 411 | CHECK(!sampler.WasSampleStackCalled()); |
| 412 | jsThread.WaitForRunning(); |
| 413 | jsThread.SendSigProf(); |
| 414 | CHECK(sampler.WaitForTick()); |
| 415 | CHECK(sampler.WasSampleStackCalled()); |
| 416 | sampler.Reset(); |
| 417 | CHECK(!sampler.WasSampleStackCalled()); |
| 418 | nonJsThread.WaitForRunning(); |
| 419 | nonJsThread.SendSigProf(); |
| 420 | CHECK(sampler.WaitForTick()); |
| 421 | CHECK(!sampler.WasSampleStackCalled()); |
| 422 | sampler.Stop(); |
| 423 | |
| 424 | jsThread.Stop(); |
| 425 | nonJsThread.Stop(); |
| 426 | jsThread.Join(); |
| 427 | nonJsThread.Join(); |
| 428 | } |
| 429 | |
| 430 | #endif // __linux__ |
| 431 | |
| 432 | |
Steve Block | 3ce2e20 | 2009-11-05 08:53:23 +0000 | [diff] [blame^] | 433 | // Test for issue http://crbug.com/23768 in Chromium. |
| 434 | // Heap can contain scripts with already disposed external sources. |
| 435 | // We need to verify that LogCompiledFunctions doesn't crash on them. |
| 436 | namespace { |
| 437 | |
| 438 | class SimpleExternalString : public v8::String::ExternalStringResource { |
| 439 | public: |
| 440 | explicit SimpleExternalString(const char* source) |
| 441 | : utf_source_(strlen(source)) { |
| 442 | for (int i = 0; i < utf_source_.length(); ++i) |
| 443 | utf_source_[i] = source[i]; |
| 444 | } |
| 445 | virtual ~SimpleExternalString() {} |
| 446 | virtual size_t length() const { return utf_source_.length(); } |
| 447 | virtual const uint16_t* data() const { return utf_source_.start(); } |
| 448 | private: |
| 449 | i::ScopedVector<uint16_t> utf_source_; |
| 450 | }; |
| 451 | |
| 452 | } // namespace |
| 453 | |
| 454 | TEST(Issue23768) { |
| 455 | v8::HandleScope scope; |
| 456 | v8::Handle<v8::Context> env = v8::Context::New(); |
| 457 | env->Enter(); |
| 458 | |
| 459 | SimpleExternalString source_ext_str("(function ext() {})();"); |
| 460 | v8::Local<v8::String> source = v8::String::NewExternal(&source_ext_str); |
| 461 | // Script needs to have a name in order to trigger InitLineEnds execution. |
| 462 | v8::Handle<v8::String> origin = v8::String::New("issue-23768-test"); |
| 463 | v8::Handle<v8::Script> evil_script = v8::Script::Compile(source, origin); |
| 464 | CHECK(!evil_script.IsEmpty()); |
| 465 | CHECK(!evil_script->Run().IsEmpty()); |
| 466 | i::Handle<i::ExternalTwoByteString> i_source( |
| 467 | i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source))); |
| 468 | // This situation can happen if source was an external string disposed |
| 469 | // by its owner. |
| 470 | i_source->set_resource(NULL); |
| 471 | |
| 472 | // Must not crash. |
| 473 | i::Logger::LogCompiledFunctions(); |
| 474 | } |
| 475 | |
| 476 | |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 477 | static inline bool IsStringEqualTo(const char* r, const char* s) { |
| 478 | return strncmp(r, s, strlen(r)) == 0; |
| 479 | } |
| 480 | |
| 481 | |
| 482 | static bool Consume(const char* str, char** buf) { |
| 483 | if (IsStringEqualTo(str, *buf)) { |
| 484 | *buf += strlen(str); |
| 485 | return true; |
| 486 | } |
| 487 | return false; |
| 488 | } |
| 489 | |
| 490 | |
| 491 | namespace { |
| 492 | |
| 493 | // A code entity is a pointer to a position of code-creation event in buffer log |
| 494 | // offset to a point where entity size begins, i.e.: '255,"func"\n'. This makes |
| 495 | // comparing code entities pretty easy. |
| 496 | typedef char* CodeEntityInfo; |
| 497 | |
| 498 | class Interval { |
| 499 | public: |
| 500 | Interval() |
| 501 | : min_addr_(reinterpret_cast<Address>(-1)), |
| 502 | max_addr_(reinterpret_cast<Address>(0)), next_(NULL) {} |
| 503 | |
| 504 | ~Interval() { delete next_; } |
| 505 | |
| 506 | size_t Length() { |
| 507 | size_t result = max_addr_ - min_addr_ + 1; |
| 508 | if (next_ != NULL) result += next_->Length(); |
| 509 | return result; |
| 510 | } |
| 511 | |
| 512 | void CloneFrom(Interval* src) { |
| 513 | while (src != NULL) { |
| 514 | RegisterAddress(src->min_addr_); |
| 515 | RegisterAddress(src->max_addr_); |
| 516 | src = src->next_; |
| 517 | } |
| 518 | } |
| 519 | |
| 520 | bool Contains(Address addr) { |
| 521 | if (min_addr_ <= addr && addr <= max_addr_) { |
| 522 | return true; |
| 523 | } |
| 524 | if (next_ != NULL) { |
| 525 | return next_->Contains(addr); |
| 526 | } else { |
| 527 | return false; |
| 528 | } |
| 529 | } |
| 530 | |
| 531 | size_t GetIndex(Address addr) { |
| 532 | if (min_addr_ <= addr && addr <= max_addr_) { |
| 533 | return addr - min_addr_; |
| 534 | } |
| 535 | CHECK_NE(NULL, next_); |
| 536 | return (max_addr_ - min_addr_ + 1) + next_->GetIndex(addr); |
| 537 | } |
| 538 | |
| 539 | Address GetMinAddr() { |
| 540 | return next_ == NULL ? min_addr_ : i::Min(min_addr_, next_->GetMinAddr()); |
| 541 | } |
| 542 | |
| 543 | Address GetMaxAddr() { |
| 544 | return next_ == NULL ? max_addr_ : i::Max(max_addr_, next_->GetMaxAddr()); |
| 545 | } |
| 546 | |
| 547 | void RegisterAddress(Address addr) { |
| 548 | if (min_addr_ == reinterpret_cast<Address>(-1) |
| 549 | || (size_t)(addr > min_addr_ ? |
| 550 | addr - min_addr_ : min_addr_ - addr) < MAX_DELTA) { |
| 551 | if (addr < min_addr_) min_addr_ = addr; |
| 552 | if (addr > max_addr_) max_addr_ = addr; |
| 553 | } else { |
| 554 | if (next_ == NULL) next_ = new Interval(); |
| 555 | next_->RegisterAddress(addr); |
| 556 | } |
| 557 | } |
| 558 | |
| 559 | Address raw_min_addr() { return min_addr_; } |
| 560 | |
| 561 | Address raw_max_addr() { return max_addr_; } |
| 562 | |
| 563 | Interval* get_next() { return next_; } |
| 564 | |
| 565 | private: |
| 566 | static const size_t MAX_DELTA = 0x100000; |
| 567 | Address min_addr_; |
| 568 | Address max_addr_; |
| 569 | Interval* next_; |
| 570 | }; |
| 571 | |
| 572 | |
| 573 | // A structure used to return log parsing results. |
| 574 | class ParseLogResult { |
| 575 | public: |
| 576 | ParseLogResult() |
| 577 | : entities_map(NULL), entities(NULL), |
| 578 | max_entities(0) {} |
| 579 | |
| 580 | ~ParseLogResult() { |
| 581 | i::DeleteArray(entities_map); |
| 582 | i::DeleteArray(entities); |
| 583 | } |
| 584 | |
| 585 | void AllocateEntities() { |
| 586 | // Make sure that the test doesn't operate on a bogus log. |
| 587 | CHECK_GT(max_entities, 0); |
| 588 | CHECK_GT(bounds.GetMinAddr(), 0); |
| 589 | CHECK_GT(bounds.GetMaxAddr(), bounds.GetMinAddr()); |
| 590 | |
| 591 | entities = i::NewArray<CodeEntityInfo>(max_entities); |
| 592 | for (int i = 0; i < max_entities; ++i) { |
| 593 | entities[i] = NULL; |
| 594 | } |
| 595 | const size_t map_length = bounds.Length(); |
| 596 | entities_map = i::NewArray<int>(map_length); |
| 597 | for (size_t i = 0; i < map_length; ++i) { |
| 598 | entities_map[i] = -1; |
| 599 | } |
| 600 | } |
| 601 | |
| 602 | bool HasIndexForAddress(Address addr) { |
| 603 | return bounds.Contains(addr); |
| 604 | } |
| 605 | |
| 606 | size_t GetIndexForAddress(Address addr) { |
| 607 | CHECK(HasIndexForAddress(addr)); |
| 608 | return bounds.GetIndex(addr); |
| 609 | } |
| 610 | |
| 611 | CodeEntityInfo GetEntity(Address addr) { |
| 612 | if (HasIndexForAddress(addr)) { |
| 613 | size_t idx = GetIndexForAddress(addr); |
| 614 | int item = entities_map[idx]; |
| 615 | return item != -1 ? entities[item] : NULL; |
| 616 | } |
| 617 | return NULL; |
| 618 | } |
| 619 | |
| 620 | void ParseAddress(char* start) { |
| 621 | Address addr = |
| 622 | reinterpret_cast<Address>(strtoul(start, NULL, 16)); // NOLINT |
| 623 | bounds.RegisterAddress(addr); |
| 624 | } |
| 625 | |
| 626 | Address ConsumeAddress(char** start) { |
| 627 | char* end_ptr; |
| 628 | Address addr = |
| 629 | reinterpret_cast<Address>(strtoul(*start, &end_ptr, 16)); // NOLINT |
| 630 | CHECK(HasIndexForAddress(addr)); |
| 631 | *start = end_ptr; |
| 632 | return addr; |
| 633 | } |
| 634 | |
| 635 | Interval bounds; |
| 636 | // Memory map of entities start addresses. |
| 637 | int* entities_map; |
| 638 | // An array of code entities. |
| 639 | CodeEntityInfo* entities; |
| 640 | // Maximal entities count. Actual entities count can be lower, |
| 641 | // empty entity slots are pointing to NULL. |
| 642 | int max_entities; |
| 643 | }; |
| 644 | |
| 645 | } // namespace |
| 646 | |
| 647 | |
| 648 | typedef void (*ParserBlock)(char* start, char* end, ParseLogResult* result); |
| 649 | |
| 650 | static void ParserCycle( |
| 651 | char* start, char* end, ParseLogResult* result, |
| 652 | ParserBlock block_creation, ParserBlock block_delete, |
| 653 | ParserBlock block_move) { |
| 654 | |
| 655 | const char* code_creation = "code-creation,"; |
| 656 | const char* code_delete = "code-delete,"; |
| 657 | const char* code_move = "code-move,"; |
| 658 | |
| 659 | const char* lazy_compile = "LazyCompile,"; |
| 660 | const char* script = "Script,"; |
| 661 | const char* function = "Function,"; |
| 662 | |
| 663 | while (start < end) { |
| 664 | if (Consume(code_creation, &start)) { |
| 665 | if (Consume(lazy_compile, &start) |
| 666 | || Consume(script, &start) |
| 667 | || Consume(function, &start)) { |
| 668 | block_creation(start, end, result); |
| 669 | } |
| 670 | } else if (Consume(code_delete, &start)) { |
| 671 | block_delete(start, end, result); |
| 672 | } else if (Consume(code_move, &start)) { |
| 673 | block_move(start, end, result); |
| 674 | } |
| 675 | while (start < end && *start != '\n') ++start; |
| 676 | ++start; |
| 677 | } |
| 678 | } |
| 679 | |
| 680 | |
| 681 | static void Pass1CodeCreation(char* start, char* end, ParseLogResult* result) { |
| 682 | result->ParseAddress(start); |
| 683 | ++result->max_entities; |
| 684 | } |
| 685 | |
| 686 | |
| 687 | static void Pass1CodeDelete(char* start, char* end, ParseLogResult* result) { |
| 688 | result->ParseAddress(start); |
| 689 | } |
| 690 | |
| 691 | |
| 692 | static void Pass1CodeMove(char* start, char* end, ParseLogResult* result) { |
| 693 | result->ParseAddress(start); |
| 694 | // Skip old address. |
| 695 | while (start < end && *start != ',') ++start; |
| 696 | CHECK_GT(end, start); |
| 697 | ++start; // Skip ','. |
| 698 | result->ParseAddress(start); |
| 699 | } |
| 700 | |
| 701 | |
| 702 | static void Pass2CodeCreation(char* start, char* end, ParseLogResult* result) { |
| 703 | Address addr = result->ConsumeAddress(&start); |
| 704 | CHECK_GT(end, start); |
| 705 | ++start; // Skip ','. |
| 706 | |
| 707 | size_t idx = result->GetIndexForAddress(addr); |
| 708 | result->entities_map[idx] = -1; |
| 709 | for (int i = 0; i < result->max_entities; ++i) { |
| 710 | // Find an empty slot and fill it. |
| 711 | if (result->entities[i] == NULL) { |
| 712 | result->entities[i] = start; |
| 713 | result->entities_map[idx] = i; |
| 714 | break; |
| 715 | } |
| 716 | } |
| 717 | // Make sure that a slot was found. |
| 718 | CHECK_GE(result->entities_map[idx], 0); |
| 719 | } |
| 720 | |
| 721 | |
| 722 | static void Pass2CodeDelete(char* start, char* end, ParseLogResult* result) { |
| 723 | Address addr = result->ConsumeAddress(&start); |
| 724 | size_t idx = result->GetIndexForAddress(addr); |
| 725 | // There can be code deletes that are not related to JS code. |
| 726 | if (result->entities_map[idx] >= 0) { |
| 727 | result->entities[result->entities_map[idx]] = NULL; |
| 728 | result->entities_map[idx] = -1; |
| 729 | } |
| 730 | } |
| 731 | |
| 732 | |
| 733 | static void Pass2CodeMove(char* start, char* end, ParseLogResult* result) { |
| 734 | Address from_addr = result->ConsumeAddress(&start); |
| 735 | CHECK_GT(end, start); |
| 736 | ++start; // Skip ','. |
| 737 | Address to_addr = result->ConsumeAddress(&start); |
| 738 | CHECK_GT(end, start); |
| 739 | |
| 740 | size_t from_idx = result->GetIndexForAddress(from_addr); |
| 741 | size_t to_idx = result->GetIndexForAddress(to_addr); |
| 742 | // There can be code moves that are not related to JS code. |
| 743 | if (from_idx != to_idx && result->entities_map[from_idx] >= 0) { |
| 744 | CHECK_EQ(-1, result->entities_map[to_idx]); |
| 745 | result->entities_map[to_idx] = result->entities_map[from_idx]; |
| 746 | result->entities_map[from_idx] = -1; |
| 747 | }; |
| 748 | } |
| 749 | |
| 750 | |
| 751 | static void ParseLog(char* start, char* end, ParseLogResult* result) { |
| 752 | // Pass 1: Calculate boundaries of addresses and entities count. |
| 753 | ParserCycle(start, end, result, |
| 754 | Pass1CodeCreation, Pass1CodeDelete, Pass1CodeMove); |
| 755 | |
| 756 | printf("min_addr: %p, max_addr: %p, entities: %d\n", |
| 757 | result->bounds.GetMinAddr(), result->bounds.GetMaxAddr(), |
| 758 | result->max_entities); |
| 759 | |
| 760 | result->AllocateEntities(); |
| 761 | |
| 762 | // Pass 2: Fill in code entries data. |
| 763 | ParserCycle(start, end, result, |
| 764 | Pass2CodeCreation, Pass2CodeDelete, Pass2CodeMove); |
| 765 | } |
| 766 | |
| 767 | |
| 768 | static inline void PrintCodeEntityInfo(CodeEntityInfo entity) { |
| 769 | const int max_len = 50; |
| 770 | if (entity != NULL) { |
| 771 | char* eol = strchr(entity, '\n'); |
| 772 | int len = eol - entity; |
| 773 | len = len <= max_len ? len : max_len; |
| 774 | printf("%-*.*s ", max_len, len, entity); |
| 775 | } else { |
| 776 | printf("%*s", max_len + 1, ""); |
| 777 | } |
| 778 | } |
| 779 | |
| 780 | |
| 781 | static void PrintCodeEntitiesInfo( |
| 782 | bool is_equal, Address addr, |
| 783 | CodeEntityInfo l_entity, CodeEntityInfo r_entity) { |
| 784 | printf("%c %p ", is_equal ? ' ' : '*', addr); |
| 785 | PrintCodeEntityInfo(l_entity); |
| 786 | PrintCodeEntityInfo(r_entity); |
| 787 | printf("\n"); |
| 788 | } |
| 789 | |
| 790 | |
| 791 | static inline int StrChrLen(const char* s, char c) { |
| 792 | return strchr(s, c) - s; |
| 793 | } |
| 794 | |
| 795 | |
| 796 | static bool AreFuncSizesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { |
| 797 | int ref_len = StrChrLen(ref_s, ','); |
| 798 | int new_len = StrChrLen(new_s, ','); |
| 799 | return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; |
| 800 | } |
| 801 | |
| 802 | |
| 803 | static bool AreFuncNamesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { |
| 804 | // Skip size. |
| 805 | ref_s = strchr(ref_s, ',') + 1; |
| 806 | new_s = strchr(new_s, ',') + 1; |
| 807 | int ref_len = StrChrLen(ref_s, '\n'); |
| 808 | int new_len = StrChrLen(new_s, '\n'); |
| 809 | // If reference is anonymous (""), it's OK to have anything in new. |
| 810 | if (ref_len == 2) return true; |
| 811 | // A special case for ErrorPrototype. Haven't yet figured out why they |
| 812 | // are different. |
| 813 | const char* error_prototype = "\"ErrorPrototype"; |
| 814 | if (IsStringEqualTo(error_prototype, ref_s) |
| 815 | && IsStringEqualTo(error_prototype, new_s)) { |
| 816 | return true; |
| 817 | } |
| 818 | // Built-in objects have problems too. |
| 819 | const char* built_ins[] = { |
| 820 | "\"Boolean\"", "\"Function\"", "\"Number\"", |
| 821 | "\"Object\"", "\"Script\"", "\"String\"" |
| 822 | }; |
| 823 | for (size_t i = 0; i < sizeof(built_ins) / sizeof(*built_ins); ++i) { |
| 824 | if (IsStringEqualTo(built_ins[i], new_s)) { |
| 825 | return true; |
| 826 | } |
| 827 | } |
| 828 | return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; |
| 829 | } |
| 830 | |
| 831 | |
| 832 | static bool AreEntitiesEqual(CodeEntityInfo ref_e, CodeEntityInfo new_e) { |
| 833 | if (ref_e == NULL && new_e != NULL) return true; |
| 834 | if (ref_e != NULL && new_e != NULL) { |
| 835 | return AreFuncSizesEqual(ref_e, new_e) && AreFuncNamesEqual(ref_e, new_e); |
| 836 | } |
| 837 | if (ref_e != NULL && new_e == NULL) { |
| 838 | // args_count entities (argument adapters) are not found by heap traversal, |
| 839 | // but they are not needed because they doesn't contain any code. |
| 840 | ref_e = strchr(ref_e, ',') + 1; |
| 841 | const char* args_count = "\"args_count:"; |
| 842 | return IsStringEqualTo(args_count, ref_e); |
| 843 | } |
| 844 | return false; |
| 845 | } |
| 846 | |
| 847 | |
| 848 | // Test that logging of code create / move / delete events |
| 849 | // is equivalent to traversal of a resulting heap. |
| 850 | TEST(EquivalenceOfLoggingAndTraversal) { |
| 851 | // This test needs to be run on a "clean" V8 to ensure that snapshot log |
| 852 | // is loaded. This is always true when running using tools/test.py because |
| 853 | // it launches a new cctest instance for every test. To be sure that launching |
| 854 | // cctest manually also works, please be sure that no tests below |
| 855 | // are using V8. |
| 856 | // |
| 857 | // P.S. No, V8 can't be re-initialized after disposal, see include/v8.h. |
| 858 | CHECK(!i::V8::IsRunning()); |
| 859 | |
| 860 | i::FLAG_logfile = "*"; |
| 861 | i::FLAG_log = true; |
| 862 | i::FLAG_log_code = true; |
| 863 | |
| 864 | // Make sure objects move. |
| 865 | bool saved_always_compact = i::FLAG_always_compact; |
| 866 | if (!i::FLAG_never_compact) { |
| 867 | i::FLAG_always_compact = true; |
| 868 | } |
| 869 | |
| 870 | v8::HandleScope scope; |
| 871 | v8::Handle<v8::Value> global_object = v8::Handle<v8::Value>(); |
| 872 | v8::Handle<v8::Context> env = v8::Context::New( |
| 873 | 0, v8::Handle<v8::ObjectTemplate>(), global_object); |
| 874 | env->Enter(); |
| 875 | |
| 876 | // Compile and run a function that creates other functions. |
| 877 | CompileAndRunScript( |
| 878 | "(function f(obj) {\n" |
| 879 | " obj.test =\n" |
| 880 | " (function a(j) { return function b() { return j; } })(100);\n" |
| 881 | "})(this);"); |
| 882 | i::Heap::CollectAllGarbage(false); |
| 883 | |
| 884 | EmbeddedVector<char, 204800> buffer; |
| 885 | int log_size; |
| 886 | ParseLogResult ref_result; |
| 887 | |
| 888 | // Retrieve the log. |
| 889 | { |
| 890 | // Make sure that no GCs occur prior to LogCompiledFunctions call. |
| 891 | i::AssertNoAllocation no_alloc; |
| 892 | |
| 893 | log_size = GetLogLines(0, &buffer); |
| 894 | CHECK_GT(log_size, 0); |
| 895 | CHECK_GT(buffer.length(), log_size); |
| 896 | |
| 897 | // Fill a map of compiled code objects. |
| 898 | ParseLog(buffer.start(), buffer.start() + log_size, &ref_result); |
| 899 | } |
| 900 | |
| 901 | // Iterate heap to find compiled functions, will write to log. |
| 902 | i::Logger::LogCompiledFunctions(); |
| 903 | char* new_log_start = buffer.start() + log_size; |
| 904 | const int new_log_size = Logger::GetLogLines( |
| 905 | log_size, new_log_start, buffer.length() - log_size); |
| 906 | CHECK_GT(new_log_size, 0); |
| 907 | CHECK_GT(buffer.length(), log_size + new_log_size); |
| 908 | |
| 909 | // Fill an equivalent map of compiled code objects. |
| 910 | ParseLogResult new_result; |
| 911 | ParseLog(new_log_start, new_log_start + new_log_size, &new_result); |
| 912 | |
| 913 | // Test their actual equivalence. |
| 914 | Interval combined; |
| 915 | combined.CloneFrom(&ref_result.bounds); |
| 916 | combined.CloneFrom(&new_result.bounds); |
| 917 | Interval* iter = &combined; |
| 918 | bool results_equal = true; |
| 919 | |
| 920 | while (iter != NULL) { |
| 921 | for (Address addr = iter->raw_min_addr(); |
| 922 | addr <= iter->raw_max_addr(); ++addr) { |
| 923 | CodeEntityInfo ref_entity = ref_result.GetEntity(addr); |
| 924 | CodeEntityInfo new_entity = new_result.GetEntity(addr); |
| 925 | if (ref_entity != NULL || new_entity != NULL) { |
| 926 | const bool equal = AreEntitiesEqual(ref_entity, new_entity); |
| 927 | if (!equal) results_equal = false; |
| 928 | PrintCodeEntitiesInfo(equal, addr, ref_entity, new_entity); |
| 929 | } |
| 930 | } |
| 931 | iter = iter->get_next(); |
| 932 | } |
| 933 | // Make sure that all log data is written prior crash due to CHECK failure. |
| 934 | fflush(stdout); |
| 935 | CHECK(results_equal); |
| 936 | |
| 937 | env->Exit(); |
| 938 | Logger::TearDown(); |
| 939 | i::FLAG_always_compact = saved_always_compact; |
| 940 | } |
| 941 | |
| 942 | #endif // ENABLE_LOGGING_AND_PROFILING |