[seq2seq] some logging for all processes in distributed mode
Author: stas00
Pull request: no
Labels: name: WIP

In 2D Parallelism, e.g. Pipeline + DeepSpeed I need to log unique device maps per process for the user to see, but currently `logger.info()` is only activated for the main process via `if is_main_process`. Currently only in `examples/seq2seq/run_seq2seq.py`, `examples/seq2seq/finetune_trainer.py`, but it'll be needed for other scripts as well down the road.

Any idea how I could accomplish that while keeping things as they are? I guess I could use `logger.warn` as a workaround, since it's not disabled for other processes. But it's not a good approach, since it's a WARNING after all. And I don't quite want to use `print()` as it might not be what the user wants if they want things quiet.

Perhaps you have some other ideas on how I could go about doing that. 

I think perhaps adding another logger that's INFO-activated for all distributed processes, and is used only occasionally when the normal logger won't do.

I think as we are getting more and more into distributed training we will need to be able to log specific things for specific processes.

Thank you.

@LysandreJik, @patrickvonplaten, @sgugger 

Comments:
I'm definitely not an expert on logging so I'll leave it to @LysandreJik and @sgugger here. The idea of adding new `multi-process` logging functionality sounds very reasonable to me though!

I would advocate for using the `logger.warning` in cases where you want to display something from all processes. While in the library we should be strict about what we want to display as info/warn/error, I think we can be a bit more flexible and use the logger verbosity differently, as it's actively defined in the scripts. Of course, this is only if you're defining the logs in the script and not in the library, otherwise we'll need to reconsider.

If we don't want to go down this road, we could also have an approach defined on the log levels. We could potentially define additional log levels, between INFO and WARN that could get the job done.



Oh, I like an intermediate level between INFO and WARN, like `IMPORTANT_INFO`? (`ALL_PROCESS_INFO` wouldn't make sense as it would not technically control the number of processes).

I'm talking about the library here, Trainer that is. But, of course, the same should apply to custom scripts.

I think a custom logger is a better idea. In particular since it needs to log the rank of the process - currently I have to add it manually.

I don't think we should mess with levels. These should be sacrosanct. This is because it could make things very confusing for the user.

But being able to retrieve a 2nd logger object that logs for all processes with the format that includes a process rank and using the same log level would be useful. 

Though need to decide whether:
a. Such logger would be not logging anything unless invoked in a distributed environment.
b. Or perhaps it's actually better for it to be identical to the normal logger under non-distributed env, so logs aren't missed - it's just it'll not include process rank.

> I'm talking about the library here, Trainer that is.

The problem is that only Trainer knows when it's executed in a distributed training but logs are in all parts of the library. Though maybe this new logger will only be used inside the `Trainer`?

(Sorry my 3yo made a wrong click.) 

> The problem is that only Trainer knows when it's executed in a distributed training but logs are in all parts of the library. 

Not really. We have `torch.distributed.get_rank()` for most things to know whether we are under distributed, though the logger shouldn't be initialized until first use since the dist env comes a bit later in the game. Down the road if we have other methods that defined multiproc we will just try those too or provide one for a user to run if it's non-standard and it'll set a multi-proc flag in the logging library.

It probably could/should copy the same format from normal logger, but embed process rank into it.

i.e. perhaps it can be created on the fly and require no special handling on the user side (or trainer side).

> Though maybe this new logger will only be used inside the Trainer?

No, user scripts will need it too. It's not trainer-specific. Think `model.parallelize()` `model.enable_pipeline` (new)

And just to clarify - this is for logging inside the model's code - perhaps I will find a way to abstract it out, but it still would be  outside of Trainer and in the core library.

An example of this is building a custom device_map for PP or MP specific to the process and logging that. This would be the same whether it was called from Trainer or user's code.

> (Sorry my 3yo made a wrong click.)

You have competition growing ;)

I have no issues with having a second logger used in multi-process environments. It would be nice if it could be handled by the `logging` class of `transformers`, so as to have a single front-end for the logging, otherwise we'll end up confusing the users as much as if we add intermediate logging levels.

Do we actually need a second logger though, wouldn't it be simpler to adapt the formatter for those particular logs?

> I have no issues with having a second logger used in multi-process environments. It would be nice if it could be handled by the `logging` class of `transformers`, so as to have a single front-end for the logging, [...]

Yes, that is what I had in mind.

> Do we actually need a second logger though, wouldn't it be simpler to adapt the formatter for those particular logs?

Could you please give a example of what you have in mind? 

I have no attachment whatsoever to how this is done. So if you already have an idea on how to make this work I'm all ears.

Thank you.

Ok I gave it more thought and my proposal of using formatters was a mistake, it won't be possible this way. I looked for a solution using filters, but, alas, the logs are already filtered by the levels before they're handled by the filters.

Thinking about it further, I'm not 100% sure how I can see several loggers here as we already have one logger per module. If you know how to do it cleanly, by all means, please do!

---

As an aside, I don't think having intermediate levels is a bad thing. The `logging` utility has an `addLevelName` method, and this specific use-case seems perfect. I understand why adding many different level names will get harder to understand, but this is the addition of one level for a situation that would benefit from it.

It would only require adding a level, which has a name. Here's how it could look like:

```py
import logging
import sys

# Add level > 30
logging.addLevelName(35, "MODEL_PARALLEL_INFO")

# Setup logging like we do in our scripts
logger = logging.getLogger(__name__)
logging.basicConfig(
    format="%(asctime)s - %(levelname)s - %(name)s -   %(message)s",
    datefmt="%m/%d/%Y %H:%M:%S",
    handlers=[logging.StreamHandler(sys.stdout)],
)

for i in range(3):
    # Simulate our scripts' logging
    logger.setLevel(logging.INFO if i == 0 else logging.WARN)

    logger.warning(f"Initiating {i}")
    logger.info("Random information")
    logger.log(logging.getLevelName("MODEL_PARALLEL_INFO"), f"Device Map of {i}: []")
```

This logs the following:

```
02/03/2021 15:40:28 - WARNING - __main__ -   Initiating 0
02/03/2021 15:40:28 - INFO - __main__ -   Random information
02/03/2021 15:40:28 - MODEL_PARALLEL_INFO - __main__ -   Device Map of 0: []
02/03/2021 15:40:28 - WARNING - __main__ -   Initiating 1
02/03/2021 15:40:28 - MODEL_PARALLEL_INFO - __main__ -   Device Map of 1: []
02/03/2021 15:40:28 - WARNING - __main__ -   Initiating 2
02/03/2021 15:40:28 - MODEL_PARALLEL_INFO - __main__ -   Device Map of 2: []
```

Happy to drop the idea if you still think this would make things confusing for the user. I do agree that it could make things confusing for users not making use of the scripts and wondering why an INFO statement slipped when they set their verbosity to `warn`.

I think we can have the intermediate level be intermediate -> so not shown when the verbosity is set to `warn`. I expect the scripts to switch the statement from
```
logger.setLevel(logging.INFO if i == 0 else logging.WARN)
logger.parallel_info(f"Initiating {i}")
```
to
```
logger.setLevel(logging.INFO if i == 0 else logging.MODEL_PARALLEL_INFO)
logger.parallel_info(f"Initiating {i}")
```

I disagree with the name though, as this is a bit too specific ;-) PARALLEL_INFO is enough IMO


To the naming:

Well, PP is too specific - not very generic either.

What we have here is 2 specific events, which may happen under any distributed training. So the common is that it's distributed, the separate is:
1. log only once for multiple processes (avoid duplicated logging)
2. log for every process (only for unique per-process logging)

and single process training is a special case of distributed with n_procs=1, so for a single proc both should be logged.

So I think this is what the name should reflect and not the specific circumstance it's used in.

------------------

To the implementation, thank you for your specific code suggestions @LysandreJik and @sgugger - please let me experiment with your proposals and try other things out and I will come back to you.



Apologies for the delay, here is how I see a simple solution that doesn't break any conventions.

We create a second logger. Just need to think how to make it appear if the user didn't explicitly configure one and make it globally available from other modules.

Here is a possible implementation:
```
# logger.py

import logging
import sys
import os

local_rank = int(os.environ.get("LOCAL_RANK", -1))

# normal logger
logger = logging.getLogger(__name__)
handler_shared = logging.StreamHandler(sys.stdout)
formatter_shared = logging.Formatter('%(asctime)s - %(levelname)s - %(name)s - %(message)s')
handler_shared.setFormatter(formatter_shared)
logger.addHandler(handler_shared)

# rank-specific logger
if local_rank != -1:
    logger_rank_specific = logging.getLogger(__name__ + "rank_specific")
    handler_rank_specific = logging.StreamHandler(sys.stdout)
    formatter_rank_specific = logging.Formatter(f'%(asctime)s - %(levelname)s - p{local_rank} - %(name)s - %(message)s')
    handler_rank_specific.setFormatter(formatter_rank_specific)
    logger_rank_specific.addHandler(handler_rank_specific)
else:
    logger_rank_specific = logger

# the 2nd logger is just for special info that each process should print
logger_rank_specific.setLevel(logging.INFO)
# set normal logger to just the main process INFO
logger.setLevel(logging.INFO if local_rank < 1 else logging.WARN)

# test
logger.warning(f"Initiating")
logger.info("Random information")

logger_rank_specific.info(f"Device Map: {[1] * local_rank}")

```

Dist test:
```
$ python -m torch.distributed.launch --nproc_per_node 4 ./logger.py
2021-02-11 19:57:45,889 - WARNING - __main__ - Initiating
2021-02-11 19:57:45,889 - INFO - __main__ - Random information
2021-02-11 19:57:45,889 - INFO - p0 - __main__rank_specific - Device Map: []
2021-02-11 19:57:45,897 - WARNING - __main__ - Initiating
2021-02-11 19:57:45,898 - INFO - p1 - __main__rank_specific - Device Map: [1]
2021-02-11 19:57:45,905 - WARNING - __main__ - Initiating
2021-02-11 19:57:45,905 - INFO - p2 - __main__rank_specific - Device Map: [1, 1]
2021-02-11 19:57:45,914 - WARNING - __main__ - Initiating
2021-02-11 19:57:45,914 - INFO - p3 - __main__rank_specific - Device Map: [1, 1, 1]
```

Non-dist test:
```
$ python ./logger.py
2021-02-11 20:21:16,716 - WARNING - __main__ - Initiating
2021-02-11 20:21:16,717 - INFO - __main__ - Random information
2021-02-11 20:21:16,717 - INFO - __main__ - Device Map: []
```

All works.

Not sure what to call the second logger, open to suggestions.

What do you think?

Thank you.

I am fine with using a second logger like this, I guess it could be called `multiprocess_logger` and that its name could be `+ "rank_specific"` like you said. Should we add a method `get_multiprocess_logger` in the logging module so that people don't have to remember the `__name__ + "rank_specific"` part? This would give an API like:
```
from .util import logging

logger = logging.get_logger(__name__)
multiprocess_logger = logging.get_multiprocess_logger(__name__)
```
in the modules where we need the `multiprocess_logger`. And the `set_verbosity_xxx` methods would affect both transformers logger.

For the scripts we would still need to do it manually though.

Yes, of course, we will have it all nicely wrapped up. If @LysandreJik is in agreement, I will work on a PR.

It'd be nice to have a somewhat shorter name for `multiprocess_logger`, but the one you proposed works too. Perhaps, in reversed to aid the completion? `logger_multiproc` or `logger_multiprocess` or `logger_mp`?

Also I'm not sure with `__name__ + "rank_specific"` - should it be in sync with the variable name - whichever we choose?

Hmm, what if instead of changing the format for that logger to be
```
logging.Formatter(f'%(asctime)s - %(levelname)s - p{local_rank} - %(name)s - %(message)s')
```
We keep the exact same format, but we simply append the actual rank to the name?
```
logger_rank_specific = logging.getLogger(__name__ + f"local_rank_{local_rank}")
logging.Formatter(f'%(asctime)s - %(levelname)s - %(name)s - %(message)s')
```
But again, either way works. Just one less thing to modify in this case.



Thanks for writing everything out, I'm ok with your proposal!