test-log.cc 33.3 KB
Newer Older
1
// Copyright 2006-2009 the V8 project authors. All rights reserved.
2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26
// Redistribution and use in source and binary forms, with or without
// modification, are permitted provided that the following conditions are
// met:
//
//     * Redistributions of source code must retain the above copyright
//       notice, this list of conditions and the following disclaimer.
//     * Redistributions in binary form must reproduce the above
//       copyright notice, this list of conditions and the following
//       disclaimer in the documentation and/or other materials provided
//       with the distribution.
//     * Neither the name of Google Inc. nor the names of its
//       contributors may be used to endorse or promote products derived
//       from this software without specific prior written permission.
//
// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
27 28 29
//
// Tests of logging functions from log.h

30
#ifdef __linux__
31
#include <pthread.h>
32 33
#include <signal.h>
#include <unistd.h>
34
#include <cmath>
35
#endif  // __linux__
36

37
#include <unordered_set>
38
#include "src/api.h"
39
#include "src/log-utils.h"
40
#include "src/log.h"
41
#include "src/objects-inl.h"
42
#include "src/profiler/cpu-profiler.h"
43
#include "src/snapshot/natives.h"
44
#include "src/utils.h"
45
#include "src/v8.h"
46
#include "src/v8threads.h"
47
#include "src/version.h"
48 49
#include "src/vm-state-inl.h"
#include "test/cctest/cctest.h"
50

51
using v8::internal::Address;
52
using v8::internal::EmbeddedVector;
53
using v8::internal::Logger;
54
using v8::internal::StrLength;
55

56 57
namespace {

58

59 60 61 62 63 64 65 66
#define SETUP_FLAGS()                            \
  bool saved_log = i::FLAG_log;                  \
  bool saved_prof = i::FLAG_prof;                \
  i::FLAG_log = true;                            \
  i::FLAG_prof = true;                           \
  i::FLAG_logfile = i::Log::kLogToTemporaryFile; \
  i::FLAG_logfile_per_isolate = false

67 68 69 70 71
static const char* StrNStr(const char* s1, const char* s2, size_t n) {
  CHECK_EQ(s1[n], '\0');
  return strstr(s1, s2);
}

72
// Look for a log line which starts with {prefix} and ends with {suffix}.
73 74
static const char* FindLogLine(const char* start, const char* end,
                               const char* prefix,
75
                               const char* suffix = nullptr) {
76
  CHECK_LT(start, end);
77 78 79 80
  CHECK_EQ(end[0], '\0');
  size_t prefixLength = strlen(prefix);
  // Loop through the input until we find /{prefix}[^\n]+{suffix}/.
  while (start < end) {
81
    const char* prefixResult = strstr(start, prefix);
82
    if (!prefixResult) return NULL;
83
    if (suffix == nullptr) return prefixResult;
84 85 86 87 88 89 90 91 92 93 94 95 96
    const char* suffixResult =
        StrNStr(prefixResult, suffix, (end - prefixResult));
    if (!suffixResult) return NULL;
    // Check that there are no newlines in between the {prefix} and the {suffix}
    // results.
    const char* newlineResult =
        StrNStr(prefixResult, "\n", (end - prefixResult));
    if (!newlineResult) return prefixResult;
    if (newlineResult > suffixResult) return prefixResult;
    start = prefixResult + prefixLength;
  }
  return NULL;
}
97

98 99
class ScopedLoggerInitializer {
 public:
100 101 102
  ScopedLoggerInitializer(bool saved_log, bool saved_prof, v8::Isolate* isolate)
      : saved_log_(saved_log),
        saved_prof_(saved_prof),
103
        temp_file_(nullptr),
104 105 106 107 108
        isolate_(isolate),
        isolate_scope_(isolate),
        scope_(isolate),
        env_(v8::Context::New(isolate)),
        logger_(reinterpret_cast<i::Isolate*>(isolate)->logger()) {
109 110 111 112 113
    env_->Enter();
  }

  ~ScopedLoggerInitializer() {
    env_->Exit();
yurys@chromium.org's avatar
yurys@chromium.org committed
114
    logger_->TearDown();
115
    if (temp_file_ != nullptr) fclose(temp_file_);
116
    i::FLAG_prof = saved_prof_;
117
    i::FLAG_log = saved_log_;
118
    log_.Dispose();
119 120
  }

121
  v8::Local<v8::Context>& env() { return env_; }
122

123 124
  v8::Isolate* isolate() { return isolate_; }

yurys@chromium.org's avatar
yurys@chromium.org committed
125 126
  Logger* logger() { return logger_; }

127 128 129 130 131 132 133 134 135 136 137 138 139 140 141
  void PrintLog(int nofLines = 0) {
    if (nofLines <= 0) {
      printf("%s", log_.start());
      return;
    }
    // Try to print the last {nofLines} of the log.
    const char* start = log_.start();
    const char* current = log_.end();
    while (current > start && nofLines > 0) {
      current--;
      if (*current == '\n') nofLines--;
    }
    printf(
        "======================================================\n"
        "Last log lines:\n...%s\n"
142
        "======================================================\n",
143 144
        current);
  }
145

146 147 148 149 150 151 152 153 154 155 156 157
  v8::Local<v8::String> GetLogString() {
    return v8::String::NewFromUtf8(isolate_, log_.start(),
                                   v8::NewStringType::kNormal, log_.length())
        .ToLocalChecked();
  }

  void StopLogging() {
    bool exists = false;
    log_ = i::ReadFile(StopLoggingGetTempFile(), &exists, true);
    CHECK(exists);
  }

158 159
  const char* FindLine(const char* prefix, const char* suffix = nullptr,
                       const char* start = nullptr) {
160 161
    // Make sure that StopLogging() has been called before.
    CHECK(log_.size());
162 163 164
    if (start == nullptr) start = log_.start();
    const char* end = log_.start() + log_.length();
    return FindLogLine(start, end, prefix, suffix);
165 166
  }

167 168
  // Find all log lines specified by the {prefix, suffix} pairs and ensure they
  // occurr in the specified order.
169 170 171 172 173 174 175 176 177 178
  void FindLogLines(const char* pairs[][2], size_t limit,
                    const char* start = nullptr) {
    const char* prefix = pairs[0][0];
    const char* suffix = pairs[0][1];
    const char* last_position = FindLine(prefix, suffix, start);
    if (last_position == nullptr) {
      PrintLog(50);
      V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s", prefix,
               suffix);
    }
179 180
    CHECK(last_position);
    for (size_t i = 1; i < limit; i++) {
181 182 183 184 185 186 187 188
      prefix = pairs[i][0];
      suffix = pairs[i][1];
      const char* position = FindLine(prefix, suffix, start);
      if (position == nullptr) {
        PrintLog(50);
        V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s",
                 prefix, suffix);
      }
189
      // Check that all string positions are in order.
190 191 192 193 194 195 196 197
      if (position <= last_position) {
        PrintLog(50);
        V8_Fatal(__FILE__, __LINE__,
                 "Log statements not in expected order (prev=%p, current=%p): "
                 "%s ... %s",
                 reinterpret_cast<const void*>(last_position),
                 reinterpret_cast<const void*>(position), prefix, suffix);
      }
198 199 200 201
      last_position = position;
    }
  }

202 203 204 205 206 207
  void LogCompiledFunctions() { logger_->LogCompiledFunctions(); }

  void StringEvent(const char* name, const char* value) {
    logger_->StringEvent(name, value);
  }

208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231
  void ExtractAllAddresses(std::unordered_set<uintptr_t>* map,
                           const char* prefix, int field_index) {
    // Make sure that StopLogging() has been called before.
    CHECK(log_.size());
    const char* current = log_.start();
    while (current != nullptr) {
      current = FindLine(prefix, nullptr, current);
      if (current == nullptr) return;
      // Find token number {index}.
      const char* previous;
      for (int i = 0; i <= field_index; i++) {
        previous = current;
        current = strchr(current + 1, ',');
        if (current == nullptr) break;
        // Skip the comma.
        current++;
      }
      if (current == nullptr) break;
      uintptr_t address = strtoll(previous, nullptr, 16);
      CHECK_LT(0, address);
      map->insert(address);
    }
  }

232
 private:
233
  FILE* StopLoggingGetTempFile() {
yurys@chromium.org's avatar
yurys@chromium.org committed
234
    temp_file_ = logger_->TearDown();
235
    CHECK(temp_file_);
236 237 238 239 240 241
    fflush(temp_file_);
    rewind(temp_file_);
    return temp_file_;
  }

  const bool saved_log_;
242
  const bool saved_prof_;
243
  FILE* temp_file_;
244 245
  v8::Isolate* isolate_;
  v8::Isolate::Scope isolate_scope_;
246
  v8::HandleScope scope_;
247
  v8::Local<v8::Context> env_;
yurys@chromium.org's avatar
yurys@chromium.org committed
248
  Logger* logger_;
249
  i::Vector<const char> log_;
250 251 252 253 254 255

  DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer);
};

}  // namespace

256 257 258 259 260 261
TEST(FindLogLine) {
  const char* string =
      "prefix1, stuff,   suffix1\n"
      "prefix2, stuff\n, suffix2\n"
      "prefix3suffix3\n"
      "prefix4 suffix4";
262
  const char* end = string + strlen(string);
263
  // Make sure the vector contains the terminating \0 character.
264 265 266 267 268 269 270 271 272 273 274 275 276 277
  CHECK(FindLogLine(string, end, "prefix1, stuff,   suffix1"));
  CHECK(FindLogLine(string, end, "prefix1, stuff"));
  CHECK(FindLogLine(string, end, "prefix1"));
  CHECK(FindLogLine(string, end, "prefix1", "suffix1"));
  CHECK(FindLogLine(string, end, "prefix1", "suffix1"));
  CHECK(!FindLogLine(string, end, "prefix2", "suffix2"));
  CHECK(!FindLogLine(string, end, "prefix1", "suffix2"));
  CHECK(!FindLogLine(string, end, "prefix1", "suffix3"));
  CHECK(FindLogLine(string, end, "prefix3", "suffix3"));
  CHECK(FindLogLine(string, end, "prefix4", "suffix4"));
  CHECK(!FindLogLine(string, end, "prefix4", "suffix4XXXXXXXXXXXX"));
  CHECK(
      !FindLogLine(string, end, "prefix4XXXXXXXXXXXXXXXXXXXXXXxxx", "suffix4"));
  CHECK(!FindLogLine(string, end, "suffix", "suffix5XXXXXXXXXXXXXXXXXXXX"));
278 279
}

280 281
// BUG(913). Need to implement support for profiling multiple VM threads.
#if 0
282 283 284 285 286

namespace {

class LoopingThread : public v8::internal::Thread {
 public:
287 288
  explicit LoopingThread(v8::internal::Isolate* isolate)
      : v8::internal::Thread(isolate),
289
        semaphore_(new v8::internal::Semaphore(0)),
290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326
        run_(true) {
  }

  virtual ~LoopingThread() { delete semaphore_; }

  void Run() {
    self_ = pthread_self();
    RunLoop();
  }

  void SendSigProf() { pthread_kill(self_, SIGPROF); }

  void Stop() { run_ = false; }

  bool WaitForRunning() { return semaphore_->Wait(1000000); }

 protected:
  bool IsRunning() { return run_; }

  virtual void RunLoop() = 0;

  void SetV8ThreadId() {
    v8_thread_id_ = v8::V8::GetCurrentThreadId();
  }

  void SignalRunning() { semaphore_->Signal(); }

 private:
  v8::internal::Semaphore* semaphore_;
  bool run_;
  pthread_t self_;
  int v8_thread_id_;
};


class LoopingJsThread : public LoopingThread {
 public:
327 328
  explicit LoopingJsThread(v8::internal::Isolate* isolate)
      : LoopingThread(isolate) { }
329
  void RunLoop() {
330
    v8::Locker locker;
331
    CHECK_NOT_NULL(CcTest::i_isolate());
332
    CHECK_GT(CcTest::i_isolate()->thread_manager()->CurrentId(), 0);
333
    SetV8ThreadId();
334 335 336
    while (IsRunning()) {
      v8::HandleScope scope;
      v8::Persistent<v8::Context> context = v8::Context::New();
337 338 339 340
      CHECK(!context.IsEmpty());
      {
        v8::Context::Scope context_scope(context);
        SignalRunning();
341
        CompileRun(
342 343
            "var j; for (var i=0; i<10000; ++i) { j = Math.sin(i); }");
      }
344
      context.Dispose();
345
      i::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(1));
346 347 348 349 350 351 352
    }
  }
};


class LoopingNonJsThread : public LoopingThread {
 public:
353 354
  explicit LoopingNonJsThread(v8::internal::Isolate* isolate)
      : LoopingThread(isolate) { }
355 356 357 358
  void RunLoop() {
    v8::Locker locker;
    v8::Unlocker unlocker;
    // Now thread has V8's id, but will not run VM code.
359
    CHECK_NOT_NULL(CcTest::i_isolate());
360
    CHECK_GT(CcTest::i_isolate()->thread_manager()->CurrentId(), 0);
361 362 363
    double i = 10;
    SignalRunning();
    while (IsRunning()) {
364
      i = std::sin(i);
365
      i::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(1));
366 367 368 369 370 371 372
    }
  }
};


class TestSampler : public v8::internal::Sampler {
 public:
373 374
  explicit TestSampler(v8::internal::Isolate* isolate)
      : Sampler(isolate, 0, true, true),
375
        semaphore_(new v8::internal::Semaphore(0)),
376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401
        was_sample_stack_called_(false) {
  }

  ~TestSampler() { delete semaphore_; }

  void SampleStack(v8::internal::TickSample*) {
    was_sample_stack_called_ = true;
  }

  void Tick(v8::internal::TickSample*) { semaphore_->Signal(); }

  bool WaitForTick() { return semaphore_->Wait(1000000); }

  void Reset() { was_sample_stack_called_ = false; }

  bool WasSampleStackCalled() { return was_sample_stack_called_; }

 private:
  v8::internal::Semaphore* semaphore_;
  bool was_sample_stack_called_;
};


}  // namespace

TEST(ProfMultipleThreads) {
402
  TestSampler* sampler = nullptr;
403 404
  {
    v8::Locker locker;
405
    sampler = new TestSampler(CcTest::i_isolate());
406 407 408 409
    sampler->Start();
    CHECK(sampler->IsActive());
  }

410
  LoopingJsThread jsThread(CcTest::i_isolate());
411
  jsThread.Start();
412
  LoopingNonJsThread nonJsThread(CcTest::i_isolate());
413 414
  nonJsThread.Start();

415
  CHECK(!sampler->WasSampleStackCalled());
416 417
  jsThread.WaitForRunning();
  jsThread.SendSigProf();
418 419 420 421
  CHECK(sampler->WaitForTick());
  CHECK(sampler->WasSampleStackCalled());
  sampler->Reset();
  CHECK(!sampler->WasSampleStackCalled());
422 423
  nonJsThread.WaitForRunning();
  nonJsThread.SendSigProf();
424 425 426
  CHECK(!sampler->WaitForTick());
  CHECK(!sampler->WasSampleStackCalled());
  sampler->Stop();
427 428 429 430 431

  jsThread.Stop();
  nonJsThread.Stop();
  jsThread.Join();
  nonJsThread.Join();
432 433

  delete sampler;
434 435 436 437 438
}

#endif  // __linux__


439 440 441 442 443 444 445 446
// Test for issue http://crbug.com/23768 in Chromium.
// Heap can contain scripts with already disposed external sources.
// We need to verify that LogCompiledFunctions doesn't crash on them.
namespace {

class SimpleExternalString : public v8::String::ExternalStringResource {
 public:
  explicit SimpleExternalString(const char* source)
447
      : utf_source_(StrLength(source)) {
448 449 450 451 452 453 454 455 456 457 458 459 460
    for (int i = 0; i < utf_source_.length(); ++i)
      utf_source_[i] = source[i];
  }
  virtual ~SimpleExternalString() {}
  virtual size_t length() const { return utf_source_.length(); }
  virtual const uint16_t* data() const { return utf_source_.start(); }
 private:
  i::ScopedVector<uint16_t> utf_source_;
};

}  // namespace

TEST(Issue23768) {
461
  v8::HandleScope scope(CcTest::isolate());
462
  v8::Local<v8::Context> env = v8::Context::New(CcTest::isolate());
463 464 465
  env->Enter();

  SimpleExternalString source_ext_str("(function ext() {})();");
466
  v8::Local<v8::String> source =
467 468
      v8::String::NewExternalTwoByte(CcTest::isolate(), &source_ext_str)
          .ToLocalChecked();
469
  // Script needs to have a name in order to trigger InitLineEnds execution.
470 471 472 473 474
  v8::Local<v8::String> origin =
      v8::String::NewFromUtf8(CcTest::isolate(), "issue-23768-test",
                              v8::NewStringType::kNormal)
          .ToLocalChecked();
  v8::Local<v8::Script> evil_script = CompileWithOrigin(source, origin);
475
  CHECK(!evil_script.IsEmpty());
476
  CHECK(!evil_script->Run(env).IsEmpty());
477 478 479 480
  i::Handle<i::ExternalTwoByteString> i_source(
      i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source)));
  // This situation can happen if source was an external string disposed
  // by its owner.
481
  i_source->set_resource(nullptr);
482 483

  // Must not crash.
484
  CcTest::i_isolate()->logger()->LogCompiledFunctions();
485 486 487
}


488
static void ObjMethod1(const v8::FunctionCallbackInfo<v8::Value>& args) {
489 490
}

491

492
TEST(LogCallbacks) {
493 494 495 496
  SETUP_FLAGS();
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);
497
  {
498
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
499 500 501 502

    v8::Local<v8::FunctionTemplate> obj = v8::Local<v8::FunctionTemplate>::New(
        isolate, v8::FunctionTemplate::New(isolate));
    obj->SetClassName(v8_str("Obj"));
503
    v8::Local<v8::ObjectTemplate> proto = obj->PrototypeTemplate();
504 505 506
    v8::Local<v8::Signature> signature = v8::Signature::New(isolate, obj);
    proto->Set(v8_str("method1"),
               v8::FunctionTemplate::New(isolate, ObjMethod1,
507
                                         v8::Local<v8::Value>(), signature),
508 509
               static_cast<v8::PropertyAttribute>(v8::DontDelete));

510
    logger.env()
511
        ->Global()
512 513
        ->Set(logger.env(), v8_str("Obj"),
              obj->GetFunction(logger.env()).ToLocalChecked())
514
        .FromJust();
515 516
    CompileRun("Obj.prototype.method1.toString();");

517
    logger.LogCompiledFunctions();
518

519
    logger.StopLogging();
520

521 522 523 524
    Address ObjMethod1_entry = reinterpret_cast<Address>(ObjMethod1);
#if USES_FUNCTION_DESCRIPTORS
    ObjMethod1_entry = *FUNCTION_ENTRYPOINT_ADDRESS(ObjMethod1_entry);
#endif
525
    i::EmbeddedVector<char, 100> ref_data;
526
    i::SNPrintF(ref_data, ",0x%" V8PRIxPTR ",1,method1",
527
                reinterpret_cast<intptr_t>(ObjMethod1_entry));
528
    CHECK(logger.FindLine("code-creation,Callback,-2,", ref_data.start()));
529 530
  }
  isolate->Dispose();
531 532 533
}


534 535
static void Prop1Getter(v8::Local<v8::String> property,
                        const v8::PropertyCallbackInfo<v8::Value>& info) {
536 537 538
}

static void Prop1Setter(v8::Local<v8::String> property,
539 540
                        v8::Local<v8::Value> value,
                        const v8::PropertyCallbackInfo<void>& info) {
541 542
}

543 544
static void Prop2Getter(v8::Local<v8::String> property,
                        const v8::PropertyCallbackInfo<v8::Value>& info) {
545 546
}

547

548
TEST(LogAccessorCallbacks) {
549 550 551 552
  SETUP_FLAGS();
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);
553
  {
554
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
555 556 557 558

    v8::Local<v8::FunctionTemplate> obj = v8::Local<v8::FunctionTemplate>::New(
        isolate, v8::FunctionTemplate::New(isolate));
    obj->SetClassName(v8_str("Obj"));
559
    v8::Local<v8::ObjectTemplate> inst = obj->InstanceTemplate();
560 561 562
    inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter);
    inst->SetAccessor(v8_str("prop2"), Prop2Getter);

563
    logger.logger()->LogAccessorCallbacks();
564

565
    logger.StopLogging();
566

567 568 569 570
    Address Prop1Getter_entry = reinterpret_cast<Address>(Prop1Getter);
#if USES_FUNCTION_DESCRIPTORS
    Prop1Getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop1Getter_entry);
#endif
571
    EmbeddedVector<char, 100> prop1_getter_record;
572
    i::SNPrintF(prop1_getter_record, ",0x%" V8PRIxPTR ",1,get prop1",
573
                reinterpret_cast<intptr_t>(Prop1Getter_entry));
574 575
    CHECK(logger.FindLine("code-creation,Callback,-2,",
                          prop1_getter_record.start()));
576

577 578 579 580
    Address Prop1Setter_entry = reinterpret_cast<Address>(Prop1Setter);
#if USES_FUNCTION_DESCRIPTORS
    Prop1Setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop1Setter_entry);
#endif
581
    EmbeddedVector<char, 100> prop1_setter_record;
582
    i::SNPrintF(prop1_setter_record, ",0x%" V8PRIxPTR ",1,set prop1",
583
                reinterpret_cast<intptr_t>(Prop1Setter_entry));
584 585
    CHECK(logger.FindLine("code-creation,Callback,-2,",
                          prop1_setter_record.start()));
586

587 588 589 590
    Address Prop2Getter_entry = reinterpret_cast<Address>(Prop2Getter);
#if USES_FUNCTION_DESCRIPTORS
    Prop2Getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop2Getter_entry);
#endif
591
    EmbeddedVector<char, 100> prop2_getter_record;
592
    i::SNPrintF(prop2_getter_record, ",0x%" V8PRIxPTR ",1,get prop2",
593
                reinterpret_cast<intptr_t>(Prop2Getter_entry));
594 595
    CHECK(logger.FindLine("code-creation,Callback,-2,",
                          prop2_getter_record.start()));
596 597
  }
  isolate->Dispose();
598
}
599

600 601
// Test that logging of code create / move events is equivalent to traversal of
// a resulting heap.
602
TEST(EquivalenceOfLoggingAndTraversal) {
603 604 605 606 607 608
  // This test needs to be run on a "clean" V8 to ensure that snapshot log
  // is loaded. This is always true when running using tools/test.py because
  // it launches a new cctest instance for every test. To be sure that launching
  // cctest manually also works, please be sure that no tests below
  // are using V8.

609
  // Start with profiling to capture all code events from the beginning.
610 611 612 613
  SETUP_FLAGS();
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);
614
  {
615
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
616 617 618 619 620 621 622

    // Compile and run a function that creates other functions.
    CompileRun(
        "(function f(obj) {\n"
        "  obj.test =\n"
        "    (function a(j) { return function b() { return j; } })(100);\n"
        "})(this);");
623
    logger.logger()->StopProfiler();
624
    reinterpret_cast<i::Isolate*>(isolate)->heap()->CollectAllGarbage(
625
        i::Heap::kMakeHeapIterableMask, i::GarbageCollectionReason::kTesting);
626
    logger.StringEvent("test-logging-done", "");
627 628

    // Iterate heap to find compiled functions, will write to log.
629 630
    logger.LogCompiledFunctions();
    logger.StringEvent("test-traversal-done", "");
631

632 633 634 635
    logger.StopLogging();

    v8::Local<v8::String> log_str = logger.GetLogString();
    logger.env()
636
        ->Global()
637
        ->Set(logger.env(), v8_str("_log"), log_str)
638
        .FromJust();
639

640 641 642
    // Load the Test snapshot's sources, see log-eq-of-logging-and-traversal.js
    i::Vector<const char> source =
        i::NativesCollection<i::TEST>::GetScriptsSource();
643 644 645 646
    v8::Local<v8::String> source_str =
        v8::String::NewFromUtf8(isolate, source.start(),
                                v8::NewStringType::kNormal, source.length())
            .ToLocalChecked();
647
    v8::TryCatch try_catch(isolate);
648
    v8::Local<v8::Script> script = CompileWithOrigin(source_str, "");
649
    if (script.IsEmpty()) {
650
      v8::String::Utf8Value exception(isolate, try_catch.Exception());
651
      FATAL("compile: %s\n", *exception);
652
    }
653
    v8::Local<v8::Value> result;
654
    if (!script->Run(logger.env()).ToLocal(&result)) {
655
      v8::String::Utf8Value exception(isolate, try_catch.Exception());
656
      FATAL("run: %s\n", *exception);
657
    }
658
    // The result either be the "true" literal or problem description.
659
    if (!result->IsTrue()) {
660
      v8::Local<v8::String> s = result->ToString(logger.env()).ToLocalChecked();
661
      i::ScopedVector<char> data(s->Utf8Length() + 1);
662
      CHECK(data.start());
663
      s->WriteUtf8(data.start());
664
      FATAL("%s\n", data.start());
665
    }
666
  }
667
  isolate->Dispose();
668
}
669 670 671


TEST(LogVersion) {
672 673 674 675
  SETUP_FLAGS();
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);
676
  {
677 678 679
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
    logger.StopLogging();

680
    i::EmbeddedVector<char, 100> ref_data;
681
    i::SNPrintF(ref_data, "%d,%d,%d,%d,%d", i::Version::GetMajor(),
682 683
                i::Version::GetMinor(), i::Version::GetBuild(),
                i::Version::GetPatch(), i::Version::IsCandidate());
684
    CHECK(logger.FindLine("v8-version,", ref_data.start()));
685 686 687
  }
  isolate->Dispose();
}
688 689 690 691 692 693 694


// https://crbug.com/539892
// CodeCreateEvents with really large names should not crash.
TEST(Issue539892) {
  class : public i::CodeEventLogger {
   public:
695 696 697
    void CodeMoveEvent(i::AbstractCode* from, Address to) override {}
    void CodeDisableOptEvent(i::AbstractCode* code,
                             i::SharedFunctionInfo* shared) override {}
698 699

   private:
700 701
    void LogRecordedBuffer(i::AbstractCode* code, i::SharedFunctionInfo* shared,
                           const char* name, int length) override {}
702
    void LogRecordedBuffer(const i::wasm::WasmCode* code, const char* name,
703
                           int length) override {}
704 705 706 707 708 709 710
  } code_event_logger;
  SETUP_FLAGS();
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);

  {
711 712
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
    logger.logger()->addCodeEventListener(&code_event_logger);
713 714 715 716 717 718 719 720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738

    // Function with a really large name.
    const char* source_text =
        "(function "
        "baaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
        "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaac"
        "(){})();";

    CompileRun(source_text);

    // Must not crash.
739
    logger.LogCompiledFunctions();
740 741 742
  }
  isolate->Dispose();
}
743 744 745 746 747 748 749 750 751 752 753 754 755 756 757 758 759 760 761 762 763 764 765 766 767 768 769 770 771 772 773 774 775 776 777 778 779

TEST(LogAll) {
  SETUP_FLAGS();
  i::FLAG_log_all = true;
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);

  {
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);

    // Function that will
    const char* source_text =
        "function testAddFn(a,b) { return a + b };"
        "let result;"
        "for (let i = 0; i < 100000; i++) { result = testAddFn(i, i); };"
        "testAddFn('1', 1);"
        "for (let i = 0; i < 100000; i++) { result = testAddFn('1', i); }";
    CompileRun(source_text);

    logger.StopLogging();

    // We should find at least one code-creation even for testAddFn();
    CHECK(logger.FindLine("api,v8::Context::New"));
    CHECK(logger.FindLine("timer-event-start", "V8.CompileCode"));
    CHECK(logger.FindLine("timer-event-end", "V8.CompileCode"));
    CHECK(logger.FindLine("code-creation,Script", ":1:1"));
    CHECK(logger.FindLine("api,v8::Script::Run"));
    CHECK(logger.FindLine("code-creation,LazyCompile,", "testAddFn"));
    if (i::FLAG_opt && !i::FLAG_always_opt) {
      CHECK(logger.FindLine("code-deopt,", "soft"));
      CHECK(logger.FindLine("timer-event-start", "V8.DeoptimizeCode"));
      CHECK(logger.FindLine("timer-event-end", "V8.DeoptimizeCode"));
    }
  }
  isolate->Dispose();
}
780 781 782 783 784 785 786 787 788 789 790 791 792 793 794 795 796 797 798 799 800 801 802 803 804 805 806 807 808 809 810

TEST(TraceMaps) {
  SETUP_FLAGS();
  i::FLAG_trace_maps = true;
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);
  {
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
    // Try to create many different kind of maps to make sure the logging won't
    // crash. More detailed tests are implemented separately.
    const char* source_text =
        "let a = {};"
        "for (let i = 0; i < 500; i++) { a['p'+i] = i };"
        "class Test { constructor(i) { this.a = 1; this['p'+i] = 1; }};"
        "let t = new Test();"
        "t.b = 1; t.c = 1; t.d = 3;"
        "for (let i = 0; i < 100; i++) { t = new Test(i) };"
        "t.b = {};";
    CompileRun(source_text);

    logger.StopLogging();

    // Mostly superficial checks.
    CHECK(logger.FindLine("map,InitialMap", ",0x"));
    CHECK(logger.FindLine("map,Transition", ",0x"));
    CHECK(logger.FindLine("map-details", ",0x"));
  }
  i::FLAG_trace_maps = false;
  isolate->Dispose();
}
811

812 813 814 815 816 817 818 819 820 821 822 823 824 825 826 827 828 829 830 831 832 833 834 835 836 837 838 839 840 841 842 843 844 845 846 847 848 849 850
TEST(LogMaps) {
  // Test that all Map details from Maps in the snapshot are logged properly.
  SETUP_FLAGS();
  i::FLAG_trace_maps = true;
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);
  {
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
    logger.StopLogging();
    // Extract all the map-detail entry addresses from the log.
    std::unordered_set<uintptr_t> map_addresses;
    logger.ExtractAllAddresses(&map_addresses, "map-details", 2);
    i::Heap* heap = reinterpret_cast<i::Isolate*>(isolate)->heap();
    i::HeapIterator iterator(heap);
    i::DisallowHeapAllocation no_gc;

    // Iterate over all maps on the heap.
    size_t i = 0;
    for (i::HeapObject* obj = iterator.next(); obj != nullptr;
         obj = iterator.next()) {
      i++;
      if (!obj->IsMap()) continue;
      uintptr_t address = reinterpret_cast<uintptr_t>(obj);
      if (map_addresses.find(address) != map_addresses.end()) continue;
      logger.PrintLog(200);
      i::Map::cast(obj)->Print();
      V8_Fatal(__FILE__, __LINE__,
               "Map (%p, #%zu) was not logged during startup with --trace-maps!"
               "\n# Expected Log Line: map_details, ... %p"
               "\n# Use logger::PrintLog() for more details.",
               reinterpret_cast<void*>(obj), i, reinterpret_cast<void*>(obj));
    }
    logger.PrintLog(200);
  }
  i::FLAG_log_function_events = false;
  isolate->Dispose();
}

851 852 853 854 855 856 857 858 859 860 861 862 863 864 865 866 867 868 869 870 871 872 873 874 875 876 877 878 879 880 881 882
TEST(ConsoleTimeEvents) {
  SETUP_FLAGS();
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);
  {
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
    // Test that console time events are properly logged
    const char* source_text =
        "console.time();"
        "console.timeEnd();"
        "console.timeStamp();"
        "console.time('timerEvent1');"
        "console.timeEnd('timerEvent1');"
        "console.timeStamp('timerEvent2');"
        "console.timeStamp('timerEvent3');";
    CompileRun(source_text);

    logger.StopLogging();

    const char* pairs[][2] = {{"timer-event-start,default,", nullptr},
                              {"timer-event-end,default,", nullptr},
                              {"timer-event,default,", nullptr},
                              {"timer-event-start,timerEvent1,", nullptr},
                              {"timer-event-end,timerEvent1,", nullptr},
                              {"timer-event,timerEvent2,", nullptr},
                              {"timer-event,timerEvent3,", nullptr}};
    logger.FindLogLines(pairs, arraysize(pairs));
  }

  isolate->Dispose();
}
883 884

TEST(LogFunctionEvents) {
885 886 887
  // Always opt and stress opt will break the fine-grained log order.
  if (i::FLAG_always_opt) return;

888 889 890 891 892 893 894 895 896
  SETUP_FLAGS();
  i::FLAG_log_function_events = true;
  v8::Isolate::CreateParams create_params;
  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
  v8::Isolate* isolate = v8::Isolate::New(create_params);
  {
    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
    const char* source_text =
        "function lazyNotExecutedFunction() { return 'lazy' };"
897 898 899 900 901 902 903 904 905
        "function lazyFunction() { "
        "  function lazyInnerFunction() { return 'lazy' };"
        "  return lazyInnerFunction;"
        "};"
        "let innerFn = lazyFunction();"
        "innerFn();"
        "(function eagerFunction(){ return 'eager' })();"
        "function Foo() { this.foo = function(){}; };"
        "let i = new Foo(); i.foo();";
906 907 908 909
    CompileRun(source_text);

    logger.StopLogging();

910
    // TODO(cbruni): Extend with first-execution log statements.
911 912
    CHECK_NULL(
        logger.FindLine("function,compile-lazy,", ",lazyNotExecutedFunction"));
913 914 915 916 917 918 919 920 921 922 923 924 925 926 927 928 929 930 931 932 933 934 935 936 937 938
    // Only consider the log starting from the first preparse statement on.
    const char* start =
        logger.FindLine("function,preparse-", ",lazyNotExecutedFunction");
    const char* pairs[][2] = {
        // Step 1: parsing top-level script, preparsing functions
        {"function,preparse-", ",lazyNotExecutedFunction"},
        // Missing name for preparsing lazyInnerFunction
        // {"function,preparse-", nullptr},
        {"function,preparse-", ",lazyFunction"},
        {"function,full-parse,", ",eagerFunction"},
        {"function,preparse-", ",Foo"},
        // Missing name for inner preparsing of Foo.foo
        // {"function,preparse-", nullptr},
        // Missing name for top-level script.
        {"function,parse-script,", nullptr},

        // Step 2: compiling top-level script and eager functions
        // - Compiling script without name.
        {"function,compile,,", nullptr},
        {"function,compile,", ",eagerFunction"},

        // Step 3: start executing script
        // Step 4. - lazy parse, lazy compiling and execute skipped functions
        //         - execute eager functions.
        {"function,parse-function,", ",lazyFunction"},
        {"function,compile-lazy,", ",lazyFunction"},
939
        {"function,first-execution,", ",lazyFunction"},
940 941 942

        {"function,parse-function,", ",lazyInnerFunction"},
        {"function,compile-lazy,", ",lazyInnerFunction"},
943 944 945
        {"function,first-execution,", ",lazyInnerFunction"},

        {"function,first-execution,", ",eagerFunction"},
946 947 948

        {"function,parse-function,", ",Foo"},
        {"function,compile-lazy,", ",Foo"},
949 950
        {"function,first-execution,", ",Foo"},

951 952
        {"function,parse-function,", ",Foo.foo"},
        {"function,compile-lazy,", ",Foo.foo"},
953
        {"function,first-execution,", ",Foo.foo"},
954 955
    };
    logger.FindLogLines(pairs, arraysize(pairs), start);
956 957 958 959
  }
  i::FLAG_log_function_events = false;
  isolate->Dispose();
}