LTP rwtest04: mmap-write + msync shows partial data visibility (page tear) on immediate verify-read

[clinx]

、

Environment

• Workload: LTP fs/rwtest04
• Reproducer:
  • Command: /opt/ltp/runltp -Q -b /root/lin/mnt002 -f fs -s rwtest04 -d /root/lin/mnt002
  • File: /root/lin/mnt002/ltp-*/mm-sync-<pid>
• Client: FUSE-based file I/O (verify uses O_RDONLY)
• Observation time: 2025-11-12 17:12:45.xxx

Expected behavior

After memcpy to a MAP_SHARED mapping and msync(..., MS_SYNC) returns 0, a verification read of the same range should observe fully updated data.

Actual behavior

Immediate verify-read returns a mix of old and new data for the same range (data comparison error). Logs show:

• Old 12KB content was persisted just before the mmap memcpy
• The subsequent msync appears to have flushed only the first 4KB page
• The verify-read hits cached data prepared earlier by a window-aligned backend read, so its syscall time is very short and “doesn’t align” with the backend request timing

User-space timeline (doio)

• mmap-write memcpy (offset 4442856, len 9927):

doio_debug_log("mmap-%s memcpy done: fd=%d offset=%d copied=%d memaddr=0x%lx duration_ns=%lld\n",
               (sysc->sy_flags & SY_WRITE) ? "write" : "read",
               fd, req->r_data.io.r_offset, req->r_data.io.r_nbytes,
               (unsigned long)memaddr, ...);

[2025-11-12 17:12:45.977696142] mmap-write memcpy done: fd=3 offset=4442856 copied=9927 memaddr=0x7f6663c3cae8 duration_ns=9430449

• msync start and completion:

doio_debug_log("msync: fd=%d offset=%d base=0x%lx len=%d flags=MS_SYNC\n",
               fd, req->r_data.io.r_offset, (unsigned long)fdc->c_memaddr,
               (int)sbuf.st_size);
msret = msync(fdc->c_memaddr, (int)sbuf.st_size, MS_SYNC);
doio_debug_log("msync: fd=%d offset=%d ret=%d errno=%d duration_ns=%lld\n", ...);

[2025-11-12 17:12:45.977715758] msync: fd=3 offset=4442856 base=0x7f6663800000 len=12800000 flags=MS_SYNC
[2025-11-12 17:12:45.982667206] msync: fd=3 offset=4442856 ret=0 errno=0 duration_ns=4937949

• verify-read (independent O_RDONLY fd) right after msync:

doio_debug_log("verify: fd=%d file=%s offset=%d len=%d\n", fd, file, offset, length);
doio_debug_log("verify-lseek: fd=%d offset=%d ret=%d errno=%d duration_ns=%lld\n", ...);
doio_debug_log("verify-read: fd=%d offset=%d buf=0x%lx len=%d ret=%d errno=%d duration_ns=%lld\n", ...);

[2025-11-12 17:12:45.982712405] verify: fd=4 file=/root/lin/mnt002/ltp-np5plAMCXo/mm-sync-107502 offset=4442856 len=9927
[2025-11-12 17:12:45.982726786] verify-lseek: fd=4 offset=4442856 ret=4442856 errno=0 duration_ns=1226
[2025-11-12 17:12:45.982805728] verify-read: fd=4 offset=4442856 buf=0x1a85c70 len=9927 ret=9927 errno=0 duration_ns=65796

• Data comparison error (mixed old/new):

*** DATA COMPARISON ERROR ***
check_file(..., 4442856, 9927, I:107540:ip-10-52-148-199:doio*, 31, 0) failed

Corrupt regions follow - unprintable chars are represented as '.'
-----------------------------------------------------------------
corrupt bytes starting at file offset 4442856
    1st 32 expected bytes:  I:107540:ip-10-52-148-199:doio*I
    1st 32 actual bytes:    ........................9:doio*I

Server/FUSE-side timeline (backend I/O)

• Prior to memcpy, a 12KB write of old data persisted:

2025/11/12 17:12:45.968617 [DEBUG] file.go:425: TRACE Write enter: ino(8508829) ... offset(4440064) len(12288) flags(WriteCache) ...
2025/11/12 17:12:45.977674 [DEBUG] file.go:532: TRACE Write: ino(8508829) offset(4440064) len(12288) ... (8999822)ns

• Read path uses window-aligned requests (128KB), may start earlier than user offset; hole handling logs:

2025/11/12 17:12:45.968765 [DEBUG] file.go:357: TRACE Read enter: ... offset(4395008) reqsize(131072) ... ffl=OpenReadOnly+OpenSync)
2025/11/12 17:12:45.982158 [DEBUG] stream_reader.go:189: ... req FileOffset(4395008) Size(45056) ExtentKey(<nil>)
2025/11/12 17:12:45.982179 [DEBUG] stream_reader.go:206: Stream read hole: ino(8508829) req(FileOffset(4395008) Size(45056) ExtentKey(<nil>)) total(45056)

• The 12KB region [4440064, 4452352) is delivered before verify-read:

2025/11/12 17:12:45.982426 [DEBUG] extent_reader.go:114: ExtentReader Read exit: req(FileOffset(4440064) Size(12288) ...) ... readBytes(12288) err(<nil>)

• Only a single 4KB overwrite (new data) is observed right after:

2025/11/12 17:12:45.982545 [DEBUG] stream_conn.go:228: sendToConn exit: ... Op(OpRandomWrite) ... FileOffset(4440064) Size(4096) ...
2025/11/12 17:12:45.982569 [DEBUG] stream_writer.go:436: Streamer write exit: ... offset(4440064) size(4096) done total(4096) err(<nil>)

• A separate example of verify-read at higher offset still triggering an earlier aligned window:

[2025-11-12 17:12:45.968535747] verify-read: fd=4 offset=5072258 ... len=124935 ret=124935 ... duration_ns=1880012
2025/11/12 17:12:45.968765 [DEBUG] file.go:357: TRACE Read enter: ... offset(4395008) reqsize(131072) ...

Why this looks like a “page tear”

• 4KB page size. User-space mmap write: S=4442856, L=9927, end inclusive E=S+L-1=4452782.
• Spans 4 pages:
  • P0 [4440064, 4444160) → tail 1304B
  • P1 [4444160, 4448256) → full 4096B
  • P2 [4448256, 4452352) → full 4096B
  • P3 [4452352, 4456448) → head 431B
• Before memcpy, old data for [4440064, 4452352) (P0–P2) was persisted.
• The msync window that followed only resulted in a single 4KB overwrite (P0), while P1/P2/P3 were not updated in that window.
• The immediate verify-read then observed “new P0 tail + old P1/P2 + old P3 head”, matching the compare output where a long run of '.' (old) is followed by the new tail “9:doio*I”.

Why verify-read time “doesn’t align” with backend time

• check_file() uses a separate O_RDONLY fd and does a single lseek+read (not reading the writer’s mmap). Its short syscall time reflects copying data from cache.
• The backend read had already populated the needed 12KB into cache before verify-read was issued, due to window-aligned prefetch/extent reads.

Impact

• Immediate data verification after msync(MS_SYNC) can read partially updated content (mixed old/new) for the same range, causing false data corruption failures in mmap workloads.

What might be happening

• Race between:
  • Background/streamed writeback of old content (already completed for P0–P2 before memcpy)
  • The subsequent msync only resulting in one 4KB flush (observed)
• Page-granular flushing and request coalescing lead to only a subset of dirty pages being persisted in that specific window, making an immediate read see a torn range.

Requests for maintainers

• Confirm semantics: After msync(..., MS_SYNC) on MAP_SHARED, should CubeFS guarantee the full dirty range is persisted atomically to the backend before returning?
• Investigate:
  • Ensuring msync-triggered flush covers the entire dirty range intersected, not just a single page
  • Coordination between FUSE writeback and mmap msync to avoid persisting stale data that races with a newer mmap write
  • Read path’s window alignment is expected, but verify that it cannot cache stale data over freshly dirtied pages post-msync
• If full atomicity is not guaranteed, document recommended barriers/flags for mmap writers to ensure strong persistence before verification.

Possible workarounds (for the test)

• Delay verification slightly after msync to allow remaining pages to flush
• Verify on page-aligned, page-sized boundaries or use fsync on the fd after msync
• Avoid immediate verification of sub-page tails/heads that straddle pages

[clinx]

I add some trace log like this

int doio_debug_enabled(void)
{
	return 1;
}

void doio_debug_log(const char *format, ...)
{
	va_list ap;
	char buf[1024];
	char prefix[64];
	struct timespec ts;
	struct tm lt;

	if (!doio_debug_enabled())
		return;

	clock_gettime(CLOCK_REALTIME, &ts);
#ifdef __linux__
	localtime_r(&ts.tv_sec, &lt);
#else
	{
		struct tm *ltp = localtime(&ts.tv_sec);
		if (ltp)
			lt = *ltp;
	}
#endif
	strftime(prefix, sizeof(prefix), "%Y-%m-%d %H:%M:%S", &lt);

	va_start(ap, format);
	vsnprintf(buf, sizeof(buf), format, ap);
	va_end(ap);
	doio_fprintf(stderr, "[%s.%09ld] %s", prefix, (long)ts.tv_nsec, buf);
}

[clinx]

log:
doio(rwtest04) (107540) 17:12:45

*** DATA COMPARISON ERROR ***
check_file(/root/lin/mnt002/ltp-np5plAMCXo/mm-sync-107502, 4442856, 9927, I:107540:ip-10-52-148-199:doio*, 31, 0) failed

Comparison fd is 4, with open flags 0
Corrupt regions follow - unprintable chars are represented as '.'

corrupt bytes starting at file offset 4442856
1st 32 expected bytes: I:107540:ip-10-52-148-199:doioI
1st 32 actual bytes: ........................9:doioI

Request number 3
fd 3 is file /root/lin/mnt002/ltp-np5plAMCXo/mm-sync-107502 - open flags are 04010002 O_RDWR,O_SYNC,
write done at file offset 4442856 - pattern is I (0111)
number of requests is 1, strides per request is 1
i/o byte count = 9927
memory alignment is unaligned

syscall: mmap-write(NULL, 12800000, PROT_WRITE, MAP_SHARED, 3, 0)
file is mmaped to: 0x7f6663800000
file-mem=0x7f6663c3cae8, length=9927, buffer=0x1a85c72

[2025-11-12 17:12:45.977696142] mmap-write memcpy done: fd=3 offset=4442856 copied=9927 memaddr=0x7f6663c3cae8 duration_ns=9430449
[2025-11-12 17:12:45.977715758] msync: fd=3 offset=4442856 base=0x7f6663800000 len=12800000 flags=MS_SYNC
[2025-11-12 17:12:45.982667206] msync: fd=3 offset=4442856 ret=0 errno=0 duration_ns=4937949
[2025-11-12 17:12:45.982712405] verify: fd=4 file=/root/lin/mnt002/ltp-np5plAMCXo/mm-sync-107502 offset=4442856 len=9927
[2025-11-12 17:12:45.982726786] verify-lseek: fd=4 offset=4442856 ret=4442856 errno=0 duration_ns=1226
[2025-11-12 17:12:45.982805728] verify-read: fd=4 offset=4442856 buf=0x1a85c70 len=9927 ret=9927 errno=0 duration_ns=65796
check_file(/root/lin/mnt002/ltp-np5plAMCXo/mm-sync-107502, 4442856, 9927, I:107540:ip-10-52-148-199:doio*, 31, 0) failed

2025/11/12 17:12:45.968765 [DEBUG] file.go:357: TRACE Read enter: ino(8508829) storageClass(2) offset(4395008) filesize(10301440) r
eqsize(131072) req(Read [ID=0x2c2b7a Node=0x8 Uid=0 Gid=0 Pid=107541] 0x4 131072 @0x431000 dir=false fl=0 lock=0 ffl=OpenReadOnly+O
penSync)

025/11/12 17:12:45.982158 [DEBUG] stream_reader.go:189: action[streamer.read] req FileOffset(4395008) Size(45056) ExtentKey()
2025/11/12 17:12:45.982179 [DEBUG] stream_reader.go:206: Stream read hole: ino(8508829) req(FileOffset(4395008) Size(45056) ExtentKey()) total(45056)

2025/11/12 17:12:45.968617 [DEBUG] file.go:425: TRACE Write enter: ino(8508829) storageClass(2) offset(4440064) len(12288) flags(WriteCache) fileflags(OpenReadOnly) quotaIds(map[]) req(Write [ID=0x2c2b74 Node=0x7 Uid=0 Gid=0 Pid=0] 0x3 12288 @4440064 fl=WriteCache lock=0 ffl=OpenReadOnly)
2025/11/12 17:12:45.977674 [DEBUG] file.go:532: TRACE Write: ino(8508829) offset(4440064) len(12288) flags(WriteCache) fileflags(OpenReadOnly) req(Write [ID=0x2c2b74 Node=0x7 Uid=0 Gid=0 Pid=0] 0x3 12288 @4440064 fl=WriteCache lock=0 ffl=OpenReadOnly) (8999822)ns
2025/11/12 17:12:45.977808 [DEBUG] file.go:425: TRACE Write enter: ino(8508829) storageClass(2) offset(4440064) len(4096) flags(WriteCache) fileflags(OpenReadOnly) quotaIds(map[]) req(Write [ID=0x2c2b7c Node=0x7 Uid=0 Gid=0 Pid=0] 0x3 4096 @4440064 fl=WriteCache lock=0 ffl=OpenReadOnly)
2025/11/12 17:12:45.982591 [DEBUG] file.go:532: TRACE Write: ino(8508829) offset(4440064) len(4096) flags(WriteCache) fileflags(OpenReadOnly) req(Write [ID=0x2c2b7c Node=0x7 Uid=0 Gid=0 Pid=0] 0x3 4096 @4440064 fl=WriteCache lock=0 ffl=OpenReadOnly) (4760969)ns

[2025-11-12 17:12:45.977696142] mmap-write memcpy done: fd=3 offset=4442856 copied=9927 memaddr=0x7f6663c3cae8 duration_ns=9430449

977696142-9430449
968265693

2025/11/12 17:12:45.968617 [DEBUG] file.go:425: TRACE Write enter: ino(8508829) storageClass(2) offset(4440064) len(12288) flags(WriteCache) fileflags(OpenReadOnly) quotaIds(map[]) req(Write [ID=0x2c2b74 Node=0x7 Uid=0 Gid=0 Pid=0] 0x3 12288 @4440064 fl=WriteCache lock=0 ffl=OpenReadOnly)

2025/11/12 17:12:45.968765 [DEBUG] file.go:357: TRACE Read enter: ino(8508829) storageClass(2) offset(4395008) filesize(10301440) r
eqsize(131072) req(Read [ID=0x2c2b7a Node=0x8 Uid=0 Gid=0 Pid=107541] 0x4 131072 @0x431000 dir=false fl=0 lock=0 ffl=OpenReadOnly+O
penSync)

[2025-11-12 17:12:45.982667206] msync: fd=3 offset=4442856 ret=0 errno=0 duration_ns=4937949
982667206-4937949
977729257
2025/11/12 17:12:45.977808 [DEBUG] file.go:425: TRACE Write enter: ino(8508829) storageClass(2) offset(4440064) len(4096) flags(WriteCache) fileflags(OpenReadOnly) quotaIds(map[]) req(Write [ID=0x2c2b7c Node=0x7 Uid=0 Gid=0 Pid=0] 0x3 4096 @4440064 fl=WriteCache lock=0 ffl=OpenReadOnly)

2025/11/12 17:12:45.982020 [DEBUG] stream_writer.go:945: Streamer flush end: eh(ExtentHandler{ID(15654)Inode(8508829)FileOffset(444
0064)Size(12288)StoreMode(1)Status(0)Dp(PartitionID(205) Type(0), Status(2) ReplicaNum(3) Hosts([10.52.148.199:17310 10.52.148.205:
17310 10.52.148.206:17310]) NearHosts([]) mediaType(HDD))Ver(0)key(ExtentKey{FileOffset(4440064),VerSeq(0) Partition(205),ExtentID(
17086),ExtentOffset(0),isSplit(false),Size(12288),CRC(0)})lastKey(ExtentKey{FileOffset(4440064),VerSeq(0) Partition(205),ExtentID(1
7086),ExtentOffset(0),isSplit(false),Size(12288),CRC(0)})flight(0)dirty(false)storageClass(2)inflight(0)dirty(false)})
2025/11/12 17:12:45.982026 [DEBUG] stream_writer.go:347: Streamer write enter: ino(8508829) offset(4440064) size(4096) flags(0) storageClass(2) isMigration(false)

2025/11/12 17:12:45.968765 [DEBUG] file.go:357: TRACE Read enter: ino(8508829) storageClass(2) offset(4395008) filesize(10301440) r
eqsize(131072) req(Read [ID=0x2c2b7a Node=0x8 Uid=0 Gid=0 Pid=107541] 0x4 131072 @0x431000 dir=false fl=0 lock=0 ffl=OpenReadOnly+O
penSync)

2025/11/12 17:12:45.981987 [DEBUG] api.go:1397: MetaWrapper AppendExtentKey: ino(8508829) ek(ExtentKey{FileOffset(4440064),VerSeq(0
) Partition(205),ExtentID(17086),ExtentOffset(0),isSplit(false),Size(12288),CRC(0)}) discard([])

2025/11/12 17:12:45.982076 [DEBUG] stream_writer.go:387: action[streamer.write] inode [8508829] latest seq [0] extentkey seq [0] info [ExtentKey{FileOffset(4440064),VerSeq(0) Partition(205),ExtentID(17086),ExtentOffset(0),isSplit(false),Size(12288),CRC(0)}] before compare seq
2025/11/12 17:12:45.982091 [DEBUG] stream_conn.go:160: req opcode 15, conn &{{0xc00d6b8880}}

2025/11/12 17:12:45.982091 [DEBUG] stream_reader.go:158: action[streamer.read] ino(8508829) offset 4395008 size 131072
2025/11/12 17:12:45.982097 [DEBUG] stream_conn.go:202: sendToConn: send to addr(10.52.148.199:17310), reqPacket(ReqID(7571739232148380855)Op(OpRandomWrite)Inode(8508829)FileOffset(4440064)Size(4096)PartitionID(205)ExtentID(17086)ExtentOffset(0)CRC(1661556600)ResultCode(0:Unknown ResultCode(0))Seq(0), errCnt(0))

2025/11/12 17:12:45.968765 [DEBUG] file.go:357: TRACE Read enter: ino(8508829) storageClass(2) offset(4395008) filesize(10301440) r
eqsize(131072) req(Read [ID=0x2c2b7a Node=0x8 Uid=0 Gid=0 Pid=107541] 0x4 131072 @0x431000 dir=false fl=0 lock=0 ffl=OpenReadOnly+O
penSync)
2025/11/12 17:12:45.982091 [DEBUG] stream_reader.go:158: action[streamer.read] ino(8508829) offset 4395008 size 131072
2025/11/12 17:12:45.982097 [DEBUG] stream_conn.go:202: sendToConn: send to addr(10.52.148.199:17310), reqPacket(ReqID(7571739232148380855)Op(OpRandomWrite)Inode(8508829)FileOffset(4440064)Size(4096)PartitionID(205)ExtentID(17086)ExtentOffset(0)CRC(1661556600)ResultCode(0:Unknown ResultCode(0))Seq(0), errCnt(0))
2025/11/12 17:12:45.982103 [DEBUG] extent_cache.go:447: PrepareReadRequests: req[ino(8508829) start(4395008) end(4526080)] ek[extentID(17086),FileOffset(Start(4440064) End(4452352))]

2025/11/12 17:12:45.982426 [DEBUG] extent_reader.go:114: ExtentReader Read exit: req(FileOffset(4440064) Size(12288) ExtentKey(ExtentKey{FileOffset(4440064),VerSeq(0) Partition(205),ExtentID(17086),ExtentOffset(0),isSplit(false),Size(12288),CRC(0)})) reqPacket(ReqID(7571739232148380856)Op(OpStreamRead)Inode(8508829)FileOffset(4440064)Size(12288)PartitionID(205)ExtentID(17086)ExtentOffset(0)CRC(0)ResultCode(0:Unknown ResultCode(0))Seq(0), errCnt(0)) readBytes(12288) err()

[2025-11-12 17:12:45.982805728] verify-read: fd=4 offset=4442856 buf=0x1a85c70 len=9927 ret=9927 errno=0 duration_ns=65796

2025/11/12 17:12:45.982485 [DEBUG] stream_conn.go:202: sendToConn: send to addr(10.52.148.199:17310), reqPacket(ReqID(7571739232148380857)Op(OpStreamRead)Inode(8508829)FileOffset(4452352)Size(4096)PartitionID(205)ExtentID(17085)ExtentOffset(0)CRC(0)ResultCode(0:Unknown ResultCode(0))Seq(0), errCnt(0))
2025/11/12 17:12:45.982538 [DEBUG] stream_writer.go:688: action[doOverwrite] streamer verseq (0) datanode rsp seq (0) code(240)
2025/11/12 17:12:45.982545 [DEBUG] stream_conn.go:228: sendToConn exit: send to addr(10.52.148.199:17310) reqPacket(ReqID(7571739232148380855)Op(OpRandomWrite)Inode(8508829)FileOffset(4440064)Size(4096)PartitionID(205)ExtentID(17086)ExtentOffset(0)CRC(1661556600)ResultCode(0:Unknown ResultCode(0))Seq(0), errCnt(0)) err()
2025/11/12 17:12:45.982558 [DEBUG] stream_writer.go:715: doOverwrit
2025/11/12 17:12:45.982563 [DEBUG] stream_writer.go:407: action[streamer.write] err retryTimes 0
2025/11/12 17:12:45.982569 [DEBUG] stream_writer.go:436: Streamer write exit: ino(8508829) filesize(12800000) offset(4440064) size(4096) done total(4096) err()
2025/11/12 17:12:45.982591 [DEBUG] file.go:532: TRACE Write: ino(8508829) offset(4440064) len(4096) flags(WriteCache) fileflags(OpenReadOnly) req(Write [ID=0x2c2b7c Node=0x7 Uid=0 Gid=0 Pid=0] 0x3 4096 @4440064 fl=WriteCache lock=0 ffl=OpenReadOnly) (4760969)ns