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-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 }