_fetch_load_order falls victim to quadratic complexity. Fixing that chops off ~126000 calls and ~0.3s from SSE startup -> 2f16e82f8c6ca8d47ac0cf739bb073c272fffe1eGood read on response times and why 0.1s is important: https://www.nngroup.com/articles/response-times-3-important-limits/
Not entirely related, but Path.__hash__ seems to pick bad hashes. The following dict maps each calling function to the number of Path.__eq__ calls it issued in total during the course of one plugin getting disabled:
{'GetMasterStatus': 18,
'SetFile': 1,
'__contains__': 31,
'__getitem__': 72,
'_children': 1995,
'_fix_load_order': 18,
'_fixed_order_plugins': 24,
'_refresh_mod_inis': 21,
'activeIndex': 10,
'cached_is_active': 30,
'getItem': 7933,
'lindex': 150,
'real_index': 9}
So e.g. all ModInfo.real_index calls combined amount to 9 calls of Path.__eq___. The notable winner here is of course DataTable.getItem, with a whopping 7933 calls.
The line in question is https://github.com/wrye-bash/wrye-bash/blob/ea7a157aed5bb70fbc816bdb7476119e8fc7e56c/Mopy/bash/bolt.py#L1643
Specifically the row in data part. It seems that the hashes returned by Path.__hash__ aren't good enough to place the keys (plugin names in this case) into enough buckets to avoid having to make a ton of comparisons - which of course takes dict performance down from O(1).
And I suspect that the cause is the usage of self._cs for the hash - ModInfo.real_index also hashes plugin names, but uses the proper case instead.
Would using -> not safe :(self._s be safe? And would we need backwards compat for it?
Ref #123, #205, #353
Keep in mind that those keys will be changed to CIstr - so (before fixing it) would be a nice metric for CIstr vs Path (and I can't tell who wins at this point!)
And no we can't use the .s I'm afraid - the ancient coupling between hash and equals :)
(edit: in short I was looking to the same thing from another prism - nice that this getItem surfaced also here - real fix (but not yet exactly for profiling!!) is tables being a double defaultdict - I mean maybe :P )
Btw, if you notice _children with some 2000 calls in there, that's an entirely different problem - we don't cache those (dependents) at all, but we should.
Ref #498, which will need that as well.
And a quick protip: if you google something like 'get calling method python', the first results will all lead you to something like this:
curframe = inspect.currentframe()
calframe = inspect.getouterframes(curframe, 2)
print(calframe[1][3])
Which works, but is insanely slow when you call it a lot (e.g. those 8000 times above). I didn't let it finish, but it ran for more than a minute. Way, way, way faster, with the only downside being that it's CPython-only:
print(sys._getframe().f_back.f_code.co_name)
And one more note:
20 0.002 0.000 0.016 0.001 bash\bosh\__init__.py:2616(get_bsa_lo)
Remember that cool BSA load order I implemented in 6aec0ce6f29a5dfb71b7f856143b439cf00be8d6? Turns out calculating it that many times has an overhead of ~0.02s per _refreshMissingStrings call. Caching it would be great, but invalidation would be hard. Changes to load order, modInfos, bsaInfos and iniInfos would have to invalidate it, or even better, part of it.
So not an attainable goal right now. Ref #233 as well.
Done for today. That took about 10 hours in total, but I managed to get it down to ~0.1s on my SSE setup (which is pretty gigantic).
I still want to figure out why disabling is slower than enabling, but that will have to wait for tomorrow.
All remaining wasted performance is in details refresh - e.g. we do SelectAndShowItem twice, apparently because of a bug (ff358ef897223ec59297c70c7f0a6da8e4a7e799) and we refresh the entire details panel even when the selected plugin hasn't changed at all (but we can't just check if old file path == new file path because the file contents may have changed - needs more sophisticated invalidation). Ref #353.
Interesting performance tidbit:
PS C:\Users\Infernio> py -2 -m timeit -s "a = set()" "a |= {0}"
10000000 loops, best of 3: 0.0594 usec per loop
PS C:\Users\Infernio> py -2 -m timeit -s "a = set()" "a.update({0})"
10000000 loops, best of 3: 0.0957 usec per loop
PS C:\Users\Infernio> py -3 -m timeit -s "a = set()" "a |= {0}"
5000000 loops, best of 5: 68.7 nsec per loop
PS C:\Users\Infernio> py -3 -m timeit -s "a = set()" "a.update({0})"
5000000 loops, best of 5: 90.4 nsec per loop
|= is always faster than update(), probably because update is a method call.
Edit: but not if you need to convert something else to a set for that:
PS C:\Users\Infernio> py -2 -m timeit -s "a = set()" "a.update([0])"
10000000 loops, best of 3: 0.156 usec per loop
PS C:\Users\Infernio> py -2 -m timeit -s "a = set()" "a |= set([0])"
1000000 loops, best of 3: 0.211 usec per loop
PS C:\Users\Infernio> py -3 -m timeit -s "a = set()" "a.update([0])"
5000000 loops, best of 5: 81.5 nsec per loop
PS C:\Users\Infernio> py -3 -m timeit -s "a = set()" "a |= set([0])"
2000000 loops, best of 5: 122 nsec per loop