1385649 - JSVM code coverage generates invalid records

Status: NEW

(Core :: JavaScript Engine, defect, P3)

Description

[Marco Castelluccio [:marco]]

Attachment: 1501085318-10518-0.info.bz2

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.

Comment 1

[Marco Castelluccio [:marco]]

I've seen this again. I suppose the generation of the LCOV file was abruptly terminated for some reason.

Comment 2

[Marco Castelluccio [:marco]]

Attachment: 1515063181-10551-0.info

This file is coming from https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=f78a83244fbebe8a469ae3512fce7f638cab7e1f&selectedJob=154075259.

The last two lines of the file are:
> DA:5899,1
> DA:590

Comment 3

[Marco Castelluccio [:marco]]

This has been happening more often lately. Nicolas, any idea what the cause might be?

Comment 4

[Nicolas B. Pierron [:nbp | PTO until 11/11]]

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.

Comment 5

[Nicolas B. Pierron [:nbp | PTO until 11/11]]

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.

Comment 6

[Marco Castelluccio [:marco]]

(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.

Comment 7

[Nicolas B. Pierron [:nbp | PTO until 11/11]]

(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

Comment 8

[Marco Castelluccio [:marco]]

(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?

Comment 9

[Nicolas B. Pierron [:nbp | PTO until 11/11]]

(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.

Comment 10

[Marco Castelluccio [:marco]]

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.

Comment 11

[Marco Castelluccio [:marco]]

Attachment: test_logs_and_lcov_files.tar.xz

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.