Slow Rpc Response After A While

I've been using the testnet a lot in the last few days and ended up with a lot of transactions on my test wallet mainly from gpu mining and tickets purchases & voting. (got up to roughly 900 test decred)

Response for getbalance using dcrctl.exe now takes a minimum of 16 seconds to complete. Is this normal behavior and could this be a problem or concern for mainnet ?

Of course when the wallet was newly created the response was immediate.

 

That could be the issue, I'm currently at 500+ addresses on my wallet... In the help listing for dcrwallet I've found the following option :

/reuseaddresses Reuse addresses for ticket purchase to cut down on address overuse

I'll try it with new wallet. Maybe it should be the default behavior if there's no drawback to it.

 

I Found the issue and it's not related to the # of addresses in the wallet. It's a problem caused by a RPC timeout during initial connection.

My current test system is a windows desktop and using a process monitor I've identified where exactly the hang occurs :

Code:

Time            Process        PID    Operation    PATH                Result    Details
12:53:54.3906177 AM    dcrctl.exe    9280    TCP Reconnect    MYPC:50343 -> MYPC:19110    SUCCESS    Length: 0, seqnum: 0, connid: 0
12:54:00.3908789 AM    dcrctl.exe    9280    TCP Reconnect    MYPC:50343 -> MYPC:19110    SUCCESS    Length: 0, seqnum: 0, connid: 0
12:54:12.3914664 AM    dcrctl.exe    9280    TCP Connect    MYPC:50344 -> MYPC:19110    SUCCESS    Length: 0, mss: 1460, sackopt: 1, tsopt: 0, wsopt: 1, rcvwin: 65700, rcvwinscale: 8, sndwinscale: 8, seqnum: 0, connid: 0
12:54:12.3915062 AM    dcrwallet.exe    8704    TCP Accept    MYPC:19110 -> MYPC:50344    SUCCESS    Length: 0, mss: 1460, sackopt: 1, tsopt: 0, wsopt: 1, rcvwin: 65700, rcvwinscale: 8, sndwinscale: 8, seqnum: 0, connid: 0
12:54:12.3916706 AM    dcrwallet.exe    8704    TCP TCPCopy    MYPC:19110 -> MYPC:50344    SUCCESS    Length: 261, seqnum: 0, connid: 0
12:54:12.3916788 AM    dcrwallet.exe    8704    TCP Receive    MYPC:19110 -> MYPC:50344    SUCCESS    Length: 261, seqnum: 0, connid: 0
12:54:12.3917011 AM    dcrctl.exe    9280    TCP Send    MYPC:50344 -> MYPC:19110    SUCCESS    Length: 261, startime: 143519, endtime: 143519, seqnum: 0, connid: 0
12:54:12.3918825 AM    dcrctl.exe    9280    TCP TCPCopy    MYPC:50344 -> MYPC:19110    SUCCESS    Length: 159, seqnum: 0, connid: 0
12:54:12.3918883 AM    dcrctl.exe    9280    TCP Receive    MYPC:50344 -> MYPC:19110    SUCCESS    Length: 159, seqnum: 0, connid: 0
12:54:12.3919056 AM    dcrwallet.exe    8704    TCP Send    MYPC:19110 -> MYPC:50344    SUCCESS    Length: 159, startime: 143519, endtime: 143519, seqnum: 0, connid: 0
12:54:12.3919869 AM    dcrwallet.exe    8704    TCP Disconnect    MYPC:19110 -> MYPC:50344    SUCCESS    Length: 0, seqnum: 0, connid: 0
12:54:12.3919907 AM    dcrctl.exe    9280    TCP Disconnect    MYPC:50344 -> MYPC:19110    SUCCESS    Length: 0, seqnum: 0, connid: 0
12:54:12.3921543 AM    dcrctl.exe    9280    Thread Exit                    SUCCESS    Thread ID: 3596, User Time: 0.0000000, Kernel Time: 0.0000000

We see that the first 2 attempts to connect do not succeed and it's only 18 seconds later that dcrwallet accept the connection and send the answer. From the dcrwallet console I saw that it was listening both on the localhost ipv4 and ipv6 address:

01:18:23 2016-02-02 [INF] DCRW: RPCS: RPC server listening on 127.0.0.1:19110
01:18:23 2016-02-02 [INF] DCRW: RPCS: RPC server listening on [::1]:19110

It got me thinking, and I found that it's exactly where the problem come from. dcrctl attempts to open a TCP socket under ipv6 first and for some reason it fails. (It could be specific to my system or my firewall rules as behavior is different on other PC I tested) Then after a timeout, it binds under ipv4 and the command proceed as expected.

If someone encounters that issue the quick solution is to add the /rpcserver:127.0.0.1:19110 option to your dcrctl wallet commands to force an Ipv4 attempt first and bypass the 18 seconds timeout.

I'm not sure if this issue would require a fix but it would be a good idea to at least document this behavior or print an info on screen when/if an attempt fails to connect on either address.