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