Create documentation for performance analysis on pylint

[jolaf]

In my company we have a number of Python projects, and on one of them (220 KB, 4200 lines of code) pylint is tremendously slow to run, it takes about 30 minutes on a 4-core machine. The other projects are of comparable size, functionality and complexity, and yet pylint runs reasonably fast on them. All the projects are "clean" meaning the code is working fine and all pylint errors and warnings have been cleaned up.

My purpose here is to identify the aspects of my code that cause pylint too long to process, and modify my code so that the problem would go away. I tried different things, like excluding some imports, splitting files and classes in half, etc., but the root of the problem still eludes me. Profiler also is not of much help as it just shows that time gets consumed in some pylint internals.

What I'm looking for is some ideas what to check or how to identify the problem. Maybe there are some internal mechanisms in pylint that could be used to find out which parts of the code beings checked are taking a lot of time to check?

Thanks!

[Pierre-Sassoulas]

Hello, which one of the pylint's internal are taking a long time ? Could you give the result of your profiler ? There is no direct way to know how long each part of the analysis take as far as I know. If you use a lot of custom exception, a fix done in astroid some time ago but not yet released might be of help, see pylint-dev/astroid#847.

[jolaf]

Unfortunately, using astroid master doesn't change anything effectively.

And here's the profiler output:

$ pylint --version
pylint 2.6.0
astroid 2.4.2
Python 3.8.5 (default, Jul 28 2020, 12:59:40) 
[GCC 9.3.0]

$ time python3 -m cProfile -s cumtime -m pylint -j1 My/Package/*.py

         2650819334 function calls (1756044709 primitive calls) in 4171.974 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    385/1    0.018    0.000 4172.013 4172.013 {built-in method builtins.exec}
        1    0.000    0.000 4172.013 4172.013 <string>:1(<module>)
        1    0.000    0.000 4172.013 4172.013 runpy.py:197(run_module)
        1    0.000    0.000 4172.009 4172.009 runpy.py:64(_run_code)
        1    0.000    0.000 4172.009 4172.009 __main__.py:5(<module>)
        1    0.000    0.000 4172.009 4172.009 __init__.py:18(run_pylint)
        1    0.000    0.000 4170.917 4170.917 run.py:74(__init__)
        1    0.000    0.000 4169.842 4169.842 pylinter.py:837(check)
        1    0.000    0.000 4169.839 4169.839 pylinter.py:885(_check_files)
       14    0.001    0.000 4169.609  297.829 pylinter.py:898(_check_file)
       14    0.010    0.001 4091.841  292.274 pylinter.py:1047(check_astroid_module)
       14    0.001    0.000 4091.831  292.274 pylinter.py:1064(_check_astroid_module)
 21813/14    0.381    0.000 4085.476  291.820 ast_walker.py:55(walk)
216484792/414444  163.709    0.000 3680.746    0.009 {built-in method builtins.next}
110022065/461784  147.196    0.000 3678.751    0.008 decorators.py:127(raise_if_nothing_inferred)
98603212/437825  261.748    0.000 3678.270    0.008 decorators.py:84(wrapped)
136176815/1165898  177.739    0.000 3665.163    0.003 util.py:144(limit_inference)
136176815/1165898  184.664    0.000 3664.132    0.003 context.py:108(cache_generator)
5695350/201136   53.221    0.000 3571.809    0.018 inference.py:357(infer_subscript)
2847267/102021   47.694    0.000 3545.971    0.035 scoped_nodes.py:2603(getitem)
(2000+ lines skipped, see attached file for full log)
        1    0.000    0.000    0.000    0.000 __init__.py:59(end_format)
        1    0.000    0.000    0.000    0.000 optparse.py:231(set_parser)
        1    0.000    0.000    0.000    0.000 shlex.py:68(punctuation_chars)
        1    0.000    0.000    0.000    0.000 pickle.py:77(PicklingError)
        1    0.000    0.000    0.000    0.000 base.py:1868(<listcomp>)
        1    0.000    0.000    0.000    0.000 pickle.py:84(UnpicklingError)
        1    0.000    0.000    0.000    0.000 __init__.py:1644(__init__)
real  69m34.777s
user  68m35.752s
sys   0m15.430s

PylintProfile.log

[jolaf]

I've managed to localize my particular problem: #4079

However it took a lot of turning parts of code on and off until the root cause was identified.

So the problem in general still stands.

[Pierre-Sassoulas]

Thanks a lot for the analysis, much appreciated. Regarding performance analysis there is #3013 where I was using the same thing than you time python3 -m cProfile -s tottime pylint/__main__.py pylint/, also a comment by @doublethefish here for svg output : #3458 (comment)