Created attachment 157810 [details] backtrace while freezed SUMMARY When trying to display any account ledger that has a large amount of transaction (1k+) cpu goes to 100% and KMyMoney freeze and has to be killed. Maybe I wasn't patient enough and it would have respond back, but more than a few minutes would still make no sense. Also, I'm guessing it related to the amount of transaction since it only happen on a few of my larger account, but maybe some specific transaction that are more likely to happen there or more reconciliation. The culprit seems to be arround this: #13 0x0000555555b452bc in SpecialLedgerItemFilterPrivate::filterAcceptsRow(QModelIndex const&, QModelIndex const&, int) const (rowCount=977, source_parent=..., idx=..., this=<optimized out>) at /build/kmymoney/models/specialledgeritemfilter.cpp:288 #14 SpecialLedgerItemFilterPrivate::filterAcceptsRow(QModelIndex const&, QModelIndex const&, int) const (this=<optimized out>, idx=<optimized out>, source_parent=..., rowCount=<optimized out>) at /build/kmymoney/models/specialledgeritemfilter.cpp:217 and caused by https://github.com/KDE/kmymoney/commit/281c9759045f2a7929264accb58638ed250cf418 or later (did rollback to f3b33e9 and it work, haven't try forward reproducing the issue. STEPS TO REPRODUCE 1. open ledger on any large account, either from the account page or the ledger itself switching to another tab OBSERVED RESULT freeze EXPECTED RESULT display the ledger SOFTWARE/OS VERSIONS Linux/KDE Plasma: (available in About System) 5.104.0 KDE Plasma Version: KDE Frameworks Version: Qt Version: 5.15.18 Built statically through the docker compose provided, but ran locally on my arch ADDITIONAL INFORMATION
How long did you wait? I've also seen master version become very slow (several minutes at least) recently when opening almost any account in the ledger, but it does seem worse with an account with very many transactions. I've been trying to get a profile of the program when that happens, but I have not yet gotten it. Remember, this is master branch, and although there are several people who do use it on a day-to-day bases, it should be considered experimental, with no guarantee of behavior, performance, or even working.
I just had it take over 11 minutes to open one ledger. I've got a gmon.out (1.4M,) but I don't think that's useful without the executable (58M) or I could post the output of gprof, which is about 3M. I'm not sure it's worth posting the profile unless it will help - I cannot interpret it yet.
I only waited a few minutes, 3 or 4 at most. I know it's master and don't expect support on it but if isolated better raise it sooner than just before release
We definitely do want to know about problems in master sooner than later. Hopefully I can get some hints from the profile, otherwise I'll post it in case someone else has a better crystal ball.
I totally agree that we need feedback on the behavior of master, so thanks for raising the bug. Looking at the bt provided, I notice a recursive call when checking reconciliation entries (lines 217 and 288 in SpecialLedgerItemFilterPrivate::filterAcceptsRow). Seems you have many reconciliations in that account without transactions in between or have filtering and sorting setup so that it causes this scenario. Opening my main account takes at most a second with 6508 transactions (on a 2.2 MHz cpu) with 15 reconciliation entries. I don't think we need the profiler data as it seems that we know where it happens. We need to find what data / filter & sorting setting is causing this. Maybe, you can provide more details. BTW: here's how I counted them (replace A000076 with the ID of your account): gpg -d thb.kmy | grep '<SPLIT' | grep 'A000076' | wc -l or if you don't use GPG encryption zgrep '<SPLIT' xxx.kmy | grep 'A000076' | wc -l
Thanks for the info. Quickly looking at my file I don't see what filtering could make this happen. Currently on the the f3b33e9 commit I can't see any "empty" reconciliation. Only possible filter would be the "hide reconciliation transaction" option, but as it is off by default, I did try with it both enabled and disabled with the same result. One thing that might be related thought is that my account was opened in 2013 and It appear I did my first reconciliation in 2019 (I kind of doubt about it but cannot be certain, it does match the number I had in a backup from 2020. maybe the file format changed and only last reconciliation was saved at one point?) So that first reconciliation would span 2013 to 2019. The other thing is I havent properly done all my reconciliation in the last year. This specific account I'm looking at has last reconciliation a year ago, with probably a ~100 transaction after it. Looking at the transaction count, I have "only" 2087 in that specific account. I'm not properly setup to debug, but I could add logs if you see something that could be helpfull. Let me know if I can investigate anything else
My own data file has one account with 2815 transactions, but smaller accounts also showed similar slowness, perhaps not as extreme. How would I count the reconciliations in it? My own data file has one account with 2815 transactions, but smaller accounts also showed similar slowness, perhaps not as extreme. How would I count the reconciliations in it? Yesterday I did post a profile to the dev mailing list, and it does show one cycle, seeming to confirm the recursion.
While working on my document (still with old version) I notice I got a lot of error of this type: * Sum of splits in transaction 'T000000000000023881' posted on 2022-10-27 is not zero. Account: Passif:****, Amount: (13,79 $) Those are all transaction I haven't yet setted a category which explain the error (although, being notified on every save is a bit annoying, but that's another issue) I have 290 of those error currently, and it might match the accounts that are getting very slow (obviously it's the account with more transaction that take more time for me to properly cleanup) At least two of them are concerned
@Jonathan: I doubt that the number of 'erroneous' transactions has any influence on this problem. Can you try changing the information heading settings in Settings/Ledger and see if turning them off makes a difference? Which one has the most impact? My first split in the account has a post date of 2001-12-28 and was reconciled on 2005-03-20. The first stored reconciliation date that may provide a header is dated 2021-01-31 (because KMyMoney did not keep that piece of information in earlier versions). So I am not sure that these dates have an influence as mine are wide spread too. @Jack: I was able to see the reconciliations of my account using (you may have to vary the 50 depending on your account tree). It shows a long list of date,value pairs. gpg -d thb.kmy | grep -A 50 -e '<ACCOUNT.*id="A000076"' | grep 'reconciliationHistory' | less
And one more question: what is the sort order (field and direction) that you have setup?
Created attachment 157957 [details] filters-settings
Created attachment 157958 [details] sort-settings
Created attachment 157959 [details] display-settings
Added a few maybe related settings, including the sort config. The specific account ledger use the default settings. Also maybe related, I use a lot scheduled transaction and display the next 30 days in the ledger as well as display past schedule at the planned date. I'll test the various sort settings on my side but might take a few hours
(In reply to Thomas Baumgart from comment #9) Apologies, I really don't know what I was thinking about - I see you meant the reconciliation history, or number of reconciliations remembered. In some of my problem accounts, I have over 25 reconciliations, as I reconcile monthly, and it appears it was early 2021 when KMM started remembering them. Might the problem be related to KMM trying to confirm that the balance from the reconciliationHistory KVP matches the ledger balance on that date? It seems possible that the slowness started around the time there were some changes to the sorting of the ledger, and I don't remember if you made and code changes after our discussions about some reconciliation separators showing up in red.
(In reply to Jack from comment #15) > (In reply to Thomas Baumgart from comment #9) [...] > Might the problem be related to KMM trying to confirm that the balance from > the reconciliationHistory KVP matches the ledger balance on that date? No, I don't think so. The balances are cached and the comparison is done when the header is actually displayed on screen (https://invent.kde.org/office/kmymoney/-/blob/master/kmymoney/views/reconciliationdelegate.cpp#L84). > It seems possible that the slowness started around the time there were some > changes to the sorting of the ledger, and I don't remember if you made and > code changes after our discussions about some reconciliation separators > showing up in red. Yes, those corrections were made. The headers should not show up in red anymore.
I found a small account that show the performance issue on a small scale so I was able to do a bunch of (not quite scientific) tests, I still did all of them twice in a row to confirm, unless noted, reverted the previous change: original settings (as in above attachment): 11 sec nothing checked in settings -> ledger -> display: 11 sec Hiding reconciled transaction: 18 sec *note 1* settings -> ledger -> display -> Don't show reconciliation entries : instant settings -> ledger -> display -> Show last reconciliation entry... : instant original was settings -> ledger -> display -> Show all reconciliation entries... : 11sec *note 2* settings -> ledger -> display -> Show last reconciliation entry... and Hiding reconciled transaction : instant settings -> ledger -> filter -> by type first: 6 sec, although it does remove the header by definition settings -> ledger -> filter -> by payee first: 6sec, which also remove the header by definition * note 1: when switch the settings from the view menu while in the ledger, I get a segfault, I could open a new issue if info needed * note 2: weirdly, if I'm on the ledger and I "apply" change to the "show reconciliation header" setting, which ever I choose including "all" update instantly in the back. Let me know if some other settings config could be useful. It's quite easy now to the the performance on that account, which to be clear isn't one of the original account I raise the issue, but still 11-18 sec to open the ledger is still an issue. > Yes, those corrections were made. The headers should not show up in red anymore. I still have red reconciliation header in that account I was able to test. I was trying to find distinction with others similar account that didn't had issue. And this might be the biggest difference. Although my checking account (the original large account) do not have red reconciliation header
adjusting state
I just reconciled an account, and had the full delay when opening the account in the ledger, when starting the reconcile wizard, when hitting "Continue" on the last page of the wizard, and yet again when I hit "Finish." In the second and fourth cases, there is a delay before the pop-up window is displayed, and a further delay before that window is actually populated with its content. I agree with the findings in Comment #17 with some additional notes. If I hit "Ctl-R" to remove display of reconciled transactions, the immediate effect is just to remove the transactions, but a few seconds later, all except the last Reconciled header also disappear. In addition, closing and then opening the file in this state shows the delay when first displaying the ledger. If anyone wants it, I have a small (41K) sample xml file with one account, 60 transactions, 120 splits, and 21 reconciliations. The delay is only a few seconds, but it's clearly different from the near instant display when all reconciliation headers are not displayed.
> In addition, closing and then opening the file in this state shows the delay when first displaying the ledger. Forgot to mention that behavior, I believe the first ledger tab get rendered even if we go straight to another account(ie from the home page), which I guess is fine if really quick, but not quite necessary. With the current issue, it create the delay even if opening a small amount that is not affected.
Git commit 7f771f516ace05813827b7ef94a200864d071532 by Thomas Baumgart. Committed on 17/04/2023 at 12:55. Pushed by tbaumgart into branch 'master'. Speed up ledger display Don't do extensive checking when source model is unsorted to avoid massive recursive calls. FIXED-IN: 5.2 M +9 -0 kmymoney/models/ledgersortproxymodel.cpp M +2 -0 kmymoney/models/ledgersortproxymodel.h M +6 -0 kmymoney/models/ledgersortproxymodel_p.h M +15 -1 kmymoney/models/specialledgeritemfilter.cpp https://invent.kde.org/office/kmymoney/commit/7f771f516ace05813827b7ef94a200864d071532
Thanks Thomas. I confirm this fix does seem work - no more delays with either my own data or the test file.