0

I'm testing Ethereum smart contracts with web3j and Geth. Geth is running with scripts like that:

PASSFILE=/var/folders/_l/kl9pdj2x50v7416j8htb6w740000gn/T/pwd6597172766860806720.tmp
DATADIR=/var/folders/_l/kl9pdj2x50v7416j8htb6w740000gn/T/geth808290308908087582
IPCPATH=/var/folders/_l/kl9pdj2x50v7416j8htb6w740000gn/T/geth808290308908087582/geth.ipc

geth --datadir $DATADIR account new --password $PASSFILE
geth --datadir $DATADIR \
    --ipcpath $IPCPATH \
    --dev \
    --rpc \
    --mine \
    --networkid 1999

(paths are generated in tests).

Smart contract wrappers are generated with web3j-maven-plugin.

The problem is that every send() invocation takes few seconds:

private TransactionReceipt deployFeature_() throws Exception {
    logger.info("Deploying feature ...");
    return contract.deployFeature(featureKey).send();
}

log (you can see 1 transaction took 16 seconds):

166955 [main] INFO FeatureTest - Deploying feature ...
182006 [main] INFO FeatureTest - Checking feature is listed ...

Web3j is connected over IPC:

web3 = Web3j.build(new UnixIpcService(ipcPath));

How can i speed-up invocations? If testing with TestRPC every invocations takes much less than a second! Since Geth is started with --dev it generates genesis file itself so i can't change difficulty. Also i can see blocks are mined very fast:

INFO [11-09|00:34:39] Commit new mining work                   number=9 txs=0 uncles=0 elapsed=2.000s
INFO [11-09|00:34:39] Successfully sealed new block            number=9 hash=b869ca…870644
INFO [11-09|00:34:39] 🔗 block reached canonical chain          number=4 hash=c758a0…a529af
INFO [11-09|00:34:39] 🔨 mined potential block                  number=9 hash=b869ca…870644
INFO [11-09|00:34:39] Commit new mining work                   number=10 txs=0 uncles=0 elapsed=84.12µs
INFO [11-09|00:34:40] Successfully sealed new block            number=10 hash=5e81a9…fc1364
INFO [11-09|00:34:40] 🔗 block reached canonical chain          number=5  hash=465c2b…78461a
INFO [11-09|00:34:40] 🔨 mined potential block                  number=10 hash=5e81a9…fc1364

For some reason invocations are not fast. What can i do?

Update 1: verbose geth log:

DEBUG[11-09|10:55:24] Reinjecting stale transactions           count=0
TRACE[11-09|10:55:24] Started ethash search for new nonces     miner=3 seed=2704551168899111732
TRACE[11-09|10:55:24] Started ethash search for new nonces     miner=0 seed=5467839612232628274
TRACE[11-09|10:55:24] Started ethash search for new nonces     miner=2 seed=1157694161266147191
TRACE[11-09|10:55:24] Started ethash search for new nonces     miner=1 seed=7845452550729559273
TRACE[11-09|10:55:25] Ethash nonce found and reported          miner=3 attempts=33111  nonce=2704551168899144843
TRACE[11-09|10:55:25] Ethash nonce search aborted              miner=1 attempts=33196
TRACE[11-09|10:55:25] Ethash nonce search aborted              miner=2 attempts=34566
TRACE[11-09|10:55:25] Ethash nonce search aborted              miner=0 attempts=29434
INFO [11-09|10:55:25] Successfully sealed new block            number=135 hash=7cbd94…37dc26
DEBUG[11-09|10:55:25] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:25] 🔗 block reached canonical chain          number=130 hash=3ca7c4…374497
INFO [11-09|10:55:25] 🔨 mined potential block                  number=135 hash=7cbd94…37dc26
TRACE[11-09|10:55:25] Propagated block                         hash=7cbd94…37dc26 recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:25] Announced block                          hash=7cbd94…37dc26 recipients=0 duration=2562047h47m16.854s
DEBUG[11-09|10:55:25] Reinjecting stale transactions           count=0
INFO [11-09|10:55:25] Commit new mining work                   number=136 txs=0 uncles=0 elapsed=297.987µs
TRACE[11-09|10:55:25] Started ethash search for new nonces     miner=3 seed=5487602165862729957
TRACE[11-09|10:55:25] Started ethash search for new nonces     miner=2 seed=1373940052212025290
TRACE[11-09|10:55:25] Started ethash search for new nonces     miner=0 seed=2640498343526987028
TRACE[11-09|10:55:25] Started ethash search for new nonces     miner=1 seed=7750561880638031679
TRACE[11-09|10:55:26] Ethash nonce found and reported          miner=3 attempts=91684  nonce=5487602165862821641
TRACE[11-09|10:55:26] Ethash nonce search aborted              miner=0 attempts=84642
TRACE[11-09|10:55:26] Ethash nonce search aborted              miner=1 attempts=88714
TRACE[11-09|10:55:26] Ethash nonce search aborted              miner=2 attempts=89722
INFO [11-09|10:55:26] Successfully sealed new block            number=136 hash=63b459…f7943d
DEBUG[11-09|10:55:26] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:26] 🔗 block reached canonical chain          number=131 hash=f3baed…7b4cd1
INFO [11-09|10:55:26] 🔨 mined potential block                  number=136 hash=63b459…f7943d
TRACE[11-09|10:55:26] Propagated block                         hash=63b459…f7943d recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:26] Announced block                          hash=63b459…f7943d recipients=0 duration=2562047h47m16.854s
DEBUG[11-09|10:55:26] Reinjecting stale transactions           count=0
INFO [11-09|10:55:26] Commit new mining work                   number=137 txs=0 uncles=0 elapsed=137µs
TRACE[11-09|10:55:26] Started ethash search for new nonces     miner=3 seed=5735737036966792397
TRACE[11-09|10:55:26] Started ethash search for new nonces     miner=2 seed=2201918865350132270
TRACE[11-09|10:55:26] Started ethash search for new nonces     miner=1 seed=7114248001329383901
TRACE[11-09|10:55:26] Started ethash search for new nonces     miner=0 seed=7064937725018178156
TRACE[11-09|10:55:26] Ethash nonce found and reported          miner=1 attempts=306    nonce=7114248001329384207
TRACE[11-09|10:55:26] Ethash nonce search aborted              miner=2 attempts=215
TRACE[11-09|10:55:26] Ethash nonce search aborted              miner=0 attempts=337
TRACE[11-09|10:55:26] Ethash nonce search aborted              miner=3 attempts=213
INFO [11-09|10:55:26] Successfully sealed new block            number=137 hash=bfebbd…7bebbb
DEBUG[11-09|10:55:26] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:26] 🔗 block reached canonical chain          number=132 hash=cc2b57…a1eaa2
INFO [11-09|10:55:26] 🔨 mined potential block                  number=137 hash=bfebbd…7bebbb
INFO [11-09|10:55:26] Mining too far in the future             wait=2s
TRACE[11-09|10:55:26] Propagated block                         hash=bfebbd…7bebbb recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:26] Announced block                          hash=bfebbd…7bebbb recipients=0 duration=2562047h47m16.854s
DEBUG[11-09|10:55:26] Reinjecting stale transactions           count=0
INFO [11-09|10:55:28] Commit new mining work                   number=138 txs=0 uncles=0 elapsed=2.004s
TRACE[11-09|10:55:28] Started ethash search for new nonces     miner=3 seed=1224837056936865954
TRACE[11-09|10:55:28] Started ethash search for new nonces     miner=0 seed=4158743884218822112
TRACE[11-09|10:55:28] Started ethash search for new nonces     miner=1 seed=8186530166650094269
TRACE[11-09|10:55:28] Started ethash search for new nonces     miner=2 seed=6717769196178392649
TRACE[11-09|10:55:28] Ethash nonce found and reported          miner=2 attempts=42268  nonce=6717769196178434917
TRACE[11-09|10:55:28] Ethash nonce search aborted              miner=0 attempts=42660
TRACE[11-09|10:55:28] Ethash nonce search aborted              miner=3 attempts=41386
TRACE[11-09|10:55:28] Ethash nonce search aborted              miner=1 attempts=41693
INFO [11-09|10:55:28] Successfully sealed new block            number=138 hash=45b114…b0a64c
DEBUG[11-09|10:55:28] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:28] 🔗 block reached canonical chain          number=133 hash=8bf749…99d498
INFO [11-09|10:55:28] 🔨 mined potential block                  number=138 hash=45b114…b0a64c
TRACE[11-09|10:55:28] Propagated block                         hash=45b114…b0a64c recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:28] Announced block                          hash=45b114…b0a64c recipients=0 duration=2562047h47m16.854s
DEBUG[11-09|10:55:28] Reinjecting stale transactions           count=0
INFO [11-09|10:55:28] Commit new mining work                   number=139 txs=0 uncles=0 elapsed=270.413µs
TRACE[11-09|10:55:28] Started ethash search for new nonces     miner=3 seed=3768964950495190140
TRACE[11-09|10:55:28] Started ethash search for new nonces     miner=2 seed=5926649220579239325
TRACE[11-09|10:55:28] Started ethash search for new nonces     miner=1 seed=3891061113576232214
TRACE[11-09|10:55:28] Started ethash search for new nonces     miner=0 seed=5321048005196544766
TRACE[11-09|10:55:28] Ethash nonce found and reported          miner=1 attempts=21588  nonce=3891061113576253802
TRACE[11-09|10:55:28] Ethash nonce search aborted              miner=3 attempts=23462
TRACE[11-09|10:55:28] Ethash nonce search aborted              miner=2 attempts=20734
TRACE[11-09|10:55:28] Ethash nonce search aborted              miner=0 attempts=22319
INFO [11-09|10:55:28] Successfully sealed new block            number=139 hash=044ca7…613598
DEBUG[11-09|10:55:28] Trie cache stats after commit            misses=38 unloads=3
TRACE[11-09|10:55:28] Propagated block                         hash=044ca7…613598 recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:28] Announced block                          hash=044ca7…613598 recipients=0 duration=2562047h47m16.854s
INFO [11-09|10:55:28] 🔗 block reached canonical chain          number=134 hash=d838f4…cee2bb
INFO [11-09|10:55:28] 🔨 mined potential block                  number=139 hash=044ca7…613598
INFO [11-09|10:55:28] Mining too far in the future             wait=2s
DEBUG[11-09|10:55:28] Reinjecting stale transactions           count=0
DEBUG[11-09|10:55:29] Recalculated downloader QoS values       rtt=20s confidence=1.000 ttl=1m0s
INFO [11-09|10:55:30] Commit new mining work                   number=140 txs=0 uncles=0 elapsed=2.005s
TRACE[11-09|10:55:30] Started ethash search for new nonces     miner=3 seed=2431275746132954900
TRACE[11-09|10:55:30] Started ethash search for new nonces     miner=0 seed=133342005747271086
TRACE[11-09|10:55:30] Started ethash search for new nonces     miner=1 seed=868361158371692178
TRACE[11-09|10:55:30] Started ethash search for new nonces     miner=2 seed=5249231453164485083
TRACE[11-09|10:55:31] Ethash nonce found and reported          miner=2 attempts=62517  nonce=5249231453164547600
TRACE[11-09|10:55:31] Ethash nonce search aborted              miner=0 attempts=62189
TRACE[11-09|10:55:31] Ethash nonce search aborted              miner=1 attempts=63614
TRACE[11-09|10:55:31] Ethash nonce search aborted              miner=3 attempts=69187
INFO [11-09|10:55:31] Successfully sealed new block            number=140 hash=03dd70…e52a0d
DEBUG[11-09|10:55:31] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:31] 🔗 block reached canonical chain          number=135 hash=7cbd94…37dc26
TRACE[11-09|10:55:31] Propagated block                         hash=03dd70…e52a0d recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:31] Announced block                          hash=03dd70…e52a0d recipients=0 duration=2562047h47m16.854s
INFO [11-09|10:55:31] 🔨 mined potential block                  number=140 hash=03dd70…e52a0d
DEBUG[11-09|10:55:31] Reinjecting stale transactions           count=0
INFO [11-09|10:55:31] Commit new mining work                   number=141 txs=0 uncles=0 elapsed=114.636µs
TRACE[11-09|10:55:31] Started ethash search for new nonces     miner=1 seed=276478866435324212
TRACE[11-09|10:55:31] Started ethash search for new nonces     miner=2 seed=6717522840261329056
TRACE[11-09|10:55:31] Started ethash search for new nonces     miner=0 seed=5244579135382777440
TRACE[11-09|10:55:31] Started ethash search for new nonces     miner=3 seed=2008888944128372975
TRACE[11-09|10:55:31] Ethash nonce found and reported          miner=1 attempts=11239  nonce=276478866435335451
TRACE[11-09|10:55:31] Ethash nonce search aborted              miner=0 attempts=12957
TRACE[11-09|10:55:31] Ethash nonce search aborted              miner=2 attempts=12635
TRACE[11-09|10:55:31] Ethash nonce search aborted              miner=3 attempts=10361
INFO [11-09|10:55:31] Successfully sealed new block            number=141 hash=f70e67…2e32f2
DEBUG[11-09|10:55:31] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:31] 🔗 block reached canonical chain          number=136 hash=63b459…f7943d
INFO [11-09|10:55:31] 🔨 mined potential block                  number=141 hash=f70e67…2e32f2
INFO [11-09|10:55:31] Commit new mining work                   number=142 txs=0 uncles=0 elapsed=123.645µs
TRACE[11-09|10:55:31] Propagated block                         hash=f70e67…2e32f2 recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:31] Announced block                          hash=f70e67…2e32f2 recipients=0 duration=2562047h47m16.854s
DEBUG[11-09|10:55:31] Reinjecting stale transactions           count=0
TRACE[11-09|10:55:31] Started ethash search for new nonces     miner=3 seed=8374694286219227537
TRACE[11-09|10:55:31] Started ethash search for new nonces     miner=2 seed=5525441204149154275
TRACE[11-09|10:55:31] Started ethash search for new nonces     miner=1 seed=5050633008585803076
TRACE[11-09|10:55:31] Started ethash search for new nonces     miner=0 seed=5994448739100426473
TRACE[11-09|10:55:31] Ethash nonce found and reported          miner=0 attempts=4285   nonce=5994448739100430758
TRACE[11-09|10:55:31] Ethash nonce search aborted              miner=3 attempts=3993
TRACE[11-09|10:55:31] Ethash nonce search aborted              miner=2 attempts=3740
TRACE[11-09|10:55:31] Ethash nonce search aborted              miner=1 attempts=6189
INFO [11-09|10:55:31] Successfully sealed new block            number=142 hash=aae188…c079bb
DEBUG[11-09|10:55:31] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:31] 🔗 block reached canonical chain          number=137 hash=bfebbd…7bebbb
INFO [11-09|10:55:31] 🔨 mined potential block                  number=142 hash=aae188…c079bb
DEBUG[11-09|10:55:31] Reinjecting stale transactions           count=0
TRACE[11-09|10:55:31] Propagated block                         hash=aae188…c079bb recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:31] Announced block                          hash=aae188…c079bb recipients=0 duration=2562047h47m16.854s
INFO [11-09|10:55:31] Mining too far in the future             wait=2s
INFO [11-09|10:55:33] Commit new mining work                   number=143 txs=0 uncles=0 elapsed=2.004s
TRACE[11-09|10:55:33] Started ethash search for new nonces     miner=1 seed=5169074969181971547
TRACE[11-09|10:55:33] Started ethash search for new nonces     miner=3 seed=452169367209038574
TRACE[11-09|10:55:33] Started ethash search for new nonces     miner=0 seed=5956945769096062545
TRACE[11-09|10:55:33] Started ethash search for new nonces     miner=2 seed=2025226096662640179
TRACE[11-09|10:55:34] Ethash nonce found and reported          miner=2 attempts=7973   nonce=2025226096662648152
TRACE[11-09|10:55:34] Ethash nonce search aborted              miner=0 attempts=8043
TRACE[11-09|10:55:34] Ethash nonce search aborted              miner=1 attempts=6665
TRACE[11-09|10:55:34] Ethash nonce search aborted              miner=3 attempts=8321
INFO [11-09|10:55:34] Successfully sealed new block            number=143 hash=b91839…9bcd57
DEBUG[11-09|10:55:34] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:34] 🔗 block reached canonical chain          number=138 hash=45b114…b0a64c
TRACE[11-09|10:55:34] Propagated block                         hash=b91839…9bcd57 recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:34] Announced block                          hash=b91839…9bcd57 recipients=0 duration=2562047h47m16.854s
INFO [11-09|10:55:34] 🔨 mined potential block                  number=143 hash=b91839…9bcd57
DEBUG[11-09|10:55:34] Reinjecting stale transactions           count=0
INFO [11-09|10:55:34] Commit new mining work                   number=144 txs=0 uncles=0 elapsed=331.063µs
TRACE[11-09|10:55:34] Started ethash search for new nonces     miner=0 seed=285769866382517826
TRACE[11-09|10:55:34] Started ethash search for new nonces     miner=2 seed=4211212444297990109
TRACE[11-09|10:55:34] Started ethash search for new nonces     miner=3 seed=7004332557753625929
TRACE[11-09|10:55:34] Started ethash search for new nonces     miner=1 seed=7813145494318450621
TRACE[11-09|10:55:34] Ethash nonce found and reported          miner=0 attempts=37990  nonce=285769866382555816
TRACE[11-09|10:55:34] Ethash nonce search aborted              miner=1 attempts=41488
TRACE[11-09|10:55:34] Ethash nonce search aborted              miner=2 attempts=41885
TRACE[11-09|10:55:34] Ethash nonce search aborted              miner=3 attempts=39940
INFO [11-09|10:55:34] Successfully sealed new block            number=144 hash=90e685…1fa3ba
DEBUG[11-09|10:55:34] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:34] 🔗 block reached canonical chain          number=139 hash=044ca7…613598
INFO [11-09|10:55:34] 🔨 mined potential block                  number=144 hash=90e685…1fa3ba
TRACE[11-09|10:55:34] Propagated block                         hash=90e685…1fa3ba recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:34] Announced block                          hash=90e685…1fa3ba recipients=0 duration=2562047h47m16.854s
DEBUG[11-09|10:55:34] Reinjecting stale transactions           count=0
INFO [11-09|10:55:34] Commit new mining work                   number=145 txs=0 uncles=0 elapsed=159.903µs
TRACE[11-09|10:55:34] Started ethash search for new nonces     miner=1 seed=5829638230506590037
TRACE[11-09|10:55:34] Started ethash search for new nonces     miner=0 seed=1575797057955125519
TRACE[11-09|10:55:34] Started ethash search for new nonces     miner=3 seed=4259186434366596182
TRACE[11-09|10:55:34] Started ethash search for new nonces     miner=2 seed=8406925385514726032
TRACE[11-09|10:55:34] Ethash nonce found and reported          miner=1 attempts=31101  nonce=5829638230506621138
TRACE[11-09|10:55:34] Ethash nonce search aborted              miner=3 attempts=32654
TRACE[11-09|10:55:34] Ethash nonce search aborted              miner=0 attempts=30571
TRACE[11-09|10:55:34] Ethash nonce search aborted              miner=2 attempts=32876
INFO [11-09|10:55:34] Successfully sealed new block            number=145 hash=9a1563…352fd8
DEBUG[11-09|10:55:34] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:34] 🔗 block reached canonical chain          number=140 hash=03dd70…e52a0d
INFO [11-09|10:55:34] 🔨 mined potential block                  number=145 hash=9a1563…352fd8
DEBUG[11-09|10:55:34] Reinjecting stale transactions           count=0
INFO [11-09|10:55:34] Mining too far in the future             wait=2s
TRACE[11-09|10:55:34] Propagated block                         hash=9a1563…352fd8 recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:34] Announced block                          hash=9a1563…352fd8 recipients=0 duration=2562047h47m16.854s
INFO [11-09|10:55:36] Commit new mining work                   number=146 txs=0 uncles=0 elapsed=2.004s
TRACE[11-09|10:55:36] Started ethash search for new nonces     miner=3 seed=8286615947492221141
TRACE[11-09|10:55:36] Started ethash search for new nonces     miner=2 seed=8741615336398335994
TRACE[11-09|10:55:36] Started ethash search for new nonces     miner=1 seed=4669180278364899564
TRACE[11-09|10:55:36] Started ethash search for new nonces     miner=0 seed=7148111501866672766
TRACE[11-09|10:55:36] Pooled new future transaction            hash=b9bbcd…d3707a from=0x4861F79070597b9aC1C254CA2Ed60A529Dd2e389 to=0xB1B74d101f884B096a61D81Be872313C1B7fe3d5
TRACE[11-09|10:55:36] Promoting queued transaction             hash=b9bbcd…d3707a
INFO [11-09|10:55:36] Submitted transaction                    fullhash=0xb9bbcd667e4ed74ffdf05fe160c3b22f0fe649bb72c77ccf1aed42fe88d3707a recipient=0xB1B74d101f884B096a61D81Be872313C1B7fe3d5
TRACE[11-09|10:55:36] Broadcast transaction                    hash=b9bbcd…d3707a recipients=0
TRACE[11-09|10:55:37] Ethash nonce found and reported          miner=2 attempts=14067  nonce=8741615336398350061
TRACE[11-09|10:55:37] Ethash nonce search aborted              miner=0 attempts=14680
TRACE[11-09|10:55:37] Ethash nonce search aborted              miner=3 attempts=12633
TRACE[11-09|10:55:37] Ethash nonce search aborted              miner=1 attempts=11797
INFO [11-09|10:55:37] Successfully sealed new block            number=146 hash=9cae54…158806
DEBUG[11-09|10:55:37] Trie cache stats after commit            misses=38 unloads=3
INFO [11-09|10:55:37] 🔗 block reached canonical chain          number=141 hash=f70e67…2e32f2
INFO [11-09|10:55:37] 🔨 mined potential block                  number=146 hash=9cae54…158806
DEBUG[11-09|10:55:37] Reinjecting stale transactions           count=0
TRACE[11-09|10:55:37] Propagated block                         hash=9cae54…158806 recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:37] Announced block                          hash=9cae54…158806 recipients=0 duration=2562047h47m16.854s
INFO [11-09|10:55:37] Commit new mining work                   number=147 txs=1 uncles=0 elapsed=387.009µs
TRACE[11-09|10:55:37] Started ethash search for new nonces     miner=3 seed=7566020767740453247
TRACE[11-09|10:55:37] Started ethash search for new nonces     miner=1 seed=5884659729515644343
TRACE[11-09|10:55:37] Started ethash search for new nonces     miner=2 seed=1071774666687042399
TRACE[11-09|10:55:37] Started ethash search for new nonces     miner=0 seed=2002936964839990580
TRACE[11-09|10:55:37] Ethash nonce found and reported          miner=1 attempts=1515   nonce=5884659729515645858
TRACE[11-09|10:55:37] Ethash nonce search aborted              miner=3 attempts=61
TRACE[11-09|10:55:37] Ethash nonce search aborted              miner=2 attempts=100
TRACE[11-09|10:55:37] Ethash nonce search aborted              miner=0 attempts=722
INFO [11-09|10:55:37] Successfully sealed new block            number=147 hash=5fc288…c85458
DEBUG[11-09|10:55:37] Trie cache stats after commit            misses=43 unloads=5
INFO [11-09|10:55:37] 🔗 block reached canonical chain          number=142 hash=aae188…c079bb
INFO [11-09|10:55:37] 🔨 mined potential block                  number=147 hash=5fc288…c85458
TRACE[11-09|10:55:37] Propagated block                         hash=5fc288…c85458 recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:37] Announced block                          hash=5fc288…c85458 recipients=0 duration=2562047h47m16.854s
DEBUG[11-09|10:55:37] Reinjecting stale transactions           count=0
TRACE[11-09|10:55:37] Removed old pending transaction          hash=b9bbcd…d3707a
TRACE[11-09|10:55:37] Skipping transaction with low nonce      sender=0x4861F79070597b9aC1C254CA2Ed60A529Dd2e389 nonce=3
INFO [11-09|10:55:37] Commit new mining work                   number=148 txs=0 uncles=0 elapsed=675.189µs
TRACE[11-09|10:55:37] Started ethash search for new nonces     miner=3 seed=3958501350403479078
TRACE[11-09|10:55:37] Started ethash search for new nonces     miner=1 seed=6203768588880501513
TRACE[11-09|10:55:37] Started ethash search for new nonces     miner=2 seed=5064820792710835590
TRACE[11-09|10:55:37] Started ethash search for new nonces     miner=0 seed=5412274811189968416
TRACE[11-09|10:55:37] Ethash nonce found and reported          miner=2 attempts=13335  nonce=5064820792710848925
TRACE[11-09|10:55:37] Ethash nonce search aborted              miner=3 attempts=16363
TRACE[11-09|10:55:37] Ethash nonce search aborted              miner=1 attempts=15195
TRACE[11-09|10:55:37] Ethash nonce search aborted              miner=0 attempts=14805
INFO [11-09|10:55:37] Successfully sealed new block            number=148 hash=a2f133…7d3c3a
DEBUG[11-09|10:55:37] Trie cache stats after commit            misses=43 unloads=5
TRACE[11-09|10:55:37] Propagated block                         hash=a2f133…7d3c3a recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:37] Announced block                          hash=a2f133…7d3c3a recipients=0 duration=2562047h47m16.854s
INFO [11-09|10:55:37] 🔗 block reached canonical chain          number=143 hash=b91839…9bcd57
INFO [11-09|10:55:37] 🔨 mined potential block                  number=148 hash=a2f133…7d3c3a
DEBUG[11-09|10:55:37] Reinjecting stale transactions           count=0
INFO [11-09|10:55:37] Mining too far in the future             wait=2s
INFO [11-09|10:55:39] Commit new mining work                   number=149 txs=0 uncles=0 elapsed=2.003s
TRACE[11-09|10:55:39] Started ethash search for new nonces     miner=3 seed=9004437381227325005
TRACE[11-09|10:55:39] Started ethash search for new nonces     miner=1 seed=4677894406148947982
TRACE[11-09|10:55:39] Started ethash search for new nonces     miner=2 seed=4282958466159618226
TRACE[11-09|10:55:39] Started ethash search for new nonces     miner=0 seed=5473315208039867250
TRACE[11-09|10:55:39] Ethash nonce found and reported          miner=1 attempts=2608   nonce=4677894406148950590
TRACE[11-09|10:55:39] Ethash nonce search aborted              miner=2 attempts=3102
TRACE[11-09|10:55:39] Ethash nonce search aborted              miner=0 attempts=2995
TRACE[11-09|10:55:39] Ethash nonce search aborted              miner=3 attempts=2149
INFO [11-09|10:55:39] Successfully sealed new block            number=149 hash=2c3ef8…a77061
DEBUG[11-09|10:55:39] Trie cache stats after commit            misses=43 unloads=5
INFO [11-09|10:55:39] 🔗 block reached canonical chain          number=144 hash=90e685…1fa3ba
INFO [11-09|10:55:39] 🔨 mined potential block                  number=149 hash=2c3ef8…a77061
INFO [11-09|10:55:39] Commit new mining work                   number=150 txs=0 uncles=0 elapsed=130.236µs
TRACE[11-09|10:55:39] Propagated block                         hash=2c3ef8…a77061 recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:39] Announced block                          hash=2c3ef8…a77061 recipients=0 duration=2562047h47m16.854s
TRACE[11-09|10:55:39] Started ethash search for new nonces     miner=3 seed=1397362054021317308
TRACE[11-09|10:55:39] Started ethash search for new nonces     miner=1 seed=8416565765969603762
DEBUG[11-09|10:55:39] Reinjecting stale transactions           count=0
TRACE[11-09|10:55:39] Started ethash search for new nonces     miner=2 seed=8261865379882237351
TRACE[11-09|10:55:39] Started ethash search for new nonces     miner=0 seed=38264667837276317
TRACE[11-09|10:55:39] Ethash nonce found and reported          miner=2 attempts=49915  nonce=8261865379882287266
TRACE[11-09|10:55:39] Ethash nonce search aborted              miner=1 attempts=48727
TRACE[11-09|10:55:39] Ethash nonce search aborted              miner=0 attempts=51358
TRACE[11-09|10:55:39] Ethash nonce search aborted              miner=3 attempts=52728
INFO [11-09|10:55:39] Successfully sealed new block            number=150 hash=b1ea6e…b8382e
DEBUG[11-09|10:55:39] Trie cache stats after commit            misses=43 unloads=5
INFO [11-09|10:55:39] 🔗 block reached canonical chain          number=145 hash=9a1563…352fd8
  • you should first check who is delaying. enable debug.verbosity(6) and check exact execution time of geth. – Nulik Nov 8 '17 at 21:54
  • i've started geth with --minerthreads 4 and --verbosity 6, see verbose log in updated Question. I've started multiple tests so probably you can see multiple transactions. What should i find in the log? Can you see something can be adjusted? – 4ntoine Nov 9 '17 at 5:59
0

It's web3j feature/issue and you can change this behaviour: https://github.com/web3j/web3j/issues/231

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.