889724 - [Call log] Call log takes too long time when loading call log list

Status: RESOLVED INVALID

(Firefox OS Graveyard :: Gaia::Dialer, defect, P1)

Description

[Leo]

+++ This bug was initially created as a clone of Bug #857398+++

1. Title : Call log takes too long time when loading call log list
2. Precondition : Existing list 500 items in Call log
3. Tester's Action : Enter call log
4. Detailed Symptom : Dialer app takes 18.9 seconds(3 times average), however it should be 1.5 seconds according to leo device spec.
5. Expected : Dialer app takes under 1.5 seconds
6. Reproducibility: Y
1) Frequency Rate : 100%

Call log performance is highly improved than before version. But, our QE team want dialer app takes under 1.5 seconds(When we calculate time, dialer app takes about 5.5 ~ 6.0 seconds). Do you improve call log more?

Comment 1

[Fernando Jiménez Moreno [:ferjm]]

Is this really happening after bug 847406? I really cannot reproduce this...

Comment 2

[Leo]

Sorry, I have a mistake. I change Detailed Symtom

========================================

4. Detailed Symptom : Dialer app takes 5.5 seconds(3 times average), however it should be 1.5 seconds according to leo device spec.

Comment 3

[Fernando Jiménez Moreno [:ferjm]]

I am not sure about what else we can do apart from bug 862385.

In any case, how are you measuring this timings?

Did you noticed bug 829399? There is not a chance that the call log gets to 500 items in normal conditions (you can still populate the db manually, but that's obviously not an user case). The limit is 250 items.

Comment 4

[Dietrich Ayala (:dietrich)]

Changing to leo- based on comment #23.
Leo, can you please:

1. retest with 250 (the built-in limit, per comment #23) and provide your results. If >1.5s then please re-set this bug to leo+.

2. please provide information on your testing method, so we can ensure we're testing the same thing, and verify that your method is correct.

Comment 5

[promise09th]

1. I can't input 250 call logs because when I input more 200 lists, call log deletes 30 lists
So, I test only 200 call logs.

Test result is :
1st time : 3.2 s
2nd time : 3.1 s
3rd time : 3.2 s

2. I input 200 logs, and method is :
(1) Run dialer app
(2) Select call log section and start stop watch at the same time
(3) When call logs show, I stop stop watch.


So, I change project flags to leo+

Comment 6

[Gabriele Svelto [:gsvelto]]

I've just retested this on my Leo, I'm using the following:

- gecko (mozilla-b2g18) 2b310a1e066d2efa12e57a3e1a72e5d278a5581f
- gaia (master) 057202ae7eed00b3c34208faf2b13b424c84691b
- 200 call log entries loaded from gaia with 'APP=communications/dialer make reference-workload-heavy'

Using your method the delay between tapping the call log button and when the first elements appear seems well below 1.5s (it looks ~1s but it's hard to measure such a short interval using a stop-watch). Could you please provide the gaia and gecko versions you've used for testing? It seems to me that the problem is fixed on gaia/master so I'm wondering if you've been testing v1-train instead.

Comment 7

[promise09th]

I'm using following device :

Gaia revision (v1-train) : 0d5a9a7577f16b6a72a982148c6f509ee1714ea2
Gecko revision : 499c1f8ea7ad0cdaa7086214278e2944b8a2ea33

and, I measure time not to show one list but to fill the screen(generally, show 4 lists)

Comment 8

[Leo]

Attachment: Measuring state

Comment 9

[Gabriele Svelto [:gsvelto]]

(In reply to promise09th from comment #7)
> and, I measure time not to show one list but to fill the screen(generally,
> show 4 lists)

OK, I could reproduce this issue but only under special conditions. Both on v1-train and master I can measure a ~4s delay before the screen is filled using the following procedure:

- install a clean gaia with |make reset-gaia|

- create a database of 200 calls using the reference workloads |APP=communications/dialer make reference-workload-heavy

- the first time I open the dialer and switch to the call log it takes 4s to fill up the list

After this it always takes one second, even if I reboot the phone. I suspect that it's happening because the dialer needs to create its internal databases the first time it runs and this might be slowing down the call log display.

However this is not a realistic scenario: the first time the user opens the dialer he won't have 200 calls in the log, the only way to hit this case is to have an artificial workload and even then it happens only once. Could you please check that this is happening only the first time too? If that's the case then I think we should re-evaluate this bug.

Comment 10

[Mike Lee [:mlee]]

(In reply to Gabriele Svelto [:gsvelto] from comment #9)
> 
> ...I suspect that it's happening because the dialer needs to create its internal databases the first time it runs and this might be slowing down the call log display.
> 
> However this is not a realistic scenario: the first time the user opens the
> dialer he won't have 200 calls in the log, the only way to hit this case is
> to have an artificial workload and even then it happens only once. Could you
> please check that this is happening only the first time too? If that's the
> case then I think we should re-evaluate this bug.

Gabriele, is that true even after a reboot? Do we know all the scenarios that trigger that DB's creation? Do we have any restore process that might also expose users to this?

Would we good to confirm Gabriele's suspicion.

Comment 11

[Gabriele Svelto [:gsvelto]]

(In reply to Mike Lee [:mlee] from comment #10)
> Gabriele, is that true even after a reboot?

Yes, after rebooting the phone, opening the call log is still fast.

> Do we know all the scenarios that trigger that DB's creation?
> Do we have any restore process that might also expose users to this?

I'm not sure but I can investigate and take a profile of this specific scenario if you think it might be worth it.

Comment 12

[Mike Lee [:mlee]]

(In reply to Gabriele Svelto [:gsvelto] from comment #11)
> ...
> I'm not sure but I can investigate and take a profile of this specific
> scenario if you think it might be worth it.

If we can confirm both of your suspicions that:

1. It's the DB's creation that causes the slowdown
2. The DB creation only happens once on the very first use if Dialer

I'd agree that this shouldn't be a leo blocker.

Comment 13

[Gabriele Svelto [:gsvelto]]

I've taken two profiles of the call log been shown, the first one is after generating the reference workload and contains the 4s delay:

http://people.mozilla.com/~bgirard/cleopatra/#report=f02c309d39d430c288d1ebdf5d85afb2ef1357d8

Look to the right side of the profile: there's a long period of inactivity followed by a burst of activity which corresponds to me clicking the log button. Before the first rdbm_getList() call hits cursor.onsuccess() for the first time there's a ~3 seconds delay which is spent entirely in the call_log_db.js file and specifically in CallLogDBManager._upgradeSchemaVersion3() which is (re)creating the database according to version 3 of the call log database schema. This is the exact line where the script gets stuck:

https://mxr.mozilla.org/gaia/source/apps/communications/dialer/js/call_log_db.js?force=1#206

On the other hand this is the profile as taken after the first run and after rebooting the phone:

http://people.mozilla.com/~bgirard/cleopatra/#report=01ddf43d949278ee95d84a363992bd08c351e210

As you can see on the right the long initial delay is gone and the call log begins repainting after less than 1s.

Now, apparently the delay is happening when the DB is being created or upgraded but looking through the code I could see no instance of us using the older schema. gaia/v1-train and gaia/master both use version 3 so there we won't hit this delay when upgrading from 1.1 to 1.2. I'm not sure about the 1.0.1 -> 1.1 transition, but it certainly shouldn't affect Leo as it won't ship with 1.0.1 in the first place.

Comment 14

[Jon Hylands [:jhylands]]

(In reply to Gabriele Svelto [:gsvelto] from comment #13)

> Now, apparently the delay is happening when the DB is being created or
> upgraded but looking through the code I could see no instance of us using
> the older schema. gaia/v1-train and gaia/master both use version 3 so there
> we won't hit this delay when upgrading from 1.1 to 1.2. I'm not sure about
> the 1.0.1 -> 1.1 transition, but it certainly shouldn't affect Leo as it
> won't ship with 1.0.1 in the first place.

If you're using a reference workload, the current dialer DB is created using version 2, so that is why there is the initial one-time upgrade to version 3.

Comment 15

[Fernando Jiménez Moreno [:ferjm]]

Thanks for the profiles Gabriel!

I can confirm that the delay happens when the DB is upgraded (the creation should be fast enough as there is no data migration, only object stores and indexes deletions/additions). The call log renders the first chunk of data in ~1s in normal conditions (even if the group count is close to the 200 limit).

The DB upgrade would only happen when there are changes in the DB schema or the DB version is bumped, which should only happen after a Dialer update (most likely via OTA/FOTA).

In any case, the bad UX provided during the DB upgrade process is mitigated in bug 862385 with the addition of a progress bar with a percentage that is shown to the user while the database is being upgraded.

Comment 16

[Gabriele Svelto [:gsvelto]]

(In reply to Jon Hylands [:jhylands] from comment #14)
> If you're using a reference workload, the current dialer DB is created using
> version 2, so that is why there is the initial one-time upgrade to version 3.

Thanks for confirming this Jon; in the light of this and comment 15 I would suggest to close this as INVALID because the problem won't affect any v1.1 Leo users and will have minimal impact on all the others. Leo, do you agree?

Comment 17

[promise09th]

I ask QE team and reply

Comment 18

[Preeti Raghunath(:Preeti)]

moving to leo- based on Comment 16.

Re-nom later if needed.

Comment 19

[Gabriele Svelto [:gsvelto]]

Thanks for your feedback, let's close this for now.