Checking special execution durations for the determination of mountable file systems

Checking special execution durations for the determination of mountable file systems

[Markus Elfring]

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?

Regards,
Markus

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

[Adhemerval Zanella]

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.

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

[Markus Elfring]

> 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.

Are any test cases available for these functions?


Which impression did you get from the displayed execution durations?


> I would check with Linux perf with kernel probing enabled to see exactly
> what is happening.

I can eventually increase the tracing depth for the analysis tool “uftrace”
(if further details from Linux function calls would be really helpful
for such a clarification approach).

Regards,
Markus

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

[Adhemerval Zanella]

On Sun, Sep 19, 2021 at 11:04 AM Markus Elfring <Markus.Elfring@web.de> wrote:
>
> > 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.
>
> Are any test cases available for these functions?

We have some very basic tests (io/tst-statvfs.c) and statfs is used
internally for pathconf (_PC_NAME_MAX),
but besides there is not much coverage. It might be possible to
cross-reference procfs/sysfs information with
the syscall returns information to check if it behaves correctly.

The LTP [1] has more tests testcases/kernel/syscalls/statfs/statfs0*.c and
testcases/kernel/syscalls/statvfs/statvfs0*.c but I am not sure which
is the total coverage.

>
>
> Which impression did you get from the displayed execution durations?

That is something in the kernel, since glibc is just a wrapper over the syscall.

>
>
> > I would check with Linux perf with kernel probing enabled to see exactly
> > what is happening.
>
> I can eventually increase the tracing depth for the analysis tool “uftrace”
> (if further details from Linux function calls would be really helpful
> for such a clarification approach).

If kernel it is still the culprit here as I think it is, it would be
better to check with kernel developers what
might be happening here. My wild guess is

>
> Regards,
> Markus

[1] https://github.com/linux-test-project/ltp

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

[Florian Weimer]

* Markus Elfring via Libc-help:

> I can eventually increase the tracing depth for the analysis tool “uftrace”
> (if further details from Linux function calls would be really helpful
> for such a clarification approach).

Have you configured any remote or otherwise special file systems?

Thanks,
Florian

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

[Adhemerval Zanella]

On Mon, Sep 20, 2021 at 10:25 AM Florian Weimer <fweimer@redhat.com> wrote:
>
> * Markus Elfring via Libc-help:
>
> > I can eventually increase the tracing depth for the analysis tool “uftrace”
> > (if further details from Linux function calls would be really helpful
> > for such a clarification approach).
>
> Have you configured any remote or otherwise special file systems?

Indeed this is my wild guess (I hit the send button before adding it).

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

[Markus Elfring]

> Have you configured any remote

No. (Not yet for the affected local storage devices.)


> or otherwise special file systems?

Would you find file system types ordinary (like the following)?
* ext4
* ext3
* exFAT
* FAT16
* NTFS

Regards,
Markus