ggcaller unexpectedly slow for PGWAS on SPARC dataset?

benrhodes26 commented 1 year ago

I am trying to reproduce your PGWAS results on the sparc (a.k.a massachusetts) dataset. Based on the figures in the paper (e.g. figure 8), I was expecting ggcaller to take ~100 minutes. Instead, it is taking more like ~14 hours.

Command

Following your PGWAS instructions, I ran the following ggcaller --refs genome_list.txt --out pyseer_results --clean-mode strict --ignore-pseduogenes --alignment core --aligner def --annotation sensitive --diamonddb CDS_protein_sequences.dmnd --save --core-threshold 1 --threads 16

The code takes a very long time in the 'gene-finding' stage (starting with the 'Traversing graph to identify ORFs...' step).

I think my system has sufficient specs to handle the job (see below). Finally, I should note that I did receive a couple of warnings when installing (see this issue).

System info

free -g

                total        used        free      shared  buff/cache   available
Mem:            503          23         356           0         124         477
Swap:           7             1           5

lscpu

Architecture:                    x86_64
CPU op-mode(s):                  32-bit, 64-bit
Byte Order:                      Little Endian
Address sizes:                   43 bits physical, 48 bits virtual
CPU(s):                          64
On-line CPU(s) list:             0-63
Thread(s) per core:              2
Core(s) per socket:              16
Socket(s):                       2
NUMA node(s):                    2
Vendor ID:                       AuthenticAMD
CPU family:                      23
Model:                           49
Model name:                      AMD EPYC 7302 16-Core Processor
Stepping:                        0
CPU MHz:                         3281.603
BogoMIPS:                        5988.67
Virtualisation:                  AMD-V
L1d cache:                       1 MiB
L1i cache:                       1 MiB
L2 cache:                        16 MiB
L3 cache:                        256 MiB

Installation

I installed ggCaller from source. In case its relevant, the pkg versions are attached. gg_caller_pkgs.txt

benrhodes26 commented 1 year ago

Actually, it was more like 18 hours in the end. Here is the terminal output (in case that helps)

Loading gene models...                                                                                                                                     
Traversing graph to identify ORFs...                                                                                                                        
|██████████████████████████████████████████████████| 100%                                                                                                   
Generating clusters of high-scoring ORFs...                                                                                                                 
Scoring ORF clusters...                                                                                                                                     
|██████████████████████████████████████████████████| 100%                                                                                                   
Identifying high-scoring ORFs...                                                                                                                            
|██████████████████████████████████████████████████| 100%
Generating initial network...                                                                                                                               
Processing paralogs...                                                                                                                                      
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 138/138 [00:03<00:00, 36.82it/s]
collapse mistranslations...                                                                                                                                 
Processing depth:  1                                                                                                                                        
Iteration:  1                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████| 47018/47018 [00:05<00:00, 8333.10it/s]
Iteration:  2                                                                                                                                               
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 3505/3505 [00:03<00:00, 906.11it/s]
Iteration:  3                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 2155/2155 [00:01<00:00, 1127.19it/s]
Iteration:  4
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 827/827 [00:00<00:00, 993.37it/s]
Iteration:  5
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 271/271 [00:00<00:00, 828.48it/s]
Iteration:  6
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 59/59 [00:00<00:00, 567.19it/s]
Iteration:  7                                                                                                                                               
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 19/19 [00:00<00:00, 358.72it/s]
Iteration:  8                                                                                                                                               
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 8/8 [00:00<00:00, 270.93it/s]
Iteration:  9                                                                                                                                               
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 3/3 [00:00<00:00, 260.96it/s]
Iteration:  10
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1/1 [00:00<00:00, 289.16it/s]
Iteration:  11                                                                                                                                              
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1/1 [00:00<00:00, 761.91it/s]
Processing depth:  2
Iteration:  1
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████| 14843/14843 [00:08<00:00, 1712.65it/s]
Iteration:  2
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 379/379 [00:01<00:00, 195.16it/s]
Iteration:  3                                                                                                                                               
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 46/46 [00:00<00:00, 109.01it/s]
Iteration:  4                                                                                                                                               
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 5/5 [00:00<00:00, 193.86it/s]
Iteration:  5                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1/1 [00:00<00:00, 29.92it/s]
Processing depth:  3
Iteration:  1                                                                                                                                               
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 14106/14106 [00:40<00:00, 347.82it/s]
Iteration:  2                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 71/71 [00:02<00:00, 30.54it/s]
Iteration:  3                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 3/3 [00:00<00:00, 12.27it/s]
annotating gene families...                                                                                                                                 
collapse gene families...                                                                                                                                   
Processing depth:  1                                                                                                                                        
Iteration:  1                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████| 14006/14006 [00:03<00:00, 3508.49it/s]
Iteration:  2
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1614/1614 [00:01<00:00, 907.60it/s]
Iteration:  3
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 522/522 [00:00<00:00, 701.74it/s]
Iteration:  4                                                                                                                                               
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 147/147 [00:00<00:00, 552.84it/s]
Iteration:  5                                                                                                                                               
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 44/44 [00:00<00:00, 625.61it/s]
Iteration:  6                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 24/24 [00:00<00:00, 1060.33it/s]
Iteration:  7                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 16/16 [00:00<00:00, 1433.74it/s]
Iteration:  8
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 5/5 [00:00<00:00, 1532.33it/s]
Iteration:  9                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 3/3 [00:00<00:00, 1607.83it/s]
Processing depth:  2
Iteration:  1
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 7536/7536 [00:13<00:00, 546.80it/s]
Iteration:  2
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 242/242 [00:02<00:00, 108.37it/s]
Iteration:  3                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 72/72 [00:00<00:00, 82.39it/s]
Iteration:  4                                                                                                                                               
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 40/40 [00:00<00:00, 131.06it/s]
Iteration:  5                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 14/14 [00:00<00:00, 36.92it/s]
Iteration:  6
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 12/12 [00:00<00:00, 86.81it/s]
Iteration:  7                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 6/6 [00:00<00:00, 37.19it/s]
Iteration:  8                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 2/2 [00:00<00:00, 94.19it/s]
Iteration:  9                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1/1 [00:00<00:00, 76.18it/s]
Iteration:  10                                                                                                                                              
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 2/2 [00:00<00:00, 39.36it/s]
Iteration:  11                                                                                                                                              
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 2/2 [00:00<00:00, 266.66it/s]
Iteration:  12
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1/1 [00:00<00:00, 24.83it/s]
Processing depth:  3
Iteration:  1                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 6915/6915 [01:24<00:00, 81.95it/s$
Iteration:  2                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 125/125 [00:08<00:00, 15.53it/s]
Iteration:  3                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 10/10 [00:00<00:00, 33.04it/s]
Iteration:  4                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 3/3 [00:00<00:00, 26.00it/s]
trimming contig ends...                                                                                                                                     
refinding genes...
Number of searches to perform:  2952773                                                                                                                     
Searching...                                                                                                                                                
translating hits...                                                                                                                                     
Updating output...
Number of refound genes:  143853
collapse gene families with refound genes...                                                                                                                
Processing depth:  1
Iteration:  1                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 5159/5159 [00:03<00:00, 1456.95it/s]
Iteration:  2                                                                                                                                               
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 16/16 [00:00<00:00, 263.60it/s]
Iteration:  3                                                                                                                                               
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1/1 [00:00<00:00, 518.90it/s]
Processing depth:  2                                                                                                                                        
Iteration:  1
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 5137/5137 [00:16<00:00, 314.44it/s]
Iteration:  2                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 16/16 [00:00<00:00, 37.20it/s]
Iteration:  3                                                                                                                                               
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1/1 [00:00<00:00, 148.13it/s]
Processing depth:  3                                                                                                                                        
Iteration:  1                                                                                                                                               
100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 5116/5116 [01:25<00:00, 59.67it/s]
Iteration:  2                                                                                                                                               
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 9/9 [00:00<00:00, 13.59it/s]
writing Roary output...                                                                                                                                     
writing GFF files...
writing gene fasta...                                                                                                                                       
generating core genome MSAs...
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 201/201 [01:30<00:00,  2.22it/s]
writing graph file...
Finished.

samhorsfield96 commented 1 year ago

Hi Ben, there's a number of things it could be:

How many genomes are you analysing? For computational benchmarking with the SPARC dataset, a maximum of 500 genomes were used (running with 616 genomes should not take as long as you are seeing however).
The computational benchmarking did not include core genome alignment, which will significantly increase runtime. You can try using --aligner ref to speed this up.
Check openmp is correctly linked (for multithreading). To do this, activate the ggCaller environment and type which ggcaller. Using the path given, find the library object for ggCaller (will be specific to your install). The path should resemble the example below, run ldd and check libgomp is linked ldd /path/to/conda/envs/ggc_env/lib/python3.9/site-packages/ggCaller-1.3.3-py3.9-linux-x86_64.egg/ggCaller_cpp.cpython-39-x86_64-linux-gnu.so

samhorsfield96 commented 1 year ago

Hi Ben, I ran into the same issue with a fresh install of ggCaller. I debugged it and found there was an issue with openMP linking. I've corrected it on the lastest commit to the master branch (87bb302), please let me know if you run into anymore issues.

samhorsfield96 / ggCaller_manuscript