gitfs - pygit2 substantially slower than gitpython rebuilding file_list cache

[duckfez]

Description of Issue

We have noticed a significant performance deviation between the gitpython and pygit2 backends for gitfs. The file list cache rebuild process for pygit2 can be 10x or more slower than gitpython. In our environment, this was leading to file_list cache rebuilds taking longer than the file_list_cache_time, and high CPU utilization at the master when minions start running a state. With enough minions running a state, the master stops responding entirely as all the worker threads are tied up doing file_list cache rebuilds in parallel. (I think there is maybe a separate locking issue here, but I'm not trying to address it right now)

Setup

In master.conf:

fileserver_backend:
  - gitfs
  - roots

gitfs_saltenv_whitelist:
  - base

# File roots via Git
gitfs_base: master
gitfs_remotes:
   - git@github.com:foo/bar.git:
     - name: foo-bar
     - base: master

and one or the other of:

# File roots via Git
gitfs_provider: pygit2
gitfs_pubkey: /home/ec2-user/.ssh/id_rsa.pub
gitfs_privkey: /home/ec2-user/.ssh/id_rsa

or

gitfs_provider: gitpython

Steps to Reproduce Issue

With gitpython:

(venv) [ec2-user@ip-172-31-61-166 master.d]$ time salt-run -c ~/venv/etc/salt -l profile fileserver.file_list | wc -l
22:57:47,652 [salt.utils.verify:558 ][WARNING ][23277] Insecure logging configuration detected! Sensitive data may be logged.
22:57:48,014 [py.warnings                              :110 ][WARNING ][23277] /home/ec2-user/salt/salt/utils/dictdiffer.py:16: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated, and in 3.8 it will stop working
  from collections import Mapping

22:57:51,862 [salt.loaded.int.grains.core              :1063][INFO    ][23277] Although 'virt-what' was found in path, the current user cannot execute it. Grains output might not be accurate.
22:57:52,150 [salt.utils.gitfs                         :30  ][PROFILE ][23277] gitfs file_name cache rebuild repo=git@github.com:foo/bar.git duration=0.11979842185974121 seconds
22:57:52,165 [salt.client.mixins                       :421 ][INFO    ][23277] Runner completed: 20191123225747673536
1011

real	0m5.575s
user	0m5.367s
sys	0m0.204s

With pygit2:

(venv) [ec2-user@ip-172-31-61-166 master.d]$ time salt-run -c ~/venv/etc/salt -l profile fileserver.file_list | wc -l
22:59:41,016 [salt.utils.verify:558 ][WARNING ][23929] Insecure logging configuration detected! Sensitive data may be logged.
22:59:41,243 [py.warnings                              :110 ][WARNING ][23929] /home/ec2-user/salt/salt/utils/dictdiffer.py:16: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated, and in 3.8 it will stop working
  from collections import Mapping

22:59:44,377 [salt.loaded.int.grains.core              :1063][INFO    ][23929] Although 'virt-what' was found in path, the current user cannot execute it. Grains output might not be accurate.
23:00:10,481 [salt.utils.gitfs                         :30  ][PROFILE ][23929] gitfs file_name cache rebuild repo=git@github.com:foo/bar.git duration=25.939875841140747 seconds
23:00:10,503 [salt.client.mixins                       :421 ][INFO    ][23929] Runner completed: 20191123225941031963
1011

real	0m30.262s
user	0m29.738s
sys	0m0.532s

The PROFILE log message is from a PR that I am submitting as soon as I'm done with this issue, where we added logging in to better understand the issue at hand.

Versions Report

(venv) [ec2-user@ip-172-31-61-166 master.d]$ salt -V
Salt Version:
           Salt: 2019.2.1-101-gae6ca7e

Dependency Versions:
           cffi: 1.13.2
       cherrypy: Not Installed
       dateutil: Not Installed
      docker-py: Not Installed
          gitdb: 2.0.6
      gitpython: 3.0.5
         Jinja2: 2.10.3
        libgit2: 0.28.2
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.6.2
   mysql-python: Not Installed
      pycparser: 2.19
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: 0.28.2
         Python: 3.7.4 (default, Nov 12 2019, 19:44:08)
   python-gnupg: Not Installed
         PyYAML: 5.1.2
          PyZMQ: 18.1.1
          smmap: 2.0.5
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.3.2

System Versions:
           dist:
         locale: UTF-8
        machine: x86_64
        release: 4.14.152-127.182.amzn2.x86_64
         system: Linux
        version: Not Installed

We have also replicated this same issue on Salt 2018.3.4 running on RHEL 7.7:

Salt Version:
           Salt: 2018.3.4

Dependency Versions:
           cffi: 1.13.2
       cherrypy: Not Installed
       dateutil: 1.5
      docker-py: Not Installed
          gitdb: 0.6.4
      gitpython: 1.0.1
          ioflo: Not Installed
         Jinja2: 2.7.2
        libgit2: 0.26.6
        libnacl: Not Installed
       M2Crypto: 0.21.1
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.6
   mysql-python: Not Installed
      pycparser: 2.17
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: 0.26.4
         Python: 2.7.5 (default, Jun 11 2019, 14:33:56)
   python-gnupg: Not Installed
         PyYAML: 3.10
          PyZMQ: 15.3.0
           RAET: Not Installed
          smmap: 0.9.0
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.1.4

System Versions:
           dist: redhat 7.7 Maipo
         locale: UTF-8
        machine: x86_64
        release: 3.10.0-1062.4.3.el7.x86_64
         system: Linux
        version: Red Hat Enterprise Linux Server 7.7 Maipo

[cmcmarrow]

I belive gitpython is built on pygit2. Gitpyhon may have implemented a cache.

[OrangeDog]

@cmcmarrow not at all.

pygit2 uses libgit2 (a C library)

gitpython uses GitDB (a pure Python library) or the git CLI

[viktordaniel]

We are experiencing the same issue. After our GIT has grown a bit (~20k files in repository), the salt master became unusable. The profile output :

pygit2:
[salt.utils.gitfs :28 ][PROFILE ][824469] gitfs file_name cache rebuild repo=ssh://git@***** duration=21.16121792793274 seconds

gitpython:
[salt.utils.gitfs :28 ][PROFILE ][1064432] gitfs file_name cache rebuild repo=git+ssh://git@***** duration=0.5155136585235596 seconds

40x faster, system load dropped 40x as well after reconfiguring salt-master to use gitpython and the saltstack is responsive again.