From 0bb27c7de12e2f2aaac33215b733779b9bfd0362 Mon Sep 17 00:00:00 2001 From: Kotresh HR Date: Wed, 15 Jul 2026 12:58:49 +0530 Subject: [PATCH 1/4] tools/cephfs-mirror: report epoch time in last snap sync time Store sync completion time (last_synced_snap.sync_time_stamp) as utime_t (Unix epoch) instead of coarse monotonic time so the metric is meaningful to operators. Fixes: https://tracker.ceph.com/issues/76506 Signed-off-by: Kotresh HR --- doc/cephfs/cephfs-mirroring.rst | 13 +++++------ doc/dev/cephfs-mirroring.rst | 4 ++-- src/tools/cephfs_mirror/PeerReplayer.cc | 30 +++++++++---------------- src/tools/cephfs_mirror/PeerReplayer.h | 8 ++++--- 4 files changed, 23 insertions(+), 32 deletions(-) diff --git a/doc/cephfs/cephfs-mirroring.rst b/doc/cephfs/cephfs-mirroring.rst index 90e6ab309ae..c69d2c6b6d7 100644 --- a/doc/cephfs/cephfs-mirroring.rst +++ b/doc/cephfs/cephfs-mirroring.rst @@ -660,7 +660,7 @@ command parameter is of format ``filesystem-name@filesystem-id peer-uuid``:: "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "33s", - "sync_time_stamp": "274900.558797s", + "sync_time_stamp": "1784150400.558797s", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, @@ -752,9 +752,8 @@ Timestamp Field: ``sync_time_stamp``. -Monotonic clock time in seconds (since daemon startup) when the snapshot sync finished, -printed with sub-second precision and an ``s`` suffix (for example, ``274900.558797s``). This -is not a wall-clock or epoch timestamp. +Unix epoch time in seconds when the snapshot sync finished, printed with +sub-second precision and an ``s`` suffix (for example, ``1784150400.558797s``). ``snaps_synced``, ``snaps_deleted``, and ``snaps_renamed`` are :ref:`per-session counters`: they count @@ -923,7 +922,7 @@ E.g., adding a regular file for synchronization would result in failed status:: "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "44s", - "sync_time_stamp": "500900.600797s", + "sync_time_stamp": "1784150733.600797s", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, @@ -972,7 +971,7 @@ In the remote filesystem:: "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "33s", - "sync_time_stamp": "274900.558797s", + "sync_time_stamp": "1784150400.558797s", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, @@ -1227,7 +1226,7 @@ Counters are not updated on every file read or write. Behavior differs by field - Durations in seconds; bytes are raw counts * - ``last_sync_timestamp`` - ``last_synced_snap.sync_time_stamp`` - - ``utime_t`` (seconds since epoch), not the monotonic string shown in admin JSON + - ``utime_t`` (seconds since epoch); same wall-clock value as admin JSON * - ``snaps_synced`` / ``snaps_deleted`` / ``snaps_renamed`` - Same field names at directory level - Reset on daemon restart or directory reassignment (same as admin socket) diff --git a/doc/dev/cephfs-mirroring.rst b/doc/dev/cephfs-mirroring.rst index 368aafc367f..a219dc95259 100644 --- a/doc/dev/cephfs-mirroring.rst +++ b/doc/dev/cephfs-mirroring.rst @@ -444,7 +444,7 @@ status. Commands of this kind take the form ``filesystem-name@filesystem-id peer "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "33s", - "sync_time_stamp": "274900.558797s", + "sync_time_stamp": "1784150400.558797s", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, @@ -548,7 +548,7 @@ status: "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "33s", - "sync_time_stamp": "274900.558797s", + "sync_time_stamp": "1784150400.558797s", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, diff --git a/src/tools/cephfs_mirror/PeerReplayer.cc b/src/tools/cephfs_mirror/PeerReplayer.cc index 8cb8dbdd183..09543a53a01 100644 --- a/src/tools/cephfs_mirror/PeerReplayer.cc +++ b/src/tools/cephfs_mirror/PeerReplayer.cc @@ -122,15 +122,6 @@ bool get_json_value(const json_spirit::mObject& obj, return false; } -double monotime_to_double(monotime t) { - return sec_duration(t.time_since_epoch()).count(); -} - -monotime monotime_from_double(double seconds) { - auto d = std::chrono::duration_cast(sec_duration(seconds)); - return monotime(d); -} - struct C_PersistSyncStatAio : Context { std::string dir_root; @@ -543,13 +534,7 @@ void PeerReplayer::update_directory_last_sync_perf_counters( sync_stat.last_sync_duration ? static_cast(*sync_stat.last_sync_duration) : 0); - utime_t t; - if (!clock::is_zero(sync_stat.last_synced)) { - t.set_from_double(monotime_to_double(sync_stat.last_synced)); - } else { - t = utime_t(); - } - perf->tset(l_cephfs_mirror_directory_last_sync_timestamp, t); + perf->tset(l_cephfs_mirror_directory_last_sync_timestamp, sync_stat.last_synced); perf->set(l_cephfs_mirror_directory_last_sync_bytes, sync_stat.last_sync_bytes ? *sync_stat.last_sync_bytes : 0); @@ -837,7 +822,7 @@ void PeerReplayer::apply_persisted_dir_sync_stat(SnapSyncStat &sync_stat, sync_stat.last_sync_duration = v.get_real(); } if (get_json_value(last_synced_snap, "sync_time_stamp", &v)) { - sync_stat.last_synced = monotime_from_double(v.get_real()); + sync_stat.last_synced.set_from_double(v.get_real()); } if (get_json_value(last_synced_snap, "sync_bytes", &v)) { sync_stat.last_sync_bytes = v.get_uint64(); @@ -1082,9 +1067,9 @@ void PeerReplayer::add_last_sync_metrics_to_persist(json_spirit::mObject &obj, if (sync_stat.last_sync_duration) { snap["sync_duration"] = json_spirit::mValue(*sync_stat.last_sync_duration); } - if (!clock::is_zero(sync_stat.last_synced)) { + if (!sync_stat.last_synced.is_zero()) { snap["sync_time_stamp"] = - json_spirit::mValue(monotime_to_double(sync_stat.last_synced)); + json_spirit::mValue(static_cast(sync_stat.last_synced)); } if (sync_stat.last_sync_bytes) { snap["sync_bytes"] = @@ -3829,7 +3814,12 @@ void PeerReplayer::dump_sync_stat(Formatter *f, const SnapSyncStat &sync_stat) { } if (sync_stat.last_sync_duration) { f->dump_string("sync_duration", format_time(*sync_stat.last_sync_duration)); - f->dump_stream("sync_time_stamp") << sync_stat.last_synced; + } + if (!sync_stat.last_synced.is_zero()) { + std::ostringstream os; + os << std::fixed << std::setprecision(6) + << static_cast(sync_stat.last_synced); + f->dump_string("sync_time_stamp", os.str() + "s"); } if (sync_stat.last_sync_bytes) { f->dump_string("sync_bytes", format_bytes(*sync_stat.last_sync_bytes)); diff --git a/src/tools/cephfs_mirror/PeerReplayer.h b/src/tools/cephfs_mirror/PeerReplayer.h index 0a12fe87d25..672422fa8e6 100644 --- a/src/tools/cephfs_mirror/PeerReplayer.h +++ b/src/tools/cephfs_mirror/PeerReplayer.h @@ -4,8 +4,10 @@ #ifndef CEPHFS_MIRROR_PEER_REPLAYER_H #define CEPHFS_MIRROR_PEER_REPLAYER_H +#include "common/Clock.h" #include "common/Formatter.h" #include "common/Thread.h" +#include "include/utime.h" #include "mds/FSMap.h" #include "ServiceDaemon.h" #include "Types.h" @@ -410,7 +412,7 @@ private: uint64_t synced_snap_count = 0; uint64_t deleted_snap_count = 0; uint64_t renamed_snap_count = 0; - monotime last_synced = clock::zero(); + utime_t last_synced; boost::optional last_sync_duration; boost::optional last_sync_crawl_duration; boost::optional last_sync_datasync_queue_wait_duration; @@ -469,7 +471,7 @@ private: void _reset_last_synced_snap_stat(const std::string &dir_root) { auto &sync_stat = m_snap_sync_stats.at(dir_root); - sync_stat.last_synced = clock::zero(); + sync_stat.last_synced = utime_t(); sync_stat.last_sync_duration.reset(); sync_stat.last_sync_crawl_duration.reset(); sync_stat.last_sync_datasync_queue_wait_duration.reset(); @@ -563,7 +565,7 @@ private: std::scoped_lock locker(m_lock); _set_last_synced_snap(dir_root, snap_id, snap_name); auto &sync_stat = m_snap_sync_stats.at(dir_root); - sync_stat.last_synced = clock::now(); + sync_stat.last_synced = ceph_clock_now(); sync_stat.last_sync_duration = duration; sync_stat.last_sync_crawl_duration = sync_stat.crawl_duration; //For empty snapshot sync, datasync_queue_wait_duration is 0 From f6d85aad99cfcbd3fc71ebd73e4fac26326e28f2 Mon Sep 17 00:00:00 2001 From: Kotresh HR Date: Thu, 23 Jul 2026 17:06:46 +0530 Subject: [PATCH 2/4] cephfs_mirror: format sync timestamps as ISO-8601 local time Show sync_time_stamp and metrics_updated_at as human-readable local timestamps in peer_status and mgr status. Keep epoch in omap and counter dump. Fixes: https://tracker.ceph.com/issues/76506 Signed-off-by: Kotresh HR --- src/pybind/mgr/mirroring/fs/metrics/format.py | 11 +++++++++-- src/tools/cephfs_mirror/PeerReplayer.cc | 6 ++---- 2 files changed, 11 insertions(+), 6 deletions(-) diff --git a/src/pybind/mgr/mirroring/fs/metrics/format.py b/src/pybind/mgr/mirroring/fs/metrics/format.py index 943eeb14e2c..6ef0b8089f8 100644 --- a/src/pybind/mgr/mirroring/fs/metrics/format.py +++ b/src/pybind/mgr/mirroring/fs/metrics/format.py @@ -1,3 +1,6 @@ +from ..checkpoint import format_epoch_timestamp + + def default_sync_stat_metrics(): return { 'state': 'idle', @@ -134,8 +137,8 @@ def format_and_order_sync_stat_for_display(stat, policy=None, dir_path=None, if isinstance(sync_bytes, (int, float)): snap['sync_bytes'] = _format_bytes(sync_bytes) sync_time_stamp = snap.get('sync_time_stamp') - if isinstance(sync_time_stamp, (int, float)): - snap['sync_time_stamp'] = f'{sync_time_stamp:.6f}s' + if isinstance(sync_time_stamp, (int, float, str)): + snap['sync_time_stamp'] = format_epoch_timestamp(sync_time_stamp) out['last_synced_snap'] = _order_dict( snap, ('id', 'name', 'crawl_duration', 'datasync_queue_wait_duration', 'sync_duration', @@ -146,6 +149,10 @@ def format_and_order_sync_stat_for_display(stat, policy=None, dir_path=None, out['current_syncing_snap'] = _order_current_syncing_snap( current_syncing_snap) + metrics_updated_at = out.get('metrics_updated_at') + if isinstance(metrics_updated_at, (int, float, str)): + out['metrics_updated_at'] = format_epoch_timestamp(metrics_updated_at) + out.pop('_instance_id', None) return _order_dict( diff --git a/src/tools/cephfs_mirror/PeerReplayer.cc b/src/tools/cephfs_mirror/PeerReplayer.cc index 09543a53a01..50497cf3535 100644 --- a/src/tools/cephfs_mirror/PeerReplayer.cc +++ b/src/tools/cephfs_mirror/PeerReplayer.cc @@ -3816,10 +3816,8 @@ void PeerReplayer::dump_sync_stat(Formatter *f, const SnapSyncStat &sync_stat) { f->dump_string("sync_duration", format_time(*sync_stat.last_sync_duration)); } if (!sync_stat.last_synced.is_zero()) { - std::ostringstream os; - os << std::fixed << std::setprecision(6) - << static_cast(sync_stat.last_synced); - f->dump_string("sync_time_stamp", os.str() + "s"); + // ISO-8601 local time with offset (matches utime_t::localtime / mgr format) + f->dump_string("sync_time_stamp", stringify(sync_stat.last_synced)); } if (sync_stat.last_sync_bytes) { f->dump_string("sync_bytes", format_bytes(*sync_stat.last_sync_bytes)); From 10e008aaca509b5f84e215fe99c41f6d12bb1f08 Mon Sep 17 00:00:00 2001 From: Kotresh HR Date: Thu, 23 Jul 2026 17:14:52 +0530 Subject: [PATCH 3/4] doc/cephfs-mirroring: document ISO-8601 sync timestamps Fixes: https://tracker.ceph.com/issues/76506 Signed-off-by: Kotresh HR --- doc/cephfs/cephfs-mirroring.rst | 20 ++++++++++++-------- doc/dev/cephfs-mirroring.rst | 4 ++-- 2 files changed, 14 insertions(+), 10 deletions(-) diff --git a/doc/cephfs/cephfs-mirroring.rst b/doc/cephfs/cephfs-mirroring.rst index c69d2c6b6d7..00313fa704d 100644 --- a/doc/cephfs/cephfs-mirroring.rst +++ b/doc/cephfs/cephfs-mirroring.rst @@ -376,7 +376,7 @@ values until the new owning daemon writes an updated entry. * - ``metrics_updated_at`` - Yes - No - - Wall-clock time of the last omap write; exposed only by + - Wall-clock time of the last omap write (ISO-8601 in mgr CLI); exposed only by ``ceph fs snapshot mirror status`` (not ``fs mirror peer status``) **Omap cleanup** @@ -660,7 +660,7 @@ command parameter is of format ``filesystem-name@filesystem-id peer-uuid``:: "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "33s", - "sync_time_stamp": "1784150400.558797s", + "sync_time_stamp": "2026-07-15T12:00:00.558797+0530", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, @@ -750,10 +750,14 @@ Plain unsigned integers with no unit suffix. Timestamp --------- -Field: ``sync_time_stamp``. +Field: ``sync_time_stamp`` (and ``metrics_updated_at`` in mgr status). -Unix epoch time in seconds when the snapshot sync finished, printed with -sub-second precision and an ``s`` suffix (for example, ``1784150400.558797s``). +Wall-clock time printed as an ISO-8601 local timestamp with sub-second precision +and timezone offset (for example, ``2026-07-15T12:00:00.558797+0530``). +``sync_time_stamp`` is when the snapshot sync finished; +``metrics_updated_at`` is when omap was last written for that directory and peer. +Omap persistence and ``counter dump`` (``last_sync_timestamp``) still store Unix +epoch seconds. ``snaps_synced``, ``snaps_deleted``, and ``snaps_renamed`` are :ref:`per-session counters`: they count @@ -922,7 +926,7 @@ E.g., adding a regular file for synchronization would result in failed status:: "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "44s", - "sync_time_stamp": "1784150733.600797s", + "sync_time_stamp": "2026-07-15T12:05:33.600797+0530", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, @@ -971,7 +975,7 @@ In the remote filesystem:: "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "33s", - "sync_time_stamp": "1784150400.558797s", + "sync_time_stamp": "2026-07-15T12:00:00.558797+0530", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, @@ -1226,7 +1230,7 @@ Counters are not updated on every file read or write. Behavior differs by field - Durations in seconds; bytes are raw counts * - ``last_sync_timestamp`` - ``last_synced_snap.sync_time_stamp`` - - ``utime_t`` (seconds since epoch); same wall-clock value as admin JSON + - Perf counter is Unix epoch seconds; admin/mgr JSON show ISO-8601 local time * - ``snaps_synced`` / ``snaps_deleted`` / ``snaps_renamed`` - Same field names at directory level - Reset on daemon restart or directory reassignment (same as admin socket) diff --git a/doc/dev/cephfs-mirroring.rst b/doc/dev/cephfs-mirroring.rst index a219dc95259..48f8314f8b6 100644 --- a/doc/dev/cephfs-mirroring.rst +++ b/doc/dev/cephfs-mirroring.rst @@ -444,7 +444,7 @@ status. Commands of this kind take the form ``filesystem-name@filesystem-id peer "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "33s", - "sync_time_stamp": "1784150400.558797s", + "sync_time_stamp": "2026-07-15T12:00:00.558797+0530", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, @@ -548,7 +548,7 @@ status: "crawl_duration": "2s", "datasync_queue_wait_duration": "1s", "sync_duration": "33s", - "sync_time_stamp": "1784150400.558797s", + "sync_time_stamp": "2026-07-15T12:00:00.558797+0530", "sync_bytes": "149.94 MiB", "sync_files": 5000 }, From 78b7fa265b522d2dd0d465568e7957ff2fbaa236 Mon Sep 17 00:00:00 2001 From: Kotresh HR Date: Thu, 23 Jul 2026 17:16:42 +0530 Subject: [PATCH 4/4] qa/cephfs-mirror: Fix tests for ISO sync_time_stamp Fixes: https://tracker.ceph.com/issues/76506 Signed-off-by: Kotresh HR --- qa/tasks/cephfs/test_mirroring.py | 36 ++++++++++++++++++++----------- 1 file changed, 24 insertions(+), 12 deletions(-) diff --git a/qa/tasks/cephfs/test_mirroring.py b/qa/tasks/cephfs/test_mirroring.py index 38522206b7c..ab34dedf2bd 100644 --- a/qa/tasks/cephfs/test_mirroring.py +++ b/qa/tasks/cephfs/test_mirroring.py @@ -11,6 +11,7 @@ import functools from io import StringIO from collections import deque +from datetime import datetime from tasks.cephfs.cephfs_test_case import CephFSTestCase from teuthology.exceptions import CommandFailedError @@ -19,6 +20,16 @@ from teuthology.orchestra import run log = logging.getLogger(__name__) +# ISO-8601 local time with offset, as dumped by peer_status / mgr status +# (e.g. 2026-07-15T12:00:00.558797+0530) +SYNC_TIME_STAMP_RE = re.compile( + r'^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}[+-]\d{4}$') + + +def parse_sync_time_stamp(ts): + """Parse sync_time_stamp / metrics_updated_at ISO-8601 display strings.""" + return datetime.strptime(ts, '%Y-%m-%dT%H:%M:%S.%f%z') + # Exceptions to retry in test assertions RETRY_EXCEPTIONS = (AssertionError, KeyError, IndexError, CommandFailedError) @@ -410,6 +421,7 @@ class TestMirroring(CephFSTestCase): self.assertRegex( last_synced_snap['sync_bytes'], r'^\d+(\.\d+)?\s+(B|KiB|MiB|GiB|TiB|PiB)$') + self.assertRegex(last_synced_snap['sync_time_stamp'], SYNC_TIME_STAMP_RE) self.assertIsInstance(last_synced_snap['sync_files'], int) self.assertGreaterEqual(last_synced_snap['sync_files'], 0) @@ -2765,12 +2777,12 @@ class TestMirroring(CephFSTestCase): 'fs', 'mirror', 'peer', 'status', f'{self.primary_fs_name}@{self.primary_fs_id}', peer_uuid) - d0_sync_time_stamp = float(self.peer_dir_status(res, '/d0', peer_uuid) - ['last_synced_snap']['sync_time_stamp'].rstrip('s')) - d1_sync_time_stamp = float(self.peer_dir_status(res, '/d1', peer_uuid) - ['last_synced_snap']['sync_time_stamp'].rstrip('s')) - d2_sync_time_stamp = float(self.peer_dir_status(res, '/d2', peer_uuid) - ['last_synced_snap']['sync_time_stamp'].rstrip('s')) + d0_sync_time_stamp = parse_sync_time_stamp( + self.peer_dir_status(res, '/d0', peer_uuid)['last_synced_snap']['sync_time_stamp']) + d1_sync_time_stamp = parse_sync_time_stamp( + self.peer_dir_status(res, '/d1', peer_uuid)['last_synced_snap']['sync_time_stamp']) + d2_sync_time_stamp = parse_sync_time_stamp( + self.peer_dir_status(res, '/d2', peer_uuid)['last_synced_snap']['sync_time_stamp']) self.assertGreaterEqual(d1_sync_time_stamp, d0_sync_time_stamp) self.assertGreaterEqual(d2_sync_time_stamp, d0_sync_time_stamp) @@ -2837,12 +2849,12 @@ class TestMirroring(CephFSTestCase): 'fs', 'mirror', 'peer', 'status', f'{self.primary_fs_name}@{self.primary_fs_id}', peer_uuid) - d0_sync_time_stamp = float(self.peer_dir_status(res, '/d0', peer_uuid) - ['last_synced_snap']['sync_time_stamp'].rstrip('s')) - d1_sync_time_stamp = float(self.peer_dir_status(res, '/d1', peer_uuid) - ['last_synced_snap']['sync_time_stamp'].rstrip('s')) - d2_sync_time_stamp = float(self.peer_dir_status(res, '/d2', peer_uuid) - ['last_synced_snap']['sync_time_stamp'].rstrip('s')) + d0_sync_time_stamp = parse_sync_time_stamp( + self.peer_dir_status(res, '/d0', peer_uuid)['last_synced_snap']['sync_time_stamp']) + d1_sync_time_stamp = parse_sync_time_stamp( + self.peer_dir_status(res, '/d1', peer_uuid)['last_synced_snap']['sync_time_stamp']) + d2_sync_time_stamp = parse_sync_time_stamp( + self.peer_dir_status(res, '/d2', peer_uuid)['last_synced_snap']['sync_time_stamp']) self.assertLess(d1_sync_time_stamp, d0_sync_time_stamp) self.assertLess(d2_sync_time_stamp, d0_sync_time_stamp)