search

decred / dcrwallet

A secure Decred wallet daemon written in Go (golang).
https://decred.org
ISC License
216 stars 155 forks source link

dcrwallet (Linux) does not sync from dcrd and causes high CPU load #687

Closed hb9xar closed 7 years ago

hb9xar commented 7 years ago

Build plattform is CentOS 7 64bit, go version go1.7.4 linux/amd64

My build from April 2nd was working fine (sorry, I don't have the latest commit hash of that build).

Today, I just updated my test installation to current git master (commit 3fad88d35412f437179460d3187a9fa5ce0d90d2) and rebuilt dcrd, dcrctl and dcrwallet. I have dcrwallet set-up to do solo stake mining.

dcrd and dcrctl seem to work OK

However, dcrwallet seems to get stuck in some kind of loop immediately at startup after entering the private passphrase, causing very high CPU load (test system with 2 vCores, all available CPU resources consumed by dcrwallet). It also does not sync blocks from dcrd.

Sending commands to dcrwallet via dcrctl does kind of work but is terribly slow. I have tried rebuilding the wallet DB from scratch (remove DB and --create from seed), without success. dcrwallet does not sync blocks from dcrd to the wallet. Doing a "getbestblock" to the wallet always returns '0':

$ alias dcrctl-stake='dcrctl --wallet -s 127.0.0.1:29110'  (my staking wallet is running on port 29110)
$ dcrctl-stake getbestblock
{
  "hash": "4261602a9d07d80ad47621a64ba6a07754902e496777edc4ff581946bd7bc29c",
  "height": 0
}

Asking dcrd for the bestblock returns:

$ dcrctl getbestblock
{
  "hash": "0000000004158dda1af03a36144f553a9a50f0b10f5bc3ebd5beb419acad45f4",
  "height": 30742
}

A pstack of the running dcrwallet process while misbehaving gives:

Thread 7 (Thread 0x7f89dd6c9700 (LWP 6358)):
#0  runtime.usleep () at /usr/lib/golang/src/runtime/sys_linux_amd64.s:95
#1  0x000000000044b232 in runtime.sysmon () at /usr/lib/golang/src/runtime/proc.go:3606
#2  0x00000000004445be in runtime.mstart1 () at /usr/lib/golang/src/runtime/proc.go:1126
#3  0x0000000000444494 in runtime.mstart () at /usr/lib/golang/src/runtime/proc.go:1096
#4  0x0000000000a23623 in crosscall_amd64 ()
#5  0x0000000000000003 in ?? ()
#6  0x00007f89dd6c9700 in ?? ()
#7  0x00007f89dd6c99c0 in ?? ()
#8  0x0000000000000000 in ?? ()
Thread 6 (Thread 0x7f89dcec8700 (LWP 6359)):
#0  github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1.(*FieldVal).Mul2 (f=0xc4270b7790, val=0xc4270b77e0, val2=0xc4270b7858, ~r2=0xc4270b77b8) at /home/decred-test/src/go/src/github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1/field.go:803
#1  0x000000000083f92d in github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1.(*FieldVal).Inverse (f=0xc4270b7980, ~r0=0x9e18efd08a8c285) at /home/decred-test/src/go/src/github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1/field.go:1185
#2  0x0000000000836003 in github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1.(*KoblitzCurve).FieldJacobianToBigAffine (curve=0x10e87a0 <github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1.secp256k1>, x=0xc4270b7aa8, y=0xc4270b7a80, z=0xc4270b7a58, ~r3=0xc4270b7ad0, ~r4=0xc4270b7af8) at /home/decred-test/src/go/src/github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1/btcec.go:94
#3  0x000000000083bda0 in github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1.(*KoblitzCurve).ScalarBaseMult (curve=0x10e87a0 <github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1.secp256k1>, k=..., ~r1=0x40, ~r2=0xc4474d1680) at /home/decred-test/src/go/src/github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/dcrec/secp256k1/btcec.go:882
#4  0x00000000007aadcb in github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/chaincfg/chainec.newSecp256k1DSA.func6 (k=..., ~r1=0x22718d390145acfd, ~r2=0xa07834b0c51b148b) at /home/decred-test/src/go/src/github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/chaincfg/chainec/secp256k1.go:187
#5  0x00000000007a7b7d in github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/chaincfg/chainec.secp256k1DSA.ScalarBaseMult (sp=..., k=..., ~r1=0x5, ~r2=0xffffffffffffffff) at /home/decred-test/src/go/src/github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/chaincfg/chainec/secp256k1.go:82
#6  0x00000000007af53e in github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/chaincfg/chainec.(*secp256k1DSA).ScalarBaseMult (this=0xc42005f1e0, k=..., ~r1=0xc4270b7e18, ~r2=0x40) at <autogenerated>:76
#7  0x0000000000766b7f in github.com/decred/dcrwallet/vendor/github.com/decred/dcrutil/hdkeychain.(*ExtendedKey).Child (k=0xc4201f3cb0, i=36115, ~r1=0xc459280340, ~r2=...) at /home/decred-test/src/go/src/github.com/decred/dcrwallet/vendor/github.com/decred/dcrutil/hdkeychain/extendedkey.go:281
#8  0x00000000004f67eb in github.com/decred/dcrwallet/wallet.deriveChildAddresses (key=0xc4201f3cb0, startIndex=0, count=75000, params=0x10d8860 <github.com/decred/dcrwallet/vendor/github.com/decred/dcrd/chaincfg.TestNet2Params>, ~r4=..., ~r5=...) at /home/decred-test/src/go/src/github.com/decred/dcrwallet/wallet/addresses.go:414
#9  0x000000000046f820 in ?? () at /usr/lib/golang/src/runtime/asm_amd64.s:373
#10 0x000000c4201f3cb0 in ?? ()
#11 0x000124f800000000 in ?? ()
#12 0x00000000010d8860 in ?? ()
#13 0x000000c4202b6f70 in ?? ()
#14 0x0000000000525423 in github.com/decred/dcrwallet/wallet.(*Wallet).findLastUsedAccount.func1 (w=0xc42013a000, client=0xc4202d2000, xpub=0x0, xpriv=0x472611 <runtime.goexit+1>, &results=0xc4204127b0, i=842351747072, account=539828224, &wg=0xc4201f3cb0) at /home/decred-test/src/go/src/github.com/decred/dcrwallet/wallet/sync.go:52
#15 0x0000000000472611 in runtime.goexit () at /usr/lib/golang/src/runtime/asm_amd64.s:2086
#16 0x000000c42013a000 in ?? ()
#17 0x000000c4202d2000 in ?? ()
#18 0x0000000000000000 in ?? ()
Thread 5 (Thread 0x7f89dc6c7700 (LWP 6360)):
#0  runtime.futex () at /usr/lib/golang/src/runtime/sys_linux_amd64.s:388
#1  0x000000000043d092 in runtime.futexsleep (addr=0x1106020 <runtime.sig>, val=0, ns=-1) at /usr/lib/golang/src/runtime/
os_linux.go:45
#2  0x00000000004232bd in runtime.notetsleep_internal (n=0x1106020 <runtime.sig>, ns=-1, ~r2=3) at /usr/lib/golang/src/ru
ntime/lock_futex.go:161
#3  0x00000000004234aa in runtime.notetsleepg (n=0x1106020 <runtime.sig>, ns=-1, ~r2=true) at /usr/lib/golang/src/runtime/lock_futex.go:206
#4  0x0000000000454e97 in os/signal.signal_recv (~r0=39619967) at /usr/lib/golang/src/runtime/sigqueue.go:116
#5  0x0000000000745542 in os/signal.loop () at /usr/lib/golang/src/os/signal/signal_unix.go:22
#6  0x0000000000472611 in runtime.goexit () at /usr/lib/golang/src/runtime/asm_amd64.s:2086
#7  0x0028840a03b61c82 in ?? ()
#8  0x01b9a73401e23bd1 in ?? ()
[...]
#88 0x030e4087015c1d36 in ?? ()
#89 0x00000000004255f6 in runtime.writebarrierptr_nostore1 (dst=0xc4202e00c0, src=8) at /usr/lib/golang/src/runtime/mbarrier.go:132
#90 0x000000000042568d in runtime.writebarrierptr (dst=0x0, src=72) at /usr/lib/golang/src/runtime/mbarrier.go:154
#91 0x00007f89dde7c4b0 in ?? ()
#92 0x0000000000000000 in ?? ()
Thread 4 (Thread 0x7f89dbb53700 (LWP 6361)):
#0  runtime.futex () at /usr/lib/golang/src/runtime/sys_linux_amd64.s:388
#1  0x000000000043d107 in runtime.futexsleep (addr=0x10e8638 <runtime.timers+24>, val=0, ns=26781731184) at /usr/lib/golang/src/runtime/os_linux.go:62
#2  0x000000000042333b in runtime.notetsleep_internal (n=0x10e8638 <runtime.timers+24>, ns=26781731184, ~r2=false) at /usr/lib/golang/src/runtime/lock_futex.go:174
#3  0x00000000004234aa in runtime.notetsleepg (n=0x10e8638 <runtime.timers+24>, ns=26781731184, ~r2=false) at /usr/lib/golang/src/runtime/lock_futex.go:206
#4  0x000000000045d1cb in runtime.timerproc () at /usr/lib/golang/src/runtime/time.go:209
#5  0x0000000000472611 in runtime.goexit () at /usr/lib/golang/src/runtime/asm_amd64.s:2086
#6  0x0000000000000000 in ?? ()
Thread 3 (Thread 0x7f89db352700 (LWP 6362)):
#0  runtime.scanobject (b=842453873952, gcw=0xc42001b228) at /usr/lib/golang/src/runtime/mgcmark.go:1138
#1  0x0000000000430bcc in runtime.gcDrain (gcw=0xc42001b228, flags=5) at /usr/lib/golang/src/runtime/mgcmark.go:993
#2  0x000000000042d341 in runtime.gcBgMarkWorker (_p_=0xc42001a000) at /usr/lib/golang/src/runtime/mgc.go:1452
#3  0x0000000000472611 in runtime.goexit () at /usr/lib/golang/src/runtime/asm_amd64.s:2086
#4  0x000000c42001a000 in ?? ()
#5  0x0000000000000000 in ?? ()
Thread 2 (Thread 0x7f89dab51700 (LWP 6363)):
#0  runtime.futex () at /usr/lib/golang/src/runtime/sys_linux_amd64.s:388
#1  0x000000000043d092 in runtime.futexsleep (addr=0xc4202d6510, val=0, ns=-1) at /usr/lib/golang/src/runtime/os_linux.go:45
#2  0x0000000000423202 in runtime.notesleep (n=0xc4202d6510) at /usr/lib/golang/src/runtime/lock_futex.go:145
#3  0x000000000044556d in runtime.stopm () at /usr/lib/golang/src/runtime/proc.go:1594
#4  0x0000000000445f1a in runtime.gcstopm () at /usr/lib/golang/src/runtime/proc.go:1798
#5  0x0000000000446eb0 in runtime.schedule () at /usr/lib/golang/src/runtime/proc.go:2084
#6  0x00000000004473d0 in runtime.goschedImpl (gp=0xc420294680) at /usr/lib/golang/src/runtime/proc.go:2198
#7  0x00000000004474b6 in runtime.gopreempt_m (gp=0xc420294680) at /usr/lib/golang/src/runtime/proc.go:2213
#8  0x0000000000457d18 in runtime.newstack () at /usr/lib/golang/src/runtime/stack.go:1053
#9  0x000000000046f7ff in runtime.morestack () at /usr/lib/golang/src/runtime/asm_amd64.s:366
#10 0x000000c42001a000 in ?? ()
#11 0x0000000000000000 in ?? ()
Thread 1 (Thread 0x7f89ddebc740 (LWP 6357)):
#0  runtime.futex () at /usr/lib/golang/src/runtime/sys_linux_amd64.s:388
#1  0x000000000043d092 in runtime.futexsleep (addr=0x10e9750 <runtime.m0+272>, val=0, ns=-1) at /usr/lib/golang/src/runtime/os_linux.go:45
#2  0x0000000000423202 in runtime.notesleep (n=0x10e9750 <runtime.m0+272>) at /usr/lib/golang/src/runtime/lock_futex.go:145
#3  0x0000000000445c9a in runtime.stoplockedm () at /usr/lib/golang/src/runtime/proc.go:1741
#4  0x000000000044709a in runtime.schedule () at /usr/lib/golang/src/runtime/proc.go:2078
#5  0x0000000000447263 in runtime.park_m (gp=0xc4204ff040) at /usr/lib/golang/src/runtime/proc.go:2183
#6  0x000000000046f6ab in runtime.mcall () at /usr/lib/golang/src/runtime/asm_amd64.s:240
#7  0x00000000010e8e00 in ?? ()
#8  0x00007ffdbb5b4380 in ?? ()
#9  0x00000000010e8e00 in ?? ()
#10 0x00007ffdbb5b4370 in ?? ()
#11 0x0000000000444494 in runtime.mstart () at /usr/lib/golang/src/runtime/proc.go:1096
#12 0x000000000046f555 in runtime.rt0_go () at /usr/lib/golang/src/runtime/asm_amd64.s:156
#13 0x0000000000000006 in ?? ()
#14 0x00007ffdbb5b43b8 in ?? ()
#15 0x0000000000000006 in ?? ()
#16 0x00007ffdbb5b43b8 in ?? ()
#17 0x0000000000000000 in ?? ()
hb9xar commented 7 years ago

I might just have found the cause.

I did experiment with 'addridxscanlen' and had a rather large value set there (addridxscanlen=75000). Removing this option from the config file did the trick and things are back to normal.

So I suspect there must have been changes in the code that now cause a much higher CPU load if using large values for this parameter.

jrick commented 7 years ago

Oh, yeah thanks for investigating that. The default value for that is now 20 and shouldn't ever need to be changed unless you have special requirements and can't respect the BIP0044 gap limit. Sadly i don't think there's much that can be done about the slow startup there as it actually has to generate absurd numbers of addresses with high scan lengths.