Fix issue 410: test-log/ProfLazyMode flakinness under Linux.

test/cctest/test-log.cc

 // Copyright 2006-2009 the V8 project authors. All rights reserved.
 //
 // Tests of logging functions from log.h
 
 #ifdef ENABLE_LOGGING_AND_PROFILING
 
 #include "v8.h"
 
 #include "log.h"
 #include "cctest.h"
@@ skipping 126 matching lines @@
  public:
   static bool IsSamplerActive() { return Logger::IsProfilerSamplerActive(); }
 };
 
 }  // namespace v8::internal
 }  // namespace v8
 
 using v8::internal::LoggerTestHelper;
 
 
+// Under Linux, we need to check if signals were delivered to avoid false
+// positives.  Under other platforms profiling is done via a high-priority
+// thread, so this case never happen.
+static bool was_sigprof_received = true;

[Søren Thygesen Gjesse, 2009/07/28 08:12:37]

Maybe move this down to 'struct sigaction old_sigprof_handler;'

[Mikhail Naganov, 2009/07/28 08:34:15]

This will add another 'ifdef' branch around lines 226-227. I think having
was_sigprof_received always declared is more straightforward.

+#ifdef __linux__
+
+#include <signal.h>
+#include <unistd.h>
+
+struct sigaction old_sigprof_handler;
+
+static void SigProfSignalHandler(int signal, siginfo_t* info, void* context) {
+  if (signal != SIGPROF) return;
+  was_sigprof_received = true;
+  old_sigprof_handler.sa_sigaction(signal, info, context);
+}
+
+#endif  // __linux__
+
+
 static int CheckThatProfilerWorks(int log_pos) {
   Logger::ResumeProfiler();
   CHECK(LoggerTestHelper::IsSamplerActive());
 
   // Verify that the current map of compiled functions has been logged.
   EmbeddedVector<char, 102400> buffer;
   int map_log_size = GetLogLines(log_pos, &buffer);
   printf("map_log_size: %d\n", map_log_size);
   CHECK_GT(map_log_size, 0);
   CHECK_GT(buffer.length(), map_log_size);
   log_pos += map_log_size;
   // Check buffer contents.
   buffer[map_log_size] = '\0';
   const char* code_creation = "\ncode-creation,";  // eq. to /^code-creation,/
   CHECK_NE(NULL, strstr(buffer.start(), code_creation));
 
+#ifdef __linux__
+  // Intercept SIGPROF handler to make sure that the test process
+  // had received it. Under load, system can defer it causing test failure.
+  // It is important to execute this after 'ResumeProfiler'.
+  was_sigprof_received = false;
+  struct sigaction sa;
+  sa.sa_sigaction = SigProfSignalHandler;
+  sigemptyset(&sa.sa_mask);
+  sa.sa_flags = SA_SIGINFO;
+  CHECK_EQ(0, sigaction(SIGPROF, &sa, &old_sigprof_handler));
+#endif  // __linux__
+
   // Force compiler to generate new code by parametrizing source.
   EmbeddedVector<char, 100> script_src;
   i::OS::SNPrintF(script_src,
                   "for (var i = 0; i < 1000; ++i) { "
                   "(function(x) { return %d * x; })(i); }",
                   log_pos);
   // Run code for 200 msecs to get some ticks.
   const double end_time = i::OS::TimeCurrentMillis() + 200;
   while (i::OS::TimeCurrentMillis() < end_time) {
     CompileAndRunScript(script_src.start());
+    // Yield CPU to give Profiler thread a chance to process ticks.
+    i::OS::Sleep(1);
   }
 
   Logger::PauseProfiler();
   CHECK(!LoggerTestHelper::IsSamplerActive());
 
   // Wait 50 msecs to allow Profiler thread to process the last
   // tick sample it has got.
   i::OS::Sleep(50);
 
   // Now we must have compiler and tick records.
   int log_size = GetLogLines(log_pos, &buffer);
   printf("log_size: %d\n", log_size);
   CHECK_GT(log_size, 0);
   CHECK_GT(buffer.length(), log_size);
   log_pos += log_size;
   // Check buffer contents.
   buffer[log_size] = '\0';
   const char* tick = "\ntick,";
   CHECK_NE(NULL, strstr(buffer.start(), code_creation));
-  CHECK_NE(NULL, strstr(buffer.start(), tick));
+  const bool ticks_found = strstr(buffer.start(), tick) != NULL;
+  CHECK_EQ(was_sigprof_received, ticks_found);
 
   return log_pos;
 }
 
 
 TEST(ProfLazyMode) {
   const bool saved_prof_lazy = i::FLAG_prof_lazy;
   const bool saved_prof = i::FLAG_prof;
   const bool saved_prof_auto = i::FLAG_prof_auto;
   i::FLAG_prof = true;
@@ skipping 500 matching lines @@
   // Make sure that all log data is written prior crash due to CHECK failure.
   fflush(stdout);
   CHECK(results_equal);
 
   env->Exit();
   Logger::TearDown();
   i::FLAG_always_compact = saved_always_compact;
 }
 
 #endif  // ENABLE_LOGGING_AND_PROFILING