Poor performance on first pinch to zoom in the gallery app

NEW
Unassigned

Status

()

4 years ago
4 years ago

People

(Reporter: cyu, Unassigned)

Tracking

Trunk
ARM
Gonk (Firefox OS)
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [gfx-noted])

(Reporter)

Description

4 years ago
Reproduced with
gaia revision: 737ef4d7a8494bc6ece4bc3f37b4de977f01333c
gecko revision: 70de2960aa87
device: flame

STR:
* Install the reference-load-medium to the device.
* Open the gallery app.
* Open any one image.
* Pinch to zoom in.

It can be observed that the first zooming of the image has > 1 sec of freeze on flame. Photos taken using the camera app doesn't have such a long freeze but still observable. A jpg image of the same dimensions (1600 x 1200) reproduces the problem.

Further investigation:
* Acquiring mDecodingMonitor in RasterImage::DoImageDataComplete():
http://hg.mozilla.org/mozilla-central/file/cb26891d69e9/image/src/RasterImage.cpp#l1271
blocks the main thread for more than 1 sec.
* Another image that has the same dimensions shows similar behavior. The main thread is blocked for > 1 sec acquiring RasterImage::mDecodingMonitor, but in mozilla::image::NotifyProgressWorker::Run(), mozilla::image::RasterImage::RequestDecodeCore().
Should be fixed by bug 1079627, which is intended to get uplifted to B2G 2.2.
Depends on: 1079627
Cervantes, just to make sure that what's happening here is what *appears* to be happening, could you please reproduce this again and get stacks for all threads?
Flags: needinfo?(cyu)
Summary: Pool performance on first pinch to zoom in the gallery app → Poor performance on first pinch to zoom in the gallery app
Whiteboard: [gfx-noted]
(Reporter)

Comment 3

4 years ago
Here is the main thread and the decoding thread when the problem is reproduced.

[Switching to thread 1 (Thread 4273.4273)](running)
(gdb) bt
#0  __futex_syscall3 () at bionic/libc/arch-arm/bionic/futex_arm.S:39
#1  0xb6e3d020 in __pthread_cond_timedwait_relative (cond=cond@entry=0xb0bf65ec, mutex=mutex@entry=0xb0bf65e4, reltime=0xf0) at bionic/libc/bionic/pthread.c:1117
#2  0xb6e3d080 in __pthread_cond_timedwait (cond=0xb0bf65ec, mutex=0xb0bf65e4, abstime=<optimized out>, clock=<optimized out>) at bionic/libc/bionic/pthread.c:1140
#3  0xb6eb9a08 in __wrap_pthread_cond_wait (cond=0xb0bf65ec, mtx=0xb0bf65e4) at mozglue/build/Nuwa.cpp:1044
#4  0xb6dcabaa in PR_EnterMonitor (mon=0xb0bf65e0) at nsprpub/pr/src/pthreads/ptsynch.c:592
#5  0xb51d5d1a in mozilla::ReentrantMonitor::Enter (this=0xb0b97198) at ../../dist/include/mozilla/ReentrantMonitor.h:83
#6  0xb55a0432 in ReentrantMonitorAutoEnter (aReentrantMonitor=..., this=0xbe845e7c) at ../../dist/include/mozilla/ReentrantMonitor.h:202
#7  mozilla::image::RasterImage::DoImageDataComplete (this=this@entry=0xb0b97120) at image/src/RasterImage.cpp:1271
#8  0xb55a1602 in mozilla::image::RasterImage::OnImageDataComplete (this=0xb0b97120, aStatus=tag_nsresult::NS_OK, aLastPart=true) at image/src/RasterImage.cpp:1297
#9  0xb55a694a in imgRequest::OnStopRequest (this=0xb0b13350, aRequest=0xb20c634c, ctxt=0x0, status=<optimized out>) at image/src/imgRequest.cpp:752
#10 0xb55a19d0 in ProxyListener::OnStopRequest (this=<optimized out>, aRequest=<optimized out>, ctxt=<optimized out>, status=<optimized out>) at image/src/imgLoader.cpp:2480
#11 0xb521ba9a in nsBaseChannel::OnStopRequest (this=0xb20c6320, request=<optimized out>, ctxt=<optimized out>, status=<optimized out>) at netwerk/base/src/nsBaseChannel.cpp:775
#12 0xb521a50c in OnStateStop (this=0xb0b3ed00) at netwerk/base/src/nsInputStreamPump.cpp:721
#13 nsInputStreamPump::OnStateStop (this=0xb0b3ed00) at netwerk/base/src/nsInputStreamPump.cpp:676
#14 0xb521a600 in nsInputStreamPump::OnInputStreamReady (this=0xb0b3ed00, stream=<optimized out>) at netwerk/base/src/nsInputStreamPump.cpp:440
#15 0xb51d7bf0 in nsInputStreamReadyEvent::Run (this=0xb0be4ec0) at xpcom/io/nsStreamUtils.cpp:169
#16 0xb51e3104 in nsThread::ProcessNextEvent (this=0xb4466110, aMayWait=<optimized out>, aResult=0xbe845fc7) at xpcom/threads/nsThread.cpp:855
#17 0xb51eefc8 in NS_ProcessNextEvent (aThread=<optimized out>, aMayWait=aMayWait@entry=false) at xpcom/glue/nsThreadUtils.cpp:265
#18 0xb532f4a8 in mozilla::ipc::MessagePump::Run (this=0xb4401d30, aDelegate=0xbe8460c8) at ipc/glue/MessagePump.cpp:99
#19 0xb5323bd4 in MessageLoop::RunInternal (this=this@entry=0xbe8460c8) at ipc/chromium/src/base/message_loop.cc:233
#20 0xb5323c88 in RunHandler (this=0xbe8460c8) at ipc/chromium/src/base/message_loop.cc:226
#21 MessageLoop::Run (this=0xbe8460c8) at ipc/chromium/src/base/message_loop.cc:200
#22 0xb5bc6b52 in nsBaseAppShell::Run (this=0xb3860d00) at widget/nsBaseAppShell.cpp:164
#23 0xb5eed942 in XRE_RunAppShell () at toolkit/xre/nsEmbedFunctions.cpp:738
#24 0xb5323bd4 in MessageLoop::RunInternal (this=this@entry=0xbe8460c8) at ipc/chromium/src/base/message_loop.cc:233
#25 0xb5323c88 in RunHandler (this=0xbe8460c8) at ipc/chromium/src/base/message_loop.cc:226
#26 MessageLoop::Run (this=this@entry=0xbe8460c8) at ipc/chromium/src/base/message_loop.cc:200
#27 0xb5eedd92 in XRE_InitChildProcess (aArgc=<optimized out>, aArgv=<optimized out>, aGMPLoader=<optimized out>) at toolkit/xre/nsEmbedFunctions.cpp:575
#28 0xb6f01134 in content_process_main (argc=7, argv=0xbe846a54) at ipc/app/../contentproc/plugin-container.cpp:211
#29 0xb6e3c4a4 in __libc_init (raw_args=0xbe846a50, onexit=<optimized out>, slingshot=0xb6f01151 <main(int, char**)>, structors=<optimized out>) at bionic/libc/bionic/libc_init_dynamic.cpp:112
#30 0xb6f01034 in _start ()
(gdb) thr 18
[Switching to thread 18 (Thread 4273.4305)](running)
(gdb) bt
#0  memset () at bionic/libc/arch-arm/krait/bionic/memset.S:92
#1  0xb5f1925a in jzero_far (target=<optimized out>, bytestozero=<optimized out>) at media/libjpeg/jutils.c:179
#2  0xb5f17366 in access_virt_barray (cinfo=<optimized out>, ptr=0xb1fd9eb0, start_row=15, num_rows=<optimized out>, writable=1) at media/libjpeg/jmemmgr.c:942
#3  0xb5f0c59e in consume_data (cinfo=0xb1f2a0a8) at media/libjpeg/jdcoefct.c:264
#4  0xb5f0c1a2 in jpeg_consume_input (cinfo=0xb1f2a0a8) at media/libjpeg/jdapimin.c:320
#5  0xb55b407e in mozilla::image::nsJPEGDecoder::WriteInternal (this=0xb1f2a000, aBuffer=0xb1601008 "\377\330\377", <incomplete sequence \340>, aCount=0) at image/decoders/nsJPEGDecoder.cpp:460
#6  0xb55a9b18 in mozilla::image::Decoder::Write (this=0xb1f2a000, aBuffer=aBuffer@entry=0xb1601008 "\377\330\377", <incomplete sequence \340>, aCount=aCount@entry=16384) at image/src/Decoder.cpp:139
#7  0xb55a010c in mozilla::image::RasterImage::WriteToDecoder (this=this@entry=0xb0b97120, aBuffer=0xb1601008 "\377\330\377", <incomplete sequence \340>, aCount=aCount@entry=16384) at image/src/RasterImage.cpp:1591
#8  0xb55a017a in mozilla::image::RasterImage::DecodeSomeData (this=this@entry=0xb0b97120, aMaxBytes=aMaxBytes@entry=16384) at image/src/RasterImage.cpp:2165
#9  0xb55ab424 in mozilla::image::DecodePool::DecodeSomeOfImage (this=<optimized out>, aImage=0xb0b97120, aDecodeUntil=aDecodeUntil@entry=mozilla::image::DecodeUntil::DONE_BYTES, bytesToDecode=bytesToDecode@entry=355856) at image/src/DecodePool.cpp:399
#10 0xb55adc04 in mozilla::image::DecodeWorker::Run (this=0xb0bd2c40) at image/src/DecodePool.cpp:101
#11 0xb51e3a96 in nsThreadPool::Run (this=0xb4403900) at xpcom/threads/nsThreadPool.cpp:225
#12 0xb51e3104 in nsThread::ProcessNextEvent (this=0xb2461320, aMayWait=<optimized out>, aResult=0xb2301d27) at xpcom/threads/nsThread.cpp:855
#13 0xb51eefc8 in NS_ProcessNextEvent (aThread=<optimized out>, aMayWait=aMayWait@entry=false) at xpcom/glue/nsThreadUtils.cpp:265
#14 0xb532f408 in mozilla::ipc::MessagePumpForNonMainThreads::Run (this=0xb24e3d60, aDelegate=0xb24ea440) at ipc/glue/MessagePump.cpp:339
#15 0xb5323bd4 in MessageLoop::RunInternal (this=this@entry=0xb24ea440) at ipc/chromium/src/base/message_loop.cc:233
#16 0xb5323c88 in RunHandler (this=0xb24ea440) at ipc/chromium/src/base/message_loop.cc:226
#17 MessageLoop::Run (this=this@entry=0xb24ea440) at ipc/chromium/src/base/message_loop.cc:200
#18 0xb51e3358 in nsThread::ThreadFunc (aArg=0xb2461320) at xpcom/threads/nsThread.cpp:356
#19 0xb6dcb1ca in _pt_root (arg=0xb20dce80) at nsprpub/pr/src/pthreads/ptthread.c:212
#20 0xb6e3b22c in __thread_entry (func=0xb6dcb131 <_pt_root>, arg=0xb20dce80, tls=0xb2301dd0) at bionic/libc/bionic/pthread_create.cpp:105
#21 0xb6e3b3c4 in pthread_create (thread_out=0xbe845c14, attr=<optimized out>, start_routine=0xb6dcb131 <_pt_root>, arg=0x78) at bionic/libc/bionic/pthread_create.cpp:224
#22 0x00000000 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Flags: needinfo?(cyu)
(Reporter)

Comment 4

4 years ago
For more information, there are 2 problems here

1. The more generic problem: as comment #3 shows, the main thread can block acquiring the mutex while the mutex is held by the decoding thread. If the decoding thread holds the mutex for a long time, the main thread will block accordingly.

2. The specific problem, a JPG image of 1600x1200 makes the problem more observable because DecodeWorker holds the mutex for a long time. A photo taken using the camera app doesn't make DecodeWorker hold the mutex for that long even though the photo is larger (1944x2592). Maybe the 1600x1200 image hit some corner case in decoding.
(In reply to Cervantes Yu from comment #4)
> 2. The specific problem, a JPG image of 1600x1200 makes the problem more
> observable because DecodeWorker holds the mutex for a long time. A photo
> taken using the camera app doesn't make DecodeWorker hold the mutex for that
> long even though the photo is larger (1944x2592). Maybe the 1600x1200 image
> hit some corner case in decoding.

The decoder should yield periodically and let the main thread acquire the lock. So maybe there is some bug in the yielding behaviour when decoding that specific image?
(In reply to Cervantes Yu from comment #4)
> 1. The more generic problem: as comment #3 shows, the main thread can block
> acquiring the mutex while the mutex is held by the decoding thread. If the
> decoding thread holds the mutex for a long time, the main thread will block
> accordingly.

That will definitely be fixed by bug 1079627.

> 2. The specific problem, a JPG image of 1600x1200 makes the problem more
> observable because DecodeWorker holds the mutex for a long time. A photo
> taken using the camera app doesn't make DecodeWorker hold the mutex for that
> long even though the photo is larger (1944x2592). Maybe the 1600x1200 image
> hit some corner case in decoding.

That's interesting. It's possible, as Timothy suggests in comment 5, that there's a bug in the decoder's yielding code. But I wonder if that particular image is just hitting a very slow path, that's made much worse by running on a relatively slow device. Two things I can think of:

- Maybe we're decoding that image progressively. That's _very_ bad for large images. There's already an open bug on this: bug 1047096. I haven't had a chance to write a patch yet, but it's easy; I can get a fix into B2G 2.2.

- Maybe the image is causing us to have to do some expensive color management. I've seen bugs before where this was very slow even on desktop.

Cervantes, is there any chance you could put the image that causes the problem online somewhere so I can debug this locally?
Flags: needinfo?(cyu)
(Reporter)

Comment 7

4 years ago
(In reply to Seth Fowler [:seth] from comment #6)
> Cervantes, is there any chance you could put the image that causes the
> problem online somewhere so I can debug this locally?

It's the reference-workload image: https://raw.githubusercontent.com/mozilla-b2g/gaia/master/test_media/reference-workload/MasterGalleryImage.jpg
Flags: needinfo?(cyu)
You need to log in before you can comment on or make changes to this bug.