Identify issue in slow torch tests
Author: LysandreJik
Pull request: yes
Labels: name: WIP

name: Testing

Pull request to try and identify the source of the hangs in the torch slow CI. Torch slow CI was taking three hours per run until a few days ago, and has since jumped to 6+ hours, for an unknown reason. The job ends up being killed as it goes over the timeout, so the resulting time might end up being even larger than six hours.

Example of run that took 3 hours (April 20, 2021): https://github.com/huggingface/transformers/actions/runs/765376348
Example of run that took 6+ hours (April 21, 2021: https://github.com/huggingface/transformers/actions/runs/768949009

Here is an example of a run that took 6+ hours, while completing the full common tests: https://github.com/huggingface/transformers/runs/2443524960?check_suite_focus=true

The common tests took 5h56 minutes to complete, and the pipeline tests took more than 4 hours to complete before being apparently killed by CI, so there was clearly something going wrong here.

In order to investigate the root cause of the issue, opening a PR here. Tests will be conducted on a testing machine with the exact same configuration as the other CI machines. Investigating on a single run, on a single GPU machine.

The approach is discussed with @stas00, who is helping out and offered some of the steps below.

## Step 1

The first step is ensuring this is not an error linked to the machine itself, so we first start by running the job on the machine without changing anything to it. We only add a 240-minute timeout so that it can go on to step 2 if it goes over the 4 hour mark (as we know it should take less than 3 hours to complete)

See run for first step here: https://github.com/huggingface/transformers/runs/2554755801

Edit: First run errored out at 6 hours like on other machines. I do not think it is a setup issue.

## Step 2 (if step 1 doesn't resolve the issue)

The second step is twofold: removing `pytest-xdist` as we do not leverage it (we're using a single worker), and adding `pytest-timeout` with a timeout of 300 seconds.

See run for second step here: https://github.com/huggingface/transformers/runs/2554760360

## Step 3 (if step 1 & 2 don't resolve the issue)

Do a manual run - at the 3 hour mark, it should be hanging.

As it is hanging, try and retrieve information about what is information. For example, with the following:

```
pip install py-spy
# dumps traceback for each thread
sudo py-spy dump --pid PID
```

## Step 4 (if no step above resolves the issue)

The diff between the two jobs (3hr and 6hr) doesn't seem to have anything that would make the tests hang - but reverting to the previous repository state could help us identify the culprit. Diff: https://github.com/huggingface/transformers/compare/95037a1..95dab34

Additionally, Stas identified two difference in dependencies between the two runs:

```
-datasets-1.5.0
+datasets-1.6.0
-nltk-3.6.1
+nltk-3.6.2
```

Those should be investigated at the same time.

Comments:
And one more possible venue of just tracing start/stop of each test, so perhaps this can help to identify which test doesn't complete.

Here is a poor man's start/stop tracer

```
# add to conftest.py
import pytest
import os
trace = os.environ.get('TRACE_START_STOP', "")
@pytest.hookimpl(tryfirst=True, hookwrapper=True)
def pytest_runtest_makereport(item, call):
    outcome = yield
    res = outcome.get_result()
    file_name, _, test_name = res.location
    test = f"{file_name} {test_name}"
    if res.when == "setup" and res.passed:
        if len(trace):
            print(f"\nTRACE {test} start")
    elif res.when == "call" and not res.passed:
        pass
    elif res.when == "teardown":
        if len(trace):
            print(f"\nTRACE {test} stop")
```
now run as:
```
TRACE_START_STOP=1 pytest tests/test_trainer.py
```
output:
```
TRACE transformers-master/tests/test_trainer.py TrainerIntegrationTest.test_can_resume_training start
.
TRACE transformers-master/tests/test_trainer.py TrainerIntegrationTest.test_can_resume_training stop

TRACE transformers-master/tests/test_trainer.py TrainerIntegrationTest.test_custom_optimizer start
.
TRACE transformers-master/tests/test_trainer.py TrainerIntegrationTest.test_custom_optimizer stop

TRACE transformers-master/tests/test_trainer.py TrainerIntegrationTest.test_data_is_not_parallelized_when_model_is_parallel start
.
TRACE transformers-master/tests/test_trainer.py TrainerIntegrationTest.test_data_is_not_parallelized_when_model_is_parallel stop

TRACE transformers-master/tests/test_trainer.py TrainerIntegrationTest.test_dynamic_shapes start
.
TRACE transformers-master/tests/test_trainer.py TrainerIntegrationTest.test_dynamic_shapes stop
```

Update: from further investigation, it was identified that the main culprit was the `test_trainer_seq2seq.py` file which is based on the `cnn_dailymail` dataset.

The issue is that this dataset contains a lot of examples and that it was cached on the shared disk, which is not necessarily in the same region as the machine. My intuition tells me reading large files such as model files is fine as the download/upload speed to the disk should be good - however, I doubt the latency holds up when looking for a lot of different small files. When processing the dataset, the machine did it at a rate of 10 examples per second - vs my laptop PC which handles them at a rate of  12,000 examples per second. Maybe @lhoestq has already encountered such an issue in the past.

Proposal to resolve the issue:

Right now I have patched this test by processing the dataset directly on the machine's disk, then moved it to the shared disk. When re-running the test, the machine picks the preprocessed dataset from the shared disk and passes the test in a total of 53 seconds, which is great.

What we learned with this endeavor is that:
- Having clean test outputs with :white_check_mark: everywhere is nice in theory, but when we have an issue we at least need the test names to be able to identify where it hangs
- Having the `pytest-timeout` dependency is a lifesaver as it can automatically kill the hanging test, like in this case.

I propose we keep the setup as it currently is, and find a way for the Slack CI feedback to say explicitly when there was a timeout. This would help to identify cases such as this one - and if such cases happen often, then we should re-think how the CI handles dataset storage, shared disk storage, or both.

Great work, @LysandreJik, at sorting it out!

> * Having clean test outputs with white_check_mark everywhere is nice in theory, but when we have an issue we at least need the test names to be able to identify where it hangs

We actually weren't getting this working fully, since pytest only prints the test name once at least one of the tests has completed. So for example if you get a pytest crash it will never print the test name if it was the first test in it.

So we should probably keep this one handy: https://github.com/huggingface/transformers/pull/11677#issuecomment-838846226
since it prints the test name as soon as the test starts (may even need to add a flush should it be buffered but usually the pytest print is unbuffered) 

But also using `pytest -sv` will also start with a printout of each full test name, before the test is run, albeit it'd be very very noisy. But in a pinch that is a possible quick solution if you want to know which test started and hasn't finished.

I haven't experienced such speed differences (12 000 vs 10 samples per sec) on my side.
Note that the recent patch updates (1.6.1 and 1.6.2) fixed memory issues that could have led to slowdowns in some cases, have you tried updating `datasets` ?

Also let me know if I can help you on this

This should be closed as resolved due to revamped testing infrastructure (#15725, #15726, #15727, #15728, #15729).