Investigate performance of action forms in 2.13 #3837

abbyad · 2017-08-29T16:27:53Z

With 2.13.0-beta.10 it is taking ~5-12 seconds to load Action forms on standard.app (eg the Delivery form). It seems to take longer from the contact profile vs from the history tab. This could perhaps be related to inputs being populated, which contains a db-object.

We need to investigate this further to characterize the performance and determine if 2.13 can be released as such.

The text was updated successfully, but these errors were encountered:

garethbowen · 2017-08-30T02:13:28Z

I've managed to eek out some small gains in the contact summary service but putting breakpoints in the code it looks like the bottleneck is Enketo rendering.

@abbyad Is there a 2.12 instance with the same forms we can use for comparison?

@alxndrsn Any ideas? Do you think it could be related to binding the contact summary into the form?

You can test 2.13.0 here: https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/#/contacts/02a2c7eba7e4f4a92aa04ff5c2072419/report/delivery

Don't compile it every time the contact summary is requested. Invalidation is handled by the page being refreshed on configuration change. #3837

alxndrsn · 2017-08-30T08:59:08Z

Don't compile it every time the contact summary is requested. Invalidation is handled by the page being refreshed on configuration change. #3837

garethbowen · 2017-08-30T09:03:40Z

I've merged my caching improvements to master and we can backport if it'd help but I think there's something else going on that I haven't been able to detect yet...

abbyad · 2017-08-30T17:37:29Z

I will create and post links to forms today with minor variants that seem to have some effect on performance so that they can be profiled.

abbyad · 2017-08-30T22:10:00Z

Here are some variants of the delivery form, which I then tested on 2.13.0-beta.10 on standard.app.

@alxndrsn offered to do some detailed profiling of the forms, but in the meantime here are some stopwatch results:

Form	Opened from History tab	Opened from Person's profile
`issue-3837-0-no-change`	1.5s	6s
`issue-3837-1-no-translations`	1s	3.5s
`issue-3837-2-no-secondary-instance`	1s	3.5s
`issue-3837-3-no-db-object`	1s	3s

Opening the forms from the History tab does not run contact-summary, nor pass any info to the form, which is helpful for quick check before proper profiling is done tomorrow.

From this quick analysis it looks like removing unused <translations> has the biggest benefits, although not terribly practical for Standard projects. That said, it probably means this isn't anything new in 2.13 so may not be a blocker, but we can wait until the proper profiling before making that call.

sglangevin · 2017-08-31T15:14:23Z

Just a note that I did some quick testing on a Tecno Y4, v2.13.0-beta.10, container v0.3.6 and I don't see a noticeable difference between the contacts tab and history tab. I also don't think the performance has degraded significantly, but it is definitely slower to open forms than it was in the past. I also noticed that contact-summary seems to run when you open a form from the Tasks tab. Is that necessary to populate certain fields?

alxndrsn · 2017-08-31T15:21:45Z

On remote server

The first five network requests when loading the linked contact are impressively slow:

alxndrsn · 2017-08-31T15:30:55Z

Loading the actual form

N.B. this is with an all-access/fully-online user

Queries

why isn't the favicon cached?
does the user object really (need to) get loaded twice simultaneously?

alxndrsn · 2017-08-31T16:04:12Z

Profile of loading the delivery form on standard.app

=>

`.trigger()`

This looks like it's part of jQuery.

`setVal()`

This looks like it's part of enketo.

`evaluate()`

This is part of our XPath evaluator.

abbyad · 2017-08-31T18:32:46Z

As requested by @alxndrsn, here is a version without the output fields in the labels: issue-3837-4-no-outputs.zip

This can also be seen in action on standard.app

Don't compile it every time the contact summary is requested. Invalidation is handled by the page being refreshed on configuration change. #3837

alxndrsn · 2017-09-01T09:31:57Z

Loading this form calls jsEvaluate() 2,500 times. This implies 2.5k xpath expressions are evaluated...

alxndrsn · 2017-09-01T09:45:48Z

From a page refresh:

Form	`jsEvaluate()` count	Time to load on server
0 - No Change	2452	15s
1 - No Translations	856	8s
2 - No Secondary Instance	856	6s
3 - No db-object	170	7s
4 - No outputs	52	3s

Time to load was measured for Toronto Health Centre in Firefox after loading a few forms for the same user, including the form in question. A single timing was taken.

Observations

It seems a strange coincidence that 1 and 2 should have the same call count when the change made is so different, unless the only translated elements are in the secondary instance.
db-object is doing something pathological
A few things we do in our forms seem to severely affect enketo performance
Outputs!?!?

alxndrsn · 2017-09-01T10:23:32Z

Conclusion

Removing the `jr:choice-name()` patch improves things significantly:

Form	`jsEvaluate()` count (with patch)	`jsEvaluate()` count (without patch)
0 - No Change	2452	58
1 - No Translations	856	58
2 - No Secondary Instance	856	58
3 - No db-object	170	54
4 - No outputs	52	52

Recommendation

~~Re-deploy webapp to standard.app with `jr:choice-name() patch removed and test performance~~ [DONE]
find a replacement for our jr:choice-name() and update our forms

References

alxndrsn · 2017-09-01T10:26:52Z

The final tests above were done on master. I'm going to re-test this on the 2.13.x branch, as the jr:choice-name() patch was slightly different in that release. I expect similar results.

alxndrsn · 2017-09-01T10:36:53Z

`2.13.x` branch

Form	`jsEvaluate()` count (with patch)	`jsEvaluate()` count (without patch)
0 - No Change	2566	84

Patch is to provide second-level calculations based on jr:choice-name().

alxndrsn · 2017-09-01T10:52:00Z

I've manually removed the jr:choice-name() patch on standard.app and see form load times of around 5s for both 0 - No change and 4 - No outputs.

abbyad · 2017-09-01T16:49:32Z

After discussion with @alxndrsn we will attempt to get around the (over)use of jr:choice-name(), especially as used for g_chw_sms in the forms above. That calc sets the default value for a text field based on prior inputs, and the default value is a template that includes other values such as patient name, ID eg Good news, ${chw_name}! ${patient_name} (${r_patient_id}) has delivered at the health facility.

One strategy is to use itext() instead, as seen in this simplified example:
<bind calculate="jr:itext( '/delivery/group_note/default_chw_sms/anc_only_home_sba_birth:label' )" nodeset="/delivery/group_note/g_chw_sms" type="string"/>

However this gives the following error:
Error loading form Error: ["FormLogicError: Could not evaluate: jr:itext( '/delivery/group_note/default_chw_sms/anc_only_home_sba_birth:label' ), message: Failed to execute 'evaluate' on 'Document': The string 'jr:itext(\"/delivery/group_note/default_chw_sms/anc_only_home_sba_birth:label\")' is not a valid XPath expression."]

The form issue-3837-0-5-no-choice-name.zip can be seen in standard.app

garethbowen · 2017-09-03T22:09:31Z

@alxndrsn This is marked for "Code review" but I think it should be "Won't fix: Not an issue" because there's no code change. Does that make sense?

alxndrsn · 2017-09-04T09:29:14Z

I'd quite like someone to check my working 😄

Also I don't think "not an issue" is a very helpful label when this clearly is an issue. Just not one whose solution can be tested or released in the standard way.

alxndrsn · 2017-09-05T18:10:28Z

@garethbowen did you check this before changing the status?

garethbowen · 2017-09-05T21:08:27Z

The logic looks fine to me. I put it in AT so the performance could be tested.

alxndrsn · 2017-09-06T10:08:36Z

I put it in AT so the performance could be tested.

I haven't made any changes to code.

abbyad · 2017-09-06T21:57:12Z

The performance AT is blocked on #3870

alxndrsn · 2017-09-07T08:47:16Z

This ticket was to investigate the performance; I was requesting a review of my investigation. Acceptance testing is to e.g. check the conclusions & recommendations I made.

garethbowen · 2017-09-18T18:10:29Z

As discussed in the planning meeting: the investigation is done, and performance improvements can be tested with #3870

garethbowen added a commit that referenced this issue Aug 30, 2017

Cache contact summary generator function

bc2bc47

Don't compile it every time the contact summary is requested. Invalidation is handled by the page being refreshed on configuration change. #3837

garethbowen mentioned this issue Aug 30, 2017

Cache contact summary generator function #3841

Merged

5 tasks

garethbowen added a commit that referenced this issue Aug 30, 2017

Cache contact summary generator function

6956b8f

Don't compile it every time the contact summary is requested. Invalidation is handled by the page being refreshed on configuration change. #3837

garethbowen added Priority: 2 - Medium Normal priority Status: 1 - Triaged Type: Performance Make something faster labels Aug 31, 2017

garethbowen added this to the August 21 - September 4 milestone Aug 31, 2017

alxndrsn mentioned this issue Aug 31, 2017

Favicon is not cached #3858

Closed

garethbowen added a commit that referenced this issue Aug 31, 2017

Cache contact summary generator function

e7c6e34

Don't compile it every time the contact summary is requested. Invalidation is handled by the page being refreshed on configuration change. #3837

alxndrsn closed this as completed Sep 1, 2017

alxndrsn added Status: 3 - Code review and removed Status: 1 - Triaged labels Sep 1, 2017

alxndrsn assigned abbyad and garethbowen Sep 1, 2017

garethbowen removed their assignment Sep 3, 2017

garethbowen added Status: 4 - Acceptance testing and removed Status: 3 - Code review labels Sep 4, 2017

abbyad mentioned this issue Sep 5, 2017

Workaround needed for stale jr:choice-name() values #3870

Closed

abbyad added the Status: Blocked Unable to progress this. label Sep 6, 2017

abbyad reopened this Sep 6, 2017

alxndrsn closed this as completed Sep 7, 2017

alxndrsn removed the Status: Blocked Unable to progress this. label Sep 7, 2017

alxndrsn reopened this Sep 7, 2017

garethbowen closed this as completed Sep 18, 2017

garethbowen added Status: 6 - Released and removed Status: 4 - Acceptance testing labels Sep 18, 2017

sglangevin added Status: 6 - Released and removed Status: 5 - Ready labels Oct 4, 2017

abbyad removed their assignment Nov 28, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Investigate performance of action forms in 2.13 #3837

Investigate performance of action forms in 2.13 #3837

abbyad commented Aug 29, 2017

garethbowen commented Aug 30, 2017 •

edited

Loading

alxndrsn commented Aug 30, 2017

garethbowen commented Aug 30, 2017

abbyad commented Aug 30, 2017

abbyad commented Aug 30, 2017

sglangevin commented Aug 31, 2017

alxndrsn commented Aug 31, 2017

alxndrsn commented Aug 31, 2017

alxndrsn commented Aug 31, 2017

abbyad commented Aug 31, 2017

alxndrsn commented Sep 1, 2017

alxndrsn commented Sep 1, 2017 •

edited

Loading

alxndrsn commented Sep 1, 2017 •

edited

Loading

alxndrsn commented Sep 1, 2017

alxndrsn commented Sep 1, 2017 •

edited

Loading

alxndrsn commented Sep 1, 2017

abbyad commented Sep 1, 2017

garethbowen commented Sep 3, 2017

alxndrsn commented Sep 4, 2017

alxndrsn commented Sep 5, 2017

garethbowen commented Sep 5, 2017

alxndrsn commented Sep 6, 2017 •

edited

Loading

abbyad commented Sep 6, 2017

alxndrsn commented Sep 7, 2017

garethbowen commented Sep 18, 2017

Investigate performance of action forms in 2.13 #3837

Investigate performance of action forms in 2.13 #3837

Comments

abbyad commented Aug 29, 2017

garethbowen commented Aug 30, 2017 • edited Loading

alxndrsn commented Aug 30, 2017

garethbowen commented Aug 30, 2017

abbyad commented Aug 30, 2017

abbyad commented Aug 30, 2017

sglangevin commented Aug 31, 2017

alxndrsn commented Aug 31, 2017

On remote server

alxndrsn commented Aug 31, 2017

Loading the actual form

Queries

alxndrsn commented Aug 31, 2017

Profile of loading the delivery form on standard.app

.trigger()

setVal()

evaluate()

abbyad commented Aug 31, 2017

alxndrsn commented Sep 1, 2017

alxndrsn commented Sep 1, 2017 • edited Loading

Observations

alxndrsn commented Sep 1, 2017 • edited Loading

Conclusion

Removing the jr:choice-name() patch improves things significantly:

Recommendation

References

alxndrsn commented Sep 1, 2017

alxndrsn commented Sep 1, 2017 • edited Loading

2.13.x branch

alxndrsn commented Sep 1, 2017

abbyad commented Sep 1, 2017

garethbowen commented Sep 3, 2017

alxndrsn commented Sep 4, 2017

alxndrsn commented Sep 5, 2017

garethbowen commented Sep 5, 2017

alxndrsn commented Sep 6, 2017 • edited Loading

abbyad commented Sep 6, 2017

alxndrsn commented Sep 7, 2017

garethbowen commented Sep 18, 2017

garethbowen commented Aug 30, 2017 •

edited

Loading

`.trigger()`

`setVal()`

`evaluate()`

alxndrsn commented Sep 1, 2017 •

edited

Loading

alxndrsn commented Sep 1, 2017 •

edited

Loading

Removing the `jr:choice-name()` patch improves things significantly:

alxndrsn commented Sep 1, 2017 •

edited

Loading

`2.13.x` branch

alxndrsn commented Sep 6, 2017 •

edited

Loading