feat(TFTrainer): improve logging
Author: borisdayma
Pull request: yes

This PR supersedes PR #4756 
I wanted initially to refactor logging between `Trainer` and `TFTrainer` but there seems to be too many differences between them for it to make sense (distributed training, logging methods, `wandb.watch`…).

Logging is now handled directly within each Trainer and all comments from previous PR have been applied here.

Notes:

* `TFTrainer`: @jplu There should be the same modifications we discussed. I just moved the check of `global_step` within logging for better readability.
* `TFTrainer._log` does not have a tqdm iterator argument (unlike in `Trainer`) since you're not using it at the moment but it could be useful in the future
* `Trainer`: main update is to handle the case where we do only evaluations (no training)

Comments:
Integration test error does not seem to be related to this PR.

@jplu On another note, I got strange results while using `run_tf_glue` as learning rate goes quickly to 0.

Command:
`run_tf_glue.py --model_name_or_path bert-base-cased --task_name MRPC --do_train --do_eval --max_seq_length 128 --per_device_train_batch_size 32 --learning_rate 2e-5 --num_train_epochs 3.0 --output_dir /tmp/MRPC/ --overwrite_output_dir --logging_dir log --evaluate_during_training --eval_steps 50 --logging_steps 10`

Graph
![image](https://user-images.githubusercontent.com/715491/84448088-5e9c2600-ac0f-11ea-9994-bdb64c84c483.png)

W&B Run: https://app.wandb.ai/borisd13/huggingface/runs/21rxop7c

Good you have restarted a new PR!

Humm for the loss that drop quickly to 0 I think it might come from your side because I get normal evolution even after multiple runs. Here an output:

```
06/12/2020 10:05:38 - INFO - transformers.trainer_tf -   ***** Running training *****
06/12/2020 10:05:38 - INFO - transformers.trainer_tf -     Num examples = 3668
06/12/2020 10:05:38 - INFO - transformers.trainer_tf -     Num Epochs = 3
06/12/2020 10:05:38 - INFO - transformers.trainer_tf -     Total optimization steps = 29
WARNING:tensorflow:From /home/jplu/transformers/src/transformers/trainer_tf.py:355: StrategyBase.experimental_run_v2 (from tensorflow.python.distribute.distribute_lib) is deprecated and will be removed in a future version.
Instructions for updating:
renamed to `run`
06/12/2020 10:05:38 - WARNING - tensorflow -   From /home/jplu/transformers/src/transformers/trainer_tf.py:355: StrategyBase.experimental_run_v2 (from tensorflow.python.distribute.distribute_lib) is deprecated and will be removed in a future version.
Instructions for updating:
renamed to `run`
WARNING:tensorflow:From /opt/anaconda3/envs/jplu-transformers/lib/python3.7/site-packages/tensorflow/python/ops/resource_variable_ops.py:1817: calling BaseResourceVariable.__init__ (from tensorflow.python.ops.resource_variable_ops) with constraint is deprecated and will be removed in a future version.
Instructions for updating:
If using Keras pass *_constraint arguments to layers.
06/12/2020 10:05:47 - WARNING - tensorflow -   From /opt/anaconda3/envs/jplu-transformers/lib/python3.7/site-packages/tensorflow/python/ops/resource_variable_ops.py:1817: calling BaseResourceVariable.__init__ (from tensorflow.python.ops.resource_variable_ops) with constraint is deprecated and will be removed in a future version.
Instructions for updating:
If using Keras pass *_constraint arguments to layers.
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:06:17 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:06:17 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:06:53 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:06:53 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
INFO:tensorflow:batch_all_reduce: 201 all-reduces with algorithm = nccl, num_packs = 1
06/12/2020 10:08:32 - INFO - tensorflow -   batch_all_reduce: 201 all-reduces with algorithm = nccl, num_packs = 1
INFO:tensorflow:batch_all_reduce: 201 all-reduces with algorithm = nccl, num_packs = 1
06/12/2020 10:08:48 - INFO - tensorflow -   batch_all_reduce: 201 all-reduces with algorithm = nccl, num_packs = 1
06/12/2020 10:09:46 - INFO - transformers.trainer_tf -   Epoch 1 Step 10 Train Loss 0.6610
06/12/2020 10:10:02 - INFO - transformers.trainer_tf -   Epoch 1 Step 20 Train Loss 0.5626
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:10:46 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:10:46 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:11:15 - INFO - transformers.trainer_tf -   Epoch 2 Step 30 Train Loss 0.5585
06/12/2020 10:11:31 - INFO - transformers.trainer_tf -   Epoch 2 Step 40 Train Loss 0.5492
06/12/2020 10:11:47 - INFO - transformers.trainer_tf -   ***** Running Evaluation *****
06/12/2020 10:11:47 - INFO - transformers.trainer_tf -     Batch size = 32
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:11:53 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:11:53 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:12:04 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
INFO:tensorflow:Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:12:04 - INFO - tensorflow -   Reduce to /job:localhost/replica:0/task:0/device:CPU:0 then broadcast to ('/job:localhost/replica:0/task:0/device:CPU:0',).
06/12/2020 10:12:08 - INFO - transformers.trainer_tf -   Epoch 2 Step 50 Validation Metrics {'eval_eval_loss': 0.5300102, 'eval_eval_acc': 0.7230392156862745, 'eval_eval_f1': 0.8274809160305343, 'eval_eval_acc_and_f1': 0.7752600658584043, 'learning_rate': 0.0}
06/12/2020 10:12:08 - INFO - transformers.trainer_tf -   Epoch 2 Step 50 Train Loss 0.6273
06/12/2020 10:13:21 - INFO - transformers.trainer_tf -   Epoch 3 Step 60 Train Loss 0.6168
06/12/2020 10:13:37 - INFO - transformers.trainer_tf -   Epoch 3 Step 70 Train Loss 0.5616
06/12/2020 10:13:53 - INFO - transformers.trainer_tf -   Epoch 3 Step 80 Train Loss 0.5551
06/12/2020 10:14:05 - INFO - transformers.trainer_tf -   Saving model in /tmp/MRPC/
```

I used the exact same command line than yours.

I seem to be having a different value of `self.train_steps`.

```
Num examples = 3668
Num Epochs = 3
Total optimization steps = 115
```
Here is my full log output: https://app.wandb.ai/borisd13/huggingface/runs/1u5spvau/logs

Actually I just checked and I'm getting the exact same problem in the `master` branch so i guess the issue I'm having is independent from this PR.

Let me know if you need any modification on this PR.

Sorry I don't see what is the issue in your logs, all the values seems ok. I get 29 steps because I run over 4 gpus.

Here is a gist with full output: https://gist.github.com/borisdayma/62fd9338aae4f373a9c0709a8961f5bc

It's probably independent. I could file a separate issue.

I still don't see what is the issue sorry, everything looks normal.

@jplu actually I noticed you have the same issue.

```
06/12/2020 10:12:08 - INFO - transformers.trainer_tf -   Epoch 2 Step 50 Validation Metrics {'eval_eval_loss': 0.5300102, 'eval_eval_acc': 0.7230392156862745, 'eval_eval_f1': 0.8274809160305343, 'eval_eval_acc_and_f1': 0.7752600658584043, 'learning_rate': 0.0}
```

In current master, learning_rate is displayed only at eval. It should not be 0 at this specific step.
If you confirm let me know if you want me to file an issue.

In any case, since it's independent from this PR, let me know if you approve it.
It's always difficult to stay in sync with master so I'd like to make all necessary changes as soon as possible since it's a difficult PR.

This is normal, it is the decay of the LR so at some point it gets 0. It is ok. I will take some time to review your PR this weekend.

Oh I see what you mean, yes it gets to 0 at the end of the first epoch, and it shouldn't, it is fixed from my side, PR will be here so no worries we can focus on your logging improvement. Thanks!!

@jplu I addressed your comments. Let me know if I understood correctly:

* `global_step` moved to `__init__`
* `epoch` added to logs directly within training loop
* In addition, I also added `epoch` in eval loop when called from training loop. If we log training loss every 20 steps and we log evaluation metrics every 50 steps, we need to make sure we add `epoch`

I'm going to add a comment for a further simplification of the code if you'd like.

# [Codecov](https://codecov.io/gh/huggingface/transformers/pull/4946?src=pr&el=h1) Report
> Merging [#4946](https://codecov.io/gh/huggingface/transformers/pull/4946?src=pr&el=desc) into [master](https://codecov.io/gh/huggingface/transformers/commit/473808da0d476792070f0e7dfebcf1121a12a34f&el=desc) will **decrease** coverage by `0.00%`.
> The diff coverage is `18.18%`.

[![Impacted file tree graph](https://codecov.io/gh/huggingface/transformers/pull/4946/graphs/tree.svg?width=650&height=150&src=pr&token=9qOlN6Hb1c)](https://codecov.io/gh/huggingface/transformers/pull/4946?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##           master    #4946      +/-   ##
==========================================
- Coverage   77.14%   77.14%   -0.01%     
==========================================
  Files         128      128              
  Lines       21745    21773      +28     
==========================================
+ Hits        16775    16796      +21     
- Misses       4970     4977       +7     
```


| [Impacted Files](https://codecov.io/gh/huggingface/transformers/pull/4946?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [src/transformers/trainer\_tf.py](https://codecov.io/gh/huggingface/transformers/pull/4946/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy90cmFpbmVyX3RmLnB5) | `18.98% <11.76%> (-0.07%)` | :arrow_down: |
| [src/transformers/trainer.py](https://codecov.io/gh/huggingface/transformers/pull/4946/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy90cmFpbmVyLnB5) | `39.62% <100.00%> (+0.14%)` | :arrow_up: |
| [src/transformers/modeling\_tf\_utils.py](https://codecov.io/gh/huggingface/transformers/pull/4946/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9tb2RlbGluZ190Zl91dGlscy5weQ==) | `87.42% <0.00%> (ø)` | |
| [src/transformers/file\_utils.py](https://codecov.io/gh/huggingface/transformers/pull/4946/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9maWxlX3V0aWxzLnB5) | `73.79% <0.00%> (+0.40%)` | :arrow_up: |
| [src/transformers/modeling\_xlnet.py](https://codecov.io/gh/huggingface/transformers/pull/4946/diff?src=pr&el=tree#diff-c3JjL3RyYW5zZm9ybWVycy9tb2RlbGluZ194bG5ldC5weQ==) | `78.65% <0.00%> (+2.29%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/huggingface/transformers/pull/4946?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/huggingface/transformers/pull/4946?src=pr&el=footer). Last update [473808d...28f004b](https://codecov.io/gh/huggingface/transformers/pull/4946?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Ok, we almost see the end of the tunnel. Just few comments yet :)

The way it is now, `epoch` and `global_step` will just be 0 in eval mode only.