448840 - jpeg image decoding slow

Status: RESOLVED WORKSFORME

(Core :: Memory Allocator, defect)

Description

[Dennis Jacobfeuerborn]

User-Agent:       Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.1a2pre) Gecko/2008080102 Minefield/3.1a2pre
Build Identifier: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.1a2pre) Gecko/2008080102 Minefield/3.1a2pre

I have a large (2.6mb, 536x13899 pixels, residing on the local harddisk) image here that displays rather slow. In fact as the image gets displayed progessively the decoding seems to become slower as the image is loaded.

Loading takes about 5 seconds on an Athlon64 dual core 4200+ cpu. Since it uses up all of the processing time of the core firefox runs on putting several of such images on a page effectively freezes firefox for the time it takes to load all the images.

Reproducible: Always

Comment 1

[Dennis Jacobfeuerborn]

Also putting the image on a html page five times and running an "strace -e trace=open -p <firefox-pid>" and "vmstat 1" shows that firefox creates quite a bit of disk i/o (which in general causes interactivity problems for firefox even if caused by other applications):

[dennis@nexus ~]$ strace -e trace=open -p 3960
Process 3960 attached - interrupt to quit
open("/home/dennis/tmp/test.html", O_RDONLY|O_LARGEFILE) = 37
open("/home/dennis/tmp/1.jpg", O_RDONLY|O_LARGEFILE) = 37
open("/home/dennis/tmp/2.jpg", O_RDONLY|O_LARGEFILE) = 46
open("/home/dennis/tmp/3.jpg", O_RDONLY|O_LARGEFILE) = 47
open("/home/dennis/tmp/4.jpg", O_RDONLY|O_LARGEFILE) = 51
open("/home/dennis/tmp/5.jpg", O_RDONLY|O_LARGEFILE) = 53
open("/tmp/jemalloc.Applbq", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.Enm4k5", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.uRiqBO", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.IKI2CB", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.hJp4Fw", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.A2xW3r", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.YBSlMn", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.NQjyGj", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.xHCFgh", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.id1ljf", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.cWkjOd", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.BHPyOc", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.1bX9of", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.zv9aKi", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.8e9FOm", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/tmp/jemalloc.gS1NEr", O_RDWR|O_CREAT|O_EXCL, 0600) = 54
open("/home/dennis/.mozilla/firefox/s4ap7k3u.trunk/sessionstore.js", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC|O_LARGEFILE, 0600) = -1 EEXIST (File exists)
open("/home/dennis/.mozilla/firefox/s4ap7k3u.trunk/sessionstore-1.js", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC|O_LARGEFILE, 0600) = 37
open("/home/dennis/.mozilla/firefox/s4ap7k3u.trunk/sessionstore-1.js", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0600) = 37
^CProcess 3960 detached

Comment 2

[Dennis Jacobfeuerborn]

Attachment: "vmstat 1" when loading test.html with 5 copies of the image

Notice the io->bo column. You can clearly see that firefox writes quite a few blocks to disk as soon as i load the testpage for no apparent reason. Since firefox is so sensitive to disk i/o it freezes almost completely while the images are loaded and only becomes usable again after it has finished doing so.

Comment 3

[Jo Hermans]

The sessionstore-1.js file is the temporary file written because sessionstore.js already exists, and it has to be an atomic operation (it will replace sessionstore.js later). But it's written a few seconds after the page is loaded, so that a crash doesn't give you a unusable sessionstore.js file ; it shouldn't interfere with the actual loading.

The /tmp/jemalloc.* files are caused by the memory allocator (jemalloc) when it's expanding your memory. See bug 447710 for more info, this is a dupe, although that one complains about the disk space, not the I/O.

Note: your operating system should cache most of this I/O (especially in /tmp) - do you know why it's causing slowness ? Are you using more memory than you physically have ?

Comment 4

[Dennis Jacobfeuerborn]

I'm aware that FF constantly accesses files like the session store, places, cache files, etc. but I'm not really concerned about those right now. The jemalloc ones concern me though because they seem to make disk i/o an important factor in memory allocation in a similar way swap space does even though I have plenty or RAM to go around. My machine has 2GB of ram of which I usually never use more than half. As you can see from the vmstat output the system was using 1GB for caching at the time.

The OS can't really cache the jemalloc stuff as it never seems to read from these files and only writes to them. I did a more complete "strace -e trace=open,close,write,read -p <pid>" call with the following result:

...
open("/home/dennis/tmp/1.jpg", O_RDONLY|O_LARGEFILE) = 37
write(19, "\372", 1)                    = 1
read(40, "\0\0\0\320\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 16
open("/tmp/jemalloc.FRVLin", O_RDWR|O_CREAT|O_EXCL, 0600) = 46
write(46, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
write(46, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
write(46, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
write(46, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
write(46, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
write(46, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
...

I stopped after FF was done loading the image. Grepping the result shows that FF does 59.385 of these writes and *no* read whatsoever. It's also strange that only zero-bytes get written to this file. Not sure what that is all about.

Is there a way to prevent FF from using the disk for this kind of allocations in about:config? I'd like to see what impact that has on browsing.

In general FF is really sensitive to disk i/o. When I scroll over a page and another process causes disk i/o (ie the feed read updating it's feeds) firefox freezes completely for a second or two at a time. Firefox causing it's own unnecessary disk i/o doesn't really help here.

If I'd have to venture a guess the problem is that the FF main thread is trying to do i/o on the main thread but since another process has "locked up" the disk the main thread just gets stuck at this point thus freezing FF. What happens if FF tries to create such a jemalloc file but can't because the disk is kept busy by another process? Is that handled asynchronously or would that create such a freeze situation for the main thread?

Comment 5

[Dennis Jacobfeuerborn]

Hm, I just realized that the jemalloc files might be mmaped which would explain the above behavior but that still doesn't explain why the files are created in the first place.

Comment 6

[Jo Hermans]

They're indeed memory-mapped files, which are used to provide a disk-bandend (to prevent overcommitting). This way, it's not possible to allocate more memory than you physically have (swapspace included), because the memory has been reserved or pre-allocated. See bug 427109 for the original checkin. Note that this still needs to be fine-tuned, to avoid bug-reports like this one.

There's is currently still an option to disable this : according to bug 447710 comment 3, you can set the environment variable MALLOC_OPTIONS to O (big O, a small 0 disables over-commit).

I'm not sure if it's possible to run this on a different thread, because it runs on a very low level : inside every malloc call ! The problem here is that a lot of memory is needed (the image is much larger in-memory than on disk !), and your process is expanding. It might be less noticeable when loading from the network, because the file doesn't need to be read from the disk, and the bandwidth is lower. But then the disk chach is also used, so the behavior could be totally different.

Comment 7

[Dennis Jacobfeuerborn]

Hm, interesting. Setting MALLOC_OPTIONS to O seems to solve the disk i/o problem and FF behaves much nicer and the test html page loads faster.

The slow decoding of the image seems to change over time though. When I start the browser and load the image the load time is fast and the image gets displayed fully almost right away. After browsing some sites though the loading of the image becomes slow and the pattern mentioned above emerges.

Comment 8

[Γριφεγ]

This is intentional according to http://mxr.mozilla.org/mozilla-central/source/memory/jemalloc/jemalloc.c#2430

Comment 9

[Justin Lebar (not reading bugmail)]

I can't reproduce this with trunk, so I'm marking as WORKSFORME.  Dennis, if you're still experiencing this problem, feel free to re-open the bug.