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