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.
On 24 Oct 2023, at 1:20, Elias Näslund wrote:
> 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.
The write_file() thread is queuing up a lot of async IO that is then
flushed by chronyc's do_exit -> put_files_struct -> filp_close, which will
be a synchronous wait for all that IO.
If that's not what you want I think you'll want to figure out how to drop
CLONE_FILES from std::thread's clone(2) syscall.
Ben
> The write_file() thread is queuing up a lot of async IO that is then flushed by chronyc's do_exit -> put_files_struct -> filp_close, which will be a synchronous wait for all that IO.
>
> If that's not what you want I think you'll want to figure out how to drop CLONE_FILES from std::thread's clone(2) syscall.
Thanks for the input. In reality the thread that writes to the NFS doesn't write that much data but enough data to interfere with chronyc tracking. I can see in wireshark that it takes over 100ms to send all data and by a coincident the writing happens at the same time as chronyc tracking. There are also several other threads in this application that we fear might be influenced as well.
I am a bit surprised that exiting of a thread will flush the NFS writes for another thread. Will have to use sshfs instead for now.