Profiling pyani performance (version 3)

[baileythegreen]

Is there a way to get cProfile working with pyani v3? I have tried a few different things, but either cProfile seems to work — but the database doesn't get population — or cProfile doesn't work, throwing one of a handful of errors, depending on how it's been called.

I think part of it may be the subcommand structure used by the development version?

[widdowquinn]

What specifically isn't working for you? Can you share any code/a script so I know where to start?

[widdowquinn]

If the problem you're having is what I think it is, then maybe #288 fixes the issue?

>>> import cProfile
>>> from pyani.scripts import pyani_script
>>> cProfile.run('pyani_script.run_main(["createdb", "--dbpath", "cprofile_test/pyanidb", "--force"])')
         25161 function calls (24323 primitive calls) in 0.041 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     21/4    0.000    0.000    0.004    0.001 <frozen importlib._bootstrap>:1017(_handle_fromlist)
        8    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:103(release)
        5    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:143(__init__)
        5    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:147(__enter__)
        5    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:151(__exit__)
[...]
        1    0.000    0.000    0.024    0.024 pyani_orm.py:315(create_db)
        1    0.000    0.000    0.001    0.001 pyani_script.py:117(add_log_headers)
        1    0.000    0.000    0.041    0.041 pyani_script.py:77(run_main)
        7    0.000    0.000    0.000    0.000 pyani_tools.py:321(termcolor)
        1    0.000    0.000    0.001    0.001 pysqlcipher.py:8(<module>)
        1    0.000    0.000    0.000    0.000 pysqlcipher.py:88(SQLiteDialect_pysqlcipher)
        1    0.000    0.000    0.000    0.000 pysqlite.py:375(_SQLite_pysqliteTimeStamp)
        1    0.000    0.000    0.000    0.000 pysqlite.py:389(_SQLite_pysqliteDate)
        1    0.000    0.000    0.000    0.000 pysqlite.py:403(SQLiteDialect_pysqlite)
        1    0.000    0.000    0.000    0.000 pysqlite.py:419(dbapi)
        1    0.000    0.000    0.000    0.000 pysqlite.py:433(_is_url_file_db)
        1    0.000    0.000    0.000    0.000 pysqlite.py:440(get_pool_class)
        1    0.000    0.000    0.000    0.000 pysqlite.py:447(_get_server_version_info)
        1    0.000    0.000    0.000    0.000 pysqlite.py:464(create_connect_args)
        1    0.000    0.000    0.000    0.000 pysqlite.py:8(<module>)
[...]
        1    0.000    0.000    0.000    0.000 schema.py:2816(table)
       13    0.000    0.000    0.000    0.000 schema.py:3021(__iter__)
       31    0.000    0.000    0.000    0.000 schema.py:3026(<genexpr>)
       36    0.000    0.000    0.000    0.000 schema.py:3028(__len__)
        1    0.000    0.000    0.000    0.000 schema.py:3106(__visit_name__)
       10    0.000    0.000    0.000    0.000 schema.py:3326(referred_table)
        5    0.000    0.000    0.000    0.000 schema.py:3570(columns_autoinc_first)
        5    0.000    0.000    0.000    0.000 schema.py:3575(<listcomp>)
        5    0.000    0.000    0.000    0.000 schema.py:3579(_autoincrement_column)
        5    0.000    0.000    0.000    0.000 schema.py:3581(_validate_autoinc)
        1    0.000    0.000    0.016    0.016 schema.py:4442(create_all)
        7    0.000    0.000    0.000    0.000 schema.py:692(_sorted_constraints)
       20    0.000    0.000    0.000    0.000 schema.py:698(<lambda>)
       21    0.000    0.000    0.000    0.000 schema.py:700(foreign_key_constraints)
       51    0.000    0.000    0.000    0.000 schema.py:712(<genexpr>)
[...]

[baileythegreen]

I'm not sure if #288 does; it doesn't seem related, on its face. I think part of the problem is that I was trying to run cProfile on the code from the command line (I'm not used to running either pyani or cProfile from within Python). I couldn't figure out the right way to combine the two things together. I tried a few things, some of which seemed clearly wrong, but I was running out of ideas.

---

python -m cProfile -o cprofile.log pyani fastani -i ../fastANI/data/ -o fastani.out -l fastani.log

IsADirectoryError: [Errno 21] Is a directory: 'pyani'

---

python -m cProfile -o cprofile.log -m pyani fastani -i ../fastANI/data/ -o fastani.out -l fastani.log

ImportError: No module named pyani.__main__; 'pyani' is a package and cannot be directly executed

---

python -m cProfile pyani/scripts/subcommands/subcmd_fastani.py -i ../fastANI/data/ -o fastani.out -l fastani.log

this produced profiling output, but I don't think it actually ran the comparisons because the database was empty.

[widdowquinn]

I think cProfile is best used programmatically. If nothing else, I spotted and fixed a problem we wouldn't otherwise have realised we had… ;)

I think cProfile is most flexible and configurable in a scripting context. It seems quite limited from the command-line:

$ python -m cProfile -h
Usage: cProfile.py [-o output_file_path] [-s sort] [-m module | scriptfile] [arg] ...

Options:
  -h, --help            show this help message and exit
  -o OUTFILE, --outfile=OUTFILE
                        Save stats to <outfile>
  -s SORT, --sort=SORT  Sort order when printing to stdout, based on
                        pstats.Stats class
  -m                    Profile a library module

I think you can only pass a module for testing (with e.g. if __name__ == __main__: if you want it to run like a script) at the command-line. Have you given the idiom I used above a try? With something like:

>>> import cProfile
>>> from pyani.scripts import pyani_script
>>> cProfile.run('pyani_script.run_main(["fastani", "-i", "../fastANI/data/", "-o", "fastani.out", "-l", "fastani.log"])')

[baileythegreen]

I am also interested in figuring out a way to plot resources used running each method over time. They seem to oscillate between using all of the ones available on my laptop, and using very little. Might help identify bottlenecks, or some other way to make it more efficient.

[widdowquinn]

Effective parallelisation is hard. I think we're better handing over processes to estabished schedulers where the developers have thought about these things much harder than we have.

[baileythegreen]

On my phone I missed that there was an option to reply to a specific comment. This makes more sense!

I'm not suggesting we try to make it so there's no need to use a scheduler for big analyses, but if there's something that is feasible to do that could make it easier for people who don't have access to a supercomputer/scheduler combination to run smaller analyses locally, that increases the potential user base for pyani, and makes it more accessible.

I am also just interested in learning how to make such plots for my computer.

[widdowquinn]

The main bottleneck isn't in parallelisation, so much; it's in collating the output from files and putting it into the database. This is particularly apparent as "user-experienced time" - the comparison jobs stop, and then there's a long wait.

The async approach wouldn't affect how long it takes in compute time to parse the files or populate the database, but it could distribute the time so that it takes place mostly while parallelised comparison jobs are underway. That is, I think, the biggest "win" we will get.

The next-biggest would be not needing to write to file, but given that we aim to support running across multiple nodes that don't share memory, this is a bigger engineering challenge and not - for me - a priority.