Writing to NFS interfere with other threads in the same process

[Elias Näslund <elias.naslund@xxxxxxxxxxxxxxxx>]

In an embedded application we're running a Yocto based linux distrubution with RT patches. One thread is writing data to a file on a NFS and another thread is once every second running chronyc tracking with popen.
The hardware is a dual core ARM with 1 gb of memory.

The problem is that chronyc tracking doesn't return within 100 ms if both threads runs in the same application. If, however, each thread runs in its own process it works as expected. It takes normally 10-20ms for chronyc tracking to return.

Tested without the RT patches with the same behavior.
Tested 4.x, 5.x and 6.x kernel with the same behavior.
Writing to a sd card works as expected.
Writing to sshfs filesystem works as expected.
Tested RT prio 70 (chrt 70 timeout 0.1 chronyc tracking) without improvement.

Full source code of test application is available at https://github.com/eliasnaslund/files/blob/master/nfs-chronyc-interfere/main.cpp

void tracking()
{
	while (!done)
	{
		auto res = command("timeout 0.1 chronyc tracking");
		std::cout << "chrony " << res << "\n";

		std::this_thread::sleep_for(std::chrono::seconds(1));
	}
}

void write_file()
{
	while (!done)
	{
		std::ofstream file;
		file.open(path);

		for (int i = 0; i < 100000; i++)
			file << "lmno..."
		file.close();
	}
}

std::thread t1(tracking);
std::thread t2(write_file);
std::this_thread::sleep_for(std::chrono::minutes(2));
done = true;
t1.join();
t2.join();


Perf shows (full log at https://github.com/eliasnaslund/files/blob/master/nfs-chronyc-interfere/perf-nfs.txt):
chronyc  4123/4123  [001]  2057.379201:          1     sched:sched_switch: prev_comm=chronyc prev_pid=4123 prev_prio=120 prev_state=R+ ==> next_comm=rcu_preempt next_pid=15 next_prio=98
    c0b5783c __schedule ([kernel.kallsyms])
    c0b5783c __schedule ([kernel.kallsyms])
    c0b57fb8 preempt_schedule_irq ([kernel.kallsyms])
    c0100c0c svc_preempt ([kernel.kallsyms])
    c04163f0 nfs_page_clear_headlock ([kernel.kallsyms])
    c04167e0 __nfs_pageio_add_request ([kernel.kallsyms])
    c0417300 nfs_pageio_add_request ([kernel.kallsyms])
    c041b664 nfs_page_async_flush ([kernel.kallsyms])
    c041b9d0 nfs_writepages_callback ([kernel.kallsyms])
    c026b88c write_cache_pages ([kernel.kallsyms])
    c041bb28 nfs_writepages ([kernel.kallsyms])
    c026de78 do_writepages ([kernel.kallsyms])
    c025fd8c filemap_fdatawrite_wbc ([kernel.kallsyms])
    c02604bc filemap_write_and_wait_range ([kernel.kallsyms])
    c041c484 nfs_wb_all ([kernel.kallsyms])
    c040c9b4 nfs_file_flush ([kernel.kallsyms])
    c02e08b4 filp_close ([kernel.kallsyms])
    c0309014 put_files_struct ([kernel.kallsyms])
    c012b2f8 do_exit ([kernel.kallsyms])
    c012bb1c do_group_exit ([kernel.kallsyms])
    c012bb80 __wake_up_parent ([kernel.kallsyms])

In the perf log a separate process is also shown as chronyc2 (symlink to chronyc) that executes in another thread:
while true; do chronyc2 tracking >/dev/null; done

It can be seen that several chronyc2 successfully runs before chronyc times out.
E.g:
Line  7603: chronyc   3950  start
Line 10936: chronyc2  3978  start
Line 21568: chronyc2  3978  stop
Line 23820: chronyc2  3979  start
Line 24908: chronyc2  3979  stop
Line 25990: chronyc2  3980  start
Line 27601: chronyc2  3980  stop
Line 28305: chronyc2  3981  start
...
Line 129550: chronyc  3950  stop


Strace is also available at https://github.com/eliasnaslund/files/blob/master/nfs-chronyc-interfere/stracelog.log.