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