410131 - DM isn't buffering writes when saving a file

Status: VERIFIED FIXED

(Core Graveyard :: File Handling, defect, P3)

Description

[Justin Dolske [:Dolske]]

DM is causing excessive writes when saving a file.

I downloaded a Tinderbox build/test log (5.5MB, via right click "View Full Log", Save As), and ran DTrace's rwsnoop while the download was going. [Truss output looks about the same.] A representative sample of output (filtered):

  UID    PID CMD          D   BYTES FILE
...
  101  14443 firefox-bin  W    1296 /export/home/dolske/Desktop/showlog.cgi
  101  14443 firefox-bin  W     628 /export/home/dolske/Desktop/showlog.cgi
  101  14443 firefox-bin  W      85 /export/home/dolske/Desktop/showlog.cgi
  101  14443 firefox-bin  W    1382 /export/home/dolske/Desktop/showlog.cgi
  101  14443 firefox-bin  W     599 /export/home/dolske/Desktop/showlog.cgi
  101  14443 firefox-bin  W     381 /export/home/dolske/Desktop/showlog.cgi
  101  14443 firefox-bin  W     452 /export/home/dolske/Desktop/showlog.cgi
  101  14443 firefox-bin  W   16384 /export/home/dolske/.mozilla/firefox
                                          /vr86v7k5.default/Cache/1CC4A7C8d01
...

The downloaded file is being saved to the disk cache and to my desktop...

The cache is being updated in 16K chunks, 344 total writes. The download itself is trickling down piecemeal. I see writes of many, many different sizes; from 8K down to 14 (!), the majority seem to be less than 1K. There are 6525 total writes (avg = 849 bytes per write).

The flip side of this is that we're presumably reading from the socket too often. SO_RCVLOWAT is one approach to helping that, but I don't remember if that works with non-blocking IO. Seems like if we know we're doing a bulk data transfer (*handwaving about transfer size, bandwidth, and responsiveness goes here*), we'd want to reduce overhead by only reading when big gulps are available. Probably fodder for another bug?

Comment 1

[Shawn Wilsher :sdwilsh]

Attachment: v1.0

This patches uriloader/exthandler, where most downloads go through.  This doesn't hit the Save As... case though - I'm still looking at how nsWebBrowserPersists handles this stuff.

Dolske - do you think you can test this (I don't have dtrace).  I'll keep looking into the other spot of code we have to fix.

Comment 2

[[e-mail]]

Comment on attachment 294963 [details] [diff] [review]
v1.0

>+// Buffer file writes in 1MB chunks
>+#define BUFFERED_OUTPUT_SIZE 1048576

seems pretty big - you won't hit the disk until you've amassed that much data. reducing 6000 writes down to a few hundred seems sufficient here, so maybe a size somewhere in the range 16 - 64k would be suitable?

Comment 3

[Shawn Wilsher :sdwilsh]

Attachment: v1.1

switch to 32kb chunks, and get the webbrowserpersists changes

Comment 4

[[e-mail]]

Comment on attachment 294968 [details] [diff] [review]
v1.1

>Index: embedding/components/webbrowserpersist/src/nsWebBrowserPersist.cpp
>===================================================================
>+    nsCOMPtr<nsIBufferedOutputStream> bos =
>+      do_CreateInstance(NS_BUFFEREDOUTPUTSTREAM_CONTRACTID);
>+    if (bos) {
>+      rv = bos->Init(fileOutputStream, BUFFERED_OUTPUT_SIZE);
>+      if (NS_SUCCEEDED(rv))
>+        NS_ADDREF(*aOutputStream = bos);
>+      else
>+        NS_ADDREF(*aOutputStream = fileOutputStream);
>+    } else {
>+      NS_ADDREF(*aOutputStream = fileOutputStream);
>+    }

nit: if you use to do_CreateInstance(, &rv) form, you can collapse the last two NS_ADDREFs into one codepath:

   nsCOMPtr<nsIBufferedOutputStream> bos =
     do_CreateInstance(NS_BUFFEREDOUTPUTSTREAM_CONTRACTID, &rv);
   if (NS_SUCCEEDED(rv)) {
     rv = bos->Init(fileOutputStream, BUFFERED_OUTPUT_SIZE);
     if (NS_SUCCEEDED(rv))
       NS_ADDREF(*aOutputStream = bos);
   }
   if (NS_FAILED(rv))
     NS_ADDREF(*aOutputStream = fileOutputStream);

Comment 5

[Justin Dolske [:Dolske]]

Are any changed needed for pausing/resuming a download (since now bytes written != bytes on disk). Flush() on pause, maybe? Or does the stream just end up getting closed either way?

Comment 6

[Shawn Wilsher :sdwilsh]

We cancel the download on pause, and restart a connection, so I'd think that closing the nsIOutputStream (which is actually an nsIBufferedOutputStream) would do it, but I don't know a whole lot about these things (and docs seem to be lacking).  I based my patches off of how you did it with the password manager ;)

Comment 7

[[e-mail]]

yep, if you close/destroy the stream it'll flush.

Comment 8

[Justin Dolske [:Dolske]]

And how about if Firefox crashes while downloading -- do we attempt to resume the download? I see a curr_bytes in downloads.sqlite, could that end up being greater than the actual size of the partial crashed-while-downloading file?

Comment 9

[Ed Lee :Mardak]

When we resume, we look at the disk file size -- not the one in the database. 

Will there be any issues with the display if it only receives updates after some number of bytes?

Comment 10

[Shawn Wilsher :sdwilsh]

(In reply to comment #9)
> Will there be any issues with the display if it only receives updates after
> some number of bytes?
I don't understand what you are asking exactly...

Comment 11

[Ed Lee :Mardak]

If the UI only receives updates on 32kb chunks, if it's downloading at slower than that, how often will the UI be updating? Will we be able to show 1KBps or is the minimum 4KBps?

Comment 12

[Shawn Wilsher :sdwilsh]

I'm pretty sure that those notifications are done as the bits are received from the network - not as it is being written to the hard drive.

Comment 13

[Christian :Biesinger (don't email me, ping me on IRC)]

Comment on attachment 294968 [details] [diff] [review]
v1.1

+  nsCOMPtr<nsIBufferedOutputStream> bos =
+    do_CreateInstance(NS_BUFFEREDOUTPUTSTREAM_CONTRACTID);

just use NS_NewBufferedOutputStream

and doing the error handling consistently between wbp and exthandler would be nice too

Comment 14

[Shawn Wilsher :sdwilsh]

Comment on attachment 294968 [details] [diff] [review]
v1.1

Actually, let me address comments before I request sr...

Comment 15

[Justin Dolske [:Dolske]]

Patch WFM, for the original steps...

  UID    PID CMD          D   BYTES FILE
...
  101  21740 firefox-bin  W   32768 /export/home/dolske/Desktop/showlog.cgi
  101  21740 firefox-bin  W   32768 /export/home/dolske/Desktop/showlog.cgi
  101  21740 firefox-bin  W   32768 /export/home/dolske/Desktop/showlog.cgi
  101  21740 firefox-bin  W   32768 /export/home/dolske/Desktop/showlog.cgi
...

A total of 220 32K writes and one final 10K write for the 7.2MB file.

So, the right-click "Save As" case is fixed, but it seems the normal click-to-download case isn't... If I go to mozilla.com and click to download a Firefox release, I see writes of varying sizes. [Mostly 3204 and 4096 bytes, but a few of different sizes.]

Oddly, I don't get the download mananger window when this happens, so something else might be broken?

Comment 16

[Shawn Wilsher :sdwilsh]

Attachment: v2.0

This gets the other case that I missed last time, and addresses review comments.

Comment 17

[Shawn Wilsher :sdwilsh]

(In reply to comment #15)
> Oddly, I don't get the download mananger window when this happens, so something
> else might be broken?
I'm oddly seeing that now too.  I'm also getting a dialog that I don't normally get, so maybe some recent checkin has changed something?

Comment 18

[Damon Sicore (:damons)]

+'ing this with P3 priority.  Please adjust priority if necessary.

Comment 19

[Shawn Wilsher :sdwilsh]

Attachment: v3.0

Addresses sr comments on irc.  I changed enough that I feel it should get review again (sorry biesi).

Comment 20

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 295339 [details] [diff] [review]
v3.0

>Index: uriloader/exthandler/nsExternalHelperAppService.cpp
>+// Buffer file writes in 32kb chunks
>+#define BUFFERED_OUTPUT_SIZE 32768

(1 << 15) might be clearer...  Or (1024 * 32) or something.

>Index: netwerk/base/public/nsNetUtil.h
>+ * passed in output stream.

passed-in

>+ * @param result
>+ *        The resulting output stream.

How come this isn't the return value?  What's the point of an nsresult return value if you always return NS_OK?  Just make this return already_AddRefed<nsIOutputStream> and be done with it?

>+    if (NS_SUCCEEDED(rv))
>+        NS_ADDREF(*result = bos);

Then this could become:

  return bos.forget();

>+    else
>+        NS_ADDREF(*result = aOutputStream);

While this (after eliminating the |else|) becomes:

  NS_ADDREF(aOutputStream);
  return aOutputStream;

Comment 21

[Shawn Wilsher :sdwilsh]

Attachment: v3.1

(In reply to comment #20)
> (1 << 15) might be clearer...  Or (1024 * 32) or something.
done

> >Index: netwerk/base/public/nsNetUtil.h
> >+ * passed in output stream.
> 
> passed-in
done

> How come this isn't the return value?  What's the point of an nsresult return
> value if you always return NS_OK?  Just make this return
> already_AddRefed<nsIOutputStream> and be done with it?
XPCOM familiarism.  Not an excuse though, I know.  Fixed!

> >+    if (NS_SUCCEEDED(rv))
> >+        NS_ADDREF(*result = bos);
> 
> Then this could become:
> 
>   return bos.forget();
I love getting reviews from you!  I learn something new every time!  Fixed.

Comment 22

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 295378 [details] [diff] [review]
v3.1

Beautiful.  Thank you!

Comment 23

[Shawn Wilsher :sdwilsh]

Checking in uriloader/exthandler/nsExternalHelperAppService.cpp;
new revision: 1.359; previous revision: 1.358
Checking in embedding/components/webbrowserpersist/src/nsWebBrowserPersist.cpp;
new revision: 1.132; previous revision: 1.131
Checking in netwerk/base/public/nsNetUtil.h;
new revision: 1.110; previous revision: 1.109

Comment 24

[Justin Dolske [:Dolske]]

Verified. dtruss on OSX shows it making 32K writes, for both test cases.