JayDDee / cpuminer-opt

Optimized multi algo CPU miner
Other
765 stars 543 forks source link

[solo mode] "Block solved" is not always printed off #329

Closed YetAnotherRussian closed 3 years ago

YetAnotherRussian commented 3 years ago

Hi. Solo mode output for a prolonged period of time looks a little bit strange:

In solo mode I got 100% accepted:

image

But the stats report and immediate output (on block acceptance) shows that not all of them are blocks, which is impossible.

I'm unsure about the reason, but feel free to ask for any debug info, if needed.

Or, maybe, this should be hardcoded: if it's getwork/gbt, then any accepted share should be forcibly considered as a solved block.

Some additional info: latest build, argon2d, Windows (any ver. really), multiple threads, gigabit lan, rpc server on a performance 4-core cpu

Thanks.

JayDDee commented 3 years ago

BLOCK SOLVED is based on the submitted share diff >= network diff. The net diff for block 4966696 is .00027 but the non-block share is only .00025. Did the wallet accept the blocks not reported by the miner?

I noticed that a new block with a lower diff was emmitted immediately after the share was submitted. The share diff would have been a valid block solution for 4956297. Can you confirm the wallet reports the same block and diff as the miner or did share 118 actually solve the next block?

You can add -D to get the actual hash value and target used to decide whether to submit the share. Since the miner submitted the share it thought it passed the test. The hash value should be <= target to be submitted.

YetAnotherRussian commented 3 years ago

Can you confirm the wallet reports the same block and diff as the miner or did share 118 actually solve the next block?

Well, in short words, yes. Same thing for a newer example block:

Block was submitted & accepted (no "BLOCK SOLVED" info): image

Reward payed & enough confirmations passed for that block: image

No other blocks found in this period of time as well.

-D option was set, will take some time to collect data

JayDDee commented 3 years ago

I don't see the block number? Did the wallet confirm block 4956658 or 4956659?

I also don't see the net diff for block 4956658. Was it higher than 4956659? Was it higher that the share diif for share 134? Edit: I found the diff for 4956658, it was higher than the share diff which is why it was not marked solved.

Edit: please also verify the block numbers of the blocks correctly reported as solved.

This could an off-by-one error in the block number.

YetAnotherRussian commented 3 years ago

I don't see the block number? Did the wallet confirm block 4956658 or 4956659?

Sorry, this info cannot be found in the wallet...

UPDATE: got some debug data:

### 1) The case we found a block, it got accepted, it was logged like a block:

[2021-06-21 18:14:30] GBT new work received in 1.00 ms [2021-06-21 18:14:30] Threads restarted for new work. [2021-06-21 18:14:32] Threads restarted for new work. [2021-06-21 18:14:32] 7 Submitted Diff 0.0005752, Block 4956884, Ntime d4acd060 [2021-06-21 18:14:32] Thread 0, Nonce 99010000, Xnonce2 Argon2d [2021-06-21 18:14:32] Data[0:19]: 0408a324 c129ae0b affe8072 7ac21fde f0d9ad60 f61d12a0 91784839 0173a85b eb0f6af5 7a8085d0 [2021-06-21 18:14:32] : d2d480bd 08d03be9 c8245b7b e249aec9 af1bf20f ead36f95 b8ec81b0 d4acd060 79e20c1e 99010000 [2021-06-21 18:14:32] Hash[7:0]: 000006ca 8a2c622e 1fac1e25 44847549 6af9a743 38615d16 6d9d8d1b 27662d73 [2021-06-21 18:14:32] Targ[7:0]: 00000ce2 79000000 00000000 00000000 00000000 00000000 00000000 00000000 [2021-06-21 18:14:32] 7 A6 S0 R1 BLOCK SOLVED 62021-06-21 18:14:32 Diff 0.0005752, Block 4956884 [2021-06-21 18:14:32] Mining info: diff 0.00030317, net_hashrate 4249147687814.563000, height 4956884 [2021-06-21 18:14:32] GBT new work received in 16.00 ms [2021-06-21 18:14:32] New Block 4956885, Net Diff 0.00030317, Ntime d6acd060 Miner TTF @ 1804.58 h/s 12m01s, Net TTF @ 4249.15 Gh/s 0m00s [2021-06-21 18:14:32] Threads restarted for new work. [2021-06-21 18:14:37] Mining info: diff 0.00030317, net_hashrate 4249147687814.563000, height 4956884 ... [CUT-OFF PART] ...

                  Periodic Report     5m00s        45m26s
                  Share rate        0.20/min     0.15/min
                  Hash rate       4336.74h/s   3797.58h/s   (1827.17h/s)
                  Lost hash rate     0.00h/s    477.66h/s
                  Submitted             1            7
                  Accepted              1            6
                  Rejected              0            1
                  Blocks Solved         1            6
                  Hi/Lo Share Diff  0.0052339 /  0.00042185

### 2) The case we found a block, it got accepted, but logged like a block:

[2021-06-21 18:32:43] Mining info: diff 0.00030317, net_hashrate 4082687570475.483900, height 4956892 [2021-06-21 18:32:43] GBT new work received in 1.00 ms [2021-06-21 18:32:43] Threads restarted for new work. [2021-06-21 18:32:48] Mining info: diff 0.00030317, net_hashrate 4082687570475.483900, height 4956892 [2021-06-21 18:32:48] GBT new work received in 1.00 ms [2021-06-21 18:32:48] Threads restarted for new work. [2021-06-21 18:32:54] Threads restarted for new work. [2021-06-21 18:32:54] 8 Submitted Diff 0.00024822, Block 4956893, Ntime 1eb1d060 [2021-06-21 18:32:54] Thread 11, Nonce 4eaeaaea, Xnonce2 main [2021-06-21 18:32:54] Data[0:19]: 0408a324 7020a4e4 7ef8772c c3572896 92031ea5 32a4a310 58ce7f75 114790fe ae093ec1 bfa82b04 [2021-06-21 18:32:54] : 174b428b 29d5f185 1a212286 d861e17b 2158aa58 5dea39f0 7786d5a8 1eb1d060 ffff0f1e 4eaeaaea [2021-06-21 18:32:54] Hash[7:0]: 00000fbc b004ebb5 4a597a93 74895a55 03164a20 9ac129b9 d4aa1530 e8136a4c [2021-06-21 18:32:54] Targ[7:0]: 00000fff ff000000 00000000 00000000 00000000 00000000 00000000 00000000 [2021-06-21 18:32:54] 8 Accepted 7 S0 R1 B6, 1101.208 sec (23ms) Diff 0.00024822, Block 4956893 [2021-06-21 18:32:54] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:32:54] GBT new work received in 16.00 ms [2021-06-21 18:32:54] New Block 4956894, Net Diff 0.00024414, Ntime 24b1d060 Miner TTF @ 1833.10 h/s 9m32s, Net TTF @ 3969.15 Gh/s 0m00s [2021-06-21 18:32:54] Threads restarted for new work. [2021-06-21 18:32:59] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:32:59] GBT new work received in 1.00 ms [2021-06-21 18:32:59] Threads restarted for new work. [2021-06-21 18:33:04] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:04] GBT new work received in 2.00 ms [2021-06-21 18:33:04] Threads restarted for new work. [2021-06-21 18:33:09] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:09] GBT new work received in 1.02 ms [2021-06-21 18:33:09] Threads restarted for new work. [2021-06-21 18:33:14] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:14] GBT new work received in 1.00 ms [2021-06-21 18:33:14] Threads restarted for new work. [2021-06-21 18:33:19] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:19] GBT new work received in 1.00 ms [2021-06-21 18:33:19] Threads restarted for new work. [2021-06-21 18:33:24] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:24] GBT new work received in 2.00 ms [2021-06-21 18:33:24] Threads restarted for new work. [2021-06-21 18:33:29] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:29] argon2d4096: 127.0.0.1:54321  Periodic Report 5m00s 1h00m Share rate 0.20/min 0.13/min Hash rate 3483.59h/s 3207.02h/s (1833.10h/s) Lost hash rate 0.00h/s 288.54h/s Submitted 1 8 Accepted 1 7 Rejected 0 1 Blocks Solved 0 6 Hi/Lo Share Diff 0.0052339 / 0.00024822 [2021-06-21 18:33:29] GBT new work received in 1.00 ms [2021-06-21 18:33:29] Threads restarted for new work. [2021-06-21 18:33:34] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:34] GBT new work received in 1.00 ms [2021-06-21 18:33:34] Threads restarted for new work. [2021-06-21 18:33:39] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:39] GBT new work received in 2.00 ms [2021-06-21 18:33:39] Threads restarted for new work. [2021-06-21 18:33:44] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:44] GBT new work received in 1.00 ms [2021-06-21 18:33:44] Threads restarted for new work. [2021-06-21 18:33:49] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:49] GBT new work received in 1.00 ms [2021-06-21 18:33:49] Threads restarted for new work. [2021-06-21 18:33:54] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:54] GBT new work received in 1.00 ms [2021-06-21 18:33:54] Threads restarted for new work. [2021-06-21 18:33:59] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:33:59] GBT new work received in 2.00 ms [2021-06-21 18:33:59] Threads restarted for new work. [2021-06-21 18:34:04] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:34:04] GBT new work received in 1.00 ms [2021-06-21 18:34:04] Threads restarted for new work. [2021-06-21 18:34:09] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:34:09] GBT new work received in 1.00 ms [2021-06-21 18:34:09] Threads restarted for new work. [2021-06-21 18:34:14] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:34:14] GBT new work received in 1.00 ms [2021-06-21 18:34:14] Threads restarted for new work. [2021-06-21 18:34:19] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:34:19] GBT new work received in 2.00 ms [2021-06-21 18:34:19] Threads restarted for new work. [2021-06-21 18:34:24] Mining info: diff 0.00024414, net_hashrate 3969149518085.090800, height 4956893 [2021-06-21 18:34:24] GBT new work received in 2.00 ms [2021-06-21 18:34:24] Threads restarted for new work. [2021-06-21 18:34:29] Mining info: diff 0.00024414, net_hashrate 4163322918242.616200, height 4956894 [2021-06-21 18:34:29] GBT new work received in 1.16 ms [2021-06-21 18:34:29] New Block 4956895, Net Diff 0.00024414, Ntime 83b1d060 Miner TTF @ 1818.29 h/s 9m36s, Net TTF @ 4163.32 Gh/s 0m00s [2021-06-21 18:34:29] Threads restarted for new work.

YetAnotherRussian commented 3 years ago

Will get some more consistent logs soon, as I got a total blackout for around 1 hour, so the ones above may be messy in terms of 1-hour report period (the tee tool from GnuWin32 tools just appended some new logs into an older ones). Will give a full .txt

UPD: check the last report @ [2021-06-21 22:12:45] and go up cpuminer_log.zip

JayDDee commented 3 years ago

I think I've found the bug. The target diff is not being updated correctly for the stats. It's only a GBT problem and it doesn't affect mining. The only symptom is that solved blocks are reported by the miner only as accepted.

Tip: in the future use --no-color when capturing debug info for a text file, it's more readable.

JayDDee commented 3 years ago

I noticed another issue, the net hashrate seem way too high. This results in a zero second TTF estimate yet blocks are emitted aproximately every 20 seconds. The net hadshrate is provided by the RPC server by the get_mininginfo method and is reported on the new block log. The value can be confirm by adding the -P option to capture the raw RPC response.

Can you add -P to see if the numbers match? Can you also try to determine the net hashrate by other means such from any pools that report it? I want to make sure it's not a miner problem.

JayDDee commented 3 years ago

Regarding the original issue it looks like the stats were based on the previous block's net diff. Net diff isn't used for verifying hash, the actual hash target is used, therefore mining wasn't directly affected, only the stats.

The only effect of the incorrect diff was in the determination of the hash being good enough to solve a block. If the previous block had a higher diff and the submitted hash was between the old diff and new diff the hash would be reported as only being good eough for an eccepted share, not a full block.

Had mining been affected you would have seen a lot of stale shares.

I have a fix for it but I'll wait for more infor about the net hashrate issue.

YetAnotherRussian commented 3 years ago

I noticed another issue, the net hashrate seem way too high

This is not an issue, or at least not a miner issue. This nethash value is the total nethash for a multi-algo netwok (that includes ASIC algorithms with the appropriate hashrate, something like "algo1 + algo2 + ... + algo n" hashrate) while the JSON-RPC server is configured to provide Argon2d "work" for cpuminer-opt. Diff value and TTF are reported correctly. I haven't seen a multi-algo solo mining which behaves not like this.

I think this side should be left "as is" instead of providing crutches in attempt to calculate the "target algo only nethash".

JayDDee commented 3 years ago

Thanks for the explanation about the hashrate. I agree there is nothing to be done in the miner.

JayDDee commented 3 years ago

cpuminer-opt-3.16.4 is released. It has changes to GBT code that has not been properly tested. Please test and report any problems.

YetAnotherRussian commented 3 years ago

Well, as for now I cannot confirm this one is fixed in 3.16.4...

image image image

Total report for ~3 hours: image

Stay tuned, I'll collect some data with -D

YetAnotherRussian commented 3 years ago

New log cpuminer_log2.zip

JayDDee commented 3 years ago

Edit: much of the analysis below is wrong because mininginfo is always one block behind. Block 208 was logged at 13:33:57

I may have found something that needs further investigation at time 13:34:27 in the log file, extracted and anotated below. It looks like a synchronization problem, a solution for a new block was submitted before the new block was logged and before the stats were updated for the new block.

[2021-06-24 13:34:22] Mining info: diff 0.00039259, net_hashrate 2829971517045.932100, height 4961207 ---> last mining info before submit, block 207, dif = .00039

[2021-06-24 13:34:22] GBT new work received in 1.61 ms [2021-06-24 13:34:22] Threads restarted for new work. ---> restart for block 207

[2021-06-24 13:34:27] Threads restarted for new work. ---> restart for block 208? No mininginfo or new_block log??? No "GBT new work received" log either

[2021-06-24 13:34:27] 4 Submitted Diff 0.00024479, Block 4961208, Ntime b05fd460 ---> hash submitted for block 208

[2021-06-24 13:34:27] Thread 10, Nonce 155855d5, Xnonce2 main [2021-06-24 13:34:27] Data[0:19]: 0408a324 47ec6e53 51e56837 91afe6b4 c89472eb 8c190d24 c0482ad2 768df04e 1b2dacf3 fbe7ac84 [2021-06-24 13:34:27] : 833a2fdf 19cc35c6 aac4a654 e368509c b29f475f 34a0c552 4248baab b05fd460 ffff0f1e 155855d5 [2021-06-24 13:34:27] Hash[7:0]: 00000ff5 14968649 a1cdeaad 62ccace6 9472b455 187c2ff8 d551aa43 ea3479fb [2021-06-24 13:34:27] Targ[7:0]: 00000fff ff000000 00000000 00000000 00000000 00000000 00000000 00000000 [2021-06-24 13:34:27] 4 (null)Accepted 3 (null)S0 (null)R1 (null)B2#[01;37m, 179.724 sec (14ms) Diff 0.00024479, Block 4961208 ---> hash for block 208 is valid but stats calculated using diff from block 207

[2021-06-24 13:34:27] Mining info: diff 0.00024414, net_hashrate 2830616464680.111800, height 4961208 ----> mininginfo finaly logged for block 208, with lower diff .00024

[2021-06-24 13:34:27] GBT new work received in 17.00 ms [2021-06-24 13:34:27] New Block 4961209, Net Diff 0.00024414, Ntime b55fd460 Miner TTF @ 1728.50 h/s 10m06s, Net TTF @ 2830.62 Gh/s 0m00s [2021-06-24 13:34:27] Threads restarted for new work. ---> block 209 received and logged

YetAnotherRussian commented 3 years ago

Btw, that's what you've asked before in details (huge nethash because of sha256, scrypt & groestl):

[2021-06-24 21:00:13] JSON protocol response: { "error": null, "result": { "networkhashps": 842823331141.94275, "difficulty_lyra2re2": 0.006680133963519649, "errors": "", "currentblocktx": 0, "difficulty": 0.0002441371325370145, "pow_algo": "Argon2d", "blocks": 4961565, "pow_algo_id": 4, "difficulty_argon2d": 0.0002441371325370145, "currentblocksize": 1000, "difficulty_sha256d": 1497264119.0667591, "difficulty_scrypt": 410512.93282714993, "difficulty_groestl": 332.15125717679672, "difficulty_yescrypt": 0.0022614096371972232, "pooledtx": 0, "chain": "main" }, "id": 8 }

JayDDee commented 3 years ago

I've found the problem, it's get_mininginfo. It's data is always for the previous block so the net_diff is always one block behind. The problem is it overwrites the global net_diff variable that had been previously set correctly based on the hash target.

A fix is a little tricky because the code is so convoluted to handle both stratum and solo which do thing differently.

JayDDee commented 3 years ago

I found a simple solution, declare a local net_diff in get_mininginfo. This will override the global net_diif preventing it from being overwritten. The get_mining info log will continue to display the data from the previous block but the share difficulty test will use a net diff derived from the actual hash target.

The code is still a mess but this solution doesn't make it any messier.

JayDDee commented 3 years ago

cpuminer-opt-3.16.5 is released which hopefully fixes this issue.

The major change is to ensure the diff calculated from the target supplied in the work is used by the miner because the diff in mininginfo is from the previous block. Previously when the diff changes the miner was one block behind updating to the new diff.

Aside from confirming that solved blocks are no longer reported as only accepted when the diff i slower than the previous block, The calculated diff should be compared with mininginfo for the same block to ensure they agree and to what level of precision. Please run a test with -D to compare the diff in the New Block logs vs the Mininginfos log for a few blocks with diffrerent diffs.

I also fixed a formatting issue in the share result log when --no-color is used, it was trying to format a null pointer instead of a string with a null char.

YetAnotherRussian commented 3 years ago

Seems to be OK for now. Will check the regular cli output as well (without --debug). cpuminer_log6.zip

JayDDee commented 3 years ago

Solved block 4 is the one that proves it now works. The previous block had a higher net diff than the submitted hash and the new net diff for the block that was solved.

Thanks for finding this bug and testing the fix.

YetAnotherRussian commented 3 years ago

Yep, regular mode is okay.

4

JayDDee commented 3 years ago

No problems reported, closing.