Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Mining stops at a random #979

Closed
Rytiss opened this issue May 14, 2015 · 17 comments
Closed

Mining stops at a random #979

Rytiss opened this issue May 14, 2015 · 17 comments

Comments

@Rytiss
Copy link

Rytiss commented May 14, 2015

At random point in time, mining suddenly stops and all that is happening is blockchain downloads. Restarting the client starts mining again.

This happens on Windows 7 x64, 0.9.20. Already observed this behavior twice.

I0514 16:54:52.093782    6960 worker.go:337] commit new work on block 332730 with 0 txs & 0 uncles
I0514 16:54:52.093782    6960 chain_manager.go:628] imported 1 block(s) (0 queued 0 ignored) in 1.346077s. #332730 [85ad7b6b / 85ad7b6b]
I0514 16:54:53.050837    6960 chain_manager.go:628] imported 0 block(s) (0 queued 1 ignored) in 2.046117s. #332730 [85ad7b6b / 85ad7b6b]
I0514 16:54:53.054837    6960 chain_manager.go:628] imported 0 block(s) (0 queued 1 ignored) in 963.055ms. #332730 [85ad7b6b / 85ad7b6b]
I0514 16:54:53.064838    6960 chain_manager.go:628] imported 1 block(s) (0 queued 0 ignored) in 9.0005ms. #332731 [c396e3c7 / c396e3c7]
I0514 16:54:53.066838    6960 worker.go:337] commit new work on block 332732 with 0 txs & 0 uncles
I0514 16:54:53.067838    6960 worker.go:337] commit new work on block 332732 with 0 txs & 0 uncles
I0514 16:55:12.454947    6960 chain_manager.go:628] imported 1 block(s) (0 queued 0 ignored) in 2.5231443s. #332732 [fd495e9d / fd495e9d]
I0514 16:55:14.610070    6960 worker.go:337] commit new work on block 332733 with 0 txs & 0 uncles
I0514 16:55:17.492235    6960 chain_manager.go:628] imported 1 block(s) (0 queued 0 ignored) in 6.0004ms. #332733 [e77ad859 / e77ad859]
I0514 16:55:17.494235    6960 worker.go:337] commit new work on block 332734 with 0 txs & 0 uncles
I0514 16:55:21.842484    6960 chain_manager.go:628] imported 1 block(s) (0 queued 0 ignored) in 5.0003ms. #332734 [05baa9d2 / 05baa9d2]
I0514 16:55:27.347799    6960 chain_manager.go:628] imported 1 block(s) (0 queued 0 ignored) in 2.2711299s. #332735 [eea98def / eea98def]
I0514 16:55:36.369315    6960 chain_manager.go:628] imported 1 block(s) (0 queued 0 ignored) in 1.1330648s. #332736 [ae915a2c / ae915a2c]
I0514 16:55:36.766337    6960 chain_manager.go:628] imported 1 block(s) (0 queued 0 ignored) in 7.0004ms. #332736 [7790cbbf / 7790cbbf]
I0514 16:55:36.776338    6960 chain_manager.go:580] Split detected. New head #332737 (c05419fc) TD=35049005405837, was #332736 (ae915a2c) TD=35047857724314
I0514 16:55:36.777338    6960 chain_manager.go:628] imported 1 block(s) (0 queued 0 ignored) in 5.0003ms. #332737 [c05419fc / c05419fc]
@tgerring
Copy link
Contributor

I saw a similar occurrence of this on my Mac while running overnight.

I've got a Windows desktop that's also mining, so I can report back if it exhibits similar behaviour.

@karalabe
Copy link
Member

I'm still seeing this issue as reported in #1008, latest develop code, so it's definitely an issue.

@simondlr
Copy link

I'm also experiencing this on my Mac (v0.9.21.1). Extremely difficult to reproduce. No clue where to start looking.

I'm running a private chain. Even when I delete all my ethereum details and the DAG (under ~/.ethash), it still does not work. It finished creating the DAG... then nothing happens.

Turning the miner of and on (after DAG creation), it just prints this:

> admin.miner.start()
I0518 13:12:04.925637   17307 miner.go:91] Starting mining operation (CPU=8 TOT=10)
true
> I0518 13:12:04.926000   17307 statedb.go:232] (+) 7ee8ed760120f116d20534136f58f7b9010b4c76
I0518 13:12:04.926252   17307 state_object.go:241] 7ee8ed760120f116d20534136f58f7b9010b4c76: gas (+ 3141592)
I0518 13:12:04.926291   17307 worker.go:342] commit new work on block 1 with 0 txs & 0 uncles
I0518 13:12:04.926320   17307 state_object.go:197] 7ee8ed760120f116d20534136f58f7b9010b4c76: #0 1500000000000000000 (+ 1500000000000000000)

Nothing new happens.

Similarly, if turn geth off and on, and start the miner it just does:

Christian <c@ethdev.com> and Lefteris <lefteris@ethdev.com> (c) 2014-2015
> admin.miner.start()
I0518 13:16:03.822389   17376 miner.go:91] Starting mining operation (CPU=8 TOT=10)
true
> I0518 13:16:03.822749   17376 statedb.go:232] (+) 7ee8ed760120f116d20534136f58f7b9010b4c76
I0518 13:16:03.823112   17376 state_object.go:241] 7ee8ed760120f116d20534136f58f7b9010b4c76: gas (+ 3141592)
I0518 13:16:03.823155   17376 worker.go:342] commit new work on block 1 with 0 txs & 0 uncles
I0518 13:16:03.823199   17376 state_object.go:197] 7ee8ed760120f116d20534136f58f7b9010b4c76: #0 1500000000000000000 (+ 1500000000000000000)
I0518 13:16:03.823493   17376 ethash.go:186] Generating DAG for epoch 0 (0000000000000000000000000000000000000000000000000000000000000000)
I0518 13:16:04.806785   17376 ethash.go:203] Done generating DAG for epoch 0, it took 983.318597ms

Nothing new happens.

Like I said previously, it is very temperamental. Sometimes, just waiting for a while (with no predictable period of time), it just starts again. It threw these errors in the past, and then I regenerated the DAG and it worked again. But now, even that doesn't seem to kickstart it again. Trying all possibilities to figure out why it is locking up. And trying to figure why it started working again previously.

@karalabe
Copy link
Member

There was an ugly race condition fixed in the miner in #1031, that could be one of the causes of the lockup. As far as I see it in the code, there is still a possible data race that could cause this kind of behavior. I'll try and repro it with the above fix to see if it disappears or not.

@simondlr
Copy link

Thanks @karalabe. I was experiencing that other race condition as well, but it wasn't related to my current issues where the chain just locks up. The other race condition threw visible errors.

@simondlr
Copy link

So, I did some debugging (aka waiting). Turns out sometimes my miner on OS X just slows down to something like a 10th of its usual hashrate, thus causing blocks to sometimes be as long as 10 minutes.

I can't seem to figure out when this happens to reproduce it predictably. Stop and starting it, doesn't always work. Regenerating the DAG also doesn't work always. Also, even restarting isn't predictable.

So, I suspect there might be something else happening rather than just system-level resource issues.

@karalabe
Copy link
Member

Do you still experience these (on latest develop I mean)?

@Rytiss
Copy link
Author

Rytiss commented May 22, 2015

Haven't seen the issue on 0.9.22.60 (from Chocolatey).

@Rytiss Rytiss closed this as completed May 22, 2015
@simondlr
Copy link

Unfortunately, still experiencing issues with this. Thought about making a new issue, tell me if I should.

On v0.9.23. It's definitely an issue with an inconsistent hashrate still. It's incredibly difficult to debug. I have no idea where to start looking. I can't measure the hashrate before it actually solves a block. The only way I know it is actually trying to mine is that my Mac goes slightly slower & it does eventually find a block (sometimes only 10min later). Sometimes it never finds a new block (even after 30min). Then sometimes it just "snaps" back, and produces blocks on the regular (< 12s/block).

I'm not sure why I'm getting inconsistent hashrates. My suspicion is that it might be DAG-related? (the only reason guess it is this, because this is the only thing that is relatively different than other blockchain mining systems). But even if I restart and try it, it is something wonky.

Any advice on how to debug this? Any help appreciated.

@karalabe karalabe reopened this May 26, 2015
@obscuren
Copy link
Contributor

Got a log?

@simondlr
Copy link

@obscuren: That's also the problem. It's not generating anything useful (at verbosity 4 at least).

At verbosity 8 there's too much noise, so I tried piping it to a logfile (to grep the related mining logs and see if there are logs I'm missing), but it seems I'm having issues with --logfile. Will debug that.

fwiw. Here's the log on startup at verbosity 4.

Simon-2:~ simon$ geth --networkid 66612 --verbosity 4 console
I0526 18:54:54.250354   53354 backend.go:255] Protocol Version: 60, Network Id: 66612
I0526 18:54:54.250397   53354 backend.go:265] Blockchain DB Version: 2
I0526 18:54:54.250646   53354 statedb.go:232] (+) 6c386a4b26f73c802f34673f7248bb118f97424a
I0526 18:54:54.250712   53354 statedb.go:232] (+) cd2a3d9f938e13cd947ec05abc7fe734df8dd826
I0526 18:54:54.250762   53354 statedb.go:232] (+) 2ef47100e0787b915105fd5e3f4ff6752079d5cb
I0526 18:54:54.250802   53354 statedb.go:232] (+) 0000000000000000000000000000000000000002
I0526 18:54:54.250867   53354 statedb.go:232] (+) 0000000000000000000000000000000000000004
I0526 18:54:54.250911   53354 statedb.go:232] (+) dbdbdb2cbd23b783741e8d7fcf51e459b497e4a6
I0526 18:54:54.250952   53354 statedb.go:232] (+) e4157b34ea9615cfbde6b4fda419828124b70c78
I0526 18:54:54.250993   53354 statedb.go:232] (+) b9c015918bdaba24b4ff057a92a3873d6eb201be
I0526 18:54:54.251031   53354 statedb.go:232] (+) e6716f9544a56c530d868e4bfbacb172315bdead
I0526 18:54:54.251072   53354 statedb.go:232] (+) 1a26338f0d905e295fccb71fa9ea849ffa12aaf4
I0526 18:54:54.251116   53354 statedb.go:232] (+) 0000000000000000000000000000000000000001
I0526 18:54:54.251156   53354 statedb.go:232] (+) 0000000000000000000000000000000000000003
I0526 18:54:54.251629   53354 chain_manager.go:247] Last block (#140) 4a81847735e3d5a877d5588657dd65b4259b8054135eb102bfab6f1ed9c4fc2c TD=19075754
I0526 18:54:54.258025   53354 statedb.go:232] (+) 0000000000000000000000000000000000000000
I0526 18:54:54.258646   53354 state_object.go:241] 0000000000000000000000000000000000000000: gas (+ 3141592)
I0526 18:54:54.258687   53354 state_object.go:197] 0000000000000000000000000000000000000000: #0 1500000000000000000 (+ 1500000000000000000)
I0526 18:54:54.263672   53354 cmd.go:137] Starting Geth/v0.9.23/darwin/go1.4
I0526 18:54:54.263756   53354 server.go:209] Starting Server
I0526 18:54:56.827149   53354 udp.go:189] Listening, enode://27f6ddad5e8b84a6d3e2f97c609a83831fa075ff43e664053d25ee27a4661682aa6d8477fc8c777ce608c6fc12814f1fff942d335df1619ffa32c072d408cc56@196.210.150.223:30303
I0526 18:54:56.827273   53354 backend.go:479] Server started
I0526 18:54:56.827255   53354 server.go:349] Listening on [::]:30303
> admin.miner.start()
I0526 18:55:58.657861   53354 backend.go:593] Automatic pregeneration of ethash DAG ON (ethash dir: /Users/simon/.ethash)
I0526 18:55:58.657926   53354 backend.go:600] checking DAG (ethash dir: /Users/simon/.ethash)
I0526 18:55:58.657935   53354 miner.go:100] Starting mining operation (CPU=8 TOT=10)
true
> I0526 18:55:58.658760   53354 state_object.go:241] ba28a0a1e4c209a5a5789ff3d454e8cfeae7274c: gas (+ 3141592)
I0526 18:55:58.658784   53354 worker.go:349] commit new work on block 141 with 0 txs & 0 uncles
I0526 18:55:58.658800   53354 state_object.go:197] ba28a0a1e4c209a5a5789ff3d454e8cfeae7274c: #0 225000000000000000000 (+ 1500000000000000000)
I0526 18:55:58.658968   53354 ethash.go:186] Generating DAG for epoch 0 (0000000000000000000000000000000000000000000000000000000000000000)
I0526 18:55:59.680981   53354 ethash.go:203] Done generating DAG for epoch 0, it took 1.022034247s

Then stopping and running it again.

> admin.miner.stop()
I0526 18:57:00.337813   53354 backend.go:647] Automatic pregeneration of ethash DAG OFF (ethash dir: /Users/simon/.ethash)
true
> admin.miner.start()
I0526 18:57:05.665683   53354 backend.go:593] Automatic pregeneration of ethash DAG ON (ethash dir: /Users/simon/.ethash)
I0526 18:57:05.665746   53354 backend.go:600] checking DAG (ethash dir: /Users/simon/.ethash)
I0526 18:57:05.665771   53354 miner.go:100] Starting mining operation (CPU=8 TOT=10)
true
> I0526 18:57:05.666457   53354 state_object.go:241] ba28a0a1e4c209a5a5789ff3d454e8cfeae7274c: gas (+ 3141592)
I0526 18:57:05.666481   53354 worker.go:349] commit new work on block 141 with 0 txs & 0 uncles
I0526 18:57:05.666495   53354 state_object.go:197] ba28a0a1e4c209a5a5789ff3d454e8cfeae7274c: #0 225000000000000000000 (+ 1500000000000000000)

In both cases, nothing new happens. This is obviously after the DAG has been created. It's not related to a newly created DAG, since even if I nuke it and redo the DAG, it also just hang and waits (assuming it's generating poor hashrates).

Best debug would be to know what the hashrate is before I even find a block. That could give more clues.

@obscuren
Copy link
Contributor

Could you try geth --vmodule=agent=6 and let it run for a while?

@simondlr
Copy link

@obscuren Not much help.

> admin.miner.start()
I0526 20:03:06.207158   54292 backend.go:593] Automatic pregeneration of ethash DAG ON (ethash dir: /Users/simon/.ethash)
I0526 20:03:06.207224   54292 backend.go:600] checking DAG (ethash dir: /Users/simon/.ethash)
I0526 20:03:06.207258   54292 miner.go:100] Starting mining operation (CPU=8 TOT=10)
true
> I0526 20:03:06.225173   54292 state_object.go:241] ba28a0a1e4c209a5a5789ff3d454e8cfeae7274c: gas (+ 3141592)
I0526 20:03:06.225202   54292 worker.go:349] commit new work on block 141 with 0 txs & 0 uncles
I0526 20:03:06.225220   54292 state_object.go:197] ba28a0a1e4c209a5a5789ff3d454e8cfeae7274c: #0 225000000000000000000 (+ 1500000000000000000)
I0526 20:03:06.225343   54292 agent.go:94] (re)started agent[0]. mining...
I0526 20:03:06.225370   54292 agent.go:94] (re)started agent[5]. mining...
I0526 20:03:06.225377   54292 agent.go:94] (re)started agent[4]. mining...
I0526 20:03:06.225358   54292 agent.go:94] (re)started agent[1]. mining...
I0526 20:03:06.225395   54292 ethash.go:186] Generating DAG for epoch 0 (0000000000000000000000000000000000000000000000000000000000000000)
I0526 20:03:06.225414   54292 agent.go:94] (re)started agent[7]. mining...
I0526 20:03:06.225348   54292 agent.go:94] (re)started agent[6]. mining...
I0526 20:03:06.225383   54292 agent.go:94] (re)started agent[3]. mining...
I0526 20:03:06.225454   54292 agent.go:94] (re)started agent[2]. mining...
I0526 20:03:07.304299   54292 ethash.go:203] Done generating DAG for epoch 0, it took 1.078914925s
admin.miner.stop
[Function]
> admin.miner.stop()
I0526 20:06:13.751838   54292 backend.go:647] Automatic pregeneration of ethash DAG OFF (ethash dir: /Users/simon/.ethash)
true
> admin.miner.start()
I0526 20:06:17.311649   54292 backend.go:593] Automatic pregeneration of ethash DAG ON (ethash dir: /Users/simon/.ethash)
I0526 20:06:17.311767   54292 backend.go:600] checking DAG (ethash dir: /Users/simon/.ethash)
I0526 20:06:17.660286   54292 miner.go:100] Starting mining operation (CPU=8 TOT=10)
true
> I0526 20:06:17.771351   54292 state_object.go:241] ba28a0a1e4c209a5a5789ff3d454e8cfeae7274c: gas (+ 3141592)
I0526 20:06:17.771426   54292 worker.go:349] commit new work on block 141 with 0 txs & 0 uncles
I0526 20:06:17.771468   54292 state_object.go:197] ba28a0a1e4c209a5a5789ff3d454e8cfeae7274c: #0 225000000000000000000 (+ 1500000000000000000)
I0526 20:06:17.771777   54292 agent.go:94] (re)started agent[3]. mining...
I0526 20:06:17.771801   54292 agent.go:94] (re)started agent[4]. mining...
I0526 20:06:17.771740   54292 agent.go:94] (re)started agent[0]. mining...
I0526 20:06:17.771897   54292 agent.go:94] (re)started agent[2]. mining...
I0526 20:06:17.771797   54292 agent.go:94] (re)started agent[6]. mining...
I0526 20:06:17.771788   54292 agent.go:94] (re)started agent[1]. mining...
I0526 20:06:17.772030   54292 agent.go:94] (re)started agent[7]. mining...
I0526 20:06:17.772123   54292 agent.go:94] (re)started agent[5]. mining...

@obscuren
Copy link
Contributor

It appears to be generating the DAG twice. @zelig could this be the dag update mechanism?

@simondlr
Copy link

Looking at the code, if I understand it correctly nextEpoch isn't set the first time it is started, thus it tries to generate the DAG again, but it is already done, so it just looks like it is generating it twice. That could explain that part?

However. The mining works sometimes and then sometimes it doesn't. So don't think it is the generation of the DAG that is the issue. I can mine, turn it off, do some coding, not closing geth and then try to mine some new transactions and then it just doesn't mine new blocks (or 1 every 10 - 30min). So something is happening subsequently, causing hashrate to drop substantially, and randomly. I've rebooted and ran it, and the hashrate was horrible. I've used a fully encumbered system and it mined perfectly.

This has been failing since 0.9.20 (the first version I tried in a while, so the error could've come from earlier), not the new auto-updating DAG code.

@obscuren
Copy link
Contributor

Could you see if running with just 4 mining threads makes a difference (geth --minerthreads 4)

@simondlr
Copy link

Nope. Nothing.

However, I've been trying to figure out what could be causing it to slow down so considerably. Understandably it behaves slightly more consistently with less load on the machine. So, I proceeded to kill all running apps, and then after about 2 minutes, it started producing blocks (while keeping 8 threads running). When producing blocks the hashrate is in the excess of 260k - 320k. 1 thread produces 59k. When it is really slow it was around 20k (for all 8 threads combined).

This could just be some fluke again, because I have run geth straight from a fresh reboot and it didn't produce blocks. (I'll be pretty annoyed if it is a fluke, because I'm starting to feel like I'm just wasting everyone's time here).

I just wish there was a way to know for sure that the load on the machine is causing it to decrease. Or, introduce some information what the current hashrate is (before even finding a block), and when (considering the difficulty) an expected block will be found. And as more resources become available it should update as it goes along.

Is there any other way I could debug this more? Or any other way I can produce blocks more consistently and not get hiccups when developing?

@fjl fjl closed this as completed Aug 9, 2015
tony-ricciardi pushed a commit to tony-ricciardi/go-ethereum that referenced this issue Jan 20, 2022
* Adds ERC20 tokens list to Ledger

* adds detection for erc20

* handle error status code correctly

* makes status code a constant

* fmt

* moves to kobigurk branch

* more temp tokens for testing

* revert circleci

* lint

* updates token list for rc1

* fixes tokens test

* fixes tokens test

* moves token data to a separate file and adds a comment on ERC20 transfer prefix
maoueh pushed a commit to streamingfast/go-ethereum that referenced this issue Sep 20, 2023
* README: remove unnecessary info from readme and simplify

* more changes

* more changes

* more changes

* add contribution guidelines

* add test command

* README: add release tag info
maoueh pushed a commit to streamingfast/go-ethereum that referenced this issue Sep 20, 2023
* README: remove unnecessary info from readme and simplify

* more changes

* more changes

* more changes

* add contribution guidelines

* add test command

* README: add release tag info
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants