Closed Bug 638075 Opened 13 years ago Closed 13 years ago

Memory consumption increases when registering a stream listener.

Categories

(Core :: JavaScript Engine, defect)

x86
Windows Vista
defect
Not set
normal

Tracking

()

RESOLVED INCOMPLETE
Tracking Status
firefox5 - ---
firefox6 - ---

People

(Reporter: Honza, Unassigned)

References

Details

(Whiteboard: [firebug-p1][Requesting blocking .x][MemShrink:P2])

Attachments

(1 file, 1 obsolete file)

This bug report is related to Firebug.

When a stream listener is registered through nsITraceableChannel, Firefox memory consumption is much bigger when downloading big files.

I am attaching an example extension that is intercepting all incoming responses from the server.

STR:
1) Install: Firefox 4b (latest nightly build) + attached extension
2) Run Firefox and start downloading: http://download.microsoft.com/download/8/3/b/83b8c814-b000-44a4-b667-8c1f58727b8b/Windows6.0-KB936330-X64-wave0.exe
3) Watch Firefox memory consumption. When I download 30-40MB of the file Firefox gets ~100MB of memory (and still increasing)

Without that extension Firefox memory consumption is still the same: around 40-50 MB

Some info about the extension:

1) "http-on-examine-response" and "http-on-examine-cached-response" are handler in order to register a stream listener for response body
2) The "@mozilla.org/network/stream-listener-tee;1" is used as the listener.
3) The response data are written into a sink (nsIOutputStream) that is
registered within the listener-tee (using init method).
4) Pipe is created to get copy of the response from the tee listener.
5) An async listener is attached to the pipe and stream is consumed.

Related Firebug report:
http://code.google.com/p/fbug/issues/detail?id=3123

Could anybody please verify? 
Perhaps there is a bug in the attached extension?

Honza
Whiteboard: [firebug-p1]
Attached file Test extension (obsolete) —
Forgot to note:

- I am downloading the file just by putting the URL into the address bar and pressing the Enter key.

- The memory goes down when the page is refreshed (but it's still a problem)

Honza
Uh...  The attached extension saves a copy of all the incoming data.  Why exactly would you NOT expect more memory usage?  

The url in comment 0 is a 726MB file.  You're stuffing it into a JS string (so 2 bytes per character, one character per byte of original file, not counting intermediate objects which may or may not get GCed).

So using the STR from comment 0, memory should go up to about 1452MB at some point, before the download finishes.
Status: NEW → RESOLVED
Closed: 13 years ago
Resolution: --- → INVALID
> Uh...  The attached extension saves a copy of all the incoming data.  Why
> exactly would you NOT expect more memory usage?  
The extension is not supposed to store the incoming data. Where do you see it?

Note that the following code, only stores "data.length".

Honza

storePartialResponse: function(request, data)
{
    var url = safeGetRequestName(request);

    if (!this.cache[url])
        this.cache[url] = data.length;
    else
        this.cache[url] += data.length;

    sysout(formatSize(this.cache[url]));
},
> You're stuffing it into a JS string (so
> 2 bytes per character, one character per byte of original file, not counting
> intermediate objects which may or may not get GCed).
I don't understand this, how should I fix it?

Thanks!
Honza
Oh, I see.  I misread that part.

When you see this happening, does gc ever occur?  You can flip the "javascript.options.mem.log" pref and watch your error console to see whether it does.
(In reply to comment #6)
> When you see this happening, does gc ever occur?  You can flip the
> "javascript.options.mem.log" pref and watch your error console to see whether
> it does.
Yes, I am seeing following in the error console.

GC mode: full, timestamp: 1299084874079000, duration: 10 ms.
CC timestamp: 1299084878677000, collected: 519 (519 waiting for GC), suspected: 1483, duration: 4 ms.
GC mode: full, timestamp: 1299084879748000, duration: 11 ms.
CC timestamp: 1299084884752000, collected: 2298 (2298 waiting for GC), suspected: 209, duration: 5 ms.
GC mode: full, timestamp: 1299084888806000, duration: 54 ms.
CC timestamp: 1299084893809000, collected: 0 (0 waiting for GC), suspected: 117, duration: 3 ms.

My feeling is that gc happens just at the beginning a few times and then the memory is increasing.

I am also seeing couple of memory drops (just like gc would happens at the moment), but it's hard to be 100% sure (I am using Win task manager).

Honza
Status: RESOLVED → REOPENED
Resolution: INVALID → ---
> Yes, I am seeing following in the error console.

> My feeling is that gc happens just at the beginning a few times

Those are mutually contradictory.  As the pageload progresses, do you see a gc every so often?  Or does memory just grow without gc ever happening?

Since you're stuffing all the data into js strings, those would hang around until gc.  So if gc never happens, the memory would just grow....
(In reply to comment #8)
> Those are mutually contradictory.  As the pageload progresses, do you see a gc
> every so often?  Or does memory just grow without gc ever happening?

Here is the scenario I am seeing:
1) Start Firefox, load google.com: ~40MB
2) Start Downloading (putting the URL into the address bar)
3) Grows to: ~60MB, drops to: ~45MB (this happens 1-2 times)
4) Grows to 200MB, gc is not happening
5) Stop Download (sure, stop growing)
6) Refresh the page: drops to 60MB

Honza

> Since you're stuffing all the data into js strings, those would hang around
> until gc. So if gc never happens, the memory would just grow....
Yes, so how could Firebug avoid this?

Note that Firebug has a max size limit for the response, but I don't know how to stop observing...

1) Stop registering a pipe async listener (using stream.asyncWait): but that would be even worst since the tee-listener would still copy response data into the pipe and nobody would read it.

2) Remove the tee listener from the request: but nsITraceableChannel.setNewListener doesn't allow that after onStartRequest.

3) Force the engine to perform garbage collection: jsdIDebuggerService.GC(), ugh, this doesn't sound right (and debugging must be on)

4) Any other options?

Honza
Status: REOPENED → RESOLVED
Closed: 13 years ago13 years ago
Resolution: --- → INVALID
> 4) Grows to 200MB, gc is not happening

OK, well the question is why not.  Andreas?

> but I don't know how to stop observing...

You can't stop observing at the moment.

You could cheat and try to send the data to /dev/null or some such, but that only works on Unix-y systems...

The other hacky option is to open some temporary file and for each bit of data you get just seek to the beginning of the file and write it there.  That should keep the file from getting too big while letting you get rid of the data.

But really, we should fix the gc issue here.
Assignee: nobody → general
Status: RESOLVED → REOPENED
Component: Networking → JavaScript Engine
QA Contact: networking → general
Resolution: INVALID → ---
(In reply to comment #10)
> But really, we should fix the gc issue here.
Agree

Honza
Component: JavaScript Engine → Networking
Then please leave the component as-is?
Component: Networking → JavaScript Engine
(In reply to comment #12)
> Then please leave the component as-is?
Sorry, that was not detected mid-air collision, I have already reported this Bugzilla problem some time ago: Bug 627145

Honza
comment 10: I will try to reproduce and comment.
I tried the extension. I see massive allocations happen during the download. GCs and CCs do happen, but can't keep up with the quick heap growth, which goes past 200MB at some point. After the download we GC and CC again and drop back to 50MB. I don't see a leak, I don't see bloat here, just lots of allocation traffic, which causes us to enlarge the heap.

In a bold new probably FF6 world we will have an incremental collector where we rely more on fast small (1MB) nursery collection instead of increased JS heap size to deal with allocation bursts.
is this a regression?
I have slightly updated the extension so it's possible to run it also in Firefox 3.6. Here is the scenario I am seeing now:

Here is the scenario I am seeing in Firefox 3.6:
1) Start Firefox, load google.com: ~25-30MB
2) Start Downloading (putting the URL into the address bar)
3) Grows to: ~70-80MB, drops to: ~35MB, happening regularly

So, I would say it works better in 3.6.
Somebody please verify
Honza
Attachment #516236 - Attachment is obsolete: true
(In reply to comment #10)
> The other hacky option is to open some temporary file and for each bit of data
> you get just seek to the beginning of the file and write it there.  That should
> keep the file from getting too big while letting you get rid of the data.
I don't understand this option. How this would prevent memory allocations? Given that data must be read from the pipe.

Honza
> I don't understand this option. How this would prevent memory allocations?

If you use writeFrom on a file output stream and pass it your pipe's input end, then all the reading and writing will happen in C++ (in the file stream's writeFrom implementation) and not create any JS objects in the process.  (Though it looks like you'd have to wrap the file stream in a buffered output stream to actually get this to work, but with that change it should work.)
> (Though it looks like you'd have to wrap the file stream in a buffered output
> stream to actually get this to work, but with that change it should work.)
This sounds like a promising workaround. Could you please provide more info (an example would be certainly great!) how to do it? + how to seek at the beginning to keep the file from getting too big.
 
Honza
1)  Create an nsIFile in the temp dir (get it from the dir service,
    createUnique a file).
2)  Open a file output stream on this file.
3)  Create a buffered output stream wrapping the file stream.
4)  Whenever you want to throw away some data from the pipe, QI the file stream
    (NOT the buffered stream) to nsISeekableStream and seek to NS_SEEK_SET and
    offset 0 then call writeFrom on the buffered output stream, passing it your
    pipe's input end, until that end claims to have no data available.

I'm pretty sure you can look up the xpcom goop specifics for that...  That's what I'd have to do to write up the example.
Would the workaround with the temp file increase disk activity dramatically? It's already bad at times.
> Would the workaround with the temp file increase disk activity dramatically?

It depends on how fast your net connection is, obviously.  ;)
I rather hope the gc issue will be fixed soon. What flag should I set to make sure this bug has proper attention? I know this won't block Fx4 release, but it could be fixed in a following dot release, no?
Honza
Is there any blocking field I could set to make sure there is a chance this is fixed in the next Firefox point release?

Honza
Set blocking2.0 to ?
Then add [Requesting blocking .x] to the whiteboard.
Add a quick comment explaining reasoning.
Adding request for blocking.x.

I hope the garbage collector issue can be fixed in the next dot release since any memory related problem doesn't make good reputation for Firebug.

Honza
Whiteboard: [firebug-p1] → [firebug-p1][Requesting blocking .x]
Any chance this could be fixed? Firebug is suffering due to this bug.
Honza
Honza, what about the plan to manually call GC ourselves every 500k (or whatever) downloaded? There is a way to grab the interface and call it directly without using the JSD entry point (just like calling the cycle collector).
I'm minusing the tracking-firefox5 nom here since this problem isn't specific to FF5 (i.e. it's not caused by a post-ff4 landing that we're deciding whether to back out).

Nevertheless, it sounds important to fix. Sayre - thoughts on who could work on this and when? I'd love to see a patch come in on central (and we'd also look at an approval request for aurora once a fix exists).
(In reply to comment #29)
> Honza, what about the plan to manually call GC ourselves every 500k (or
> whatever) downloaded? There is a way to grab the interface and call it directly
> without using the JSD entry point (just like calling the cycle collector).
The plan is to use it as temporary workaround, I am just a bit afraid what side impact this solution could have.

Honza
Re-minusing this (bugzilla collision?)
> The plan is to use it as temporary workaround, I am just a bit afraid what side
> impact this solution could have.

Originally, we talked about using the JSD to call GC, and that would have odd side effects. But I mean to call the interface directly (not using the JSD API).
(In reply to comment #33)
> Originally, we talked about using the JSD to call GC, and that would have odd
> side effects. But I mean to call the interface directly (not using the JSD
> API).

Specifically, I assume you mean Components.utils.forceGC? Or do you need the cycle collector to be triggered as well? (Which would mean nsIDOMWindowUtils.garbageCollect() instead, I guess.)

Probably just Cu.forceGC(), since jsd.GC() does not trigger CC.
(In reply to comment #24)
> I rather hope the gc issue will be fixed soon.

It sounds like this is a bug in Firebug to me. There are massive allocations in the presence of GCs and CCs. In comment 19 and comment 21, a way to avoid all of these allocations is given. What's wrong with that approach?
Robert, that approach involves creating a file on disk and dumping this data (which in this case Firebug is not interested in at all) to that file.  One drawback is that it involves disk i/o, of course.
(In reply to comment #34)
> (In reply to comment #33)
> Probably just Cu.forceGC(), since jsd.GC() does not trigger CC.
Yes, this is what I used. I have committed a patch to Firebug SVN and it'll be also ported in Firebug 1.7

Honza
(In reply to comment #32)
> Re-minusing this (bugzilla collision?)
Yes it was undetected collision.
Honza
Whiteboard: [firebug-p1][Requesting blocking .x] → [firebug-p1][Requesting blocking .x][MemShrink:P2]
What's the status of this?  Comment 24 makes it sound like this is a GC issue, which means there's a good chance it was fixed by bug 656120.  Can we close this bug now?
I'm closing this.  Please reopen if there's still a clear problem.
Status: REOPENED → RESOLVED
Closed: 13 years ago13 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: