Re: Checking special execution durations for the determination of mountable file systems

[Adhemerval Zanella <adhemerval.zanella@linaro.org>]

On Sun, Sep 19, 2021 at 3:41 AM Markus Elfring via Libc-help
<libc-help@sourceware.org> wrote:
>
> Hello,
>
> I came along the need to check unexpected software execution durations
> at another place.
>
> * Qt
>    https://doc.qt.io/qt-5/qstorageinfo.html#mountedVolumes
>
> * KPMcore
>    https://github.com/KDE/kpmcore/blob/ce39e149040bce9782b91e532d041ca0c7548a77/src/fs/filesystem.cpp#L145
>
> Example:
> [Markus_Elfring@fedora mountedVolumes]$ time ./mountedVolumes
> Number of eventually mounted filesystems: 43
>
> real    3m3,561s
> user    0m0,016s
> sys    0m0,026s
>
>
> I increased software analysis efforts accordingly.
> https://github.com/namhyung/uftrace/
>
> [Markus_Elfring@fedora mountedVolumes]$ time sudo uftrace record --data=/home/Markus_Elfring/Test/mountedVolumes/Probe-uftrace/ --nest-libcall --kernel --num-thread=4 ./mountedVolumes
> Number of eventually mounted filesystems: 42
>
> real    3m4,835s
> user    0m0,346s
> sys    0m3,549s
>
>
> [Markus_Elfring@fedora ~]$ uftrace --data=Test/mountedVolumes/Probe-uftrace report --filter=QStorageInfo::mountedVolumes
>    Total time   Self time       Calls  Function
>    ==========  ==========  ==========  ====================
>      3.000  m  478.403 us           1  QStorageInfo::mountedVolumes
>      3.000  m   38.261 us          90  QStorageInfo::QStorageInfo
>      3.000  m   10.244 ms          48  QStorageInfo::setPath
>      3.000  m    3.000  m          23  linux:schedule
>      3.000  m    1.030  m          48  statvfs64
>      1.030  m    1.315 ms          47  __x64_sys_statfs
>     45.887 ms    5.746 ms         944  QDirIterator::next
>     28.768 ms    3.691 ms         944  QFileInfo::symLinkTarget
>     19.421 ms    1.246 ms        3185  fgets
>     18.845 ms  659.323 us        1900  QFileInfo::isFile
>     18.035 ms    1.207 ms         950  statx
> …
>
>
> Another bit of background information:
> The function “statvfs64” gets called by the function “QStorageInfoPrivate::retrieveVolumeInfo” (which is called by the function “QStorageInfoPrivate::doStat” and so on).
> https://github.com/bminor/glibc/blob/595c22ecd8e87a27fd19270ed30fdbae9ad25426/sysdeps/unix/sysv/linux/statvfs64.c#L27
> https://code.woboq.org/qt5/qtbase/src/corelib/io/qstorageinfo_unix.cpp.html#_ZN19QStorageInfoPrivate18retrieveVolumeInfoEv
> https://code.woboq.org/qt5/qtbase/src/corelib/io/qstorageinfo_unix.cpp.html#_ZN19QStorageInfoPrivate14mountedVolumesEv
>
>
> Would you like to help with the clarification for the shown measurements?

The statvfs() calls statfs() which in turn is a syscall. There is some
memory copy involved on __internal_statvfs64(),
but it's runtime should be negligible. I would check with Linux perf
with kernel probing enabled to see exactly
what is happening.