v8/test/cctest/test-traced-value.cc
Benedikt Meurer a2af7e1101 [tracing] Improve tracing signals for compilation/optimization.
This adds OBJECT/SNAPSHOT trace events for Script and SharedFunctionInfo
objects, logging their creation with appropriate information to make
sense of them.

Based on that we introduces five flow events to model the optimized
compilation via tracing in the "disabled-by-default-v8.compile" category:

  - "v8.optimizingCompile.start" logs the creation of the
    PipelineCompilationJob (for TurboFan JavaScript optimization)
    with the "function" argument referring to the trace event
    object created for the SharedFunctionInfo.
  - "v8.optimzingCompile.prepare" logs the preparation of the
    PipelineCompilationJob on the main thread, also carrying the
    "function" argument. This connects the flow event to the actual
    tracing duration event associated with the preparation phases.
  - "v8.optimizingCompile.execute" logs the (usually concurrent)
    optimization of the TurboFan graph (again with "function").
  - "v8.optimizingCompile.finalize" logs the main thread phase which
    finalizes the optimized code and eventually installs it (in case
    of success).
  - "v8.optimizingCompile.end" signals the end of the
    PipelineCompilationJob, which carries the "compilationInfo",
    that contains the interesting bits of the OptimizedCompilationInfo,
    specifically whether the compile was successfull and which functions
    were inlined for example.

This also adds two instant events "V8.AbortOptimization" and
"V8.RetryOptimization" in "disabled-by-default-v8.compile" category
that are emitted when TurboFan cannot optimize a certain function.
In case of "V8.RetryOptimization", TurboFan might be able to optimize
it later, whereas "V8.AbortOptimization" permanently disables the
optimization of a given function. The JSON representation of this is

```js
{
  "pid": 256639,
  "tid": 256639,
  "ts": 6935411377801,
  "tts": 159116,
  "ph": "I",
  "cat": "disabled-by-default-v8.compile",
  "name": "V8.AbortOptimization",
  "dur": 0,
  "tdur": 0,
  "args": {
    "reason": "Function is too big to be optimized",
    "function": {
      "id_ref": "0x600000001",
      "scope": "v8::internal::SharedFunctionInfo"
    }
  }
},
```

where the "function" refers to a previously emitted SNAPSHOT for the
function in question. In the trace viewer it will show up as instant
event under "v8.optimizingCompile.prepare" in case of the relevant
example where optimization is disabled due to reaching the bytecode
limit (as in the JSON above), i.e. it'll look something like this

  https://i.paste.pics/aafc2de9df10ea8f5acc1a761d80f07b.png

for the example highlighted in the recent blog post

  https://ponyfoo.com/articles/javascript-performance-pitfalls-v8

that describes the optimization limit. The "v8.optimizingCompile.end"
duration event will also carry this information as part of the
"compilationInfo" object, but specifically for CI tools, etc. it might
be a whole lot easier to just look for the "V8.AbortOptimization"
instant event.

Bug: v8:8598, v8:9039
Tbr: ulan@chromium.org
Doc: bit.ly/v8-tracing-signals
Change-Id: Ic87ac336004690c65b6b15ad73bc6fbd4b5f12c4
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1511483
Commit-Queue: Benedikt Meurer <bmeurer@chromium.org>
Reviewed-by: Peter Marshall <petermarshall@chromium.org>
Reviewed-by: Benedikt Meurer <bmeurer@chromium.org>
Cr-Commit-Position: refs/heads/master@{#60448}
2019-03-25 14:49:08 +00:00

156 lines
4.9 KiB
C++

// Copyright 2016 the V8 project authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
#include "src/tracing/traced-value.h"
#include "test/cctest/cctest.h"
using v8::tracing::TracedValue;
TEST(FlatDictionary) {
auto value = TracedValue::Create();
value->SetInteger("int", 2014);
value->SetDouble("double", 0.0);
value->SetBoolean("bool", true);
value->SetString("string", "string");
std::string json = "PREFIX";
value->AppendAsTraceFormat(&json);
CHECK_EQ(
"PREFIX{\"int\":2014,\"double\":0,\"bool\":true,\"string\":"
"\"string\"}",
json);
}
TEST(NoDotPathExpansion) {
auto value = TracedValue::Create();
value->SetInteger("in.t", 2014);
value->SetDouble("doub.le", -20.25);
value->SetBoolean("bo.ol", true);
value->SetString("str.ing", "str.ing");
std::string json;
value->AppendAsTraceFormat(&json);
CHECK_EQ(
"{\"in.t\":2014,\"doub.le\":-20.25,\"bo.ol\":true,\"str.ing\":\"str."
"ing\"}",
json);
}
TEST(Hierarchy) {
auto value = TracedValue::Create();
value->SetInteger("i0", 2014);
value->BeginDictionary("dict1");
value->SetInteger("i1", 2014);
value->BeginDictionary("dict2");
value->SetBoolean("b2", false);
value->EndDictionary();
value->SetString("s1", "foo");
value->EndDictionary();
value->SetDouble("d0", 0.0);
value->SetDouble("d1", 10.5);
value->SetBoolean("b0", true);
value->BeginArray("a1");
value->AppendInteger(1);
value->AppendBoolean(true);
value->BeginDictionary();
value->SetInteger("i2", 3);
value->EndDictionary();
value->EndArray();
value->SetString("s0", "foo");
value->BeginArray("arr1");
value->BeginDictionary();
value->EndDictionary();
value->BeginArray();
value->EndArray();
value->BeginDictionary();
value->EndDictionary();
value->EndArray();
std::string json;
value->AppendAsTraceFormat(&json);
CHECK_EQ(
"{\"i0\":2014,\"dict1\":{\"i1\":2014,\"dict2\":{\"b2\":false},"
"\"s1\":\"foo\"},\"d0\":0,\"d1\":10.5,\"b0\":true,\"a1\":[1,true,{\"i2\":"
"3}],\"s0\":\"foo\",\"arr1\":[{},[],{}]}",
json);
}
TEST(Nesting) {
auto value = TracedValue::Create();
auto v0 = TracedValue::Create();
auto v2 = TracedValue::Create();
v0->SetString("s1", std::string("Hello World!"));
v2->SetValue("v0", v0.get());
value->SetValue("v2", v2.get());
std::string json;
value->AppendAsTraceFormat(&json);
CHECK_EQ("{\"v2\":{\"v0\":{\"s1\":\"Hello World!\"}}}", json);
}
TEST(LongStrings) {
std::string long_string = "supercalifragilisticexpialidocious";
std::string long_string2 = "0123456789012345678901234567890123456789";
char long_string3[4096];
for (size_t i = 0; i < sizeof(long_string3); ++i)
long_string3[i] = static_cast<char>('a' + (i % 26));
long_string3[sizeof(long_string3) - 1] = '\0';
auto value = TracedValue::Create();
value->SetString("a", "short");
value->SetString("b", long_string);
value->BeginArray("c");
value->AppendString(long_string2);
value->AppendString("");
value->BeginDictionary();
value->SetString("a", long_string3);
value->EndDictionary();
value->EndArray();
std::string json;
value->AppendAsTraceFormat(&json);
CHECK_EQ("{\"a\":\"short\",\"b\":\"" + long_string + "\",\"c\":[\"" +
long_string2 + "\",\"\",{\"a\":\"" + long_string3 + "\"}]}",
json);
}
TEST(Escaping) {
const char* string1 = "abc\"\'\\\\x\"y\'z\n\x09\x17";
std::string chars127;
for (int i = 1; i <= 127; ++i) {
chars127 += static_cast<char>(i);
}
auto value = TracedValue::Create();
value->SetString("a", string1);
value->SetString("b", chars127);
std::string json;
value->AppendAsTraceFormat(&json);
// Cannot use the expected value literal directly in CHECK_EQ
// as it fails to process the # character on Windows.
const char* expected =
R"({"a":"abc\"'\\\\x\"y'z\n\t\u0017","b":"\u0001\u0002\u0003\u0004\u0005)"
R"(\u0006\u0007\b\t\n\u000B\f\r\u000E\u000F\u0010\u0011\u0012\u0013)"
R"(\u0014\u0015\u0016\u0017\u0018\u0019\u001A\u001B\u001C\u001D\u001E)"
R"(\u001F !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ)"
R"([\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\u007F"})";
CHECK_EQ(expected, json);
}
TEST(Utf8) {
const char* string1 = "Люблю тебя, Петра творенье";
const char* string2 = "\u2600\u26FF";
auto value = TracedValue::Create();
value->SetString("a", string1);
value->SetString("b", string2);
// Surrogate pair test. Smile emoji === U+1F601 === \xf0\x9f\x98\x81
value->SetString("c", "\U0001F601");
std::string json;
value->AppendAsTraceFormat(&json);
const char* expected =
"{\"a\":\"\u041B\u044E\u0431\u043B\u044E \u0442\u0435\u0431\u044F, \u041F"
"\u0435\u0442\u0440\u0430 \u0442\u0432\u043E\u0440\u0435\u043D\u044C"
"\u0435\",\"b\":\"\u2600\u2600\u26FF\",\"c\":\"\xf0\x9f\x98\x81\"}";
CHECK_EQ(expected, json);
}