[trainer + examples] set log level from CLI
Author: stas00
Pull request: yes

As examples keep adding more more debug dumps as info (3 new dumps in `run_translation.py`) and repetitive logger warnings keep on growing - w/o being able to control the level of noise, this PR gives the noise control back to the user. 

One of the main pros of this change is that now we can actually use `logger.debug` and put the less important info there, and only activate it when reporting issues or debugging something. Much better than having only `info` or `warning` toggle to logging.

This PR:

1. Introduces `--log_level` which has the normal 5 levels, plus "passive" which doesn't do anything special and let's the driver application do whatever it wants. if it's not `passive` it sets the log level to that arg's value asap.
2. Change Traner's `log_metrics` to be a non-logger print, since this is the whole point of the training/eval and thus IMHO should be always printed as its result. I can see where someone would say, but what if I don't want even this printed. This is fair, in which case I propose to add an explicit new arg `--print_results`.
3. As a single template to work on changes `run_translation.py` to also use this new CLI arg to do the log settings in its own and all sub-modules it uses, e.g. `datasets` here. e.g. previously `datasets` verbosity was on its own.

Questions/Notes to reviewers:
1. If this is accepted I propose to deprecate `training_args.should_log`  since now it's no longer just `info` or `warn`, but provides a more refined control over log levels. And if it's passed to auto-set `--log_level=info`. I left the original logic there for now. The examples can still default to `warn` as they are now.
2. It's however possible that there should be `--train_log_level` and `--log_level` with the latter overriding the former if set, but most likely these should be in sync with everything.
3. Obviously if this is accepted once this example is polished - we will replicate the same for other examples in another PR.
4. I couldn't find how get rid of logger warnings at import time, but it's alright, as now there are only a few left.
5. Specific to Deepspeed integration I need to find a way to do the same there as it's *very* noisy. (in a follow up PR most likely if  find a way).
 
I am very open to other ways of implementing it, naming it, etc.  Not really attached to how, but when I develop/debug code I want to see only the messages that I need to focus on and not hundreds of lines of noise that it's always the same and makes it difficult to see the important things.

With this PR I get:

```
export BS=16; rm -r output_dir; PYTHONPATH=src USE_TF=0 CUDA_VISIBLE_DEVICES=0 python examples/pytorch/translation/run_translation.py --model_name_or_path t5-small --output_dir output_dir --adam_eps 1e-06  --do_train --label_smoothing 0.1 --learning_rate 3e-5 --logging_first_step --logging_steps 500 --max_source_length 128 --max_target_length 128 --num_train_epochs 1 --overwrite_output_dir --per_device_train_batch_size $BS --predict_with_generate --sortish_sampler --source_lang en --target_lang ro --dataset_name wmt16 --dataset_config "ro-en" --source_prefix "translate English to Romanian: " --val_max_target_length 128 --warmup_steps 50 --max_train_samples 50 --max_eval_samples 50 \
--log_level=critical
2021-06-20 19:17:40.705704: I tensorflow/stream_executor/platform/default/dso_loader.cc:49] Successfully opened dynamic library libcudart.so.11.0
{'loss': 3.0621, 'learning_rate': 6.000000000000001e-07, 'epoch': 0.25}                                                                                          
{'train_runtime': 1.3178, 'train_samples_per_second': 37.943, 'train_steps_per_second': 3.035, 'train_loss': 2.9988757967948914, 'epoch': 1.0}                   
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 4/4 [00:00<00:00,  7.43it/s]
***** train metrics *****
  epoch                    =        1.0
  train_loss               =     2.9989
  train_runtime            = 0:00:01.31
  train_samples            =         50
  train_samples_per_second =     37.943
  train_steps_per_second   =      3.035
```

Thank you.

@sgugger, @LysandreJik, @patrickvonplaten 


Comments:
> but for the `should_print` (or whatever) argument, I would wait until a user actually requests it. It seems weird to me to run a training script and not even want to have the metrics outputted.

Totally agree!

wrt the rest of the logic, it looks like I didn't look close enough and `should_log` is a toggle on sort of whether this is a master or a slave node, but I don't know the sagemaker logic to tell that particular branch. So it has its function.

After experimenting with different approaches, it looks like to give users a full control they really should be able to set separately the log_level on the master and slave nodes. So I propose to further add another arg:

So training args:
```
    def get_node_log_level(self):
        default_log_level_master_node = logging.INFO
        default_log_level_slave_node = logging.WARNING
        log_level_master_node = default_log_level_master_node if self.log_level_master_node != -1 else self.log_level_master_node
        log_level_slave_node = default_log_level_slave_node if self.log_level_slave_node != -1 else self.log_level_slave_node
        return log_level_master_node if self.should_log else log_level_slave_node
```

and then the application side becomes much simpler:

```
    log_level = training_args.get_node_log_level()
    logger.setLevel(log_level)
    datasets.utils.logging.set_verbosity(log_level)
    transformers.utils.logging.set_verbosity(log_level)
```

no need for any logic there.

W/o the cli arg for the slave, the user then can't really set a high log level since the slave nodes will still be set to WARNING.

(After experiments with 64nodes any extra line gets multiplied many times. I wish I could control the exceptions too.)

I'm just not sure whether to call the 2 new args:

1.
```
--log_level
--log_level_slave
```
or 2.
```
--log_level_master
--log_level_slave
```
or 3.
```
--log_level_master_node
--log_level_slave_node
```

I'd say the 2nd one is more explicit and probably is a better choice in the long run. 3rd - may be even more clear.

Please let me know your thoughts on this modification to the new CLI args and the naming.

thank you!

Ah yes, `should_log` is a property that determines if a process is the local main or not (and also takes into account the `log_on_each_node` argument). I would keep `--log_level` for the log level of the main process (or main processes if `log_on_each_node` is true) since most users are not using distributed training, so it makes sense keeping it like that.

For the other argument, let's not use the slave terminology as many people have voiced it makes them uncomfortable. We can use main/replica and call the second argument `--log_level_replica` for instance. I think the default `"passive"` should then be warning if no `log_level` is passed and `log_level+1` if one is passed, does that make sense?



> Ah yes, `should_log` is a property that determines if a process is the local main or not (and also takes into account the `log_on_each_node` argument). I would keep `--log_level` for the log level of the main process (or main processes if `log_on_each_node` is true) since most users are not using distributed training, so it makes sense keeping it like that.

+1

> For the other argument, let's not use the slave terminology as many people have voiced it makes them uncomfortable. 

But we are using MASTER for torch.distributed, so those who are uncomfortable with master/slave are already uncomfortable.

> We can use main/replica and call the second argument `--log_level_replica` for instance. 

This sounds very foreign, but logically it makes sense.

Do you know if someone has found a new standard pair for master/slave that is getting embraced by the industry?

> I think the default `"passive"` should then be warning if no `log_level` is passed and `log_level+1` if one is passed, does that make sense?

The assumption of `log_level+1` doesn't quite work here. What if the user wants to get `log.DEBUG` for the main process and still keep the slave nodes relatively quiet. +1 would force them all to `log.INFO` which would be too much. (and it'd be +10 here ;)

Therefore I propose to just stick to (please ignore the naming at this moment):
```
        default_log_level_master_node = logging.INFO
        default_log_level_slave_node = logging.WARNING
```
and only override each with the corresponding:
```
--log_level_master_node
--log_level_slave_node
```



> But we are using MASTER for torch.distributed, so those who are uncomfortable with master/slave are already uncomfortable.

I may have missed something, but there should not be any master reference in the Transformers code base, so I'm not sure what you mean. We can't control how PyTorch names its arguments if you're referring to `--master_port` and `--master_addr`.

> Do you know if someone has found a new standard pair for master/slave that is getting embraced by the industry?

`main` and `replica` seem to be used, but I don't know if there are the new standard. I don't think there is one, but I may have missed something. I'm not attached to those names if you have better ideas.

> The assumption of log_level+1 doesn't quite work here. 

That makes sense, let's go for defaults to INFO and WARNING respectively.

> > But we are using MASTER for torch.distributed, so those who are uncomfortable with master/slave are already uncomfortable.
> 
> I may have missed something, but there should not be any master reference in the Transformers code base, so I'm not sure what you mean. We can't control how PyTorch names its arguments if you're referring to `--master_port` and `--master_addr`.

Indeed, that what I was referring to. 

> > Do you know if someone has found a new standard pair for master/slave that is getting embraced by the industry?
> 
> `main` and `replica` seem to be used, but I don't know if there are the new standard. I don't think there is one, but I may have missed something. I'm not attached to those names if you have better ideas.

I asked about this on the torch slack and was told that they dealt with **blacklists**:
https://github.com/pytorch/pytorch/search?q=blacklist&type=commits
replacing those with **blocklists**. But master/slave hasn't been dealt with yet. But I also don't see any `slave` in the pytorch source code - only in 3rd party code, so perhaps there is no need to.

And the best finding was the sharing of this resource:
https://en.wikipedia.org/wiki/Master/slave_(technology)#Replacements

So in our context, given that we are dealing with master and slave being identical, I think these 3 would be the most matching:

1. Primary/Replica
2. Master/Replica
3. Source/Replica

and personally I 2nd resonates the most, same as master weights for example.

Unless I'm missing something in the whole controversy, master on its own, with the slave connotation is OK, right? Otherwise we would have to kill the concept of mastering something - that would be super 1984. 

It's not controversial as long it's use in the context of mastering something, which is not really what the master process is all about, so I would use main as GitHub now does, or primary if you prefer this terminology.

Like I said though, the argument for controlling the primary process for logging should just be `log_level` IMO as distributed training is not used by all users, and `log_level`, `log_level_replicas` is clear enough.

Sounds good, Sylvain. I was just using the opportunity to get clarity around this modern development to do the right thing in the future code.

No problem at all!

ok, so as discussed - added `--log_level_replica` (let me know if you prefer `--log_level_replicas`)

Though now as I'm thinking about it - I don't think the name is unambiguous since we have replicas that are on the same node and those replicas get very different treatment.

I also added a test and extended docs.

I moved `log_on_each_node` into the log_* group in training args.

There is a bit of an overlap / possible conflict in setting `transformers` log-level in the user code and also in trainer's init. The early setting in the app is important to catch those early logs and we hope that the app used the same log-level - otherwise trainer's init will reset user's log-level for `transformers` - but I think this is expected if `--log_level` is passed. Just don't pass it.

That's why I added the extended docs so that the whole domain of logging is discussed in one place.

Comments and suggestions for further improvements are welcome. Thank you!

If you don't mind having another look with my last changes at your convenience, @sgugger - thank you.

Looking good!

Noticing one potentially undesirable effect of this change, since the example now syncs `datasets`'s verbosity level, their `info` is a way too loud, and a lot of it is too much unimportant info. They seem to use warning as info and info as debug.

Filed an issue there: https://github.com/huggingface/datasets/issues/2543 - I'd change many warnings to infos and the previous infos to debug there.