Finance::Quote Load Times
Diem, John
jed at tulane.edu
Mon Oct 26 19:32:21 EDT 2015
I also see longer than previously retrieve quotes times after F::Q takes 64 seconds to load.
--jed
Sent from my iPad
On Oct 26, 2015, at 14:36, David T. <sunfish62 at yahoo.com<mailto:sunfish62 at yahoo.com>> wrote:
John,
I’m not sure if it’s part of the same problem, but I am seeing extended times when I try to update prices (Tools->Price Editor, Get Quotes). My most recent attempt took 23 seconds, which I think is longer than I remember. To be honest, my memory isn’t what it used to be, though, so this may just be noise in the discussion.
However, digging in my own instance of dtruss, I found that I had exact matches for the lines you pulled out of Jed’s file:
1754/0xbd49: 10842 16980748 17 kevent64(0x3, 0x0, 0x0) = 1 0
1754/0xbd49: 10900 36 32 kevent64(0x3, 0xB0010588, 0x1) = 1 0
1766/0xbd94: 801338 20840963 35 stat64("./Net/LibIDN.pmc\0", 0x7FFF5FBEBD70, 0x2000) = -1 Err#60
dtrace: 13701 dynamic variable drops with non-empty dirty list
1766/0xbd94: 801411 20464549 68 stat64("./Net/LibIDN.pm\0", 0x7FFF5FBEBCC0, 0x2000) = -1 Err#60
1766/0xbd94: 803418 15 11 read(0x3, "L_opening'};\n\t\t${*$self}{'_SSL_opened'} = -1;\n\t\t$DEBUG>=1 && DEBUG( \"fatal SSL error: $SSL_ERROR\" );\n\t\treturn $self->fatal_ssl_error();\n\t }\n\n\t $DEBUG>=2 && DEBUG('ssl handshake in progress' );\n\t # connect failed because handshake needs to be compl", 0x2000) = 8192 0
1766/0xbd94: 805749 9 5 read(0x3, " ||= 0;\n return $self->error(\"Invalid offset for SSL write\") if ($offset>$buf_len);\n return 0 if ($offset == $buf_len);\n\n $SSL_ERROR = undef;\n my $written;\n if ( $write_all ) {\n\tmy $data = $length < $buf_len-$offset ? substr($$buffer, $offse", 0x2000) = 8192 0
1766/0xbd94: 808078 9 5 read(0x3, "(%to);\n\tif ( $result ) {\n\t $socket->blocking(0) if ! $was_blocking;\n\t return $socket;\n\t} else {\n\t # upgrade to SSL failed, downgrade socket to original class\n\t if ( $original_class ) {\n\t\tbless($socket,$original_class);\n\t\t$socket->blocking(0) if", 0x2000) = 8192 0
1766/0xbd94: 810094 7 5 read(0x3, "r_trap) eq 'CODE') {\n\t$error_trap->($self, $self->errstr().\"\\n\<smb://n/>".$self->get_ssleay_error());\n } elsif ( ${*$self}{'_SSL_ioclass_upgraded'} ) {\n\t# downgrade only\n\t$self->stop_SSL;\n } else {\n\t# kill socket\n\t$self->close\n }\n return;\n}\n\nsub get_ssle", 0x2000) = 8192 0
1766/0xbd94: 812398 8 5 read(0x3, "_;\n\t\t}\n\t }\n\t if ( defined( my $f = $arg_hash->{SSL_ca_file} )) {\n\t\tdie \"SSL_ca_file $f does not exist\" if ! -f $f;\n\t\tdie \"SSL_ca_file $f is not accessable\" if ! -r _;\n\t }\n\t if ( defined( my $d = $arg_hash->{SSL_ca_path} )) {\n\t\tdie \"only SSL_ca_", 0x2000) = 8192 0
1766/0xbd94: 813840 6 4 read(0x3, "free( $dh );\n\t $rv || return IO::Socket::SSL->error( \"Failed to set DH from $f\" );\n\t} elsif ( my $dh = $arg_hash->{SSL_dh} ) {\n\t # binary, e.g. DH*\n\t Net::SSLeay::CTX_set_tmp_dh( $ctx,$dh )\n\t\t|| return IO::Socket::SSL->error( \"Failed to set DH fro", 0x2000) = 8192 0
My Mac is running 10.10.5.
Does this help the discussion?
David
On Oct 26, 2015, at 2:05 PM, Jed Diem <jed at tulane.edu<mailto:jed at tulane.edu>> wrote:
On 10/26/15 9:51 AM, John Ralls wrote:
On Oct 25, 2015, at 6:21 PM, John Ralls <jralls at ceridwen.us<mailto:jralls at ceridwen.us>> wrote:
On Oct 25, 2015, at 3:19 PM, Jed Diem <jed at tulane.edu<mailto:jed at tulane.edu>> wrote:
On 10/25/15 3:04 PM, John Ralls wrote:
On Oct 25, 2015, at 12:42 PM, John Ralls <jralls at ceridwen.us<mailto:jralls at ceridwen.us>> wrote:
On Oct 25, 2015, at 11:40 AM, Jed Diem <jed at tulane.edu<mailto:jed at tulane.edu>> wrote:
John,
I've attached two Activity Monitor files and a gnucash.trace file. gnucash.trace1 goes with sample1 which taken at the beginning of the "Checking Finance::Quote" splash screen message.
During the gnucash run from which sample1 was taken I managed to grab "perl" from the Activity Monitor. It was there for very short time.
It's sample file is "Sample of perl5.18.”
Jed,
Looks like the GnuCash thread is blocked waiting for input, which is what one would expect. It’s hard to be completely sure that it’s the read we think it is since we can’t see the Scheme level calls, only the C calls that they produce.
I’m a bit troubled by the Perl trace because it seems to be from 3 minutes after the end of the gnucash.trace. Surely it’s from a second start attempt. I’m not surprised that it was brief. Did it occur near the beginning or the end of the “Finance::Quote” period?
A bit of Googling reminded me of dtruss, which will collect some useful information. (For any Linux users following along, it’s the BSD equivalent of strace.)
Open /Applications/Utilities/Terminal. At the prompt type
sudo dtruss -d -f -e -o -n Gnucash-bin > ~/gnucash.dtruss 2>&1
It will prompt for your password. Enter that, then launch Gnucash. When it gets past the Finance::Quote message and starts loading your data file, return to Terminal and type Control-C to stop dtruss. Attach ~/gnucash.dtruss to a reply.
Regards,
John Ralls
John,
The dtruss file is attached.
First, let me explain that dtruss logs system function calls, or “syscalls”. The output format is
PID/THRD RELATIVE ELAPSD CPU SYSCALL(args) = return
Here’s the read from price-quotes.scm which launched gnc-fq-check:
1754/0xbd1a: 8962426 65120398 10 read(0x19, "(\"1.38\" \"adig\" \"aex\" \"aiahk\" \"amfiindia\" \"asegr\" \"asia\" \"asx\" \"australia\" \"bamosz\" \"bet\" \"bmonesbittburns\" \"bourso\" \"brasil\" \"bse\" \"bsero\" \"canada\" \"canadamutual\" \"citywire\" \"cominvest\" \"cse\" \"deka\" \"dutch\" \"dwsfunds\" \"europe\" \"fetch_live_currencies\" \"fide", 0x4000) = 981 0
The “relative” value is supposed to be the time read was called in micro-seconds after GnuCash started up; the elapsd value, 65120398, is how long it took in micro-seconds — that’s about 65 seconds, in line with your other observations. The “relative” values don’t really seem to be consistent with the elapsed values (the maximum is only 13068372, or 13 seconds), so I suspect that they’re really only useful for ordering the entries.
The next question is what’s taking all of that time? Looking through the file, I found the following:
First, there are a bunch of instances similar to
1766/0xbd94: 801290 6 4 stat64("/System/Library/Perl/Extras/5.18/darwin-thread-multi-level/Net/LibIDN.pmc\0", 0x7FFF5FBEBD70, 0x2000) = -1 Err#2
1766/0xbd94: 801293 4 2 stat64("/System/Library/Perl/Extras/5.18/darwin-thread-multi-2level/Net/LibIDN.pm\0", 0x7FFF5FBEBCC0, 0x2000) = -1 Err#2
but with different paths. (Note that first number, 1766. It’s different from the one in the first set. 1754 is the Gnucash-bin process and 1766 is perl.) Err#2 is “ENOENT”, file doesn’t exist. Ho-hum.
Then we get
1754/0xbd49: 10842 16980748 17 kevent64(0x3, 0x0, 0x0) = 1 0
1754/0xbd49: 10900 36 32 kevent64(0x3, 0xB0010588, 0x1)
= 1 0
1766/0xbd94: 801338 20840963 35 stat64("./Net/LibIDN.pmc\0", 0x7FFF5FBEBD70, 0x2000) = -1 Err#60
dtrace: 13701 dynamic variable drops with non-empty dirty list
1766/0xbd94: 801411 20464549 68 stat64("./Net/LibIDN.pm\0", 0x7FFF5FBEBCC0, 0x2000) = -1 Err#60
1766/0xbd94: 803418 15 11 read(0x3, "L_opening'};\n\t\t${*$self}{'_SSL_opened'} = -1;\n\t\t$DEBUG>=1 && DEBUG( \"fatal SSL error: $SSL_ERROR\" );\n\t\treturn $self->fatal_ssl_error();\n\t }\n\n\t $DEBUG>=2 && DEBUG('ssl handshake in progress' );\n\t # connect failed because handshake needs to be compl", 0x2000) = 8192 0
1766/0xbd94: 805749 9 5 read(0x3, " ||= 0;\n return $self->error(\"Invalid offset for SSL write\") if ($offset>$buf_len);\n return 0 if ($offset == $buf_len);\n\n $SSL_ERROR = undef;\n my $written;\n if ( $write_all ) {\n\tmy $data = $length < $buf_len-$offset ? substr($$buffer, $offse", 0x2000) = 8192 0
1766/0xbd94: 808078 9 5 read(0x3, "(%to);\n\tif ( $result ) {\n\t $socket->blocking(0) if ! $was_blocking;\n\t return $socket;\n\t} else {\n\t # upgrade to SSL failed, downgrade socket to original class\n\t if ( $original_class ) {\n\t\tbless($socket,$original_class);\n\t\t$socket->blocking(0) if", 0x2000) = 8192 0
1766/0xbd94: 810094 7 5 read(0x3, "r_trap) eq 'CODE') {\n\t$error_trap->($self, $self->errstr().\"\\n\<smb://n/>".$self->get_ssleay_error());\n } elsif ( ${*$self}{'_SSL_ioclass_upgraded'} ) {\n\t# downgrade only\n\t$self->stop_SSL;\n } else {\n\t# kill socket\n\t$self->close\n }\n return;\n}\n\nsub get_ssle", 0x2000) = 8192 0
1766/0xbd94: 812398 8 5 read(0x3, "_;\n\t\t}\n\t }\n\t if ( defined( my $f = $arg_hash->{SSL_ca_file} )) {\n\t\tdie \"SSL_ca_file $f does not exist\" if ! -f $f;\n\t\tdie \"SSL_ca_file $f is not accessable\" if ! -r _;\n\t }\n\t if ( defined( my $d = $arg_hash->{SSL_ca_path} )) {\n\t\tdie \"only SSL_ca_", 0x2000) = 8192 0
1766/0xbd94: 813840 6 4 read(0x3, "free( $dh );\n\t $rv || return IO::Socket::SSL->error( \"Failed to set DH from $f\" );\n\t} elsif ( my $dh = $arg_hash->{SSL_dh} ) {\n\t # binary, e.g. DH*\n\t Net::SSLeay::CTX_set_tmp_dh( $ctx,$dh )\n\t\t|| return IO::Socket::SSL->error( \"Failed to set DH fro", 0x2000) = 8192 0
On my system (Late 2013 Mac Pro, 10.10.5, Xcode 7.0.2) those lines look like
93504/0x30736af: 422183 36168 18 stat64("./Net/LibIDN.pmc\0", 0x7FFF5324BDA0, 0x2000) = -1 Err#2
93504/0x30736af: 422204 34531 19 stat64("./Net/LibIDN.pm\0", 0x7FFF5324BCF0, 0x2000) = -1 Err#2
93504/0x30736af: 423216 6 4 read(0x3, "L_opening'};\n\t\t${*$self}{'_SSL_opened'} = -1;\n\t\t$DEBUG>=1 && DEBUG( \"fatal SSL error: $SSL_ERROR\" );\n\t\treturn $self->fatal_ssl_error();\n\t }\n\n\t $DEBUG>=2 && DEBUG('ssl handshake in progress' );\n\t # connect failed because handshake needs to be compl", 0x2000) = 8192 0
93504/0x30736af: 424319 4 3 read(0x3, " ||= 0;\n return $self->error(\"Invalid offset for SSL write\") if ($offset>$buf_len);\n return 0 if ($offset == $buf_len);\n\n $SSL_ERROR = undef;\n my $written;\n if ( $write_all ) {\n\tmy $data = $length < $buf_len-$offset ? substr($$buffer, $offse", 0x2000) = 8192 0
93504/0x30736af: 425429 4 3 read(0x3, "(%to);\n\tif ( $result ) {\n\t $socket->blocking(0) if ! $was_blocking;\n\t return $socket;\n\t} else {\n\t # upgrade to SSL failed, downgrade socket to original class\n\t if ( $original_class ) {\n\t\tbless($socket,$original_class);\n\t\t$socket->blocking(0) if", 0x2000) = 8192 0
93504/0x30736af: 426438 4 3 read(0x3, "r_trap) eq 'CODE') {\n\t$error_trap->($self, $self->errstr().\"\\n\<smb://n/>".$self->get_ssleay_error());\n } elsif ( ${*$self}{'_SSL_ioclass_upgraded'} ) {\n\t# downgrade only\n\t$self->stop_SSL;\n } else {\n\t# kill socket\n\t$self->close\n }\n return;\n}\n\nsub get_ssle", 0x2000) = 8192 0
93504/0x30736af: 427894 5 3 read(0x3, "_;\n\t\t}\n\t }\n\t if ( defined( my $f = $arg_hash->{SSL_ca_file} )) {\n\t\tdie \"SSL_ca_file $f does not exist\" if ! -f $f;\n\t\tdie \"SSL_ca_file $f is not accessable\" if ! -r _;\n\t }\n\t if ( defined( my $d = $arg_hash->{SSL_ca_path} )) {\n\t\tdie \"only SSL_ca_", 0x2000) = 8192 0
93504/0x30736af: 428887 5 3 read(0x3, "free( $dh );\n\t $rv || return IO::Socket::SSL->error( \"Failed to set DH from $f\" );\n\t} elsif ( my $dh = $arg_hash->{SSL_dh} ) {\n\t # binary, e.g. DH*\n\t Net::SSLeay::CTX_set_tmp_dh( $ctx,$dh )\n\t\t|| return IO::Socket::SSL->error( \"Failed to set DH fro", 0x2000) = 8192 0
and the read line shows
93493/0x30735a1: 6661515 1407287 10 read(0x19, "(\"1.37\" \"adig\" \"aex\" \"aiahk\" \"amfiindia\" \"asegr\" \"asia\" \"asx\" \"australia\" \"bamosz\" \"bet\" \"bitcoin_aud\" \"bitcoin_cad\" \"bitcoin_chf\" \"bitcoin_cny\" \"bitcoin_dkk\" \"bitcoin_eur\" \"bitcoin_gbp\" \"bitcoin_hkd\" \"bitcoin_jpy\" \"bitcoin_nok\" \"bitcoin_nzd\" \"bitcoin_pln\"", 0x4000) = 1395 0
Note that the stat64(./Net/LibIDN.pm…) fails with Err#2, ENOENT and takes only 35ms; the read takes 1.4 seconds.
Unfortunately I can’t test my MBA because I’ve already upgraded it to 10.11 and dtruss seems to be blocked from probing a lot of the perl stat64 calls and I need to clean up a bit to make room to install Xcode 7.1 on the Mac Pro.
Maybe Erik will have some ideas about the weird load times and error.
FWIW, upgrading Xcode to 7.1 didn’t change anything.
Regards,
John Ralls
John, I suppose that's good but now I really don't have any idea what's going on. I think I will upgrade to 2.6.9 latter today.
--jed
_______________________________________________
gnucash-user mailing list
gnucash-user at gnucash.org<mailto:gnucash-user at gnucash.org>
https://lists.gnucash.org/mailman/listinfo/gnucash-user
-----
Please remember to CC this list on all your replies.
You can do this by using Reply-To-List or Reply-All.
More information about the gnucash-user
mailing list