GNOME Bugzilla – Bug 166601
Cache timeout logic in Unix backend is broken
Last modified: 2005-07-20 00:04:59 UTC
Please describe the problem: When opening an open/save dialog and there is a large amount of files and directories in the visible directory, it takes unreasonably long time. For instance a folder with 2627 files and folders takes about 25 seconds. Steps to reproduce: 1. Start some application, in my case gedit 2. Click Open 3. Navigate to the big directory 4. Wait........ ;) Actual results: It takes a long time. Expected results: It should be quick. ;-) Does this happen every time? Yes Other information: I will attach strace output of my gedit run.
Created attachment 37122 [details] Strace of starting gedit, opening open dialog, closing, exiting
I think I gave you the wrong instructions; sorry about that :( Could you please do this: 1. Run gedit and figure out its PID 2. strace -f -ttt -p <pid> -o logfile 3. Invoke the File/Open dialog on the folder which takes a long time to load 4. Kill the strace 5. Attach the logfile here.
Created attachment 37263 [details] Jimmac's strace This is from Jimmac running Gimp. Doing "File/Open" can take a long time; visiting the same folder from an already-open file chooser is quick. Grep for "futex" near the end of the file. It blocks for 70 seconds (!) and then resumes. I wonder why that happens only when you pop up the dialog initially.
federico said on IRC that he would love to have two things: 1. a good strace log with timings and threads, both of opening a new file chooser and of setting the path in an existing one (also, possibly, of remapping an existing one like in the gimp) 2. a good ltrace to see what calls to gnome-vfs we are doing
I can not produce this right now, but will try to get this up soon. Sorry for the delay..,
*** Bug 167673 has been marked as a duplicate of this bug. ***
Here is an strace log from my test app on loading my home directory. http://vektor.ca/bugs/chooser-log.txt.bz2
This file corrupted: http://vektor.ca/bugs/chooser-log.txt.bz2 laurent@stan:~/tmp$ bunzip2 chooser-log.txt.bz2 bunzip2: Compressed file ends unexpectedly; perhaps it is corrupted? *Possible* reason follows. bunzip2: No such file or directory Input file = chooser-log.txt.bz2, output file = chooser-log.txt It is possible that the compressed file(s) have become corrupted. You can use the -tvv option to test integrity of such files. You can use the `bzip2recover' program to attempt to recover data from undamaged sections of corrupted files. bunzip2: Deleting output file chooser-log.txt, if it exists.
Created attachment 38098 [details] Laurent's galeon "save as" trace This was generated using Galeon's save as. The default directory to save in was ~/tmp so it's interesting to see that it first tries to open every file in ~/ before processing ~/tmp. It seems to open the files and read a block, so it's no wonder it's so slow the 1st time.
I also ran ltrace like this: ltrace -f -ttt -p 8355 --library=/usr/lib/libgnomevfs-2.so.0 -o filechooser.ltrace It only gave this: 8355 1109690103.339839 --- UNKNOWN_SIGNAL (Unknown signal 32) --- 8355 1109690103.340926 --- UNKNOWN_SIGNAL (Unknown signal 32) --- 9101 1109690103.360903 +++ exited (status 0) +++ 8355 1109690103.377388 --- SIGCHLD (Child exited) --- 8355 1109690103.393058 gnome_vfs_unescape_string(0x93ffac0, 0, 32, 0x400ea2fc, 0x9103d00) = 0x93014a8 9102 1109690103.394881 +++ exited (status 0) +++ 8355 1109690103.394946 --- SIGCHLD (Child exited) --- 8355 1109690103.509866 gnome_vfs_expand_initial_tilde(0x93ffac0, -1, 0, 0, 0) = 0x93a4a10 8355 1109690103.510130 gnome_vfs_expand_initial_tilde(0x93ffac0, -1, 0, 0, 0) = 0x932eee8 8355 1109690103.510231 gnome_vfs_expand_initial_tilde(0x932f078, -1, 0, 0, 0) = 0x9541428 8355 1109690103.513089 gnome_vfs_expand_initial_tilde(0x932eee8, -1, 0, 0, 0) = 0x93a4a10 8355 1109690107.617543 gnome_vfs_mime_application_free(0, 0x8bf30c8, 1, 0x8195850, 0x93c3820) = 0
I've been debugging a little and it looks like xdg_mime_get_mime_type_for_file opens the file if it can't get the mime-type from the file name. Returning after xdg_mime_get_mime_type_from_file_name() seems to fix the problem but is not a long term solution.
The URL above works fine for me to get the log and uncompress it using bunzip2 version 1.0.2.
Making any real progress here will likely require to use a 2-phase approach to mime type detection: while populating the file list, guess the mime type based only on the filename, and then do whatever mime sniffing is necessary in the background, updating the icons as we go.
See also bug #302322 and bug #154394.
In my case (bug 302322), the annotated trace shows that the mime stuff is *not* to blame. It only kicks in once in a while, namely for extensions that are not recognized. The culprit is doing everything twice.
There is a bug in gtk_file_system_unix_get_folder that means that if loading ends up taking more than 2s, it will likely take a whole lot more than 2s. Basically, in the case where we assign to ->asof, we should do so *after* filling in stats and mimes and using a then-current timestamp. (But note, that we cannot simply move the assignment down -- it still has to be done under the same condition.) Without this change, the cache can be stale from the time it is filled in. Not good.
Morten, why don't you attach a patch instead of writing a long explanation what needs to change ?
Because my tree is currently polluted with, among other things, all the annotation Federico asked me to do for bug 302322...
So, uh, checkout another tree to work on?
Guys, I'll do it in due time. (Yosh: no, that'll blow my inode quota. Yes, that is so 80ish.)
Created attachment 45836 [details] [review] Patch according to Mortens instructions (I hope) I attach my interpretation of Mortens patch instructions. Feel free to laugh at me if I completely misunderstood / did something stupid. :-)
However, I have noticed that the problem appears to be mostly(?) fixed with gtk 2.6.7 (or some other library upgrade since the bug was reported) even without any further patches...
Created attachment 45842 [details] [review] Patch for cache timeout bugs The key here is to get a new value of time(NULL) after stat-ing all those files. We should also set asof again after re-reading the stat/mime info due to staleness.
*** Bug 302322 has been marked as a duplicate of this bug. ***
*** Bug 307915 has been marked as a duplicate of this bug. ***
Any reason the patch is not going in? It may not fix all problems, but it certainly does fix wrong behaviour when the cache times out.
2005-06-23 Matthias Clasen <mclasen@redhat.com> * gtk/gtkfilesystemunix.c (gtk_file_system_unix_get_folder): Fix an error in the cache timeout logic. (#166601, Morten Welinder)
I'm going to change the title of this bug and mark it as fixed. Performance in the file chooser is a big topic. I'll start a wiki page to document the optimization effort there. I have done some preliminary profiles and know more or less what's going on.