2021-09-14 GnuCash IRC logs
00:08:10 *** fell has joined #gnucash
00:08:10 *** ChanServ sets mode: +o fell
00:15:41 *** fell has quit IRC
00:29:53 *** Mechtilde has joined #gnucash
00:31:12 *** fell has joined #gnucash
00:31:12 *** ChanServ sets mode: +o fell
00:40:31 *** Jeanl has joined #gnucash
00:43:32 *** Jeanl has quit IRC
01:43:52 *** frakturfreak1 has joined #gnucash
01:45:50 *** frakturfreak has quit IRC
01:47:06 *** Mechtilde has quit IRC
01:49:04 *** fell has quit IRC
01:50:23 *** fell has joined #gnucash
01:50:24 *** ChanServ sets mode: +o fell
02:19:18 *** mikee has quit IRC
02:20:04 *** mikee has joined #gnucash
02:51:17 *** Hamaryns has joined #gnucash
02:51:17 *** ChanServ sets mode: +v Hamaryns
03:06:41 *** Bambuzel has joined #gnucash
03:06:41 *** ChanServ sets mode: +v Bambuzel
03:30:39 *** jonp` has joined #gnucash
03:32:41 *** jonp has quit IRC
03:34:50 *** Mechtilde has joined #gnucash
03:48:31 *** fell has quit IRC
03:48:50 *** fell has joined #gnucash
03:48:51 *** ChanServ sets mode: +o fell
04:07:06 *** User has joined #gnucash
04:18:20 *** bertbob has quit IRC
04:25:28 *** bertbob has joined #gnucash
04:25:28 *** ChanServ sets mode: +v bertbob
04:26:16 *** jervin has quit IRC
04:29:47 *** JeffQ has joined #gnucash
04:29:47 *** ChanServ sets mode: +v JeffQ
04:42:51 *** Hamaryns has quit IRC
04:50:02 *** chris has quit IRC
04:57:26 *** Hamaryns has joined #gnucash
04:57:26 *** ChanServ sets mode: +v Hamaryns
06:07:29 *** Bambuzel has quit IRC
06:14:19 *** Hamaryns has quit IRC
06:20:05 *** Hamaryns has joined #gnucash
06:20:05 *** ChanServ sets mode: +v Hamaryns
06:50:49 *** Hamaryns has quit IRC
06:58:11 *** chris has joined #gnucash
06:58:11 *** ChanServ sets mode: +v chris
07:33:35 *** Aussie_matt has joined #gnucash
08:12:15 *** gjanssens has joined #gnucash
08:12:16 *** ChanServ sets mode: +o gjanssens
08:39:05 *** Jimraehl1 has joined #gnucash
08:39:39 *** Jimraehl1 has quit IRC
08:52:07 *** sbluhm has joined #gnucash
08:53:02 *** Mechtilde has quit IRC
09:11:29 *** tomk_dk has joined #gnucash
09:14:39 *** sbluhm has quit IRC
09:33:20 *** Mechtilde has joined #gnucash
09:38:24 *** Pegasus_RPG has joined #gnucash
10:10:59 *** Aussie_matt has quit IRC
10:31:42 *** jervin has joined #gnucash
10:42:53 *** jervin has quit IRC
10:55:52 *** Pegasus_RPG has quit IRC
11:03:10 *** Pegasus_RPG has joined #gnucash
11:11:16 *** Mechtilde has quit IRC
11:18:37 *** guak has joined #gnucash
11:23:12 <fell> jralls, was the version bump intended in yor last commit?
11:23:29 <jralls> fell, Crud. No.
11:30:25 <jralls> Restrored.
11:31:06 <fell> thanks!
11:59:50 *** kcin has joined #gnucash
12:12:05 *** storyjesse has quit IRC
12:57:57 *** kcin has quit IRC
12:59:42 <jralls> Simon, I'm working on https://bugs.gnucash.org/show_bug.cgi?id=798237. I don't quite follow you on the minimum output log level idea.
13:01:48 *** jervin has joined #gnucash
13:06:51 *** sbluhm has joined #gnucash
13:27:52 *** sbluhm has quit IRC
13:32:14 *** sbluhm has joined #gnucash
13:48:00 <Simon> jralls: if there is a *global* minimum log level (i.e. "info") then you can have a fast path in the code that ignores debug log messages entirely, instead of trying to look up the log level for the current module
13:48:23 <Simon> when you have at least one module actually configured for debug logging, you lower that minimum level
13:49:52 <Simon> all you'd need to do for that is iterate through all the configured module log levels whenever one is changed and find out what the lowest level is
13:50:01 <jralls> Simon, OK, that's what I thought. Neither that nor switching from string to string_view makes any difference in the profile.
13:50:21 <jralls> Were you using gcc prof instead of a sampling profiler?
13:51:13 <Simon> I was using cachegrind, but a couple of the log statements were half the execution time so those were measured with "time"
13:51:36 <Simon> https://github.com/nomis/gnucash/commit/8801b3d1f2a5c9a494f1cefc0c3cecb705d05e26
13:52:08 <Simon> the "#if 0" part isn't necessary, I was just removing everything I could get away with
13:53:02 <Simon> how quickly does it get from DEBUG() to returning based on a minimum log level?
13:54:04 <Simon> half the time was spent on checking prices for duplicates too
13:54:43 <jralls> That commit hasn't been merged into gnucash. There aren't any logging entries in the Apple Instruments profile trace at all.
13:55:15 <Simon> I know it hasn't, because I don't expect you to remove logging calls
13:58:11 <Simon> 25.6s to load... I think I have the wrong code installed because it should be under 10s
13:59:02 <Simon> back down to 8.9s now
13:59:15 <jralls> Eh, not quite true that there's no logging calls. There's no qof_log that shows up. There's 2 seconds out of 12.5 in g_log called from sixtp_sax_end_handler.
13:59:21 * Simon reverts https://github.com/Gnucash/gnucash/commit/e901adf97abe06ca145c3c7f0b1ae04fd18b98a1
13:59:25 <jralls> How big is the file, uncompressed?
13:59:41 <Simon> 61MB, and it is stored uncompressed
14:00:28 <jralls> And mine is 53M, so comparable.
14:00:34 <Simon> 12.2s if I re-enable logging
14:00:45 <Simon> I'll try reverting https://github.com/nomis/gnucash/commit/8801b3d1f2a5c9a494f1cefc0c3cecb705d05e26 now
14:01:34 <jralls> Again comparable to my 14s; the profiler slows things down a bit.
14:02:00 <Simon> now it's 27s
14:02:36 <jralls> Interesting. Try switching to the latest maint.
14:04:13 <Simon> I've also got https://github.com/Gnucash/gnucash/commit/3173f9043f6b8ac491dba554fd4fe4aee12c3c3e that made 2.6 faster but has no measurable impact on 4.6; I bought a faster CPU since then though
14:09:17 <jralls> Interesting that it doesn't affect 4.x. I really hated having to put that in but we were getting crashes from bad copy-and-paste operations inserting partial UTF-8 codepoints.
14:14:33 <Simon> rebased against 574f567b625d3a175ba153bb1c63a0d14e8dd75a; 8.8s, with logging 12.3s, without commented out xml logging 17.s
14:15:33 <Simon> 1299 accounts, 24416 transactions, 45465 prices
14:18:06 <jralls> Is it actually logging anything?
14:18:19 <Simon> I've updated my sa branch so those commits will have moved; sa-2021-08-24 is the old one
14:18:39 <Simon> not during file loading, no
14:18:51 *** Mechtilde has joined #gnucash
14:19:08 <Simon> before I rebased I was getting error log messages so I should really have logging enabled... but it slows down the loading
14:19:30 <Simon> 9the errors were after file loading had finished)
14:20:05 <Simon> 19:01:48 ERROR <gnc.engine> [xaccSplitCommitEdit()] Account lost track of moved or deleted split. <-- but this is gone now
14:20:31 <Simon> I think that's in the book end process, which differed slightly in my branch
14:24:36 <jralls> No, it's part of xaccTransCommitEdit. It gets called for every transaction in dom_tree_to_transaction.
14:25:37 <Simon> in any case, it's a gui app so I'd never normally see the log messages
14:26:22 <Simon> although the python code will email me from cron
14:26:40 <Simon> 40% overhead on loading to be able to see log messages is a significant amount of itme
14:26:42 <Simon> time*
14:27:57 <jralls> You don't have to look at them for them to take time. But it's weird that you're seeing that logging overhead when I see so little.
14:34:49 <Simon> you see no difference in total time at all?
14:34:58 <jralls> Heh, just figured out why qof_log_check changes make no difference on load: It's used only for the ENTER/LEAVE macros.
14:35:38 <Simon> are you sure? it's called by log4glib_handler
14:36:29 <Simon> do you get a difference in load time if you apply either of my two commits?
14:36:54 <Simon> the number of prices probably has an impact on total XML function calls
14:37:04 <jralls> Well, I got a 2 second saving from commenting out https://github.com/Gnucash/gnucash/blob/574f567b625d3a175ba153bb1c63a0d14e8dd75a/libgnucash/backend/xml/sixtp.cpp#L569.
14:41:10 <jralls> I just got your sa branch, I'll build that and profile it.
14:43:42 <jralls> 10.19 secs with your branch vs. 14.13 with unmodified maint.
14:45:39 <jralls> That's total run time of qof_session_load_from_xml_file_v2_full.
15:03:46 *** tomk_dk has quit IRC
15:22:37 *** frakturfreak1 has quit IRC
15:39:45 *** gjanssens has quit IRC
15:44:01 *** JeffQ has quit IRC
16:32:58 *** sbluhm has quit IRC
16:38:26 *** User has quit IRC
16:43:45 *** ArtGravity has joined #gnucash
16:43:45 *** ChanServ sets mode: +v ArtGravity
17:19:47 *** frakturfreak1 has joined #gnucash
18:47:11 <Simon> jralls: this looks unintentional? https://github.com/Gnucash/gnucash/commit/74d0630867c6cfbb509db2f4ca7edb722db82956#diff-5dd0479d237691832584ffaf7bbecc6ef34f02419be0208f9d4c4dfd2e3348cbL96-R96
18:50:30 <Simon> the comments in qoflog.h too
18:51:21 <jralls> Simon, thanks, yes, a sed regex that got away.
18:51:48 <Simon> qoflog.h needs a reword since it states a preference for using glib functions
18:52:18 *** Pegasus_RPG has quit IRC
18:52:24 *** Pegasus_RPG has joined #gnucash
18:59:16 <jralls> Simon, done.
19:05:43 *** Pegasus_RPG has quit IRC
19:13:53 <Simon> jralls: gnc_scm_loDEBUG exists elsewhere in the code too
19:14:11 <Simon> libgnucash/core-utils/gnc-glib-utils.c:gnc_scm_loDEBUG(const gchar *msg)
19:14:14 <Simon> libgnucash/core-utils/gnc-glib-utils.h:void gnc_scm_loDEBUG(const gchar *msg);
19:14:22 <Simon> I'll try the modified logging code tomorrow
19:14:57 <jralls> Simon, thanks.
19:18:37 <chris> jralls: how about PWARN old fns like DxaccAccountSetCurrency and friends and remove in 5.x
19:20:41 <jralls> chris, I don't think that the runtime message does anything for us and we don't yet guarantee API stability for C/C++. If they're not swigged they can just be deleted.
20:15:26 *** guak has quit IRC
20:49:43 *** bertbob has quit IRC
20:50:54 *** bertbob has joined #gnucash
20:50:54 *** ChanServ sets mode: +v bertbob
20:53:00 *** storyjesse has joined #gnucash
20:54:09 *** bertbob has quit IRC
20:57:55 <chris> DxaccAccountSetCurrency is swigged unfortunately
20:58:38 *** bertbob has joined #gnucash
20:58:38 *** ChanServ sets mode: +v bertbob
21:02:54 *** bertbob has quit IRC
21:11:48 *** bertbob has joined #gnucash
21:11:48 *** ChanServ sets mode: +v bertbob
21:17:09 *** bertbob has quit IRC
21:32:20 *** Pegasus_RPG has joined #gnucash
21:35:47 <chris> sugar...
21:40:12 <chris> jralls: ok i'm not sure why CI fails past few commits, I hope it's not caused by mine
21:40:29 <chris> no time for me to invx gtg now
21:50:44 *** bertbob has joined #gnucash
21:50:44 *** ChanServ sets mode: +v bertbob
22:06:33 *** jralls has quit IRC
22:08:34 *** jralls has joined #gnucash
22:08:34 *** ChanServ sets mode: +o jralls
22:15:11 *** KipITOne has joined #gnucash
22:15:12 *** ChanServ sets mode: +v KipITOne
22:18:27 *** Pegasus_RPG has quit IRC
22:29:54 *** KipITOne has quit IRC
22:30:37 *** KipITOne has joined #gnucash
22:30:38 *** ChanServ sets mode: +v KipITOne
22:36:24 *** KipITOne has quit IRC
22:40:46 *** jralls_afk has joined #gnucash
22:40:46 *** ChanServ sets mode: +o jralls_afk
22:41:41 *** jralls has quit IRC
22:59:35 *** KipITOne has joined #gnucash
22:59:35 *** ChanServ sets mode: +v KipITOne
23:21:19 *** KipITOne has quit IRC
23:22:27 *** KipITOne has joined #gnucash
23:22:27 *** ChanServ sets mode: +v KipITOne
23:23:09 *** KipITOne has quit IRC
23:23:52 *** KipITOne has joined #gnucash
23:23:52 *** ChanServ sets mode: +v KipITOne
23:30:27 *** TownsendHardware has quit IRC
23:57:36 *** TownsendHardware has joined #gnucash