[robinhood-support] Help understanding running the changelog reader

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

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