After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 556749 - (cache-fileinfo) Need to cache PROPFIND results
(cache-fileinfo)
Need to cache PROPFIND results
Status: RESOLVED DUPLICATE of bug 728375
Product: gvfs
Classification: Core
Component: webdav backend
0.2.x
Other All
: Normal normal
: ---
Assigned To: Christian Kellner
gvfs-maint
Depends on:
Blocks:
 
 
Reported: 2008-10-17 15:46 UTC by krose
Modified: 2014-04-19 06:41 UTC
See Also:
GNOME target: ---
GNOME version: 2.21/2.22



Description krose 2008-10-17 15:46:02 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).
Comment 1 Christian Kellner 2009-05-26 10:53:29 UTC
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.
Comment 2 Ross Lagerwall 2014-04-19 06:41:46 UTC
Closing as a duplicate of the gvfs-wide caching feature.

*** This bug has been marked as a duplicate of bug 728375 ***