Created attachment 373417 [details] Instruments trace Hi! I've been using GnuCash 2.x for a while on OSX. I tried upgrading to 3.x a few times over the past few years but always found the UI to be painfully slow. With OSX Catalina being released today I will soon be forced to upgrade, as the 2.x app is a 32bit application. I've linked below a screen recording of me clicking around on the accounts list. As you can see there is a significant, random delay that occurs when selecting accounts. Similar delays occur when opening an account or just generally navigating in the UI. This is running on a top of the line macbook pro with 8 cores, 32GB ram and a Vega 20 GPU. I have nothing significant running in the background. Profiling with Instruments shows the main thread pegged at 100% of one core. Most of the time spent seems to be related to prices. Namely from direct_balance_conversion() to price_list_from_hashtable() to g_list_copy(). I do have a lot of prices in my file. 221,581 to be precise. From an uninformed look at the code it looks like it is g_list_copy-ing those entries from multiple places in the main thread? Link to screen recording and profiler screenshot https://imgur.com/a/NQieI1w Attached is the full Instruments trace. Please let me know if I can do anything to help. Thanks a lot, Adrien
You didn't analyze that profile very well. Yes, the "hot trace" leads to g_list_copy and its attendant g_slice_alloc, but that takes up only 2 seconds of the 14 for that particular redraw. Other functions further up the stack are eating more of the time. There seem to be two other redraws taking 3 seconds each. Did you have more than one GnuCash window or dialog open when you took the profile? Bob Fewell, we've set gnc_account_get_value() as the tree model's modify_func. It's called every time the Accounts page is redrawn and that seems to be a real time-sink on this user's book. Can you see a way to cache the values and only recalculate when the there's a change?
Ah, my bad! I was trying to provide some context as I know something being "slow" is not a great bug report, but to be honest I've only played with Instruments a couple times. I can see you were able to pinpoint a hot spot candidate so I'm happy. I did not have another window/dialog open, but I did click more than once in the window, maybe that's what the redraws are about? Do you need a more precise profile?
I don't think so, but let's wait for Bob to weigh in. He doesn't do Mac so he won't be able to read the profile, but may have some useful questions that I can work out from the profile you've provided. Redraws are triggered by all sorts of things. Selecting an account will trigger one because the selection highlight has to be placed on the new line--and the UI isn't usually smart enough to realize that the new line is the same as the old line and there's actually no change. The application's code is supposed to keep track of that if it wants to. The information that you clicked more than once suggests looking at smaller time-slices in the profile to see if I can work out a timeline of what's happening. You could run a little experiment to check the "too many prices" hypothesis: Make a copy of your file with File > Save As..., which will switch you to the new one. Open Tools > Price Database and select "Remove Old". Pick a date and a last-price policy and go. Twiddle your thumbs for a few minutes while it does that. When it's done see if it's any faster.
Created attachment 373419 [details] Updated instruments trace
A first try of deleting prices, selecting the "Last Week" option, removed 80% of entries (leaving around 600 per commodity, so around 50k). The UI was snappier but I could still see random lag occurrences when clicking around the account list. Going further and removing all prices except the last month (leaving around 3k total), I don't have random lag anymore. This seems to confirm the large number of price entries I keep is the source of the lag. I did notice a further slow down though: with the database cleaned, I have around 1sec of lag when expanding or collapsing entries in the account list. I've attached a new profile to the report. Still looks related to determining currency values to my untrained eye. Here is a screen recording https://imgur.com/a/sOtW3Z9
Just confirming some details, I wonder if it also to do with what columns are being displayed, trace file probably does not have that detail regarding time spent on each column values? John, I assume you meant gnc_tree_model_account_get_value() Adrian, can list all the columns being displayed on the Accounts page.
Columns are: Name, Description, Total, Total (EUR). Tried removing the last one to maybe avoid some conversions but the behaviour is the same.
Bob, sorry, yes gnc_tree_model_account_get_value().
I have added a cache for the model account values, PR589. It seems quicker but I probably do not have the same level of prices / accounts as reported. Will await feedback on PR.
Amazing! I'll happily try out a development build and report back if you can send me a binary
https://sourceforge.net/projects/gnucash/files/Development/Gnucash-3.7-Test.dmg/download
Just tried it and unfortunately it doesn't look like this build is helping. I'll attach a profile of me expanding and closing one account branch, using this build
Created attachment 373425 [details] Trace with development build
Roughly same amount of time (4 3/4 seconds) in a single click-response. The main difference between the cached and uncached traces is that the uncached one spends about a second in gnc_ui_account_get_print_report_balance and the cached version spends that second in gnc_account_ui_get_print_balance instead, spending 2.7 seconds there in the uncached version and 3.7 seconds in the cached version. Note that there are two branches in the MacOS redraw code, one taking ~4.7 seconds and the other ~1.5 and that in both of them gnc_tree_model_account_get_value consumes ~95% of the time; the times above are for the 4.7 branch. The other second is used by gnc_tree_model_compute_period_balance. The time used in gnc_account_ui_get_print_balance for the cached version is 1.75 xaccAccountGetBalanceInCurrency 1 xaccAccountGetPresentBalanceInCurrency 1 xaccAccountGetProjectedBalanceInCurrency All of which do basically the same thing: They walk the tree of subaccounts collecting the indicated balances and converting them to the root currency at the latest price.
I think I have found my mistake, I was using NULL as an indicator of cached value and I should of been using g_has_table_lookup_extended. Will have a look at changing this and report back.
I pushed another attempt at this which hopefully does what is required. As stated above I was not caching returned NULL values from ...print_balance functions and needed to use the lookup_extended function to determine if a value was in the cache. John, if you have time, would it be possible for you to create a new binary for Adrian to try.
NP, https://sourceforge.net/projects/gnucash/files/Development/Gnucash-3.7-Test2.dmg/download
John, is this the correct binary? It has a build id of "git 3.7-135-gb6ca533+(2019-10-15)" which is the date of the first one you sent me (I don't have that one anymore to compare). Asking because I'm not seeing a change in behaviour.
Yes, as long as it says it's Gnucash-3.7-Test2 in Finder. I just pulled in the changes and recompiled without running cmake, which is what sets the version in the About Gnucash... window and the splash screen.
Nope, strike that. I hadn't done "ninja install" so it was in fact the old binary. I'll get a new one up in an hour or so (it takes about that long for Apple to do its notarization dance).
Apple was slow, it took over 6 hours to do the notarization! https://sourceforge.net/projects/gnucash/files/Development/Gnucash-3.7-Test3.dmg/download
Just tried out the binary and I can confirm that it is much, much better! The UI is very fast now. Thanks for fixing this and for the quick turnaround.
I have pushed the changes to maint so will be in the next release.
