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