Hello,
first time Robinhood user and I'm trying to understand what is going
on. As far as I can see, I have installed and configured Robinhood
properly to work with our Lustre test system, which is connected to our
clients via TCP. I have root access to the client, but not to the MDS
servers (at least not directly, though I can ask our sysadmins to
perform checks or changes there).
I performed the first scan on our system, which took 3 days to scan
about 135 million files, and the mysql database took about 220GB. I
started the scan on Jan 19th and finished on Jan 22th as you can see
below.
Then later I tried to run the changelog reader, which I was assuming it
would take only a few minutes or a few hours, but it has been going on
for 24+ hours now (see below). This is a test system, and though it has
some activity I wasn't expecting so much. By looking at the Robinhood
logs I see something quite strange, since it says that is checking log
entries created on Jan 17h. Does this make any sense?
,----
| 2026/01/23 11:10:55 [8479/4] STATS | last received: rec_id=56074347,
rec_time=2026/01/17 17:01:51.147649, received at 2026/01/23 11:10:55.976729
| 2026/01/23 11:10:55 [8479/4] STATS | receive speed: 641.34
rec/sec, log/real time ratio: 0.11
| 2026/01/23 11:10:55 [8479/4] STATS | last pushed: rec_id=56073014,
rec_time=2026/01/17 17:01:50.845489, pushed at 2026/
`----
Any help or pointers appreciated.
Initial Lustre scan
===================
$ sudo /scratch/angelv-adm/robinhood/robin/sbin/robinhood --scan --once -L
stderr -f /etc/robinhood.d/basto.conf
2026/01/19 16:00:20 [75687/1] CheckFS | '/storage' matches mount point
'/storage', type=lustre, fs=10.1.1.7@tcp:10.1.1.8@tcp:/storage
WARNING: MYSQL_OPT_RECONNECT is deprecated and will be removed in a future
version.
2026/01/19 16:00:20 [75687/1] ListMgr | Default value for field 'uid'
(0x756E6B6E6F776E) doesn't match expected value unknown
2026/01/19 16:00:20 [75687/1] ListMgr | Changing default value of
'ENTRIES.uid'...
[...]
2026/01/19 16:00:21 [75687/2] FS_Scan | Starting scan of /storage
WARNING: MYSQL_OPT_RECONNECT is deprecated and will be removed in a future
version.
[...]
2026/01/22 08:15:57 [75687/3] STATS | ==================== Dumping stats at
2026/01/22 08:15:57 =====================
2026/01/22 08:15:57 [75687/3] STATS | ======== General statistics =========
2026/01/22 08:15:57 [75687/3] STATS | Daemon start time: 2026/01/19 16:00:20
2026/01/22 08:15:57 [75687/3] STATS | Started modules: scan
WARNING: MYSQL_OPT_RECONNECT is deprecated and will be removed in a future
version.
2026/01/22 08:15:57 [75687/3] STATS | ======== FS scan statistics =========
2026/01/22 08:15:57 [75687/3] STATS | current scan interval = 18.5d
2026/01/22 08:15:57 [75687/3] STATS | scan is running:
2026/01/22 08:15:57 [75687/3] STATS | started at : 2026/01/19 16:00:21
(2.7d ago)
2026/01/22 08:15:57 [75687/3] STATS | last action: 2026/01/22 07:35:22
(40.6min ago)
2026/01/22 08:15:57 [75687/3] STATS | progress : 135161107 entries
scanned (0 errors)
2026/01/22 08:15:57 [75687/3] STATS | inst. speed (potential):
374.81 entries/sec (5.34 ms/entry/thread)
2026/01/22 08:15:57 [75687/3] STATS | avg. speed (effective):
584.26 entries/sec (3.37 ms/entry/thread)
WARNING: MYSQL_OPT_RECONNECT is deprecated and will be removed in a future
version.
2026/01/22 08:15:57 [75687/3] STATS | ==== EntryProcessor Pipeline Stats ===
2026/01/22 08:15:57 [75687/3] STATS | Idle threads: 9
2026/01/22 08:15:57 [75687/3] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2026/01/22 08:15:57 [75687/3] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2026/01/22 08:15:57 [75687/3] STATS | Stage | Wait | Curr |
Done | Total | ms/op |
2026/01/22 08:15:57 [75687/3] STATS | 0: GET_FID | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:15:57 [75687/3] STATS | 1: GET_INFO_DB | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:15:57 [75687/3] STATS | 2: GET_INFO_FS | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:15:57 [75687/3] STATS | 3: PRE_APPLY | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:15:57 [75687/3] STATS | 4: DB_APPLY | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:15:57 [75687/3] STATS | 5: CHGLOG_CLR | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:15:57 [75687/3] STATS | 6: RM_OLD_ENTRIES | 0 | 1 |
0 | 0 | 0.00 |
2026/01/22 08:15:57 [75687/3] STATS | DB ops:
get=231699/ins=134929132/upd=231975/rm=0
2026/01/22 08:15:57 [75687/3] STATS | --- Pipeline stage details ---
2026/01/22 08:15:57 [75687/3] STATS | RM_OLD_ENTRIES: (1 op): special op,
status=processing
2026/01/22 08:21:07 [75687/4] FS_Scan | File list of /storage has been
updated
2026/01/22 08:21:07 [75687/1] Main | FS Scan finished
2026/01/22 08:21:07 [75687/1] EntryProc | Pipeline successfully flushed
2026/01/22 08:21:07 [75687/1] STATS | ==== EntryProcessor Pipeline Stats ===
2026/01/22 08:21:07 [75687/1] STATS | Idle threads: 0
2026/01/22 08:21:07 [75687/1] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2026/01/22 08:21:07 [75687/1] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2026/01/22 08:21:07 [75687/1] STATS | Stage | Wait | Curr |
Done | Total | ms/op |
2026/01/22 08:21:07 [75687/1] STATS | 0: GET_FID | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:21:07 [75687/1] STATS | 1: GET_INFO_DB | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:21:07 [75687/1] STATS | 2: GET_INFO_FS | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:21:07 [75687/1] STATS | 3: PRE_APPLY | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:21:07 [75687/1] STATS | 4: DB_APPLY | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:21:07 [75687/1] STATS | 5: CHGLOG_CLR | 0 | 0 |
0 | 0 | 0.00 |
2026/01/22 08:21:07 [75687/1] STATS | 6: RM_OLD_ENTRIES | 0 | 0 |
0 | 1 | 2744730.21 |
2026/01/22 08:21:07 [75687/1] STATS | DB ops:
get=231699/ins=134929132/upd=231975/rm=0
2026/01/22 08:21:07 [75687/1] Main | All tasks done! Exiting.
Running the changelog reader
============================
sudo /scratch/angelv-adm/robinhood/robin/sbin/robinhood --readlog --once -L
stderr -f /etc/robinhood.d/basto.conf
2026/01/22 08:55:49 [8479/1] CheckFS | '/storage' matches mount point
'/storage', type=lustre, fs=10.1.1.7@tcp:10.1.1.8@tcp:/storage
WARNING: MYSQL_OPT_RECONNECT is deprecated and will be removed in a future
version.
2026/01/22 08:55:49 [8479/1] ListMgr | Default value for field 'uid'
(0x756E6B6E6F776E) doesn't match expected value unknown
2026/01/22 08:55:49 [8479/1] ListMgr | Changing default value of
'ENTRIES.uid'...
[...]
2026/01/22 08:55:50 [8479/1] llapi | warning: llapi_changelog_start()
called without CHANGELOG_FLAG_EXTRA_FLAGS
2026/01/22 08:55:50 [8479/2] ChangeLog | LU-1331 is fixed in this version
of Lustre.
2026/01/22 08:55:50 [8479/3] EntryProc | CREATE record on already existing
entry [0x20000ddea:0x3:0x0]. This is normal if you scanned it previously.
[...]
2026/01/23 11:10:55 [8479/4] STATS | ==================== Dumping stats at
2026/01/23 11:10:55 =====================
2026/01/23 11:10:55 [8479/4] STATS | ======== General statistics =========
2026/01/23 11:10:55 [8479/4] STATS | Daemon start time: 2026/01/22 08:55:49
2026/01/23 11:10:55 [8479/4] STATS | Started modules: log_reader
2026/01/23 11:10:55 [8479/4] STATS | ChangeLog reader #0:
2026/01/23 11:10:55 [8479/4] STATS | fs_name = storage
2026/01/23 11:10:55 [8479/4] STATS | mdt_name = MDT0000
2026/01/23 11:10:55 [8479/4] STATS | reader_id = cl4
2026/01/23 11:10:55 [8479/4] STATS | records read = 56074347
2026/01/23 11:10:55 [8479/4] STATS | interesting records = 42314658
2026/01/23 11:10:55 [8479/4] STATS | suppressed records = 13759686
2026/01/23 11:10:55 [8479/4] STATS | records pending = 1000
2026/01/23 11:10:55 [8479/4] STATS | status = busy
2026/01/23 11:10:55 [8479/4] STATS | last received: rec_id=56074347,
rec_time=2026/01/17 17:01:51.147649, received at 2026/01/23 11:10:55.976729
2026/01/23 11:10:55 [8479/4] STATS | receive speed: 641.34 rec/sec,
log/real time ratio: 0.11
2026/01/23 11:10:55 [8479/4] STATS | last pushed: rec_id=56073014,
rec_time=2026/01/17 17:01:50.845489, pushed at 2026/01/23 11:10:55.976728
2026/01/23 11:10:55 [8479/4] STATS | push speed: 641.34 rec/sec,
log/real time ratio: 0.11
2026/01/23 11:10:55 [8479/4] STATS | last committed: rec_id=56072880,
rec_time=2026/01/17 17:01:50.774055, committed at 2026/01/23 11:10:55.976671
2026/01/23 11:10:55 [8479/4] STATS | commit speed: 641.34 rec/sec,
log/real time ratio: 0.11
2026/01/23 11:10:55 [8479/4] STATS | last cleared: rec_id=56072257,
rec_time=2026/01/17 17:01:50.676509, cleared at 2026/01/23 11:10:55.143817
2026/01/23 11:10:55 [8479/4] STATS | clear speed: 640.68 rec/sec,
log/real time ratio: 0.11
2026/01/23 11:10:55 [8479/4] STATS | ChangeLog stats:
2026/01/23 11:10:55 [8479/4] STATS | MARK: 0, CREAT: 5, MKDIR: 2, HLINK:
1, SLINK: 0, MKNOD: 0, UNLNK: 5, RMDIR: 1, RENME: 1
2026/01/23 11:10:55 [8479/4] STATS | RNMTO: 0, OPEN: 28037176, CLOSE:
28037147, LYOUT: 1, TRUNC: 3, SATTR: 2, XATTR: 0
2026/01/23 11:10:55 [8479/4] STATS | HSM: 0, MTIME: 0, CTIME: 0, ATIME:
0, MIGRT: 0, FLRW: 0, RESYNC: 0, GXATR: 3, NOPEN: 0
2026/01/23 11:10:56 [8479/4] STATS | ==== EntryProcessor Pipeline Stats ===
2026/01/23 11:10:56 [8479/4] STATS | Idle threads: 9
2026/01/23 11:10:56 [8479/4] STATS | Id constraints count: 100 (hash
min=0/max=3/avg=0.0)
2026/01/23 11:10:56 [8479/4] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2026/01/23 11:10:56 [8479/4] STATS | Stage | Wait | Curr |
Done | Total | ms/op |
2026/01/23 11:10:56 [8479/4] STATS | 0: GET_FID | 0 | 0 |
0 | 0 | 0.00 |
2026/01/23 11:10:56 [8479/4] STATS | 1: GET_INFO_DB | 64 | 0 |
32 | 432932 | 0.31 |
2026/01/23 11:10:56 [8479/4] STATS | 2: GET_INFO_FS | 0 | 0 |
0 | 432933 | 0.64 |
2026/01/23 11:10:56 [8479/4] STATS | 3: PRE_APPLY | 0 | 0 |
0 | 432933 | 0.00 |
2026/01/23 11:10:56 [8479/4] STATS | 4: DB_APPLY | 1 | 3 |
0 | 432932 | 1.73 | 39.42% batched (avg batch size: 2.3)
2026/01/23 11:10:56 [8479/4] STATS | 5: CHGLOG_CLR | 0 | 0 |
0 | 432932 | 0.02 |
2026/01/23 11:10:56 [8479/4] STATS | 6: RM_OLD_ENTRIES | 0 | 0 |
0 | 0 | 0.00 |
2026/01/23 11:10:56 [8479/4] STATS | DB ops:
get=42313607/ins=0/upd=42313571/rm=1
2026/01/23 11:10:56 [8479/4] STATS | --- Pipeline stage details ---
2026/01/23 11:10:56 [8479/4] STATS | GET_INFO_DB : first: changelog
record #56072914, fid=[0x20000ca25:0x107b3:0x0], status=waiting
2026/01/23 11:10:56 [8479/4] STATS | GET_INFO_DB : last: changelog record
#56073041, fid=[0x20000ca25:0x133aa:0x0], status=waiting
2026/01/23 11:10:56 [8479/4] STATS | DB_APPLY : first: changelog
record #56072910, fid=[0x20000ca25:0x107b3:0x0], status=processing
2026/01/23 11:10:56 [8479/4] STATS | DB_APPLY : last: changelog record
#56072913, fid=[0x20000ca25:0x131e4:0x0], status=waiting
--
Ángel de Vicente
Research Software Engineer (Supercomputing and BigData)
Tel.: +34 922-605-747
---------------------------------------------------------------------------------------------
AVISO LEGAL: Este mensaje puede contener información confidencial y/o
privilegiada. Si usted no es el destinatario final del mismo o lo ha recibido
por error, por favor notifíquelo al remitente inmediatamente. Cualquier uso no
autorizadas del contenido de este mensaje está estrictamente prohibida. Más
información en: https://www.iac.es/es/responsabilidad-legal
DISCLAIMER: This message may contain confidential and / or privileged
information. If you are not the final recipient or have received it in error,
please notify the sender immediately. Any unauthorized use of the content of
this message is strictly prohibited. More information:
https://www.iac.es/en/disclaimer
_______________________________________________
robinhood-support mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/robinhood-support
