Something wrong with coverage stats recently?

[Trott]

On or around April 9, coverage.nodejs.org shows coverage plummeting on both JS and C++. Seems like some kind of problem was introduced into the coverage job? codecov.io results seem fine, in comparison.

[richardlau]

If it was due to a code change it was between these commits: 6ed912d...c849f2d

[richardlau]

https://ci.nodejs.org/job/node-test-commit-linux-coverage-daily/486/nodes=benchmark/console is the job that generated coverage for c849f2d.

https://codecov.io/github/nodejs/node/commit/c849f2d4f8ff19c830b6a97bd6978bf41f878e8b is the codecov.io that was uploaded from that job. The discrepency is certainly odd.

[richardlau]

Looks like the cctest is crashing in https://ci.nodejs.org/job/node-test-commit-linux-coverage-daily/486/nodes=benchmark/consoleFull which means the js tests aren't being run:

23:07:21 [----------] 6 tests from BaseObjectPtrTest
23:07:21 [ RUN      ] BaseObjectPtrTest.ScopedDetached
23:07:21 Segmentation fault
23:07:21 make[2]: *** [cctest] Error 139
23:07:21 make[2]: Leaving directory `/home/iojs/build/workspace/node-test-commit-linux-coverage-daily/nodes/benchmark'
23:07:21 make[1]: *** [test-cov] Error 2
23:07:21 make[1]: Leaving directory `/home/iojs/build/workspace/node-test-commit-linux-coverage-daily/nodes/benchmark'
23:07:21 make: [coverage-test] Error 2 (ignored)
23:07:21 make coverage-report-js

[richardlau]

Crashes when NODE_V8_COVERAGE is set. Here's a stack trace for the crash with a Debug build:

-bash-4.2$ NODE_V8_COVERAGE=out/Release/.coverage out/Debug/cctest
Running main() from ../test/cctest/gtest/gtest_main.cc
[==========] Running 104 tests from 16 test suites.
[----------] Global test environment set-up.
[----------] 14 tests from AliasBufferTest
[ RUN      ] AliasBufferTest.Uint8Array
[       OK ] AliasBufferTest.Uint8Array (76 ms)
[ RUN      ] AliasBufferTest.Int8Array
[       OK ] AliasBufferTest.Int8Array (71 ms)
[ RUN      ] AliasBufferTest.Uint16Array
[       OK ] AliasBufferTest.Uint16Array (72 ms)
[ RUN      ] AliasBufferTest.Int16Array
[       OK ] AliasBufferTest.Int16Array (72 ms)
[ RUN      ] AliasBufferTest.Uint32Array
[       OK ] AliasBufferTest.Uint32Array (72 ms)
[ RUN      ] AliasBufferTest.Int32Array
[       OK ] AliasBufferTest.Int32Array (71 ms)
[ RUN      ] AliasBufferTest.Float32Array
[       OK ] AliasBufferTest.Float32Array (72 ms)
[ RUN      ] AliasBufferTest.Float64Array
[       OK ] AliasBufferTest.Float64Array (71 ms)
[ RUN      ] AliasBufferTest.SharedArrayBuffer1
[       OK ] AliasBufferTest.SharedArrayBuffer1 (72 ms)
[ RUN      ] AliasBufferTest.SharedArrayBuffer2
[       OK ] AliasBufferTest.SharedArrayBuffer2 (71 ms)
[ RUN      ] AliasBufferTest.SharedArrayBuffer3
[       OK ] AliasBufferTest.SharedArrayBuffer3 (71 ms)
[ RUN      ] AliasBufferTest.SharedArrayBuffer4
[       OK ] AliasBufferTest.SharedArrayBuffer4 (72 ms)
[ RUN      ] AliasBufferTest.OperatorOverloads
[       OK ] AliasBufferTest.OperatorOverloads (71 ms)
[ RUN      ] AliasBufferTest.OperatorOverloadsRefs
[       OK ] AliasBufferTest.OperatorOverloadsRefs (71 ms)
[----------] 14 tests from AliasBufferTest (1005 ms total)

[----------] 2 tests from Base64Test
[ RUN      ] Base64Test.Encode
[       OK ] Base64Test.Encode (0 ms)
[ RUN      ] Base64Test.Decode
[       OK ] Base64Test.Decode (0 ms)
[----------] 2 tests from Base64Test (0 ms total)

[----------] 6 tests from BaseObjectPtrTest
[ RUN      ] BaseObjectPtrTest.ScopedDetached


#
# Fatal error in ../deps/v8/src/api/api-inl.h, line 129
# Debug check failed: allow_empty_handle || that != nullptr.
#
#
#
#FailureMessage Object: 0x7ffc56581e20
 1: 0x17e946c node::DumpBacktrace(_IO_FILE*) [out/Debug/cctest]
 2: 0x1a41b3b  [out/Debug/cctest]
 3: 0x1a41b91  [out/Debug/cctest]
 4: 0x2bb7f78 V8_Fatal(char const*, int, char const*, ...) [out/Debug/cctest]
 5: 0x2bb7fa3  [out/Debug/cctest]
 6: 0x20a9014  [out/Debug/cctest]
 7: 0x20c4259 v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) [out/Debug/cctest]
 8: 0x1bae294 node::profiler::V8CoverageConnection::WriteProfile(v8::Local<v8::String>) [out/Debug/cctest]
 9: 0x1bacfd2 node::profiler::V8ProfilerConnection::V8ProfilerSessionDelegate::SendMessageToFrontend(v8_inspector::StringView const&) [out/Debug/cctest]
10: 0x1b7cab8  [out/Debug/cctest]
11: 0x1b7c99c  [out/Debug/cctest]
12: 0x26e5015 v8_inspector::V8InspectorSessionImpl::sendProtocolResponse(int, std::unique_ptr<v8_crdtp::Serializable, std::default_delete<v8_crdtp::Serializable> >) [out/Debug/cctest]
13: 0x277435e v8_inspector::protocol::DispatcherBase::sendResponse(int, v8_inspector::protocol::DispatchResponse const&, std::unique_ptr<v8_inspector::protocol::DictionaryValue, std::default_delete<v8_inspector::protocol::DictionaryValue> >) [out/Debug/cctest]
14: 0x27a375c v8_inspector::protocol::Profiler::DispatcherImpl::takePreciseCoverage(int, v8_inspector::String16 const&, v8_crdtp::span<unsigned char>, std::unique_ptr<v8_inspector::protocol::DictionaryValue, std::default_delete<v8_inspector::protocol::DictionaryValue> >, v8_inspector::protocol::ErrorSupport*) [out/Debug/cctest]
15: 0x27a93d9 v8_inspector::protocol::Profiler::DispatcherImpl::dispatch(int, v8_inspector::String16 const&, v8_crdtp::span<unsigned char>, std::unique_ptr<v8_inspector::protocol::DictionaryValue, std::default_delete<v8_inspector::protocol::DictionaryValue> >) [out/Debug/cctest]
16: 0x27761d6 v8_inspector::protocol::UberDispatcher::dispatch(int, v8_inspector::String16 const&, std::unique_ptr<v8_inspector::protocol::Value, std::default_delete<v8_inspector::protocol::Value> >, v8_crdtp::span<unsigned char>) [out/Debug/cctest]
17: 0x26e414d v8_inspector::V8InspectorSessionImpl::dispatchProtocolMessage(v8_inspector::StringView const&) [out/Debug/cctest]
18: 0x1b7c5e5  [out/Debug/cctest]
19: 0x1b8cfd1 node::inspector::NodeInspectorClient::dispatchMessageFromFrontend(int, v8_inspector::StringView const&) [out/Debug/cctest]
20: 0x1b80a67  [out/Debug/cctest]
21: 0x1bac8f5 node::profiler::V8ProfilerConnection::DispatchMessage(char const*, char const*) [out/Debug/cctest]
22: 0x1baebba node::profiler::V8CoverageConnection::End() [out/Debug/cctest]
23: 0x1bafe10  [out/Debug/cctest]
24: 0x1bafffa  [out/Debug/cctest]
25: 0x1bb003e  [out/Debug/cctest]
26: 0x181f411 node::Environment::RunAtExitCallbacks() [out/Debug/cctest]
27: 0x17b0b98 node::RunAtExit(node::Environment*) [out/Debug/cctest]
28: 0x179ec6b node::FreeEnvironment(node::Environment*) [out/Debug/cctest]
29: 0x17074fe EnvironmentTestFixture::Env::~Env() [out/Debug/cctest]
30: 0x1700ced BaseObjectPtrTest_ScopedDetached_Test::TestBody() [out/Debug/cctest]
31: 0x16be7e4 void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) [out/Debug/cctest]
32: 0x16b3805 void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) [out/Debug/cctest]
33: 0x167b2bd testing::Test::Run() [out/Debug/cctest]
34: 0x167c156 testing::TestInfo::Run() [out/Debug/cctest]
35: 0x167ccb7 testing::TestSuite::Run() [out/Debug/cctest]
36: 0x168ecea testing::internal::UnitTestImpl::RunAllTests() [out/Debug/cctest]
37: 0x16c0012 bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) [out/Debug/cctest]
38: 0x16b4e48 bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) [out/Debug/cctest]
39: 0x168c9a0 testing::UnitTest::Run() [out/Debug/cctest]
40: 0x16daa0d RUN_ALL_TESTS() [out/Debug/cctest]
41: 0x16da8dc main [out/Debug/cctest]
42: 0x7f793e153545 __libc_start_main [/lib64/libc.so.6]
43: 0xe492d5  [out/Debug/cctest]
Illegal instruction (core dumped)
-bash-4.2$

[richardlau]

If it was due to a code change it was between these commits: 6ed912d...c849f2d

Looking at the commits in that range, the most likely suspect is 8aa7ef7 (#32672), particularly as the inspector is showing up in the stack frames of the back trace where the crash occurred. I've run the coverage job (in non-publish mode) against a branch with 8aa7ef7 reverted and it looks to have avoided the crash and is back to the coverage numbers we're used to:

https://ci.nodejs.org/job/node-test-commit-linux-coverage-daily/499/nodes=benchmark/console

13:44:10 Gathered coveraged data for 209 files
13:44:10 Javascript coverage %: 96.91%
13:44:10 C++ coverage %: 89.5%

cc @addaleax

[joyeecheung]

It seems the true cause was 5bf4372 which changes it to EndStartedProfilers() at exit unconditionally (which relies on callbacks setup in pre-execution), instead of only in places where there is a fully-baked Environment. It happened to be fine until 8aa7ef7 since before that we always only call StartProfilers in Environments that will be fully baked, but 8aa7ef7 made the half-baked Environments used in the cctest hit this bug. (i.e. when LoadEnvironment() is not called to set up the source map cache getter at pre-execution)

[joyeecheung]

There should be multiple way to fix this

• Make the profile serialization return early from pre-execution (makes sense because environment variables are only processed at pre-execution, well in JS anyway) and ignore the commands to write the profiles
• Move the source map caching stuff into C++ so they'll always be functional, even in half-baked Environments,. This kind of diagnostics runtime states in C++ usually doesn't matter in snapshots so keeping them out of the JS world should be OK (what V8 does is to just discard debugger states in snapshot and always start from scratch anyway)
• Somehow make sure that we only start the profilers when we are sure that the Environment will be fully baked. I am not sure how that's possible if we want to have --inspect-brk-node for half-baked Environments (for snapshots)

[joyeecheung]

Upon further inspection, simply give up for those half-baked Environments should make more sense - porting the coverage serialization in C++ might not be worth it, considering we'll always need to reach into the JS land to compute source maps for user modules.

This should at least fix the issue for cctests, I am verifying if there are other places where this mismatch could lead to issues. This does mean that we won't have JS coverage data from code run in most cctests (that don't do pre-execution), but I guess that's fine.

diff --git a/src/inspector_profiler.cc b/src/inspector_profiler.cc
index cc4c309175..03cf2f6e5c 100644
--- a/src/inspector_profiler.cc
+++ b/src/inspector_profiler.cc
@@ -209,6 +209,16 @@ void V8CoverageConnection::WriteProfile(Local<String> message) {
   HandleScope handle_scope(isolate);
   Context::Scope context_scope(context);

+  // This is only set up during pre-execution (when the environment variables
+  // becomes available in the JS land). If it's empty, we don't have coverage
+  // directory path (which is resolved in JS land at the moment) either, so
+  // the best we could to is to just discard the profile and do nothing.
+  // This should only happen in half-baked Environments created using the
+  // embedder API.
+  if (env_->source_map_cache_getter().IsEmpty()) {
+    return;
+  }
+
   // Get message.result from the response.
   Local<Object> result;
   if (!ParseProfile(env_, message, type()).ToLocal(&result)) {

[joyeecheung]

Hm, another part of the cause was #31910 - before that we always run pre-execution for CreateEnvironment(), so another possible fix would be to implement what I suggested in #31910 (comment) and introduce a separate step to fully bootstrap the environment (maybe an internal API would already suffice), then we will still have JS coverage from cctest. This would also re-enable that cctest being commented out in #31910

[joyeecheung]

Fix in #32960 JS coverage got back to 96.58% locally. C++ coverage doesn't work on my machine anyway.