Unnecessary stat()s in external audio & subtitle scans make playback start slow (~50 seconds)

[chkno]

Bug report

Describe the bug

Here is a clear and concise description of what the problem is:

On TV show playback start, Kodi calls stat() on every media file and thumbnail in the same directory as the media file selected for playback, one file at a time. This can delay playback start significantly, especially when playing from a networked filesystem where a stat() call can take 10ms. For example:

792 episodes * 2 files/episode (media and thumbnail) * 3 stats/file (two scans for subtitles + a scan for separate audio) * 10ms = 47 seconds, a long time to display the loading spinner waiting for playback to begin.

Splitting by seasons helps a little bit: 365 episodes * 2 * 3 * 10ms = 22 seconds, but it's still quite a delay.

These stat calls are unnecessary. After collecting all this stat info, ScanPathsForAssociatedItems filters by filename and discards all of it that's not related to the media being played. The filenames are collected by the much, much faster getdents call -- the stat data from all the other files is never used.

Two example stack traces of these stat calls:

$ gdb path/to/kodi 12345 # Attached while the playback-starting spinner is displayed
...
(gdb) break stat
(gdb) c
...
Thread 26 "VideoPlayer" hit Breakpoint 1, 0x00007f5bc5d34120 in stat64 () from /nix/store/q29bwjibv9gi9n86203s38n0577w09sx-glibc-2.33-117/lib/libc.so.6
(gdb) bt
#0  0x00007f5bc5d34120 in stat64 () from /nix/store/q29bwjibv9gi9n86203s38n0577w09sx-glibc-2.33-117/lib/libc.so.6
#1  0x0000000000de032a in XFILE::CPosixDirectory::GetDirectory(CURL const&, CFileItemList&) ()
#2  0x0000000001d53dab in XFILE::CDirectory::GetDirectory(CURL const&, std::shared_ptr<XFILE::IDirectory> const&, CFileItemList&, XFILE::CDirectory::CHints const&) ()
#3  0x0000000001d54fb3 in XFILE::CDirectory::GetDirectory(CURL const&, CFileItemList&, XFILE::CDirectory::CHints const&) ()
#4  0x0000000001d550ef in XFILE::CDirectory::GetDirectory(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, CFileItemList&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int) ()
#5  0x000000000178c594 in CUtil::GetItemsToScan(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&, CFileItemList&) ()
#6  0x000000000178ea17 in CUtil::ScanForExternalDemuxSub(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >&) ()
#7  0x0000000000e9a661 in CDVDFactoryInputStream::CreateInputStream(IVideoPlayer*, CFileItem const&, bool) ()
#8  0x0000000000f757b9 in CVideoPlayer::OpenInputStream() ()
#9  0x0000000000f7a952 in CVideoPlayer::Prepare() ()
#10 0x0000000000f7d99f in CVideoPlayer::HandleMessages() ()
#11 0x0000000000f7ebbc in CVideoPlayer::Process() ()
#12 0x0000000001281d85 in CThread::Action() ()
#13 0x0000000001284edb in ?? ()
#14 0x0000000001285de6 in ?? ()
#15 0x00007f5bc5b49c50 in ?? () from /nix/store/18fz9jnhmfkzkh6p1iwwwng4i7x4rag7-gcc-10.3.0-lib/lib/libstdc++.so.6
#16 0x00007f5bc7063d40 in start_thread () from /nix/store/q29bwjibv9gi9n86203s38n0577w09sx-glibc-2.33-117/lib/libpthread.so.0
#17 0x00007f5bc5d4403f in clone () from /nix/store/q29bwjibv9gi9n86203s38n0577w09sx-glibc-2.33-117/lib/libc.so.6

and

#0  0x00007f5bc5d34120 in stat64 () from /nix/store/q29bwjibv9gi9n86203s38n0577w09sx-glibc-2.33-117/lib/libc.so.6
#1  0x0000000000de032a in XFILE::CPosixDirectory::GetDirectory(CURL const&, CFileItemList&) ()
#2  0x0000000001d53dab in XFILE::CDirectory::GetDirectory(CURL const&, std::shared_ptr<XFILE::IDirectory> const&, CFileItemList&, XFILE::CDirectory::CHints const&) ()
#3  0x0000000001d54fb3 in XFILE::CDirectory::GetDirectory(CURL const&, CFileItemList&, XFILE::CDirectory::CHints const&) ()
#4  0x0000000001d550ef in XFILE::CDirectory::GetDirectory(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, CFileItemList&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int) ()
#5  0x000000000178c594 in CUtil::GetItemsToScan(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&, CFileItemList&) ()
#6  0x00000000017905f5 in CUtil::ScanForExternalAudio(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >&) ()
#7  0x0000000000e9a656 in CDVDFactoryInputStream::CreateInputStream(IVideoPlayer*, CFileItem const&, bool) ()
#8  0x0000000000f757b9 in CVideoPlayer::OpenInputStream() ()
#9  0x0000000000f7a952 in CVideoPlayer::Prepare() ()
#10 0x0000000000f7d99f in CVideoPlayer::HandleMessages() ()
#11 0x0000000000f7ebbc in CVideoPlayer::Process() ()
#12 0x0000000001281d85 in CThread::Action() ()
#13 0x0000000001284edb in ?? ()
#14 0x0000000001285de6 in ?? ()
#15 0x00007f5bc5b49c50 in ?? () from /nix/store/18fz9jnhmfkzkh6p1iwwwng4i7x4rag7-gcc-10.3.0-lib/lib/libstdc++.so.6
#16 0x00007f5bc7063d40 in start_thread () from /nix/store/q29bwjibv9gi9n86203s38n0577w09sx-glibc-2.33-117/lib/libpthread.so.0
#17 0x00007f5bc5d4403f in clone () from /nix/store/q29bwjibv9gi9n86203s38n0577w09sx-glibc-2.33-117/lib/libc.so.6

Expected Behavior

Here is a clear and concise description of what was expected to happen:

Playback should start quickly, showing a spinner for less than 1 second.

Actual Behavior

A loading spinner is displayed for 10s of seconds before playback begins. Playback start gets slower and slower as more episodes are added.

Possible Fix

Stat lazily? Pass a path prefix to GetItemsToScan?

To Reproduce

Steps to reproduce the behavior:

1. Create a TV show library with many episodes.
2. Mount it via a network filesystem.
3. Play one of the episodes in Kodi.

Debuglog

The debuglog can be found here: kodi-slow.log

Also, here's an strace log showing 4781 sequential stats from one thread (average stat time 11.5 ms), statting every file three times, blocking playback start for 55 seconds:
kodi-slow-one-thread-strace.log

Additional context or screenshots (if appropriate)

Here is some additional context or explanation that might help:

It looks like #20471 (scan for external subtitles once instead of twice) will reduce the delay by a third (3 scans → 2 scans) when it makes its way into a release. This will help reduce the impact of this, but doesn't address the core problem that unrelated files are unnecessarilly stated.

Your Environment

Used Operating system:

• Android

• iOS

• tvOS

• Linux

• OSX

• Windows

• Windows UWP

• Operating system version/name: NixOS 21.11.334247.573095944e7

• Kodi version: 19.4

note: Once the issue is made we require you to update it with new information or Kodi versions should that be required.
Team Kodi will consider your problem report however, we will not make any promises the problem will be solved.

[asinitial]

2022-03-26 19:33:02.977 T:20136   DEBUG <general>: CUtil::ScanForExternalSubtitles: Searching for subtitles...
2022-03-26 19:33:02.977 T:20136   DEBUG <general>: CurlFile::Open(0xac6e0fc210) https://***.com/d/UA5GEURUH6OVY66/
2022-03-26 19:33:02.977 T:20136   DEBUG <general>: XCURL::DllLibCurlGlobal::easy_acquire - Created session to https://***.com
2022-03-26 19:33:04.087 T:7620    DEBUG <general>: ------ Window Init (Pointer.xml) ------
2022-03-26 19:33:09.622 T:7620    DEBUG <general>: ------ Window Deinit (Pointer.xml) ------
2022-03-26 19:33:31.098 T:5700    DEBUG <general>: Thread JobWorker 5700 terminating (autodelete)
2022-03-26 19:33:31.098 T:17920   DEBUG <general>: Thread JobWorker 17920 terminating (autodelete)
2022-03-26 19:33:31.098 T:3244    DEBUG <general>: Thread JobWorker 3244 terminating (autodelete)
2022-03-26 19:34:09.314 T:19000   DEBUG <general>: CAESinkDirectSound::Deinitialize: Cleaning up
2022-03-26 19:34:41.433 T:7620    DEBUG <general>: Keyboard: scancode: 0x0f, sym: 0x9, unicode: 0x0000, modifier: 0x0
2022-03-26 19:34:41.434 T:7620    DEBUG <general>: ------ Window Init (Pointer.xml) ------
2022-03-26 19:34:42.033 T:7620    DEBUG <general>: Keyboard: scancode: 0x38, sym: 0x308, unicode: 0x0000, modifier: 0x256
2022-03-26 19:34:42.034 T:7620    DEBUG <general>: CInputManager::HandleKey: alt-leftalt (0x4f0d4) pressed, action is 
2022-03-26 19:34:47.118 T:7620    DEBUG <general>: ------ Window Deinit (Pointer.xml) ------
2022-03-26 19:34:47.652 T:7620    DEBUG <general>: ------ Window Init (Pointer.xml) ------
2022-03-26 19:34:53.069 T:7620    DEBUG <general>: ------ Window Deinit (Pointer.xml) ------
2022-03-26 19:35:32.809 T:7620    DEBUG <general>: ------ Window Init (Pointer.xml) ------
2022-03-26 19:35:50.779 T:7620    DEBUG <general>: ------ Window Deinit (Pointer.xml) ------
2022-03-26 19:36:10.389 T:20136   ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2022-03-26 19:36:10.389 T:20136 WARNING <general>: CCurlFile::FillBuffer - Reconnect, (re)try 1
2022-03-26 19:36:11.409 T:20136   DEBUG <general>: CUtil::ScanForExternalSubtitles: END (total time: 188434 ms)

Same here, it looks like Kodi also tries to download the whole file from the HTTPS server to scan for subtitles, then load the video, and the process lasting time depends on the file size.

Kodi Version: 19.4
OS: Windows 10 pro

[chkno]

I think I'm pointing at a narrower problem than asinitial is? I'm specifically pointing at the problem of PosixDirectory (as invoked by ScanForExternalAudio) doing a whole bunch of unnecessary, repeated, uncached stat calls on symlinks in the local filesystem on GNU/Linux.

I can work around the performance problem with this kludge:

--- a/xbmc/platform/posix/filesystem/PosixDirectory.cpp
+++ b/xbmc/platform/posix/filesystem/PosixDirectory.cpp
@@ -25,6 +25,22 @@ CPosixDirectory::CPosixDirectory(void) = default;
 
 CPosixDirectory::~CPosixDirectory(void) = default;
 
+// Until C++20
+static bool endsWith(const std::string& s, const std::string& suffix)
+{
+    return s.size() >= suffix.size() && s.compare(s.size() - suffix.size(), suffix.size(), suffix) == 0;
+}
+
+// Live dangerously!  Boldly assume that names ending in these extensions are files
+// and not directories!  We do this because these stat calls to confirm the file type
+// are sooooo slooooooooooow, and just make using Kodi not very much fun.  :(
+static bool dangerouslyAssumeIsFile(const std::string& name) {
+  for (auto &ext : { ".ass", ".avi", ".jpg", ".mkv", ".mp4", ".mpeg", ".ogm", ".ssa", ".webm", ".webp"})
+    if (endsWith(name, ext))
+      return true;
+  return false;
+}
+
 bool CPosixDirectory::GetDirectory(const CURL& url, CFileItemList &items)
 {
   std::string root = url.Get();
@@ -54,7 +70,7 @@ bool CPosixDirectory::GetDirectory(const CURL& url, CFileItemList &items)
     // is not equal to the (correct) stat() obtained one. In this case the file type
     // could not be determined and the value of dirent.d_type is set to DT_UNKNOWN.
     // In order to get a correct value we have to incur the cost of calling stat.
-    if (entry->d_type == DT_UNKNOWN || entry->d_type == DT_LNK)
+    if ((entry->d_type == DT_UNKNOWN || entry->d_type == DT_LNK) && !dangerouslyAssumeIsFile(entry->d_name))
     {
       if (stat(itemPath.c_str(), &buffer) == 0)
         bStat = true;