`dvc queue`: unexpected behaviour

[mattseddon]

Bug Report

Description

Whilst checking out the new dvc queue command I have run into some unexpected behaviour. I won't duplicate the steps to reproduce here but after queueing and running experiments I have run in to two different issues.

VS Code demo project: dvc queue status returning ERROR: Invalid experiment '{entry.stash_rev[:7]}'. (produced when running with the extension)
example-get-started: dvc queue status returning

Task     Name    Created    Status
f3d69ee          02:17 PM   Success
08ccb05          02:17 PM   Success

ERROR: unexpected error - Extra data: line 1 column 56 (char 55)

(produced without having the extension involved).

In both instances this resulted in the HEAD baseline entry being dropped from the exp show data:

example-get-started example

❯ dvc exp show --show-json
{
  "workspace": {
    "baseline": {
      "data": {
        "timestamp": null,
        "params": {
          "params.yaml": {
            "data": {
              "prepare": {
                "split": 0.21,
                "seed": 20170428
              },
              "featurize": {
                "max_features": 200,
                "ngrams": 2
              },
              "train": {
                "seed": 20170428,
                "n_est": 50,
                "min_split": 0.01
              }
            }
          }
        },
        "deps": {
          "data/data.xml": {
            "hash": "22a1a2931c8370d3aeedd7183606fd7f",
            "size": 14445097,
            "nfiles": null
          },
          "src/prepare.py": {
            "hash": "f09ea0c15980b43010257ccb9f0055e2",
            "size": 1576,
            "nfiles": null
          },
          "data/prepared": {
            "hash": "153aad06d376b6595932470e459ef42a.dir",
            "size": 8437363,
            "nfiles": 2
          },
          "src/featurization.py": {
            "hash": "e0265fc22f056a4b86d85c3056bc2894",
            "size": 2490,
            "nfiles": null
          },
          "data/features": {
            "hash": "f35d4cc2c552ac959ae602162b8543f3.dir",
            "size": 2232588,
            "nfiles": 2
          },
          "src/train.py": {
            "hash": "c3961d777cfbd7727f9fde4851896006",
            "size": 967,
            "nfiles": null
          },
          "model.pkl": {
            "hash": "46865edbf3d62fc5c039dd9d2b0567a4",
            "size": 1763725,
            "nfiles": null
          },
          "src/evaluate.py": {
            "hash": "44e714021a65edf881b1716e791d7f59",
            "size": 2346,
            "nfiles": null
          }
        },
        "outs": {
          "data/prepared": {
            "hash": "153aad06d376b6595932470e459ef42a.dir",
            "size": 8437363,
            "nfiles": 2,
            "use_cache": true,
            "is_data_source": false
          },
          "data/features": {
            "hash": "f35d4cc2c552ac959ae602162b8543f3.dir",
            "size": 2232588,
            "nfiles": 2,
            "use_cache": true,
            "is_data_source": false
          },
          "model.pkl": {
            "hash": "46865edbf3d62fc5c039dd9d2b0567a4",
            "size": 1763725,
            "nfiles": null,
            "use_cache": true,
            "is_data_source": false
          },
          "data/data.xml": {
            "hash": "22a1a2931c8370d3aeedd7183606fd7f",
            "size": 14445097,
            "nfiles": null,
            "use_cache": true,
            "is_data_source": true
          }
        },
        "queued": false,
        "running": false,
        "executor": null,
        "metrics": {
          "evaluation.json": {
            "data": {
              "avg_prec": 0.9249974999612706,
              "roc_auc": 0.9460213440787918
            }
          }
        }
      }
    }
  },
  "f3d69eedda6b1c051b115523cf5c6c210490d0ea": {
    "baseline": {
      "data": {
        "timestamp": "2022-07-13T14:17:20",
        "params": {
          "params.yaml": {
            "data": {
              "prepare": {
                "split": 0.21,
                "seed": 20170428
              },
              "featurize": {
                "max_features": 200,
                "ngrams": 2
              },
              "train": {
                "seed": 20170428,
                "n_est": 50,
                "min_split": 0.01
              }
            }
          }
        },
        "deps": {
          "data/data.xml": {
            "hash": "22a1a2931c8370d3aeedd7183606fd7f",
            "size": 14445097,
            "nfiles": null
          },
          "src/prepare.py": {
            "hash": "f09ea0c15980b43010257ccb9f0055e2",
            "size": 1576,
            "nfiles": null
          },
          "data/prepared": {
            "hash": "153aad06d376b6595932470e459ef42a.dir",
            "size": 8437363,
            "nfiles": 2
          },
          "src/featurization.py": {
            "hash": "e0265fc22f056a4b86d85c3056bc2894",
            "size": 2490,
            "nfiles": null
          },
          "data/features": {
            "hash": "f35d4cc2c552ac959ae602162b8543f3.dir",
            "size": 2232588,
            "nfiles": 2
          },
          "src/train.py": {
            "hash": "c3961d777cfbd7727f9fde4851896006",
            "size": 967,
            "nfiles": null
          },
          "model.pkl": {
            "hash": "46865edbf3d62fc5c039dd9d2b0567a4",
            "size": 1763725,
            "nfiles": null
          },
          "src/evaluate.py": {
            "hash": "44e714021a65edf881b1716e791d7f59",
            "size": 2346,
            "nfiles": null
          }
        },
        "outs": {
          "data/prepared": {
            "hash": "153aad06d376b6595932470e459ef42a.dir",
            "size": 8437363,
            "nfiles": 2,
            "use_cache": true,
            "is_data_source": false
          },
          "data/features": {
            "hash": "f35d4cc2c552ac959ae602162b8543f3.dir",
            "size": 2232588,
            "nfiles": 2,
            "use_cache": true,
            "is_data_source": false
          },
          "model.pkl": {
            "hash": "46865edbf3d62fc5c039dd9d2b0567a4",
            "size": 1763725,
            "nfiles": null,
            "use_cache": true,
            "is_data_source": false
          },
          "data/data.xml": {
            "hash": "22a1a2931c8370d3aeedd7183606fd7f",
            "size": 14445097,
            "nfiles": null,
            "use_cache": true,
            "is_data_source": true
          }
        },
        "queued": false,
        "running": false,
        "executor": null,
        "metrics": {
          "evaluation.json": {
            "data": {
              "avg_prec": 0.9249974999612706,
              "roc_auc": 0.9460213440787918
            }
          }
        }
      }
    }
  }
}

Reproduce

1. clone example-get-started
2. add git+https://github.com/iterative/dvc to src/requirements.txt
3. create venv, source activate script and install requirements
4. dvc pull
5. change params.yaml and queue x2 with dvc exp run --queue
6. dvc queue start -j 2
7. dvc exp show
8. dvc queue status
9. dvc exp show

When recreating this I can see that both experiments were successful in dvc queue status but the second one has not made it into the table. Final results:

❯ dvc queue status 
Task     Name    Created    Status
9d22751          02:50 PM   Success
962c834          02:50 PM   Success

Worker status: 0 active, 0 idle

First column of exp show:

  workspace
  bigrams-experiment
  └── 65584bd [exp-c88e8]

and the shas don't match?

Expected

Should be able to run exp show & queue status in parallel with the execution of tasks from the queue.

Environment information

Output of dvc doctor:

$ dvc doctor
DVC version: 2.13.1.dev87+gc2668110 
---------------------------------
Platform: Python 3.8.9 on macOS-12.2.1-arm64-arm-64bit
Supports:
        webhdfs (fsspec = 2022.5.0),
        http (aiohttp = 3.8.1, aiohttp-retry = 2.5.1),
        https (aiohttp = 3.8.1, aiohttp-retry = 2.5.1)
Cache types: reflink, hardlink, symlink
Cache directory: apfs on /dev/disk3s1s1
Caches: local
Remotes: https
Workspace directory: apfs on /dev/disk3s1s1
Repo: dvc, git

Additional Information (if any):

Please let me know if you need anything else from me. Thank you.

[mattseddon]

Also realise that I am working with something that isn't even officially released, so if this isn't the correct way to give early feedback then please LMK.

[dberenbaum]

Is it happening for you consistently? I'm not able to reproduce:

$ dvc queue status
Task     Name    Created    Status
16508a7          04:48 PM   Success
94aa5f6          04:48 PM   Success

Worker status: 0 active, 1 idle
$ dvc exp show
 ──────────────────────────────────────────────────────────────────────────────────────>
  Experiment                Created        avg_prec   roc_auc   prepare.split   prepare>
 ──────────────────────────────────────────────────────────────────────────────────────>
  workspace                 -                 0.925   0.94602   0.2             2017042>
  bigrams-experiment        May 19, 2022      0.925   0.94602   0.2             2017042>
  ├── 32a003b [exp-36288]   04:49 PM        0.92017   0.94309   0.2             2017042>
  └── 991e27b [exp-9e5c5]   04:49 PM        0.91783    0.9407   0.2             2017042>
 ──────────────────────────────────────────────────────────────────────────────────────>

and the shas don't match?

This is expected although we have discussed trying to address it. Queued experiments have always (even before dvc queue) had different shas than the completed experiments.

Also realise that I am working with something that isn't even officially released, so if this isn't the correct way to give early feedback then please LMK.

Please give any feedback you have so we can try to resolve before real users get their hands on it 🙏 .

[mattseddon]

Yesterday I tried to recreate 4 times and hit this issue 3 times.

Today I tried twice and hit on the second time so 4/6 times.

Screen.Recording.2022-07-14.at.10.52.00.am.mov

Notice in the video that I start queue execution with 2 workers but every time I call queue status it only shows 1 (yesterday I consistently saw 2). The queue tasks both show success but the second one has not made it into the experiments table.

[mattseddon]

This is expected although we have discussed trying to address it. Queued experiments have always (even before dvc queue) had different shas than the completed experiments.

Based on the above and treeverse/vscode-dvc#1995 (comment) I think we are going to need the relevant queue task sha against each experiment in the exp show data. Will that be possible?

[dberenbaum]

This is expected although we have discussed trying to address it. Queued experiments have always (even before dvc queue) had different shas than the completed experiments.

Based on the above and iterative/vscode-dvc#1995 (comment) I think we are going to need the relevant queue task sha against each experiment in the exp show data. Will that be possible?

@karajan1001 Shouldn't the "Name" column be populated with the final experiment name? I know this was true at some point (see #7591 (comment)).

[mattseddon]

Running experiments from the queue and then making a commit leads to a change of behaviour in exp show. The previous commit is not returned by default.

Details:

❯ git rev-parse --short HEAD
30a82db1
❯ git rev-parse --short HEAD~1
26c5bbed
❯ dvc exp show
─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── 
  Experiment                Created    step      loss      acc   lr       weight_decay   epochs   data/MNIST   train.py  
 ─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── 
  workspace                 -            14   0.95962   0.7735   0.003    0              15       0aed307      90f29a9   
  26c5bbe                   11:21 AM     14   0.95962   0.7735   0.003    0              15       0aed307      90f29a9   
  │ ╓ 2a83d89 [exp-50d00]   11:35 AM     14    0.9642    0.675   0.0045   0              15       0aed307      90f29a9   
  │ ╟ e0d0f6c               11:35 AM     13    1.0903   0.6801   0.0045   0              15       0aed307      90f29a9   
  │ ╟ 814009f               11:35 AM     12    1.0301   0.6605   0.0045   0              15       0aed307      90f29a9   
  │ ╟ fe2c348               11:35 AM     11    1.1769   0.6408   0.0045   0              15       0aed307      90f29a9  
... 

The git log shows that both EXEC_HEAD & EXEC_BASELINE are still against the previous commit:

commit 26c5bbeddece45965cf518bde132180f7edbe7f2 (refs/exps/exec/EXEC_HEAD, refs/exps/exec/EXEC_BASELINE)

By running a new experiment in the workspace both refs are moved.

Do you want a separate issue for this?