search

nedbat / coveragepy

The code coverage tool for Python
https://coverage.readthedocs.io
Apache License 2.0
2.98k stars 427 forks source link

Expected performance of coveragepy? #1862

Open oerp-odoo opened 2 days ago

oerp-odoo commented 2 days ago

I wonder what is the expected performance of coverage? In my case it looks like some tests run 2x slower than without coverage

I am using python 3.12 with standard unittest framework.

Also, I noticed there is kind of big overhead before anything starts running, when you enable coverage. My app starts in about 1s, but if I enable coverage it starts running tests after about ~13s.

Here is a small sample of tests that are run without coverage:

2024-09-26 08:48:12,662 1 INFO odoodb odoo.addons.base.models.ir_attachment: filestore gc 0 checked, 0 removed 
2024-09-26 08:48:12,662 1 INFO odoodb odoo.service.server: 8 post-tests in 3.11s, 1804 queries 
2024-09-26 08:48:12,662 1 INFO odoodb odoo.tests.stats: base_env_meta: 12 tests 0.12s 118 queries 
2024-09-26 08:48:12,662 1 INFO odoodb odoo.tests.stats: reports_project: 16 tests 3.11s 1804 queries 
2024-09-26 08:48:12,662 1 INFO odoodb odoo.tests.stats: sale_importer_project: 9 tests 0.73s 286 queries 
2024-09-26 08:48:12,662 1 INFO odoodb odoo.tests.stats: versatil: 43 tests 0.36s 230 queries 
2024-09-26 08:48:12,662 1 INFO odoodb odoo.tests.result: 0 failed, 0 error(s) of 50 tests when loading database 'odoodb' 
2024-09-26 08:48:12,662 1 INFO odoodb odoo.service.server: Initiating shutdown 
2024-09-26 08:48:12,662 1 INFO odoodb odoo.service.server: Hit CTRL-C again or send a second signal to force the shutdown. 
2024-09-26 08:48:12,706 1 INFO odoodb odoo.sql_db: ConnectionPool(used=0/count=0/max=64): Closed 2 connections

Here same tests with coverage:

2024-09-26 08:50:09,710 1 INFO odoodb odoo.service.server: 8 post-tests in 5.98s, 1804 queries 
2024-09-26 08:50:09,711 1 INFO odoodb odoo.tests.stats: base_env_meta: 12 tests 0.22s 118 queries 
2024-09-26 08:50:09,711 1 INFO odoodb odoo.tests.stats: reports_project: 16 tests 5.97s 1804 queries 
2024-09-26 08:50:09,711 1 INFO odoodb odoo.tests.stats: sale_importer_project: 9 tests 1.01s 286 queries 
2024-09-26 08:50:09,711 1 INFO odoodb odoo.tests.stats: versatil: 43 tests 0.42s 230 queries 
2024-09-26 08:50:09,711 1 INFO odoodb odoo.tests.result: 0 failed, 0 error(s) of 50 tests when loading database 'odoodb' 
2024-09-26 08:50:09,711 1 INFO odoodb odoo.service.server: Initiating shutdown 
2024-09-26 08:50:09,711 1 INFO odoodb odoo.service.server: Hit CTRL-C again or send a second signal to force the shutdown. 
2024-09-26 08:50:10,044 1 INFO odoodb odoo.sql_db: ConnectionPool(used=0/count=0/max=64): Closed 2 connections

All tests run slower especially ones with lots of queries. Note, odoo is tightly coupled with database engine (postgres), so there are lots of tests that depend on database. Not sure if its relevant here.

My .coveragerc:

[run]
include =
    /opt/odoo/projects/monodoo/*
    /opt/odoo/projects/custom/*

omit =
    **/tests/*
    **/migrations/*

[report]
# Regexes for lines to exclude from consideration
exclude_lines =
    # Have to re-enable the standard pragma
    pragma: no cover

    # Don't complain if non-runnable code isn't run:
    if __name__ == .__main__.:

I run coverage like this:

os.execvp(cmd, cmd_args)

Where cmd is coverage and cmd_args = ['coverage', 'run', '/opt/odoo/odoo/odoo-bin', '-d', 'odoodb', '--stop-after-init', '--test-enable', '-u', 'my-module']

P.S. I also run it via docker container.

nedbat commented 2 days ago

The first thing to check is what tracer you are using. Coverage.py has a C tracer and a Python tracer. You want the C tracer. It still adds overhead to your execution, but less than the Python tracer.

Add --debug=sys to your coverage run --debug=sys command, and you will get diagnostic output starting like this:

-- sys -------------------------------------------------------
               coverage_version: 7.6.2a0.dev1
                coverage_module: /Users/ned/coverage/trunk/coverage/__init__.py
                           core: CTracer
                        CTracer: available
           plugins.file_tracers: -none-
            plugins.configurers: -none-

core: CTracer is the thing you want to see. If it says PyTracer, then we can work out why.

oerp-odoo commented 2 days ago

This is what I get with sys debug:

-- sys -------------------------------------------------------
               coverage_version: 7.6.1
                coverage_module: /opt/odoo/venv/lib/python3.12/site-packages/coverage/__init__.py
                           core: CTracer
                        CTracer: available
           plugins.file_tracers: -none-
            plugins.configurers: -none-
      plugins.context_switchers: -none-
              configs_attempted: /.coveragerc
                   configs_read: /.coveragerc
                    config_file: /.coveragerc
                config_contents: b"# coverage run /opt/odoo/venv/bin/odoo -u base_env_meta --stop-after-init -d odoodb -p 8055 --test-enable\n[run]\ninclude =\n    /opt/odoo/projects/monodoo/*\n    /opt/odoo/projects/custom/*\n\nomit =\n    **/tests/*\n    **/migrations/*\n\n[report]\n# Regexes for lines to exclude from consideration\nexclude_lines =\n    # Have to re-enable the standard pragma\n    pragma: no cover\n\n    # Don't complain if non-runnable code isn't run:\n    if __name__ == .__main__.:\n"
                      data_file: /.coverage
                         python: 3.12.3 (main, Jul 31 2024, 17:43:48) [GCC 13.2.0]
                       platform: Linux-5.15.0-119-generic-x86_64-with-glibc2.39
                 implementation: CPython
                    gil_enabled: True
                     executable: /opt/odoo/venv/bin/python3
                   def_encoding: utf-8
                    fs_encoding: utf-8
                            pid: 30
                            cwd: /
                           path: /opt/odoo/venv/bin
                                 /usr/lib/python312.zip
                                 /usr/lib/python3.12
                                 /usr/lib/python3.12/lib-dynload
                                 /opt/odoo/venv/lib/python3.12/site-packages
                                 /opt/odoo/odoo
                                 /opt/odoo/packages/songs
                                 /opt/odoo/packages/songs_accounting
                                 /opt/odoo/packages/utilsx
                                 /opt/odoo/packages/odookit
                                 /opt/odoo/songs_custom
                    environment: COVERAGE_RUN = true
                                 HOME = /root
                   command_line: /opt/odoo/venv/bin/coverage run --debug=sys /opt/odoo/venv/bin/odoo -u versatil --test-enable --stop-after-init -d odoodb -p 8055
                 coverage_paths: /opt/odoo/venv/lib/python3.12/site-packages/coverage
                   stdlib_paths: /usr/lib/python3.12/re
                                 /usr/lib/python3.12
              third_party_paths: /opt/odoo/venv/lib/python
                                 /opt/odoo/venv/local/lib/python3.12/dist-packages
                                 /opt/odoo/venv/local/bin
                                 /opt/odoo/venv/lib/python3.12/site-packages
                                 /root/.local/bin
                                 /opt/odoo/venv/bin
                                 /root/.local/lib/python3.12/site-packages
                   source_match: -none-
              source_pkgs_match: -none-
                  include_match: /opt/odoo/projects/monodoo/*
                                 /opt/odoo/projects/monodoo/*
                                 /opt/odoo/projects/custom/*
                                 /opt/odoo/projects/custom/*
                     omit_match: **/tests/*
                                 **/migrations/*
                    cover_match: /opt/odoo/venv/lib/python3.12/site-packages/coverage
                    pylib_match: /usr/lib/python3.12
                                 /usr/lib/python3.12/re
                    third_match: /opt/odoo/venv/bin
                                 /opt/odoo/venv/lib/python
                                 /opt/odoo/venv/lib/python3.12/site-packages
                                 /opt/odoo/venv/local/bin
                                 /opt/odoo/venv/local/lib/python3.12/dist-packages
                                 /root/.local/bin
                                 /root/.local/lib/python3.12/site-packages
          source_in_third_match: -none-
         sqlite3_sqlite_version: 3.45.1
             sqlite3_temp_store: 0
        sqlite3_compile_options: ATOMIC_INTRINSICS=1, COMPILER=gcc-13.2.0, DEFAULT_AUTOVACUUM,
                                 DEFAULT_CACHE_SIZE=-2000, DEFAULT_FILE_FORMAT=4,
                                 DEFAULT_JOURNAL_SIZE_LIMIT=-1, DEFAULT_MMAP_SIZE=0, DEFAULT_PAGE_SIZE=4096,
                                 DEFAULT_PCACHE_INITSZ=20, DEFAULT_RECURSIVE_TRIGGERS,
                                 DEFAULT_SECTOR_SIZE=4096, DEFAULT_SYNCHRONOUS=2,
                                 DEFAULT_WAL_AUTOCHECKPOINT=1000, DEFAULT_WAL_SYNCHRONOUS=2,
                                 DEFAULT_WORKER_THREADS=0, DIRECT_OVERFLOW_READ, ENABLE_COLUMN_METADATA,
                                 ENABLE_DBSTAT_VTAB, ENABLE_FTS3, ENABLE_FTS3_PARENTHESIS,
                                 ENABLE_FTS3_TOKENIZER, ENABLE_FTS4, ENABLE_FTS5, ENABLE_LOAD_EXTENSION,
                                 ENABLE_MATH_FUNCTIONS, ENABLE_PREUPDATE_HOOK, ENABLE_RTREE, ENABLE_SESSION,
                                 ENABLE_STMTVTAB, ENABLE_UNLOCK_NOTIFY, ENABLE_UPDATE_DELETE_LIMIT,
                                 HAVE_ISNAN, LIKE_DOESNT_MATCH_BLOBS, MALLOC_SOFT_LIMIT=1024,
                                 MAX_ATTACHED=10, MAX_COLUMN=2000, MAX_COMPOUND_SELECT=500,
                                 MAX_DEFAULT_PAGE_SIZE=32768, MAX_EXPR_DEPTH=1000, MAX_FUNCTION_ARG=127,
                                 MAX_LENGTH=1000000000, MAX_LIKE_PATTERN_LENGTH=50000,
                                 MAX_MMAP_SIZE=0x7fff0000, MAX_PAGE_COUNT=0xfffffffe, MAX_PAGE_SIZE=65536,
                                 MAX_SCHEMA_RETRY=25, MAX_SQL_LENGTH=1000000000, MAX_TRIGGER_DEPTH=1000,
                                 MAX_VARIABLE_NUMBER=250000, MAX_VDBE_OP=250000000, MAX_WORKER_THREADS=8,
                                 MUTEX_PTHREADS, SECURE_DELETE, SOUNDEX, SYSTEM_MALLOC, TEMP_STORE=1,
                                 THREADSAFE=1, USE_URI
-- end -------------------------------------------------------

I guess tracer is not the problem. When I run with debug, I immediately see debug output, but then nothing changes for ~12s and only after that time I see tests start running.

nedbat commented 1 day ago

OK, it's good that you have the right pieces in place. Is it possible to give me a way to reproduce the problem?

oerp-odoo commented 1 day ago

Yes, it should be possible to run official odoo docker, like:

docker run -d -e POSTGRES_USER=odoo -e POSTGRES_PASSWORD=odoo -e POSTGRES_DB=postgres --name db postgres:15
docker run -d -p 8069:8069 --name odoo --link db:db -t odoo:17.0
docker exec -it odoo bash
cd ~/
pip install coverage
odoo -d odoodb -i sales_team --stop-after-init -p 8055 --db_host=db --db_password=odoo
odoo -d odoodb -u sales_team --stop-after-init -p 8055 --db_host=db --db_password=odoo --test-enable
/var/lib/odoo/.local/bin/coverage run /usr/bin/odoo -d odoodb -u sales_team --test-enable --stop-after-init -p 8055 --db_host=db --db_password=odoo

With odoo -d odoodb -u sales_team --stop-after-init -p 8055 --db_host=db --db_password=odoo --test-enable it should run tests normally without coverage. With /var/lib/odoo/.local/bin/coverage run /usr/bin/odoo -d odoodb -u sales_team --test-enable --stop-after-init -p 8055 --db_host=db --db_password=odoo, same tests with coverage.

Though when I tested same thing on official image, I noticed that there was no delay, even though tests with coverage still run about 30% slower than without (for this sales_team module, for me it ran around 10s without and 13s with coverage).

Now regarding initial delay of 12-13s, it looks like it is related with Python 3.12 version or maybe some packages on that version specifically. The reason official image has no delay, because they still use 3.10 python. I use 3.12. To make sure it was the case, I switched my source code all the way back since 3.10 was used. And then I noticed that delay was gone as well.

What I also noticed, was that when that delay is happening, if I click CTRL+C, I get this traceback:

    runner.run()
  File "/opt/odoo/venv/lib/python3.12/site-packages/coverage/execfile.py", line 211, in run
    exec(code, main_mod.__dict__)
  File "/opt/odoo/odoo/odoo-bin", line 5, in <module>
    import odoo
  File "/opt/odoo/odoo/odoo/__init__.py", line 77, in <module>
    import PyPDF2
  File "/opt/odoo/venv/lib/python3.12/site-packages/PyPDF2/__init__.py", line 10, in <module>
    from ._encryption import PasswordType
  File "/opt/odoo/venv/lib/python3.12/site-packages/PyPDF2/_encryption.py", line 36, in <module>
    from .generic import (
  File "/opt/odoo/venv/lib/python3.12/site-packages/PyPDF2/generic/__init__.py", line 36, in <module>
    from ._annotations import AnnotationBuilder
  File "/opt/odoo/venv/lib/python3.12/site-packages/PyPDF2/generic/_annotations.py", line 3, in <module>
    from ._base import (
  File "/opt/odoo/venv/lib/python3.12/site-packages/PyPDF2/generic/_base.py", line 35, in <module>
    from .._codecs import _pdfdoc_encoding_rev
  File "/opt/odoo/venv/lib/python3.12/site-packages/PyPDF2/_codecs/__init__.py", line 3, in <module>
    from .adobe_glyphs import adobe_glyphs
  File "/opt/odoo/venv/lib/python3.12/site-packages/PyPDF2/_codecs/adobe_glyphs.py", line 13437, in <module>
    _complete()
  File "/opt/odoo/venv/lib/python3.12/site-packages/PyPDF2/_codecs/adobe_glyphs.py", line 13430, in _complete
    def _complete() -> None:

So I wonder maybe it is related with PyPDF2 package? And specifically when it is used with 3.12?

Odoo uses newer PyPDF2, if python is greater than 3.10 (https://github.com/odoo/odoo/blob/7e536998d84744a464e91fa5e056fc06f7796d6f/requirements.txt#L55):

PyPDF2==1.26.0 ; python_version <= '3.10'
PyPDF2==2.12.1 ; python_version > '3.10'