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