Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Optimize "search-file" transaction #745

Open
sidt4 opened this issue Apr 26, 2024 · 6 comments
Open

Optimize "search-file" transaction #745

sidt4 opened this issue Apr 26, 2024 · 6 comments

Comments

@sidt4
Copy link
Contributor

sidt4 commented Apr 26, 2024

Current search-file transaction is very costly causing PK clients to wait for more than a minute. This has been discussed in https://gitlab.gnome.org/GNOME/gnome-software/-/issues/2280.

There are 2 cases where this issue is primarily seen:

  1. First search-file transaction after boot
  2. search-file transaction while disk I/O is in progress

Below are PK logs from 4 instances of GNOME Software starts after system boot in Debian unstable (apt backend). The first instance shows use case [1] explained above, and the fourth instance shows use case [2], when a VM disk write was in progress.

Log from journalctl -xb /usr/libexec/packagekitd | grep search-file:

Apr 25 20:21:51 linux PackageKit[4127]: search-file transaction /15_beeddcdb (/usr/share/metainfo/org.freedesktop.appstream.compose.metainfo.xml) from uid 1010 finished with success after 96861ms
Apr 25 20:21:52 linux PackageKit[4127]: search-file transaction /16_eedbcedc (/usr/share/applications/firefox-esr.desktop) from uid 1010 finished with success after 1167ms
Apr 25 20:21:53 linux PackageKit[4127]: search-file transaction /17_cdaeddcb (/usr/share/applications/google-chrome.desktop) from uid 1010 finished with success after 1134ms
Apr 25 20:21:54 linux PackageKit[4127]: search-file transaction /18_bbeecbcb (/usr/share/applications/empathy.desktop) from uid 1010 finished with success after 1120ms

Apr 25 20:22:14 linux PackageKit[4127]: search-file transaction /38_bcacccad (/usr/share/metainfo/org.freedesktop.appstream.compose.metainfo.xml) from uid 1010 finished with success after 1161ms
Apr 25 20:22:15 linux PackageKit[4127]: search-file transaction /39_dbebddac (/usr/share/applications/firefox-esr.desktop) from uid 1010 finished with success after 1136ms
Apr 25 20:22:16 linux PackageKit[4127]: search-file transaction /40_dadddebb (/usr/share/applications/google-chrome.desktop) from uid 1010 finished with success after 1171ms
Apr 25 20:22:18 linux PackageKit[4127]: search-file transaction /41_eddaadbb (/usr/share/applications/empathy.desktop) from uid 1010 finished with success after 1165ms

Apr 26 20:40:08 linux PackageKit[19561]: search-file transaction /17_adbdebcd (/usr/share/metainfo/org.freedesktop.appstream.compose.metainfo.xml) from uid 1010 finished with success after 1209ms
Apr 26 20:40:10 linux PackageKit[19561]: search-file transaction /18_caadedab (/usr/share/applications/firefox-esr.desktop) from uid 1010 finished with success after 1184ms
Apr 26 20:40:11 linux PackageKit[19561]: search-file transaction /19_eddaadda (/usr/share/applications/google-chrome.desktop) from uid 1010 finished with success after 1161ms
Apr 26 20:40:12 linux PackageKit[19561]: search-file transaction /20_ebaccbca (/usr/share/applications/empathy.desktop) from uid 1010 finished with success after 1181ms

Apr 26 21:01:08 linux PackageKit[23578]: search-file transaction /17_aadeccaa (/usr/share/metainfo/org.freedesktop.appstream.compose.metainfo.xml) from uid 1010 finished with success after 45707ms
Apr 26 21:01:10 linux PackageKit[23578]: search-file transaction /18_aedeeccb (/usr/share/applications/firefox-esr.desktop) from uid 1010 finished with success after 1537ms
Apr 26 21:01:11 linux PackageKit[23578]: search-file transaction /19_bcbeeada (/usr/share/applications/google-chrome.desktop) from uid 1010 finished with success after 1404ms

As explained in https://gitlab.gnome.org/GNOME/gnome-software/-/issues/2280#note_2064829, it would be good if we can cache and optimize the search-file transaction by looking up cache and using get-files transaction to speed up things.

As a start, we can use this optimization path when N=1 (when search-file as a single file argument)

@ximion
Copy link
Collaborator

ximion commented Apr 29, 2024

There is nothing PackageKit can do here, it's just a slow operation on most backends.

As explained in https://gitlab.gnome.org/GNOME/gnome-software/-/issues/2280#note_2064829, it would be good if we can cache and optimize the search-file transaction by looking up cache and using get-files transaction to speed up things.

Then over time we would have a massive, duplicated cache shadowing the one of the native package manager, and causing all kinds of synchronization issues. And if we would expire it often, it would not bring us any gains as we would have to hit the native PM a lot anyway and wait for a result.

Having frontends use search-file both async and sparingly is IMHO still far better than papering over the inherent slow-ness of this operation on most backends.

@sidt4
Copy link
Contributor Author

sidt4 commented Apr 29, 2024

Just compared the worst case execution times of search via dpkg and apt-file, which happens to be 5x faster.

Using dpkg -S:

# sync && echo 3 > /proc/sys/vm/drop_caches

# root@linux:~# time dpkg -S /usr/share/applications/org.gnome.Builder.desktop 
gnome-builder: /usr/share/applications/org.gnome.Builder.desktop

real	0m52.988s
user	0m1.172s
sys	0m1.687s

Using apt-file:

# sync && echo 3 > /proc/sys/vm/drop_caches
# time apt-file search /usr/share/applications/org.gnome.Builder.desktop 
gnome-builder: /usr/share/applications/org.gnome.Builder.desktop

real	0m9.738s
user	0m2.068s
sys	0m1.682s

Thoughts ?

@ximion
Copy link
Collaborator

ximion commented Apr 29, 2024

apt-file is an optional component which downloads at lest 20MB of extra data on every apt update. We can not expect apt-file to be present on all systems, so we can't really depend on it (AGAIk it also does not provide a convenient library to use).
10sec is still pretty slow. But the dpkg time feels insanely slow, I wonder why that is... It shouldn't be this slow.

$ time dpkg -S /usr/share/applications/org.kde.ark.desktop 
ark: /usr/share/applications/org.kde.ark.desktop

real    0m0,254s
user    0m0,163s
sys     0m0,089s

@sidt4
Copy link
Contributor Author

sidt4 commented Apr 29, 2024

10sec is still pretty slow. But the dpkg time feels insanely slow, I wonder why that is... It shouldn't be this slow.

Execution times are low after kernel caches FS pages (i.e from second run onwards, but the first search-file query will always be costly)

Using dpkg -S:

root@linux:~# sync && echo 3 > /proc/sys/vm/drop_caches
root@linux:~# time dpkg -S /usr/share/applications/org.gnome.Builder.desktop 
gnome-builder: /usr/share/applications/org.gnome.Builder.desktop

real	0m46.280s
user	0m1.003s
sys	0m1.199s

root@linux:~# time dpkg -S /usr/share/applications/org.gnome.Builder.desktop 
gnome-builder: /usr/share/applications/org.gnome.Builder.desktop

real	0m0.682s
user	0m0.471s
sys	0m0.211s

root@linux:~# time dpkg -S /usr/share/applications/org.gnome.Builder.desktop 
gnome-builder: /usr/share/applications/org.gnome.Builder.desktop

real	0m0.577s
user	0m0.404s
sys	0m0.173s

Using apt-file:

root@linux:~# sync && echo 3 > /proc/sys/vm/drop_caches
root@linux:~# time apt-file search /usr/share/applications/org.gnome.Builder.desktop 
gnome-builder: /usr/share/applications/org.gnome.Builder.desktop

real	0m8.728s
user	0m1.677s
sys	0m1.308s

root@linux:~# time apt-file search /usr/share/applications/org.gnome.Builder.desktop 
gnome-builder: /usr/share/applications/org.gnome.Builder.desktop

real	0m0.860s
user	0m0.881s
sys	0m0.513s

root@linux:~# time apt-file search /usr/share/applications/org.gnome.Builder.desktop 
gnome-builder: /usr/share/applications/org.gnome.Builder.desktop

real	0m0.940s
user	0m0.914s
sys	0m0.628s

@sidt4
Copy link
Contributor Author

sidt4 commented Apr 29, 2024

Having frontends use search-file both async and sparingly is IMHO still far better than papering over the inherent slow-ness of this operation on most backends.

We already do async + only 3 search-file calls on my Debian unstable.

Issue is the first search-file transaction will always run for 60 - 90 seconds (due to heavy un-cached disk I/O), and PK clients will have to wait for this single search-file transaction to complete (virtually blocking the UI). This is the case with GNOME Software (which has already removed almost all app .desktop file lookup from search-file transactions).

then over time we would have a massive, duplicated cache shadowing the one of the native package manager,

No. The idea was to keep the count low (max 10 entries per PK client with LRU cache). GNOME Software does search-file for exactly 1 file atm. The others are caused by external app issues. Refer https://gitlab.gnome.org/GNOME/gnome-software/-/issues/2280#note_2096855

and causing all kinds of synchronization issues.

Not sure what sync issues we would face here as every call to search-file would make sure the cache is in sync.

Sample code:

cache = {
    "/usr/share/metainfo/org.freedesktop.appstream.compose.metainfo.xml": "appstream-compose",
    "/usr/share/applications/firefox-esr.desktop": "firefox-esr",
    "/usr/share/applications/google-chrome.desktop": "google-chrome-stable",
    "/usr/share/applications/empathy.desktop": "empathy"
}

function search_file_cached (filename):
   pkg_name = lookup_cache (cache, filename):

   if pkg_name:
       # get-files(pkg_name) faster than search-file(filename)
       pkg_files = pk_client_get_files(pkg_name)

       if filename in pkg_files:
           return pkg_name

    # not-in-cache / cache-entry-invalid , do 'search-file' and update cache.
    pkg_name = pk_client_search_files (filename)

    # add / replace entry in cache.
    update_cache (cache, filename, pkg_name)

    return pkg_name

@sidt4
Copy link
Contributor Author

sidt4 commented May 2, 2024

Here is the worst case execution time of top 60 search-file transactions on my system over the past month.

The pattern clearly shows a sudden drop from 60 - 80 seconds to < 10 seconds, clearly indicating that kernel FS caching plays a major role in the performance of search-file transaction, and PK clients which depend on it.

Execution time of top 60 search-file transactions:

Execution time of 'search-file' transactions

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants