Fix #15009: ErrorLogger::readCode: cache code so we don't have to re-read files

[ludviggunne]

This edit introduces the following changes:

• Add a sourceLineCallback parameter to ErrorMessage::toString, which is used for expanding the {code} part of the error template. If sourceLineCallback is nullptr, {code} is expanded to an empty string and no read is performed. This happens in the case of suppressed errors or xml output for example, and replaces the use of the noCode parameter from c976cac. The default value for this parameter is ErrorMessage::directSourceLineCallback, which does what the function readCode did originally, i.e. just opens and reads the file with no caching.

• Add a mSourceCache member to ErrorLogger. This keeps file streams open for reuse to avoid repeatedly opening the same file for each error. The cache has multiple entries since an error path may refer to multiple files. To limit the number of streams open at the same time, an entry is evicted when the size meets ErrorLogger::mSourceCacheSize. To avoid evicting the primary source file (where the error originates), the entries are sorted by priority, where the primary source file has priority 0 and the files referred to in the error path have decreasing priority starting with -1. ErrorLogger::sourceFileCallback does a lookup in the cache before constructing the error context and is passed to ErrorMessage::toString. The priority for all entries is decremented on each lookup so that entries that haven't been used for a while are evicted.

[ludviggunne]

Will add benchmarks and more tests.

[danmar]

I believe this approach still leads to multiple file-opens. the warnings often jump up and down in the file. i.e. when there are more than one location, more than 1 type of warning, ...
it seems to me it will help a lot for the case when there is a noisy warning that generates 1000 warnings with growing linenumbers..

Spontanously I would cache the whole files. But only cache a few files.

[ludviggunne]

I believe this approach still leads to multiple file-opens. the warnings often jump up and down in the file. i.e. when there are more than one location, more than 1 type of warning, ... it seems to me it will help a lot for the case when there is a noisy warning that generates 1000 warnings with growing linenumbers..

If there are multiple errors the file is kept open, but it does scan the file each time.
AFAIK most of the overhead comes from opening the file, at least on windows.

Spontanously I would cache the whole files. But only cache a few files.

I considered that but I worried it would take up a lot of memory for large files.
Could be worth comparing though.

[ludviggunne]

Here are some benchmarks from a single file that generates a lot of MISRA warnings. I've compared the main branch and this PR, once without any suppressions and once with all MISRA warnings suppressed. The execution time is more or less the same when suppressions are used, likely due to c976cac.

Details

Linux

Benchmark 1: no cache, with suppressions
  Time (mean ± σ):      6.653 s ±  0.797 s    [User: 6.578 s, System: 0.224 s]
  Range (min … max):    5.449 s …  8.544 s    20 runs

Benchmark 2: with cache, with suppressions
  Time (mean ± σ):      6.837 s ±  0.391 s    [User: 6.711 s, System: 0.260 s]
  Range (min … max):    6.661 s …  8.471 s    20 runs

Benchmark 3: no cache, no suppressions
  Time (mean ± σ):     14.376 s ±  0.381 s    [User: 13.269 s, System: 1.370 s]
  Range (min … max):   13.832 s … 15.250 s    20 runs

Benchmark 4: with cache, no suppressions
  Time (mean ± σ):      6.717 s ±  0.080 s    [User: 6.709 s, System: 0.254 s]
  Range (min … max):    6.642 s …  7.008 s    20 runs

Summary
  no cache, with suppressions ran
    1.01 ± 0.12 times faster than with cache, no suppressions
    1.03 ± 0.14 times faster than with cache, with suppressions
    2.16 ± 0.27 times faster than no cache, no suppressions

Windows

Benchmark 1: no cache, no suppressions
  Time (mean ± σ):      8.403 s ±  0.234 s    [User: 6.157 s, System: 1.972 s]
  Range (min … max):    7.961 s …  8.825 s    20 runs

Benchmark 2: with cache, no suppressions
  Time (mean ± σ):      2.246 s ±  0.044 s    [User: 1.820 s, System: 0.198 s]
  Range (min … max):    2.157 s …  2.348 s    20 runs

Benchmark 3: no cache, with suppressions
  Time (mean ± σ):      2.156 s ±  0.036 s    [User: 1.736 s, System: 0.192 s]
  Range (min … max):    2.103 s …  2.235 s    20 runs

Benchmark 4: with cache, with suppressions
  Time (mean ± σ):      2.118 s ±  0.030 s    [User: 1.727 s, System: 0.169 s]
  Range (min … max):    2.074 s …  2.182 s    20 runs

Summary
  with cache, with suppressions ran
    1.02 ± 0.02 times faster than no cache, with suppressions
    1.06 ± 0.03 times faster than with cache, no suppressions
    3.97 ± 0.12 times faster than no cache, no suppressions

[danmar]

I would like one more test in other_test.py that targets this optimisation. I suggest that the testcode contains 2 functions with different warnings so that the line numbers of the reported warnings are going up and down.
Use strace to check how many times the file is reopened. Ideally it is not reopened every time the line number goes up.

[ludviggunne]

I would like one more test in other_test.py that targets this optimisation. I suggest that the testcode contains 2 functions with different warnings so that the line numbers of the reported warnings are going up and down. Use strace to check how many times the file is reopened. Ideally it is not reopened every time the line number goes up.

It's guaranteed not to reopen if there is only one file, even if the line number goes up and down. But I could add a test with multiple files.

[danmar]

I would like one more test in other_test.py that targets this optimisation. I suggest that the testcode contains 2 functions with different warnings so that the line numbers of the reported warnings are going up and down. Use strace to check how many times the file is reopened. Ideally it is not reopened every time the line number goes up.

It's guaranteed not to reopen if there is only one file, even if the line number goes up and down. But I could add a test with multiple files.

I agree that is how it works now. But I want a test that catches regressions. I suggest a test with only 1 file.
A test with multiple files sounds good also.

[danmar]

how does this work when 2 threads reports a warning in a header at the same time? Do they reuse the same cache?
I don't have strong opinions if we should share the cache between threads or not as long as it's thread safe.

[MartinBP]

I considered that but I worried it would take up a lot of memory for large files.
Could be worth comparing though.

Did you try this out?

When I was implementing the suppression cache I also did a "primitive" implementation of a file cache.
Upon encountering a new file, I would read the entire file and cache all lines in a vector, so line lookup after that became O(1).

I was also slightly worried about the cache taking up a lot of memory at that time, so I had a limit on the number of files that could fit in the cache (1000 I think).
In practice I don't think it will become an issue and the number could possibly be even higher.

[MartinBP]

Here are some benchmarks from a single file that generates a lot of MISRA warnings. I've compared the main branch and this PR, once without any suppressions and once with all MISRA warnings suppressed. The execution time is more or less the same when suppressions are used, likely due to

Did you also do a benchmark with multiple files generating warnings to benchmark the code that removes entries from the cache?

[ludviggunne]

Did you try this out?

Here is a comparison where the files are cached as vectors of lines, using the same example project as above (single file, > 1MB). IMHO the difference is negligible. This doesn't account for the overhead of resetting the file pointer though since the line numbers are strictly increasing, I could try to generate a test file that would expose this.

Did you also do a benchmark with multiple files generating warnings to benchmark the code that removes entries from the cache?

Currently running this same benchmark for a project with multiple files and cross references, but it's taking a while 😅

Details

Linux

Benchmark 1: no cache
  Time (mean ± σ):     11.959 s ±  0.599 s    [User: 11.304 s, System: 0.956 s]
  Range (min … max):   11.255 s … 13.949 s    20 runs

Benchmark 2: cached file handles
  Time (mean ± σ):      5.864 s ±  0.039 s    [User: 5.922 s, System: 0.193 s]
  Range (min … max):    5.819 s …  5.987 s    20 runs

Benchmark 3: cached file contents
  Time (mean ± σ):      5.847 s ±  0.025 s    [User: 5.907 s, System: 0.194 s]
  Range (min … max):    5.804 s …  5.913 s    20 runs

Summary
  cached file contents ran
    1.00 ± 0.01 times faster than cached file handles
    2.05 ± 0.10 times faster than no cache

Windows

Benchmark 1: no cache
  Time (mean ± σ):     10.896 s ±  2.370 s    [User: 7.744 s, System: 2.636 s]
  Range (min … max):    8.386 s … 16.430 s    20 runs

Benchmark 2: cached file handles
  Time (mean ± σ):      2.208 s ±  0.038 s    [User: 1.775 s, System: 0.192 s]
  Range (min … max):    2.154 s …  2.288 s    20 runs

Benchmark 3: cached file contents
  Time (mean ± σ):      2.266 s ±  0.043 s    [User: 1.831 s, System: 0.196 s]
  Range (min … max):    2.213 s …  2.390 s    20 runs

Summary
  cached file handles ran
    1.03 ± 0.03 times faster than cached file contents
    4.94 ± 1.08 times faster than no cache

[ludviggunne]

This doesn't account for the overhead of resetting the file pointer though since the line numbers are strictly increasing, I could try to generate a test file that would expose this.

Here are benchmarks for a single file that generates 1000 errors, each referencing an earlier line. Still a very small difference.

Details

Linux

Benchmark 1: cached file handles
  Time (mean ± σ):      6.486 s ±  0.038 s    [User: 6.783 s, System: 0.118 s]
  Range (min … max):    6.419 s …  6.554 s    20 runs

Benchmark 2: cached file contents
  Time (mean ± σ):      6.313 s ±  0.029 s    [User: 6.478 s, System: 0.110 s]
  Range (min … max):    6.264 s …  6.363 s    20 runs

Benchmark 3: no cache
  Time (mean ± σ):      9.811 s ±  0.146 s    [User: 10.700 s, System: 0.244 s]
  Range (min … max):    9.698 s … 10.252 s    20 runs

Summary
  cached file contents ran
    1.03 ± 0.01 times faster than cached file handles
    1.55 ± 0.02 times faster than no cache

Windows

Benchmark 1: no cache
  Time (mean ± σ):      7.329 s ±  0.371 s    [User: 6.396 s, System: 0.628 s]
  Range (min … max):    6.662 s …  8.177 s    20 runs

Benchmark 2: cached file handles
  Time (mean ± σ):      6.103 s ±  0.135 s    [User: 5.646 s, System: 0.167 s]
  Range (min … max):    5.867 s …  6.370 s    20 runs

Benchmark 3: cached file contents
  Time (mean ± σ):      5.738 s ±  0.208 s    [User: 5.301 s, System: 0.157 s]
  Range (min … max):    5.477 s …  6.160 s    20 runs

Summary
  cached file contents ran
    1.06 ± 0.05 times faster than cached file handles
    1.28 ± 0.08 times faster than no cache

[ludviggunne]

how does this work when 2 threads reports a warning in a header at the same time? Do they reuse the same cache? I don't have strong opinions if we should share the cache between threads or not as long as it's thread safe.

ProcessExecutor and ThreadExecutor both forward the error messages to the parent process/main thread, so the cache is centralized. I will add a test with the -j flag.

[MartinBP]

Here is a comparison where the files are cached as vectors of lines, using the same example project as above (single file, > 1MB). IMHO the difference is negligible. This doesn't account for the overhead of resetting the file pointer though since the line numbers are strictly increasing, I could try to generate a test file that would expose this.

Good to know that they perform the same in that specific scenario. It will be interesting how the two solutions perform in the bigger benchmark that you're doing.

Have you thought about the potential drawbacks (if any) about having file streams open for a long time or the maximum number of file streams a process can have open at the same time?

I found the proof-of-concept cache that I was playing around with in case it adds any value to this pull request.

Details

class FileLineCache {
public:
    explicit FileLineCache(std::size_t maxSize) : mMaxSize(maxSize) {}
    const std::vector<std::string>* find(const std::string& filename) const {
        for (const auto& e : mEntries)
            if (e.filename == filename)
                return &e.lines;
        return nullptr;
    }
    const std::vector<std::string>& insert(std::string filename, std::vector<std::string> lines) {
        if (mEntries.size() >= mMaxSize)
            mEntries.pop_front();
        mEntries.push_back({std::move(filename), std::move(lines)});
        return mEntries.back().lines;
    }
private:
    struct Entry {
        std::string filename;
        std::vector<std::string> lines;
    };
    std::size_t mMaxSize;
    std::deque<Entry> mEntries;
};
static std::mutex s_fileLineCacheMutex;
static FileLineCache s_fileLineCache(1000);
static std::string readCode(const std::string &file, int linenr, int column, const char endl[])
{
    std::string line;
    {
        std::lock_guard<std::mutex> lock(s_fileLineCacheMutex);
        const std::vector<std::string>* cached = s_fileLineCache.find(file);
        if (!cached) {
            std::vector<std::string> lines;
            std::ifstream fin(file);
            std::string l;
            while (std::getline(fin, l))
                lines.push_back(std::move(l));
            cached = &s_fileLineCache.insert(file, std::move(lines));
        }
        if (linenr > 0 && linenr <= static_cast<int>(cached->size())) {
            line = (*cached)[linenr - 1];
        }
    }
    const std::string::size_type endPos = line.find_last_not_of("\r\n\t ");
    if (endPos + 1 < line.size())
        line.erase(endPos + 1);
    std::string::size_type pos = 0;
    while ((pos = line.find('\t', pos)) != std::string::npos)
        line[pos] = ' ';
    return line + endl + std::string((column>0 ? column-1 : 0), ' ') + '^';
}