BERT pretraining hangs at first epoch: MisconfigurationException
State: closed | Pull request: no
Labels: name: bug

Hello, I've been trying to pretrain a BERT model with the [`[examples/nlp/language_modeling/bert_pretraining.py]`](https://github.com/NVIDIA/NeMo/blob/main/examples/nlp/language_modeling/bert_pretraining.py) script and the training hangs at the first epoch. Previously I used to train with the script that was there before [using PyTorch Lightning's DDPPlugin](https://github.com/NVIDIA/NeMo/commit/7d4ad85dc38d41eae4369f2d1b6ec8f3de5cf1b7#diff-388430d4055e0020d401768aa02e821c948d18afe24e37c10e9d443c88de0477) (i.e with older dependencies, using **nemo_toolkit[all]==1.0.0b1**) which worked just fine.
This is the raised exception now: `MisconfigurationException: ModelCheckpoint(monitor='val_loss') not found in the returned metrics: ['train_loss']. HINT: Did you call self.log('val_loss', value) in the LightningModule?`

**_P.S:_** I need to use this version of NeMo (1.0.0rc1) because I'm going to integrate another PyTorch Lightning plugin once this works, the 1.0.0rc1 is only compatible with an older Lightning version that doesn't support plugins.

 - Environment location: personal laptop
 - Method of NeMo install: 
        apt-get update && apt-get install -y libsndfile1 ffmpeg
        pip install Cython
        python -m pip install git+https://github.com/NVIDIA/NeMo.git@main

**Environment details**

- Ubuntu 20.4
- PyTorch version==1.8.1+cu111
- Python version==Python 3.8.5
- PyTorch Lightning version==1.2.10
- NeMo toolkit version==1.0.0rc4


Stack trace:
```
[NeMo W 2021-04-29 13:10:38 nemo_logging:349] /home/mallonus/tunbert-pip/lib/python3.8/site-packages/omegaconf/basecontainer.py:225: UserWarning: cfg.pretty() is deprecated and will be removed in a future version.
    Use OmegaConf.to_yaml(cfg)
    
      warnings.warn(
    
[NeMo I 2021-04-29 13:10:38 bert_pretraining:29] Config:
     name: PretrainingBERTFromText
    trainer:
      gpus: 1
      num_nodes: 1
      max_epochs: 10
      max_steps: null
      accumulate_grad_batches: 1
      precision: 16
      amp_level: O1
      accelerator: ddp
      gradient_clip_val: 0.0
      log_every_n_steps: 1
      val_check_interval: 1.0
      checkpoint_callback: false
      logger: false
    model:
      nemo_path: null
      only_mlm_loss: false
      num_tok_classification_layers: 1
      num_seq_classification_layers: 2
      max_seq_length: 128
      mask_prob: 0.15
      short_seq_prob: 0.1
      language_model:
        pretrained_model_name: bert-base-uncased
        lm_checkpoint: null
        config:
          attention_probs_dropout_prob: 0.1
          hidden_act: gelu
          hidden_dropout_prob: 0.1
          hidden_size: 768
          initializer_range: 0.02
          intermediate_size: 3072
          max_position_embeddings: 512
          num_attention_heads: 12
          num_hidden_layers: 12
          type_vocab_size: 2
          vocab_size: 30522
        config_file: null
      tokenizer:
        tokenizer_name: ${model.language_model.pretrained_model_name}
        vocab_file: null
        tokenizer_model: null
        special_tokens:
          unk_token: '[UNK]'
          sep_token: '[SEP]'
          pad_token: '[PAD]'
          bos_token: '[CLS]'
          mask_token: '[MASK]'
          eos_token: '[SEP]'
          cls_token: '[CLS]'
      train_ds:
        data_file: dev-data/pretraining_data/train.txt
        max_seq_length: ${model.max_seq_length}
        mask_prob: ${model.mask_prob}
        short_seq_prob: ${model.short_seq_prob}
        batch_size: 2
        shuffle: true
        num_samples: -1
        num_workers: 2
        drop_last: false
        pin_memory: false
      validation_ds:
        data_file: dev-data/pretraining_data/valid.txt
        max_seq_length: ${model.max_seq_length}
        mask_prob: ${model.mask_prob}
        short_seq_prob: ${model.short_seq_prob}
        batch_size: 2
        shuffle: false
        num_samples: -1
        num_workers: 2
        drop_last: false
        pin_memory: false
      optim:
        name: adamw
        lr: 3.0e-05
        weight_decay: 0.0
        sched:
          name: CosineAnnealing
          warmup_steps: null
          warmup_ratio: 0.1
          min_lr: 0.0
          last_epoch: -1
    exp_manager:
      exp_dir: null
      name: PretrainingBERTFromText
      create_tensorboard_logger: true
      create_checkpoint_callback: true
    
GPU available: True, used: True
TPU available: False, using: 0 TPU cores
Using native 16bit precision.
[NeMo I 2021-04-29 13:10:38 exp_manager:216] Experiments will be logged at /home/mallonus/tunbert-master/nemo_experiments/PretrainingBERTFromText/2021-04-29_13-10-38
[NeMo I 2021-04-29 13:10:38 exp_manager:563] TensorboardLogger has been set up
[NeMo I 2021-04-29 13:10:47 modelPT:695] Optimizer config = AdamW (
    Parameter Group 0
        amsgrad: False
        betas: (0.9, 0.999)
        eps: 1e-08
        lr: 3e-05
        weight_decay: 0.0
    )
[NeMo I 2021-04-29 13:10:47 lr_scheduler:617] Scheduler "<nemo.core.optim.lr_scheduler.CosineAnnealing object at 0x7f44269322e0>" 
    will be used during training (effective maximum steps = 80) - 
    Parameters : 
    (warmup_steps: null
    warmup_ratio: 0.1
    min_lr: 0.0
    last_epoch: -1
    max_steps: 80
    )
LOCAL_RANK: 0 - CUDA_VISIBLE_DEVICES: [0]
[NeMo I 2021-04-29 13:10:47 modelPT:695] Optimizer config = AdamW (
    Parameter Group 0
        amsgrad: False
        betas: (0.9, 0.999)
        eps: 1e-08
        lr: 3e-05
        weight_decay: 0.0
    )
[NeMo I 2021-04-29 13:10:47 lr_scheduler:617] Scheduler "<nemo.core.optim.lr_scheduler.CosineAnnealing object at 0x7f4426757b20>" 
    will be used during training (effective maximum steps = 80) - 
    Parameters : 
    (warmup_steps: null
    warmup_ratio: 0.1
    min_lr: 0.0
    last_epoch: -1
    max_steps: 80
    )
initializing ddp: GLOBAL_RANK: 0, MEMBER: 1/1
INFO:root:Added key: store_based_barrier_key:1 to store for rank: 0

  | Name                  | Type                           | Params
-------------------------------------------------------------------------
0 | bert_model            | BertEncoder                    | 109 M 
1 | mlm_classifier        | BertPretrainingTokenClassifier | 24.1 M
2 | mlm_loss              | SmoothedCrossEntropyLoss       | 0     
3 | nsp_classifier        | SequenceClassifier             | 592 K 
4 | nsp_loss              | CrossEntropyLoss               | 0     
5 | agg_loss              | AggregatorLoss                 | 0     
6 | validation_perplexity | Perplexity                     | 0     
-------------------------------------------------------------------------
110 M     Trainable params
0         Non-trainable params
110 M     Total params
442.788   Total estimated model params size (MB)
[NeMo W 2021-04-29 13:10:49 nemo_logging:349] /home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/utilities/distributed.py:68: UserWarning: The dataloader, val dataloader 0, does not have many workers which may be a bottleneck. Consider increasing the value of the `num_workers` argument` (try 4 which is the number of cpus on this machine) in the `DataLoader` init to improve performance.
      warnings.warn(*args, **kwargs)
    
Validation sanity check: 100%|███████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 2/2 [00:00<00:00,  5.42it/s][NeMo I 2021-04-29 13:10:49 bert_lm_model:184] evaluation perplexity 26155.0595703125
[NeMo W 2021-04-29 13:10:49 nemo_logging:349] /home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/utilities/distributed.py:68: UserWarning: The validation_epoch_end should not return anything as of 9.1. To log, use self.log(...) or self.write(...) directly in the LightningModule
      warnings.warn(*args, **kwargs)
    
[NeMo W 2021-04-29 13:10:49 nemo_logging:349] /home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/utilities/distributed.py:68: UserWarning: The dataloader, train dataloader, does not have many workers which may be a bottleneck. Consider increasing the value of the `num_workers` argument` (try 4 which is the number of cpus on this machine) in the `DataLoader` init to improve performance.
      warnings.warn(*args, **kwargs)
    
Epoch 0: 100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 10/10 [00:03<00:00,  2.73it/s, loss=10.7, v_num=0-38][NeMo I 2021-04-29 13:10:53 bert_lm_model:184] evaluation perplexity 26092.4775390625██████████████                                                                                  | 1/2 [00:00<00:00,  6.30it/s]
[NeMo W 2021-04-29 13:10:53 nemo_logging:349] /home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/utilities/distributed.py:68: UserWarning: The {log:dict keyword} was deprecated in 0.9.1 and will be removed in 1.0.0
    Please use self.log(...) inside the lightningModule instead.
    # log on a step or aggregate epoch metric to the logger and/or progress bar (inside LightningModule)
    self.log('train_loss', loss, on_step=True, on_epoch=True, prog_bar=True)
      warnings.warn(*args, **kwargs)
    
Epoch 0: 100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 10/10 [00:03<00:00,  2.63it/s, loss=10.7, v_num=0-38Saving latest checkpoint...                                                                                                                                                                                         
Traceback (most recent call last):
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/trainer.py", line 637, in run_train
    self.train_loop.run_training_epoch()
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/training_loop.py", line 577, in run_training_epoch
    self.trainer.run_evaluation(on_epoch=True)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/trainer.py", line 752, in run_evaluation
    self.evaluation_loop.on_evaluation_end()
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/evaluation_loop.py", line 100, in on_evaluation_end
    self.trainer.call_hook('on_validation_end', *args, **kwargs)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/trainer.py", line 1095, in call_hook
    trainer_hook(*args, **kwargs)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/callback_hook.py", line 185, in on_validation_end
    callback.on_validation_end(self, self.lightning_module)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/callbacks/model_checkpoint.py", line 212, in on_validation_end
    self.save_checkpoint(trainer, pl_module)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/callbacks/model_checkpoint.py", line 247, in save_checkpoint
    self._validate_monitor_key(trainer)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/callbacks/model_checkpoint.py", line 495, in _validate_monitor_key
    raise MisconfigurationException(m)
pytorch_lightning.utilities.exceptions.MisconfigurationException: ModelCheckpoint(monitor='val_loss') not found in the returned metrics: ['train_loss']. HINT: Did you call self.log('val_loss', value) in the LightningModule?

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "models/bert-nvidia/bert_pretraining.py", line 33, in main
    trainer.fit(bert_model)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/trainer.py", line 499, in fit
    self.dispatch()
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/trainer.py", line 546, in dispatch
    self.accelerator.start_training(self)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/accelerators/accelerator.py", line 73, in start_training
    self.training_type_plugin.start_training(trainer)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/plugins/training_type/training_type_plugin.py", line 114, in start_training
    self._results = trainer.run_train()
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/trainer.py", line 670, in run_train
    self.train_loop.on_train_end()
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/training_loop.py", line 134, in on_train_end
    self.check_checkpoint_callback(should_update=True, is_last=True)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/trainer/training_loop.py", line 164, in check_checkpoint_callback
    cb.on_validation_end(self.trainer, model)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/callbacks/model_checkpoint.py", line 212, in on_validation_end
    self.save_checkpoint(trainer, pl_module)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/callbacks/model_checkpoint.py", line 247, in save_checkpoint
    self._validate_monitor_key(trainer)
  File "/home/mallonus/tunbert-pip/lib/python3.8/site-packages/pytorch_lightning/callbacks/model_checkpoint.py", line 495, in _validate_monitor_key
    raise MisconfigurationException(m)
pytorch_lightning.utilities.exceptions.MisconfigurationException: ModelCheckpoint(monitor='val_loss') not found in the returned metrics: ['train_loss']. HINT: Did you call self.log('val_loss', value) in the LightningModule?

Set the environment variable HYDRA_FULL_ERROR=1 for a complete stack trace.
Epoch 0: 100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 10/10 [00:03<00:00,  2.54it/s, loss=10.7, v_num=0-38]

```

This error happens usually in cases you train for limited steps and no validation has happend at all. Therefore there would be no validation loss logged. You may train for more steps, or drop the validation section, or increase the frequency of validation.

@VahidooX Thank you for your response! I had to set `create_checkpoint_callback` to `false` in `exp_manager` and stopped seeing the error.