Startup troubles for 2.4.0 under OS X

[John Ralls]

On Feb 6, 2011, at 9:36 PM, David T. wrote:

> 
> 
> --- On Sun, 2/6/11, John Ralls <jralls at ceridwen.us> wrote:
> 
>> From: John Ralls <jralls at ceridwen.us>
>> Subject: Re: Startup troubles for 2.4.0 under OS X
>> To: "David T." <sunfish62 at yahoo.com>
>> Cc: gnucash-user at lists.gnucash.org
>> Date: Sunday, February 6, 2011, 8:54 PM
>> 
>> On Feb 6, 2011, at 8:44 PM, David T. wrote:
>> 
>>> The compressed file is 1.8 MB. XML. Intel Mac running
>> 10.5.8. It is the only data file I have.
>>> 
>>> Typically, this part of start up takes 30 secs. I
>> *thought* I put in a bug about the start up running
>> thousands of sql transaction checks (or something like it),
>> but I can't seem to find that at bugzilla or on the list
>> archives. 
>>> 
>>> I just looked in gnucash.trace, where I see 5MB of
>> statements like the following:
>>> 
>>> * 17:01:28  INFO <gnc.engine>
>> [trans_cleanup_commit] get rid of rollback trans=0x11788440
>>> * 17:01:28  INFO <gnc.engine>
>> [xaccTransSetDateInternal] addr=0x11788220 set date to
>> 1061276400.000000000 Tue Aug 19 00:00:00 2003
>>> * 17:01:28  INFO <gnc.engine>
>> [xaccTransSetDateInternal] addr=0x11788220 set date to
>> 1157752805.000000000 Fri Sep  8 15:00:05 2006
>>> 
>>> I honestly don't understand why the hell it's doing
>> this. While it *does* process about 25 of these a second, it
>> does enough of them to take 4 minutes and 40 seconds of
>> these. Why would xaccTransSetDateInternal run in excess of
>> 7000 times on start up?
>>> 
>>> David
>>> 
>>> Ps: I will add info to the wiki about how to track
>> down gnucash.trace and the console logfile on Mac, since I
>> can never remember the steps to locate these files
>>> --- On Sun, 2/6/11, John Ralls <jralls at ceridwen.us>
>> wrote:
>>> 
>>>> From: John Ralls <jralls at ceridwen.us>
>>>> Subject: Re: Startup troubles for 2.4.0 under OS
>> X
>>>> To: "David T." <sunfish62 at yahoo.com>
>>>> Cc: "Users Gnucash" <gnucash-user at gnucash.org>
>>>> Date: Sunday, February 6, 2011, 6:09 PM
>>>> 
>>>> On Feb 6, 2011, at 5:10 PM, David T. wrote:
>>>> 
>>>>> And again, I am staring at 4 minutes start up
>> at the
>>>> "Loading User data" prompt.
>>>>> 
>>>>> This is REALLY ANNOYING. Can anyone explain
>> why this
>>>> happens some times but not others?
>>>>> 
>>>> 
>>>> What kind of file? How big? Do you have only the
>> one?
>>>> Remind me how long it takes when it loads quickly,
>> and what
>>>> kind of mac you're using.
>> 
>> If it's an XML file I'm not likely to connect it with a
>> SQLite bug unless you hit me over the head with it... which
>> the xaccTransDateInternal may have done. Is there a
>> correspondingly huge log file? If there is, does it show
>> what dates are getting changed?
> 
> I am not seeing huge log files today, but I have in the past.
> 
> When I look at the log file just now I see:
> 
> mod	trans_guid	split_guid	time_now	date_entered	date_posted	acc_guid	acc_name	num	description	notes	memo	action	reconciled	amount	value	date_reconciled
> -----------------
> ===== START
> ===== END
> ===== START
> ===== END
> ===== START
> ===== END
> ===== START
> ===== END
> ===== START
> ===== END
> ===== START
> D	3419d8045ad74cf434e1599f56f18218	6899319eccb9490f9bcc4d5a3d231787	2011-02-06 21:26:40.000000 -0800	2011-02-06 21:26:40.000000 -0800	2011-02-06 00:00:00.000000 -0800								n	0/1	0/100	1969-12-31 16:00:00.000000 -0800
> ===== END
> ===== START
> D	41f264721f8756903d29115848fb1251	12868df7aa2876419aca8e7787024ffb	2011-02-06 21:26:41.000000 -0800	2011-02-06 21:26:41.000000 -0800	2011-02-06 00:00:00.000000 -0800								n	0/1	0/100	1969-12-31 16:00:00.000000 -0800
> ===== END
> ===== START
> D	78fd1710a7315da5175ff3317ded6929	d2a5645380b6be5f156282ccff637153	2011-02-06 21:26:41.000000 -0800	2011-02-06 21:26:41.000000 -0800	2011-02-06 00:00:00.000000 -0800								n	0/1	0/100	1969-12-31 16:00:00.000000 -0800
> ===== END
> ===== START
> D	b8907a54ed5c3576b04c3f86ebd0c703	461bf9d0dd830b76a0b2390792f8d9a8	2011-02-06 21:26:41.000000 -0800	2011-02-06 21:26:41.000000 -0800	2011-02-06 00:00:00.000000 -0800								n	0/1	0/100	1969-12-31 16:00:00.000000 -0800
> ===== END
> ===== START
> D	783b85f5fa32c4dc4fdc638191c88a6b	06a78d4330e0ba96d3d73a88c7ffff34	2011-02-06 21:26:41.000000 -0800	2011-02-06 21:26:41.000000 -0800	2011-02-06 00:00:00.000000 -0800								n	0/1	0/100	1969-12-31 16:00:00.000000 -0800
> ===== END
> 
> I note the odd timestamps: one with today's date but zero hours, and the other being the unix zero date 1969-12-31...

The timestamps aren't really so odd if you look at the header:  The two with times are the date/time the record was written and the date/time the record was entered in Gnucash. The date with no time is the transaction date you entered; no time
is recorded for that. The zero date/time is the reconciled date, indicating that the transactions aren't reconciled.

Unless you have auto-save disabled you'll have several log files for a normal session, and the first one will have the record of all the churning -- if it was something actually logged.

Another point to note is that the dates in the trace log are quite old -- one from 2003 and the other from 2006. It seems likely that the churning is from scrubbing; the why is a bit mysterious.

Regards,
John Ralls