PoW Timing Changed

[da-tai]

Yes, it is block 99-00 but looking at logs now, miners start (zilminer) too earlier to mine Zilliqa and extends how long a miner is stayed on to mine it (more than 60 seconds). For example, logs of proxy shows

[2019-10-21 06:42:57,140 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", false, 20], "id": 1} Normally this doesn't happen (false and 20) Normally after 30, false changes to true the number counts down to 0 then POW Begins. During the change to true and 30, zilminer begins mining DAG and using the dual mining scripts to get rid of any open miners.

Now, something changed, which forces miners to start but then there are no jobs to work on.

[2019-10-21 06:42:57,140 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", false, 20], "id": 1} [2019-10-21 06:42:57,840 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", false, 19], "id": 1} [2019-10-21 06:42:59,315 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", false, 18], "id": 1} [2019-10-21 06:43:00,862 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 29], "id": 1} [2019-10-21 06:43:01,414 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 28], "id": 1} skipped some logs [2019-10-21 06:43:24,370 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 5], "id": 1} [2019-10-21 06:43:25,997 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 4], "id": 1} [2019-10-21 06:43:26,727 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 3], "id": 1} [2019-10-21 06:43:27,521 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 2], "id": 1} [2019-10-21 06:43:28,194 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 1], "id": 1} [2019-10-21 06:43:29,742 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 0], "id": 1} [2019-10-21 06:43:30,173 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 30], "id": 1} skipped some logs [2019-10-21 06:43:55,991 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 4], "id": 1} [2019-10-21 06:43:56,927 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 3], "id": 1} [2019-10-21 06:43:57,885 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 2], "id": 1} [2019-10-21 06:43:59,500 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 0], "id": 1} [2019-10-21 06:44:01,069 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 29], "id": "1"} skipped some logs [2019-10-21 06:44:24,724 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 5], "id": 1} [2019-10-21 06:44:26,371 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 3], "id": 1} [2019-10-21 06:44:27,806 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 2], "id": 1} [2019-10-21 06:44:29,411 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 0], "id": "1"} [2019-10-21 06:44:30,432 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 30], "id": 1} skipped some logs [2019-10-21 06:44:56,592 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 3], "id": 1} [2019-10-21 06:44:59,923 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 0], "id": 1} [2019-10-21 06:45:01,022 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 30], "id": 1} [2019-10-21 06:45:03,508 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 27], "id": 1} [2019-10-21 06:45:05,691 INFO log.py:79] {"jsonrpc": "2.0", "result": ["", "", "", true, 25], "id": 1} First Job begins

Here you can see miners would of started at 06:43:00,862 but the first job is 2 minutes after because of the calculation of PoW.

[ckyang]

@Swaggadan Thanks for raising this issue, could you please attach the full zil_pool.log for further debugging?

[da-tai]

@Swaggadan Thanks for raising this issue, could you please attach the full zil_pool.log for further debugging?

Sure. I no longer have the exact log as it has been overwritten but this one will do just as fine. zil_pool.log

[ckyang]

@Swaggadan I guess the 2 minutes delay should come from some microblock timeout, but it should not always happened. Can you confirm if it always happened? Besides, the mining jobs will begin after 2 minutes thus this issue should not be a major one.

[da-tai]

Is the microblock timeout thing going to be fixed? It started happening only after the last update you guys did. Right now, it happens sometimes, not every time. The mining jobs should start 2 minutes after zilminer is initiated (as in think its time to mine)?

[ckyang]

The microblock timeout only happened when no microblock received on directory-service nodes. In other word, in some circumstances (ex. the first epoch we applying regular upgrading procedure), there would be no shards generated, then no microblock would be sent to directory-service nodes. After 2 minutes waiting, the directory-service nodes would keep composing the finalblock, then advance to next epoch. Thus the microblock timeout is a special case from current design, and the 2-minutes delay of miner should be also belongs to this.

[ckyang]

Since this issue only happened rarely and is expected along with microblock timeout, we can close this issue for now, until there is some design change in the future.