Solutions are replayed with the wrong times

[Zannick]

INFO  [2024-06-15 22:25:19.571446 -07:00] analyzer::search.470 | Similar mode found new shortest winning path after 48792485 rounds: estimated 3596681ms (heap max was: 3596782ms)
INFO  [2024-06-15 22:25:19.571541 -07:00] analyzer::search.478 | Max time to consider is now: 3596681ms
INFO  [2024-06-15 22:25:19.574915 -07:00] analyzer::solutions.127 | Wrote route of 3613012ms to "solutions/3613012.m4" in 3.319198ms

Somehow we've found a state that the db believes will be 3596681 but when replayed to make the graph file, it gains around 16s. We've actually got quite a number of these recently, and the one that is "best" is written out to best.txt with the lower time, while its graph has the higher time.

[Zannick]

The route command on the current best produces a final result of 3611519ms, which is neither of the other numbers (3594381ms during the search and in the file, 3610712ms in the graph file).

[Zannick]

So there are three different numbers in play here:

1. The time in the statedb of the state that started the Similar route and reached the goal by replaying the history suffix.
2. The time from replaying the whole of the history.
3. The time from replaying the history as interpreted from the formatted string history.

I see a potential race in (1) and (2) because we read the history from the db and then we read the elapsed time, when we could read in the other order (or at the same time). (2) and (3) is problematic because (3) uses move_to to find the shortest path to the destination spot, and the route explicitly lists every individual step, so for exits and spot-to-spot movements it shouldn't change, which would just leave condensed edges. So arguably it should improve the route. But also it sometimes chooses to move to multiple AV2 map points (which shouldn't make a difference due to the orthogonal movement involved). In this particular case, it has 16 map steps with extra points, and 1 condensed edge.

The condensed edge:

== 924. Move... to Amagi Breach > East Ruins > Northeast Bubbles Corner Access ==
  Take exit Amagi Breach > East Ruins > Arch West ==> High Rock Lower Ledge (1)
  Move to Amagi Breach > East Ruins > Northeast Bubbles Center
  Take exit Amagi Breach > East Ruins > Northeast Bubbles Center ==> Northeast Bubbles Corner Access (1)
position: Amagi_Breach__East_Ruins__Arch_West → Amagi_Breach__East_Ruins__Northeast_Bubbles_Corner_Access
energy: 246 → 148
progress=122, est=627551, elapsed=2592437, score=3219988

The third step here used the exit with Nanite Mist, which takes 2807ms. These two spots also have a local connection of 2000ms between them, which was not taken. The difference of 807ms accounts exactly for the difference between 3611519 and 3610712.

[Zannick]

I'm concluding that this is a result of changing the heap to use one that replaces elements of equal value in #183. In particular, we derive SortBy on the wrapper classes we used to use with the original heap, but now, since we use DoublePriorityQueue as the underlying storage, we provide the priority separately. I hadn't bothered with replacing all the element types, though.

The issue is that SortBy derives Eq and Hash based on that priority value... so our wrappers are treated as equivalent if they have the same score. As a result, the states we should have reached earlier got worse scores and were not popped appropriately.