I got assigned task with two pages loading too long time. The first one was about custom form with password reset functionality (solved). The second one was poorly described and was about some certifications take long time to load (moved to next post).
Password reset page
Lets start with the custom page for password reset. Some basic info. Different roles have access to different users and acounts, e.g. manager, user administrator or basic user with admin accounts.
Workflow did not contain extensive QueryOptions or context search, but the Form did have quite large QueryOption and quite a few filters for AND and OR clauses.
My first approach and funny silly debug mistake.
This was initital process to confirm that the slow performance is caused by the custom code and not by OOTB IIQ.
This line is for future retrospective if ever changes: so far I have not found a better way on how to debug XML objects in IIQ. The only way is through “console output messages” into a log file.
These are the last lines of the first script section.
qo.addFilters(filters);
return (context.countObjects(qo,));I add lines above to the Form objects scrpt fields, like this
log.error("script identity start")
...
qo.addFilters(filters);
log.error("script identity end");
return (context.countObjects(Links.class,qo) > 0);Second script for hidden variable
log.error("script hidden start")
...
qo.addFilters(filters);
log.error("script hidden end");
return (context.countObjects(Links.class,qo) > 0);Now I open the password reset page and I get a bit confused about the output and timings between the steps in the log file.
It shows some some 2 seconds between steps, rather than start/end log messages (not exact log messages)
script identity end – 14:03:14
script hidden start – 14:03:16
Bit puzzled, but after a while i can see it clearly and smile about how silly i was 🙂
Correcting the debug messages and confirming the delay is due to the countObjects DB search in both scripts.
log.error("script hidden start")
...
qo.addFilters(filters);
log.error("script hidden end1");
int objs = context.countObjects(Links.class,qo);
log.error("script hidden end2");
return (objs > 0);Moving down from TEST to my DEV environment
My spadmin in my own dev is set up without additional roles or anything, therefore the admin user cannot reset any passwords with the custom functionality. It is a good thing, because the query takes around 26 seconds and returns 0 records.
Assumptions:
It must go through whole table to find nothing. (correct)
It must be due to missing index. (wrong)
It should be easy to locate the DB query with trace enabled (correct)
I used Dev tools in Edge and check the timings for the API call. I enabled trace on all objects in log4j2 and soon I was able to see the two queries.
Combined select query with one inner and 3 left joins on Identity table. I am not database expert, but I could see that each left join is increased exponentially from the live statistics in MSSQL studio.
I removed the left joins and related OR clauses. One inner and one left join as a result. Suddenly It returned results (still 0) within a second. I was on the right path.
Reviewed the code for QueryOptions and filters. Logically it could have been split, so I did split it with some extra optimizing and added comments for my colleagues on why it is split in simialr query options and context.countObjects calls.
Now it runs on my DEV within a second. Retested and confirmed usecases for different user types, deployed to TEST. 4 seconds to under 1 second(success). Finally created a PR and waiting for the next release to save 8 seconds in Production for each password reset.
How did I debug in this case?
- used error debug messages to find/confirm the problematic code
- set up DEV environment to not run any tasks, that allows me to run trace on all objects and classes used by IIQ when needed
- read trace logs for SQL queries and timings