Merge PR #70212 into main

* refs/pull/70212/head:
	qa/cephfs-mirror: Fix tests for ISO sync_time_stamp
	doc/cephfs-mirroring: document ISO-8601 sync timestamps
	cephfs_mirror: format sync timestamps as ISO-8601 local time
	tools/cephfs-mirror: report epoch time in last snap sync time

Reviewed-by: Karthik U S <karthik.u.s1@ibm.com>
This commit is contained in:
Kotresh HR 2026-07-30 09:28:12 +05:30
commit 10292cc86f
6 changed files with 60 additions and 48 deletions

View File

@ -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": "274900.558797s",
"sync_time_stamp": "2026-07-15T12:00:00.558797+0530",
"sync_bytes": "149.94 MiB",
"sync_files": 5000
},
@ -750,11 +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).
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.
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<cephfs_mirroring_sync_metric_fields>`: they count
@ -923,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": "500900.600797s",
"sync_time_stamp": "2026-07-15T12:05:33.600797+0530",
"sync_bytes": "149.94 MiB",
"sync_files": 5000
},
@ -972,7 +975,7 @@ In the remote filesystem::
"crawl_duration": "2s",
"datasync_queue_wait_duration": "1s",
"sync_duration": "33s",
"sync_time_stamp": "274900.558797s",
"sync_time_stamp": "2026-07-15T12:00:00.558797+0530",
"sync_bytes": "149.94 MiB",
"sync_files": 5000
},
@ -1227,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), not the monotonic string shown in 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)

View File

@ -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": "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": "274900.558797s",
"sync_time_stamp": "2026-07-15T12:00:00.558797+0530",
"sync_bytes": "149.94 MiB",
"sync_files": 5000
},

View File

@ -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)

View File

@ -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(

View File

@ -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<clock::duration>(sec_duration(seconds));
return monotime(d);
}
struct C_PersistSyncStatAio : Context {
std::string dir_root;
@ -544,13 +535,7 @@ void PeerReplayer::update_directory_last_sync_perf_counters(
sync_stat.last_sync_duration ?
static_cast<uint64_t>(*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);
@ -838,7 +823,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();
@ -1088,9 +1073,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<double>(sync_stat.last_synced));
}
if (sync_stat.last_sync_bytes) {
snap["sync_bytes"] =
@ -3839,7 +3824,10 @@ 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()) {
// 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));

View File

@ -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<double> last_sync_duration;
boost::optional<double> last_sync_crawl_duration;
boost::optional<double> last_sync_datasync_queue_wait_duration;
@ -485,7 +487,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();
@ -579,7 +581,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