Parallel processing throughput keeps decreasing

[aallrd]

Hello,

I am trying to use lcov to process a lot of coverage data from a big project.
The server I am using has 56 cores available, I am using --parallel 12 and I see 12 geninfo child processes running as expected.
I would expect constant files/s processing but I observe the reported throughput on the stdout going down as time passes, and the remaining time going up.

$ lcov --version
lcov: LCOV version 2.0-1
$ geninfo --version
geninfo: LCOV version 2.0-1
$ lcov \
  --parallel 12 \
  --test-name 639717 \
  --rc geninfo_unexecuted_blocks=1 \
  --output-file coverage.639717.info \
  --gcov-tool $(pwd)/gcov \
  --capture \
  --build-directory SOURCES \
  --directory COVERAGE/639717
Capturing coverage data from COVERAGE/639717
geninfo cmd: 'geninfo COVERAGE/639717 --output-filename coverage.639717.info --test-name 639717 --build-directory SOURCES --gcov-tool /opt/bin/gcov --rc geninfo_unexecuted_blocks=1 --parallel 12 --memory 0'
Found gcov version: 11.2.1
Using intermediate gcov format
Writing temporary data to /tmp/geninfo_datVndA
Scanning COVERAGE/639717 for .gcda files ...
Found 44782 data files in COVERAGE/639717
files remaining: 44582 (101.31 files/s - predict 7.33 minutes remaining)
files remaining: 44382 (74.21 files/s - predict 9.97 minutes remaining)
files remaining: 44182 (60.64 files/s - predict 12.14 minutes remaining)
files remaining: 43982 (53.95 files/s - predict 13.59 minutes remaining)
files remaining: 43782 (49.13 files/s - predict 14.85 minutes remaining)
files remaining: 43582 (45.17 files/s - predict 16.08 minutes remaining)
files remaining: 43382 (41.93 files/s - predict 17.24 minutes remaining)
[...]
files remaining: 39382 (15.89 files/s - predict 41.31 minutes remaining)
[...]

I am not seeing any resource issue / contention on the server.
Do you have an idea why the lcov throughput is going down?

Thank you.

[henry2cox]

One thing that is likely to be costing time is that you are using the "testname' feature.
This results in a constantly growing DB because the tool has to hold (unique) data for each testcase.
If you need to know what test hit which code: then you are kinda screwed - and just have to bite the bullet. You will see the master process size increase steadily - which may ultimately also limit parallelism.
If you don't need to keep track of individual test coverage and only want the aggregate, then the --forget-test-names feature might help you.

The other thing you probably want to do is to add --profile to your command line, then take a look at the performance spreadsheet to see if lcov/geninfo is doing anything that is obviously stupid.

[henry2cox]

Incidentally: if you have 56 cores - you might want to use --parallel 0 (to let the tool decide how many cores to use) and --memory someReasonableBound (to give it hints about how to throttle to avoid thrashing). That might help to go faster.
We see near linear performance improvement up to close to the number of available cores. YMMV - especially if you get into thrashing range.

[aallrd]

I removed --test-name and added --forget-test-names, the throughput was still going down.
It seems I cannot set a memory value, is the below command valid?

$ lcov \
  --parallel 0 \
  --memory 2000 \
  --forget-test-names \
  --rc geninfo_unexecuted_blocks=1 \
  --output-file coverage.639717.info \
  --gcov-tool $(pwd)/gcov \
  --capture \
  --build-directory SOURCES \
  --directory COVERAGE/639717
Capturing coverage data from COVERAGE/639717
geninfo cmd: 'geninfo COVERAGE/639717 --output-filename coverage.639717.info --build-directory SOURCES --gcov-tool /opt/bin/gcov --rc geninfo_unexecuted_blocks=1 --parallel 0 --memory 0.0019073486328125'
geninfo: WARNING: Value "0.0019073486328125" invalid for option memory (number expected)
Use geninfo --help to get usage information

[henry2cox]

Damn. Yes - your command is correct..but you hit a bug in my code :-(

In the process of fixing.
In the meantime, the workaround is to multiply the limit you actually want by 2^20.

Sigh.
He who makes no mistakes, makes nothing at all.

I'm also a bit skeptical that dropping test names is going to help...that issue is mostly about aggregation, not capture.
Could be something else in the code. Unfortunately, there is not a lot of debug/diagnostic print in this area to help us debug. Almost have to wait for process to complete and look at shrapnel. When this happens internally: I just run stuff in the debugger to see what is happening.
Can you monitor process size of the master and of the slaves? Will help to know if they are roughly constant size or increasing, and if their total CPU usage is roughly constant or increasing. (Profile will tell us that...but not until the end.)

[aallrd]

I have reduced the number of files to be able to reach the end of the process.
I tried your workaround for the memory and managed to set it to 4000M, but the throughput is worse and still decreasing:

$ lcov \
  --parallel 0 \
  --memory 4194304000 \
  --forget-test-names \
  --rc geninfo_unexecuted_blocks=1 \
  --output-file coverage.639717.info \
  --gcov-tool /opt/bin/gcov \
  --capture \
  --build-directory SOURCES \
  --directory COVERAGE/639717
Capturing coverage data from COVERAGE/639717
geninfo cmd: 'geninfo COVERAGE/639717 --output-filename coverage.639717.info --build-directory SOURCES --gcov-tool /opt/bin/gcov --rc geninfo_unexecuted_blocks=1 --parallel 0 --memory 4000'
Found gcov version: 11.2.1
Using intermediate gcov format
Writing temporary data to /tmp/geninfo_datAs4M
Scanning COVERAGE/639717 for .gcda files ...
Found 2894 data files in COVERAGE/639717
files remaining: 2694 (20.38 files/s - predict 2.20 minutes remaining)
files remaining: 2494 (9.35 files/s - predict 4.45 minutes remaining)
files remaining: 2294 (9.63 files/s - predict 3.97 minutes remaining)
files remaining: 2094 (9.29 files/s - predict 3.76 minutes remaining)
files remaining: 1894 (8.72 files/s - predict 3.62 minutes remaining)
files remaining: 1694 (8.12 files/s - predict 3.48 minutes remaining)
files remaining: 1494 (7.54 files/s - predict 3.30 minutes remaining)
[...]

I am trying to get the profile you requested but it seems I have an issue of my own with source paths and the process fails with an error preventing I guess the report from being generated:

$ lcov \
  --parallel 0 \
  --profile profile.json \
  --forget-test-names \
  --rc geninfo_unexecuted_blocks=1 \
  --output-file coverage.639717.info \
  --gcov-tool /opt/bin/gcov \
  --capture \
  --build-directory SOURCES  \
  --directory COVERAGE/639717
Capturing coverage data from COVERAGE/639717
geninfo cmd: 'geninfo COVERAGE/639717 --output-filename coverage.639717.info --build-directory SOURCES --gcov-tool /opt/bin/gcov --rc geninfo_unexecuted_blocks=1 --profile profile.json --parallel 0 --memory 0'
Found gcov version: 11.2.1
Using intermediate gcov format
Writing temporary data to /tmp/geninfo_datTx2r
Scanning COVERAGE/639717 for .gcda files ...
Found 2894 data files in COVERAGE/639717
files remaining: 2694 (127.46 files/s - predict 0.35 minutes remaining)
files remaining: 2494 (110.98 files/s - predict 0.37 minutes remaining)
files remaining: 2294 (90.99 files/s - predict 0.42 minutes remaining)
files remaining: 2094 (80.45 files/s - predict 0.43 minutes remaining)
files remaining: 1894 (72.26 files/s - predict 0.44 minutes remaining)
files remaining: 1694 (67.84 files/s - predict 0.42 minutes remaining)
files remaining: 1494 (64.25 files/s - predict 0.39 minutes remaining)
files remaining: 1294 (61.36 files/s - predict 0.35 minutes remaining)
files remaining: 1094 (55.86 files/s - predict 0.33 minutes remaining)
files remaining: 894 (53.68 files/s - predict 0.28 minutes remaining)
files remaining: 694 (50.69 files/s - predict 0.23 minutes remaining)
files remaining: 494 (48.71 files/s - predict 0.17 minutes remaining)
files remaining: 294 (46.41 files/s - predict 0.11 minutes remaining)
files remaining: 94 (44.53 files/s - predict 0.04 minutes remaining)
geninfo: ERROR: geninfo: ERROR: geninfo: ERROR: geninfo: ERROR: unable to open /proc/self/cwd/cpp/source.cpp: No such file or directory
        (use "geninfo --ignore-errors source ..." to bypass this error)

What can I do to remove/replace the prefix /proc/self/cwd from the source file path? I have seen a --substitute REGEXP option but I don't know how to use it, or if it would be useful.

The resulting profile.json content from the above failing command just in case:

{
  "config": {
    "uname": "Linux foo 4.18.0-372.9.1.el8.x86_64 #1 SMP Fri Apr 15 22:12:19 EDT 2022 x86_64 x86_64 x86_64 GNU/Linux",
    "tool_dir": "/usr/bin",
    "bin": "/usr/bin",
    "date": "Wed Jul 12 17:55:19 CEST 2023",
    "version": "LCOV version 2.0-1",
    "cmdLine": "geninfo COVERAGE/639717 --output-filename coverage.639717.info --build-directory SOURCES --gcov-tool /opt/bin/gcov --rc geninfo_unexecuted_blocks=1 --substitute /proc/self/cwd --profile profile.json --parallel 0 --memory 0",
    "cores": 56,
    "maxParallel": 56,
    "tool": "geninfo",
    "url": "https://github.com//linux-test-project/lcov"
  },
  "total": 0.0400650501251221,
  "find": {
    "COVERAGE/639717": 0.0244309902191162
  },
  "gen_info": {
    "COVERAGE/639717": 0.0268959999084473
  }
}

[henry2cox]

You can add --keep-going to the command line - so that the tool will ignore all the issues that it can (you may still hit a fatal error that cannot be overlooked).

You are correct WRT pathname munging.
If the paths that got encoded into your coverage data (during build) are not what you want/need - then you can use --substitute regexp to change them (see the man page for examples - but it is basically Perl syntax regexps). Fundamentally, this is no different than just running sed on the data after you generated it. However, if the tool is looking for source code so that it can do some filtering, then you either need to use --substitute (so the paths are correct and the sources can be found) or to skip filtering in this step and do it later (after sed).

Profile looks wrong/truncated - probably due to the error that was not skipped.

[henry2cox]

Fix for the --memory issue in fe6cbb8
(Performance issue - if any - is not resolved.)

[aallrd]

I manages to get the profile.json:

$ lcov \
  --parallel 0 \
  --profile profile.json \
  --capture \
  --gcov-tool $(which gcov) \
  --forget-test-names \
  --rc geninfo_unexecuted_blocks=1 \
  --output-file coverage.639717.info \
  --build-directory SOURCES   \
  --directory COVERAGE/639717   \
  --substitute 's#/proc/self/cwd/#SOURCES/#g' \
  --exclude '/opt/*' \
  --exclude '/usr/*' \
  --keep-going
Found gcov version: 11.2.1
Using intermediate gcov format
Writing temporary data to /tmp/geninfo_datcWmu
Scanning COVERAGE/639717 for .gcda files ...
Found 2894 data files in COVERAGE/639717
files remaining: 2694 (197.62 files/s - predict 0.23 minutes remaining)
files remaining: 2494 (169.77 files/s - predict 0.24 minutes remaining)
files remaining: 2294 (140.87 files/s - predict 0.27 minutes remaining)
files remaining: 2094 (123.27 files/s - predict 0.28 minutes remaining)
files remaining: 1894 (116.29 files/s - predict 0.27 minutes remaining)
files remaining: 1694 (92.70 files/s - predict 0.30 minutes remaining)
files remaining: 1494 (87.59 files/s - predict 0.28 minutes remaining)
files remaining: 1294 (82.76 files/s - predict 0.26 minutes remaining)
files remaining: 1094 (75.72 files/s - predict 0.24 minutes remaining)
files remaining: 894 (70.73 files/s - predict 0.21 minutes remaining)
files remaining: 694 (65.40 files/s - predict 0.18 minutes remaining)
files remaining: 494 (62.14 files/s - predict 0.13 minutes remaining)
files remaining: 294 (58.00 files/s - predict 0.08 minutes remaining)
files remaining: 94 (53.88 files/s - predict 0.03 minutes remaining)
Excluded data for 118 files due to include/exclude options
geninfo: WARNING: Error: unknown line '70' in SOURCES/lib/awesome/file.cpp: there are only 68 lines in file.
Finished .info-file creation

The profile is a really big file with many keys, do you have hints at what I should look at first?

$ jq keys < profile.json
[
  "append",
  "child",
  "config",
  "data",
  "emit",
  "exec",
  "find",
  "gen_info",
  "merge",
  "parse",
  "process",
  "total",
  "undump"
]

[henry2cox]

One possibility (that may not be doable, depending on your company policies) - is to mail me a compressed version of the file.
It isn't too hard to deduce a good address.

The other thing to do if you have not already is to generate a spreadsheet so you can see some basic statistics:
$LCOV_HOME/share/lcov/support-scripts/spreadsheet.py -o foo.xlsx profile.json

One of the basic questions is whether the distribution of CPU times and memory is relatively uniform or if there are substantial outliers - then to figure out why the outliers exist.
Another basic question is whether some particular step is taking more time or memory than we expect.

Have you been able to extract from your full set of files..and how long did that take (wall clock) compared to this subset?
Are there any unusual features of that data that we don't see in the smaller subset?

You may already be doing it, but for large examples, we typically fragment two ways: split into N subsets and send each of those to the compute farm - then aggregate the result at the end.
One particular job went from about 17 hours to just under 20 minutes (combination of tricks + at least one or two bug fixes).
YMMV.

[aallrd]

I have managed to "anonymize" the reports so I can attach them here: anonymized-reports.tar.gz
These files are from the above subset run on 2894 files, where we can already see the throughput decreasing over time.
I'll try to get the same reports with with our target 44782 files during the night, and measure how long it takes.

If I understood your trick, it would mean:

• splitting my directory COVERAGE/639717 containing all the gcda files into several directories COVERAGE/639717-X
• run as many lcov capture commands as X with --build-directory SOURCES --directory COVERAGE/639717-X
• run as many lcov add-tracefile commands as X on the collection of coverage.639717.X.infofiles

Does that sound right?

[henry2cox]

Right - except that the last step is to run lcov --add once, to merge all the .info files generated in step 2.
(You can use glob matching for this...one of the reasons that that option exists.)

The spreadsheet seems to indicate that it took about 80s wall clock time to process about 2900 files.
Observed parallelism speedup was ~27 on your 56-core machine. You didn't enable memory throttling (just an observation - I have no reason to think that enabling or disabling would have any effect).
It takes 1.1s to for a slave to process 1 file on average; stddev is 0.65 (so pretty high - not sure why)
Does this look correct?

I don't collect timestamps - so I can't easily see whether performance degrades as we go along.
(But I do have a small patch which emits a bit more information in the interval callback, which might help.)

[aallrd]

The full run on 44782 files was not able to complete and seems stuck, it is still "running" after ~12h.

$ date
Thu Jul 13 20:55:02 CEST 2023
$ lcov [...] &
Capturing coverage data from COVERAGE/639717
geninfo cmd: 'geninfo COVERAGE/639717 --output-filename coverage.639717.info --build-directory SOURCES --gcov-tool /opt/bin/gcov --keep-going --rc geninfo_unexecuted_blocks=1 --exclude /opt/* --exclude /usr/* --substitute s#/proc/self/cwd/#SOURCES/#g --profile profile.json --parallel 0 --memory 0'
Found gcov version: 11.2.1
Using intermediate gcov format
Writing temporary data to /tmp/geninfo_dat6s1X
Scanning COVERAGE/639717 for .gcda files ...
Found 44782 data files in COVERAGE/639717
files remaining: 44582 (127.36 files/s - predict 5.83 minutes remaining)
files remaining: 44382 (114.02 files/s - predict 6.49 minutes remaining)
[...]
files remaining: 3782 (0.99 files/s - predict 63.66 minutes remaining)
files remaining: 3582 (0.99 files/s - predict 60.18 minutes remaining)
files remaining: 3382 (0.99 files/s - predict 56.71 minutes remaining)
files remaining: 3182 (0.99 files/s - predict 53.33 minutes remaining)
$ date
Fri Jul 14 09:17:34 CEST 2023

The top output shows:

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
466502 foo       20   0    0.1g   0.0g   0.0g S   0.0   0.0   0:00.42 lcov
466534 foo       20   0    3.3g   0.4g   0.0g S   0.0   0.1 145:09.77 geninfo
188253 foo       20   0    3.3g   2.6g   0.0g D   2.3   0.7   0:25.43 geninfo
188419 foo       20   0    3.3g   2.6g   0.0g D   2.6   0.7   0:25.37 geninfo
188456 foo       20   0    3.3g   2.6g   0.0g D   2.3   0.7   0:25.31 geninfo
[+ ~50 others]

In the beginning of the run the geninfo processes used to take ~400MB in RES memory before completing in a few seconds, as time passes they seem to take longer and consume way more memory.
Also, the X geninfo processes seem to be called with the same args as the lcov command, is that expected for these processing commands?

UID         PID   PPID  C STIME TTY          TIME CMD
foo      306717 466534  3 09:27 ?        00:00:00 geninfo COVERAGE/639717 --output-filename coverage.639717.info --build-directory SOURCES --gcov-tool /opt/bin/gcov --keep-going --rc geninfo_unexecuted_blocks=1 --exclude /opt/* --exclude /usr/* --substitute s#/proc/self/cwd/#SOURCES/#g --profile profile.json --parallel 0 --memory 0

The server activity seems okay, I cannot see any contention on I/O, CPU or memory.

I'll try to split in batches as you suggested to see if I can get it to complete.

I was not expecting this coverage processing operation to be so long and resource greedy, but I have no reference.
Would it be possible for you to share data from jobs that you have seen successfully processed, like number of files / elapsed time / resources ?
I would like to get an idea if I can expect this to complete in a few minutes or if hours will always be required.

[henry2cox]

Your data is somewhat unexpected - but I am not sure if it is a bug or just a large data set.
Execution seems rather different than other projects that I'm familiar with. In particular, the small experiment you ran yesterday appeared to process 4K files in about 1.5 minutes.
Naively, I would expect to see your 40K files take about 15 minutes - and specifically, the remaining 3K files we see in your list above to also take about another minute - but that is not what what we observe.

Would be good to understand why this happens - and to fix it, if it is a bug.

Not sure whether it matters or not but:

• how many source files in your project/how many compilation units? This will be the same as the number of .gcno files.
• do we have 40K .gcda files because you have (say) 10 individual data sets, each containing data for 4K compilation units? Or are there really 40K compilation units and only one test suite/one set of merged runtime coverage data?
• you are using gcc 11
• there is nothing particularly strange or funky about your project/your code - as far as we know.

It is possible that the number of compilation units is affecting performance - but I am not entirely sure why that would be.
I have a speculation :-) - but I would rather not look foolish until we have more data.

I just re-ran an experiment to extract coverage data from the LLVM source code (llvm 11 + some local changes).
I don't have data for any of the larger projects at hand - and probably could not share, even if I did (sorry).

• 2058 files
• 22 core/32Gb linux VM
• 180.79s total time (start to finish).
  (Ran it about 5 minutes ago and got 155.21s; in this case, I attribute the difference to inconsistent notwork and filesystem performance).
• average time per file: 1.98s, stddev 0.81
• effective parallelism: 14.29 (saw 16.11 in the other attempt)

Found LLVM gcov version 11.0.0, which emulates gcov version 4.2.0
Using intermediate gcov format
Writing temporary data to /tmp/geninfo_datU75C
Scanning . for .gcda files ...
Found 2058 data files in .
files:1838 elapsed:0.1m predict 0.7m to go: 44.99 files/s 0.12 s/file (interval:44.99 f/s 0.12 s/f)
files:1618 elapsed:0.3m predict 1.1m to go: 24.89 files/s 0.29 s/file (interval:17.20 f/s 0.46 s/f)
files:1398 elapsed:0.6m predict 1.2m to go: 19.22 files/s 0.47 s/file (interval:13.20 f/s 0.84 s/f)
files:1178 elapsed:0.9m predict 1.2m to go: 16.10 files/s 0.68 s/file (interval:10.84 f/s 1.29 s/f)
files:958 elapsed:1.3m predict 1.1m to go: 14.54 files/s 0.90 s/file (interval:10.47 f/s 1.79 s/f)
files:738 elapsed:1.7m predict 0.9m to go: 13.26 files/s 1.09 s/file (interval:9.22 f/s 2.07 s/f)
files:518 elapsed:2.1m predict 0.7m to go: 12.20 files/s 1.26 s/file (interval:8.22 f/s 2.29 s/f)
Finished .info-file creation

Predicted completion time is computed from throughput seen to date. Also printing throughput seen in each print interval so that we can see whether it changing. Interval length is now set such that each thread is expected to process ~10 files. The above data shows the performance degrading - but the earlier one did not (and the last 2 intervals were actually slightly faster than any of the others).

There are some more experiments and some additional things we can do to try to figure out what is happening with your job.
You may or may not want to share that data, though - and you may or may not want to contact (more) privately.

[aallrd]

Here are some details about the files I am trying to process.
I have a SOURCES folder containing the source code of the application and the associated gcno files:

SOURCES/lib/awesome/file.cpp
SOURCES/output/lib/awesome/o/awesome/file.gcno

When executing my application, the folder COVERAGE/<PID> is created containing the gcda files:

COVERAGE/<PID>/output/lib/awesome/o/awesome/file.gcda

In both these folders there are:

• C++ source files: 172021
• gcno files: 52372
• gcda files: 44782

All these gcda files were generated from a single execution of the application (single <PID> folder) with dummy args (like calling --version).

The full lcov run started yesterday was finally able to complete in ~15h, the final full.coverage.info file is 423MB.
I am attaching the reports here: anonymized-full-reports.tar.gz.

I took up your suggestion and divided the COVERAGE/<PID> directory into N COVERAGE/<PID>-N folders of 2000 files each.
I ran the same lcov command as before, sequentially on each of these directories, the full run completed in ~13min.
Merging the files took then 3min and the resulting merged.coverage.info file is 422MB.

  add=()
  for f in output/coverage.*.info; do
    add+=(--add "${f}")
  done
  lcov --output-file merged.coverage.info --ignore-errors format ${add[@]}

So it seems to match exactly what you described in #228 (comment).
I guess it means there is some kind of issue in lcov with handling a lot of files in a single run.

[henry2cox]

Quick clarification:

• when you fragment into ~20 chunks of 2000 elements each, did you process them sequentially (on one host) is 13 minutes total, OR
• did you send the fragments off to N machines in the compute farm (to execute in parallel) - and got a result back in 13 minutes?

If the former case is what you observe, then it should be straightforward for the tool to fragment in exactly the same way - and improve performance quite markedly.
If the latter: then an external script to dispatch to the farm is needed.

Either way: this does look like a bug that I am not entirely sure how to diagnose or fix.
I would expect monolithic and fragmented sequential performance to be rather similar to each other.

When you get further down the road, I am curious what you see WRT coverage categorization, binning, etc. - but I suspect that you cannot tell me.
I doubt that a single HTML report for 170K files is going to be terribly useful or usable, though.
Presumably, the project consists of multiple subsystems and modules such that a split report for each of the various teams would be what is desired.

As an aside: if you name the output files to end in .gz ("anonomized-full.info.gz") - then the data will be compressed.
That probably doesn't actually save you anything as your FS is likely compressed and de-duped (but 'quota' seems to look at the claimed size - not the actual storage).
Similarly, the HTML results can also be compressed - but as mentioned above, I doubt that those will be useful in any case.