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 "v8threads.h"
  43 #include "v8utils.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 = 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 = v8::String::NewExternal(&source_ext_str);
 309   // Script needs to have a name in order to trigger InitLineEnds execution.
 310   v8::Handle<v8::String> origin = v8::String::New("issue-23768-test");
 311   v8::Handle<v8::Script> evil_script = v8::Script::Compile(source, origin);
 312   CHECK(!evil_script.IsEmpty());
 313   CHECK(!evil_script->Run().IsEmpty());
 314   i::Handle<i::ExternalTwoByteString> i_source(
 315       i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source)));
 316   // This situation can happen if source was an external string disposed
 317   // by its owner.
 318   i_source->set_resource(NULL);
 319
 320   // Must not crash.
 321   CcTest::i_isolate()->logger()->LogCompiledFunctions();
 322 }
 323
 324
 325 static void ObjMethod1(const v8::FunctionCallbackInfo<v8::Value>& args) {
 326 }
 327
 328
 329 TEST(LogCallbacks) {
 330   ScopedLoggerInitializer initialize_logger;
 331   Logger* logger = initialize_logger.logger();
 332
 333   v8::Local<v8::FunctionTemplate> obj =
 334       v8::Local<v8::FunctionTemplate>::New(CcTest::isolate(),
 335                                            v8::FunctionTemplate::New());
 336   obj->SetClassName(v8_str("Obj"));
 337   v8::Handle<v8::ObjectTemplate> proto = obj->PrototypeTemplate();
 338   v8::Local<v8::Signature> signature = v8::Signature::New(obj);
 339   proto->Set(v8_str("method1"),
 340              v8::FunctionTemplate::New(ObjMethod1,
 341                                        v8::Handle<v8::Value>(),
 342                                        signature),
 343              static_cast<v8::PropertyAttribute>(v8::DontDelete));
 344
 345   initialize_logger.env()->Global()->Set(v8_str("Obj"), obj->GetFunction());
 346   CompileRun("Obj.prototype.method1.toString();");
 347
 348   logger->LogCompiledFunctions();
 349
 350   bool exists = false;
 351   i::Vector<const char> log(
 352       i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true));
 353   CHECK(exists);
 354
 355   i::EmbeddedVector<char, 100> ref_data;
 356   i::OS::SNPrintF(ref_data,
 357                   "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"method1\"\0",
 358                   ObjMethod1);
 359
 360   CHECK_NE(NULL, StrNStr(log.start(), ref_data.start(), log.length()));
 361 }
 362
 363
 364 static void Prop1Getter(v8::Local<v8::String> property,
 365                         const v8::PropertyCallbackInfo<v8::Value>& info) {
 366 }
 367
 368 static void Prop1Setter(v8::Local<v8::String> property,
 369                         v8::Local<v8::Value> value,
 370                         const v8::PropertyCallbackInfo<void>& info) {
 371 }
 372
 373 static void Prop2Getter(v8::Local<v8::String> property,
 374                         const v8::PropertyCallbackInfo<v8::Value>& info) {
 375 }
 376
 377
 378 TEST(LogAccessorCallbacks) {
 379   ScopedLoggerInitializer initialize_logger;
 380   Logger* logger = initialize_logger.logger();
 381
 382   v8::Local<v8::FunctionTemplate> obj =
 383       v8::Local<v8::FunctionTemplate>::New(CcTest::isolate(),
 384                                            v8::FunctionTemplate::New());
 385   obj->SetClassName(v8_str("Obj"));
 386   v8::Handle<v8::ObjectTemplate> inst = obj->InstanceTemplate();
 387   inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter);
 388   inst->SetAccessor(v8_str("prop2"), Prop2Getter);
 389
 390   logger->LogAccessorCallbacks();
 391
 392   bool exists = false;
 393   i::Vector<const char> log(
 394       i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true));
 395   CHECK(exists);
 396
 397   EmbeddedVector<char, 100> prop1_getter_record;
 398   i::OS::SNPrintF(prop1_getter_record,
 399                   "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"get prop1\"",
 400                   Prop1Getter);
 401   CHECK_NE(NULL,
 402            StrNStr(log.start(), prop1_getter_record.start(), log.length()));
 403
 404   EmbeddedVector<char, 100> prop1_setter_record;
 405   i::OS::SNPrintF(prop1_setter_record,
 406                   "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"set prop1\"",
 407                   Prop1Setter);
 408   CHECK_NE(NULL,
 409            StrNStr(log.start(), prop1_setter_record.start(), log.length()));
 410
 411   EmbeddedVector<char, 100> prop2_getter_record;
 412   i::OS::SNPrintF(prop2_getter_record,
 413                   "code-creation,Callback,-2,0x%" V8PRIxPTR ",1,\"get prop2\"",
 414                   Prop2Getter);
 415   CHECK_NE(NULL,
 416            StrNStr(log.start(), prop2_getter_record.start(), log.length()));
 417 }
 418
 419
 420 typedef i::NativesCollection<i::TEST> TestSources;
 421
 422
 423 // Test that logging of code create / move events is equivalent to traversal of
 424 // a resulting heap.
 425 TEST(EquivalenceOfLoggingAndTraversal) {
 426   // This test needs to be run on a "clean" V8 to ensure that snapshot log
 427   // is loaded. This is always true when running using tools/test.py because
 428   // it launches a new cctest instance for every test. To be sure that launching
 429   // cctest manually also works, please be sure that no tests below
 430   // are using V8.
 431
 432   // Start with profiling to capture all code events from the beginning.
 433   ScopedLoggerInitializer initialize_logger;
 434   Logger* logger = initialize_logger.logger();
 435
 436   // Compile and run a function that creates other functions.
 437   CompileRun(
 438       "(function f(obj) {\n"
 439       "  obj.test =\n"
 440       "    (function a(j) { return function b() { return j; } })(100);\n"
 441       "})(this);");
 442   logger->StopProfiler();
 443   CcTest::heap()->CollectAllGarbage(i::Heap::kMakeHeapIterableMask);
 444   logger->StringEvent("test-logging-done", "");
 445
 446   // Iterate heap to find compiled functions, will write to log.
 447   logger->LogCompiledFunctions();
 448   logger->StringEvent("test-traversal-done", "");
 449
 450   bool exists = false;
 451   i::Vector<const char> log(
 452       i::ReadFile(initialize_logger.StopLoggingGetTempFile(), &exists, true));
 453   CHECK(exists);
 454   v8::Handle<v8::String> log_str = v8::String::New(log.start(), log.length());
 455   initialize_logger.env()->Global()->Set(v8_str("_log"), log_str);
 456
 457   i::Vector<const unsigned char> source = TestSources::GetScriptsSource();
 458   v8::Handle<v8::String> source_str = v8::String::New(
 459       reinterpret_cast<const char*>(source.start()), source.length());
 460   v8::TryCatch try_catch;
 461   v8::Handle<v8::Script> script = v8::Script::Compile(source_str, v8_str(""));
 462   if (script.IsEmpty()) {
 463     v8::String::Utf8Value exception(try_catch.Exception());
 464     printf("compile: %s\n", *exception);
 465     CHECK(false);
 466   }
 467   v8::Handle<v8::Value> result = script->Run();
 468   if (result.IsEmpty()) {
 469     v8::String::Utf8Value exception(try_catch.Exception());
 470     printf("run: %s\n", *exception);
 471     CHECK(false);
 472   }
 473   // The result either be a "true" literal or problem description.
 474   if (!result->IsTrue()) {
 475     v8::Local<v8::String> s = result->ToString();
 476     i::ScopedVector<char> data(s->Utf8Length() + 1);
 477     CHECK_NE(NULL, data.start());
 478     s->WriteUtf8(data.start());
 479     printf("%s\n", data.start());
 480     // Make sure that our output is written prior crash due to CHECK failure.
 481     fflush(stdout);
 482     CHECK(false);
 483   }
 484 }