Home | History | Annotate | Download | only in cctest
      1 // Copyright 2006-2009 the V8 project authors. All rights reserved.
      2 //
      3 // Tests of logging functions from log.h
      4 
      5 #ifdef __linux__
      6 #include <math.h>
      7 #include <pthread.h>
      8 #include <signal.h>
      9 #include <unistd.h>
     10 #endif  // __linux__
     11 
     12 #include "v8.h"
     13 #include "log.h"
     14 #include "cpu-profiler.h"
     15 #include "natives.h"
     16 #include "v8threads.h"
     17 #include "v8utils.h"
     18 #include "cctest.h"
     19 #include "vm-state-inl.h"
     20 
     21 using v8::internal::Address;
     22 using v8::internal::EmbeddedVector;
     23 using v8::internal::Logger;
     24 using v8::internal::StrLength;
     25 
     26 namespace {
     27 
     28 
     29 class ScopedLoggerInitializer {
     30  public:
     31   explicit ScopedLoggerInitializer(bool prof_lazy)
     32       : saved_log_(i::FLAG_log),
     33         saved_prof_lazy_(i::FLAG_prof_lazy),
     34         saved_prof_(i::FLAG_prof),
     35         saved_prof_auto_(i::FLAG_prof_auto),
     36         temp_file_(NULL),
     37         // Need to run this prior to creating the scope.
     38         trick_to_run_init_flags_(init_flags_(prof_lazy)),
     39         scope_(),
     40         env_(v8::Context::New()) {
     41     env_->Enter();
     42   }
     43 
     44   ~ScopedLoggerInitializer() {
     45     env_->Exit();
     46     LOGGER->TearDown();
     47     if (temp_file_ != NULL) fclose(temp_file_);
     48     i::FLAG_prof_lazy = saved_prof_lazy_;
     49     i::FLAG_prof = saved_prof_;
     50     i::FLAG_prof_auto = saved_prof_auto_;
     51     i::FLAG_log = saved_log_;
     52   }
     53 
     54   v8::Handle<v8::Context>& env() { return env_; }
     55 
     56   FILE* StopLoggingGetTempFile() {
     57     temp_file_ = LOGGER->TearDown();
     58     CHECK_NE(NULL, temp_file_);
     59     fflush(temp_file_);
     60     rewind(temp_file_);
     61     return temp_file_;
     62   }
     63 
     64  private:
     65   static bool init_flags_(bool prof_lazy) {
     66     i::FLAG_log = true;
     67     i::FLAG_prof = true;
     68     i::FLAG_prof_lazy = prof_lazy;
     69     i::FLAG_prof_auto = false;
     70     i::FLAG_logfile = i::Log::kLogToTemporaryFile;
     71     return prof_lazy;
     72   }
     73 
     74   const bool saved_log_;
     75   const bool saved_prof_lazy_;
     76   const bool saved_prof_;
     77   const bool saved_prof_auto_;
     78   FILE* temp_file_;
     79   const bool trick_to_run_init_flags_;
     80   v8::HandleScope scope_;
     81   v8::Handle<v8::Context> env_;
     82 
     83   DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer);
     84 };
     85 
     86 }  // namespace
     87 
     88 
     89 static const char* StrNStr(const char* s1, const char* s2, int n) {
     90   if (s1[n] == '\0') return strstr(s1, s2);
     91   i::ScopedVector<char> str(n + 1);
     92   i::OS::StrNCpy(str, s1, static_cast<size_t>(n));
     93   str[n] = '\0';
     94   char* found = strstr(str.start(), s2);
     95   return found != NULL ? s1 + (found - str.start()) : NULL;
     96 }
     97 
     98 
     99 TEST(ProfLazyMode) {
    100   ScopedLoggerInitializer initialize_logger(true);
    101 
    102   if (!i::V8::UseCrankshaft()) return;
    103 
    104   LOGGER->StringEvent("test-start", "");
    105   CompileRun("var a = (function(x) { return x + 1; })(10);");
    106   LOGGER->StringEvent("test-profiler-start", "");
    107   v8::V8::ResumeProfiler();
    108   CompileRun(
    109       "var b = (function(x) { return x + 2; })(10);\n"
    110       "var c = (function(x) { return x + 3; })(10);\n"
    111       "var d = (function(x) { return x + 4; })(10);\n"
    112       "var e = (function(x) { return x + 5; })(10);");
    113   v8::V8::PauseProfiler();
    114   LOGGER->StringEvent("test-profiler-stop", "");
    115   CompileRun("var f = (function(x) { return x + 6; })(10);");
    116   // Check that profiling can be resumed again.
    117   LOGGER->StringEvent("test-profiler-start-2", "");
    118   v8::V8::ResumeProfiler();
    119   CompileRun(
    120       "var g = (function(x) { return x + 7; })(10);\n"
    121       "var h = (function(x) { return x + 8; })(10);\n"
    122       "var i = (function(x) { return x + 9; })(10);\n"
    123       "var j = (function(x) { return x + 10; })(10);");
    124   v8::V8::PauseProfiler();
    125   LOGGER->StringEvent("test-profiler-stop-2", "");
    126   LOGGER->StringEvent("test-stop", "");
    127 
    128   bool exists = false;
    129   i::Vector<const char> log(
    130       i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true));
    131   CHECK(exists);
    132 
    133   const char* test_start_position =
    134       StrNStr(log.start(), "test-start,", log.length());
    135   CHECK_NE(NULL, test_start_position);
    136   const char* test_profiler_start_position =
    137       StrNStr(log.start(), "test-profiler-start,", log.length());
    138   CHECK_NE(NULL, test_profiler_start_position);
    139   CHECK_GT(test_profiler_start_position, test_start_position);
    140   const char* test_profiler_stop_position =
    141       StrNStr(log.start(), "test-profiler-stop,", log.length());
    142   CHECK_NE(NULL, test_profiler_stop_position);
    143   CHECK_GT(test_profiler_stop_position, test_profiler_start_position);
    144   const char* test_profiler_start_2_position =
    145       StrNStr(log.start(), "test-profiler-start-2,", log.length());
    146   CHECK_NE(NULL, test_profiler_start_2_position);
    147   CHECK_GT(test_profiler_start_2_position, test_profiler_stop_position);
    148 
    149   // Nothing must be logged until profiling is resumed.
    150   CHECK_EQ(NULL, StrNStr(test_start_position,
    151                          "code-creation,",
    152                          static_cast<int>(test_profiler_start_position -
    153                                           test_start_position)));
    154   // Nothing must be logged while profiling is suspended.
    155   CHECK_EQ(NULL, StrNStr(test_profiler_stop_position,
    156                          "code-creation,",
    157                          static_cast<int>(test_profiler_start_2_position -
    158                                           test_profiler_stop_position)));
    159 }
    160 
    161 
    162 // BUG(913). Need to implement support for profiling multiple VM threads.
    163 #if 0
    164 
    165 namespace {
    166 
    167 class LoopingThread : public v8::internal::Thread {
    168  public:
    169   explicit LoopingThread(v8::internal::Isolate* isolate)
    170       : v8::internal::Thread(isolate),
    171         semaphore_(v8::internal::OS::CreateSemaphore(0)),
    172         run_(true) {
    173   }
    174 
    175   virtual ~LoopingThread() { delete semaphore_; }
    176 
    177   void Run() {
    178     self_ = pthread_self();
    179     RunLoop();
    180   }
    181 
    182   void SendSigProf() { pthread_kill(self_, SIGPROF); }
    183 
    184   void Stop() { run_ = false; }
    185 
    186   bool WaitForRunning() { return semaphore_->Wait(1000000); }
    187 
    188  protected:
    189   bool IsRunning() { return run_; }
    190 
    191   virtual void RunLoop() = 0;
    192 
    193   void SetV8ThreadId() {
    194     v8_thread_id_ = v8::V8::GetCurrentThreadId();
    195   }
    196 
    197   void SignalRunning() { semaphore_->Signal(); }
    198 
    199  private:
    200   v8::internal::Semaphore* semaphore_;
    201   bool run_;
    202   pthread_t self_;
    203   int v8_thread_id_;
    204 };
    205 
    206 
    207 class LoopingJsThread : public LoopingThread {
    208  public:
    209   explicit LoopingJsThread(v8::internal::Isolate* isolate)
    210       : LoopingThread(isolate) { }
    211   void RunLoop() {
    212     v8::Locker locker;
    213     CHECK(i::Isolate::Current() != NULL);
    214     CHECK_GT(i::Isolate::Current()->thread_manager()->CurrentId(), 0);
    215     SetV8ThreadId();
    216     while (IsRunning()) {
    217       v8::HandleScope scope;
    218       v8::Persistent<v8::Context> context = v8::Context::New();
    219       CHECK(!context.IsEmpty());
    220       {
    221         v8::Context::Scope context_scope(context);
    222         SignalRunning();
    223         CompileRun(
    224             "var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }");
    225       }
    226       context.Dispose();
    227       i::OS::Sleep(1);
    228     }
    229   }
    230 };
    231 
    232 
    233 class LoopingNonJsThread : public LoopingThread {
    234  public:
    235   explicit LoopingNonJsThread(v8::internal::Isolate* isolate)
    236       : LoopingThread(isolate) { }
    237   void RunLoop() {
    238     v8::Locker locker;
    239     v8::Unlocker unlocker;
    240     // Now thread has V8's id, but will not run VM code.
    241     CHECK(i::Isolate::Current() != NULL);
    242     CHECK_GT(i::Isolate::Current()->thread_manager()->CurrentId(), 0);
    243     double i = 10;
    244     SignalRunning();
    245     while (IsRunning()) {
    246       i = sin(i);
    247       i::OS::Sleep(1);
    248     }
    249   }
    250 };
    251 
    252 
    253 class TestSampler : public v8::internal::Sampler {
    254  public:
    255   explicit TestSampler(v8::internal::Isolate* isolate)
    256       : Sampler(isolate, 0, true, true),
    257         semaphore_(v8::internal::OS::CreateSemaphore(0)),
    258         was_sample_stack_called_(false) {
    259   }
    260 
    261   ~TestSampler() { delete semaphore_; }
    262 
    263   void SampleStack(v8::internal::TickSample*) {
    264     was_sample_stack_called_ = true;
    265   }
    266 
    267   void Tick(v8::internal::TickSample*) { semaphore_->Signal(); }
    268 
    269   bool WaitForTick() { return semaphore_->Wait(1000000); }
    270 
    271   void Reset() { was_sample_stack_called_ = false; }
    272 
    273   bool WasSampleStackCalled() { return was_sample_stack_called_; }
    274 
    275  private:
    276   v8::internal::Semaphore* semaphore_;
    277   bool was_sample_stack_called_;
    278 };
    279 
    280 
    281 }  // namespace
    282 
    283 TEST(ProfMultipleThreads) {
    284   TestSampler* sampler = NULL;
    285   {
    286     v8::Locker locker;
    287     sampler = new TestSampler(v8::internal::Isolate::Current());
    288     sampler->Start();
    289     CHECK(sampler->IsActive());
    290   }
    291 
    292   LoopingJsThread jsThread(v8::internal::Isolate::Current());
    293   jsThread.Start();
    294   LoopingNonJsThread nonJsThread(v8::internal::Isolate::Current());
    295   nonJsThread.Start();
    296 
    297   CHECK(!sampler->WasSampleStackCalled());
    298   jsThread.WaitForRunning();
    299   jsThread.SendSigProf();
    300   CHECK(sampler->WaitForTick());
    301   CHECK(sampler->WasSampleStackCalled());
    302   sampler->Reset();
    303   CHECK(!sampler->WasSampleStackCalled());
    304   nonJsThread.WaitForRunning();
    305   nonJsThread.SendSigProf();
    306   CHECK(!sampler->WaitForTick());
    307   CHECK(!sampler->WasSampleStackCalled());
    308   sampler->Stop();
    309 
    310   jsThread.Stop();
    311   nonJsThread.Stop();
    312   jsThread.Join();
    313   nonJsThread.Join();
    314 
    315   delete sampler;
    316 }
    317 
    318 #endif  // __linux__
    319 
    320 
    321 // Test for issue http://crbug.com/23768 in Chromium.
    322 // Heap can contain scripts with already disposed external sources.
    323 // We need to verify that LogCompiledFunctions doesn't crash on them.
    324 namespace {
    325 
    326 class SimpleExternalString : public v8::String::ExternalStringResource {
    327  public:
    328   explicit SimpleExternalString(const char* source)
    329       : utf_source_(StrLength(source)) {
    330     for (int i = 0; i < utf_source_.length(); ++i)
    331       utf_source_[i] = source[i];
    332   }
    333   virtual ~SimpleExternalString() {}
    334   virtual size_t length() const { return utf_source_.length(); }
    335   virtual const uint16_t* data() const { return utf_source_.start(); }
    336  private:
    337   i::ScopedVector<uint16_t> utf_source_;
    338 };
    339 
    340 }  // namespace
    341 
    342 TEST(Issue23768) {
    343   v8::HandleScope scope;
    344   v8::Handle<v8::Context> env = v8::Context::New();
    345   env->Enter();
    346 
    347   SimpleExternalString source_ext_str("(function ext() {})();");
    348   v8::Local<v8::String> source = v8::String::NewExternal(&source_ext_str);
    349   // Script needs to have a name in order to trigger InitLineEnds execution.
    350   v8::Handle<v8::String> origin = v8::String::New("issue-23768-test");
    351   v8::Handle<v8::Script> evil_script = v8::Script::Compile(source, origin);
    352   CHECK(!evil_script.IsEmpty());
    353   CHECK(!evil_script->Run().IsEmpty());
    354   i::Handle<i::ExternalTwoByteString> i_source(
    355       i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source)));
    356   // This situation can happen if source was an external string disposed
    357   // by its owner.
    358   i_source->set_resource(NULL);
    359 
    360   // Must not crash.
    361   LOGGER->LogCompiledFunctions();
    362 }
    363 
    364 
    365 static v8::Handle<v8::Value> ObjMethod1(const v8::Arguments& args) {
    366   return v8::Handle<v8::Value>();
    367 }
    368 
    369 TEST(LogCallbacks) {
    370   ScopedLoggerInitializer initialize_logger(false);
    371 
    372   v8::Persistent<v8::FunctionTemplate> obj =
    373       v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New());
    374   obj->SetClassName(v8_str("Obj"));
    375   v8::Handle<v8::ObjectTemplate> proto = obj->PrototypeTemplate();
    376   v8::Local<v8::Signature> signature = v8::Signature::New(obj);
    377   proto->Set(v8_str("method1"),
    378              v8::FunctionTemplate::New(ObjMethod1,
    379                                        v8::Handle<v8::Value>(),
    380                                        signature),
    381              static_cast<v8::PropertyAttribute>(v8::DontDelete));
    382 
    383   initialize_logger.env()->Global()->Set(v8_str("Obj"), obj->GetFunction());
    384   CompileRun("Obj.prototype.method1.toString();");
    385 
    386   LOGGER->LogCompiledFunctions();
    387 
    388   bool exists = false;
    389   i::Vector<const char> log(
    390       i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true));
    391   CHECK(exists);
    392 
    393   i::EmbeddedVector<char, 100> ref_data;
    394   i::OS::SNPrintF(ref_data,
    395                   "code-creation,Callback,0x%" V8PRIxPTR ",1,\"method1\"\0",
    396                   ObjMethod1);
    397 
    398   CHECK_NE(NULL, StrNStr(log.start(), ref_data.start(), log.length()));
    399 
    400   obj.Dispose();
    401 }
    402 
    403 
    404 static v8::Handle<v8::Value> Prop1Getter(v8::Local<v8::String> property,
    405                                          const v8::AccessorInfo& info) {
    406   return v8::Handle<v8::Value>();
    407 }
    408 
    409 static void Prop1Setter(v8::Local<v8::String> property,
    410                                          v8::Local<v8::Value> value,
    411                                          const v8::AccessorInfo& info) {
    412 }
    413 
    414 static v8::Handle<v8::Value> Prop2Getter(v8::Local<v8::String> property,
    415                                          const v8::AccessorInfo& info) {
    416   return v8::Handle<v8::Value>();
    417 }
    418 
    419 TEST(LogAccessorCallbacks) {
    420   ScopedLoggerInitializer initialize_logger(false);
    421 
    422   v8::Persistent<v8::FunctionTemplate> obj =
    423       v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New());
    424   obj->SetClassName(v8_str("Obj"));
    425   v8::Handle<v8::ObjectTemplate> inst = obj->InstanceTemplate();
    426   inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter);
    427   inst->SetAccessor(v8_str("prop2"), Prop2Getter);
    428 
    429   LOGGER->LogAccessorCallbacks();
    430 
    431   bool exists = false;
    432   i::Vector<const char> log(
    433       i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true));
    434   CHECK(exists);
    435 
    436   EmbeddedVector<char, 100> prop1_getter_record;
    437   i::OS::SNPrintF(prop1_getter_record,
    438                   "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop1\"",
    439                   Prop1Getter);
    440   CHECK_NE(NULL,
    441            StrNStr(log.start(), prop1_getter_record.start(), log.length()));
    442 
    443   EmbeddedVector<char, 100> prop1_setter_record;
    444   i::OS::SNPrintF(prop1_setter_record,
    445                   "code-creation,Callback,0x%" V8PRIxPTR ",1,\"set prop1\"",
    446                   Prop1Setter);
    447   CHECK_NE(NULL,
    448            StrNStr(log.start(), prop1_setter_record.start(), log.length()));
    449 
    450   EmbeddedVector<char, 100> prop2_getter_record;
    451   i::OS::SNPrintF(prop2_getter_record,
    452                   "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop2\"",
    453                   Prop2Getter);
    454   CHECK_NE(NULL,
    455            StrNStr(log.start(), prop2_getter_record.start(), log.length()));
    456 
    457   obj.Dispose();
    458 }
    459 
    460 
    461 TEST(IsLoggingPreserved) {
    462   ScopedLoggerInitializer initialize_logger(false);
    463 
    464   CHECK(LOGGER->is_logging());
    465   LOGGER->ResumeProfiler();
    466   CHECK(LOGGER->is_logging());
    467   LOGGER->PauseProfiler();
    468   CHECK(LOGGER->is_logging());
    469 }
    470 
    471 
    472 typedef i::NativesCollection<i::TEST> TestSources;
    473 
    474 
    475 // Test that logging of code create / move events is equivalent to traversal of
    476 // a resulting heap.
    477 TEST(EquivalenceOfLoggingAndTraversal) {
    478   // This test needs to be run on a "clean" V8 to ensure that snapshot log
    479   // is loaded. This is always true when running using tools/test.py because
    480   // it launches a new cctest instance for every test. To be sure that launching
    481   // cctest manually also works, please be sure that no tests below
    482   // are using V8.
    483   //
    484   // P.S. No, V8 can't be re-initialized after disposal, see include/v8.h.
    485   CHECK(!i::V8::IsRunning());
    486 
    487   // Start with profiling to capture all code events from the beginning.
    488   ScopedLoggerInitializer initialize_logger(false);
    489 
    490   // Compile and run a function that creates other functions.
    491   CompileRun(
    492       "(function f(obj) {\n"
    493       "  obj.test =\n"
    494       "    (function a(j) { return function b() { return j; } })(100);\n"
    495       "})(this);");
    496   v8::V8::PauseProfiler();
    497   HEAP->CollectAllGarbage(i::Heap::kMakeHeapIterableMask);
    498   LOGGER->StringEvent("test-logging-done", "");
    499 
    500   // Iterate heap to find compiled functions, will write to log.
    501   LOGGER->LogCompiledFunctions();
    502   LOGGER->StringEvent("test-traversal-done", "");
    503 
    504   bool exists = false;
    505   i::Vector<const char> log(
    506       i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true));
    507   CHECK(exists);
    508   v8::Handle<v8::String> log_str = v8::String::New(log.start(), log.length());
    509   initialize_logger.env()->Global()->Set(v8_str("_log"), log_str);
    510 
    511   i::Vector<const unsigned char> source = TestSources::GetScriptsSource();
    512   v8::Handle<v8::String> source_str = v8::String::New(
    513       reinterpret_cast<const char*>(source.start()), source.length());
    514   v8::TryCatch try_catch;
    515   v8::Handle<v8::Script> script = v8::Script::Compile(source_str, v8_str(""));
    516   if (script.IsEmpty()) {
    517     v8::String::Utf8Value exception(try_catch.Exception());
    518     printf("compile: %s\n", *exception);
    519     CHECK(false);
    520   }
    521   v8::Handle<v8::Value> result = script->Run();
    522   if (result.IsEmpty()) {
    523     v8::String::Utf8Value exception(try_catch.Exception());
    524     printf("run: %s\n", *exception);
    525     CHECK(false);
    526   }
    527   // The result either be a "true" literal or problem description.
    528   if (!result->IsTrue()) {
    529     v8::Local<v8::String> s = result->ToString();
    530     i::ScopedVector<char> data(s->Length() + 1);
    531     CHECK_NE(NULL, data.start());
    532     s->WriteAscii(data.start());
    533     printf("%s\n", data.start());
    534     // Make sure that our output is written prior crash due to CHECK failure.
    535     fflush(stdout);
    536     CHECK(false);
    537   }
    538 }
    539