System lags when switching to Journal

[jfuhrer]

OFW: Q2C18 Build: 486

This has been a pretty noticeable problem since 485. I'm not sure of the precise conditions by which to reproduce it yet (it always occurs, but sometimes it's far worse than others) but basically, switching to Journal from the donut can be a HUGE hassle a lot of the time. The areas of the Journal that were obscured by the Frame seem to have a really hard time loading, including the Search and Back buttons. And none of the Journal will be usable until thoes areas load. This sort of lag didn't appear in previous builds and it's really important to eliminate when it's a feature as central as Journal.

[tomeu]

Have added some debugging messages that measure performance of refreshing the list of journal entries.

Could you please test again with difference number of journal entries and report the times both on b2 and b3?

This patch will be in the next image after 488.

Thanks!

[jfuhrer]

On a B3 with 23 journal entries present: 14 seconds to load. On a B3 with 8 journal entries present: 6 seconds to load.

On a B2 with 15 journal entries present: 41 seconds to load. On a B2 with 8 journal entries present: 5 seconds to load.

[tomeu]

The following data should give some insights about how are we spending time when refreshing the list view in the journal (numbers are on a b3):

0 entries:

DEBUG - root: datastore.find took 0.167750s and returned 0 entries
DEBUG - root: ListView._update took 0.000000s for 0 entries

1 entry:

DEBUG - root: datastore.find took 0.287241s and returned 1 entries
DEBUG - root: ListView._update took 0.100000s for 1 entries

DEBUG - root: datastore.find took 0.042793s and returned 0 entries
DEBUG - root: ListView._update took 0.000000s for 0 entries

DEBUG - root: datastore.find took 0.089548s and returned 1 entries
DEBUG - root: ListView._update took 0.010000s for 1 entries

DEBUG - root: datastore.find took 0.011119s and returned 0 entries
DEBUG - root: ListView._update took 0.000000s for 0 entries

DEBUG - root: datastore.find took 0.089636s and returned 1 entries
DEBUG - root: ListView._update took 0.010000s for 1 entries

2 entries:

DEBUG - root: datastore.find took 0.266975s and returned 2 entries
DEBUG - root: ListView._update took 0.030000s for 2 entries

DEBUG - root: datastore.find took 0.217557s and returned 2 entries
DEBUG - root: ListView._update took 0.030000s for 2 entries

DEBUG - root: datastore.find took 0.012135s and returned 0 entries
DEBUG - root: ListView._update took 0.000000s for 0 entries

DEBUG - root: datastore.find took 0.211665s and returned 2 entries
DEBUG - root: ListView._update took 0.040000s for 2 entries

8 entries:

DEBUG - root: datastore.find took 2.883188s and returned 8 entries
DEBUG - root: ListView._update took 0.220000s for 8 entries

DEBUG - root: datastore.find took 0.011771s and returned 0 entries
DEBUG - root: ListView._update took 0.000000s for 0 entries

DEBUG - root: datastore.find took 1.602133s and returned 8 entries
DEBUG - root: ListView._update took 0.150000s for 8 entries

DEBUG - root: datastore.find took 0.010984s and returned 0 entries
DEBUG - root: ListView._update took 0.010000s for 0 entries

DEBUG - root: datastore.find took 1.692017s and returned 8 entries
DEBUG - root: ListView._update took 0.110000s for 8 entries

16 entries:

DEBUG - root: datastore.find took 4.397195s and returned 16 entries
DEBUG - root: ListView._update took 0.280000s for 16 entries

DEBUG - root: datastore.find took 0.046173s and returned 0 entries
DEBUG - root: ListView._update took 0.000000s for 0 entries

DEBUG - root: datastore.find took 4.338615s and returned 16 entries
DEBUG - root: ListView._update took 0.270000s for 16 entries

DEBUG - root: datastore.find took 0.079475s and returned 1 entries
DEBUG - root: ListView._update took 0.020000s for 1 entries

DEBUG - root: datastore.find took 1.861575s and returned 8 entries
DEBUG - root: ListView._update took 0.120000s for 8 entries

DEBUG - root: datastore.find took 0.205638s and returned 2 entries
DEBUG - root: ListView._update took 0.030000s for 2 entries

Some comments:

- Time spent in queries that return 0 results are the same regardless of the number of entries in the database. This makes me think the query itself is always fast, so no need of optimizing the data access.

- Time spent in the datastore is proportional to the number of entries _returned_, so I suspect of the ORM in sqlalchemy.

Ben, do you agree with the above? If so, do you think you can reduce considerably the amount of time spent there? Or should be better to implement paging in the journal for trial2? (a bit too late to add so much code, in my opinion)

[marco]

I don't think we should even consider paging until the datastore performance is acceptable. 4 seconds for 16 entries is ridiculous... Also it feels like a regression. We need performance tests in the datastore.

Tomeu, aside from the obvious problem with the datastore, what are the multiple requests there? Are there "optimizations" we can do on the journal side? Can you explain exactly what is going on, i.e. how user actions, datastore calls, and entries in your log are related? For example I thought datastore.find() only returned a list of ids? Where do we get the actual objects...

[tomeu]

We only have one dbus message here, the call to find() returns ids, properties and file names. So I think Ben can just think about profiling and improving performance of the find call, no need to take in account what the journal is doing.

Another hack that we can do is call find() async from the journal and append the entries as they come. But of course I think find() performance can and must be greatly improved.

But not only the datastore must be improved, we also spend too much time setting up the hippo canvas objects: 0.015s/entry. If we have 100 entries we'll spend 1.5s setting up the canvas. Depending on when we deliver a lazy, paged scroll view, this will be a problem or not. But in this point we can do many things to improve perf (we are doing some calls through dbus to the object type registry that could be cached, for example).

[marco]

Please *no* hacks until the situation is resolved. Moving to dbus async calls already managed to hide this issue for several weeks, let's not do that mistake again.

On the other hand improving the hippo-canvas side of the problem make sense.

[tomeu]

Replying to marco:

Please *no* hacks until the situation is resolved.

I think we all agree on this, but I still don't know how much the situation can improve without heavy refactoring, so I share the hacks that pass through my head and that could deliver a good enough experience until we solve things properly.

Moving to dbus async calls already managed to hide this issue for several weeks, let's not do that mistake again.

In the journal we don't have dbus async calls, this performance issue was visible to everybody who played with journal having more than a dozen of entries.

On the other hand improving the hippo-canvas side of the problem make sense.

Looking at this right now.

[marco]

I think we all agree on this, but I still don't know how much the situation can improve without >heavy refactoring, so I share the hacks that pass through my head and that could deliver a good >enough experience until we solve things properly.

The thing is, there is absolutely no hope to be able to provide a decent user experience with 4 secs for 16 entries. We need to something about that, even it requires heavy refactoring.

[marco]

To give an idea of the perf requirements, I think we need to be able to fetch 50 entries in under 0.5 seconds (on B3).

[marco]

Will be much better on image > 508. It would be good to time it again.

[tomeu]

On a B3, we fetch from the datastore 30 entries in 0.5s.

I think this should be improved, but don't feel it's a blocker for trial2 anymore.

Even more because I'm working in lazy scrolling from the journal, that we need anyway due to the memory consumption of loading all entries at once. Ticket about this: #2228.

[jg]

Seems like a plan. lazy scrolling + memory consumption work certainly seems the right direction for now.

[marco]

Ok, so making this Trial-3. Lazy scrolling is covered by #2228

[marco]

I'm closing this since journal performance seem pretty good on the latest images.