GNOME Bugzilla – Bug 556749
Need to cache PROPFIND results
Last modified: 2014-04-19 06:41:46 UTC
Please describe the problem: I see the attached behavior when I try to browse a DAV share from an apache2 server. On connect to the server, PROPFIND / is issued once with Depth 1. It takes a while, because this directory has over 1000 subdirectories. That's reasonable. Okay so far. Then the weird stuff begins. When I click "311" (ignoring my taste in music for a moment), the *exact same* PROPFIND /311 with Depth 0 request is issued *twice* in a row over the same connection. Exactly the same headers, exactly the same result. I see other redundant requests, as well. But then it gets *really* strange. After PROPFIND /311 with Depth 1 is issued, gvfs issues *another* PROPFIND / with Depth 1! In god's name, why? This appears to be the root of the slowdown I see: the needless repetition of requests for data that seconds before had been transferred. And I suspect the SMB gvfs backend is doing something similar. Not sure if local caching + If-Modified-Since requests are valid here, but that may be a potential solution. Nautilus may be re-reading the parent directory unnecessarily; however, IMO the gvfs backend should be able to more gracefully deal with this situation, since not every application in existence can be rewritten to assume the data it is accessing is 20 mbits and 70 msec away. In my case, this is data that hardly ever changes: the only time the root directory of this DAV share changes is when I rip a new CD, which probably occurs once every few weeks. Furthermore, it has become clear by looking at my apache logs that the gnome DAV's request behavior is completely pathological. For one 5418548 byte (~5MB) Ogg file, I see the following requests with the bytes served in the 7th field: 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:23 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:23 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:23 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:23 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3287 krose [16/Oct/2008:16:44:23 -0400] 200 5418548 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:23 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3290 krose [16/Oct/2008:16:44:23 -0400] 206 5385780 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3283 krose [16/Oct/2008:16:44:23 -0400] 206 5418548 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:24 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:24 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3284 krose [16/Oct/2008:16:44:24 -0400] 206 5353012 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3321 krose [16/Oct/2008:16:44:24 -0400] 206 3636 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3321 krose [16/Oct/2008:16:44:24 -0400] 206 69172 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:24 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:24 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3321 krose [16/Oct/2008:16:44:24 -0400] 206 2711092 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3285 krose [16/Oct/2008:16:44:24 -0400] 206 1351220 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3287 krose [16/Oct/2008:16:44:24 -0400] 206 675380 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3290 krose [16/Oct/2008:16:44:24 -0400] 206 618036 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3283 krose [16/Oct/2008:16:44:24 -0400] 206 671284 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3284 krose [16/Oct/2008:16:44:24 -0400] 206 605748 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3321 krose [16/Oct/2008:16:44:25 -0400] 206 560692 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3285 krose [16/Oct/2008:16:44:25 -0400] 206 564788 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3287 krose [16/Oct/2008:16:44:25 -0400] 206 335412 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3290 krose [16/Oct/2008:16:44:25 -0400] 206 167476 0 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:25 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3286 krose [16/Oct/2008:16:44:25 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3283 krose [16/Oct/2008:16:44:25 -0400] 206 5287476 107 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3284 krose [16/Oct/2008:16:46:12 -0400] 206 2575924 60 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3321 krose [16/Oct/2008:16:47:13 -0400] 206 1216052 26 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3285 krose [16/Oct/2008:16:47:40 -0400] 206 540212 10 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3287 krose [16/Oct/2008:16:47:51 -0400] 206 200244 5 "GET /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3290 krose [16/Oct/2008:16:48:08 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" 192.168.33.1:80 192.168.35.130 3290 krose [16/Oct/2008:16:48:12 -0400] 207 770 0 "PROPFIND /coroner/no_more_color/7_why_it_hurts.ogg HTTP/1.1" "-" "gvfs/0.2.5" If you're not counting, that's 39739742 bytes---about 38 MB---transferred for one 5 MB Ogg file played continuously without interruption. Clearly, gvfs (or at least the DAV backend) needs better caching behavior. I'm filing this bug under the WebDAV backend, but it's possible the right solution is a general caching layer in gvfs. I filed this bug at the request of the Ubuntu team. The original Ubuntu change request is 284638. Steps to reproduce: 1. Set up a WebDAV share in apache that serves music files 2. Mount the share on a gvfs client 3. Use Audacious to listen to the music 4. Observe the apache log files to see what requests are being made and how much data is being transferred. Actual results: Too much data is transferred Expected results: The client should cache the data locally, since WAN network access is *at best* going to add latency to and reduce bandwidth from the disk read on the server. Does this happen every time? Yes Other information: My gvfs and related components are 0.2.5-0ubuntu2 (hardy up-to-date). My nautilus is 1:2.22.5.1-0ubuntu1 (also hardy up-to-date).
It's prolly nautilus doing that requests. The initial PROPFINDs you are seeing are done by gvfs itself but the rest are directory listings and stat() calls from nautilus. You are of course 100% right about the total lack of caching. The WebDAV rfc says results MAY be cached so we are not really pathological but more like non-optimal. ;-) But yeah, we need to add a cache for dir listings and (simple?) stat calls.
Closing as a duplicate of the gvfs-wide caching feature. *** This bug has been marked as a duplicate of bug 728375 ***