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