Core Apps: Very long TTFB for patientDashboard.page when many encounters

mksd · November 4, 2016, 1:07pm

Hi all,

In my quest to work around the loading issues of patientDashboard.gsp I realised that there were in fact two problems happening at the same time when loading that page for a visit with many encounters (say 100+). The first issue is discussed here and is addressed by RA-1244.

The other problem happens before anything else and I can’t quite put my finger on what is happening, look:

After that almost 12 sec waiting time, and only then, the first lines of the controllers are reached and other pieces of code (JS… etc). But what may be causing this initial loading time?

Could anyone give pointers as to which directions to look at?

lluismf · November 4, 2016, 4:44pm

Can you debug Spring’s DispatcherServlet ? Maybe you can see where the time is spent.

mksd · November 4, 2016, 5:17pm

Thanks @lluismf. Something happens in between those two steps in the thread:

The webapp lands right away at the breakpoint in doService(HttpServletRequest, HttpServletResponse) and needs another 12 secs to reach doDispatch(HttpServletRequest, HttpServletResponse).

I’m not familiar with all this but I’ll try to understand what happens inside doService(..)…

mksd · November 4, 2016, 5:36pm

After debugging further I can see that everything is fine up to that point:

github.com

spring-projects/spring-framework/blob/3.1.x/org.springframework.web/src/main/java/org/springframework/web/bind/annotation/support/HandlerMethodInvoker.java#L176


				}
				if (!implicitModel.containsAttribute(attrName)) {
					implicitModel.addAttribute(attrName, attrValue);
				}
			}
			Object[] args = resolveHandlerArguments(handlerMethodToInvoke, handler, webRequest, implicitModel);
			if (debug) {
				logger.debug("Invoking request handler method: " + handlerMethodToInvoke);
			}
			ReflectionUtils.makeAccessible(handlerMethodToInvoke);
			return handlerMethodToInvoke.invoke(handler, args);
		}
		catch (IllegalStateException ex) {
			// Internal assertion failed (e.g. invalid signature):
			// throw exception with full handler method context...
			throw new HandlerMethodInvocationException(handlerMethodToInvoke, ex);
		}
		catch (InvocationTargetException ex) {
			// User-defined @ModelAttribute/@InitBinder/@RequestMapping method threw an exception...
			ReflectionUtils.rethrowException(ex.getTargetException());
			return null;

Any clues?

lluismf · November 4, 2016, 6:38pm

What’s the value of handlerMethodToInvoke ? It should be the controller’s method with bad performance.

But I doubt that VisitDetailsFragmentController is the culprit, because it receives Visit as a parameter and is populated before. What’s the controller that obtains the Visit from DB, is it PatientDashboardPageController ? Maybe you should implement paging there … but the visit persistent already contains a set of encounters so maybe it’s impossible.

Tip: setting show sql in the hibernate config file will log all the SQL queries performed by Hibernate.

mksd · November 4, 2016, 7:05pm

I am almost certain that it is not VisitDetailsFragmentController either. When debugging while loading the problem page, I can see that I go twice to handlerMethodToInvoke and that the second time is not problematic (no delay) and corresponds to VisitDetailsFragmentController (I can see that visually from the state of the page).

So it “should” be PatientDashboardPageController, but in fact it actually takes 12 sec to get to the first line of this controller as well. I was initially wondering if the Spring injection of some of its parameters could be the issue?

Just restarted everything to answer your actual question, here is what I see just before the delay:

So: org.openmrs.module.uiframework.PageController@7ee3fc35 which could make sense with PatientDashboardPageController.

And the second time (so when there is no delay) it is: org.openmrs.module.uiframework.FragmentActionController@c1469e8 which is consistent with VisitDetailsFragmentController.

lluismf · November 4, 2016, 7:31pm

If this was the case then it should take 12 seconds regardless of the patient, right ?

Both PatientDashboardPageController and VisitDetailsFragmentController have no ancestor class, I ignore its relationship with PageController and FragmentActionController.

If I were you I will keep debugging, enter the invoked method until you detect the performance penalty.

mksd · November 4, 2016, 7:42pm

By debugging further inside UI Framework (v 3.4 here) I could nail down to this exact instruction:

boundTemplate.toString()

That is what takes 12 sec, the Groovy rendering of the view for that page…

mksd · November 4, 2016, 7:51pm

The only difference between two visits (one that loads normally and the one that takes 12 sec) would be how the model is filled right? So by default that will be my next line of investigation: observe the model differences between two visits that have very different loading times…

But of course if something obvious comes to the mind of anyone following this thread, please jump in!

Thanks so far @lluismf!

darius · November 4, 2016, 8:50pm

I would guess that somewhere in the gsp is a line that triggers visit.encounters to be lazy-loaded and this is what gets slow for visits with many encounters.

(It has to be something in the GSP itself, for the slowness to be coming from that line.)

mksd · November 5, 2016, 8:52am

Correct! And the culprit is this loop in visits.gsp:

visits.eachWithIndex { wrapper, idx ->
  def primaryDiagnoses = wrapper.getUniqueDiagnoses(true, false)

Not the loop itself of course but the repeated call to:

wrapper.getUniqueDiagnoses(true, false)

Before/while I look into it in more depth, does that ring a bell that this method may be suboptimal?

mksd · November 5, 2016, 9:24am

So this guy takes up to 10 sec to run for a visit with ~1,000 encounters (sorry @lluismf, I gave misleading numbers earlier but here we go):

github.com

openmrs/openmrs-module-emrapi/blob/1.12/api/src/main/java/org/openmrs/module/emrapi/visit/VisitDomainWrapper.java#L341-L362


	public List<Diagnosis> getUniqueDiagnoses(Boolean primaryOnly, Boolean confirmedOnly) {
		Map<CodedOrFreeTextAnswer, Diagnosis> diagnoses = new LinkedHashMap<CodedOrFreeTextAnswer, Diagnosis>();
		for (Encounter encounter : getSortedEncounters(SortOrder.MOST_RECENT_FIRST)) {


List<Diagnosis> diagnosesFromEncounter = getDiagnosesFromEncounter(encounter);
if (diagnosesFromEncounter == null) {
    return null;
}


			for (Diagnosis d : diagnosesFromEncounter) {
				if (!primaryOnly || d.getOrder() == Diagnosis.Order.PRIMARY) {
					if (!confirmedOnly || d.getCertainty() == Diagnosis.Certainty.CONFIRMED) {
						if (!diagnoses.containsKey(d.getDiagnosis())) {
							diagnoses.put(d.getDiagnosis(), d);
						}
					}
				}
			}


		}

This file has been truncated. show original

@darius, what do you think, in the context of Core Apps’ visits.gsp and our need of a quick fix, should we look at optimising that specific method and open an EA ticket, or would there be an easier/faster way to patch just that page?

After looking real quick, it seems that the main source of inefficiency is the 1,000+ calls of

getDiagnosesFromEncounter(encounter)

lluismf · November 5, 2016, 6:32pm

Not sure if it’s a quick fix, but I would replace these nested loops by a single SQL query.

Other methods in this class have the same potential problem e.g. getDiagnosesFromMostRecentDispositionByType

darius · November 7, 2016, 7:17pm

Hmm, this is tricky to find a quick fix for.

One option is making it asynchronous. (This may still leave a bunch of server load.)

Better option is to write an explicit SQL or HQL query to get primary diagnoses by visit, as Lluis suggests.

-Darius (by phone)

mksd · November 11, 2016, 7:10pm

@darius, @lluismf, could you point me to an example where something similar is done? I’m talking about the plumbing involved in creating a new API function whose implementations rests on a SQL or HQL query.

darius · November 11, 2016, 8:35pm

Check out

github.com

openmrs/openmrs-module-emrapi/blob/master/api/src/main/java/org/openmrs/module/emrapi/concept/HibernateEmrConceptDAO.java

/*
 * The contents of this file are subject to the OpenMRS Public License
 * Version 1.0 (the "License"); you may not use this file except in
 * compliance with the License. You may obtain a copy of the License at
 * http://license.openmrs.org
 *
 * Software distributed under the License is distributed on an "AS IS"
 * basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the
 * License for the specific language governing rights and limitations
 * under the License.
 *
 * Copyright (C) OpenMRS, LLC.  All Rights Reserved.
 */

package org.openmrs.module.emrapi.concept;

import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collection;
import java.util.Collections;

This file has been truncated. show original

As well as the related service.

-Darius (by phone)

mksd · November 12, 2016, 12:54pm

Thanks Darius.

And what’s your recommended approach to test (while developing) those queries? If possible on a real database. Or I guess my question is: how can I play around with this without launching the whole webapp?

ssmusoke · November 12, 2016, 1:01pm

@mksd if you are using IntelliJ - you can use the Hibernate Console.

Checkout whatever branch of OpenMRS core you are using and setup the console against the hibernate-cfg.xml file.
Create a Data source connection to your MySQL database running openmrs so that you can query it
Follow the steps here https://www.jetbrains.com/help/idea/2016.2/hibernate-console-tool-window.html

mksd · November 12, 2016, 1:09pm

Ah thanks @ssmusoke, exactly what I was looking for! I will try this out soon and report back.

mksd · November 14, 2016, 6:31pm

@darius, @lluismf

Ok I almost have got an HQL query that returns the primary diagnoses, I have further questions:

Q1. Would it be ok to replace the implementation of VisitDomainWrapper.getPrimaryDiagnoses() then? Also, any idea why this method was not used in visits.gsp, is it because it may not return a list of unique diagnoses?

Q2. In your opinion, which DAO class and service should I hook my new DAO method to in EMR API?