Verifier task scheduling is suboptimal

[kellpossible]

When contributors start at different times or work at different rates, the verifier task scheduling appears to be suboptimal, placing the most urgent tasks close to the back of the queue

Here is an example where one contributor (left set of chunks) started performing contributions about 30 seconds after the other contributor:

You can see that the contribution which is currently a blocking dependency (chunk 0) has not yet been verified and appears to be close to the back of the queue of verifications.

[kellpossible]

If we decide to accept #302 with the lock taking timeout I think this might cause the waiting contributor to drop during a long ceremony such as universal. (heads up @julesdesmit ). Hopefully if we have more than enough verifiers it shouldn't be a problem though.

[zosorock]

I think we should prioritize this solution perhaps using the message queue as suggested by @ibaryshnikov. @julesdesmit please feel free to add you suggestions here, I know you were looking at the code and thinking of other possible solutions.

Since this is affecting the running of the Ceremony (only 3 of the 8 Verifiers are doing work), I will label it a bug.

[zosorock]

I am currently running a test on Coordinator2 and one of the verifiers not getting any work is print messages like these, over and over:

Aug 18 00:56:56 stg-verifier7 setup1-verifier[5266]: Aug 18 00:56:56.408  INFO setup1_verifier::coordinator_requests: aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h joined the queue with status false
Aug 18 00:56:56 stg-verifier7 setup1-verifier[5266]: Aug 18 00:56:56.408 ERROR setup1_verifier::verifier: Error while verifying Failed to lock a chunk
Aug 18 00:56:56 stg-verifier7 setup1-verifier[5266]: Aug 18 00:56:56.408  WARN setup1_verifier::verifier: Clearing tasks

He does not show as dropped in the Coordinator but he cannot get more tasks either. He tries to lock a chunk then gets a "StorageLocatorAlreadyExists" error:

Aug 18 00:59:56.234 TRACE aleo_setup_coordinator::authentication::authentication_middleware: Authentication for address aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h message is: "post /v1/verifier/try_lock"
Aug 18 00:59:56.250 TRACE aleo_setup_coordinator::api::verifier::try_lock: Verifier aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier attempting to lock a chunk
Aug 18 00:59:56.250 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator_state: Popping task for aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier
Aug 18 00:59:56.250 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator: Fetched task (7, 1) for aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier
Aug 18 00:59:56.250 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetching ./transcript/round_height
Aug 18 00:59:56.250 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetched ./transcript/round_height
Aug 18 00:59:56.250 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetching ./transcript/round_height
Aug 18 00:59:56.250 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetched ./transcript/round_height
Aug 18 00:59:56.250 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetching ./transcript/round_3/state.json
Aug 18 00:59:56.259 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetched ./transcript/round_3/state.json
Aug 18 00:59:56.259 DEBUG try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator: Locking chunk 7 for aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20 .verifier
Aug 18 00:59:56.259 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetching ./transcript/round_height
Aug 18 00:59:56.259 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetched ./transcript/round_height
Aug 18 00:59:56.259 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator: Current round height from storage is 3
Aug 18 00:59:56.259 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetching ./transcript/round_height
Aug 18 00:59:56.259 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetched ./transcript/round_height
Aug 18 00:59:56.259 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetching ./transcript/round_height
Aug 18 00:59:56.259 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetched ./transcript/round_height
Aug 18 00:59:56.259 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetching ./transcript/round_3/state.json
Aug 18 00:59:56.268 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Fetched ./transcript/round_3/state.json
Aug 18 00:59:56.268 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator: Preparing to lock chunk 7
Aug 18 00:59:56.268 DEBUG try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}:try_lock_chunk{chunk=7}: phase1_coordinator::objects::round: aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier is attempting to lock chunk 7
Aug 18 00:59:56.268 DEBUG try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}:try_lock_chunk{chunk=7}: phase1_coordinator::objects::round: Checking the lock count for aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier
Aug 18 00:59:56.270 DEBUG try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}:try_lock_chunk{chunk=7}: phase1_coordinator::objects::round: aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier is holding 0 locks
Aug 18 00:59:56.270 DEBUG try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}:try_lock_chunk{chunk=7}: phase1_coordinator::objects::round: Obtained response locator ContributionLocator { round_height: 3, chunk_id: 7, contribution_id: 1, is_verified: false }
Aug 18 00:59:56.270 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}:try_lock_chunk{chunk=7}: phase1_coordinator::objects::chunk: Chunk 7 contributions complete (true) and verifications complete (false)
Aug 18 00:59:56.270 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}:try_lock_chunk{chunk=7}: phase1_coordinator::storage::disk: Initializing "./transcript/round_4/chunk_7/contribution_0.verified"
Aug 18 00:59:56.270 ERROR try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}:try_lock_chunk{chunk=7}: phase1_coordinator::storage::disk: Locator "./transcript/round_4/chunk_7/contribution_0.verified" in call to initialize() already exists in storage.
Aug 18 00:59:56.270 ERROR try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}:try_lock_chunk{chunk=7}: phase1_coordinator::objects::round: error=StorageLocatorAlreadyExists
Aug 18 00:59:56.272  INFO try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator: Failed to acquire lock for aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier
Aug 18 00:59:56.272 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator: Adding task (7, 1) back to assigned tasks
Aug 18 00:59:56.272 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator_state: Rolling back pending task on chunk 7 for aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier
Aug 18 00:59:56.272 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator_state: Pushing front task for aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier
Aug 18 00:59:56.272 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Updating ./transcript/coordinator.json
Aug 18 00:59:56.284 TRACE try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::storage::disk: Updated ./transcript/coordinator.json
Aug 18 00:59:56.284 ERROR try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator: StorageLocatorAlreadyExists
Aug 18 00:59:56.286 ERROR try_lock{participant=aleo140snk2r98wdr4g43nxjpzpm4nzv20a98lnhcne9ruj95tjj6ls9s4es20h.verifier}: phase1_coordinator::coordinator: error=StorageLocatorAlreadyExists

[ibaryshnikov]

It happens because pending verifications are put into a HashMap

    pending_verification: HashMap<Task, Participant>,

After the changes from #363 there's no longer need to have a Participant here, we only need to know which task is pending verification. As a result, we can use a different data structure, and it will solve the issue.