Open Bug 1385649 Opened 4 years ago Updated 4 years ago

JSVM code coverage generates invalid records

Categories

(Core :: JavaScript Engine, defect, P3)

defect

Tracking

()

Tracking Status
firefox57 --- wontfix

People

(Reporter: marco, Unassigned)

References

(Blocks 1 open bug)

Details

(Whiteboard: [js:tech-debt])

Attachments

(3 files)

I'm attaching an example lcov file generated on automation in a xpcshell test.

There's an invalid line ("DA:536"). DA lines should be in the format DA:LINE_NUMBER,HITS.

The line is the last line in the file.
Priority: -- → P3
Whiteboard: [js:tech-debt]
I've seen this again. I suppose the generation of the LCOV file was abruptly terminated for some reason.
Attachment #8940145 - Attachment mime type: application/x-info → text/plain
This has been happening more often lately. Nicolas, any idea what the cause might be?
Flags: needinfo?(nicolas.b.pierron)
I do not think this would be corrupted data.

One guess would be that we kill the parent/child process while shutting it down, and before it finishes writing the output of the code coverage, which ends the dumped content half ways in the output generation.
Flags: needinfo?(nicolas.b.pierron)
One way to test would be to add some flushing code after each write, and see if we can reproduce this issue.
And also adding some extra tag at the end to double check that we finished generating the code coverage output.
(In reply to Nicolas B. Pierron [:nbp] from comment #4)
> I do not think this would be corrupted data.
> 
> One guess would be that we kill the parent/child process while shutting it
> down, and before it finishes writing the output of the code coverage, which
> ends the dumped content half ways in the output generation.

I was thinking that too, but I think we are exiting the processes cleanly in debug builds (unless there's a shutdown hang, but in this case there wasn't): https://searchfox.org/mozilla-central/rev/d8ac097a1de2544f0e51d186bc850662c5b7430a/dom/ipc/ContentChild.cpp#2050.
What does the JS engine do on shutdown?

(In reply to Nicolas B. Pierron [:nbp] from comment #5)
> One way to test would be to add some flushing code after each write, and see
> if we can reproduce this issue.
> And also adding some extra tag at the end to double check that we finished
> generating the code coverage output.

There is `end_of_record` which is supposed to be at the end of every record but isn't present here.
(In reply to Marco Castelluccio [:marco] from comment #6)
> I was thinking that too, but I think we are exiting the processes cleanly in
> debug builds (unless there's a shutdown hang, but in this case there
> wasn't):
> https://searchfox.org/mozilla-central/rev/
> d8ac097a1de2544f0e51d186bc850662c5b7430a/dom/ipc/ContentChild.cpp#2050.
> What does the JS engine do on shutdown?

Unfortunately the JS engine is the last to be shutdown, as the JS engine is still used during the shutdown.  The CodeCoverage code is executed by destructor of the JSRuntime [0][1], so at the very end of the process.  We have to do so, because the CodeCoverage depends on the finalizers of the compartment and scripts to record all the code coverage information.

[0] https://searchfox.org/mozilla-central/source/js/src/vm/CodeCoverage.cpp#598,601,639,642
[1] https://searchfox.org/mozilla-central/source/js/src/vm/Runtime.h#241,600
(In reply to Nicolas B. Pierron [:nbp] from comment #7)
> (In reply to Marco Castelluccio [:marco] from comment #6)
> > I was thinking that too, but I think we are exiting the processes cleanly in
> > debug builds (unless there's a shutdown hang, but in this case there
> > wasn't):
> > https://searchfox.org/mozilla-central/rev/
> > d8ac097a1de2544f0e51d186bc850662c5b7430a/dom/ipc/ContentChild.cpp#2050.
> > What does the JS engine do on shutdown?
> 
> Unfortunately the JS engine is the last to be shutdown, as the JS engine is
> still used during the shutdown.  The CodeCoverage code is executed by
> destructor of the JSRuntime [0][1], so at the very end of the process.  We
> have to do so, because the CodeCoverage depends on the finalizers of the
> compartment and scripts to record all the code coverage information.
> 
> [0]
> https://searchfox.org/mozilla-central/source/js/src/vm/CodeCoverage.cpp#598,
> 601,639,642
> [1] https://searchfox.org/mozilla-central/source/js/src/vm/Runtime.h#241,600

OK, so I guess there's no way that the operations of the destructor terminate other than the process getting killed?
(In reply to Marco Castelluccio [:marco] from comment #8)
> OK, so I guess there's no way that the operations of the destructor
> terminate other than the process getting killed?

That would be my guess.
I've also seen invalid FN records, even though this seems to happen most of the time with DA records (maybe because they are the most common ones).

This is happening really often, we should investigate more.
Summary: JSVM code coverage generates invalid DA records (with line number but without hits) → JSVM code coverage generates invalid records
I've looked at two cases where this was wrong, Marionette Headless on Windows (on 632bb768b1dd4b96a196412e8f7b669ca09d6d91, https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=632bb768b1dd4b96a196412e8f7b669ca09d6d91&filter-searchStr=ccov&selectedJob=177462678) and Firefox UI Functional on Windows (on fb435df9797a471419670fe2d053432556959a9d, https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=fb435df9797a471419670fe2d053432556959a9d&filter-searchStr=ccov&selectedJob=177241603).
Both suites are Marionette-based.

In both cases, the wrong DA record was for the browser/base/content/content.js source file.

I'm attaching an archive containing the info files and the logs for those two jobs.
You need to log in before you can comment on or make changes to this bug.