x/telemetry/internal/counter: TestConcurrentExtension failures

[gopherbot]

#!watchflakes
default <- pkg == "golang.org/x/telemetry/internal/counter" && test == "TestConcurrentExtension"

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestConcurrentExtension
    concurrent_test.go:75: prog2 failed: exit status 1; output:
        running program "inc2"
        setting counter time to inc2
        counter bug: corrupt: limit 131296 is within mapping length 147456
    concurrent_test.go:69: prog1 failed: exit status 1; output:
        running program "inc1"
        setting counter time to inc1
        counter bug: corrupt: limit 131104 is within mapping length 147456
    concurrent_test.go:110: failed to parse: /home/swarming/.swarming/w/ir/x/t/TestConcurrentExtension2697617232/001/local/counter.test@devel-devel-linux-riscv64-2025-10-08.v1.count: corrupt counter file
--- FAIL: TestConcurrentExtension (0.04s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "golang.org/x/telemetry/internal/counter" && test == "TestConcurrentExtension"

2025-10-08 14:25 x_telemetry-go1.24-linux-riscv64 telemetry@badf71c6 release-branch.go1.24@3a666bca x/telemetry/internal/counter.TestConcurrentExtension (log)

=== RUN   TestConcurrentExtension
    concurrent_test.go:75: prog2 failed: exit status 1; output:
        running program "inc2"
        setting counter time to inc2
        counter bug: corrupt: limit 131296 is within mapping length 147456
    concurrent_test.go:69: prog1 failed: exit status 1; output:
        running program "inc1"
        setting counter time to inc1
        counter bug: corrupt: limit 131104 is within mapping length 147456
    concurrent_test.go:110: failed to parse: /home/swarming/.swarming/w/ir/x/t/TestConcurrentExtension2697617232/001/local/counter.test@devel-devel-linux-riscv64-2025-10-08.v1.count: corrupt counter file
--- FAIL: TestConcurrentExtension (0.04s)

— watchflakes

[findleyr]

@cherrymui any chance there is a bug in atomics in riscv64? Otherwise, this is going to be a very deep dive into the telemetry code :)

[cherrymui]

any chance there is a bug in atomics in riscv64?

I would not expect that. Otherwise things would be much worse. If it is just a one-off failure, maybe it is due to the machine being not very stable (memory error or file corruption), so perhaps we can wait and see if there are more occurrences. That said, I'll take a look at the code.

[cherrymui]

Well, maybe the atomics are actually broken. It looks suspicious to me. I'll look into if I can reproduce the failure and then fix.

[cherrymui]

The atomics we use on RISCV64 don't look strong enough to me. In particular, the LRW/LRD instruction with only the aq bit set doesn't provide the sequentially consistent semantics that Go needs; neither does the SCW/SCD instruction with only the rl bit set for the CAS sequence. That said, I tried to make it use stronger atomics (by setting both aq and rl bits, and/or adding FENCE instructions), the test still fail... There may be something else...

[cherrymui]

I spent more time looking into this. When it fails, it is m.entryAt read from a valid offset within the mapping but got a bunch of zeros. It returns ok=false as nameLen is 0. It is not that an offset pointing beyond the end of the mapping. ok=false while the limit is not growing out of the mapping causes this check to fail.

I grabbed the counter file and the content is indeed 0 at and around that offset. An example:

loopup("gophers50449"), datalen=0xc000 headOff=0x144 head=0x7ae0

with file content

00006ff0  67 6f 70 68 65 72 73 33  38 33 00 00 00 00 00 00  |gophers383......|
00007000  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
00008000  01 00 00 00 00 00 00 00  0a 00 00 ff e0 63 00 00  |.............c..|
00008010  67 6f 70 68 65 72 73 35  31 31 00 00 00 00 00 00  |gophers511......|

Another one

loopup("gophers972"), datalen=0xc000 headOff=0x340 head=0xb0e0

with file content

0000aff0  67 6f 70 68 65 72 73 39  31 32 00 00 00 00 00 00  |gophers912......|
0000b000  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
0000b300  01 00 00 00 00 00 00 00  0a 00 00 ff 20 ab 00 00  |............ ...|
0000b310  67 6f 70 68 65 72 73 39  33 37 00 00 00 00 00 00  |gophers937......|

In all cases I saw, it is always the beginning area of the last physical page (4K size on the machine) in a logical page (16K size), i.e. starting at address 0x...3000, 0x...7000, 0x...b000, or 0x...f000. Sometime a whole page (e.g. 0x7000-0x8000 in the first example), sometimes only the beginning area (e.g. 0xb000-0xb300 in the second one).

This gives me a feeling that there is something weird going on with the file system, when there are concurrent file extension, WriteAt, and mmap's. On the builder machine, it has TMPDIR=$HOME/tmp set by default, which is on an ext4 file system. I tried setting GOTMPDIR=/tmp, which is tmpfs, and the test does not fail.

I'm not an expert on Linux file system implementation, but here is my hunch: In m.extend, we WriteAt the last four bytes of the logical page to extend the file size. With the concurrent WriteAt and mmap, maybe the kernel puts the write into some buffer (perhaps 4K size), and that buffer is not what a concurrent mmap sees when it writing new entries to it. And later the write buffer is flushed, which overwrites the file content as zeros, just that last page. Then an mmap'd load from that area gets all zeros, and crashes. When it fails, it is always both prog1 and prog2 fail, at offsets close to each other in the same 4K range. So I think it is not the synchronization between the two processes (e.g. due to bad atomics). The two processes' mmap are coherent, but not coherent with the file system, so both saw corruption.

With tmpfs, it is probably that the file write and the mmap are always in the same memory, so it is conherent.

Not sure why the failure is specific to the RISCV builders. Could be different file systems (many builders are VMs, whereas the RISCV ones may be physical hardwares?), or could be related to a specific version of the ext4 implementation (I've seen 6.14.0-28-generic #28.1~24.04.1-Ubuntu and 6.6.88-win2030 #2025.08.14.16.08+bf2ec5d53 kernels on the RISCV gomote). Or could be that the file system implementation on RISCV has some race conditions (due to atomics being too weak?).

I tried to add more synchronizations, like sprinkling f.Sync and Msync here and there, and open the file with O_SYNC, but it still fails. man 2 open says

Likewise, applications should avoid mixing mmap(2) of files with direct I/O to the same files.

It reads like there could be coherence issues, such as what we saw (I'm not sure "direct I/O" means O_DIRECT specifically, or more general read/write I/O). But I'm also not sure what is the best way to safely extend the file's size concurrently with each other and with concurrent mmaps. (We can't use f.Truncate to extend the file as we do in the linker, as it may shrink the file under race condition.)

cc @aclements for insights about Linux file system implementations.

[cherrymui]

To work around this, I hacked up a synchronization protocol, to ensure that the file can only be extended by one process a time, and other processes won't do another extension until observing the updated file size (so it won't be extending the same range). This seems to work. This also makes it possible to use Truncate to extend the file (as we won't extend the file n overlapping ranges or under race condition), although the protocol (or a slight variation of it) probably also works with extending with WriteAt. CL 711096 does this.

Without this, the test fails on riscv64 gomote under stress in O(minutes) with O(100) runs. With the patch, it doesn't fail in a few hours, with a few thousands runs.

This may require updating the file format version, which seems a bit heavy-weighted. It might be possible to squeeze the field into the existing format.

Another workaround is, instead of skipping over just the last record in a (logical) page, skipping over a full physical page. I.e. for the case of RISCV, skip over the last 4K range in every 16K. This may not work well in general as on some systems the physical page size can be pretty big (e.g. 64K). I'm also not sure if the file's write buffer size is always a physical page.

[gopherbot]

Change https://go.dev/cl/711096 mentions this issue: internal/counter: synchronize file extension

[cherrymui]

(Discussed with @aclements offline. Post here for records.)

Looking more into how the failure occurs: with debug prints (without applying the CL), here is the log of a failure execution, where the corruption is at 0x27140. (offsets and sizes are all hex)

    timestamp                 prog1                        prog2
---------------------------------------------------------------------------
00:35:22.625666426   extend(28000)
00:35:22.625745428   stat size=24000
00:35:22.625765179   before WriteAt 27ffc
00:35:22.625880182                               extend(28000)
00:35:22.625938433                               stat size=28000
00:35:22.626028186                               before mmap
00:35:22.626100687                               after mmap, datalen=28000
00:35:22.649483796   after WriteAt 27ffc
00:35:22.649978559   before mmap
00:35:22.650255566   after mmap, datalen=28000

What happened is that prog1 wanted to extend the file and did an WriteAt. Shortly after the WriteAt started but not finished, prog2 concurrently wanted to extend the file, and observed the new file size, and directly went ahead to the mmap. prog1's WriteAt returned later. (We originally thought it was due to both processes concurrently doing WriteAt. This could occur, but it can still fail without it.)

Apparently, with the concurrent WriteAt and mmap, the write buffer and the mmap didn't get the same memory. It went ahead writing more data into the mmap. At a later time, the write buffer flushed (the whole physical page, not just the four bytes we actually wrote) and zeroed the data that were written to the mmap.

By extending the file with Truncate, it presumably won't have a write buffer. So it is fine for concurrent processes to observe the size update and go ahead mmap, even if the Truncate call hasn't returned. Problem is that we need to synchronize the Truncate, to make sure it only extends, never shrinks.

The synchronization protocol on the CL does this. A problem is that it is not fault tolerant. If a process crashes during the execution of the critical section, the file will appear "locked", and other processes won't be able to make progress. One possibility is to use some lockfile mechanism, where the kernel will clear the lock if the process dies.

[findleyr]

This code is very complicated. It will take me a while to page it back in... no pun intended.

While we're looking at this, I don't understand this comment that I wrote in m.place:
https://github.com/golang/telemetry/blob/5be28d7074430e24ae185929d0bc13d7bb1137ad/internal/counter/file.go#L544

	// Note: Checking for crossing a page boundary would be
	// start/pageSize != (start+n-1)/pageSize,
	// but we are checking for reaching the page end, so no -1.
	// The page end is reserved for use by extend.
	// See the comment in m.extend.

Uh, shouldn't we be checking start+n+4, to allow for the four bytes that are zeroed out to extend the page? That certainly looks like a potential source of corruption, independent of the reported filesystem issues.

I've been reading about the problem of mixing I/O with mmap, and it does seem fundamentally fraught.

@cherrymui one thing that I'm not sure about: based on your description of the problem, it sounds like writing the 4 bytes with O_DIRECT might actually avoid the problem, since it bypasses the page cache? Is it easy for you to try that? (I don't have an easy reproducer).

[cherrymui]

shouldn't we be checking start+n+4, to allow for the four bytes that are zeroed out to extend the page?

I think (start+n-1)/pageSize (happens to) work because the record is 32-byte long and 32-byte aligned. So it cannot end at anywhere in the middle of those 4 bytes. I.e., a record either does not overlap with those 4 bytes, or completely contains them, and the check avoids the latter.

it sounds like writing the 4 bytes with O_DIRECT might actually avoid the problem, since it bypasses the page cache?

Yes, I tried, and it fails very quickly even without concurrency, and even on an AMD64 machine (as long as TMPDIR or GOTMPDIR is ext4 (or perhaps other disk-based file systems), not tmpfs, e.g. GOTMPDIR=$HOME/tmp go test -run=ConcurrentExt ./internal/counter/). I didn't look into the details as the manapage seems to clearly discourage using O_DIRECT along with mmap.

It would be great if we could avoid synchronization, since the format tries so hard to avoid it

I agree that this would be great. Unfortunately, the current mechanism is based on the assumption that concurrent WriteAt and mmap are safe, which is not actually true. If we really want to do this, perhaps we can go with the other workaround mentioned in #75809 (comment) :

Another workaround is, instead of skipping over just the last record in a (logical) page, skipping over a full physical page. I.e. for the case of RISCV, skip over the last 4K range in every 16K.

I'm not sure if the buffer size is always a physical page size, though. And if the physical page size is large, we may have to increase the logical page size.