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