AssertionError: Caught AssertionError in replica 1 on device 1. AssertionError: timer has already been started

Hello, I'm trying to use deepspeed. I have deepspeed and mpi4py pip installed in my image and I also have libopenmpi-dev for mpi4py. I'm using the following ds_config.json file for my training job:

{
    "fp16": {
        "enabled": "true",
        "loss_scale": 0,
        "loss_scale_window": 1000,
        "hysteresis": 2,
        "min_loss_scale": 1,
        "initial_scale_power": 16
    },

    "zero_optimization": {
        "stage": 2,
        "allgather_partitions": "true",
        "allgather_bucket_size": 2e8,
        "overlap_comm": "true",
        "reduce_scatter": "true",
        "reduce_bucket_size": 2e8,
        "contiguous_gradients": "true",
        "cpu_offload": "true"
    },


    "zero_allow_untested_optimizer": "true",
    "optimizer": {
        "type": "AdamW",
        "params": {
            "lr": 0.001,
            "betas": [0.8, 0.999],
            "eps": 1e-8,
            "weight_decay": 3e-7
        }
    },

    "scheduler": {
        "type": "WarmupLR",
        "params": {
            "warmup_min_lr": 0,
            "warmup_max_lr": 3e-5,
            "warmup_num_steps": 500
        }
    },

    "steps_per_print": 2000,
    "wall_clock_breakdown": "false"
}

and I'm using --local-rank=-1(this is a huggingface training job) and I'm trying to train this job on 4 Tesla V100-SXM2-16GB. However, I run into the following AssertionError below

[1/2] c++ -MMD -MF flatten_unflatten.o.d -DTORCH_EXTENSION_NAME=utils -DTORCH_API_INCLUDE_EXTENSION_H -isystem /usr/local/lib/python3.8/dist-packages/torch/include -isystem /usr/local/lib/python3.8/dist-packages/torch/include/torch/csrc/api/include -isystem /usr/local/lib/python3.8/dist-packages/torch/include/TH -isystem /usr/local/lib/python3.8/dist-packages/torch/include/THC -isystem /usr/include/python3.8 -D_GLIBCXX_USE_CXX11_ABI=0 -fPIC -std=c++14 -c /usr/local/lib/python3.8/dist-packages/deepspeed/ops/csrc/utils/flatten_unflatten.cpp -o flatten_unflatten.o 
[2/2] c++ flatten_unflatten.o -shared -L/usr/local/lib/python3.8/dist-packages/torch/lib -lc10 -ltorch_cpu -ltorch -ltorch_python -o utils.so
Loading extension module utils...
Time to load utils op: 13.478780031204224 seconds
[2021-02-09 22:26:48,901] [INFO] [stage2.py:130:__init__] Reduce bucket size 200000000.0
[2021-02-09 22:26:48,901] [INFO] [stage2.py:131:__init__] Allgather bucket size 200000000.0
[2021-02-09 22:26:48,901] [INFO] [stage2.py:132:__init__] CPU Offload: true
group 0 param 0 = 459801600
[2021-02-09 22:26:52,231] [INFO] [stage2.py:399:__init__] optimizer state initialized
[2021-02-09 22:26:52,232] [INFO] [engine.py:586:_configure_optimizer] DeepSpeed Final Optimizer = <deepspeed.runtime.zero.stage2.FP16_DeepSpeedZeroOptimizer object at 0x7fea11ea1190>
[2021-02-09 22:26:52,232] [INFO] [engine.py:405:_configure_lr_scheduler] DeepSpeed using configured LR scheduler = WarmupLR
[2021-02-09 22:26:52,232] [INFO] [logging.py:60:log_dist] [Rank 0] DeepSpeed LR Scheduler = <deepspeed.runtime.lr_schedules.WarmupLR object at 0x7fe9b1759ca0>
[2021-02-09 22:26:52,232] [INFO] [logging.py:60:log_dist] [Rank 0] step=0, skipped=0, lr=[3e-05], mom=[[0.8, 0.999]]

[2021-02-09 22:26:52,232] [INFO] [config.py:733:print] DeepSpeedEngine configuration:
[2021-02-09 22:26:52,232] [INFO] [config.py:737:print]   activation_checkpointing_config  <deepspeed.runtime.activation_checkpointing.config.DeepSpeedActivationCheckpointingConfig object at 0x7fe9b26b1340>
[2021-02-09 22:26:52,232] [INFO] [config.py:737:print]   allreduce_always_fp32 ........ False
[2021-02-09 22:26:52,232] [INFO] [config.py:737:print]   amp_enabled .................. False
[2021-02-09 22:26:52,232] [INFO] [config.py:737:print]   amp_params ................... False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   checkpoint_tag_validation_enabled  True
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   checkpoint_tag_validation_fail  False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   disable_allgather ............ False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   dump_state ................... False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   dynamic_loss_scale_args ...... {'init_scale': 4294967296, 'scale_window': 1000, 'delayed_shift': 2, 'min_scale': 1}
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   elasticity_enabled ........... False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   flops_profiler_config ........ <deepspeed.profiling.config.DeepSpeedFlopsProfilerConfig object at 0x7fe9b26b1280>
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   fp16_enabled ................. true
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   global_rank .................. 0
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   gradient_accumulation_steps .. 4
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   gradient_clipping ............ 1.0
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   gradient_predivide_factor .... 1.0
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   initial_dynamic_scale ........ 4294967296
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   loss_scale ................... 0
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   memory_breakdown ............. False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   optimizer_legacy_fusion ...... False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   optimizer_name ............... adamw
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   optimizer_params ............. {'lr': 3e-05, 'betas': [0.8, 0.999], 'eps': 1e-08, 'weight_decay': 3e-07}
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   pipeline ..................... {'stages': 'auto', 'partition': 'best', 'seed_layers': False, 'activation_checkpoint_interval': 0}
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   pld_enabled .................. False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   pld_params ................... False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   prescale_gradients ........... False
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   scheduler_name ............... WarmupLR
[2021-02-09 22:26:52,233] [INFO] [config.py:737:print]   scheduler_params ............. {'warmup_min_lr': 0, 'warmup_max_lr': 3e-05, 'warmup_num_steps': 500}
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   sparse_attention ............. None
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   sparse_gradients_enabled ..... False
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   steps_per_print .............. 2000
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   tensorboard_enabled .......... False
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   tensorboard_job_name ......... DeepSpeedJobName
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   tensorboard_output_path ...... 
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   train_batch_size ............. 8
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   train_micro_batch_size_per_gpu  2
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   wall_clock_breakdown ......... false
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   world_size ................... 1
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   zero_allow_untested_optimizer  true
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   zero_config .................. {
    "allgather_bucket_size": 200000000.0,
    "allgather_partitions": "true",
    "contiguous_gradients": "true",
    "cpu_offload": "true",
    "elastic_checkpoint": true,
    "load_from_fp32_weights": true,
    "overlap_comm": "true",
    "reduce_bucket_size": 200000000.0,
    "reduce_scatter": "true",
    "stage": 2
}
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   zero_enabled ................. True
[2021-02-09 22:26:52,234] [INFO] [config.py:737:print]   zero_optimization_stage ...... 2
[2021-02-09 22:26:52,234] [INFO] [config.py:739:print]   json = {
    "fp16":{
        "enabled":"true",
        "hysteresis":2,
        "loss_scale":0,
        "loss_scale_window":1000,
        "min_loss_scale":1
    },
    "gradient_accumulation_steps":4,
    "gradient_clipping":1.0,
    "optimizer":{
        "params":{
            "betas":[
                0.8,
                0.999
            ],
            "eps":1e-08,
            "lr":3e-05,
            "weight_decay":3e-07
        },
        "type":"AdamW"
    },
    "scheduler":{
        "params":{
            "warmup_max_lr":3e-05,
            "warmup_min_lr":0,
            "warmup_num_steps":500
        },
        "type":"WarmupLR"
    },
    "steps_per_print":2000,
    "train_micro_batch_size_per_gpu":2,
    "wall_clock_breakdown":"false",
    "zero_allow_untested_optimizer":"true",
    "zero_optimization":{
        "allgather_bucket_size":200000000.0,
        "allgather_partitions":"true",
        "contiguous_gradients":"true",
        "cpu_offload":"true",
        "overlap_comm":"true",
        "reduce_bucket_size":200000000.0,
        "reduce_scatter":"true",
        "stage":2
    }
}
Using /root/.cache/torch_extensions as PyTorch extensions root...
No modifications detected for re-loaded extension module utils, skipping build step...
Loading extension module utils...
Time to load utils op: 0.0004968643188476562 seconds

 0%|          | 0/3 [00:00<?, ?it/s]/usr/local/lib/python3.8/dist-packages/nlp/utils/py_utils.py:191: UserWarning: The given NumPy array is not writeable, and PyTorch does not support non-writeable tensors. This means you can write to the underlying (supposedly non-writeable) NumPy array using the tensor. You may want to copy the array to protect its data or make it writeable before converting it to a tensor. This type of warning will be suppressed for the rest of this program. (Triggered internally at  /pytorch/torch/csrc/utils/tensor_numpy.cpp:141.)
  return function(data_struct)
Traceback (most recent call last):
  File "abstractive_summarization.py", line 374, in <module>
    run()
  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 829, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 782, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1066, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 610, in invoke
    return callback(*args, **kwargs)
  File "abstractive_summarization.py", line 349, in run
    trainer.train()
  File "/usr/local/lib/python3.8/dist-packages/transformers/trainer.py", line 888, in train
    tr_loss += self.training_step(model, inputs)
  File "/usr/local/lib/python3.8/dist-packages/transformers/trainer.py", line 1250, in training_step
    loss = self.compute_loss(model, inputs)
  File "/usr/local/lib/python3.8/dist-packages/transformers/trainer.py", line 1277, in compute_loss
    outputs = model(**inputs)
  File "/usr/local/lib/python3.8/dist-packages/torch/nn/modules/module.py", line 722, in _call_impl
    result = self.forward(*input, **kwargs)
  File "/usr/local/lib/python3.8/dist-packages/torch/nn/parallel/data_parallel.py", line 155, in forward
    outputs = self.parallel_apply(replicas, inputs, kwargs)
  File "/usr/local/lib/python3.8/dist-packages/torch/nn/parallel/data_parallel.py", line 165, in parallel_apply
    return parallel_apply(replicas, inputs, kwargs, self.device_ids[:len(replicas)])
  File "/usr/local/lib/python3.8/dist-packages/torch/nn/parallel/parallel_apply.py", line 85, in parallel_apply
    output.reraise()
  File "/usr/local/lib/python3.8/dist-packages/torch/_utils.py", line 395, in reraise
    raise self.exc_type(msg)
AssertionError: Caught AssertionError in replica 1 on device 1.
Original Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/torch/nn/parallel/parallel_apply.py", line 60, in _worker
    output = module(*input, **kwargs)
  File "/usr/local/lib/python3.8/dist-packages/torch/nn/modules/module.py", line 722, in _call_impl
    result = self.forward(*input, **kwargs)
  File "/usr/local/lib/python3.8/dist-packages/deepspeed/runtime/engine.py", line 830, in forward
    self.timers('forward_microstep').start()
  File "/usr/local/lib/python3.8/dist-packages/deepspeed/utils/timer.py", line 38, in start
    assert not self.started_, 'timer has already been started'
AssertionError: timer has already been started

  0%|          | 0/3 [00:09<?, ?it/s]

I'd greatly appreciate any help with this and what I might be missing. Thank you

Start with the full traceback from abstractive_summarization.py through transformers Trainer.train and PyTorch DataParallel.parallel_apply; the supplied log is truncated before the underlying assertion location. Compare that execution path with DeepSpeed's stage2.py initialization and reproduce the failure using the provided configuration and four-GPU setup. Done means identifying the cause of the already-started timer assertion and confirming a reproducible fix.