Recent Slowdown in RMG

[amarkpayne]

I think other people have noticed this as well, but we wanted to post an issue here so that we can have a discussion about it in one place. I believe the slowdown is due to one or more pull requests made on or after our pull-request hackathon.

On my computer, the minimal example has gone from taking 3-4 mins to 7-8 mins. I believe the slowdown becomes more substantial as the model size increases, but I am not entirely sure about this.

I ran the minimal example on a branch I created a few days ago (7-8 min runtime), and a branch I created at the beginning of June(3-4 min runtime). Attached are the RMG profile stats if anyone is interested.
Slow_RMG.profile.dot.pdf
Fast_RMG.profile.dot.pdf

[mjohnson541]

Turning Dynamics Criterion calculations off makes a difference of ~14% in the minimal example. This is implemented automatically in later Accelerator Tools pull requests when the dynamics criterion is unused. However, since these operations scale linearly I would expect it to be significantly less than that for larger models.

[goldmanm]

Improving the accuracy of degeneracy and symmetry meant dealing with all the resonance structures, which at least partially contributes to the slowdown. The greatest contribution to slowing down running RMG from my contributions would be in findDegeneracies, since we are generating resonance structures to eliminate degenerate reactions (instead of just using one molecular graph for comparison). This increases the resonance structure generation from ~2% runtime to ~8% runtime, which is quite substantial (given that the new case runs for longer). This could be reduced by about half if we could access the species already in the core/edge instead of generating new resonance structures in findDegeneracies. However, in parallelization, I am not sure the generate reaction nodes contain information about species in core and edge.

I think some is also due to just comparing many more structures when dealing with all the resonance isomers. In order to get accurate values, isomorphic resonance structures are generated, which are sort of redundant (since it is the same graph), but I haven't found an alternative to yielding accurate symmetry and degeneracy values without them.

[rwest]

If the profile graphics listed the actual (cumulative) time within each function, not just as a percentage of the total time, it would make comparison across different runs easier. (because the total time is different across runs).
Can probably be achieved by tweaking this function https://github.com/ReactionMechanismGenerator/RMG-Py/blob/master/rmgpy/rmg/main.py#L1295

[amarkpayne]

Attached are files with time for each module in seconds (the 2nd entry in parenthesis). Also, I have attached the RMG.log files for each run. The previous RMG version runs the minimal example in 4:33 while the more recent branch runs in 8:55.

Interestingly, I one time forgot to make clean when I switched from the new branch back to the old branch, and it still ran close to 4:33. This suggests that the code in question is not in a compiled file.

Fast.pdf
Fast.txt
Slow.pdf
Slow.txt

[mliu49]

I looked into the degeneracy related areas that I pointed out in #1113 as potentially contributing to the slowdown. The changes are in the degeneracy_speedup branch. For eg1, it reduced the internal time of findDegeneracies by a factor of 3, but it didn't make any difference on the total run time. I'm not sure if it would make a difference for a larger model. I also wanted to compare with the only_core_degeneracy branch, but it encountered an error for eg1.

[alongd]

Feels like the slowdown became even worse lately.
I ran a job which on v2.1.0 took less than 10 minutes:

    Execution time (DD:HH:MM:SS): 00:00:08:32
    Memory used: 446.57 MB
MODEL GENERATION COMPLETED

The final model core has 78 species and 1721 reactions
The final model edge has 312 species and 7522 reactions

but on the current master the same job takes more than 5 hrs:

    Execution time (DD:HH:MM:SS): 00:05:12:12
    Memory used: 460.94 MB
MODEL GENERATION COMPLETED

The final model core has 78 species and 1665 reactions
The final model edge has 310 species and 8826 reactions

(Interesting to note that RMG reports approximately the same memory usage. Both runs done on my local PC a day apart. This run was ethylamine oxidation. I didn't notice any significant change in my observables, [OH] and [NH2])

[mjohnson541]

There is an edge seed generation issue on master right now (an unnecessary operation during seed generation that slowed down model generation significantly for smaller models) The fix is on proper seed mechanisms, but I haven't been able to pull it in yet due to the travis issue. For now turning seed generation off should speed things up. I think it may explain a factor of 2-4x increase in runtime. I assume the rest comes from the degeneracy stuff.

[mliu49]

That's a striking difference. None of the attempts at speedup have been merged into master, but we've still been merging other items. Are you on master for both py and db?

I also think that the latest database PR might have also slowed down model generation, but I'm not sure exactly how. Any chance you could profile your two runs?

[alongd]

Sure. How do I profile a run?
(yes, both repositories were master in the second run)

[mjohnson541]

Now that I think about it I think this is likely the edge seed generation issue. I never looked at it for anything other than the minimal example and the operation squares quadratically with edge reactions. Try running it with seed generation explicitly turned off.

[rwest]

Simplest way to profile is to put -p on the command line:

python $RMGpy/rmg.py -p input.py

[alongd]

OK, I'll do both (profiling on master + turning seed off)
@mjohnson541 , how do I turned off seed generation? (and shall I turn off both Seed and Seed_edge?)

[goldmanm]

I just made a small pull request that turns seed mechanism generation off by default. turn_default_seed_mech_gen_off