EDIT: Sorry, missed to post the Robinhood logs for the last fullscan with
increased nb_threads_scan.
Hello Gerald,
thank you for your reply!
Indeed increasing the number of nb_threads_scan may improve the fullscan.
Currently we are running Robinhood version 3.1.4 with Lustre 2.10.6.
Latest tests so far with ~4M files:
* Fullscan took 10.2 hours with nb_threads = 16 and nb_threads_scan = 2
* Fullscan took 3.7 hours with nb_threads = 32 and nb_threads_scan = 16
But the situation is still not clear to me, since it looks like the threads are
most time idle
and the processing speed (avg. speed and total number of entries from pipeline
stats) is still relatively low.
I assume that the problem must have its cause somewhere else.
Robinhood log for the scan with increased number of nb_threads_scan:
2019/06/13 15:41:38 [8258/2] FS_Scan | Starting scan of /lustre/xxx
2019/06/13 15:41:38 [8258/2] FS_Scan | Notice: this is the first scan (DB is
empty)
2019/06/13 15:56:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 15:56:38 =====================
2019/06/13 15:56:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 15:56:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 15:56:38 [8258/3] STATS | Started modules: scan
2019/06/13 15:56:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 15:56:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 15:56:38 [8258/3] STATS | scan is running:
2019/06/13 15:56:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(15.0min ago)
2019/06/13 15:56:38 [8258/3] STATS | last action: 2019/06/13 15:56:38 (00s
ago)
2019/06/13 15:56:38 [8258/3] STATS | progress : 701789 entries scanned
(0 errors)
2019/06/13 15:56:38 [8258/3] STATS | inst. speed (potential): 379.50
entries/sec (42.16 ms/entry/thread)
2019/06/13 15:56:38 [8258/3] STATS | avg. speed (effective): 779.77
entries/sec (19.91 ms/entry/thread)
2019/06/13 15:56:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 15:56:38 [8258/3] STATS | Idle threads: 31
2019/06/13 15:56:38 [8258/3] STATS | Id constraints count: 2 (hash
min=0/max=1/avg=0.0)
2019/06/13 15:56:38 [8258/3] STATS | Name constraints count: 2 (hash
min=0/max=1/avg=0.0)
2019/06/13 15:56:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 15:56:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
43739 | 1.77 |
2019/06/13 15:56:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
709672 | 0.25 |
2019/06/13 15:56:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
709672 | 0.04 |
2019/06/13 15:56:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
709672 | 0.00 |
2019/06/13 15:56:38 [8258/3] STATS | 4: DB_APPLY | 1 | 1 | 0 |
709670 | 0.72 | 77.87% batched (avg batch size: 4.5)
2019/06/13 15:56:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 15:56:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 15:56:38 [8258/3] STATS | DB ops: get=0/ins=709670/upd=0/rm=0
2019/06/13 15:56:38 [8258/3] STATS | --- Pipeline stage details ---
2019/06/13 15:56:38 [8258/3] STATS | DB_APPLY : first:
[0x240006325:0xdd9f:0x0], status=processing
2019/06/13 15:56:38 [8258/3] STATS | DB_APPLY : last:
[0x240006322:0xcef3:0x0], status=waiting
2019/06/13 16:11:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 16:11:38 =====================
2019/06/13 16:11:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 16:11:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 16:11:38 [8258/3] STATS | Started modules: scan
2019/06/13 16:11:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 16:11:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 16:11:38 [8258/3] STATS | scan is running:
2019/06/13 16:11:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(30.0min ago)
2019/06/13 16:11:38 [8258/3] STATS | last action: 2019/06/13 16:11:38 (00s
ago)
2019/06/13 16:11:38 [8258/3] STATS | progress : 994254 entries scanned
(0 errors)
2019/06/13 16:11:38 [8258/3] STATS | inst. speed (potential): 401.66
entries/sec (39.83 ms/entry/thread)
2019/06/13 16:11:38 [8258/3] STATS | avg. speed (effective): 552.36
entries/sec (28.39 ms/entry/thread)
2019/06/13 16:11:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 16:11:38 [8258/3] STATS | Idle threads: 32
2019/06/13 16:11:38 [8258/3] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 16:11:38 [8258/3] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 16:11:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 16:11:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:11:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
293064 | 0.27 |
2019/06/13 16:11:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
293064 | 0.01 |
2019/06/13 16:11:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
293064 | 0.00 |
2019/06/13 16:11:38 [8258/3] STATS | 4: DB_APPLY | 0 | 0 | 0 |
293066 | 1.13 | 28.96% batched (avg batch size: 2.4)
2019/06/13 16:11:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:11:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:11:38 [8258/3] STATS | DB ops: get=0/ins=1002736/upd=0/rm=0
2019/06/13 16:26:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 16:26:38 =====================
2019/06/13 16:26:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 16:26:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 16:26:38 [8258/3] STATS | Started modules: scan
2019/06/13 16:26:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 16:26:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 16:26:38 [8258/3] STATS | scan is running:
2019/06/13 16:26:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(45.0min ago)
2019/06/13 16:26:38 [8258/3] STATS | last action: 2019/06/13 16:26:38 (00s
ago)
2019/06/13 16:26:38 [8258/3] STATS | progress : 1294595 entries scanned
(0 errors)
2019/06/13 16:26:38 [8258/3] STATS | inst. speed (potential): 370.52
entries/sec (43.18 ms/entry/thread)
2019/06/13 16:26:38 [8258/3] STATS | avg. speed (effective): 479.48
entries/sec (32.97 ms/entry/thread)
2019/06/13 16:26:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 16:26:38 [8258/3] STATS | Idle threads: 31
2019/06/13 16:26:38 [8258/3] STATS | Id constraints count: 1 (hash
min=0/max=1/avg=0.0)
2019/06/13 16:26:38 [8258/3] STATS | Name constraints count: 1 (hash
min=0/max=1/avg=0.0)
2019/06/13 16:26:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 16:26:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:26:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
299203 | 0.27 |
2019/06/13 16:26:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
299203 | 0.01 |
2019/06/13 16:26:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
299203 | 0.00 |
2019/06/13 16:26:38 [8258/3] STATS | 4: DB_APPLY | 0 | 1 | 0 |
299202 | 1.12 | 27.11% batched (avg batch size: 2.5)
2019/06/13 16:26:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:26:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:26:38 [8258/3] STATS | DB ops: get=0/ins=1301938/upd=0/rm=0
2019/06/13 16:26:38 [8258/3] STATS | --- Pipeline stage details ---
2019/06/13 16:26:38 [8258/3] STATS | DB_APPLY : (1 op):
[0x2400061f7:0xdb7d:0x0], status=processing
2019/06/13 16:41:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 16:41:38 =====================
2019/06/13 16:41:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 16:41:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 16:41:38 [8258/3] STATS | Started modules: scan
2019/06/13 16:41:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 16:41:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 16:41:38 [8258/3] STATS | scan is running:
2019/06/13 16:41:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(1.0h ago)
2019/06/13 16:41:38 [8258/3] STATS | last action: 2019/06/13 16:41:38 (00s
ago)
2019/06/13 16:41:38 [8258/3] STATS | progress : 1619986 entries scanned
(0 errors)
2019/06/13 16:41:38 [8258/3] STATS | inst. speed (potential): 373.72
entries/sec (42.81 ms/entry/thread)
2019/06/13 16:41:38 [8258/3] STATS | avg. speed (effective): 450.00
entries/sec (35.31 ms/entry/thread)
2019/06/13 16:41:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 16:41:38 [8258/3] STATS | Idle threads: 32
2019/06/13 16:41:38 [8258/3] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 16:41:38 [8258/3] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 16:41:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 16:41:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:41:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
323529 | 0.26 |
2019/06/13 16:41:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
323529 | 0.01 |
2019/06/13 16:41:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
323529 | 0.00 |
2019/06/13 16:41:38 [8258/3] STATS | 4: DB_APPLY | 0 | 0 | 0 |
323530 | 1.07 | 29.72% batched (avg batch size: 2.5)
2019/06/13 16:41:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:41:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:41:38 [8258/3] STATS | DB ops: get=0/ins=1625468/upd=0/rm=0
2019/06/13 16:56:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 16:56:38 =====================
2019/06/13 16:56:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 16:56:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 16:56:38 [8258/3] STATS | Started modules: scan
2019/06/13 16:56:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 16:56:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 16:56:38 [8258/3] STATS | scan is running:
2019/06/13 16:56:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(1.2h ago)
2019/06/13 16:56:38 [8258/3] STATS | last action: 2019/06/13 16:56:38 (00s
ago)
2019/06/13 16:56:38 [8258/3] STATS | progress : 1786482 entries scanned
(0 errors)
2019/06/13 16:56:38 [8258/3] STATS | inst. speed (potential): 110.26
entries/sec (145.12 ms/entry/thread)
2019/06/13 16:56:38 [8258/3] STATS | avg. speed (effective): 397.00
entries/sec (39.47 ms/entry/thread)
2019/06/13 16:56:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 16:56:38 [8258/3] STATS | Idle threads: 32
2019/06/13 16:56:38 [8258/3] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 16:56:38 [8258/3] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 16:56:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 16:56:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:56:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
167136 | 0.28 |
2019/06/13 16:56:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
167136 | 0.01 |
2019/06/13 16:56:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
167136 | 0.00 |
2019/06/13 16:56:38 [8258/3] STATS | 4: DB_APPLY | 0 | 0 | 0 |
167136 | 1.20 | 25.95% batched (avg batch size: 2.4)
2019/06/13 16:56:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:56:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 16:56:38 [8258/3] STATS | DB ops: get=0/ins=1792604/upd=0/rm=0
2019/06/13 17:11:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 17:11:38 =====================
2019/06/13 17:11:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 17:11:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 17:11:38 [8258/3] STATS | Started modules: scan
2019/06/13 17:11:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 17:11:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 17:11:38 [8258/3] STATS | scan is running:
2019/06/13 17:11:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(1.5h ago)
2019/06/13 17:11:38 [8258/3] STATS | last action: 2019/06/13 17:11:38 (00s
ago)
2019/06/13 17:11:38 [8258/3] STATS | progress : 1905536 entries scanned
(0 errors)
2019/06/13 17:11:38 [8258/3] STATS | inst. speed (potential): 197.63
entries/sec (80.96 ms/entry/thread)
2019/06/13 17:11:38 [8258/3] STATS | avg. speed (effective): 352.88
entries/sec (44.63 ms/entry/thread)
2019/06/13 17:11:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 17:11:38 [8258/3] STATS | Idle threads: 32
2019/06/13 17:11:38 [8258/3] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 17:11:38 [8258/3] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 17:11:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 17:11:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
43 | 0.90 |
2019/06/13 17:11:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
122015 | 0.32 |
2019/06/13 17:11:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
122015 | 0.01 |
2019/06/13 17:11:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
122015 | 0.00 |
2019/06/13 17:11:38 [8258/3] STATS | 4: DB_APPLY | 0 | 0 | 0 |
122015 | 1.40 | 20.46% batched (avg batch size: 2.4)
2019/06/13 17:11:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:11:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:11:38 [8258/3] STATS | DB ops: get=0/ins=1914619/upd=0/rm=0
2019/06/13 17:26:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 17:26:38 =====================
2019/06/13 17:26:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 17:26:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 17:26:38 [8258/3] STATS | Started modules: scan
2019/06/13 17:26:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 17:26:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 17:26:38 [8258/3] STATS | scan is running:
2019/06/13 17:26:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(1.8h ago)
2019/06/13 17:26:38 [8258/3] STATS | last action: 2019/06/13 17:26:38 (00s
ago)
2019/06/13 17:26:38 [8258/3] STATS | progress : 2108540 entries scanned
(0 errors)
2019/06/13 17:26:38 [8258/3] STATS | inst. speed (potential): 137.70
entries/sec (116.20 ms/entry/thread)
2019/06/13 17:26:38 [8258/3] STATS | avg. speed (effective): 334.69
entries/sec (47.78 ms/entry/thread)
2019/06/13 17:26:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 17:26:38 [8258/3] STATS | Idle threads: 31
2019/06/13 17:26:38 [8258/3] STATS | Id constraints count: 2 (hash
min=0/max=1/avg=0.0)
2019/06/13 17:26:38 [8258/3] STATS | Name constraints count: 2 (hash
min=0/max=1/avg=0.0)
2019/06/13 17:26:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 17:26:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:26:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
177576 | 0.32 |
2019/06/13 17:26:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
177576 | 0.01 |
2019/06/13 17:26:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
177576 | 0.00 |
2019/06/13 17:26:38 [8258/3] STATS | 4: DB_APPLY | 0 | 2 | 0 |
177574 | 1.09 | 34.42% batched (avg batch size: 2.6)
2019/06/13 17:26:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:26:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:26:38 [8258/3] STATS | DB ops: get=0/ins=2092193/upd=0/rm=0
2019/06/13 17:26:38 [8258/3] STATS | --- Pipeline stage details ---
2019/06/13 17:26:38 [8258/3] STATS | DB_APPLY : first:
[0x24000656a:0x1319a:0x0], status=processing
2019/06/13 17:26:38 [8258/3] STATS | DB_APPLY : last:
[0x24000656a:0x13191:0x0], status=processing
2019/06/13 17:41:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 17:41:38 =====================
2019/06/13 17:41:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 17:41:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 17:41:38 [8258/3] STATS | Started modules: scan
2019/06/13 17:41:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 17:41:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 17:41:38 [8258/3] STATS | scan is running:
2019/06/13 17:41:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(2.0h ago)
2019/06/13 17:41:38 [8258/3] STATS | last action: 2019/06/13 17:41:38 (00s
ago)
2019/06/13 17:41:38 [8258/3] STATS | progress : 2266815 entries scanned
(0 errors)
2019/06/13 17:41:38 [8258/3] STATS | inst. speed (potential): 132.75
entries/sec (120.53 ms/entry/thread)
2019/06/13 17:41:38 [8258/3] STATS | avg. speed (effective): 314.84
entries/sec (50.79 ms/entry/thread)
2019/06/13 17:41:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 17:41:38 [8258/3] STATS | Idle threads: 31
2019/06/13 17:41:38 [8258/3] STATS | Id constraints count: 3 (hash
min=0/max=1/avg=0.0)
2019/06/13 17:41:38 [8258/3] STATS | Name constraints count: 3 (hash
min=0/max=1/avg=0.0)
2019/06/13 17:41:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 17:41:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:41:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 1 | 0 |
171481 | 0.32 |
2019/06/13 17:41:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
171481 | 0.01 |
2019/06/13 17:41:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
171481 | 0.00 |
2019/06/13 17:41:38 [8258/3] STATS | 4: DB_APPLY | 2 | 1 | 0 |
171480 | 1.08 | 32.77% batched (avg batch size: 2.7)
2019/06/13 17:41:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:41:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:41:38 [8258/3] STATS | DB ops: get=0/ins=2263673/upd=0/rm=0
2019/06/13 17:41:38 [8258/3] STATS | --- Pipeline stage details ---
2019/06/13 17:41:38 [8258/3] STATS | GET_INFO_DB : (1 op): /lustre/xxx/...,
status=processing
2019/06/13 17:41:38 [8258/3] STATS | DB_APPLY : first:
[0x24000656f:0x501f:0x0], status=processing
2019/06/13 17:41:38 [8258/3] STATS | DB_APPLY : last:
[0x24000656f:0x36a8:0x0], status=waiting
2019/06/13 17:56:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 17:56:38 =====================
2019/06/13 17:56:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 17:56:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 17:56:38 [8258/3] STATS | Started modules: scan
2019/06/13 17:56:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 17:56:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 17:56:38 [8258/3] STATS | scan is running:
2019/06/13 17:56:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(2.2h ago)
2019/06/13 17:56:38 [8258/3] STATS | last action: 2019/06/13 17:56:38 (00s
ago)
2019/06/13 17:56:38 [8258/3] STATS | progress : 2522044 entries scanned
(0 errors)
2019/06/13 17:56:38 [8258/3] STATS | inst. speed (potential): 219.11
entries/sec (73.02 ms/entry/thread)
2019/06/13 17:56:38 [8258/3] STATS | avg. speed (effective): 311.36
entries/sec (51.35 ms/entry/thread)
2019/06/13 17:56:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 17:56:38 [8258/3] STATS | Idle threads: 30
2019/06/13 17:56:38 [8258/3] STATS | Id constraints count: 2 (hash
min=0/max=1/avg=0.0)
2019/06/13 17:56:38 [8258/3] STATS | Name constraints count: 2 (hash
min=0/max=1/avg=0.0)
2019/06/13 17:56:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 17:56:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:56:38 [8258/3] STATS | 1: GET_INFO_DB | 1 | 0 | 0 |
242613 | 0.30 |
2019/06/13 17:56:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
242613 | 0.01 |
2019/06/13 17:56:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
242613 | 0.00 |
2019/06/13 17:56:38 [8258/3] STATS | 4: DB_APPLY | 1 | 1 | 0 |
242614 | 0.97 | 42.52% batched (avg batch size: 2.8)
2019/06/13 17:56:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:56:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 17:56:38 [8258/3] STATS | DB ops: get=0/ins=2506287/upd=0/rm=0
2019/06/13 17:56:38 [8258/3] STATS | --- Pipeline stage details ---
2019/06/13 17:56:38 [8258/3] STATS | GET_INFO_DB : first: /lustre/xxx/...,
status=processing
2019/06/13 17:56:38 [8258/3] STATS | GET_INFO_DB : last: /lustre/xxx/...,
status=processing
2019/06/13 17:56:38 [8258/3] STATS | DB_APPLY : first:
[0x2400069a6:0x1297:0x0], status=processing
2019/06/13 17:56:38 [8258/3] STATS | DB_APPLY : last:
[0x2400069a6:0x128a:0x0], status=waiting
2019/06/13 18:11:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 18:11:38 =====================
2019/06/13 18:11:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 18:11:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 18:11:38 [8258/3] STATS | Started modules: scan
2019/06/13 18:11:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 18:11:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 18:11:38 [8258/3] STATS | scan is running:
2019/06/13 18:11:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(2.5h ago)
2019/06/13 18:11:38 [8258/3] STATS | last action: 2019/06/13 18:11:38 (00s
ago)
2019/06/13 18:11:38 [8258/3] STATS | progress : 2870347 entries scanned
(0 errors)
2019/06/13 18:11:38 [8258/3] STATS | inst. speed (potential): 205.19
entries/sec (77.97 ms/entry/thread)
2019/06/13 18:11:38 [8258/3] STATS | avg. speed (effective): 318.93
entries/sec (50.13 ms/entry/thread)
2019/06/13 18:11:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 18:11:38 [8258/3] STATS | Idle threads: 31
2019/06/13 18:11:38 [8258/3] STATS | Id constraints count: 2 (hash
min=0/max=1/avg=0.0)
2019/06/13 18:11:38 [8258/3] STATS | Name constraints count: 2 (hash
min=0/max=1/avg=0.0)
2019/06/13 18:11:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 18:11:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:11:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
348334 | 0.28 |
2019/06/13 18:11:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
348334 | 0.01 |
2019/06/13 18:11:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
348334 | 0.00 |
2019/06/13 18:11:38 [8258/3] STATS | 4: DB_APPLY | 0 | 2 | 0 |
348334 | 0.88 | 45.94% batched (avg batch size: 2.8)
2019/06/13 18:11:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:11:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:11:38 [8258/3] STATS | DB ops: get=0/ins=2854621/upd=0/rm=0
2019/06/13 18:11:38 [8258/3] STATS | --- Pipeline stage details ---
2019/06/13 18:11:38 [8258/3] STATS | DB_APPLY : first:
[0x240006569:0x17b0c:0x0], status=processing
2019/06/13 18:11:38 [8258/3] STATS | DB_APPLY : last:
[0x240006569:0x17b00:0x0], status=processing
2019/06/13 18:26:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 18:26:38 =====================
2019/06/13 18:26:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 18:26:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 18:26:38 [8258/3] STATS | Started modules: scan
2019/06/13 18:26:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 18:26:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 18:26:38 [8258/3] STATS | scan is running:
2019/06/13 18:26:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(2.8h ago)
2019/06/13 18:26:38 [8258/3] STATS | last action: 2019/06/13 18:26:38 (00s
ago)
2019/06/13 18:26:38 [8258/3] STATS | progress : 3194789 entries scanned
(0 errors)
2019/06/13 18:26:38 [8258/3] STATS | inst. speed (potential): 120.07
entries/sec (133.25 ms/entry/thread)
2019/06/13 18:26:38 [8258/3] STATS | avg. speed (effective): 322.71
entries/sec (49.54 ms/entry/thread)
2019/06/13 18:26:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 18:26:38 [8258/3] STATS | Idle threads: 32
2019/06/13 18:26:38 [8258/3] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 18:26:38 [8258/3] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 18:26:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 18:26:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:26:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
340012 | 0.28 |
2019/06/13 18:26:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
340012 | 0.01 |
2019/06/13 18:26:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
340012 | 0.00 |
2019/06/13 18:26:38 [8258/3] STATS | 4: DB_APPLY | 0 | 0 | 0 |
340014 | 0.89 | 45.60% batched (avg batch size: 2.8)
2019/06/13 18:26:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:26:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:26:38 [8258/3] STATS | DB ops: get=0/ins=3194635/upd=0/rm=0
2019/06/13 18:41:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 18:41:38 =====================
2019/06/13 18:41:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 18:41:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 18:41:38 [8258/3] STATS | Started modules: scan
2019/06/13 18:41:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 18:41:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 18:41:38 [8258/3] STATS | scan is running:
2019/06/13 18:41:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(3.0h ago)
2019/06/13 18:41:38 [8258/3] STATS | last action: 2019/06/13 18:41:38 (00s
ago)
2019/06/13 18:41:38 [8258/3] STATS | progress : 3398148 entries scanned
(0 errors)
2019/06/13 18:41:38 [8258/3] STATS | inst. speed (potential): 141.23
entries/sec (113.29 ms/entry/thread)
2019/06/13 18:41:38 [8258/3] STATS | avg. speed (effective): 314.64
entries/sec (50.80 ms/entry/thread)
2019/06/13 18:41:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 18:41:38 [8258/3] STATS | Idle threads: 32
2019/06/13 18:41:38 [8258/3] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 18:41:38 [8258/3] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 18:41:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 18:41:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:41:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
195764 | 0.32 |
2019/06/13 18:41:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
195764 | 0.01 |
2019/06/13 18:41:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
195764 | 0.00 |
2019/06/13 18:41:38 [8258/3] STATS | 4: DB_APPLY | 0 | 0 | 0 |
195764 | 1.08 | 33.66% batched (avg batch size: 2.7)
2019/06/13 18:41:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:41:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:41:38 [8258/3] STATS | DB ops: get=0/ins=3390399/upd=0/rm=0
2019/06/13 18:56:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 18:56:38 =====================
2019/06/13 18:56:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 18:56:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 18:56:38 [8258/3] STATS | Started modules: scan
2019/06/13 18:56:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 18:56:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 18:56:38 [8258/3] STATS | scan is running:
2019/06/13 18:56:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(3.2h ago)
2019/06/13 18:56:38 [8258/3] STATS | last action: 2019/06/13 18:56:38 (00s
ago)
2019/06/13 18:56:38 [8258/3] STATS | progress : 3617541 entries scanned
(0 errors)
2019/06/13 18:56:38 [8258/3] STATS | inst. speed (potential): 125.24
entries/sec (127.76 ms/entry/thread)
2019/06/13 18:56:38 [8258/3] STATS | avg. speed (effective): 309.19
entries/sec (51.70 ms/entry/thread)
2019/06/13 18:56:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 18:56:38 [8258/3] STATS | Idle threads: 32
2019/06/13 18:56:38 [8258/3] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 18:56:38 [8258/3] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 18:56:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 18:56:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:56:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
220410 | 0.31 |
2019/06/13 18:56:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
220410 | 0.01 |
2019/06/13 18:56:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
220410 | 0.00 |
2019/06/13 18:56:38 [8258/3] STATS | 4: DB_APPLY | 0 | 0 | 0 |
220410 | 1.02 | 38.20% batched (avg batch size: 3.0)
2019/06/13 18:56:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:56:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 18:56:38 [8258/3] STATS | DB ops: get=0/ins=3610809/upd=0/rm=0
2019/06/13 19:11:38 [8258/3] STATS | ==================== Dumping stats at
2019/06/13 19:11:38 =====================
2019/06/13 19:11:38 [8258/3] STATS | ======== General statistics =========
2019/06/13 19:11:38 [8258/3] STATS | Daemon start time: 2019/06/13 15:41:38
2019/06/13 19:11:38 [8258/3] STATS | Started modules: scan
2019/06/13 19:11:38 [8258/3] STATS | ======== FS scan statistics =========
2019/06/13 19:11:38 [8258/3] STATS | current scan interval = 18.5d
2019/06/13 19:11:38 [8258/3] STATS | scan is running:
2019/06/13 19:11:38 [8258/3] STATS | started at : 2019/06/13 15:41:38
(3.5h ago)
2019/06/13 19:11:38 [8258/3] STATS | last action: 2019/06/13 19:11:38 (00s
ago)
2019/06/13 19:11:38 [8258/3] STATS | progress : 3818723 entries scanned
(0 errors)
2019/06/13 19:11:38 [8258/3] STATS | inst. speed (potential): 124.41
entries/sec (128.60 ms/entry/thread)
2019/06/13 19:11:38 [8258/3] STATS | avg. speed (effective): 303.07
entries/sec (52.74 ms/entry/thread)
2019/06/13 19:11:38 [8258/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 19:11:38 [8258/3] STATS | Idle threads: 32
2019/06/13 19:11:38 [8258/3] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 19:11:38 [8258/3] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 19:11:38 [8258/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 19:11:38 [8258/3] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 19:11:38 [8258/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
207316 | 0.31 |
2019/06/13 19:11:38 [8258/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
207316 | 0.01 |
2019/06/13 19:11:38 [8258/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
207316 | 0.00 |
2019/06/13 19:11:38 [8258/3] STATS | 4: DB_APPLY | 0 | 0 | 0 |
207316 | 1.05 | 35.49% batched (avg batch size: 2.7)
2019/06/13 19:11:38 [8258/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 19:11:38 [8258/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 19:11:38 [8258/3] STATS | DB ops: get=0/ins=3818125/upd=0/rm=0
2019/06/13 19:23:22 [8258/4] FS_Scan | Full scan of /lustre/xxx completed,
3948736 entries found (0 errors). Duration = 13303.88s
2019/06/13 19:23:22 [8258/4] FS_Scan | Flushing pipeline...
2019/06/13 19:23:27 [8258/4] FS_Scan | File list of /lustre/xxx has been updated
2019/06/13 19:23:27 [8258/1] Main | FS Scan finished
2019/06/13 19:23:27 [8258/1] EntryProc | Pipeline successfully flushed
2019/06/13 19:23:27 [8258/1] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 19:23:27 [8258/1] STATS | Idle threads: 0
2019/06/13 19:23:27 [8258/1] STATS | Id constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 19:23:27 [8258/1] STATS | Name constraints count: 0 (hash
min=0/max=0/avg=0.0)
2019/06/13 19:23:27 [8258/1] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 19:23:27 [8258/1] STATS | 0: GET_FID | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 19:23:27 [8258/1] STATS | 1: GET_INFO_DB | 0 | 0 | 0 |
130612 | 0.32 |
2019/06/13 19:23:27 [8258/1] STATS | 2: GET_INFO_FS | 0 | 0 | 0 |
130612 | 0.01 |
2019/06/13 19:23:27 [8258/1] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
130612 | 0.00 |
2019/06/13 19:23:27 [8258/1] STATS | 4: DB_APPLY | 0 | 0 | 0 |
130612 | 1.11 | 34.29% batched (avg batch size: 2.6)
2019/06/13 19:23:27 [8258/1] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 19:23:27 [8258/1] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
1 | 4981.83 |
2019/06/13 19:23:27 [8258/1] STATS | DB ops: get=0/ins=3948737/upd=0/rm=0
2019/06/13 19:23:27 [8258/1] Main | All tasks done! Exiting.
Best regards
Gabriele
________________________________________
From: Hofer, Gerald (HPE Pointnext South Pacific Delivery)
<gerald.ho...@hpe.com>
Sent: Thursday, June 13, 2019 07:01
To: Marion Hakanson; Iannetti, Gabriele
Cc: robinhood-support@lists.sourceforge.net
Subject: RE: [robinhood-support] Lustre fullscan extremely slow on Lustre 2.10
I spent quite some time improving the scan performance on a system and did go
from more than a week of scan time down to just over one day for just over
500Million entries. This was also related to an upgrade from 2.5. But I ended
up much faster in Robinhood 3 then I ever was in 2.5.
Environment: RHEL 7.6, Robinhood 3.1.5, Lustre 2.10.5
These are the settings that I ended up with:
EntryProcessor {
nb_threads = 32;
max_pending_operations = 10000;
max_batch_size = 1;
STAGE_DB_APPLY_threads_max = 20;
STAGE_GET_INFO_DB_threads_max = 20;
}
It took me a while to understand the details - but that document does describe
it all:
https://github.com/cea-hpc/robinhood/wiki/pipeline_tuning
In my case I think turning of the batching made a lot of difference.
Now I am pretty much maxing out the SSDs for the database.
Statistics:
entries scanned: 511441340
errors: 3
# threads: 8
average speed: 5633.80 entries/sec
There are also some database tunings that are essential - but it does not look
like you are database bound at the moment.
To give you an perspective on the GET_FID stage - that is only applicable for a
smaller number of requests going through the pipeline. So it can be perfectly
normal that that number is 0. I just started a scan and this is how it looks
like for me:
2019/06/13 13:36:00 [12080/3] STATS | scan is running:
2019/06/13 13:36:00 [12080/3] STATS | started at : 2019/06/13 11:53:41
(1.7h ago)
2019/06/13 13:36:00 [12080/3] STATS | last action: 2019/06/13 13:36:00
(00s ago)
2019/06/13 13:36:00 [12080/3] STATS | progress : 30326605 entries
scanned (3 errors)
2019/06/13 13:36:00 [12080/3] STATS | inst. speed (potential): 5472.89
entries/sec (1.46 ms/entry/thread)
2019/06/13 13:36:00 [12080/3] STATS | avg. speed (effective): 4939.99
entries/sec (1.34 ms/entry/thread)
2019/06/13 13:36:00 [12080/3] STATS | ==== EntryProcessor Pipeline Stats ===
2019/06/13 13:36:00 [12080/3] STATS | Idle threads: 0
2019/06/13 13:36:00 [12080/3] STATS | Id constraints count: 10000 (hash
min=0/max=5/avg=0.7)
2019/06/13 13:36:00 [12080/3] STATS | Name constraints count: 10000 (hash
min=0/max=7/avg=0.7)
2019/06/13 13:36:00 [12080/3] STATS | Stage | Wait | Curr | Done |
Total | ms/op |
2019/06/13 13:36:00 [12080/3] STATS | 0: GET_FID | 0 | 0 | 0 |
37395 | 2.19 |
2019/06/13 13:36:00 [12080/3] STATS | 1: GET_INFO_DB | 9962 | 1 | 0 |
1824557 | 0.45 |
2019/06/13 13:36:00 [12080/3] STATS | 2: GET_INFO_FS | 0 | 26 | 6 |
1824558 | 3.75 |
2019/06/13 13:36:00 [12080/3] STATS | 3: PRE_APPLY | 0 | 0 | 0 |
1824553 | 0.00 |
2019/06/13 13:36:00 [12080/3] STATS | 4: DB_APPLY | 0 | 3 | 0 |
1824554 | 0.97 |
2019/06/13 13:36:00 [12080/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 13:36:00 [12080/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 |
0 | 0.00 |
2019/06/13 13:36:00 [12080/3] STATS | DB ops:
get=29438671/ins=0/upd=30396715/rm=0
2019/06/13 13:36:00 [12080/3] STATS | --- Pipeline stage details ---
A bit later:
For me the biggest issue was to limit the amount of requests in the coordinator
(I am using Robinhood for Lustre HSM). If that number got too high, I got into
all sorts of trouble.
If I read your log files correctly, there is just not enough data coming into
the pipeline. Maybe you can increase the number of threads that run the scan.
This is the setting that I am using:
fs_scan {
scan_interval = 30d;
nb_threads_scan = 8;
}
Hope that helps,
Gerald
-----Original Message-----
From: Marion Hakanson [mailto:hakan...@ohsu.edu]
Sent: Thursday, 13 June 2019 8:16
To: Iannetti, Gabriele <g.ianne...@gsi.de>
Cc: robinhood-support@lists.sourceforge.net
Subject: Re: [robinhood-support] Lustre fullscan extremely slow on Lustre 2.10
Our experience has been similar.
Initial scan, CentOS-6.6, Robinhood 2.5, Lustre IEEL-2.3 (2.5-based) took 6
days for 387M entries.
We recently upgraded all servers and clients to CentOS-7.5, Lustre 2.10.6, and
Robinhood 3.1.4; Same hardware everywhere. Initial scan has been running for
116 days, has only scanned 92M items (out of 183M).
Note that for us, Lustre-2.10.6 has been quite a bit slower for interactive use
(ls in a new directory, etc.) than the previous version. There just seems to
be a lot more locking overhead. So we are not at this time blaming Robinhood
for this slowdown.
I'm sorry that I can't answer any of your questions.
Regards,
Marion
> From: "Iannetti, Gabriele" <g.ianne...@gsi.de>
> To: "robinhood-support@lists.sourceforge.net"
> <robinhood-support@lists.sourceforge.net>
> Date: Wed, 12 Jun 2019 12:52:03 +0000
>
> Hi all,
>
> we are trying to run Robinhood for our next Lustre Installation with 2.10
> which is extremely slow.
>
> I have also tested a fullscan with the same Robinhood client and
> server boxes of our old Lustre installation with 2.5 and it performs
> significantly better (on the old Lustre installation the avg. speed was about
> 2000 entries/sec compared to few hundreds).
>
> Just as a comparison the full scan of the new Lustre installation took
> relatively long...
>
> > Fullscan of old Lustre installation took 3 days for 594M entries.
> > Fullscan of new Lustre installation took 23 days for 533M entries.
>
> I do not understand the cause of the bad performance of the fullscan
> on our next Lustre installation (changelog processing is also slow).
>
> So far no meta data performance or file server issues were detected.
> The meta data operations were tested with 'lfs path2fid'/'ls' on each single
> MDS and file server synchronous write and read performance were also tested
> with few million small files from multiple clients in parallel.
>
> Few numbers about our Lustre installations:
>
> NEW INSTALLATION
>
> Lustre Server Version: 2.10.6
> Number of MDTs: 2
> Number of OSTs: 294
>
> OLD INSTALLATION
>
> Lustre Version: 2.5
> Number of MDTs: 2
> Number of OSTs: 630
>
> LUSTRE CLIENT
> Tested with 2.10 and 2.12
>
> SINGLE FOLDER SCAN EXAMPLE
>
> In the following I post few lines of a Robinhood log of a folder scan
> on the Lustre new installation, where each stats dump looks the same except
> the last dump stats, where the GET_FID stage has non 0 value:
>
> 2019/06/11 15:07:24 [13345/2] FS_Scan | Starting scan of /lustre/xxx
> 2019/06/11 15:07:24 [13345/2] FS_Scan | Notice: this is the first scan
> (DB is empty)
> 2019/06/11 15:22:24 [13345/3] STATS | ==================== Dumping
> stats at 2019/06/11 15:22:24 =====================
> 2019/06/11 15:22:24 [13345/3] STATS | ======== General statistics
> =========
> 2019/06/11 15:22:24 [13345/3] STATS | Daemon start time: 2019/06/11
> 15:07:24
> 2019/06/11 15:22:24 [13345/3] STATS | Started modules: scan
> 2019/06/11 15:22:24 [13345/3] STATS | ======== FS scan statistics
> =========
> 2019/06/11 15:22:24 [13345/3] STATS | current scan interval = 18.5d
> 2019/06/11 15:22:24 [13345/3] STATS | scan is running:
> 2019/06/11 15:22:24 [13345/3] STATS | started at : 2019/06/11 15:07:24
> (15.0min ago)
> 2019/06/11 15:22:24 [13345/3] STATS | last action: 2019/06/11 15:22:24
> (00s ago)
> 2019/06/11 15:22:24 [13345/3] STATS | progress : 64932 entries scanned
> (0 errors)
> 2019/06/11 15:22:24 [13345/3] STATS | inst. speed (potential): 35.92
> entries/sec (55.67 ms/entry/thread)
> 2019/06/11 15:22:24 [13345/3] STATS | avg. speed (effective): 72.15
> entries/sec (27.64 ms/entry/thread)
> 2019/06/11 15:22:24 [13345/3] STATS | ==== EntryProcessor Pipeline
> Stats ===
> 2019/06/11 15:22:24 [13345/3] STATS | Idle threads: 16
> 2019/06/11 15:22:24 [13345/3] STATS | Id constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/11 15:22:24 [13345/3] STATS | Name constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/11 15:22:24 [13345/3] STATS | Stage | Wait | Curr | Done
> | Total | ms/op |
> 2019/06/11 15:22:24 [13345/3] STATS | 0: GET_FID | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/11 15:22:24 [13345/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0
> | 64865 | 0.36 |
> 2019/06/11 15:22:24 [13345/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0
> | 64865 | 0.01 |
> 2019/06/11 15:22:24 [13345/3] STATS | 3: PRE_APPLY | 0 | 0 | 0
> | 64865 | 0.00 |
> 2019/06/11 15:22:24 [13345/3] STATS | 4: DB_APPLY | 0 | 0 | 0
> | 64865 | 1.25 | 15.53% batched (avg batch size: 2.4)
> 2019/06/11 15:22:24 [13345/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/11 15:22:24 [13345/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/11 15:22:24 [13345/3] STATS | DB ops:
> get=0/ins=64865/upd=0/rm=0
> 2019/06/11 15:37:24 [13345/3] STATS | ==================== Dumping
> stats at 2019/06/11 15:37:24 =====================
> 2019/06/11 15:37:24 [13345/3] STATS | ======== General statistics
> =========
> 2019/06/11 15:37:24 [13345/3] STATS | Daemon start time: 2019/06/11
> 15:07:24
> 2019/06/11 15:37:24 [13345/3] STATS | Started modules: scan
> 2019/06/11 15:37:24 [13345/3] STATS | ======== FS scan statistics
> =========
> 2019/06/11 15:37:24 [13345/3] STATS | current scan interval = 18.5d
> 2019/06/11 15:37:24 [13345/3] STATS | scan is running:
> 2019/06/11 15:37:24 [13345/3] STATS | started at : 2019/06/11 15:07:24
> (30.0min ago)
> 2019/06/11 15:37:24 [13345/3] STATS | last action: 2019/06/11 15:37:24
> (00s ago)
> 2019/06/11 15:37:24 [13345/3] STATS | progress : 135638 entries
> scanned (0 errors)
> 2019/06/11 15:37:24 [13345/3] STATS | inst. speed (potential): 48.26
> entries/sec (41.45 ms/entry/thread)
> 2019/06/11 15:37:24 [13345/3] STATS | avg. speed (effective): 75.35
> entries/sec (26.47 ms/entry/thread)
> 2019/06/11 15:37:24 [13345/3] STATS | ==== EntryProcessor Pipeline
> Stats ===
> 2019/06/11 15:37:24 [13345/3] STATS | Idle threads: 16
> 2019/06/11 15:37:24 [13345/3] STATS | Id constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/11 15:37:24 [13345/3] STATS | Name constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/11 15:37:24 [13345/3] STATS | Stage | Wait | Curr | Done
> | Total | ms/op |
> 2019/06/11 15:37:24 [13345/3] STATS | 0: GET_FID | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/11 15:37:24 [13345/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0
> | 64445 | 0.36 |
> 2019/06/11 15:37:24 [13345/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0
> | 64445 | 0.01 |
> 2019/06/11 15:37:24 [13345/3] STATS | 3: PRE_APPLY | 0 | 0 | 0
> | 64445 | 0.00 |
> 2019/06/11 15:37:24 [13345/3] STATS | 4: DB_APPLY | 0 | 0 | 0
> | 64445 | 1.28 | 13.67% batched (avg batch size: 2.3)
> 2019/06/11 15:37:24 [13345/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/11 15:37:24 [13345/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/11 15:37:24 [13345/3] STATS | DB ops:
> get=0/ins=129310/upd=0/rm=0
> 2019/06/11 15:52:24 [13345/3] STATS | ==================== Dumping
> stats at 2019/06/11 15:52:24 =====================
> 2019/06/11 15:52:24 [13345/3] STATS | ======== General statistics
> =========
> 2019/06/11 15:52:24 [13345/3] STATS | Daemon start time: 2019/06/11
> 15:07:24
> 2019/06/11 15:52:24 [13345/3] STATS | Started modules: scan
> 2019/06/11 15:52:24 [13345/3] STATS | ======== FS scan statistics
> =========
> 2019/06/11 15:52:24 [13345/3] STATS | current scan interval = 18.5d
> 2019/06/11 15:52:24 [13345/3] STATS | scan is running:
> 2019/06/11 15:52:24 [13345/3] STATS | started at : 2019/06/11 15:07:24
> (45.0min ago)
> 2019/06/11 15:52:24 [13345/3] STATS | last action: 2019/06/11 15:52:24
> (00s ago)
> 2019/06/11 15:52:24 [13345/3] STATS | progress : 202031 entries
> scanned (0 errors)
> 2019/06/11 15:52:24 [13345/3] STATS | inst. speed (potential): 38.16
> entries/sec (52.41 ms/entry/thread)
> 2019/06/11 15:52:24 [13345/3] STATS | avg. speed (effective): 74.83
> entries/sec (26.65 ms/entry/thread)
> 2019/06/11 15:52:24 [13345/3] STATS | ==== EntryProcessor Pipeline
> Stats ===
> 2019/06/11 15:52:24 [13345/3] STATS | Idle threads: 16
> 2019/06/11 15:52:24 [13345/3] STATS | Id constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/11 15:52:24 [13345/3] STATS | Name constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/11 15:52:24 [13345/3] STATS | Stage | Wait | Curr | Done
> | Total | ms/op |
> 2019/06/11 15:52:24 [13345/3] STATS | 0: GET_FID | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/11 15:52:24 [13345/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0
> | 67000 | 0.36 |
> 2019/06/11 15:52:24 [13345/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0
> | 67000 | 0.01 |
> 2019/06/11 15:52:24 [13345/3] STATS | 3: PRE_APPLY | 0 | 0 | 0
> | 67000 | 0.00 |
> 2019/06/11 15:52:24 [13345/3] STATS | 4: DB_APPLY | 0 | 0 | 0
> | 67000 | 1.27 | 12.16% batched (avg batch size: 2.4)
> 2019/06/11 15:52:24 [13345/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/11 15:52:24 [13345/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/11 15:52:24 [13345/3] STATS | DB ops:
> get=0/ins=196310/upd=0/rm=0
> 2019/06/12 01:07:24 [13345/3] STATS | ==================== Dumping
> stats at 2019/06/12 01:07:24 =====================
> 2019/06/12 01:07:24 [13345/3] STATS | ======== General statistics
> =========
> 2019/06/12 01:07:24 [13345/3] STATS | Daemon start time: 2019/06/11
> 15:07:24
> 2019/06/12 01:07:24 [13345/3] STATS | Started modules: scan
> 2019/06/12 01:07:24 [13345/3] STATS | ======== FS scan statistics
> =========
> 2019/06/12 01:07:24 [13345/3] STATS | current scan interval = 18.5d
> 2019/06/12 01:07:24 [13345/3] STATS | scan is running:
> 2019/06/12 01:07:24 [13345/3] STATS | started at : 2019/06/11 15:07:24
> (10.0h ago)
> 2019/06/12 01:07:24 [13345/3] STATS | last action: 2019/06/12 01:07:24
> (00s ago)
> 2019/06/12 01:07:24 [13345/3] STATS | progress : 3840469 entries
> scanned (0 errors)
> 2019/06/12 01:07:24 [13345/3] STATS | inst. speed (potential): 30.58
> entries/sec (65.39 ms/entry/thread)
> 2019/06/12 01:07:24 [13345/3] STATS | avg. speed (effective): 106.68
> entries/sec (18.69 ms/entry/thread)
> 2019/06/12 01:07:24 [13345/3] STATS | ==== EntryProcessor Pipeline
> Stats ===
> 2019/06/12 01:07:24 [13345/3] STATS | Idle threads: 16
> 2019/06/12 01:07:24 [13345/3] STATS | Id constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/12 01:07:24 [13345/3] STATS | Name constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/12 01:07:24 [13345/3] STATS | Stage | Wait | Curr | Done
> | Total | ms/op |
> 2019/06/12 01:07:24 [13345/3] STATS | 0: GET_FID | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/12 01:07:24 [13345/3] STATS | 1: GET_INFO_DB | 0 | 0 | 0
> | 67331 | 0.36 |
> 2019/06/12 01:07:24 [13345/3] STATS | 2: GET_INFO_FS | 0 | 0 | 0
> | 67331 | 0.01 |
> 2019/06/12 01:07:24 [13345/3] STATS | 3: PRE_APPLY | 0 | 0 | 0
> | 67331 | 0.00 |
> 2019/06/12 01:07:24 [13345/3] STATS | 4: DB_APPLY | 0 | 0 | 0
> | 67331 | 1.29 | 12.56% batched (avg batch size: 2.4)
> 2019/06/12 01:07:24 [13345/3] STATS | 5: CHGLOG_CLR | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/12 01:07:24 [13345/3] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/12 01:07:24 [13345/3] STATS | DB ops:
> get=0/ins=3838009/upd=0/rm=0 ...
> 2019/06/12 01:21:21 [13345/4] FS_Scan | Full scan of /lustre/alice
> completed, 3948736 entries found (0 errors). Duration = 36837.18s
> 2019/06/12 01:21:21 [13345/4] FS_Scan | Flushing pipeline...
> 2019/06/12 01:21:26 [13345/4] FS_Scan | File list of /lustre/alice has
> been updated
> 2019/06/12 01:21:26 [13345/1] Main | FS Scan finished In general each
> fullscan of the new Lustre installation is very slow compared to the old
> installation.
>
> We have also done a fullscan of both the new and old Lustre installation with
> the same Robinhood client and server setup.
>
> 2019/06/12 01:21:26 [13345/1] EntryProc | Pipeline successfully
> flushed
> 2019/06/12 01:21:26 [13345/1] STATS | ==== EntryProcessor Pipeline
> Stats ===
> 2019/06/12 01:21:26 [13345/1] STATS | Idle threads: 0
> 2019/06/12 01:21:26 [13345/1] STATS | Id constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/12 01:21:26 [13345/1] STATS | Name constraints count: 0 (hash
> min=0/max=0/avg=0.0)
> 2019/06/12 01:21:26 [13345/1] STATS | Stage | Wait | Curr | Done
> | Total | ms/op |
> 2019/06/12 01:21:26 [13345/1] STATS | 0: GET_FID | 0 | 0 | 0
> | 43782 | 0.72 |
> 2019/06/12 01:21:26 [13345/1] STATS | 1: GET_INFO_DB | 0 | 0 | 0
> | 110728 | 0.33 |
> 2019/06/12 01:21:26 [13345/1] STATS | 2: GET_INFO_FS | 0 | 0 | 0
> | 110728 | 0.23 |
> 2019/06/12 01:21:26 [13345/1] STATS | 3: PRE_APPLY | 0 | 0 | 0
> | 110728 | 0.00 |
> 2019/06/12 01:21:26 [13345/1] STATS | 4: DB_APPLY | 0 | 0 | 0
> | 110728 | 0.66 | 61.59% batched (avg batch size: 18.9)
> 2019/06/12 01:21:26 [13345/1] STATS | 5: CHGLOG_CLR | 0 | 0 | 0
> | 0 | 0.00 |
> 2019/06/12 01:21:26 [13345/1] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0
> | 1 | 4566.98 |
> 2019/06/12 01:21:26 [13345/1] STATS | DB ops:
> get=0/ins=3948737/upd=0/rm=0
> 2019/06/12 01:21:26 [13345/1] Main | All tasks done! Exiting.
>
> What do you think?
> Is there anything suspicious about the dumped stats that could hint to a very
> slow processing?
> Is it a problem that the GET_FID stages values are 0 except in the last
> dumped stats?
>
> Let me know if you need more information.
>
> We would appreciate your help.
>
>
> Best regards
> Gabriele Iannetti
>
> _______________________________________________
> robinhood-support mailing list
> robinhood-support@lists.sourceforge.net
> INVALID URI REMOVED
> .net_lists_listinfo_robinhood-2Dsupport&d=DwICAg&c=C5b8zRQO1miGmBeVZ2L
> FWg&r=AwU3qMnLPEP_LBcSoaWjKgpcr41iy2nHz71h4bwVVeM&m=gu9TxqYz1vPgqzvobQ
> aHNZH-x56xbi0yJ7yRMDryfRU&s=0bHXdiZBn_SwetU47FV4QswP5bJsVP3DA6vzz_igT6
> s&e=
>
_______________________________________________
robinhood-support mailing list
robinhood-support@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/robinhood-support
_______________________________________________
robinhood-support mailing list
robinhood-support@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/robinhood-support
