How to print the metric (across all working trainer in DDP mode) into console after each epoch is end?

[rudaoshi]

❓ Questions and Help

What is your question?

How to print the metric (across all working trainer in DDP mode) into console after each epoch is end?

When I run the program in a remote cluster, it is not convinent to use tensorboard to view the log.

Code

What have you tried?

First, I want to find a hook called after the metrics are gathered through multiple workers, but I'm not able to find it.
Callbacks are supposed to be designed to solve similar problem. But I do not know which one is the correct entry.
I've tried on_validation_epoch_end, on_validation_end, both print a message in each worker.

Second, about to produce the logging message, I tried logging and getLoger, notworking. I tried print, it works. But I still want to use logging. Any suggestions?

What's your environment?

• OS: [e.g. iOS, Linux, Win] Mac
• Packaging [e.g. pip, conda] pip
• Version [e.g. 0.5.2.1] 1.1.8

[rudaoshi]

I noticed that in on_validation_end, the metrics seem been synced and are same accorss workers.

Then the problem becomes that how can I check whether I'm in the main/first process so that I can just print one log.

There is another issue: the on_train_end seems never been called, while on_validation_end called in the end of each epoch.

[awaelchli]

For example:

# in LightningModule
self.log("metric", metric, on_epoch=True, prog_bar=True, sync_dist=True)

if self.global_rank == 0:
    # do something only on main process

[rudaoshi]

Thank you for your help!

[rudaoshi]

There is one problem left:

How can I use logging module (or other logger module) to log debug message or log information in callbacks ?

They seems not working. Only print can print message to the console, which is not full functional logger.

[awaelchli]

In the callback, you can simply call "pl_module.log(...)".
For logging debug messages, I can recommend the built in Python logging module and setting the level to logging.DEBUG or INFO.

[rudaoshi]

Thank you for your help.

logging.info(...) works in the callback, but pl_module.log(...) is not working. It says that pl_module.log(...) not permit in on_validation_end .

[awaelchli]

Try on_validation_epoch_end instead of on_validation_end
A concrete example of what you want to achieve would be great (code snippet).

[rudaoshi]

Thank you very much for your nice help. @awaelchli

I'm still struggling to obtain epoch-wise performance logging to screen.

Here is my current code and the problem.
I've asked a question containing my current code here: #6352 , but currently no answers.

The validation_step in trainer:

    def validation_step(self, batch, batch_idx, data_loader_idx):

        output = self.machine.forward(batch, outputs="both")
        loss = self.loss(output, batch)
        self.log("dev_loss", loss, on_step=False, on_epoch=True, prog_bar=False, sync_dist=True)

        metric = self.problem_evaluator_dev(output, batch)
        self.log_dict(dict(("dev_" + k, v) for k, v in metric.items()),
                          on_step=False, on_epoch=True,
                          prog_bar=False, sync_dist=True)
        return {"loss": loss}

the on_validation_end in the callback:

def on_validation_end(self, trainer, pl_module):

        if pl_module.global_rank == 0:
            logging.info("Dev: " + str(pl_module.problem_evaluator_dev.compute()))

and it print a log:

INFO:root:Dev: {'unlabel.Precision': tensor(0.7071, device='cuda:0'), 'unlabel.Recall': tensor(0.7551, device='cuda:0'), 'unlabel.FBeta': tensor(0.7303, device='cuda:0'), 'label.Precision': tensor(0.7323, device='cuda:0'), 'label.Recall': tensor(0.7323, device='cuda:0'), 'label.FBeta': tensor(0.7323, device='cuda:0'), 'unlabel_graph_accuracy': tensor(0.3521, device='cuda:0'), 'label_graph_accuracy': tensor(0.3287, device='cuda:0')}

Following the log, the checkpoint callback print a log:

Epoch 1, global step 1567: dev_label.FBeta/dataloader_idx_0 reached 0.81325 (best 0.81325), saving model to ".../lightning_logs/version_21/checkpoints/epoch=1-step=1567.ckpt" as top 1

where the "dataloader_idx_0" is corresponding to the problem_evaluator_dev, so the printed value should be same.

I used pytorch_lightning version 1.1.8. So may be compute reset something? I read the code of checkpointcallback, but cannot figure out how it get and compare the metric.

I aslo tried direcly get the metric value from trainer.callback_metrics:

    def on_validation_end(self, trainer, pl_module) -> None:

        if trainer.running_sanity_check:
            return
        metrics_dict = deepcopy(trainer.callback_metrics)
        logger.warning("Dev: " + str(metrics_dict))

However, the value is not synced between ddp training processes.

I donot use the prog_bar option because there are too many metric and can not show in one line. In some enviroment, the progress bar is shortened so I cannot read them all.

Thank you again for your nice help!

BTW: I think the sync mechanism in ddp is rather confusing, especially for new users. If there is some callbacks like on_metric_synced, it would be much helpful.

[rudaoshi]

There is another related question:

We initialize the metric by compute_on_step=True, so in each step, the compute() is called, and the "state variables" had been "synchronized across the distributed backend".

So the metric should be synced and always same accross the distributed backend.

But why the phenomenon in the previous post happen?

[SkafteNicki]

@rudaoshi the metric is only synchronized at each step when dist_sync_on_step=True. compute_on_step=True just indicates that the metric should be returned for the current batch.
Also since metrics have build in synchronization you should not log them using sync_dist=True.
In general I would recommend logging the metric objects directly (so logging self.log(self.metric,...) instead of self.log(self.metric.compute(),...), as lightning will then take care of this for you.

[stale]

This issue has been automatically marked as stale because it hasn't had any recent activity. This issue will be closed in 7 days if no further activity occurs. Thank you for your contributions, Pytorch Lightning Team!