Can we improve performance?

[JHertz5]

What is your question?
There are lots of places in the codebase where we initialise an empty list and then append items to that list, even though, in many cases, every element of the list is known from the start. For example, in vhdlFile (line 135):

            lObjects = []
            for sToken in lTokens:
                lObjects.append(parser.item(sToken))

This is inefficient, as the machine will need to move the object to new memory every time an item is appended. It is much more efficient to do this using a list comprehension.

            lObjects = [parser.item(sToken) for sToken in lTokens]

Performance is an issue for VSG. Part of this is just because it is written in Python, so it will naturally be slower than if it were written in a lower-level language like rust or C. However, I'd like to investigate whether we can improve performance somewhat with changes like these.

A quick test run with a long test file gave me the following results for the section above:

Before:
Time = 77612316 ns
Time = 78840997 ns
After:
Time = 77119071 ns
Time = 77136794 ns
Time = 76735795 ns

This suggests that there is a (small) performance improvement here. Maybe there are other places where we can get more performance improvements that will add up to something noticable.

I'm basically raising this issue to get a branch to facilitate these improvements/this investigation.

[JHertz5]

I've found that get_tokens_bounded_by is relatively high up on this list when looking at profiler output. I've been able to trace this down to the function extract_closest_pair. This was also identified as a bottleneck in previous analysis.

This function searches by going through the list of tokens sequentially. I've been able to (with some help from copilot) replace this with a binary search that has significantly sped the function up!

Before the change:

       83    0.000    0.000    0.299    0.004 /home/jhertzog/code/vhdl-style-guide-fork/bin/../vsg/vhdlFile/vhdlFile.py:270(get_tokens_bounded_by)

       83    0.000    0.000    0.064    0.001 /home/jhertzog/code/vhdl-style-guide-fork/bin/../vsg/vhdlFile/vhdlFile.py:270(get_tokens_bounded_by)

That's a ~6x performance increase! This is my first time using python profilers and attempting serious performance optimisation, so I'm pretty please with myself! I wonder whether there are other places where we are using linear searches that could be replaced with a binary search...

[JHertz5]

Another function that I've found to be a bit of a bottleneck is find_next_token. In my test run, using a UVVM file for testing, this was called over 80,000 times and took rougly 1 second of the 2.6 second runtime!

I've been able to optimise this a bit (again with some help from copilot).

Before:

    83397    0.995    0.000    0.995    0.000 /home/jhertzog/code/vhdl-style-guide-fork/bin/../vsg/vhdlFile/utils.py:281(find_next_token)

After:

    83397    0.106    0.000    0.110    0.000 /home/jhertzog/code/vhdl-style-guide-fork/bin/../vsg/vhdlFile/utils.py:281(find_next_token)

This runs ~10x faster and cuts almost a second off of the runtime, which is pretty impressive.

The original code is as follows:

def find_next_token(iToken, lObjects):
    for iCurrent, oToken in enumerate(lObjects[iToken::]):
        if type(oToken) == parser.item:
            return iCurrent + iToken
    return iToken

This is very readable, pythonic, clear code, but when the function is being called this often, it turns out that we can make some optimisations.

1. Slicing lObjects creates a whole new list object which is a relatively slow operation. If we just loop through the array up to a limit, without slicing, we get better performance.
2. We can cache parser.item to speed up the attribute lookup.
3. Using type(oToken) is parser.item is faster than type(oToken) == parser.item.
4. Using a while loop rather than a for loop is a bit faster. There is some overhead from using enumerate as well, so we can speed up by avoiding that.

I'm surprised that these changes make such a big difference though, probably just because the function is called so often. I can see the slice being a serious bottleneck since lObjects is usually very long, but the rest of the improvements are probably smaller.

There are a few other places where we can make similar changes (although if they aren't called as often, the performance gains will be much more limited).

[JHertz5]

Recording here - for the profiling, I've got the following code snippet attached to apply_rules:

import cProfile
import pstats, io
def profile_this(func):
    def wrapper(*args, **kwargs):
        profiler = cProfile.Profile()
        profiler.enable()
        result = func(*args, **kwargs)
        profiler.disable()
        s = io.StringIO()
        pstats.Stats(profiler, stream=s).sort_stats("cumulative").print_stats(100)
        print(s.getvalue())
        return result
    return wrapper

# This function is in a separate module from __main__ as a workaround for https://bugs.python.org/issue25053
# see also https://stackoverflow.com/questions/41385708/multiprocessing-example-giving-attributeerror/42383397#42383397
@profile_this
def apply_rules(commandLineArguments, oConfig, tIndexFileName):

This snippet profiles apply_rules (or whichever function it's attached to, I could move it elsewhere) and prints out the top 100 functions with the longest cumulative time. I'm running the tool as normal but limiting the number of jobs.

./bin/vsg -f test.vhd --jobs 1

Understandably, the profiler doesn't seem to be able to handle parallel execution.

[JHertz5]

Another profiler tool that I've been using is line_profiler. I've

• Installed it

pip install line_profiler

• Added an @profile decorator to the function in question to mark it for profiling
• Then run the tool as follows

kernprof -l -v ./bin/vsg -f test.vhd --jobs 1

The tool then prints out a line by line list of the time spent on individual lines of code within the function. Very useful!

[JHertz5]

I think I'm at a stage where I'm ready to pause work and merge what I have so far. Given that this is my first attempt at using code profiling tools, I'm very pleased with how it's gone and very impressed with the python tool ecosystem.

I'm using a 3.5k line test file for my "benchmarking"

Starting from the master branch, it takes about 7.6 seconds to run VSG on this file.

$ time ./bin/vsg -f test.vhd --jobs 1 -a | tail -n 1
NOTE: Refer to online documentation at https://vhdl-style-guide.readthedocs.io/en/latest/index.html for more information.

real    0m7.641s
user    0m7.525s
sys     0m0.117s

With the change to use binary search in extract_closest_pair, the time drops by about a second:

$ time ./bin/vsg -f test.vhd --jobs 1 -a | tail -n 1
NOTE: Refer to online documentation at https://vhdl-style-guide.readthedocs.io/en/latest/index.html for more information.

real    0m6.611s
user    0m6.507s
sys     0m0.106s

The biggest change was optimising find_next_token. This function is used super super frequently, so making some tweaks to these ten lines of code made an incredible difference. These changes drop the time down to ~2.5 seconds!

$ time ./bin/vsg -f test.vhd --jobs 1 -a | tail -n 1
NOTE: Refer to online documentation at https://vhdl-style-guide.readthedocs.io/en/latest/index.html for more information.

real    0m2.564s
user    0m2.446s
sys     0m0.119s

There were then several other changes that made some marginal improvements.

 time ./bin/vsg -f test.vhd --jobs 1 -a | tail -n 1
NOTE: Refer to online documentation at https://vhdl-style-guide.readthedocs.io/en/latest/index.html for more information.

real    0m2.440s
user    0m2.326s
sys     0m0.115s

So we took it from 7.64 seconds to 2.44 seconds!! This is over 3x speed improvement!

I'm very pleased with how this exercise has gone. I think I'll struggle to make any more significant improvements at the moment and I'm going back to work tomorrow so will have much less time to work on this, so this a good place to pause optimisation effort. I'm going to check through the branch and then merge the changes.