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
21 using v8::internal::Address;
22 using v8::internal::EmbeddedVector;
23 using v8::internal::Logger;
24 using v8::internal::StrLength;
25
26 namespace {
27
28
29 class ScopedLoggerInitializer {
30 public:
ScopedLoggerInitializer(bool prof_lazy)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
~ScopedLoggerInitializer()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
env()54 v8::Handle<v8::Context>& env() { return env_; }
55
StopLoggingGetTempFile()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:
init_flags_(bool prof_lazy)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
StrNStr(const char * s1,const char * s2,int n)89 static 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
TEST(ProfLazyMode)99 TEST(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
165 namespace {
166
167 class 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
207 class 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
233 class 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
253 class 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
283 TEST(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.
324 namespace {
325
326 class SimpleExternalString : public v8::String::ExternalStringResource {
327 public:
SimpleExternalString(const char * source)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 }
~SimpleExternalString()333 virtual ~SimpleExternalString() {}
length() const334 virtual size_t length() const { return utf_source_.length(); }
data() const335 virtual const uint16_t* data() const { return utf_source_.start(); }
336 private:
337 i::ScopedVector<uint16_t> utf_source_;
338 };
339
340 } // namespace
341
TEST(Issue23768)342 TEST(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
ObjMethod1(const v8::Arguments & args)365 static v8::Handle<v8::Value> ObjMethod1(const v8::Arguments& args) {
366 return v8::Handle<v8::Value>();
367 }
368
TEST(LogCallbacks)369 TEST(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
Prop1Getter(v8::Local<v8::String> property,const v8::AccessorInfo & info)404 static v8::Handle<v8::Value> Prop1Getter(v8::Local<v8::String> property,
405 const v8::AccessorInfo& info) {
406 return v8::Handle<v8::Value>();
407 }
408
Prop1Setter(v8::Local<v8::String> property,v8::Local<v8::Value> value,const v8::AccessorInfo & info)409 static void Prop1Setter(v8::Local<v8::String> property,
410 v8::Local<v8::Value> value,
411 const v8::AccessorInfo& info) {
412 }
413
Prop2Getter(v8::Local<v8::String> property,const v8::AccessorInfo & info)414 static v8::Handle<v8::Value> Prop2Getter(v8::Local<v8::String> property,
415 const v8::AccessorInfo& info) {
416 return v8::Handle<v8::Value>();
417 }
418
TEST(LogAccessorCallbacks)419 TEST(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
TEST(IsLoggingPreserved)461 TEST(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
472 typedef 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.
TEST(EquivalenceOfLoggingAndTraversal)477 TEST(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