Skip to content

Commit 2a5ff23

Browse files
committed
fix: log the convenience epoch metric once per step (#20902)
At an epoch boundary several metric groups are flushed at the same step (the training-epoch-end flush, the validation-end flush, and the last train-step flush). Each `step=None` flush re-stamped the convenience `epoch` metric via `setdefault`, so loggers that keep per-call history (e.g. MLflow) recorded two `epoch` datapoints per epoch and misaligned epoch-based x-axes. Track the last `(step, epoch)` for which the convenience `epoch` metric was auto-added and skip re-adding it at the same step. The key is `(step, epoch)` (not `step` alone) so an epoch that advances without an optimizer step (e.g. under gradient accumulation) is still recorded. The tracker is reset per run so a fresh fit/validate/test re-emits `epoch`. Step-indexed loggers (TensorBoard, CSV) are unaffected because they merge by step. Update the logger-history assertions in test_all.py, test_logger_connector.py, and the train/eval loop logging tests to expect the single-`epoch`-per-step behavior, and add a focused regression test.
1 parent 4819088 commit 2a5ff23

6 files changed

Lines changed: 82 additions & 9 deletions

File tree

src/lightning/pytorch/CHANGELOG.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,8 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/).
2424

2525
### Fixed
2626

27+
- Fixed the convenience `epoch` metric being logged twice at the same step (once per metric group flushed at an epoch boundary), which produced duplicate `epoch` datapoints and misaligned epoch-based x-axes in loggers that keep per-call history such as MLflow ([#20902](https://github.com/Lightning-AI/pytorch-lightning/issues/20902))
28+
2729
- Fixed PyTorch Lightning profiler not capturing dataloader worker initialization time ([#21771](https://github.com/Lightning-AI/pytorch-lightning/issues/21771))
2830

2931
- Fixed `FSDPStrategy` raising `RuntimeError` under PyTorch 2.5+ when `root_device` is CPU, by passing an explicit `torch.device("cpu")` instead of `device_id=None` (relevant only when the GPU-accelerator guard is bypassed) ([#21774](https://github.com/Lightning-AI/pytorch-lightning/pull/21774))

src/lightning/pytorch/trainer/connectors/logger_connector/logger_connector.py

Lines changed: 16 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,9 @@ def __init__(self, trainer: "pl.Trainer") -> None:
3838
self._current_fx: Optional[str] = None
3939
# None: hasn't started, True: first loop iteration, False: subsequent iterations
4040
self._first_loop_iter: Optional[bool] = None
41+
# tracks the last ``(step, epoch)`` for which the convenience ``epoch`` metric was
42+
# auto-added, so it is not logged more than once at the same step (see ``log_metrics``)
43+
self._logged_epoch_step: Optional[tuple[int, int]] = None
4144

4245
def on_trainer_init(
4346
self,
@@ -121,9 +124,17 @@ def log_metrics(self, metrics: _OUT_DICT, step: Optional[int] = None) -> None:
121124
if step_metric is not None:
122125
step = int(step_metric)
123126
else:
124-
# added metrics for convenience
125-
scalar_metrics.setdefault("epoch", self.trainer.current_epoch)
126127
step = self.trainer.fit_loop.epoch_loop._batches_that_stepped
128+
# add the convenience `epoch` metric, but only once per `(step, epoch)`.
129+
# Several metric groups can be flushed at the same step (e.g. the
130+
# training-epoch-end and validation-end flushes), and stamping `epoch` on
131+
# each of them makes loggers that keep per-call history (e.g. MLflow) record
132+
# duplicate `epoch` datapoints per epoch, misaligning epoch-based x-axes (#20902).
133+
if "epoch" not in scalar_metrics:
134+
current_epoch = self.trainer.current_epoch
135+
if self._logged_epoch_step != (step, current_epoch):
136+
scalar_metrics["epoch"] = current_epoch
137+
self._logged_epoch_step = (step, current_epoch)
127138

128139
# log actual metrics
129140
for logger in self.trainer.loggers:
@@ -230,6 +241,9 @@ def reset_metrics(self) -> None:
230241
self._progress_bar_metrics = {}
231242
self._logged_metrics = {}
232243
self._callback_metrics = {}
244+
# reset per-run so the convenience `epoch` metric is re-emitted at the start of a
245+
# fresh fit/validate/test run (this is called per-run, not per-epoch)
246+
self._logged_epoch_step = None
233247

234248
def reset_results(self) -> None:
235249
results = self.trainer._results

tests/tests_pytorch/loggers/test_all.py

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -125,14 +125,18 @@ def log_metrics(self, metrics, step):
125125
if logger_class == TensorBoardLogger:
126126
expected = [
127127
(0, ["epoch", "train_some_val"]),
128-
(0, ["early_stop_on", "epoch", "val_loss"]),
128+
# the convenience `epoch` metric is only stamped on the first flush at a
129+
# given step, so the validation-end flush at step 0 no longer repeats it (#20902)
130+
(0, ["early_stop_on", "val_loss"]),
129131
(1, ["epoch", "test_loss"]),
130132
]
131133
assert log_metric_names == expected
132134
else:
133135
expected = [
134136
(0, ["epoch", "train_some_val"]),
135-
(0, ["early_stop_on", "epoch", "val_loss"]),
137+
# the convenience `epoch` metric is only stamped on the first flush at a
138+
# given step, so the validation-end flush at step 0 no longer repeats it (#20902)
139+
(0, ["early_stop_on", "val_loss"]),
136140
(1, ["epoch", "test_loss"]),
137141
]
138142
assert log_metric_names == expected

tests/tests_pytorch/trainer/connectors/test_logger_connector.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -58,4 +58,5 @@ def test_uses_batches_that_stepped(mock_convert):
5858
metrics=mock_convert.return_value, step=trainer.fit_loop.epoch_loop._batches_that_stepped
5959
)
6060
logger.save.assert_called_once_with()
61-
mock_convert.return_value.setdefault.assert_called_once_with("epoch", trainer.current_epoch)
61+
# the convenience `epoch` metric is added once per `(step, epoch)` (see #20902)
62+
mock_convert.return_value.__setitem__.assert_called_once_with("epoch", trainer.current_epoch)

tests/tests_pytorch/trainer/logging_/test_eval_loop_logging.py

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -543,16 +543,18 @@ def test_step(self, batch, batch_idx):
543543
"valid_loss_0",
544544
"valid_loss_1",
545545
}
546+
# the validation-end flush shares a step with the earlier train flush, so it no longer
547+
# re-emits a duplicate `epoch` (which the train flush already stamped) — see #20902.
546548
assert mock_log_metrics.mock_calls == [
547549
call({"hp_metric": -1}, None),
548550
call(metrics={"train_loss": ANY, "epoch": 0}, step=0),
549551
call(metrics={"valid_loss_0_step": ANY, "valid_loss_2": ANY}, step=0),
550552
call(metrics={"valid_loss_0_step": ANY, "valid_loss_2": ANY}, step=1),
551-
call(metrics={"valid_loss_0_epoch": ANY, "valid_loss_1": ANY, "epoch": 0}, step=0),
553+
call(metrics={"valid_loss_0_epoch": ANY, "valid_loss_1": ANY}, step=0),
552554
call(metrics={"train_loss": ANY, "epoch": 1}, step=1),
553555
call(metrics={"valid_loss_0_step": ANY, "valid_loss_2": ANY}, step=2),
554556
call(metrics={"valid_loss_0_step": ANY, "valid_loss_2": ANY}, step=3),
555-
call(metrics={"valid_loss_0_epoch": ANY, "valid_loss_1": ANY, "epoch": 1}, step=1),
557+
call(metrics={"valid_loss_0_epoch": ANY, "valid_loss_1": ANY}, step=1),
556558
]
557559

558560
def get_metrics_at_idx(idx):

tests/tests_pytorch/trainer/logging_/test_train_loop_logging.py

Lines changed: 52 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -733,16 +733,66 @@ def training_step(self, batch, batch_idx):
733733
)
734734
trainer.fit(model)
735735

736+
# `epoch` is stamped once per step: the epoch-end flush that shares a step with the
737+
# last step-level flush no longer re-emits a duplicate `epoch` (see #20902).
736738
mock_log_metrics.assert_has_calls([
737739
call(metrics={"foo_step": 0.0, "epoch": 0}, step=0),
738740
call(metrics={"foo_step": 0.0, "epoch": 0}, step=1),
739-
call(metrics={"foo_epoch": 0.0, "epoch": 0}, step=1),
741+
call(metrics={"foo_epoch": 0.0}, step=1),
740742
call(metrics={"foo_step": 0.0, "epoch": 1}, step=2),
741743
call(metrics={"foo_step": 0.0, "epoch": 1}, step=3),
742-
call(metrics={"foo_epoch": 0.0, "epoch": 1}, step=3),
744+
call(metrics={"foo_epoch": 0.0}, step=3),
743745
])
744746

745747

748+
@mock.patch("lightning.pytorch.loggers.TensorBoardLogger.log_metrics")
749+
def test_log_metrics_no_duplicate_epoch_per_step(mock_log_metrics, tmp_path):
750+
"""The convenience ``epoch`` metric must be logged at most once per step.
751+
752+
Regression test for https://github.com/Lightning-AI/pytorch-lightning/issues/20902: the
753+
training-epoch-end and validation-end flushes share a step, and stamping ``epoch`` on both
754+
produced duplicate ``epoch`` datapoints (rendered as two points per epoch in e.g. MLflow).
755+
756+
"""
757+
758+
class MyModel(BoringModel):
759+
def training_step(self, batch, batch_idx):
760+
self.log("train_metric", 1.0, on_step=False, on_epoch=True)
761+
return super().training_step(batch, batch_idx)
762+
763+
def validation_step(self, batch, batch_idx):
764+
self.log("val_metric", 2.0, on_step=False, on_epoch=True)
765+
return super().validation_step(batch, batch_idx)
766+
767+
trainer = Trainer(
768+
default_root_dir=tmp_path,
769+
limit_train_batches=2,
770+
limit_val_batches=2,
771+
max_epochs=2,
772+
log_every_n_steps=1,
773+
enable_model_summary=False,
774+
enable_checkpointing=False,
775+
enable_progress_bar=False,
776+
logger=TensorBoardLogger(tmp_path),
777+
)
778+
trainer.fit(MyModel())
779+
780+
# count, per step, how many logged batches carried an `epoch` value
781+
epoch_counts = collections.Counter()
782+
for logged in mock_log_metrics.call_args_list:
783+
metrics = logged.kwargs.get("metrics")
784+
if metrics is None and logged.args:
785+
metrics = logged.args[0]
786+
step = logged.kwargs.get("step")
787+
if step is None and len(logged.args) > 1:
788+
step = logged.args[1]
789+
if metrics and "epoch" in metrics:
790+
epoch_counts[step] += 1
791+
792+
assert epoch_counts, "expected `epoch` to be logged at least once"
793+
assert all(count == 1 for count in epoch_counts.values()), epoch_counts
794+
795+
746796
@mock.patch("lightning.pytorch.loggers.TensorBoardLogger.log_metrics")
747797
def test_log_on_train_start(mock_log_metrics, tmp_path):
748798
"""Tests that logged metrics on_train_start get reset after the first epoch."""

0 commit comments

Comments
 (0)