src/v8/test/cctest/test-log.cc

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