Finance::Quote Load Times

Mon Oct 26 14:05:24 EDT 2015

On 10/26/15 9:51 AM, John Ralls wrote:
>> On Oct 25, 2015, at 6:21 PM, John Ralls <jralls at ceridwen.us> wrote:
>>
>>
>>> On Oct 25, 2015, at 3:19 PM, Jed Diem <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> wrote:
>>>>>
>>>>>
>>>>>> On Oct 25, 2015, at 11:40 AM, Jed Diem <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\".$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\".$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
>