1022482 - [dolphin][perf] improve the performance of deleting pictures

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: Gaia::Gallery, defect, P2)

Description

[Peipei Cheng (needinfo if you need my action)]

Here is the test data of deleting 100 picture:
Dolphin: 13.18 s
7715 android: 2.52s
6821 android: 5.62

Following are the analysis from spreadtrum after adding gaia logs.

Test 1:
# It took 0.082s for the "for" loop.
[1401924077.787]  Enter function before for loop   
[1401924077.869]  Enter function after for loop   

# The first successful deletion and last successful has a gap of: 1.009s
[1401924080.822] /sdcard0/photos/ztLP6w==_T8hPWaAbEUyU.gif Enter function storage.delete.onsuccess //The first successful deletion
[1401924081.831] /sdcard0/photos/SW2s_1183292368.bmp Enter function storage.delete.onsuccess  //The last successful deletion

Test 2:
# It took 0.082s for the "for" loop.
[1401924077.787]  Enter function before for loop  //for loop start
[1401924077.869]  Enter function after for loop   //for loop end

# The first successful deletion and last successful has a gap of: 1.009s
[shufang] [1401924080.822] /sdcard0/photos/ztLP6w==_T8hPWaAbEUyU.gif Enter function storage.delete.onsuccess
[shufang] [1401924081.831] /sdcard0/photos/SW2s_1183292368.bmp Enter function storage.delete.onsuccess

Test 3:
# It took 0.106s for the "for" loop.
[1401935285.604]  Enter function before for loop
[1401935285.71]  Enter function after for loop
shufang: to clearSelection time [1401935285.711]  no pictures  //After cleaning up pictures：0.001s

# The first successful deletion and last successful has a gap of: 1.164s
[shufang] [1401935288.346] /sdcard0/photos/__163W~8.JPG Enter function storage.delete.onsuccess //The first successful deletion
[shufang] [1401935289.51] /sdcard0/photos/6.jpg Enter function storage.delete.onsuccess  //The last successful deletion

Analysis：
It actually took very little time for gaia to remove pictures. So most of the time should be spent on removing pictures from mediadb.

Comment 1

[ben.song]

root cause:
1)Delete 100 pictures of storage time consuming 0.925s.
           
2)Delete entry function executed from deleteSelectedItems () to media.js in the deleteFiles () function only takes 3.23s.But there is a bottom DBRequest.transaction API in deleteFiles (), this API return onsuccess about 0.1s delay every time,When you remove a small amount of picture is not affected, but when you delete 100 pictures, delay reached about 11s, the time delay in the whole delete the proportion accounted for 76%.So the bottom DBRequest.transaction API have delay.
          
 3)Delete 100 pictures belongs parent container DOM element of time is 1.2s.

Comment 2

[ben.song]

Specific analysis process is as follows:
     setup 1:When user selects 100 pictures to delete,deleteFile(filename) in mediadb.js  will delete the corresponding file storage.(storage:navigator.getDeviceStorage(mediaType)) The process total take 0.925s.

     setup 2:to delete the storage corresponding to the file would trigger an event of 'change' specified in the storage,the event handler changeHandler() would be called ,after that enter deleteRecord()  and add filename of this file into an array of pendingDeletions to ready for deleting, finally enter processingQueue().

     setup 3:in processingQueue(),access to the IDBObjectStore object through media.db.transaction.objectStore(),then use delete() of IDBObjectStore object to delete the record of the file from object store and return an IDBRequest object, finally specify a onsuccess event for the IDBRequest object to wait for a response. The process From the set of onsuccess event to the response total take 11 s which hode 76% percentage of the total time. 

    setup 4:Wait until after the onsuccess processingQueue response, and then call its event handler, and transferred queueDeleteNotification () to determine the current deletes, that is whether the current cumulative volume reaches a specified volume, if reached then transferred sendNotifications (), empty deletes the accumulated volume, transferred dispatchEvent () distributed deleted types of events.
    setup 5:dispatchEvent () call the handler specified ondelete be deleted. Delete all the pictures of the interface takes 1.2s.

Comment 3

[Jan Jongboom [:janjongboom] (inactive)]

So quick analysis from my side (on Peak 1.4): most requests are fast, but every 3rd or so takes 300 ms. All this work is spent in IDBObjectStore.cpp. Here is an example of where the time goes:

I/IDBObjectStore(  411): IDBObjectStore.delete 0ms.
I/IDBObjectStore(  126): IDBObjectStore.delete doDatabaseWork 4ms.
I/IDBObjectStore(  411): IDBObjectStore.delete getSuccessResult 332ms.

That seems excessive to me, deleting an item from IDB should not take that long. Pinging bent as he's the IDB owner.

This is a list of timings of deleting files by the way measured from gaia, 98% of this time is spent in IDBObjectStore (391, 66, 33, 397, 66, 33, 377, 52, 30, 352, 58, 31, 338, 44, 29, 322, 224, 28, 307)

If this something we can't address in Gecko land, we should not queue to delete from IDB and rather just do multiple at a time. Have to measure perf of that as well.

Comment 4

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Hi Jan,

Are those times listed measuring the time spent inside the function? Or are they timestamps? http://mxr.mozilla.org/mozilla-central/source/dom/indexedDB/IDBObjectStore.cpp#3656 shows that DeleteHelper::GetSuccessResult should be lightning-fast, so I'm betting that these are timestamps.

Timestamps are often misleading when dealing with async storage like IDB. Every action has to wait its turn to go through event loops and with IDB there could be other transactions that delay the start of the operation. A real profile is often a much better diagnostic tool for cases like this. At the very least it's better to collect a timestamp at the start and end of a function so that event loop latency is visible.

But most likely here something in DeleteHelper::DoDatabaseWork is taking a long time. http://mxr.mozilla.org/mozilla-central/source/dom/indexedDB/IDBObjectStore.cpp#3648 shows that it doesn't do much except call into SQLite, so we'd need to look deeper there.

There's nothing wrong with issuing multiple delete commands at once without waiting for each request's success callback. (Your application logic might need that behavior but IDB doesn't require it.)

Comment 5

[Ivan Tsay (:ITsay)]

Hi Pei-pei,

Could you help to check if Buri performs the same as Dolphin with v1.4? For the performance issue, we want to compare it with Buri first.

Comment 6

[Peipei Cheng (needinfo if you need my action)]

Average time on Buri v1.4 is 10 seconds for 100 pictures which is similar to Dolphin.

Comment 7

[Ivan Tsay (:ITsay)]

Remove noms for now since buri performs the same.

Comment 8

[ranjith253]

Updating performance values with latest FFOS v2.2 on flame device.
For deleting 500 images.
Iteration 1 (MM:SS:MS): 00:41:75
Iteration 2 (MM:SS:MS): 00:41:15
Iteration 3 (MM:SS:MS): 00:40:42

Comment 9

[BMO Automation]

Firefox OS is not being worked on