Line data Source code
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 : #include <unordered_set>
31 : #include <vector>
32 : #include "src/api-inl.h"
33 : #include "src/builtins/builtins.h"
34 : #include "src/log-utils.h"
35 : #include "src/log.h"
36 : #include "src/objects-inl.h"
37 : #include "src/ostreams.h"
38 : #include "src/profiler/cpu-profiler.h"
39 : #include "src/snapshot/natives.h"
40 : #include "src/v8.h"
41 : #include "src/version.h"
42 : #include "src/vm-state-inl.h"
43 : #include "test/cctest/cctest.h"
44 :
45 : using v8::internal::Address;
46 : using v8::internal::EmbeddedVector;
47 : using v8::internal::Logger;
48 : using v8::internal::StrLength;
49 :
50 : namespace {
51 :
52 :
53 : #define SETUP_FLAGS() \
54 : bool saved_log = i::FLAG_log; \
55 : bool saved_prof = i::FLAG_prof; \
56 : i::FLAG_log = true; \
57 : i::FLAG_prof = true; \
58 : i::FLAG_logfile = i::Log::kLogToTemporaryFile; \
59 : i::FLAG_logfile_per_isolate = false
60 :
61 25074 : static std::vector<std::string> Split(const std::string& s, char delimiter) {
62 : std::vector<std::string> result;
63 : std::string line;
64 50148 : std::istringstream stream(s);
65 450756 : while (std::getline(stream, line, delimiter)) {
66 133536 : result.push_back(line);
67 : }
68 25074 : return result;
69 : }
70 :
71 : class ScopedLoggerInitializer {
72 : public:
73 59 : ScopedLoggerInitializer(bool saved_log, bool saved_prof, v8::Isolate* isolate)
74 : : saved_log_(saved_log),
75 : saved_prof_(saved_prof),
76 : temp_file_(nullptr),
77 : isolate_(isolate),
78 : isolate_scope_(isolate),
79 : scope_(isolate),
80 59 : env_(v8::Context::New(isolate)),
81 236 : logger_(reinterpret_cast<i::Isolate*>(isolate)->logger()) {
82 59 : env_->Enter();
83 59 : }
84 :
85 236 : ~ScopedLoggerInitializer() {
86 59 : env_->Exit();
87 59 : logger_->TearDown();
88 59 : if (temp_file_ != nullptr) fclose(temp_file_);
89 59 : i::FLAG_prof = saved_prof_;
90 59 : i::FLAG_log = saved_log_;
91 59 : }
92 :
93 : v8::Local<v8::Context>& env() { return env_; }
94 :
95 : v8::Isolate* isolate() { return isolate_; }
96 :
97 : i::Isolate* i_isolate() { return reinterpret_cast<i::Isolate*>(isolate()); }
98 :
99 : Logger* logger() { return logger_; }
100 :
101 0 : v8::Local<v8::String> GetLogString() {
102 0 : int length = static_cast<int>(raw_log_.size());
103 0 : return v8::String::NewFromUtf8(isolate_, raw_log_.c_str(),
104 0 : v8::NewStringType::kNormal, length)
105 0 : .ToLocalChecked();
106 : }
107 :
108 : void PrintLog() {
109 : i::StdoutStream os;
110 : os << raw_log_ << std::flush;
111 : }
112 :
113 54 : void StopLogging() {
114 54 : bool exists = false;
115 108 : raw_log_ = i::ReadFile(StopLoggingGetTempFile(), &exists, true);
116 108 : log_ = Split(raw_log_, '\n');
117 54 : CHECK(exists);
118 54 : }
119 :
120 : // Searches |log_| for a line which contains all the strings in |search_terms|
121 : // as substrings, starting from the index |start|, and returns the index of
122 : // the found line. Returns std::string::npos if no line is found.
123 25241 : size_t IndexOfLine(const std::vector<std::string>& search_terms,
124 : size_t start = 0) {
125 136047 : for (size_t i = start; i < log_.size(); ++i) {
126 : const std::string& line = log_.at(i);
127 : bool all_terms_found = true;
128 179437 : for (const std::string& term : search_terms) {
129 98822 : all_terms_found &= line.find(term) != std::string::npos;
130 : }
131 80615 : if (all_terms_found) return i;
132 : }
133 : return std::string::npos;
134 : }
135 :
136 : bool ContainsLine(const std::vector<std::string>& search_terms,
137 : size_t start = 0) {
138 93 : return IndexOfLine(search_terms, start) != std::string::npos;
139 : }
140 :
141 : // Calls IndexOfLine for each set of substring terms in
142 : // |all_line_search_terms|, in order. Returns true if they're all found.
143 8 : bool ContainsLinesInOrder(
144 : const std::vector<std::vector<std::string>>& all_line_search_terms,
145 : size_t start = 0) {
146 8 : CHECK_GT(log_.size(), 0);
147 109 : for (auto& search_terms : all_line_search_terms) {
148 101 : start = IndexOfLine(search_terms, start);
149 101 : if (start == std::string::npos) return false;
150 101 : ++start; // Skip the found line.
151 : }
152 : return true;
153 : }
154 :
155 24 : std::unordered_set<uintptr_t> ExtractLogAddresses(std::string search_term,
156 : size_t address_column,
157 : bool allow_duplicates) {
158 24 : CHECK_GT(log_.size(), 0);
159 : // Map addresses of Maps to log_lines.
160 : std::unordered_map<uintptr_t, std::string> map;
161 : size_t current = 0;
162 : while (true) {
163 50088 : current = IndexOfLine({search_term}, current);
164 25044 : if (current == std::string::npos) break;
165 : std::string current_line = log_.at(current);
166 50040 : std::vector<std::string> columns = Split(current_line, ',');
167 25020 : ++current; // Skip the found line.
168 : // TODO(crbug.com/v8/8084): These two continue lines should really be
169 : // errors. But on Windows the log is sometimes mysteriously cut off at the
170 : // end. If the cut-off point happens to fall in the address field, the
171 : // conditions will be triggered.
172 25020 : if (address_column >= columns.size()) continue;
173 : uintptr_t address =
174 25020 : strtoll(columns.at(address_column).c_str(), nullptr, 16);
175 25020 : if (address == 0) continue;
176 25020 : if (!allow_duplicates) {
177 : auto match = map.find(address);
178 : // Ignore same address but different log line.
179 12510 : if (match != map.end() && match->second.compare(current_line) == 0) {
180 0 : for (size_t i = 0; i < current; i++) {
181 : printf("%s\n", log_.at(i).c_str());
182 : }
183 : printf("%zu\n", current);
184 0 : V8_Fatal(__FILE__, __LINE__, "%s, ... %p apperead twice:\n %s",
185 : search_term.c_str(), reinterpret_cast<void*>(address),
186 0 : current_line.c_str());
187 : }
188 : }
189 25020 : map.insert({address, current_line});
190 : }
191 : // Extract all keys.
192 : std::unordered_set<uintptr_t> result;
193 25044 : for (auto key_value : map) {
194 : result.insert(key_value.first);
195 : }
196 24 : return result;
197 : }
198 :
199 5 : void LogCodeObjects() { logger_->LogCodeObjects(); }
200 15 : void LogCompiledFunctions() { logger_->LogCompiledFunctions(); }
201 :
202 : void StringEvent(const char* name, const char* value) {
203 0 : logger_->StringEvent(name, value);
204 : }
205 :
206 : private:
207 54 : FILE* StopLoggingGetTempFile() {
208 54 : temp_file_ = logger_->TearDown();
209 54 : CHECK(temp_file_);
210 54 : fflush(temp_file_);
211 54 : rewind(temp_file_);
212 54 : return temp_file_;
213 : }
214 :
215 : const bool saved_log_;
216 : const bool saved_prof_;
217 : FILE* temp_file_;
218 : v8::Isolate* isolate_;
219 : v8::Isolate::Scope isolate_scope_;
220 : v8::HandleScope scope_;
221 : v8::Local<v8::Context> env_;
222 : Logger* logger_;
223 :
224 : std::string raw_log_;
225 : std::vector<std::string> log_;
226 :
227 : DISALLOW_COPY_AND_ASSIGN(ScopedLoggerInitializer);
228 : };
229 :
230 19 : class TestCodeEventHandler : public v8::CodeEventHandler {
231 : public:
232 : explicit TestCodeEventHandler(v8::Isolate* isolate)
233 38 : : v8::CodeEventHandler(isolate), isolate_(isolate) {}
234 :
235 51 : size_t CountLines(std::string prefix, std::string suffix = std::string()) {
236 51 : if (event_log_.empty()) return 0;
237 :
238 : size_t match = 0;
239 44265 : for (const std::string& line : event_log_) {
240 : size_t prefix_pos = line.find(prefix);
241 44223 : if (prefix_pos == std::string::npos) continue;
242 : size_t suffix_pos = line.rfind(suffix);
243 4417 : if (suffix_pos == std::string::npos) continue;
244 45 : if (suffix_pos != line.length() - suffix.length()) continue;
245 45 : if (prefix_pos >= suffix_pos) continue;
246 45 : match++;
247 : }
248 :
249 : return match;
250 : }
251 :
252 20010 : void Handle(v8::CodeEvent* code_event) override {
253 20010 : std::string log_line = "";
254 20010 : log_line += v8::CodeEvent::GetCodeEventTypeName(code_event->GetCodeType());
255 : log_line += " ";
256 40020 : log_line += FormatName(code_event);
257 20010 : event_log_.push_back(log_line);
258 20010 : }
259 :
260 : private:
261 20010 : std::string FormatName(v8::CodeEvent* code_event) {
262 20010 : std::string name = std::string(code_event->GetComment());
263 20010 : if (name.empty()) {
264 111 : v8::Local<v8::String> functionName = code_event->GetFunctionName();
265 111 : std::string buffer(functionName->Utf8Length(isolate_) + 1, 0);
266 111 : functionName->WriteUtf8(isolate_, &buffer[0],
267 222 : functionName->Utf8Length(isolate_) + 1);
268 : // Sanitize name, removing unwanted \0 resulted from WriteUtf8
269 222 : name = std::string(buffer.c_str());
270 : }
271 :
272 20010 : return name;
273 : }
274 :
275 : std::vector<std::string> event_log_;
276 : v8::Isolate* isolate_;
277 : };
278 :
279 : } // namespace
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.
284 : namespace {
285 :
286 : class SimpleExternalString : public v8::String::ExternalStringResource {
287 : public:
288 5 : explicit SimpleExternalString(const char* source)
289 5 : : utf_source_(StrLength(source)) {
290 225 : for (int i = 0; i < utf_source_.length(); ++i)
291 220 : utf_source_[i] = source[i];
292 5 : }
293 10 : ~SimpleExternalString() override = default;
294 40 : size_t length() const override { return utf_source_.length(); }
295 20 : const uint16_t* data() const override { return utf_source_.start(); }
296 : private:
297 : i::ScopedVector<uint16_t> utf_source_;
298 : };
299 :
300 : } // namespace
301 :
302 26644 : TEST(Issue23768) {
303 10 : v8::HandleScope scope(CcTest::isolate());
304 5 : v8::Local<v8::Context> env = v8::Context::New(CcTest::isolate());
305 5 : env->Enter();
306 :
307 5 : SimpleExternalString source_ext_str("(function ext() {})();");
308 : v8::Local<v8::String> source =
309 5 : v8::String::NewExternalTwoByte(CcTest::isolate(), &source_ext_str)
310 : .ToLocalChecked();
311 : // Script needs to have a name in order to trigger InitLineEnds execution.
312 : v8::Local<v8::String> origin =
313 5 : v8::String::NewFromUtf8(CcTest::isolate(), "issue-23768-test",
314 5 : v8::NewStringType::kNormal)
315 5 : .ToLocalChecked();
316 : v8::Local<v8::Script> evil_script =
317 5 : CompileWithOrigin(source, origin, v8_bool(false));
318 5 : CHECK(!evil_script.IsEmpty());
319 10 : CHECK(!evil_script->Run(env).IsEmpty());
320 : i::Handle<i::ExternalTwoByteString> i_source(
321 : i::ExternalTwoByteString::cast(*v8::Utils::OpenHandle(*source)),
322 : CcTest::i_isolate());
323 : // This situation can happen if source was an external string disposed
324 : // by its owner.
325 5 : i_source->SetResource(CcTest::i_isolate(), nullptr);
326 :
327 : // Must not crash.
328 5 : CcTest::i_isolate()->logger()->LogCompiledFunctions();
329 5 : }
330 :
331 0 : static void ObjMethod1(const v8::FunctionCallbackInfo<v8::Value>& args) {
332 0 : }
333 :
334 26644 : UNINITIALIZED_TEST(LogCallbacks) {
335 5 : SETUP_FLAGS();
336 : v8::Isolate::CreateParams create_params;
337 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
338 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
339 : {
340 10 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
341 :
342 : v8::Local<v8::FunctionTemplate> obj = v8::Local<v8::FunctionTemplate>::New(
343 10 : isolate, v8::FunctionTemplate::New(isolate));
344 5 : obj->SetClassName(v8_str("Obj"));
345 5 : v8::Local<v8::ObjectTemplate> proto = obj->PrototypeTemplate();
346 5 : v8::Local<v8::Signature> signature = v8::Signature::New(isolate, obj);
347 15 : proto->Set(v8_str("method1"),
348 : v8::FunctionTemplate::New(isolate, ObjMethod1,
349 : v8::Local<v8::Value>(), signature),
350 5 : static_cast<v8::PropertyAttribute>(v8::DontDelete));
351 :
352 : logger.env()
353 10 : ->Global()
354 10 : ->Set(logger.env(), v8_str("Obj"),
355 15 : obj->GetFunction(logger.env()).ToLocalChecked())
356 : .FromJust();
357 : CompileRun("Obj.prototype.method1.toString();");
358 :
359 : logger.LogCompiledFunctions();
360 5 : logger.StopLogging();
361 :
362 5 : Address ObjMethod1_entry = reinterpret_cast<Address>(ObjMethod1);
363 : #if USES_FUNCTION_DESCRIPTORS
364 : ObjMethod1_entry = *FUNCTION_ENTRYPOINT_ADDRESS(ObjMethod1_entry);
365 : #endif
366 : i::EmbeddedVector<char, 100> suffix_buffer;
367 5 : i::SNPrintF(suffix_buffer, ",0x%" V8PRIxPTR ",1,method1", ObjMethod1_entry);
368 15 : CHECK(logger.ContainsLine(
369 : {"code-creation,Callback,-2,", std::string(suffix_buffer.start())}));
370 : }
371 5 : isolate->Dispose();
372 5 : }
373 :
374 0 : static void Prop1Getter(v8::Local<v8::String> property,
375 : const v8::PropertyCallbackInfo<v8::Value>& info) {
376 0 : }
377 :
378 0 : static void Prop1Setter(v8::Local<v8::String> property,
379 : v8::Local<v8::Value> value,
380 : const v8::PropertyCallbackInfo<void>& info) {
381 0 : }
382 :
383 0 : static void Prop2Getter(v8::Local<v8::String> property,
384 : const v8::PropertyCallbackInfo<v8::Value>& info) {
385 0 : }
386 :
387 26644 : UNINITIALIZED_TEST(LogAccessorCallbacks) {
388 5 : SETUP_FLAGS();
389 : v8::Isolate::CreateParams create_params;
390 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
391 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
392 : {
393 10 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
394 :
395 : v8::Local<v8::FunctionTemplate> obj = v8::Local<v8::FunctionTemplate>::New(
396 10 : isolate, v8::FunctionTemplate::New(isolate));
397 5 : obj->SetClassName(v8_str("Obj"));
398 5 : v8::Local<v8::ObjectTemplate> inst = obj->InstanceTemplate();
399 5 : inst->SetAccessor(v8_str("prop1"), Prop1Getter, Prop1Setter);
400 5 : inst->SetAccessor(v8_str("prop2"), Prop2Getter);
401 :
402 5 : logger.logger()->LogAccessorCallbacks();
403 :
404 5 : logger.StopLogging();
405 :
406 5 : Address Prop1Getter_entry = reinterpret_cast<Address>(Prop1Getter);
407 : #if USES_FUNCTION_DESCRIPTORS
408 : Prop1Getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop1Getter_entry);
409 : #endif
410 : EmbeddedVector<char, 100> prop1_getter_record;
411 : i::SNPrintF(prop1_getter_record, ",0x%" V8PRIxPTR ",1,get prop1",
412 5 : Prop1Getter_entry);
413 15 : CHECK(logger.ContainsLine({"code-creation,Callback,-2,",
414 : std::string(prop1_getter_record.start())}));
415 :
416 5 : Address Prop1Setter_entry = reinterpret_cast<Address>(Prop1Setter);
417 : #if USES_FUNCTION_DESCRIPTORS
418 : Prop1Setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop1Setter_entry);
419 : #endif
420 : EmbeddedVector<char, 100> prop1_setter_record;
421 : i::SNPrintF(prop1_setter_record, ",0x%" V8PRIxPTR ",1,set prop1",
422 5 : Prop1Setter_entry);
423 15 : CHECK(logger.ContainsLine({"code-creation,Callback,-2,",
424 : std::string(prop1_setter_record.start())}));
425 :
426 5 : Address Prop2Getter_entry = reinterpret_cast<Address>(Prop2Getter);
427 : #if USES_FUNCTION_DESCRIPTORS
428 : Prop2Getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(Prop2Getter_entry);
429 : #endif
430 : EmbeddedVector<char, 100> prop2_getter_record;
431 : i::SNPrintF(prop2_getter_record, ",0x%" V8PRIxPTR ",1,get prop2",
432 5 : Prop2Getter_entry);
433 15 : CHECK(logger.ContainsLine({"code-creation,Callback,-2,",
434 : std::string(prop2_getter_record.start())}));
435 : }
436 5 : isolate->Dispose();
437 5 : }
438 :
439 : // Test that logging of code create / move events is equivalent to traversal of
440 : // a resulting heap.
441 26639 : UNINITIALIZED_TEST(EquivalenceOfLoggingAndTraversal) {
442 : // This test needs to be run on a "clean" V8 to ensure that snapshot log
443 : // is loaded. This is always true when running using tools/test.py because
444 : // it launches a new cctest instance for every test. To be sure that launching
445 : // cctest manually also works, please be sure that no tests below
446 : // are using V8.
447 :
448 : // Start with profiling to capture all code events from the beginning.
449 0 : SETUP_FLAGS();
450 : v8::Isolate::CreateParams create_params;
451 0 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
452 0 : v8::Isolate* isolate = v8::Isolate::New(create_params);
453 : {
454 0 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
455 :
456 : // Compile and run a function that creates other functions.
457 : CompileRun(
458 : "(function f(obj) {\n"
459 : " obj.test =\n"
460 : " (function a(j) { return function b() { return j; } })(100);\n"
461 : "})(this);");
462 0 : logger.logger()->StopProfilerThread();
463 0 : CcTest::PreciseCollectAllGarbage();
464 : logger.StringEvent("test-logging-done", "");
465 :
466 : // Iterate heap to find compiled functions, will write to log.
467 : logger.LogCompiledFunctions();
468 : logger.StringEvent("test-traversal-done", "");
469 :
470 0 : logger.StopLogging();
471 :
472 0 : v8::Local<v8::String> log_str = logger.GetLogString();
473 : logger.env()
474 0 : ->Global()
475 0 : ->Set(logger.env(), v8_str("_log"), log_str)
476 : .FromJust();
477 :
478 : // Load the Test snapshot's sources, see log-eq-of-logging-and-traversal.js
479 : i::Vector<const char> source =
480 0 : i::NativesCollection<i::TEST>::GetScriptsSource();
481 : v8::Local<v8::String> source_str =
482 0 : v8::String::NewFromUtf8(isolate, source.start(),
483 : v8::NewStringType::kNormal, source.length())
484 0 : .ToLocalChecked();
485 0 : v8::TryCatch try_catch(isolate);
486 0 : v8::Local<v8::Script> script = CompileWithOrigin(source_str, "", false);
487 0 : if (script.IsEmpty()) {
488 0 : v8::String::Utf8Value exception(isolate, try_catch.Exception());
489 0 : FATAL("compile: %s\n", *exception);
490 : }
491 : v8::Local<v8::Value> result;
492 0 : if (!script->Run(logger.env()).ToLocal(&result)) {
493 0 : v8::String::Utf8Value exception(isolate, try_catch.Exception());
494 0 : FATAL("run: %s\n", *exception);
495 : }
496 : // The result either be the "true" literal or problem description.
497 0 : if (!result->IsTrue()) {
498 0 : v8::Local<v8::String> s = result->ToString(logger.env()).ToLocalChecked();
499 0 : i::ScopedVector<char> data(s->Utf8Length(isolate) + 1);
500 0 : CHECK(data.start());
501 0 : s->WriteUtf8(isolate, data.start());
502 0 : FATAL("%s\n", data.start());
503 : }
504 : }
505 0 : isolate->Dispose();
506 0 : }
507 :
508 26644 : UNINITIALIZED_TEST(LogVersion) {
509 5 : SETUP_FLAGS();
510 : v8::Isolate::CreateParams create_params;
511 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
512 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
513 : {
514 10 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
515 5 : logger.StopLogging();
516 :
517 : i::EmbeddedVector<char, 100> line_buffer;
518 5 : i::SNPrintF(line_buffer, "%d,%d,%d,%d,%d", i::Version::GetMajor(),
519 : i::Version::GetMinor(), i::Version::GetBuild(),
520 5 : i::Version::GetPatch(), i::Version::IsCandidate());
521 15 : CHECK(
522 : logger.ContainsLine({"v8-version,", std::string(line_buffer.start())}));
523 : }
524 5 : isolate->Dispose();
525 5 : }
526 :
527 : // https://crbug.com/539892
528 : // CodeCreateEvents with really large names should not crash.
529 26644 : UNINITIALIZED_TEST(Issue539892) {
530 5 : class FakeCodeEventLogger : public i::CodeEventLogger {
531 : public:
532 : explicit FakeCodeEventLogger(i::Isolate* isolate)
533 5 : : CodeEventLogger(isolate) {}
534 :
535 0 : void CodeMoveEvent(i::AbstractCode from, i::AbstractCode to) override {}
536 0 : void CodeDisableOptEvent(i::AbstractCode code,
537 0 : i::SharedFunctionInfo shared) override {}
538 :
539 : private:
540 29 : void LogRecordedBuffer(i::AbstractCode code, i::SharedFunctionInfo shared,
541 29 : const char* name, int length) override {}
542 0 : void LogRecordedBuffer(const i::wasm::WasmCode* code, const char* name,
543 0 : int length) override {}
544 : };
545 :
546 5 : SETUP_FLAGS();
547 : v8::Isolate::CreateParams create_params;
548 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
549 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
550 : FakeCodeEventLogger code_event_logger(reinterpret_cast<i::Isolate*>(isolate));
551 :
552 : {
553 10 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
554 5 : logger.logger()->AddCodeEventListener(&code_event_logger);
555 :
556 : // Function with a really large name.
557 : const char* source_text =
558 : "(function "
559 : "baaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
560 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
561 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
562 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
563 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
564 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
565 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
566 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
567 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
568 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
569 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
570 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
571 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
572 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
573 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
574 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
575 : "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaac"
576 : "(){})();";
577 :
578 : CompileRun(source_text);
579 :
580 : // Must not crash.
581 : logger.LogCompiledFunctions();
582 : }
583 5 : isolate->Dispose();
584 5 : }
585 :
586 26644 : UNINITIALIZED_TEST(LogAll) {
587 5 : SETUP_FLAGS();
588 5 : i::FLAG_log_all = true;
589 5 : i::FLAG_turbo_inlining = false;
590 5 : i::FLAG_allow_natives_syntax = true;
591 : v8::Isolate::CreateParams create_params;
592 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
593 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
594 :
595 : {
596 10 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
597 :
598 : const char* source_text = R"(
599 : function testAddFn(a,b) {
600 : return a + b
601 : };
602 : let result;
603 :
604 : // Warm up the ICs.
605 : for (let i = 0; i < 100000; i++) {
606 : result = testAddFn(i, i);
607 : };
608 :
609 : // Enforce optimization.
610 : %OptimizeFunctionOnNextCall(testAddFn);
611 : result = testAddFn(1, 1);
612 :
613 : // Cause deopt.
614 : testAddFn('1', 1)
615 : for (let i = 0; i < 100000; i++) {
616 : result = testAddFn('1', i);
617 : }
618 : )";
619 : CompileRun(source_text);
620 :
621 5 : logger.StopLogging();
622 :
623 : // We should find at least one code-creation even for testAddFn();
624 15 : CHECK(logger.ContainsLine({"api,v8::Context::New"}));
625 15 : CHECK(logger.ContainsLine({"timer-event-start", "V8.CompileCode"}));
626 15 : CHECK(logger.ContainsLine({"timer-event-end", "V8.CompileCode"}));
627 15 : CHECK(logger.ContainsLine({"code-creation,Script", ":1:1"}));
628 15 : CHECK(logger.ContainsLine({"api,v8::Script::Run"}));
629 15 : CHECK(logger.ContainsLine({"code-creation,LazyCompile,", "testAddFn"}));
630 :
631 5 : if (i::FLAG_opt && !i::FLAG_always_opt) {
632 9 : CHECK(logger.ContainsLine({"code-deopt,", "not a Smi"}));
633 9 : CHECK(logger.ContainsLine({"timer-event-start", "V8.DeoptimizeCode"}));
634 9 : CHECK(logger.ContainsLine({"timer-event-end", "V8.DeoptimizeCode"}));
635 : }
636 : }
637 5 : isolate->Dispose();
638 5 : }
639 :
640 : #ifndef V8_TARGET_ARCH_ARM
641 26643 : UNINITIALIZED_TEST(LogInterpretedFramesNativeStack) {
642 4 : SETUP_FLAGS();
643 4 : i::FLAG_interpreted_frames_native_stack = true;
644 : v8::Isolate::CreateParams create_params;
645 4 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
646 4 : v8::Isolate* isolate = v8::Isolate::New(create_params);
647 :
648 : {
649 8 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
650 :
651 : const char* source_text =
652 : "function testLogInterpretedFramesNativeStack(a,b) { return a + b };"
653 : "testLogInterpretedFramesNativeStack('1', 1);";
654 : CompileRun(source_text);
655 :
656 4 : logger.StopLogging();
657 :
658 12 : CHECK(logger.ContainsLine(
659 : {"InterpretedFunction", "testLogInterpretedFramesNativeStack"}));
660 : }
661 4 : isolate->Dispose();
662 4 : }
663 : #endif // V8_TARGET_ARCH_ARM
664 :
665 26644 : UNINITIALIZED_TEST(ExternalCodeEventListener) {
666 5 : i::FLAG_log = false;
667 5 : i::FLAG_prof = false;
668 :
669 : v8::Isolate::CreateParams create_params;
670 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
671 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
672 :
673 : {
674 10 : v8::HandleScope scope(isolate);
675 : v8::Isolate::Scope isolate_scope(isolate);
676 5 : v8::Local<v8::Context> context = v8::Context::New(isolate);
677 : v8::Context::Scope context_scope(context);
678 :
679 : TestCodeEventHandler code_event_handler(isolate);
680 :
681 : const char* source_text_before_start =
682 : "function testCodeEventListenerBeforeStart(a,b) { return a + b };"
683 : "testCodeEventListenerBeforeStart('1', 1);";
684 : CompileRun(source_text_before_start);
685 :
686 15 : CHECK_EQ(code_event_handler.CountLines("LazyCompile",
687 : "testCodeEventListenerBeforeStart"),
688 : 0);
689 :
690 5 : code_event_handler.Enable();
691 :
692 15 : CHECK_GE(code_event_handler.CountLines("LazyCompile",
693 : "testCodeEventListenerBeforeStart"),
694 : 1);
695 :
696 : const char* source_text_after_start =
697 : "function testCodeEventListenerAfterStart(a,b) { return a + b };"
698 : "testCodeEventListenerAfterStart('1', 1);";
699 : CompileRun(source_text_after_start);
700 :
701 15 : CHECK_GE(code_event_handler.CountLines("LazyCompile",
702 : "testCodeEventListenerAfterStart"),
703 : 1);
704 : }
705 5 : isolate->Dispose();
706 5 : }
707 :
708 26644 : UNINITIALIZED_TEST(ExternalCodeEventListenerInnerFunctions) {
709 5 : i::FLAG_log = false;
710 5 : i::FLAG_prof = false;
711 :
712 : v8::ScriptCompiler::CachedData* cache;
713 : static const char* source_cstring =
714 : "(function f1() { return (function f2() {}); })()";
715 :
716 : v8::Isolate::CreateParams create_params;
717 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
718 5 : v8::Isolate* isolate1 = v8::Isolate::New(create_params);
719 : { // Test that we emit the correct code events from eagerly compiling.
720 10 : v8::HandleScope scope(isolate1);
721 : v8::Isolate::Scope isolate_scope(isolate1);
722 5 : v8::Local<v8::Context> context = v8::Context::New(isolate1);
723 : v8::Context::Scope context_scope(context);
724 :
725 : TestCodeEventHandler code_event_handler(isolate1);
726 5 : code_event_handler.Enable();
727 :
728 5 : v8::Local<v8::String> source_string = v8_str(source_cstring);
729 5 : v8::ScriptOrigin origin(v8_str("test"));
730 : v8::ScriptCompiler::Source source(source_string, origin);
731 : v8::Local<v8::UnboundScript> script =
732 5 : v8::ScriptCompiler::CompileUnboundScript(isolate1, &source)
733 5 : .ToLocalChecked();
734 15 : CHECK_EQ(code_event_handler.CountLines("Script", "f1"), 1);
735 15 : CHECK_EQ(code_event_handler.CountLines("Script", "f2"), 1);
736 5 : cache = v8::ScriptCompiler::CreateCodeCache(script);
737 : }
738 5 : isolate1->Dispose();
739 :
740 5 : v8::Isolate* isolate2 = v8::Isolate::New(create_params);
741 : { // Test that we emit the correct code events from deserialization.
742 10 : v8::HandleScope scope(isolate2);
743 : v8::Isolate::Scope isolate_scope(isolate2);
744 5 : v8::Local<v8::Context> context = v8::Context::New(isolate2);
745 : v8::Context::Scope context_scope(context);
746 :
747 : TestCodeEventHandler code_event_handler(isolate2);
748 5 : code_event_handler.Enable();
749 :
750 5 : v8::Local<v8::String> source_string = v8_str(source_cstring);
751 5 : v8::ScriptOrigin origin(v8_str("test"));
752 : v8::ScriptCompiler::Source source(source_string, origin, cache);
753 : {
754 : i::DisallowCompilation no_compile_expected(
755 : reinterpret_cast<i::Isolate*>(isolate2));
756 5 : v8::ScriptCompiler::CompileUnboundScript(
757 : isolate2, &source, v8::ScriptCompiler::kConsumeCodeCache)
758 : .ToLocalChecked();
759 : }
760 15 : CHECK_EQ(code_event_handler.CountLines("Script", "f1"), 1);
761 15 : CHECK_EQ(code_event_handler.CountLines("Script", "f2"), 1);
762 : }
763 5 : isolate2->Dispose();
764 5 : }
765 :
766 : #ifndef V8_TARGET_ARCH_ARM
767 26643 : UNINITIALIZED_TEST(ExternalCodeEventListenerWithInterpretedFramesNativeStack) {
768 4 : i::FLAG_log = false;
769 4 : i::FLAG_prof = false;
770 4 : i::FLAG_interpreted_frames_native_stack = true;
771 :
772 : v8::Isolate::CreateParams create_params;
773 4 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
774 4 : v8::Isolate* isolate = v8::Isolate::New(create_params);
775 :
776 : {
777 8 : v8::HandleScope scope(isolate);
778 : v8::Isolate::Scope isolate_scope(isolate);
779 4 : v8::Local<v8::Context> context = v8::Context::New(isolate);
780 4 : context->Enter();
781 :
782 : TestCodeEventHandler code_event_handler(isolate);
783 :
784 : const char* source_text_before_start =
785 : "function testCodeEventListenerBeforeStart(a,b) { return a + b };"
786 : "testCodeEventListenerBeforeStart('1', 1);";
787 : CompileRun(source_text_before_start);
788 :
789 12 : CHECK_EQ(code_event_handler.CountLines("InterpretedFunction",
790 : "testCodeEventListenerBeforeStart"),
791 : 0);
792 :
793 4 : code_event_handler.Enable();
794 :
795 12 : CHECK_GE(code_event_handler.CountLines("InterpretedFunction",
796 : "testCodeEventListenerBeforeStart"),
797 : 1);
798 :
799 : const char* source_text_after_start =
800 : "function testCodeEventListenerAfterStart(a,b) { return a + b };"
801 : "testCodeEventListenerAfterStart('1', 1);";
802 : CompileRun(source_text_after_start);
803 :
804 12 : CHECK_GE(code_event_handler.CountLines("InterpretedFunction",
805 : "testCodeEventListenerAfterStart"),
806 : 1);
807 :
808 12 : CHECK_EQ(
809 : code_event_handler.CountLines("Builtin", "InterpreterEntryTrampoline"),
810 : 1);
811 :
812 4 : context->Exit();
813 : }
814 4 : isolate->Dispose();
815 4 : }
816 : #endif // V8_TARGET_ARCH_ARM
817 :
818 26644 : UNINITIALIZED_TEST(TraceMaps) {
819 5 : SETUP_FLAGS();
820 5 : i::FLAG_trace_maps = true;
821 : v8::Isolate::CreateParams create_params;
822 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
823 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
824 : {
825 10 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
826 : // Try to create many different kind of maps to make sure the logging won't
827 : // crash. More detailed tests are implemented separately.
828 : const char* source_text = R"(
829 : let a = {};
830 : for (let i = 0; i < 500; i++) {
831 : a['p'+i] = i
832 : };
833 : class Test {
834 : constructor(i) {
835 : this.a = 1;
836 : this['p'+i] = 1;
837 : }
838 : };
839 : let t = new Test();
840 : t.b = 1; t.c = 1; t.d = 3;
841 : for (let i = 0; i < 100; i++) {
842 : t = new Test(i)
843 : };
844 : t.b = {};
845 : )";
846 5 : CompileRunChecked(isolate, source_text);
847 :
848 5 : logger.StopLogging();
849 :
850 : // Mostly superficial checks.
851 15 : CHECK(logger.ContainsLine({"map,InitialMap", ",0x"}));
852 15 : CHECK(logger.ContainsLine({"map,Transition", ",0x"}));
853 15 : CHECK(logger.ContainsLine({"map-details", ",0x"}));
854 : }
855 5 : i::FLAG_trace_maps = false;
856 5 : isolate->Dispose();
857 5 : }
858 :
859 : namespace {
860 : // Ensure that all Maps found on the heap have a single corresponding map-create
861 : // and map-details entry in the v8.log.
862 12 : void ValidateMapDetailsLogging(v8::Isolate* isolate,
863 : ScopedLoggerInitializer* logger) {
864 : // map-create might have duplicates if a Map address is reused after a gc.
865 : std::unordered_set<uintptr_t> map_create_addresses =
866 24 : logger->ExtractLogAddresses("map-create", 2, true);
867 : std::unordered_set<uintptr_t> map_details_addresses =
868 24 : logger->ExtractLogAddresses("map-details", 2, false);
869 :
870 : // Iterate over all maps on the heap.
871 : i::Heap* heap = reinterpret_cast<i::Isolate*>(isolate)->heap();
872 24 : i::HeapIterator iterator(heap);
873 : i::DisallowHeapAllocation no_gc;
874 : size_t i = 0;
875 126840 : for (i::HeapObject obj = iterator.next(); !obj.is_null();
876 : obj = iterator.next()) {
877 241146 : if (!obj->IsMap()) continue;
878 12510 : i++;
879 12510 : uintptr_t address = obj->ptr();
880 12510 : if (map_create_addresses.find(address) == map_create_addresses.end()) {
881 : // logger->PrintLog();
882 0 : i::Map::cast(obj)->Print();
883 0 : V8_Fatal(__FILE__, __LINE__,
884 : "Map (%p, #%zu) creation not logged during startup with "
885 : "--trace-maps!"
886 : "\n# Expected Log Line: map-create, ... %p",
887 : reinterpret_cast<void*>(obj->ptr()), i,
888 0 : reinterpret_cast<void*>(obj->ptr()));
889 12510 : } else if (map_details_addresses.find(address) ==
890 : map_details_addresses.end()) {
891 : // logger->PrintLog();
892 0 : i::Map::cast(obj)->Print();
893 0 : V8_Fatal(__FILE__, __LINE__,
894 : "Map (%p, #%zu) details not logged during startup with "
895 : "--trace-maps!"
896 : "\n# Expected Log Line: map-details, ... %p",
897 : reinterpret_cast<void*>(obj->ptr()), i,
898 0 : reinterpret_cast<void*>(obj->ptr()));
899 : }
900 : }
901 12 : }
902 :
903 : } // namespace
904 :
905 26644 : UNINITIALIZED_TEST(LogMapsDetailsStartup) {
906 : // Reusing map addresses might cause these tests to fail.
907 5 : if (i::FLAG_gc_global || i::FLAG_stress_compaction ||
908 : i::FLAG_stress_incremental_marking) {
909 1 : return;
910 : }
911 : // Test that all Map details from Maps in the snapshot are logged properly.
912 4 : SETUP_FLAGS();
913 4 : i::FLAG_trace_maps = true;
914 : v8::Isolate::CreateParams create_params;
915 4 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
916 4 : v8::Isolate* isolate = v8::Isolate::New(create_params);
917 : {
918 8 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
919 4 : logger.StopLogging();
920 4 : ValidateMapDetailsLogging(isolate, &logger);
921 : }
922 :
923 4 : i::FLAG_log_function_events = false;
924 4 : isolate->Dispose();
925 : }
926 :
927 26644 : UNINITIALIZED_TEST(LogMapsDetailsCode) {
928 : // Reusing map addresses might cause these tests to fail.
929 5 : if (i::FLAG_gc_global || i::FLAG_stress_compaction ||
930 : i::FLAG_stress_incremental_marking) {
931 1 : return;
932 : }
933 4 : SETUP_FLAGS();
934 4 : i::FLAG_retain_maps_for_n_gc = 0xFFFFFFF;
935 4 : i::FLAG_trace_maps = true;
936 : v8::Isolate::CreateParams create_params;
937 4 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
938 4 : v8::Isolate* isolate = v8::Isolate::New(create_params);
939 : const char* source = R"(
940 : // Normal properties overflowing into dict-mode.
941 : let a = {};
942 : for (let i = 0; i < 500; i++) {
943 : a['p'+i] = i
944 : };
945 : // Constructor / initial maps
946 : function Constructor(dictElements=false) {
947 : this.a = 1;
948 : this.b = 2;
949 : this.c = 3;
950 : if (dictElements) {
951 : this[0xFFFFF] = 1;
952 : }
953 : this.d = 4;
954 : this.e = 5;
955 : this.f = 5;
956 : }
957 : // Keep objects and their maps alive to avoid reusing map addresses.
958 : let instances = [];
959 : let instance;
960 : for (let i =0; i < 500; i++) {
961 : instances.push(new Constructor());
962 : }
963 : // Map deprecation.
964 : for (let i =0; i < 500; i++) {
965 : instance = new Constructor();
966 : instance.d = 1.1;
967 : instances.push(instance);
968 : }
969 : for (let i =0; i < 500; i++) {
970 : instance = new Constructor();
971 : instance.b = 1.1;
972 : instances.push(instance);
973 : }
974 : for (let i =0; i < 500; i++) {
975 : instance = new Constructor();
976 : instance.c = Object;
977 : instances.push(instance);
978 : }
979 : // Create instance with dict-elements.
980 : instances.push(new Constructor(true));
981 :
982 : // Class
983 : class Test {
984 : constructor(i) {
985 : this.a = 1;
986 : this['p'+i] = 1;
987 : }
988 : };
989 : let t = new Test();
990 : t.b = 1; t.c = 1; t.d = 3;
991 : for (let i = 0; i < 100; i++) {
992 : t = new Test(i);
993 : instances.push(t);
994 : }
995 : t.b = {};
996 :
997 : // Anonymous classes
998 : function create(value) {
999 : return new class {
1000 : constructor() {
1001 : this.value = value;
1002 : }
1003 : }
1004 : }
1005 : for (let i = 0; i < 100; i++) {
1006 : instances.push(create(i));
1007 : };
1008 :
1009 : // Modifying some protoypes.
1010 : Array.prototype.helper = () => 1;
1011 : [1,2,3].helper();
1012 : )";
1013 : {
1014 8 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1015 4 : CompileRunChecked(isolate, source);
1016 4 : logger.StopLogging();
1017 4 : ValidateMapDetailsLogging(isolate, &logger);
1018 : }
1019 :
1020 4 : i::FLAG_log_function_events = false;
1021 4 : isolate->Dispose();
1022 : }
1023 :
1024 26644 : UNINITIALIZED_TEST(LogMapsDetailsContexts) {
1025 : // Reusing map addresses might cause these tests to fail.
1026 5 : if (i::FLAG_gc_global || i::FLAG_stress_compaction ||
1027 : i::FLAG_stress_incremental_marking) {
1028 1 : return;
1029 : }
1030 : // Test that all Map details from Maps in the snapshot are logged properly.
1031 4 : SETUP_FLAGS();
1032 4 : i::FLAG_trace_maps = true;
1033 : v8::Isolate::CreateParams create_params;
1034 4 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
1035 4 : v8::Isolate* isolate = v8::Isolate::New(create_params);
1036 :
1037 : {
1038 8 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1039 : // Use the default context.
1040 4 : CompileRunChecked(isolate, "{a:1}");
1041 : // Create additional contexts.
1042 4 : v8::Local<v8::Context> env1 = v8::Context::New(isolate);
1043 4 : env1->Enter();
1044 4 : CompileRun(env1, "{b:1}").ToLocalChecked();
1045 :
1046 4 : v8::Local<v8::Context> env2 = v8::Context::New(isolate);
1047 4 : env2->Enter();
1048 4 : CompileRun(env2, "{c:1}").ToLocalChecked();
1049 4 : env2->Exit();
1050 4 : env1->Exit();
1051 :
1052 4 : logger.StopLogging();
1053 4 : ValidateMapDetailsLogging(isolate, &logger);
1054 : }
1055 :
1056 4 : i::FLAG_log_function_events = false;
1057 4 : isolate->Dispose();
1058 : }
1059 :
1060 26644 : UNINITIALIZED_TEST(ConsoleTimeEvents) {
1061 5 : SETUP_FLAGS();
1062 : v8::Isolate::CreateParams create_params;
1063 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
1064 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
1065 : {
1066 10 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1067 : // Test that console time events are properly logged
1068 : const char* source_text =
1069 : "console.time();"
1070 : "console.timeEnd();"
1071 : "console.timeStamp();"
1072 : "console.time('timerEvent1');"
1073 : "console.timeEnd('timerEvent1');"
1074 : "console.timeStamp('timerEvent2');"
1075 : "console.timeStamp('timerEvent3');";
1076 : CompileRun(source_text);
1077 :
1078 5 : logger.StopLogging();
1079 :
1080 : std::vector<std::vector<std::string>> lines = {
1081 : {"timer-event-start,default,"}, {"timer-event-end,default,"},
1082 : {"timer-event,default,"}, {"timer-event-start,timerEvent1,"},
1083 : {"timer-event-end,timerEvent1,"}, {"timer-event,timerEvent2,"},
1084 110 : {"timer-event,timerEvent3,"}};
1085 5 : CHECK(logger.ContainsLinesInOrder(lines));
1086 : }
1087 :
1088 5 : isolate->Dispose();
1089 5 : }
1090 :
1091 26643 : UNINITIALIZED_TEST(LogFunctionEvents) {
1092 : // Always opt and stress opt will break the fine-grained log order.
1093 5 : if (i::FLAG_always_opt) return;
1094 :
1095 3 : SETUP_FLAGS();
1096 3 : i::FLAG_log_function_events = true;
1097 : v8::Isolate::CreateParams create_params;
1098 3 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
1099 3 : v8::Isolate* isolate = v8::Isolate::New(create_params);
1100 :
1101 : {
1102 6 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1103 :
1104 : // Run some warmup code to help ignoring existing log entries.
1105 : CompileRun(
1106 : "function warmUp(a) {"
1107 : " let b = () => 1;"
1108 : " return function(c) { return a+b+c; };"
1109 : "};"
1110 : "warmUp(1)(2);"
1111 : "(function warmUpEndMarkerFunction(){})();");
1112 :
1113 : const char* source_text =
1114 : "function lazyNotExecutedFunction() { return 'lazy' };"
1115 : "function lazyFunction() { "
1116 : " function lazyInnerFunction() { return 'lazy' };"
1117 : " return lazyInnerFunction;"
1118 : "};"
1119 : "let innerFn = lazyFunction();"
1120 : "innerFn();"
1121 : "(function eagerFunction(){ return 'eager' })();"
1122 : "function Foo() { this.foo = function(){}; };"
1123 : "let i = new Foo(); i.foo();";
1124 : CompileRun(source_text);
1125 :
1126 3 : logger.StopLogging();
1127 :
1128 : // Ignore all the log entries that happened before warmup
1129 9 : size_t start = logger.IndexOfLine(
1130 3 : {"function,first-execution", "warmUpEndMarkerFunction"});
1131 3 : CHECK(start != std::string::npos);
1132 : std::vector<std::vector<std::string>> lines = {
1133 : // Create a new script
1134 : {"script,create"},
1135 : {"script-details"},
1136 : // Step 1: parsing top-level script, preparsing functions
1137 : {"function,preparse-", ",lazyNotExecutedFunction"},
1138 : // Missing name for preparsing lazyInnerFunction
1139 : // {"function,preparse-", nullptr},
1140 : {"function,preparse-", ",lazyFunction"},
1141 : {"function,full-parse,", ",eagerFunction"},
1142 : {"function,preparse-", ",Foo"},
1143 : // Missing name for inner preparsing of Foo.foo
1144 : // {"function,preparse-", nullptr},
1145 : // Missing name for top-level script.
1146 : {"function,parse-script,"},
1147 :
1148 : // Step 2: compiling top-level script and eager functions
1149 : // - Compiling script without name.
1150 : {"function,compile,"},
1151 : {"function,compile,", ",eagerFunction"},
1152 :
1153 : // Step 3: start executing script
1154 : // Step 4. - lazy parse, lazy compiling and execute skipped functions
1155 : // - execute eager functions.
1156 : {"function,parse-function,", ",lazyFunction"},
1157 : {"function,compile-lazy,", ",lazyFunction"},
1158 : {"function,first-execution,", ",lazyFunction"},
1159 :
1160 : {"function,parse-function,", ",lazyInnerFunction"},
1161 : {"function,compile-lazy,", ",lazyInnerFunction"},
1162 : {"function,first-execution,", ",lazyInnerFunction"},
1163 :
1164 : {"function,first-execution,", ",eagerFunction"},
1165 :
1166 : {"function,parse-function,", ",Foo"},
1167 : {"function,compile-lazy,", ",Foo"},
1168 : {"function,first-execution,", ",Foo"},
1169 :
1170 : {"function,parse-function,", ",Foo.foo"},
1171 : {"function,compile-lazy,", ",Foo.foo"},
1172 : {"function,first-execution,", ",Foo.foo"},
1173 201 : };
1174 3 : CHECK(logger.ContainsLinesInOrder(lines, start));
1175 : }
1176 3 : i::FLAG_log_function_events = false;
1177 3 : isolate->Dispose();
1178 : }
1179 :
1180 26644 : UNINITIALIZED_TEST(BuiltinsNotLoggedAsLazyCompile) {
1181 5 : SETUP_FLAGS();
1182 : v8::Isolate::CreateParams create_params;
1183 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
1184 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
1185 : {
1186 10 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1187 :
1188 : logger.LogCodeObjects();
1189 : logger.LogCompiledFunctions();
1190 5 : logger.StopLogging();
1191 :
1192 : i::Handle<i::Code> builtin = logger.i_isolate()->builtins()->builtin_handle(
1193 5 : i::Builtins::kBooleanConstructor);
1194 : i::EmbeddedVector<char, 100> buffer;
1195 :
1196 : // Should only be logged as "Builtin" with a name, never as "LazyCompile".
1197 15 : i::SNPrintF(buffer, ",0x%" V8PRIxPTR ",%d,BooleanConstructor",
1198 5 : builtin->InstructionStart(), builtin->InstructionSize());
1199 15 : CHECK(logger.ContainsLine(
1200 : {"code-creation,Builtin,3,", std::string(buffer.start())}));
1201 :
1202 15 : i::SNPrintF(buffer, ",0x%" V8PRIxPTR ",%d,", builtin->InstructionStart(),
1203 5 : builtin->InstructionSize());
1204 15 : CHECK(!logger.ContainsLine(
1205 : {"code-creation,LazyCompile,3,", std::string(buffer.start())}));
1206 : }
1207 5 : isolate->Dispose();
1208 79922 : }
|
