Mining 1-2 MB blocks in ZCash makes no economic sense at all, bitcoin network pays several thousands dollars in fees for 1 MB blocks.

If it takes more than 5 seconds to build new block template I encourage miners to mine empty blocks instead. So please either optimise it or remove 20% tax if you are not capable to deploy fix or raise fees to some decent level like 1000x from current price via hard fork.

New block to mine on <skipped> at height 106477 with 57 tx, 10.00000000 reward, 0.01994709 fees (25.5959ms, 3.260499057s)

The former is a time spent on building merkle tree on a pool side, the latter is how much time spent to call getblocktemplate via loopback interface: 3.26 seconds.

It takes 3.26 seconds to produce block template with just 57 transactions in zcashd on decent hardware. Up to 3% of block time.

+1 . I notice pool freezing, because of transaction spam.

getmempoolinfo

{
  "size": 305,
  "bytes": 11080568,
  "usage": 23548336
}

I am working on a patch to completely ignore mempool for now, will mine empty blocks.

I'm seeing similar issues with slow getblocktemplate today. It hasn't been reported above, but I'm also seeing extremely large RSS after running a node for several weeks. After some digging, I think this could be related: bitcoin/bitcoin#6876.

Leaving aside the issue of whether or not this is actually intentional transaction spam, I think it's fair to expect getblocktemplate to handle these worst-case situations without become extremely slow.

I can confirm the issue as well. Those large spam blocks cause huge CPU usage and even crashed some of my nodes on lower-spec machines.

Looks like it started around block #106077 (0000000030728e6b5b5484473812dd3c8ff4a857693fa1a48b457bfd72661c17) at 19:35:35 GMT yesterday (Sunday 30th Apr).

Looking at a single sample, an amount of ZEC is unshielded (e.g. txn c18cd332d4e09b9e53a4a9e23d32206d997aa7ece9d7bd41872d1b6fd2bbca79 unshielded 82.74963511 ZEC into t1QMCGKi92v85Jmar2PD3SjQF8Eadbd2y4q), then sent in a single transaction with 100s of small outputs (e.g. t1QMCGKi92v85Jmar2PD3SjQF8Eadbd2y4q sent 82.74963511 ZEC to 1869 outputs - tx c00782ba18f2ae70b60b983fb273c2160020a10e4cab27db39e8a5c59320071c), which then seem to get (partially?) re-aggregated into other addresses.

Some of the addresses involved t1VoqSxHh1ZnWBRFyHh6diWM4whimFzhjcJ have been around for a while (and have been part of similar patterns of transactions in the past).

@sammy007 wore:

[...] if you are going to pretend that it's fine.
[...] or raise fees to some decent level like 1000x from current price via hard fork.

We are not "pretending that it's fine". This started at 9:08 UTC which was only 2 hours before you filed the ticket; please give us time to analyse the issue thoroughly. There's not going to be any knee-jerk reaction where we raise fees (at all, let alone by 1000-fold) unless we have strong evidence that it is required. Nor would raising fees require a hard fork, if it were required.

Spam started more than 12 hours ago. And this is not my duty to watch network state.
Provide an option to ignore txes of particular size or an option to require higher fees for nodes.
GBT uses mempool, we need such txes to never reach it.

Indeed the large blocks do seem to have started around block 106077, which was at 2017-04-30 19:35:35 UTC, which is just under 20 hours ago. I stand corrected.

@daira: My bad. It looks like the activity comes in waves.

This is quite critical problem. Pool is suffering.

We've been looking into this for the last ten hours or so. Here's what we've established:

• The transactions appear to be the result of a miner collecting six month's worth of mining rewards into a single address, most likely via a script started over the weekend.
• The script appears to use batching: around 300 transactions are created at a time containing ~250 inputs each (for a size of around 37070 bytes each), and the next batch is not created until the previous batch has been completely removed from the mempool.
• The mining network is clearing these batches from the mempool in about six blocks (as expected given the transaction sizes and block size limit).
• Per-transaction-input validation time is around 0.2-0.4ms for an up-to-date node, or 0.6-0.9ms for a node syncing the block chain at the same time (both measured on my Core i7-6600U laptop).
  • This is the quadratic hashing issue inherited from Bitcoin, and is in line with our existing benchmark on a Xeon E3-1225 V2 for validating a transaction with many inputs (specifically 555 inputs, targeting the consensus maximum transaction size of 100,000 bytes).
  • This puts the time to validate the full blocks (containing around 60 of these transactions) at around 6 seconds (60 tx/block * 250 txin/tx * 0.4 ms/txin), with a maximum of 10 seconds for an up-to-date node (again, as seen on my Core i7-6600U laptop).
• getblocktemplate latency appears to be affected by the mempool load, but we are still investigating exactly how.

We are still in the middle of investigating several parts of the code, and will post another update later on.

Here is the log output for getblocktemplate with -debug=bench after applying this patch to master, while there were 255 of these transactions in my local mempool:

 - getblocktemplate called
   - Preamble: 0.01ms
   - Longpoll: 0.14ms
 keypool reserve 2
   - CreateNewBlock called
     - Preamble: 0.02ms
     - Locked preamble: 0.23ms
     - Mempool access: 3310.92ms
       - Prev tx access: 3291.40ms (0.05ms x 61769)
       - Coins access: 6.29ms (0.00ms x 61769)
     - Block filling: 6536.69ms
       - Check inputs: 6480.59ms (104.53ms x 62)
       - Update coins: 38.83ms (0.63ms x 62)
 CreateNewBlock(): total size 1985159
     - Block creation: 0.27ms
       - Connect 63 transactions: 445.62ms (7.073ms/tx, 0.033ms/txin) [1.26s]
     - Verify 13326 txins: 1067.32ms (0.080ms/txin) [5.09s]
     - Block validation: 1385.73ms
     - Total time: 11548.25ms
 keypool return 2
   - Block update: 11601.63ms
   - Ret prep txs: 21.15ms
   - Ret prep aux: 3.60ms
   - Total time: 11626.59ms

The bottlenecks are:

• Prev tx access: CCoinsViewCache::HaveCoins(txin.prevout.hash)
• Check inputs: ContextualCheckInputs(tx)
• Block validation: TestBlockValidity(block)

As the primary bottleneck is transparent signature validation, I've opened #2335 to switch to libsecp256k1 for validation, which should be "anywhere between 2.5 and 5.5 times faster" per bitcoin/bitcoin#6954.

@sammy007 @a1binos @zapv0lt @gobitfly @miningpoolhub please test this PR in your infrastructure and let me know how much latency this removes compared to the current release (either overall, or using the benchmark patch I linked in my last comment).

Intel(R) Core(TM) i7-6700K CPU @ 4.00GHz str4d:2333-validation-speed

1.60983597s
419.145133ms
847.123985ms
22.432544ms
1.482908816s

Intel(R) Xeon(R) CPU E3-1245 v5 @ 3.50GHz v1.0.8-1 -TestBlockValidity

3.808361534s
2.762839296s
4.369284388s
3.075969ms
4.253306917s

This is getting pretty severe now, zcashd becomes unresponsive and takes 100% CPU on 4 cores. My pool is not functioning correctly because zcashd is freezing, you cannot even do zcash-cli getinfo without it hanging for 10 seconds.

the process is now back to 100% cpu usage, even going as high as 400% an error in the console window is [POOL] [ZCASH] (Thread 1) Could not parse rpc data from daemon instance 0
Request Data: {"method":{getblocksubsidy",params":[],"id":1493752719588
Request Data: Work queue depth exceeded

Check top, and zcashd is taking 100% CPU Usage. 100% per thread at 400% CPU

ZCASHD is on ubuntu server 64bit with 48GB ram allocated to the virtual machine.

ZCASHD debug.log spammed, with new blocks, when this is happening cpu usage spikes to 100% per CPU core.

2017-05-02 21:14:54 CreateNewBlock(): total size 1982104
2017-05-02 21:14:56 keypool return 5
2017-05-02 21:14:57 keypool reserve 5
2017-05-02 21:15:00 CreateNewBlock(): total size 1982104
2017-05-02 21:15:01 keypool return 5
2017-05-02 21:15:03 keypool reserve 5
2017-05-02 21:15:06 CreateNewBlock(): total size 1982104
2017-05-02 21:15:08 keypool return 5
2017-05-02 21:15:09 keypool reserve 5
2017-05-02 21:15:12 CreateNewBlock(): total size 1982104
2017-05-02 21:15:13 keypool return 5
2017-05-02 21:15:15 keypool reserve 5
2017-05-02 21:15:18 CreateNewBlock(): total size 1982104
2017-05-02 21:15:19 keypool return 5
2017-05-02 21:15:21 keypool reserve 5
2017-05-02 21:15:24 CreateNewBlock(): total size 1982104
2017-05-02 21:15:25 keypool return 5
2017-05-02 21:15:27 keypool reserve 5
2017-05-02 21:15:29 CreateNewBlock(): total size 1982104
2017-05-02 21:15:31 keypool return 5
2017-05-02 21:15:33 keypool reserve 5
2017-05-02 21:15:36 CreateNewBlock(): total size 1982104
2017-05-02 21:15:37 keypool return 5

@Xandrah per our chat in #zcash on Rocket.Chat, the reason for the lock-up (and likely for the ballooning memory usage) is because getblocktemplate is being called every few seconds, but each call is taking a few seconds to return. getblocktemplate holds the global lock cs_main, so while it is running, other calls (including subsequent getblocktemplate calls) will back up, eventually exceeding the work queue depth and causing the error you saw. You can increase the work queue depth from its default of 16 with -rpcworkqueue=##, but getblocktemplate needs to be called less frequently if it is taking longer to respond.

Got about the same results as Sammy with the pr.

If the "activity" seems to be "in waves", i'd suggest that this is f2pool processing dayly payments. Its hashrate grew up noticebly the last few days. Unlike flypool - its the only matching in hash power opponent, which processes just-in-time on-the-fly micropayments when miners reach their "threshold" - f2pool makes all the payments (hundreds of tons of them, eventually) just 1 time per day, nearly the morning of China time.
Suggestion: let f2pool implement "threshold" payments distributed equally (in common) during all the day (like Flypool), or somehow let it rearrange miners on several groups which get their coins on some different predefined time patterns.

Red flag: Nathan mistakenly thought that the Incident Response team had required this ticket to be prioritised for 1.0.9. In fact the opposite was true, the Incident Response team (me as Executive Coordinator) had decided that we would take steps to fix the problem in the short term explicitly under the assumption that this would not imply that this ticket would be prioritised for 1.0.9.

The next step on this issue is diagnosis, experimentation, and benchmarking. Why does this issue not happen in Bitcoin?

The next step on this issue is diagnosis, experimentation, and benchmarking. Why does this issue not happen in Bitcoin?

For some historical context 0.11.x bitcoind had major performance issues(it couldn't properly handle mining/propagation of 1MB blocks without the relay network and had some pretty severe performance degradation with mempools larger than a few megabytes) these were fairly well known issues at the time, and these issues were largely resolved with the 0.12 bitcoin core release(diagnosis, experimentation, benchmarking and of course writing the code to resolve them was done).

When I was operating a pool with 0.11.x I had to do a lot of mostly manual mempool monitoring and limiting to prevent GBT call times from being excessive. The performance issues were not due to a single cause but multiple factors and required major rewrites of a number of internal bitcoin core components to resolve.

Since zcash is a fork of 0.11.2 I would expect it to have those same issues bitcoin had back then.

You may want to rebase on top of bitcoin 0.14.1 since it has many performance improvements since 0.11.2.

@jameshilliard Thanks for the context! Looks like we have our work cut out for us.

#2342, adding the -mempooltxinputlimit config option to limit the number of transparent inputs in transactions, is included in 1.0.10. Updating the milestone for remaining issues.

The original problem was mitigated by adding -mempooltxinputlimit, and then solved by fixing the quadratic hashing problem at Overwinter activation (which also removed -mempooltxinputlimit). If there are other tx validation performance improvements that could be pulled in from Bitcoin, that should be a separate ticket.

Note, incidentally, that we solved this without raising fees (denominated in ZEC) at all.