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 25120 : static std::vector<std::string> Split(const std::string& s, char delimiter) {
62 : std::vector<std::string> result;
63 : std::string line;
64 50240 : std::istringstream stream(s);
65 343742 : while (std::getline(stream, line, delimiter)) {
66 134191 : result.push_back(line);
67 : }
68 25120 : return result;
69 : }
70 :
71 : class ScopedLoggerInitializer {
72 : public:
73 122 : 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 61 : env_(v8::Context::New(isolate)),
81 244 : logger_(reinterpret_cast<i::Isolate*>(isolate)->logger()) {
82 61 : env_->Enter();
83 61 : }
84 :
85 183 : ~ScopedLoggerInitializer() {
86 61 : env_->Exit();
87 61 : logger_->TearDown();
88 61 : if (temp_file_ != nullptr) fclose(temp_file_);
89 61 : i::FLAG_prof = saved_prof_;
90 61 : i::FLAG_log = saved_log_;
91 61 : }
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 112 : void StopLogging() {
114 56 : bool exists = false;
115 112 : raw_log_ = i::ReadFile(StopLoggingGetTempFile(), &exists, true);
116 112 : log_ = Split(raw_log_, '\n');
117 56 : CHECK(exists);
118 56 : }
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 25309 : size_t IndexOfLine(const std::vector<std::string>& search_terms,
124 : size_t start = 0) {
125 162028 : for (size_t i = start; i < log_.size(); ++i) {
126 81014 : const std::string& line = log_.at(i);
127 : bool all_terms_found = true;
128 261189 : for (const std::string& term : search_terms) {
129 99219 : all_terms_found &= line.find(term) != std::string::npos;
130 : }
131 80985 : 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 9 : bool ContainsLinesInOrder(
144 : const std::vector<std::vector<std::string>>& all_line_search_terms,
145 : size_t start = 0) {
146 18 : CHECK_GT(log_.size(), 0);
147 141 : for (auto& search_terms : all_line_search_terms) {
148 123 : start = IndexOfLine(search_terms, start);
149 123 : if (start == std::string::npos) return false;
150 123 : ++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 75264 : current = IndexOfLine({search_term}, current);
164 25088 : if (current == std::string::npos) break;
165 25064 : std::string current_line = log_.at(current);
166 50128 : std::vector<std::string> columns = Split(current_line, ',');
167 25064 : ++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 50128 : if (address_column >= columns.size()) continue;
173 : uintptr_t address =
174 25064 : strtoll(columns.at(address_column).c_str(), nullptr, 16);
175 25064 : if (address == 0) continue;
176 25064 : if (!allow_duplicates) {
177 : auto match = map.find(address);
178 : // Ignore same address but different log line.
179 12532 : 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 25064 : map.insert({address, current_line});
190 : }
191 : // Extract all keys.
192 24 : std::unordered_set<uintptr_t> result;
193 25112 : 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 56 : FILE* StopLoggingGetTempFile() {
208 56 : temp_file_ = logger_->TearDown();
209 56 : CHECK(temp_file_);
210 56 : fflush(temp_file_);
211 56 : rewind(temp_file_);
212 56 : 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 46892 : for (const std::string& line : event_log_) {
240 : size_t prefix_pos = line.find(prefix);
241 46847 : if (prefix_pos == std::string::npos) continue;
242 : size_t suffix_pos = line.rfind(suffix);
243 5410 : 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 20826 : void Handle(v8::CodeEvent* code_event) override {
253 20826 : std::string log_line = "";
254 20826 : log_line += v8::CodeEvent::GetCodeEventTypeName(code_event->GetCodeType());
255 : log_line += " ";
256 41652 : log_line += FormatName(code_event);
257 20826 : event_log_.push_back(log_line);
258 20826 : }
259 :
260 : private:
261 20826 : std::string FormatName(v8::CodeEvent* code_event) {
262 20826 : std::string name = std::string(code_event->GetComment());
263 20826 : 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 20826 : 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 28342 : 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 28342 : 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 28342 : 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 28337 : 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()->StopProfiler();
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 28342 : 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 28342 : 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 28342 : 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 28342 : TEST(LogInterpretedFramesNativeStack) {
640 5 : SETUP_FLAGS();
641 5 : i::FLAG_interpreted_frames_native_stack = true;
642 : v8::Isolate::CreateParams create_params;
643 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
644 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
645 :
646 : {
647 5 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
648 :
649 : const char* source_text =
650 : "function testLogInterpretedFramesNativeStack(a,b) { return a + b };"
651 : "testLogInterpretedFramesNativeStack('1', 1);";
652 : CompileRun(source_text);
653 :
654 5 : logger.StopLogging();
655 :
656 15 : CHECK(logger.ContainsLine(
657 5 : {"InterpretedFunction", "testLogInterpretedFramesNativeStack"}));
658 : }
659 5 : isolate->Dispose();
660 5 : }
661 :
662 28342 : TEST(ExternalCodeEventListener) {
663 5 : i::FLAG_log = false;
664 5 : i::FLAG_prof = false;
665 :
666 : v8::Isolate::CreateParams create_params;
667 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
668 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
669 :
670 : {
671 5 : v8::HandleScope scope(isolate);
672 : v8::Isolate::Scope isolate_scope(isolate);
673 5 : v8::Local<v8::Context> context = v8::Context::New(isolate);
674 : v8::Context::Scope context_scope(context);
675 :
676 : TestCodeEventHandler code_event_handler(isolate);
677 :
678 : const char* source_text_before_start =
679 : "function testCodeEventListenerBeforeStart(a,b) { return a + b };"
680 : "testCodeEventListenerBeforeStart('1', 1);";
681 : CompileRun(source_text_before_start);
682 :
683 15 : CHECK_EQ(code_event_handler.CountLines("LazyCompile",
684 : "testCodeEventListenerBeforeStart"),
685 : 0);
686 :
687 5 : code_event_handler.Enable();
688 :
689 15 : CHECK_GE(code_event_handler.CountLines("LazyCompile",
690 : "testCodeEventListenerBeforeStart"),
691 : 1);
692 :
693 : const char* source_text_after_start =
694 : "function testCodeEventListenerAfterStart(a,b) { return a + b };"
695 : "testCodeEventListenerAfterStart('1', 1);";
696 : CompileRun(source_text_after_start);
697 :
698 15 : CHECK_GE(code_event_handler.CountLines("LazyCompile",
699 : "testCodeEventListenerAfterStart"),
700 5 : 1);
701 : }
702 5 : isolate->Dispose();
703 5 : }
704 :
705 28342 : TEST(ExternalCodeEventListenerInnerFunctions) {
706 5 : i::FLAG_log = false;
707 5 : i::FLAG_prof = false;
708 :
709 : v8::ScriptCompiler::CachedData* cache;
710 : static const char* source_cstring =
711 : "(function f1() { return (function f2() {}); })()";
712 :
713 : v8::Isolate::CreateParams create_params;
714 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
715 5 : v8::Isolate* isolate1 = v8::Isolate::New(create_params);
716 : { // Test that we emit the correct code events from eagerly compiling.
717 5 : v8::HandleScope scope(isolate1);
718 : v8::Isolate::Scope isolate_scope(isolate1);
719 5 : v8::Local<v8::Context> context = v8::Context::New(isolate1);
720 : v8::Context::Scope context_scope(context);
721 :
722 : TestCodeEventHandler code_event_handler(isolate1);
723 5 : code_event_handler.Enable();
724 :
725 5 : v8::Local<v8::String> source_string = v8_str(source_cstring);
726 5 : v8::ScriptOrigin origin(v8_str("test"));
727 : v8::ScriptCompiler::Source source(source_string, origin);
728 : v8::Local<v8::UnboundScript> script =
729 : v8::ScriptCompiler::CompileUnboundScript(isolate1, &source)
730 10 : .ToLocalChecked();
731 15 : CHECK_EQ(code_event_handler.CountLines("Script", "f1"), 1);
732 15 : CHECK_EQ(code_event_handler.CountLines("Script", "f2"), 1);
733 10 : cache = v8::ScriptCompiler::CreateCodeCache(script);
734 : }
735 5 : isolate1->Dispose();
736 :
737 5 : v8::Isolate* isolate2 = v8::Isolate::New(create_params);
738 : { // Test that we emit the correct code events from deserialization.
739 5 : v8::HandleScope scope(isolate2);
740 : v8::Isolate::Scope isolate_scope(isolate2);
741 5 : v8::Local<v8::Context> context = v8::Context::New(isolate2);
742 : v8::Context::Scope context_scope(context);
743 :
744 : TestCodeEventHandler code_event_handler(isolate2);
745 5 : code_event_handler.Enable();
746 :
747 5 : v8::Local<v8::String> source_string = v8_str(source_cstring);
748 5 : v8::ScriptOrigin origin(v8_str("test"));
749 : v8::ScriptCompiler::Source source(source_string, origin, cache);
750 : {
751 : i::DisallowCompilation no_compile_expected(
752 : reinterpret_cast<i::Isolate*>(isolate2));
753 : v8::ScriptCompiler::CompileUnboundScript(
754 : isolate2, &source, v8::ScriptCompiler::kConsumeCodeCache)
755 5 : .ToLocalChecked();
756 : }
757 15 : CHECK_EQ(code_event_handler.CountLines("Script", "f1"), 1);
758 20 : CHECK_EQ(code_event_handler.CountLines("Script", "f2"), 1);
759 : }
760 5 : isolate2->Dispose();
761 5 : }
762 :
763 28342 : TEST(ExternalCodeEventListenerWithInterpretedFramesNativeStack) {
764 5 : i::FLAG_log = false;
765 5 : i::FLAG_prof = false;
766 5 : i::FLAG_interpreted_frames_native_stack = true;
767 :
768 : v8::Isolate::CreateParams create_params;
769 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
770 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
771 :
772 : {
773 5 : v8::HandleScope scope(isolate);
774 : v8::Isolate::Scope isolate_scope(isolate);
775 5 : v8::Local<v8::Context> context = v8::Context::New(isolate);
776 5 : context->Enter();
777 :
778 : TestCodeEventHandler code_event_handler(isolate);
779 :
780 : const char* source_text_before_start =
781 : "function testCodeEventListenerBeforeStart(a,b) { return a + b };"
782 : "testCodeEventListenerBeforeStart('1', 1);";
783 : CompileRun(source_text_before_start);
784 :
785 15 : CHECK_EQ(code_event_handler.CountLines("InterpretedFunction",
786 : "testCodeEventListenerBeforeStart"),
787 : 0);
788 :
789 5 : code_event_handler.Enable();
790 :
791 15 : CHECK_GE(code_event_handler.CountLines("InterpretedFunction",
792 : "testCodeEventListenerBeforeStart"),
793 : 1);
794 :
795 : const char* source_text_after_start =
796 : "function testCodeEventListenerAfterStart(a,b) { return a + b };"
797 : "testCodeEventListenerAfterStart('1', 1);";
798 : CompileRun(source_text_after_start);
799 :
800 15 : CHECK_GE(code_event_handler.CountLines("InterpretedFunction",
801 : "testCodeEventListenerAfterStart"),
802 : 1);
803 :
804 15 : CHECK_EQ(
805 : code_event_handler.CountLines("Builtin", "InterpreterEntryTrampoline"),
806 : 1);
807 :
808 10 : context->Exit();
809 : }
810 5 : isolate->Dispose();
811 5 : }
812 :
813 28342 : TEST(TraceMaps) {
814 5 : SETUP_FLAGS();
815 5 : i::FLAG_trace_maps = true;
816 : v8::Isolate::CreateParams create_params;
817 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
818 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
819 : {
820 5 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
821 : // Try to create many different kind of maps to make sure the logging won't
822 : // crash. More detailed tests are implemented separately.
823 : const char* source_text = R"(
824 : let a = {};
825 : for (let i = 0; i < 500; i++) {
826 : a['p'+i] = i
827 : };
828 : class Test {
829 : constructor(i) {
830 : this.a = 1;
831 : this['p'+i] = 1;
832 : }
833 : };
834 : let t = new Test();
835 : t.b = 1; t.c = 1; t.d = 3;
836 : for (let i = 0; i < 100; i++) {
837 : t = new Test(i)
838 : };
839 : t.b = {};
840 : )";
841 5 : CompileRunChecked(isolate, source_text);
842 :
843 5 : logger.StopLogging();
844 :
845 : // Mostly superficial checks.
846 15 : CHECK(logger.ContainsLine({"map,InitialMap", ",0x"}));
847 15 : CHECK(logger.ContainsLine({"map,Transition", ",0x"}));
848 15 : CHECK(logger.ContainsLine({"map-details", ",0x"}));
849 : }
850 5 : i::FLAG_trace_maps = false;
851 5 : isolate->Dispose();
852 5 : }
853 :
854 : namespace {
855 : // Ensure that all Maps found on the heap have a single corresponding map-create
856 : // and map-details entry in the v8.log.
857 12 : void ValidateMapDetailsLogging(v8::Isolate* isolate,
858 : ScopedLoggerInitializer* logger) {
859 : // map-create might have duplicates if a Map address is reused after a gc.
860 : std::unordered_set<uintptr_t> map_create_addresses =
861 24 : logger->ExtractLogAddresses("map-create", 2, true);
862 : std::unordered_set<uintptr_t> map_details_addresses =
863 24 : logger->ExtractLogAddresses("map-details", 2, false);
864 :
865 : // Iterate over all maps on the heap.
866 12 : i::Heap* heap = reinterpret_cast<i::Isolate*>(isolate)->heap();
867 24 : i::HeapIterator iterator(heap);
868 : i::DisallowHeapAllocation no_gc;
869 : size_t i = 0;
870 246994 : for (i::HeapObject obj = iterator.next(); !obj.is_null();
871 : obj = iterator.next()) {
872 234438 : if (!obj->IsMap()) continue;
873 12532 : i++;
874 12532 : uintptr_t address = obj->ptr();
875 12532 : if (map_create_addresses.find(address) == map_create_addresses.end()) {
876 : // logger->PrintLog();
877 0 : i::Map::cast(obj)->Print();
878 : V8_Fatal(__FILE__, __LINE__,
879 : "Map (%p, #%zu) creation not logged during startup with "
880 : "--trace-maps!"
881 : "\n# Expected Log Line: map-create, ... %p",
882 : reinterpret_cast<void*>(obj->ptr()), i,
883 0 : reinterpret_cast<void*>(obj->ptr()));
884 12532 : } else if (map_details_addresses.find(address) ==
885 : map_details_addresses.end()) {
886 : // logger->PrintLog();
887 0 : i::Map::cast(obj)->Print();
888 : V8_Fatal(__FILE__, __LINE__,
889 : "Map (%p, #%zu) details not logged during startup with "
890 : "--trace-maps!"
891 : "\n# Expected Log Line: map-details, ... %p",
892 : reinterpret_cast<void*>(obj->ptr()), i,
893 0 : reinterpret_cast<void*>(obj->ptr()));
894 : }
895 : }
896 12 : }
897 :
898 : } // namespace
899 :
900 28342 : TEST(LogMapsDetailsStartup) {
901 : // Reusing map addresses might cause these tests to fail.
902 5 : if (i::FLAG_gc_global || i::FLAG_stress_compaction ||
903 : i::FLAG_stress_incremental_marking) {
904 1 : return;
905 : }
906 : // Test that all Map details from Maps in the snapshot are logged properly.
907 4 : SETUP_FLAGS();
908 4 : i::FLAG_trace_maps = true;
909 : v8::Isolate::CreateParams create_params;
910 4 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
911 4 : v8::Isolate* isolate = v8::Isolate::New(create_params);
912 : {
913 4 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
914 4 : logger.StopLogging();
915 4 : ValidateMapDetailsLogging(isolate, &logger);
916 : }
917 :
918 4 : i::FLAG_log_function_events = false;
919 4 : isolate->Dispose();
920 : }
921 :
922 28342 : TEST(LogMapsDetailsCode) {
923 : // Reusing map addresses might cause these tests to fail.
924 5 : if (i::FLAG_gc_global || i::FLAG_stress_compaction ||
925 : i::FLAG_stress_incremental_marking) {
926 1 : return;
927 : }
928 4 : SETUP_FLAGS();
929 4 : i::FLAG_retain_maps_for_n_gc = 0xFFFFFFF;
930 4 : i::FLAG_trace_maps = true;
931 : v8::Isolate::CreateParams create_params;
932 4 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
933 4 : v8::Isolate* isolate = v8::Isolate::New(create_params);
934 : const char* source = R"(
935 : // Normal properties overflowing into dict-mode.
936 : let a = {};
937 : for (let i = 0; i < 500; i++) {
938 : a['p'+i] = i
939 : };
940 : // Constructor / initial maps
941 : function Constructor(dictElements=false) {
942 : this.a = 1;
943 : this.b = 2;
944 : this.c = 3;
945 : if (dictElements) {
946 : this[0xFFFFF] = 1;
947 : }
948 : this.d = 4;
949 : this.e = 5;
950 : this.f = 5;
951 : }
952 : // Keep objects and their maps alive to avoid reusing map addresses.
953 : let instances = [];
954 : let instance;
955 : for (let i =0; i < 500; i++) {
956 : instances.push(new Constructor());
957 : }
958 : // Map deprecation.
959 : for (let i =0; i < 500; i++) {
960 : instance = new Constructor();
961 : instance.d = 1.1;
962 : instances.push(instance);
963 : }
964 : for (let i =0; i < 500; i++) {
965 : instance = new Constructor();
966 : instance.b = 1.1;
967 : instances.push(instance);
968 : }
969 : for (let i =0; i < 500; i++) {
970 : instance = new Constructor();
971 : instance.c = Object;
972 : instances.push(instance);
973 : }
974 : // Create instance with dict-elements.
975 : instances.push(new Constructor(true));
976 :
977 : // Class
978 : class Test {
979 : constructor(i) {
980 : this.a = 1;
981 : this['p'+i] = 1;
982 : }
983 : };
984 : let t = new Test();
985 : t.b = 1; t.c = 1; t.d = 3;
986 : for (let i = 0; i < 100; i++) {
987 : t = new Test(i);
988 : instances.push(t);
989 : }
990 : t.b = {};
991 :
992 : // Anonymous classes
993 : function create(value) {
994 : return new class {
995 : constructor() {
996 : this.value = value;
997 : }
998 : }
999 : }
1000 : for (let i = 0; i < 100; i++) {
1001 : instances.push(create(i));
1002 : };
1003 :
1004 : // Modifying some protoypes.
1005 : Array.prototype.helper = () => 1;
1006 : [1,2,3].helper();
1007 : )";
1008 : {
1009 4 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1010 4 : CompileRunChecked(isolate, source);
1011 4 : logger.StopLogging();
1012 4 : ValidateMapDetailsLogging(isolate, &logger);
1013 : }
1014 :
1015 4 : i::FLAG_log_function_events = false;
1016 4 : isolate->Dispose();
1017 : }
1018 :
1019 28342 : TEST(LogMapsDetailsContexts) {
1020 : // Reusing map addresses might cause these tests to fail.
1021 5 : if (i::FLAG_gc_global || i::FLAG_stress_compaction ||
1022 : i::FLAG_stress_incremental_marking) {
1023 1 : return;
1024 : }
1025 : // Test that all Map details from Maps in the snapshot are logged properly.
1026 4 : SETUP_FLAGS();
1027 4 : i::FLAG_trace_maps = true;
1028 : v8::Isolate::CreateParams create_params;
1029 4 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
1030 4 : v8::Isolate* isolate = v8::Isolate::New(create_params);
1031 :
1032 : {
1033 4 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1034 : // Use the default context.
1035 4 : CompileRunChecked(isolate, "{a:1}");
1036 : // Create additional contexts.
1037 4 : v8::Local<v8::Context> env1 = v8::Context::New(isolate);
1038 4 : env1->Enter();
1039 4 : CompileRun(env1, "{b:1}").ToLocalChecked();
1040 :
1041 4 : v8::Local<v8::Context> env2 = v8::Context::New(isolate);
1042 4 : env2->Enter();
1043 4 : CompileRun(env2, "{c:1}").ToLocalChecked();
1044 4 : env2->Exit();
1045 4 : env1->Exit();
1046 :
1047 4 : logger.StopLogging();
1048 4 : ValidateMapDetailsLogging(isolate, &logger);
1049 : }
1050 :
1051 4 : i::FLAG_log_function_events = false;
1052 4 : isolate->Dispose();
1053 : }
1054 :
1055 28342 : TEST(ConsoleTimeEvents) {
1056 5 : SETUP_FLAGS();
1057 : v8::Isolate::CreateParams create_params;
1058 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
1059 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
1060 : {
1061 5 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1062 : // Test that console time events are properly logged
1063 : const char* source_text =
1064 : "console.time();"
1065 : "console.timeEnd();"
1066 : "console.timeStamp();"
1067 : "console.time('timerEvent1');"
1068 : "console.timeEnd('timerEvent1');"
1069 : "console.timeStamp('timerEvent2');"
1070 : "console.timeStamp('timerEvent3');";
1071 : CompileRun(source_text);
1072 :
1073 5 : logger.StopLogging();
1074 :
1075 : std::vector<std::vector<std::string>> lines = {
1076 : {"timer-event-start,default,"}, {"timer-event-end,default,"},
1077 : {"timer-event,default,"}, {"timer-event-start,timerEvent1,"},
1078 : {"timer-event-end,timerEvent1,"}, {"timer-event,timerEvent2,"},
1079 110 : {"timer-event,timerEvent3,"}};
1080 10 : CHECK(logger.ContainsLinesInOrder(lines));
1081 : }
1082 :
1083 5 : isolate->Dispose();
1084 5 : }
1085 :
1086 28342 : TEST(LogFunctionEvents) {
1087 : // Always opt and stress opt will break the fine-grained log order.
1088 6 : if (i::FLAG_always_opt) return;
1089 :
1090 4 : SETUP_FLAGS();
1091 4 : i::FLAG_log_function_events = true;
1092 : v8::Isolate::CreateParams create_params;
1093 4 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
1094 4 : v8::Isolate* isolate = v8::Isolate::New(create_params);
1095 :
1096 : {
1097 4 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1098 :
1099 : // Run some warmup code to help ignoring existing log entries.
1100 : CompileRun(
1101 : "function warmUp(a) {"
1102 : " let b = () => 1;"
1103 : " return function(c) { return a+b+c; };"
1104 : "};"
1105 : "warmUp(1)(2);"
1106 : "(function warmUpEndMarkerFunction(){})();");
1107 :
1108 : const char* source_text =
1109 : "function lazyNotExecutedFunction() { return 'lazy' };"
1110 : "function lazyFunction() { "
1111 : " function lazyInnerFunction() { return 'lazy' };"
1112 : " return lazyInnerFunction;"
1113 : "};"
1114 : "let innerFn = lazyFunction();"
1115 : "innerFn();"
1116 : "(function eagerFunction(){ return 'eager' })();"
1117 : "function Foo() { this.foo = function(){}; };"
1118 : "let i = new Foo(); i.foo();";
1119 : CompileRun(source_text);
1120 :
1121 4 : logger.StopLogging();
1122 :
1123 : // Ignore all the log entries that happened before warmup
1124 : size_t start = logger.IndexOfLine(
1125 12 : {"function,first-execution", "warmUpEndMarkerFunction"});
1126 4 : CHECK(start != std::string::npos);
1127 : std::vector<std::vector<std::string>> lines = {
1128 : // Create a new script
1129 : {"script,create"},
1130 : {"script-details"},
1131 : // Step 1: parsing top-level script, preparsing functions
1132 : {"function,preparse-", ",lazyNotExecutedFunction"},
1133 : // Missing name for preparsing lazyInnerFunction
1134 : // {"function,preparse-", nullptr},
1135 : {"function,preparse-", ",lazyFunction"},
1136 : {"function,full-parse,", ",eagerFunction"},
1137 : {"function,preparse-", ",Foo"},
1138 : // Missing name for inner preparsing of Foo.foo
1139 : // {"function,preparse-", nullptr},
1140 : // Missing name for top-level script.
1141 : {"function,parse-script,"},
1142 :
1143 : // Step 2: compiling top-level script and eager functions
1144 : // - Compiling script without name.
1145 : {"function,compile,"},
1146 : {"function,compile,", ",eagerFunction"},
1147 :
1148 : // Step 3: start executing script
1149 : // Step 4. - lazy parse, lazy compiling and execute skipped functions
1150 : // - execute eager functions.
1151 : {"function,parse-function,", ",lazyFunction"},
1152 : {"function,compile-lazy,", ",lazyFunction"},
1153 : {"function,first-execution,", ",lazyFunction"},
1154 :
1155 : {"function,parse-function,", ",lazyInnerFunction"},
1156 : {"function,compile-lazy,", ",lazyInnerFunction"},
1157 : {"function,first-execution,", ",lazyInnerFunction"},
1158 :
1159 : {"function,first-execution,", ",eagerFunction"},
1160 :
1161 : {"function,parse-function,", ",Foo"},
1162 : {"function,compile-lazy,", ",Foo"},
1163 : {"function,first-execution,", ",Foo"},
1164 :
1165 : {"function,parse-function,", ",Foo.foo"},
1166 : {"function,compile-lazy,", ",Foo.foo"},
1167 : {"function,first-execution,", ",Foo.foo"},
1168 268 : };
1169 8 : CHECK(logger.ContainsLinesInOrder(lines, start));
1170 : }
1171 4 : i::FLAG_log_function_events = false;
1172 4 : isolate->Dispose();
1173 : }
1174 :
1175 28342 : TEST(BuiltinsNotLoggedAsLazyCompile) {
1176 5 : SETUP_FLAGS();
1177 : v8::Isolate::CreateParams create_params;
1178 5 : create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
1179 5 : v8::Isolate* isolate = v8::Isolate::New(create_params);
1180 : {
1181 5 : ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
1182 :
1183 5 : logger.LogCodeObjects();
1184 5 : logger.LogCompiledFunctions();
1185 5 : logger.StopLogging();
1186 :
1187 : i::Handle<i::Code> builtin = logger.i_isolate()->builtins()->builtin_handle(
1188 5 : i::Builtins::kBooleanConstructor);
1189 : i::EmbeddedVector<char, 100> buffer;
1190 :
1191 : // Should only be logged as "Builtin" with a name, never as "LazyCompile".
1192 : i::SNPrintF(buffer, ",0x%" V8PRIxPTR ",%d,BooleanConstructor",
1193 10 : builtin->InstructionStart(), builtin->InstructionSize());
1194 15 : CHECK(logger.ContainsLine(
1195 : {"code-creation,Builtin,3,", std::string(buffer.start())}));
1196 :
1197 : i::SNPrintF(buffer, ",0x%" V8PRIxPTR ",%d,", builtin->InstructionStart(),
1198 10 : builtin->InstructionSize());
1199 15 : CHECK(!logger.ContainsLine(
1200 5 : {"code-creation,LazyCompile,3,", std::string(buffer.start())}));
1201 : }
1202 5 : isolate->Dispose();
1203 85016 : }
|
