Skip to content

Commit c686a5e

Browse files
metrics dedup
1 parent ef42f54 commit c686a5e

2 files changed

Lines changed: 113 additions & 13 deletions

File tree

‎composer/loggers/mlflow_logger.py‎

Lines changed: 44 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,8 @@
3434
__all__ = ['MLFlowLogger']
3535

3636
DEFAULT_MLFLOW_EXPERIMENT_NAME = 'my-mlflow-experiment'
37+
LOG_DUPLICATED_METRIC_VALUE_PER_N_STEPS = 100
38+
LOG_DUPLICATED_METRIC_VALUE_PER_N_MILLIS = 600000
3739

3840

3941
class MlflowMonitorProcess(multiprocessing.Process):
@@ -118,6 +120,11 @@ class MLFlowLogger(LoggerDestination):
118120
logging_buffer_seconds (int, optional): The amount of time, in seconds, that MLflow
119121
waits before sending logs to the MLflow tracking server. Metrics/params/tags logged
120122
within this buffer time will be grouped in batches before being sent to the backend.
123+
log_duplicated_metric_every_n_steps (int, optional): The number of steps to wait before
124+
logging the duplicated metric value. Duplicated metric value means the new step has the
125+
same value as the previous step. (default: ``100``)
126+
log_duplicated_metric_every_n_millis (int, optional): The number of milliseconds to wait
127+
before logging the duplicated metric value. (default: ``600000``)
121128
"""
122129

123130
def __init__(
@@ -138,6 +145,8 @@ def __init__(
138145
run_group: Optional[str] = None,
139146
resume: bool = False,
140147
logging_buffer_seconds: Optional[int] = 10,
148+
log_duplicated_metric_every_n_steps: int = 100,
149+
log_duplicated_metric_every_n_millis: int = 600000,
141150
) -> None:
142151
try:
143152
import mlflow
@@ -179,6 +188,10 @@ def __init__(
179188
mlflow.set_system_metrics_samples_before_logging(6)
180189
mlflow.set_system_metrics_sampling_interval(5)
181190

191+
self.log_duplicated_metric_every_n_steps = log_duplicated_metric_every_n_steps
192+
self.log_duplicated_metric_every_n_millis = log_duplicated_metric_every_n_millis
193+
self._metrics_cache = {}
194+
182195
self._rank_zero_only = rank_zero_only
183196
self._last_flush_time = time.time()
184197
self._flush_interval = flush_interval
@@ -385,18 +398,37 @@ def rename(self, key: str):
385398
def log_metrics(self, metrics: dict[str, Any], step: Optional[int] = None) -> None:
386399
from mlflow import log_metrics
387400

388-
if self._enabled:
389-
# Convert all metrics to floats to placate mlflow.
390-
metrics = {
391-
self.rename(k): float(v)
392-
for k, v in metrics.items()
393-
if not any(fnmatch.fnmatch(k, pattern) for pattern in self.ignore_metrics)
394-
}
395-
log_metrics(
396-
metrics=metrics,
397-
step=step,
398-
synchronous=self.synchronous,
399-
)
401+
if not self._enabled:
402+
return
403+
404+
metrics_to_log = {}
405+
step = step or 0
406+
current_time_millis = int(time.time() * 1000)
407+
for k, v in metrics.items():
408+
if any(fnmatch.fnmatch(k, pattern) for pattern in self.ignore_metrics):
409+
continue
410+
if k in self._metrics_cache:
411+
value, last_step, last_time = self._metrics_cache[k]
412+
if value == v and step < last_step + self.log_duplicated_metric_every_n_steps and current_time_millis < last_time + self.log_duplicated_metric_every_n_millis:
413+
# Skip logging the metric if it has the same value as the last step and it's
414+
# within the step and time window.
415+
continue
416+
else:
417+
# Log the metric if it has a different value or it's outside the step and time
418+
# window, and update the metrics cache.
419+
self._metrics_cache[k] = (v, step, current_time_millis)
420+
metrics_to_log[self.rename(k)] = float(v)
421+
else:
422+
# Log the metric if it's the first time it's being logged, and update the metrics
423+
# cache.
424+
self._metrics_cache[k] = (v, step, current_time_millis)
425+
metrics_to_log[self.rename(k)] = float(v)
426+
427+
log_metrics(
428+
metrics=metrics_to_log,
429+
step=step,
430+
synchronous=self.synchronous,
431+
)
400432

401433
def log_hyperparameters(self, hyperparameters: dict[str, Any]):
402434
from mlflow import log_params

‎tests/loggers/test_mlflow_logger.py‎

Lines changed: 69 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,10 @@
1919
from tests.common.datasets import RandomClassificationDataset, RandomImageDataset
2020
from tests.common.markers import device
2121
from tests.common.models import SimpleConvModel, SimpleModel
22-
from tests.models.test_hf_model import check_hf_model_equivalence, check_hf_tokenizer_equivalence
22+
from tests.models.test_hf_model import (
23+
check_hf_model_equivalence,
24+
check_hf_tokenizer_equivalence,
25+
)
2326

2427

2528
def _get_latest_mlflow_run(experiment_name, tracking_uri=None):
@@ -836,6 +839,71 @@ def test_mlflow_logging_time_buffer(tmp_path):
836839
assert len(mock_log_batch.call_args_list[1][1]['metrics']) == 2 * steps
837840

838841

842+
def test_mlflow_logging_with_metrics_dedupping(tmp_path):
843+
with patch('mlflow.log_metrics') as mock_log_metrics:
844+
845+
mlflow_uri = tmp_path / Path('my-test-mlflow-uri')
846+
experiment_name = 'mlflow_logging_test'
847+
mock_state = MagicMock()
848+
mock_logger = MagicMock()
849+
850+
test_mlflow_logger = MLFlowLogger(
851+
tracking_uri=mlflow_uri,
852+
experiment_name=experiment_name,
853+
log_system_metrics=True,
854+
run_name='test_run',
855+
logging_buffer_seconds=2,
856+
log_duplicated_metric_every_n_steps=3,
857+
log_duplicated_metric_every_n_millis=10000,
858+
)
859+
test_mlflow_logger.init(state=mock_state, logger=mock_logger)
860+
# # Test dedupping of metrics and duplicated metrics get logged per
861+
# # `log_duplicated_metric_every_n_steps` steps.
862+
# steps = 10
863+
# for i in range(steps):
864+
# # 'foo' always have different values, while 'bar' always have the same value.
865+
# metrics = {
866+
# 'foo': i,
867+
# 'bar': 0,
868+
# }
869+
# test_mlflow_logger.log_metrics(metrics, step=i)
870+
871+
# if i % 3 == 0:
872+
# # 'bar' will be logged every 3 steps.
873+
# mock_log_metrics.assert_called_with(metrics={'foo': float(i), 'bar': 0.0}, step=i, synchronous=False)
874+
# else:
875+
# # 'bar' will not be logged.
876+
# mock_log_metrics.assert_called_with(metrics={'foo': float(i)}, step=i, synchronous=False)
877+
878+
# Test dedupping of metrics and duplicated metrics get logged per
879+
# `log_duplicated_metric_every_n_millis` milliseconds.
880+
timestamps = [0, 5, 10, 15, 20, 25, 30, 35, 40, 45]
881+
# Reset the metrics cache.
882+
test_mlflow_logger._metrics_cache = {}
883+
with patch('time.time', side_effect=timestamps):
884+
for i in range(len(timestamps)):
885+
# 'foo' always have different values, while 'bar' always have the same value.
886+
metrics = {
887+
'foo': i,
888+
'bar': 0,
889+
}
890+
test_mlflow_logger.log_metrics(metrics, step=0)
891+
892+
if i % 2 == 0:
893+
# 'bar' will be logged every 2 steps.
894+
mock_log_metrics.assert_called_with(
895+
metrics={
896+
'foo': float(i),
897+
'bar': 0.0,
898+
}, step=0, synchronous=False,
899+
)
900+
else:
901+
# 'bar' will not be logged.
902+
mock_log_metrics.assert_called_with(metrics={'foo': float(i)}, step=0, synchronous=False)
903+
904+
test_mlflow_logger.post_close()
905+
906+
839907
def test_mlflow_resume_run(tmp_path):
840908
mlflow = pytest.importorskip('mlflow')
841909

0 commit comments

Comments
 (0)