<div dir="ltr">We run stress tests of Lustre 2.7 on Centos 6.6 inside a VirtualBox 5.2.<br>The tests include performing the following operations on the filesystem for several minutes in random order:<br>- create directory/file/hard link/symlink<br>- remove existing path<br>- chmod path<br>- move path<br><br>Except chmod, all operations above are supposed to change ctime of the parent directory. Before and after each operation the parent directory is lstatted. In our tests we verify that ctime of the parent directory has changed.<br>Below is the simplified Python pseudocode:<br><br>now_bef = time.time()<br>st_bef = os.lstat(parent_path)<br>run_fs_operation(path)<br>st_aft = os.lstat(parent_path)<br>now_aft = time.time()<br>assert (st_bef.st_ctime < st_aft.st_ctime) \<br> or ((st_bef.st_ctime == st_aft.st_ctime) and (abs(int(now_bef) - st_bef.st_ctime) <= 1)), \<br> "ctime not updated; '%s' ts before: %s; ts after: %s; st before: %s; st after: %s" % (path, now_bef, now_aft, st_bef, st_aft)<br><br>We tolerate 1-second difference between time.time() and ctime due to <a href="https://lkml.org/lkml/2009/11/27/169">https://lkml.org/lkml/2009/11/27/169</a>.<br><br>We observed that occasionally mtime/ctime are not updated. For example, a new directory was created at 1536278713 = 00:05:13, but its parent's ctime was still 1536278707 = 00:05:07. As we can see the assertion was triggered:<br><br>AssertionError: ctime not updated; 'b'/mnt/lustre/dir_\xc5\x9b_0/dir_\xc5\x9b_1/dir_\xc5\x9b_0/dir_\xc5\x9b_1/dir_\xc5\x9b_0/dir_\xc5\x9b_1/dir_\xc5\x9b_1/dir_\xc5\x9b_1/dir_\xc5\x9b_1''<br> ts before: 1536278713.0100942;<br> ts after: 1536278713.0103905;<br> st before: os.stat_result(<br> st_mode=16877, st_ino=144115205255730395,<br> st_dev=1264717536, st_nlink=2, st_uid=0, st_gid=0,<br> st_size=4096,<br> st_atime=1536278696,<br> st_mtime=1536278707,<br> st_ctime=1536278707);<br> st after: os.stat_result(<br> st_mode=16877, st_ino=144115205255730395,<br> st_dev=1264717536, st_nlink=2, st_uid=0, st_gid=0,<br> st_size=4096,<br> st_atime=1536278696,<br> st_mtime=1536278707,<br> st_ctime=1536278707)<br><br>This particular error was caused by creating a new directory, but they happen after other operations too.<br>As the assertion triggered from time to time, we have recently added a loop that waits for parent's ctime to be updated. In this case it happened after 1 second:<br><br>ctime updated after 1 seconds; 'b'/mnt/lustre/dir_\xc5\x9b_0/dir_\xc5\x9b_1/dir_\xc5\x9b_0/dir_\xc5\x9b_1/dir_\xc5\x9b_0/dir_\xc5\x9b_1/dir_\xc5\x9b_1/dir_\xc5\x9b_1/dir_\xc5\x9b_1''<br> ts before: 1536278713.0100942;<br> ts now: 1536278714.0112765;<br> st before: os.stat_result(st_mode=16877,<br> st_ino=144115205255730395, st_dev=1264717536,<br> st_nlink=2, st_uid=0, st_gid=0, st_size=4096,<br> st_atime=1536278696,<br> st_mtime=1536278707,<br> st_ctime=1536278707);<br> st now: os.stat_result(st_mode=16877, st_ino=144115205255730395,<br> st_dev=1264717536, st_nlink=3, st_uid=0, st_gid=0,<br> st_size=4096,<br> st_atime=1536278696,<br> st_mtime=1536278713,<br> st_ctime=1536278713)<br><br>We saw cases where after more than a dozen seconds ctime was still wrong, but got repaired on its own after more than a minute.<br><br>Lustre version: lustre-2.7.0-2.6.32_504.8.1.el6_lustre.x86_64.x86_64<br><br>What might be important is that we use aggressive time synchronization between host and guess machine (VBoxService with --timesync-interval 1000). Below is the snippet from VBoxService logs:<br><br>00:04:40.263572 timesync vgsvcTimeSyncWorker: Host: 2018-09-07T00:05:12.515000000Z (MinAdjust: 100 ms)<br>00:04:40.263635 timesync vgsvcTimeSyncWorker: Guest: - 2018-09-07T00:05:11.120961000Z => 1 394 039 000 ns drift<br>00:04:40.263663 timesync vgsvcTimeSyncAdjust: adjtime by 1 394 039 000 ns<br>00:04:41.263879 timesync vgsvcTimeSyncWorker: Host: 2018-09-07T00:05:13.515000000Z (MinAdjust: 100 ms)<br>00:04:41.263934 timesync vgsvcTimeSyncWorker: Guest: - 2018-09-07T00:05:12.121272000Z => 1 393 728 000 ns drift<br>00:04:41.263976 timesync vgsvcTimeSyncAdjust: adjtime by 1 393 728 000 ns<br>00:04:42.264138 timesync vgsvcTimeSyncWorker: Host: 2018-09-07T00:05:14.515000000Z (MinAdjust: 100 ms)<br>00:04:42.264209 timesync vgsvcTimeSyncWorker: Guest: - 2018-09-07T00:05:13.121532000Z => 1 393 468 000 ns drift<br>00:04:42.264249 timesync vgsvcTimeSyncAdjust: adjtime by 1 393 468 000 ns<br>00:04:43.264406 timesync vgsvcTimeSyncWorker: Host: 2018-09-07T00:05:15.515000000Z (MinAdjust: 100 ms)<br>00:04:43.264470 timesync vgsvcTimeSyncWorker: Guest: - 2018-09-07T00:05:14.121801000Z => 1 393 199 000 ns drift<br>00:04:43.264498 timesync vgsvcTimeSyncAdjust: adjtime by 1 393 199 000 ns<br>00:04:44.264631 timesync vgsvcTimeSyncWorker: Host: 2018-09-07T00:05:16.514000000Z (MinAdjust: 100 ms)<br>00:04:44.264703 timesync vgsvcTimeSyncWorker: Guest: - 2018-09-07T00:05:15.122026000Z => 1 391 974 000 ns drift<br>00:04:44.264733 timesync vgsvcTimeSyncAdjust: adjtime by 1 391 974 000 ns<br><br>This is nothing unusual: similar adjustments are made in every test and in most cases they don't cause any problems with ctime.<br><br>Why are mtime/ctime occasionally not updated? Is there a way to make sure that metadata is fully up to date?<br><br>-- <br>Best regards,<br>Marcin Barczyński
</div>