Querying the local database is sometimes slow

[wshanks]

The first time I run yaourt -Syua each day it takes a long time (20-60 seconds) before prompting for a password for sudo. I did some profiling and narrowed it down to this command:

package-query --aur-url https://aur.archlinux.org -Qdtf %n --sort n

It seems like the first time I run that command each day it is slow and then after that it is fast (less than half a second), though I'm not sure it is exactly once a day.

I think the --aur-url ... is just there because of the way yaourt wraps package-query and doesn't do matter here because this is a local database query (if it were connecting to the aur I could understand the variable time). Do you have any idea why the speed varies like this? I thought maybe a large shared library could be getting loaded and cached into memory and that was why subsequent tries were fast, but package-query and all of its dependencies seem very small.

[f2404]

Well, you're asking yaourt to sync AUR database by passing the -a parameter. Can you try it without -a (yaourt -Syu) and see if it makes any difference?

But I'm thinking this could probably be related to sudo, see for example https://serverfault.com/questions/38114/why-does-sudo-command-take-long-to-execute.

[wshanks]

I see the same behavior for yaourt -Syu. I am running yaourt with this wrapper script:

exec {BASH_XTRACEFD}> >(tee yaourt.log | sed -u 's/^.*$/now/' | date -f - +%s.%N > yaourt.tim)
set -x
. /usr/bin/yaourt -Syu

I got this technique from a Stack Overflow answer. set -x causes bash to print every command before executing it. The first line exec redirects all of those commands to a file and records the time the command was executed with date. Looking at paste yaourt.tim yaourt.log, I see:

1501990838.271470125    + . /usr/bin/yaourt -Syu    
1501990838.271536873    ++ export TEXTDOMAINDIR=/usr/share/locale                                        
1501990838.271550173    ++ TEXTDOMAINDIR=/usr/share/locale 
...
1501990838.531342496    ++ prepare_status_list
1501990838.531361537    ++ (( SHOWORPHANS ))
1501990838.531382519    ++ pkgquery -Qdtf %n --sort n
1501990838.531554643    ++ package-query --aur-url https://aur.archlinux.org -Qdtf %n --sort n
1501990855.186345743    ++ cleanup_add rm /tmp/yaourt-tmp-willsalmanj/orphans.8941
...
1501990855.199693589    ++ is_sudo_allowed pacman --color auto -Sy
1501990855.199711396    ++ ((  SUDOINSTALLED  ))
1501990855.199726532    ++ ((  SUDONOVERIF  ))
1501990855.199740463    ++ ((  SUDOREDIRECT  ))
1501990855.199765935    ++ _is_sudo_allowed pacman --color auto -Sy
1501990855.199803246    ++ sudo -nl pacman --color auto -Sy

The last set of commands is the first time that sudo is used. Note that it comes after the slow down for package-query.

[wshanks]

Today I tried running package-query -Qdtf %n --sort n before running yaourt. The first time it took 31 seconds. I tried it a couple more times and it took 0.2 seconds each time after the frist.

[f2404]

Thanks for the update! Could you please run pacman -Qdt next time to see how fast it executes?

[wshanks]

pacman -Qdt is also slow. So I guess this is a pacman question rather than a package-query question?

[f2404]

I guess it could be the time required to load sync dbs into the memory. package-query is using pacman's library (libalpm) functions so it essentially comes to how db files are processed by the library. Does pacman command take the same time as package-query? If it does, then there's nothing I can do here.

[wshanks]

Yes, I don't think anything can be done by package-query to help with this. It seemed like the pacman command took the same time, but I didn't have good statistics.

If you think of anything else to try for debugging let me know, but I will close the issue now. I asked on the pacman mailing list and was told the command loads everything in /var/lib/pacman/local but still should be fast. I tried removing all orphaned packages plus some others I didn't need. I will see if that makes it faster (total number only dropped from 1700 to 1600).