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" |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 16 | #include "cpu-profiler.h" |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 17 | #include "v8threads.h" |
| 18 | #include "cctest.h" |
| 19 | |
| 20 | using v8::internal::Address; |
| 21 | using v8::internal::EmbeddedVector; |
| 22 | using v8::internal::Logger; |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 23 | using v8::internal::StrLength; |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 24 | |
| 25 | namespace i = v8::internal; |
| 26 | |
| 27 | static void SetUp() { |
| 28 | // Log to memory buffer. |
| 29 | i::FLAG_logfile = "*"; |
| 30 | i::FLAG_log = true; |
| 31 | Logger::Setup(); |
| 32 | } |
| 33 | |
| 34 | static void TearDown() { |
| 35 | Logger::TearDown(); |
| 36 | } |
| 37 | |
| 38 | |
| 39 | TEST(EmptyLog) { |
| 40 | SetUp(); |
| 41 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 0)); |
| 42 | CHECK_EQ(0, Logger::GetLogLines(100, NULL, 0)); |
| 43 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 100)); |
| 44 | CHECK_EQ(0, Logger::GetLogLines(100, NULL, 100)); |
| 45 | TearDown(); |
| 46 | } |
| 47 | |
| 48 | |
| 49 | TEST(GetMessages) { |
| 50 | SetUp(); |
| 51 | Logger::StringEvent("aaa", "bbb"); |
| 52 | Logger::StringEvent("cccc", "dddd"); |
| 53 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 0)); |
| 54 | char log_lines[100]; |
| 55 | memset(log_lines, 0, sizeof(log_lines)); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 56 | // See Logger::StringEvent. |
| 57 | const char* line_1 = "aaa,\"bbb\"\n"; |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 58 | const int line_1_len = StrLength(line_1); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 59 | // The exact size. |
| 60 | CHECK_EQ(line_1_len, Logger::GetLogLines(0, log_lines, line_1_len)); |
| 61 | CHECK_EQ(line_1, log_lines); |
| 62 | memset(log_lines, 0, sizeof(log_lines)); |
| 63 | // A bit more than the first line length. |
| 64 | CHECK_EQ(line_1_len, Logger::GetLogLines(0, log_lines, line_1_len + 3)); |
| 65 | log_lines[line_1_len] = '\0'; |
| 66 | CHECK_EQ(line_1, log_lines); |
| 67 | memset(log_lines, 0, sizeof(log_lines)); |
| 68 | const char* line_2 = "cccc,\"dddd\"\n"; |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 69 | const int line_2_len = StrLength(line_2); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 70 | // Now start with line_2 beginning. |
| 71 | CHECK_EQ(0, Logger::GetLogLines(line_1_len, log_lines, 0)); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 72 | CHECK_EQ(line_2_len, Logger::GetLogLines(line_1_len, log_lines, line_2_len)); |
| 73 | CHECK_EQ(line_2, log_lines); |
| 74 | memset(log_lines, 0, sizeof(log_lines)); |
| 75 | CHECK_EQ(line_2_len, |
| 76 | Logger::GetLogLines(line_1_len, log_lines, line_2_len + 3)); |
| 77 | CHECK_EQ(line_2, log_lines); |
| 78 | memset(log_lines, 0, sizeof(log_lines)); |
| 79 | // Now get entire buffer contents. |
| 80 | const char* all_lines = "aaa,\"bbb\"\ncccc,\"dddd\"\n"; |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 81 | const int all_lines_len = StrLength(all_lines); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 82 | CHECK_EQ(all_lines_len, Logger::GetLogLines(0, log_lines, all_lines_len)); |
| 83 | CHECK_EQ(all_lines, log_lines); |
| 84 | memset(log_lines, 0, sizeof(log_lines)); |
| 85 | CHECK_EQ(all_lines_len, Logger::GetLogLines(0, log_lines, all_lines_len + 3)); |
| 86 | CHECK_EQ(all_lines, log_lines); |
| 87 | memset(log_lines, 0, sizeof(log_lines)); |
| 88 | TearDown(); |
| 89 | } |
| 90 | |
| 91 | |
| 92 | static int GetLogLines(int start_pos, i::Vector<char>* buffer) { |
| 93 | return Logger::GetLogLines(start_pos, buffer->start(), buffer->length()); |
| 94 | } |
| 95 | |
| 96 | |
| 97 | TEST(BeyondWritePosition) { |
| 98 | SetUp(); |
| 99 | Logger::StringEvent("aaa", "bbb"); |
| 100 | Logger::StringEvent("cccc", "dddd"); |
| 101 | // See Logger::StringEvent. |
| 102 | const char* all_lines = "aaa,\"bbb\"\ncccc,\"dddd\"\n"; |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 103 | const int all_lines_len = StrLength(all_lines); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 104 | EmbeddedVector<char, 100> buffer; |
| 105 | const int beyond_write_pos = all_lines_len; |
| 106 | CHECK_EQ(0, Logger::GetLogLines(beyond_write_pos, buffer.start(), 1)); |
| 107 | CHECK_EQ(0, GetLogLines(beyond_write_pos, &buffer)); |
| 108 | CHECK_EQ(0, Logger::GetLogLines(beyond_write_pos + 1, buffer.start(), 1)); |
| 109 | CHECK_EQ(0, GetLogLines(beyond_write_pos + 1, &buffer)); |
| 110 | CHECK_EQ(0, Logger::GetLogLines(beyond_write_pos + 100, buffer.start(), 1)); |
| 111 | CHECK_EQ(0, GetLogLines(beyond_write_pos + 100, &buffer)); |
| 112 | CHECK_EQ(0, Logger::GetLogLines(10 * 1024 * 1024, buffer.start(), 1)); |
| 113 | CHECK_EQ(0, GetLogLines(10 * 1024 * 1024, &buffer)); |
| 114 | TearDown(); |
| 115 | } |
| 116 | |
| 117 | |
| 118 | TEST(MemoryLoggingTurnedOff) { |
| 119 | // Log to stdout |
| 120 | i::FLAG_logfile = "-"; |
| 121 | i::FLAG_log = true; |
| 122 | Logger::Setup(); |
| 123 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 0)); |
| 124 | CHECK_EQ(0, Logger::GetLogLines(100, NULL, 0)); |
| 125 | CHECK_EQ(0, Logger::GetLogLines(0, NULL, 100)); |
| 126 | CHECK_EQ(0, Logger::GetLogLines(100, NULL, 100)); |
| 127 | Logger::TearDown(); |
| 128 | } |
| 129 | |
| 130 | |
| 131 | static void CompileAndRunScript(const char *src) { |
| 132 | v8::Script::Compile(v8::String::New(src))->Run(); |
| 133 | } |
| 134 | |
| 135 | |
| 136 | namespace v8 { |
| 137 | namespace internal { |
| 138 | |
| 139 | class LoggerTestHelper : public AllStatic { |
| 140 | public: |
| 141 | static bool IsSamplerActive() { return Logger::IsProfilerSamplerActive(); } |
| 142 | }; |
| 143 | |
| 144 | } // namespace v8::internal |
| 145 | } // namespace v8 |
| 146 | |
| 147 | using v8::internal::LoggerTestHelper; |
| 148 | |
| 149 | |
| 150 | // Under Linux, we need to check if signals were delivered to avoid false |
| 151 | // positives. Under other platforms profiling is done via a high-priority |
| 152 | // thread, so this case never happen. |
| 153 | static bool was_sigprof_received = true; |
| 154 | #ifdef __linux__ |
| 155 | |
| 156 | struct sigaction old_sigprof_handler; |
| 157 | pthread_t our_thread; |
| 158 | |
| 159 | static void SigProfSignalHandler(int signal, siginfo_t* info, void* context) { |
| 160 | if (signal != SIGPROF || !pthread_equal(pthread_self(), our_thread)) return; |
| 161 | was_sigprof_received = true; |
| 162 | old_sigprof_handler.sa_sigaction(signal, info, context); |
| 163 | } |
| 164 | |
| 165 | #endif // __linux__ |
| 166 | |
| 167 | |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 168 | namespace { |
| 169 | |
| 170 | class ScopedLoggerInitializer { |
| 171 | public: |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 172 | explicit ScopedLoggerInitializer(bool prof_lazy) |
| 173 | : saved_prof_lazy_(i::FLAG_prof_lazy), |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 174 | saved_prof_(i::FLAG_prof), |
| 175 | saved_prof_auto_(i::FLAG_prof_auto), |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 176 | trick_to_run_init_flags_(init_flags_(prof_lazy)), |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 177 | need_to_set_up_logger_(i::V8::IsRunning()), |
| 178 | scope_(), |
| 179 | env_(v8::Context::New()) { |
| 180 | if (need_to_set_up_logger_) Logger::Setup(); |
| 181 | env_->Enter(); |
| 182 | } |
| 183 | |
| 184 | ~ScopedLoggerInitializer() { |
| 185 | env_->Exit(); |
| 186 | Logger::TearDown(); |
| 187 | i::FLAG_prof_lazy = saved_prof_lazy_; |
| 188 | i::FLAG_prof = saved_prof_; |
| 189 | i::FLAG_prof_auto = saved_prof_auto_; |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 190 | } |
| 191 | |
| 192 | v8::Handle<v8::Context>& env() { return env_; } |
| 193 | |
| 194 | private: |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 195 | static bool init_flags_(bool prof_lazy) { |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 196 | i::FLAG_prof = true; |
| 197 | i::FLAG_prof_lazy = prof_lazy; |
| 198 | i::FLAG_prof_auto = false; |
| 199 | i::FLAG_logfile = "*"; |
| 200 | return prof_lazy; |
| 201 | } |
| 202 | |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 203 | const bool saved_prof_lazy_; |
| 204 | const bool saved_prof_; |
| 205 | const bool saved_prof_auto_; |
| 206 | const bool trick_to_run_init_flags_; |
| 207 | const bool need_to_set_up_logger_; |
| 208 | v8::HandleScope scope_; |
| 209 | v8::Handle<v8::Context> env_; |
| 210 | |
| 211 | DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer); |
| 212 | }; |
| 213 | |
| 214 | |
| 215 | class LogBufferMatcher { |
| 216 | public: |
| 217 | LogBufferMatcher() { |
| 218 | // Skip all initially logged stuff. |
| 219 | log_pos_ = GetLogLines(0, &buffer_); |
| 220 | } |
| 221 | |
| 222 | int log_pos() { return log_pos_; } |
| 223 | |
| 224 | int GetNextChunk() { |
| 225 | int chunk_size = GetLogLines(log_pos_, &buffer_); |
| 226 | CHECK_GT(buffer_.length(), chunk_size); |
| 227 | buffer_[chunk_size] = '\0'; |
| 228 | log_pos_ += chunk_size; |
| 229 | return chunk_size; |
| 230 | } |
| 231 | |
| 232 | const char* Find(const char* substr) { |
| 233 | return strstr(buffer_.start(), substr); |
| 234 | } |
| 235 | |
| 236 | const char* Find(const i::Vector<char>& substr) { |
| 237 | return Find(substr.start()); |
| 238 | } |
| 239 | |
| 240 | bool IsInSequence(const char* s1, const char* s2) { |
| 241 | const char* s1_pos = Find(s1); |
| 242 | const char* s2_pos = Find(s2); |
| 243 | CHECK_NE(NULL, s1_pos); |
| 244 | CHECK_NE(NULL, s2_pos); |
| 245 | return s1_pos < s2_pos; |
| 246 | } |
| 247 | |
| 248 | void PrintBuffer() { |
| 249 | puts(buffer_.start()); |
| 250 | } |
| 251 | |
| 252 | private: |
| 253 | EmbeddedVector<char, 102400> buffer_; |
| 254 | int log_pos_; |
| 255 | }; |
| 256 | |
| 257 | } // namespace |
| 258 | |
| 259 | |
| 260 | static void CheckThatProfilerWorks(LogBufferMatcher* matcher) { |
| 261 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 0); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 262 | CHECK(LoggerTestHelper::IsSamplerActive()); |
| 263 | |
| 264 | // Verify that the current map of compiled functions has been logged. |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 265 | CHECK_GT(matcher->GetNextChunk(), 0); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 266 | const char* code_creation = "\ncode-creation,"; // eq. to /^code-creation,/ |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 267 | CHECK_NE(NULL, matcher->Find(code_creation)); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 268 | |
| 269 | #ifdef __linux__ |
| 270 | // Intercept SIGPROF handler to make sure that the test process |
| 271 | // had received it. Under load, system can defer it causing test failure. |
| 272 | // It is important to execute this after 'ResumeProfiler'. |
| 273 | our_thread = pthread_self(); |
| 274 | was_sigprof_received = false; |
| 275 | struct sigaction sa; |
| 276 | sa.sa_sigaction = SigProfSignalHandler; |
| 277 | sigemptyset(&sa.sa_mask); |
| 278 | sa.sa_flags = SA_SIGINFO; |
| 279 | CHECK_EQ(0, sigaction(SIGPROF, &sa, &old_sigprof_handler)); |
| 280 | #endif // __linux__ |
| 281 | |
| 282 | // Force compiler to generate new code by parametrizing source. |
| 283 | EmbeddedVector<char, 100> script_src; |
| 284 | i::OS::SNPrintF(script_src, |
Leon Clarke | d91b9f7 | 2010-01-27 17:25:45 +0000 | [diff] [blame] | 285 | "function f%d(x) { return %d * x; }" |
| 286 | "for (var i = 0; i < 10000; ++i) { f%d(i); }", |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 287 | matcher->log_pos(), matcher->log_pos(), matcher->log_pos()); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 288 | // Run code for 200 msecs to get some ticks. |
| 289 | const double end_time = i::OS::TimeCurrentMillis() + 200; |
| 290 | while (i::OS::TimeCurrentMillis() < end_time) { |
| 291 | CompileAndRunScript(script_src.start()); |
| 292 | // Yield CPU to give Profiler thread a chance to process ticks. |
| 293 | i::OS::Sleep(1); |
| 294 | } |
| 295 | |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 296 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 0); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 297 | CHECK(!LoggerTestHelper::IsSamplerActive()); |
| 298 | |
| 299 | // Wait 50 msecs to allow Profiler thread to process the last |
| 300 | // tick sample it has got. |
| 301 | i::OS::Sleep(50); |
| 302 | |
| 303 | // Now we must have compiler and tick records. |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 304 | CHECK_GT(matcher->GetNextChunk(), 0); |
| 305 | matcher->PrintBuffer(); |
| 306 | CHECK_NE(NULL, matcher->Find(code_creation)); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 307 | const char* tick = "\ntick,"; |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 308 | const bool ticks_found = matcher->Find(tick) != NULL; |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 309 | CHECK_EQ(was_sigprof_received, ticks_found); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 310 | } |
| 311 | |
| 312 | |
| 313 | TEST(ProfLazyMode) { |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 314 | ScopedLoggerInitializer initialize_logger(true); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 315 | |
| 316 | // No sampling should happen prior to resuming profiler. |
| 317 | CHECK(!LoggerTestHelper::IsSamplerActive()); |
| 318 | |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 319 | LogBufferMatcher matcher; |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 320 | // Nothing must be logged until profiling is resumed. |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 321 | CHECK_EQ(0, matcher.log_pos()); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 322 | |
| 323 | CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); |
| 324 | |
| 325 | // Nothing must be logged while profiling is suspended. |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 326 | CHECK_EQ(0, matcher.GetNextChunk()); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 327 | |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 328 | CheckThatProfilerWorks(&matcher); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 329 | |
| 330 | CompileAndRunScript("var a = (function(x) { return x + 1; })(10);"); |
| 331 | |
| 332 | // No new data beyond last retrieved position. |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 333 | CHECK_EQ(0, matcher.GetNextChunk()); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 334 | |
| 335 | // Check that profiling can be resumed again. |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 336 | CheckThatProfilerWorks(&matcher); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 337 | } |
| 338 | |
| 339 | |
| 340 | // Profiling multiple threads that use V8 is currently only available on Linux. |
| 341 | #ifdef __linux__ |
| 342 | |
| 343 | namespace { |
| 344 | |
| 345 | class LoopingThread : public v8::internal::Thread { |
| 346 | public: |
| 347 | LoopingThread() |
| 348 | : v8::internal::Thread(), |
| 349 | semaphore_(v8::internal::OS::CreateSemaphore(0)), |
| 350 | run_(true) { |
| 351 | } |
| 352 | |
| 353 | virtual ~LoopingThread() { delete semaphore_; } |
| 354 | |
| 355 | void Run() { |
| 356 | self_ = pthread_self(); |
| 357 | RunLoop(); |
| 358 | } |
| 359 | |
| 360 | void SendSigProf() { pthread_kill(self_, SIGPROF); } |
| 361 | |
| 362 | void Stop() { run_ = false; } |
| 363 | |
| 364 | bool WaitForRunning() { return semaphore_->Wait(1000000); } |
| 365 | |
| 366 | protected: |
| 367 | bool IsRunning() { return run_; } |
| 368 | |
| 369 | virtual void RunLoop() = 0; |
| 370 | |
| 371 | void SetV8ThreadId() { |
| 372 | v8_thread_id_ = v8::V8::GetCurrentThreadId(); |
| 373 | } |
| 374 | |
| 375 | void SignalRunning() { semaphore_->Signal(); } |
| 376 | |
| 377 | private: |
| 378 | v8::internal::Semaphore* semaphore_; |
| 379 | bool run_; |
| 380 | pthread_t self_; |
| 381 | int v8_thread_id_; |
| 382 | }; |
| 383 | |
| 384 | |
| 385 | class LoopingJsThread : public LoopingThread { |
| 386 | public: |
| 387 | void RunLoop() { |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 388 | v8::Locker locker; |
| 389 | CHECK(v8::internal::ThreadManager::HasId()); |
| 390 | SetV8ThreadId(); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 391 | while (IsRunning()) { |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 392 | v8::HandleScope scope; |
| 393 | v8::Persistent<v8::Context> context = v8::Context::New(); |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 394 | CHECK(!context.IsEmpty()); |
| 395 | { |
| 396 | v8::Context::Scope context_scope(context); |
| 397 | SignalRunning(); |
| 398 | CompileAndRunScript( |
| 399 | "var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }"); |
| 400 | } |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 401 | context.Dispose(); |
| 402 | i::OS::Sleep(1); |
| 403 | } |
| 404 | } |
| 405 | }; |
| 406 | |
| 407 | |
| 408 | class LoopingNonJsThread : public LoopingThread { |
| 409 | public: |
| 410 | void RunLoop() { |
| 411 | v8::Locker locker; |
| 412 | v8::Unlocker unlocker; |
| 413 | // Now thread has V8's id, but will not run VM code. |
| 414 | CHECK(v8::internal::ThreadManager::HasId()); |
| 415 | double i = 10; |
| 416 | SignalRunning(); |
| 417 | while (IsRunning()) { |
| 418 | i = sin(i); |
| 419 | i::OS::Sleep(1); |
| 420 | } |
| 421 | } |
| 422 | }; |
| 423 | |
| 424 | |
| 425 | class TestSampler : public v8::internal::Sampler { |
| 426 | public: |
| 427 | TestSampler() |
| 428 | : Sampler(0, true), |
| 429 | semaphore_(v8::internal::OS::CreateSemaphore(0)), |
| 430 | was_sample_stack_called_(false) { |
| 431 | } |
| 432 | |
| 433 | ~TestSampler() { delete semaphore_; } |
| 434 | |
| 435 | void SampleStack(v8::internal::TickSample*) { |
| 436 | was_sample_stack_called_ = true; |
| 437 | } |
| 438 | |
| 439 | void Tick(v8::internal::TickSample*) { semaphore_->Signal(); } |
| 440 | |
| 441 | bool WaitForTick() { return semaphore_->Wait(1000000); } |
| 442 | |
| 443 | void Reset() { was_sample_stack_called_ = false; } |
| 444 | |
| 445 | bool WasSampleStackCalled() { return was_sample_stack_called_; } |
| 446 | |
| 447 | private: |
| 448 | v8::internal::Semaphore* semaphore_; |
| 449 | bool was_sample_stack_called_; |
| 450 | }; |
| 451 | |
| 452 | |
| 453 | } // namespace |
| 454 | |
| 455 | TEST(ProfMultipleThreads) { |
| 456 | LoopingJsThread jsThread; |
| 457 | jsThread.Start(); |
| 458 | LoopingNonJsThread nonJsThread; |
| 459 | nonJsThread.Start(); |
| 460 | |
| 461 | TestSampler sampler; |
| 462 | sampler.Start(); |
| 463 | CHECK(!sampler.WasSampleStackCalled()); |
| 464 | jsThread.WaitForRunning(); |
| 465 | jsThread.SendSigProf(); |
| 466 | CHECK(sampler.WaitForTick()); |
| 467 | CHECK(sampler.WasSampleStackCalled()); |
| 468 | sampler.Reset(); |
| 469 | CHECK(!sampler.WasSampleStackCalled()); |
| 470 | nonJsThread.WaitForRunning(); |
| 471 | nonJsThread.SendSigProf(); |
Ben Murdoch | f87a203 | 2010-10-22 12:50:53 +0100 | [diff] [blame^] | 472 | CHECK(!sampler.WaitForTick()); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 473 | CHECK(!sampler.WasSampleStackCalled()); |
| 474 | sampler.Stop(); |
| 475 | |
| 476 | jsThread.Stop(); |
| 477 | nonJsThread.Stop(); |
| 478 | jsThread.Join(); |
| 479 | nonJsThread.Join(); |
| 480 | } |
| 481 | |
| 482 | #endif // __linux__ |
| 483 | |
| 484 | |
Steve Block | 3ce2e20 | 2009-11-05 08:53:23 +0000 | [diff] [blame] | 485 | // Test for issue http://crbug.com/23768 in Chromium. |
| 486 | // Heap can contain scripts with already disposed external sources. |
| 487 | // We need to verify that LogCompiledFunctions doesn't crash on them. |
| 488 | namespace { |
| 489 | |
| 490 | class SimpleExternalString : public v8::String::ExternalStringResource { |
| 491 | public: |
| 492 | explicit SimpleExternalString(const char* source) |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 493 | : utf_source_(StrLength(source)) { |
Steve Block | 3ce2e20 | 2009-11-05 08:53:23 +0000 | [diff] [blame] | 494 | for (int i = 0; i < utf_source_.length(); ++i) |
| 495 | utf_source_[i] = source[i]; |
| 496 | } |
| 497 | virtual ~SimpleExternalString() {} |
| 498 | virtual size_t length() const { return utf_source_.length(); } |
| 499 | virtual const uint16_t* data() const { return utf_source_.start(); } |
| 500 | private: |
| 501 | i::ScopedVector<uint16_t> utf_source_; |
| 502 | }; |
| 503 | |
| 504 | } // namespace |
| 505 | |
| 506 | TEST(Issue23768) { |
| 507 | v8::HandleScope scope; |
| 508 | v8::Handle<v8::Context> env = v8::Context::New(); |
| 509 | env->Enter(); |
| 510 | |
| 511 | SimpleExternalString source_ext_str("(function ext() {})();"); |
| 512 | v8::Local<v8::String> source = v8::String::NewExternal(&source_ext_str); |
| 513 | // Script needs to have a name in order to trigger InitLineEnds execution. |
| 514 | v8::Handle<v8::String> origin = v8::String::New("issue-23768-test"); |
| 515 | v8::Handle<v8::Script> evil_script = v8::Script::Compile(source, origin); |
| 516 | CHECK(!evil_script.IsEmpty()); |
| 517 | CHECK(!evil_script->Run().IsEmpty()); |
| 518 | i::Handle<i::ExternalTwoByteString> i_source( |
| 519 | i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source))); |
| 520 | // This situation can happen if source was an external string disposed |
| 521 | // by its owner. |
| 522 | i_source->set_resource(NULL); |
| 523 | |
| 524 | // Must not crash. |
| 525 | i::Logger::LogCompiledFunctions(); |
| 526 | } |
| 527 | |
| 528 | |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 529 | static v8::Handle<v8::Value> ObjMethod1(const v8::Arguments& args) { |
| 530 | return v8::Handle<v8::Value>(); |
| 531 | } |
| 532 | |
| 533 | TEST(LogCallbacks) { |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 534 | ScopedLoggerInitializer initialize_logger(false); |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 535 | LogBufferMatcher matcher; |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 536 | |
| 537 | v8::Persistent<v8::FunctionTemplate> obj = |
| 538 | v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New()); |
| 539 | obj->SetClassName(v8::String::New("Obj")); |
| 540 | v8::Handle<v8::ObjectTemplate> proto = obj->PrototypeTemplate(); |
| 541 | v8::Local<v8::Signature> signature = v8::Signature::New(obj); |
| 542 | proto->Set(v8::String::New("method1"), |
| 543 | v8::FunctionTemplate::New(ObjMethod1, |
| 544 | v8::Handle<v8::Value>(), |
| 545 | signature), |
| 546 | static_cast<v8::PropertyAttribute>(v8::DontDelete)); |
| 547 | |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 548 | initialize_logger.env()->Global()->Set(v8_str("Obj"), obj->GetFunction()); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 549 | CompileAndRunScript("Obj.prototype.method1.toString();"); |
| 550 | |
| 551 | i::Logger::LogCompiledFunctions(); |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 552 | CHECK_GT(matcher.GetNextChunk(), 0); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 553 | |
| 554 | const char* callback_rec = "code-creation,Callback,"; |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 555 | char* pos = const_cast<char*>(matcher.Find(callback_rec)); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 556 | CHECK_NE(NULL, pos); |
| 557 | pos += strlen(callback_rec); |
| 558 | EmbeddedVector<char, 100> ref_data; |
| 559 | i::OS::SNPrintF(ref_data, |
| 560 | "0x%" V8PRIxPTR ",1,\"method1\"", ObjMethod1); |
| 561 | *(pos + strlen(ref_data.start())) = '\0'; |
| 562 | CHECK_EQ(ref_data.start(), pos); |
| 563 | |
| 564 | obj.Dispose(); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 565 | } |
| 566 | |
| 567 | |
| 568 | static v8::Handle<v8::Value> Prop1Getter(v8::Local<v8::String> property, |
| 569 | const v8::AccessorInfo& info) { |
| 570 | return v8::Handle<v8::Value>(); |
| 571 | } |
| 572 | |
| 573 | static void Prop1Setter(v8::Local<v8::String> property, |
| 574 | v8::Local<v8::Value> value, |
| 575 | const v8::AccessorInfo& info) { |
| 576 | } |
| 577 | |
| 578 | static v8::Handle<v8::Value> Prop2Getter(v8::Local<v8::String> property, |
| 579 | const v8::AccessorInfo& info) { |
| 580 | return v8::Handle<v8::Value>(); |
| 581 | } |
| 582 | |
| 583 | TEST(LogAccessorCallbacks) { |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 584 | ScopedLoggerInitializer initialize_logger(false); |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 585 | LogBufferMatcher matcher; |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 586 | |
| 587 | v8::Persistent<v8::FunctionTemplate> obj = |
| 588 | v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New()); |
| 589 | obj->SetClassName(v8::String::New("Obj")); |
| 590 | v8::Handle<v8::ObjectTemplate> inst = obj->InstanceTemplate(); |
| 591 | inst->SetAccessor(v8::String::New("prop1"), Prop1Getter, Prop1Setter); |
| 592 | inst->SetAccessor(v8::String::New("prop2"), Prop2Getter); |
| 593 | |
| 594 | i::Logger::LogAccessorCallbacks(); |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 595 | CHECK_GT(matcher.GetNextChunk(), 0); |
| 596 | matcher.PrintBuffer(); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 597 | |
| 598 | EmbeddedVector<char, 100> prop1_getter_record; |
| 599 | i::OS::SNPrintF(prop1_getter_record, |
| 600 | "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop1\"", |
| 601 | Prop1Getter); |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 602 | CHECK_NE(NULL, matcher.Find(prop1_getter_record)); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 603 | EmbeddedVector<char, 100> prop1_setter_record; |
| 604 | i::OS::SNPrintF(prop1_setter_record, |
| 605 | "code-creation,Callback,0x%" V8PRIxPTR ",1,\"set prop1\"", |
| 606 | Prop1Setter); |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 607 | CHECK_NE(NULL, matcher.Find(prop1_setter_record)); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 608 | EmbeddedVector<char, 100> prop2_getter_record; |
| 609 | i::OS::SNPrintF(prop2_getter_record, |
| 610 | "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop2\"", |
| 611 | Prop2Getter); |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 612 | CHECK_NE(NULL, matcher.Find(prop2_getter_record)); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 613 | |
| 614 | obj.Dispose(); |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 615 | } |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 616 | |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 617 | |
| 618 | TEST(LogTags) { |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 619 | ScopedLoggerInitializer initialize_logger(false); |
Andrei Popescu | 402d937 | 2010-02-26 13:31:12 +0000 | [diff] [blame] | 620 | LogBufferMatcher matcher; |
| 621 | |
| 622 | const char* open_tag = "open-tag,"; |
| 623 | const char* close_tag = "close-tag,"; |
| 624 | |
| 625 | // Check compatibility with the old style behavior. |
| 626 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 627 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 0); |
| 628 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 629 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 0); |
| 630 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 631 | CHECK_EQ(NULL, matcher.Find(open_tag)); |
| 632 | CHECK_EQ(NULL, matcher.Find(close_tag)); |
| 633 | |
| 634 | const char* open_tag1 = "open-tag,1\n"; |
| 635 | const char* close_tag1 = "close-tag,1\n"; |
| 636 | |
| 637 | // Check non-nested tag case. |
| 638 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 639 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 640 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 641 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 642 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 643 | CHECK_GT(matcher.GetNextChunk(), 0); |
| 644 | CHECK(matcher.IsInSequence(open_tag1, close_tag1)); |
| 645 | |
| 646 | const char* open_tag2 = "open-tag,2\n"; |
| 647 | const char* close_tag2 = "close-tag,2\n"; |
| 648 | |
| 649 | // Check nested tags case. |
| 650 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 651 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 652 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 653 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 2); |
| 654 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 655 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 2); |
| 656 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 657 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 658 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 659 | CHECK_GT(matcher.GetNextChunk(), 0); |
| 660 | // open_tag1 < open_tag2 < close_tag2 < close_tag1 |
| 661 | CHECK(matcher.IsInSequence(open_tag1, open_tag2)); |
| 662 | CHECK(matcher.IsInSequence(open_tag2, close_tag2)); |
| 663 | CHECK(matcher.IsInSequence(close_tag2, close_tag1)); |
| 664 | |
| 665 | // Check overlapped tags case. |
| 666 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 667 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 668 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 669 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 2); |
| 670 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 671 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 672 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 673 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 2); |
| 674 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 675 | CHECK_GT(matcher.GetNextChunk(), 0); |
| 676 | // open_tag1 < open_tag2 < close_tag1 < close_tag2 |
| 677 | CHECK(matcher.IsInSequence(open_tag1, open_tag2)); |
| 678 | CHECK(matcher.IsInSequence(open_tag2, close_tag1)); |
| 679 | CHECK(matcher.IsInSequence(close_tag1, close_tag2)); |
| 680 | |
| 681 | const char* open_tag3 = "open-tag,3\n"; |
| 682 | const char* close_tag3 = "close-tag,3\n"; |
| 683 | |
| 684 | // Check pausing overflow case. |
| 685 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 686 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 687 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 688 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 2); |
| 689 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 690 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 2); |
| 691 | CHECK_EQ(v8::PROFILER_MODULE_CPU, Logger::GetActiveProfilerModules()); |
| 692 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 693 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 694 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 3); |
| 695 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 696 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 3); |
| 697 | CHECK_EQ(v8::PROFILER_MODULE_NONE, Logger::GetActiveProfilerModules()); |
| 698 | // Must be no tags, because logging must be disabled. |
| 699 | CHECK_EQ(NULL, matcher.Find(open_tag3)); |
| 700 | CHECK_EQ(NULL, matcher.Find(close_tag3)); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 701 | } |
| 702 | |
| 703 | |
Steve Block | 6ded16b | 2010-05-10 14:33:55 +0100 | [diff] [blame] | 704 | TEST(IsLoggingPreserved) { |
| 705 | ScopedLoggerInitializer initialize_logger(false); |
| 706 | |
| 707 | CHECK(Logger::is_logging()); |
| 708 | Logger::ResumeProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 709 | CHECK(Logger::is_logging()); |
| 710 | Logger::PauseProfiler(v8::PROFILER_MODULE_CPU, 1); |
| 711 | CHECK(Logger::is_logging()); |
| 712 | |
| 713 | CHECK(Logger::is_logging()); |
| 714 | Logger::ResumeProfiler( |
| 715 | v8::PROFILER_MODULE_HEAP_STATS | v8::PROFILER_MODULE_JS_CONSTRUCTORS, 1); |
| 716 | CHECK(Logger::is_logging()); |
| 717 | Logger::PauseProfiler( |
| 718 | v8::PROFILER_MODULE_HEAP_STATS | v8::PROFILER_MODULE_JS_CONSTRUCTORS, 1); |
| 719 | CHECK(Logger::is_logging()); |
| 720 | |
| 721 | CHECK(Logger::is_logging()); |
| 722 | Logger::ResumeProfiler( |
| 723 | v8::PROFILER_MODULE_CPU | |
| 724 | v8::PROFILER_MODULE_HEAP_STATS | v8::PROFILER_MODULE_JS_CONSTRUCTORS, 1); |
| 725 | CHECK(Logger::is_logging()); |
| 726 | Logger::PauseProfiler( |
| 727 | v8::PROFILER_MODULE_CPU | |
| 728 | v8::PROFILER_MODULE_HEAP_STATS | v8::PROFILER_MODULE_JS_CONSTRUCTORS, 1); |
| 729 | CHECK(Logger::is_logging()); |
| 730 | } |
| 731 | |
| 732 | |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 733 | static inline bool IsStringEqualTo(const char* r, const char* s) { |
| 734 | return strncmp(r, s, strlen(r)) == 0; |
| 735 | } |
| 736 | |
| 737 | |
| 738 | static bool Consume(const char* str, char** buf) { |
| 739 | if (IsStringEqualTo(str, *buf)) { |
| 740 | *buf += strlen(str); |
| 741 | return true; |
| 742 | } |
| 743 | return false; |
| 744 | } |
| 745 | |
| 746 | |
| 747 | namespace { |
| 748 | |
| 749 | // A code entity is a pointer to a position of code-creation event in buffer log |
| 750 | // offset to a point where entity size begins, i.e.: '255,"func"\n'. This makes |
| 751 | // comparing code entities pretty easy. |
| 752 | typedef char* CodeEntityInfo; |
| 753 | |
| 754 | class Interval { |
| 755 | public: |
| 756 | Interval() |
| 757 | : min_addr_(reinterpret_cast<Address>(-1)), |
| 758 | max_addr_(reinterpret_cast<Address>(0)), next_(NULL) {} |
| 759 | |
| 760 | ~Interval() { delete next_; } |
| 761 | |
| 762 | size_t Length() { |
| 763 | size_t result = max_addr_ - min_addr_ + 1; |
| 764 | if (next_ != NULL) result += next_->Length(); |
| 765 | return result; |
| 766 | } |
| 767 | |
| 768 | void CloneFrom(Interval* src) { |
| 769 | while (src != NULL) { |
| 770 | RegisterAddress(src->min_addr_); |
| 771 | RegisterAddress(src->max_addr_); |
| 772 | src = src->next_; |
| 773 | } |
| 774 | } |
| 775 | |
| 776 | bool Contains(Address addr) { |
| 777 | if (min_addr_ <= addr && addr <= max_addr_) { |
| 778 | return true; |
| 779 | } |
| 780 | if (next_ != NULL) { |
| 781 | return next_->Contains(addr); |
| 782 | } else { |
| 783 | return false; |
| 784 | } |
| 785 | } |
| 786 | |
| 787 | size_t GetIndex(Address addr) { |
| 788 | if (min_addr_ <= addr && addr <= max_addr_) { |
| 789 | return addr - min_addr_; |
| 790 | } |
| 791 | CHECK_NE(NULL, next_); |
| 792 | return (max_addr_ - min_addr_ + 1) + next_->GetIndex(addr); |
| 793 | } |
| 794 | |
| 795 | Address GetMinAddr() { |
| 796 | return next_ == NULL ? min_addr_ : i::Min(min_addr_, next_->GetMinAddr()); |
| 797 | } |
| 798 | |
| 799 | Address GetMaxAddr() { |
| 800 | return next_ == NULL ? max_addr_ : i::Max(max_addr_, next_->GetMaxAddr()); |
| 801 | } |
| 802 | |
| 803 | void RegisterAddress(Address addr) { |
| 804 | if (min_addr_ == reinterpret_cast<Address>(-1) |
| 805 | || (size_t)(addr > min_addr_ ? |
| 806 | addr - min_addr_ : min_addr_ - addr) < MAX_DELTA) { |
| 807 | if (addr < min_addr_) min_addr_ = addr; |
| 808 | if (addr > max_addr_) max_addr_ = addr; |
| 809 | } else { |
| 810 | if (next_ == NULL) next_ = new Interval(); |
| 811 | next_->RegisterAddress(addr); |
| 812 | } |
| 813 | } |
| 814 | |
| 815 | Address raw_min_addr() { return min_addr_; } |
| 816 | |
| 817 | Address raw_max_addr() { return max_addr_; } |
| 818 | |
| 819 | Interval* get_next() { return next_; } |
| 820 | |
| 821 | private: |
| 822 | static const size_t MAX_DELTA = 0x100000; |
| 823 | Address min_addr_; |
| 824 | Address max_addr_; |
| 825 | Interval* next_; |
| 826 | }; |
| 827 | |
| 828 | |
| 829 | // A structure used to return log parsing results. |
| 830 | class ParseLogResult { |
| 831 | public: |
| 832 | ParseLogResult() |
| 833 | : entities_map(NULL), entities(NULL), |
| 834 | max_entities(0) {} |
| 835 | |
| 836 | ~ParseLogResult() { |
| 837 | i::DeleteArray(entities_map); |
| 838 | i::DeleteArray(entities); |
| 839 | } |
| 840 | |
| 841 | void AllocateEntities() { |
| 842 | // Make sure that the test doesn't operate on a bogus log. |
| 843 | CHECK_GT(max_entities, 0); |
| 844 | CHECK_GT(bounds.GetMinAddr(), 0); |
| 845 | CHECK_GT(bounds.GetMaxAddr(), bounds.GetMinAddr()); |
| 846 | |
| 847 | entities = i::NewArray<CodeEntityInfo>(max_entities); |
| 848 | for (int i = 0; i < max_entities; ++i) { |
| 849 | entities[i] = NULL; |
| 850 | } |
| 851 | const size_t map_length = bounds.Length(); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 852 | entities_map = i::NewArray<int>(static_cast<int>(map_length)); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 853 | for (size_t i = 0; i < map_length; ++i) { |
| 854 | entities_map[i] = -1; |
| 855 | } |
| 856 | } |
| 857 | |
| 858 | bool HasIndexForAddress(Address addr) { |
| 859 | return bounds.Contains(addr); |
| 860 | } |
| 861 | |
| 862 | size_t GetIndexForAddress(Address addr) { |
| 863 | CHECK(HasIndexForAddress(addr)); |
| 864 | return bounds.GetIndex(addr); |
| 865 | } |
| 866 | |
| 867 | CodeEntityInfo GetEntity(Address addr) { |
| 868 | if (HasIndexForAddress(addr)) { |
| 869 | size_t idx = GetIndexForAddress(addr); |
| 870 | int item = entities_map[idx]; |
| 871 | return item != -1 ? entities[item] : NULL; |
| 872 | } |
| 873 | return NULL; |
| 874 | } |
| 875 | |
| 876 | void ParseAddress(char* start) { |
| 877 | Address addr = |
| 878 | reinterpret_cast<Address>(strtoul(start, NULL, 16)); // NOLINT |
| 879 | bounds.RegisterAddress(addr); |
| 880 | } |
| 881 | |
| 882 | Address ConsumeAddress(char** start) { |
| 883 | char* end_ptr; |
| 884 | Address addr = |
| 885 | reinterpret_cast<Address>(strtoul(*start, &end_ptr, 16)); // NOLINT |
| 886 | CHECK(HasIndexForAddress(addr)); |
| 887 | *start = end_ptr; |
| 888 | return addr; |
| 889 | } |
| 890 | |
| 891 | Interval bounds; |
| 892 | // Memory map of entities start addresses. |
| 893 | int* entities_map; |
| 894 | // An array of code entities. |
| 895 | CodeEntityInfo* entities; |
| 896 | // Maximal entities count. Actual entities count can be lower, |
| 897 | // empty entity slots are pointing to NULL. |
| 898 | int max_entities; |
| 899 | }; |
| 900 | |
| 901 | } // namespace |
| 902 | |
| 903 | |
| 904 | typedef void (*ParserBlock)(char* start, char* end, ParseLogResult* result); |
| 905 | |
| 906 | static void ParserCycle( |
| 907 | char* start, char* end, ParseLogResult* result, |
| 908 | ParserBlock block_creation, ParserBlock block_delete, |
| 909 | ParserBlock block_move) { |
| 910 | |
| 911 | const char* code_creation = "code-creation,"; |
| 912 | const char* code_delete = "code-delete,"; |
| 913 | const char* code_move = "code-move,"; |
| 914 | |
| 915 | const char* lazy_compile = "LazyCompile,"; |
| 916 | const char* script = "Script,"; |
| 917 | const char* function = "Function,"; |
| 918 | |
| 919 | while (start < end) { |
| 920 | if (Consume(code_creation, &start)) { |
| 921 | if (Consume(lazy_compile, &start) |
| 922 | || Consume(script, &start) |
| 923 | || Consume(function, &start)) { |
| 924 | block_creation(start, end, result); |
| 925 | } |
| 926 | } else if (Consume(code_delete, &start)) { |
| 927 | block_delete(start, end, result); |
| 928 | } else if (Consume(code_move, &start)) { |
| 929 | block_move(start, end, result); |
| 930 | } |
| 931 | while (start < end && *start != '\n') ++start; |
| 932 | ++start; |
| 933 | } |
| 934 | } |
| 935 | |
| 936 | |
| 937 | static void Pass1CodeCreation(char* start, char* end, ParseLogResult* result) { |
| 938 | result->ParseAddress(start); |
| 939 | ++result->max_entities; |
| 940 | } |
| 941 | |
| 942 | |
| 943 | static void Pass1CodeDelete(char* start, char* end, ParseLogResult* result) { |
| 944 | result->ParseAddress(start); |
| 945 | } |
| 946 | |
| 947 | |
| 948 | static void Pass1CodeMove(char* start, char* end, ParseLogResult* result) { |
| 949 | result->ParseAddress(start); |
| 950 | // Skip old address. |
| 951 | while (start < end && *start != ',') ++start; |
| 952 | CHECK_GT(end, start); |
| 953 | ++start; // Skip ','. |
| 954 | result->ParseAddress(start); |
| 955 | } |
| 956 | |
| 957 | |
| 958 | static void Pass2CodeCreation(char* start, char* end, ParseLogResult* result) { |
| 959 | Address addr = result->ConsumeAddress(&start); |
| 960 | CHECK_GT(end, start); |
| 961 | ++start; // Skip ','. |
| 962 | |
| 963 | size_t idx = result->GetIndexForAddress(addr); |
| 964 | result->entities_map[idx] = -1; |
| 965 | for (int i = 0; i < result->max_entities; ++i) { |
| 966 | // Find an empty slot and fill it. |
| 967 | if (result->entities[i] == NULL) { |
| 968 | result->entities[i] = start; |
| 969 | result->entities_map[idx] = i; |
| 970 | break; |
| 971 | } |
| 972 | } |
| 973 | // Make sure that a slot was found. |
| 974 | CHECK_GE(result->entities_map[idx], 0); |
| 975 | } |
| 976 | |
| 977 | |
| 978 | static void Pass2CodeDelete(char* start, char* end, ParseLogResult* result) { |
| 979 | Address addr = result->ConsumeAddress(&start); |
| 980 | size_t idx = result->GetIndexForAddress(addr); |
| 981 | // There can be code deletes that are not related to JS code. |
| 982 | if (result->entities_map[idx] >= 0) { |
| 983 | result->entities[result->entities_map[idx]] = NULL; |
| 984 | result->entities_map[idx] = -1; |
| 985 | } |
| 986 | } |
| 987 | |
| 988 | |
| 989 | static void Pass2CodeMove(char* start, char* end, ParseLogResult* result) { |
| 990 | Address from_addr = result->ConsumeAddress(&start); |
| 991 | CHECK_GT(end, start); |
| 992 | ++start; // Skip ','. |
| 993 | Address to_addr = result->ConsumeAddress(&start); |
| 994 | CHECK_GT(end, start); |
| 995 | |
| 996 | size_t from_idx = result->GetIndexForAddress(from_addr); |
| 997 | size_t to_idx = result->GetIndexForAddress(to_addr); |
| 998 | // There can be code moves that are not related to JS code. |
| 999 | if (from_idx != to_idx && result->entities_map[from_idx] >= 0) { |
| 1000 | CHECK_EQ(-1, result->entities_map[to_idx]); |
| 1001 | result->entities_map[to_idx] = result->entities_map[from_idx]; |
| 1002 | result->entities_map[from_idx] = -1; |
| 1003 | }; |
| 1004 | } |
| 1005 | |
| 1006 | |
| 1007 | static void ParseLog(char* start, char* end, ParseLogResult* result) { |
| 1008 | // Pass 1: Calculate boundaries of addresses and entities count. |
| 1009 | ParserCycle(start, end, result, |
| 1010 | Pass1CodeCreation, Pass1CodeDelete, Pass1CodeMove); |
| 1011 | |
| 1012 | printf("min_addr: %p, max_addr: %p, entities: %d\n", |
| 1013 | result->bounds.GetMinAddr(), result->bounds.GetMaxAddr(), |
| 1014 | result->max_entities); |
| 1015 | |
| 1016 | result->AllocateEntities(); |
| 1017 | |
| 1018 | // Pass 2: Fill in code entries data. |
| 1019 | ParserCycle(start, end, result, |
| 1020 | Pass2CodeCreation, Pass2CodeDelete, Pass2CodeMove); |
| 1021 | } |
| 1022 | |
| 1023 | |
| 1024 | static inline void PrintCodeEntityInfo(CodeEntityInfo entity) { |
| 1025 | const int max_len = 50; |
| 1026 | if (entity != NULL) { |
| 1027 | char* eol = strchr(entity, '\n'); |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 1028 | int len = static_cast<int>(eol - entity); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 1029 | len = len <= max_len ? len : max_len; |
| 1030 | printf("%-*.*s ", max_len, len, entity); |
| 1031 | } else { |
| 1032 | printf("%*s", max_len + 1, ""); |
| 1033 | } |
| 1034 | } |
| 1035 | |
| 1036 | |
| 1037 | static void PrintCodeEntitiesInfo( |
| 1038 | bool is_equal, Address addr, |
| 1039 | CodeEntityInfo l_entity, CodeEntityInfo r_entity) { |
| 1040 | printf("%c %p ", is_equal ? ' ' : '*', addr); |
| 1041 | PrintCodeEntityInfo(l_entity); |
| 1042 | PrintCodeEntityInfo(r_entity); |
| 1043 | printf("\n"); |
| 1044 | } |
| 1045 | |
| 1046 | |
| 1047 | static inline int StrChrLen(const char* s, char c) { |
Steve Block | d0582a6 | 2009-12-15 09:54:21 +0000 | [diff] [blame] | 1048 | return static_cast<int>(strchr(s, c) - s); |
Steve Block | a7e24c1 | 2009-10-30 11:49:00 +0000 | [diff] [blame] | 1049 | } |
| 1050 | |
| 1051 | |
| 1052 | static bool AreFuncSizesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { |
| 1053 | int ref_len = StrChrLen(ref_s, ','); |
| 1054 | int new_len = StrChrLen(new_s, ','); |
| 1055 | return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; |
| 1056 | } |
| 1057 | |
| 1058 | |
| 1059 | static bool AreFuncNamesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { |
| 1060 | // Skip size. |
| 1061 | ref_s = strchr(ref_s, ',') + 1; |
| 1062 | new_s = strchr(new_s, ',') + 1; |
| 1063 | int ref_len = StrChrLen(ref_s, '\n'); |
| 1064 | int new_len = StrChrLen(new_s, '\n'); |
| 1065 | // If reference is anonymous (""), it's OK to have anything in new. |
| 1066 | if (ref_len == 2) return true; |
| 1067 | // A special case for ErrorPrototype. Haven't yet figured out why they |
| 1068 | // are different. |
| 1069 | const char* error_prototype = "\"ErrorPrototype"; |
| 1070 | if (IsStringEqualTo(error_prototype, ref_s) |
| 1071 | && IsStringEqualTo(error_prototype, new_s)) { |
| 1072 | return true; |
| 1073 | } |
| 1074 | // Built-in objects have problems too. |
| 1075 | const char* built_ins[] = { |
| 1076 | "\"Boolean\"", "\"Function\"", "\"Number\"", |
| 1077 | "\"Object\"", "\"Script\"", "\"String\"" |
| 1078 | }; |
| 1079 | for (size_t i = 0; i < sizeof(built_ins) / sizeof(*built_ins); ++i) { |
| 1080 | if (IsStringEqualTo(built_ins[i], new_s)) { |
| 1081 | return true; |
| 1082 | } |
| 1083 | } |
| 1084 | return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; |
| 1085 | } |
| 1086 | |
| 1087 | |
| 1088 | static bool AreEntitiesEqual(CodeEntityInfo ref_e, CodeEntityInfo new_e) { |
| 1089 | if (ref_e == NULL && new_e != NULL) return true; |
| 1090 | if (ref_e != NULL && new_e != NULL) { |
| 1091 | return AreFuncSizesEqual(ref_e, new_e) && AreFuncNamesEqual(ref_e, new_e); |
| 1092 | } |
| 1093 | if (ref_e != NULL && new_e == NULL) { |
| 1094 | // args_count entities (argument adapters) are not found by heap traversal, |
| 1095 | // but they are not needed because they doesn't contain any code. |
| 1096 | ref_e = strchr(ref_e, ',') + 1; |
| 1097 | const char* args_count = "\"args_count:"; |
| 1098 | return IsStringEqualTo(args_count, ref_e); |
| 1099 | } |
| 1100 | return false; |
| 1101 | } |
| 1102 | |
| 1103 | |
| 1104 | // Test that logging of code create / move / delete events |
| 1105 | // is equivalent to traversal of a resulting heap. |
| 1106 | TEST(EquivalenceOfLoggingAndTraversal) { |
| 1107 | // This test needs to be run on a "clean" V8 to ensure that snapshot log |
| 1108 | // is loaded. This is always true when running using tools/test.py because |
| 1109 | // it launches a new cctest instance for every test. To be sure that launching |
| 1110 | // cctest manually also works, please be sure that no tests below |
| 1111 | // are using V8. |
| 1112 | // |
| 1113 | // P.S. No, V8 can't be re-initialized after disposal, see include/v8.h. |
| 1114 | CHECK(!i::V8::IsRunning()); |
| 1115 | |
| 1116 | i::FLAG_logfile = "*"; |
| 1117 | i::FLAG_log = true; |
| 1118 | i::FLAG_log_code = true; |
| 1119 | |
| 1120 | // Make sure objects move. |
| 1121 | bool saved_always_compact = i::FLAG_always_compact; |
| 1122 | if (!i::FLAG_never_compact) { |
| 1123 | i::FLAG_always_compact = true; |
| 1124 | } |
| 1125 | |
| 1126 | v8::HandleScope scope; |
| 1127 | v8::Handle<v8::Value> global_object = v8::Handle<v8::Value>(); |
| 1128 | v8::Handle<v8::Context> env = v8::Context::New( |
| 1129 | 0, v8::Handle<v8::ObjectTemplate>(), global_object); |
| 1130 | env->Enter(); |
| 1131 | |
| 1132 | // Compile and run a function that creates other functions. |
| 1133 | CompileAndRunScript( |
| 1134 | "(function f(obj) {\n" |
| 1135 | " obj.test =\n" |
| 1136 | " (function a(j) { return function b() { return j; } })(100);\n" |
| 1137 | "})(this);"); |
| 1138 | i::Heap::CollectAllGarbage(false); |
| 1139 | |
| 1140 | EmbeddedVector<char, 204800> buffer; |
| 1141 | int log_size; |
| 1142 | ParseLogResult ref_result; |
| 1143 | |
| 1144 | // Retrieve the log. |
| 1145 | { |
| 1146 | // Make sure that no GCs occur prior to LogCompiledFunctions call. |
| 1147 | i::AssertNoAllocation no_alloc; |
| 1148 | |
| 1149 | log_size = GetLogLines(0, &buffer); |
| 1150 | CHECK_GT(log_size, 0); |
| 1151 | CHECK_GT(buffer.length(), log_size); |
| 1152 | |
| 1153 | // Fill a map of compiled code objects. |
| 1154 | ParseLog(buffer.start(), buffer.start() + log_size, &ref_result); |
| 1155 | } |
| 1156 | |
| 1157 | // Iterate heap to find compiled functions, will write to log. |
| 1158 | i::Logger::LogCompiledFunctions(); |
| 1159 | char* new_log_start = buffer.start() + log_size; |
| 1160 | const int new_log_size = Logger::GetLogLines( |
| 1161 | log_size, new_log_start, buffer.length() - log_size); |
| 1162 | CHECK_GT(new_log_size, 0); |
| 1163 | CHECK_GT(buffer.length(), log_size + new_log_size); |
| 1164 | |
| 1165 | // Fill an equivalent map of compiled code objects. |
| 1166 | ParseLogResult new_result; |
| 1167 | ParseLog(new_log_start, new_log_start + new_log_size, &new_result); |
| 1168 | |
| 1169 | // Test their actual equivalence. |
| 1170 | Interval combined; |
| 1171 | combined.CloneFrom(&ref_result.bounds); |
| 1172 | combined.CloneFrom(&new_result.bounds); |
| 1173 | Interval* iter = &combined; |
| 1174 | bool results_equal = true; |
| 1175 | |
| 1176 | while (iter != NULL) { |
| 1177 | for (Address addr = iter->raw_min_addr(); |
| 1178 | addr <= iter->raw_max_addr(); ++addr) { |
| 1179 | CodeEntityInfo ref_entity = ref_result.GetEntity(addr); |
| 1180 | CodeEntityInfo new_entity = new_result.GetEntity(addr); |
| 1181 | if (ref_entity != NULL || new_entity != NULL) { |
| 1182 | const bool equal = AreEntitiesEqual(ref_entity, new_entity); |
| 1183 | if (!equal) results_equal = false; |
| 1184 | PrintCodeEntitiesInfo(equal, addr, ref_entity, new_entity); |
| 1185 | } |
| 1186 | } |
| 1187 | iter = iter->get_next(); |
| 1188 | } |
| 1189 | // Make sure that all log data is written prior crash due to CHECK failure. |
| 1190 | fflush(stdout); |
| 1191 | CHECK(results_equal); |
| 1192 | |
| 1193 | env->Exit(); |
| 1194 | Logger::TearDown(); |
| 1195 | i::FLAG_always_compact = saved_always_compact; |
| 1196 | } |
| 1197 | |
| 1198 | #endif // ENABLE_LOGGING_AND_PROFILING |