I have a fairly simple visualforce page that uses a custom controller extension. The page can be quite slow to load on the first load, and sometimes times out.
This debug log shows a 12,852 ms duration on the first load, with a 225 ms subsequent load.
View state is only 4.35 kb. The page has no javascript, and almost no CSS. The controller extension runs 6 queries, all filtered on indexed fields, and CPU usage registers at 0.
Number of SOQL queries: 6 out of 100
Number of query rows: 3 out of 50000
Number of SOSL queries: 0 out of 20
Number of DML statements: 0 out of 150
Number of DML rows: 0 out of 10000
Maximum CPU time: 0 out of 10000
Maximum heap size: 0 out of 6000000
Number of callouts: 0 out of 100
Number of Email Invocations: 0 out of 10
Number of future calls: 0 out of 50
Number of queueable jobs added to the queue: 0 out of 50
Number of Mobile Apex push calls: 0 out of 10
The page evaluates a series of 6 training exercises to see if they are complete (my own private trailhead...).
Extension Code The code for the extension is almost verbatim what SFDCFox helped me out with on this post. I've left it out of the post, but have added it pastebin here
Visualforce page I´ll post the full code for the Visualforce page below, but first i want to higlight two things that I think could perhaps be improved, though I dont know if doing so would decrease the load time.
- Rendering OutputPanel For each question, I have two output panels, one of which is rendered based on a boolean field returned from the controller. Seems like a reasonable approach, but perhaps there is a more efficient way?
Code example for question 1:
<apex:outputPanel rendered="{!HasCreatedChatterPost}">
<apex:image url="{!URLFOR($Resource.GraphicsPack, imageurl)}" height="16px" styleClass="check"/>Nice Work! Chatter post created succesfully
</apex:outputPanel>
<apex:outputPanel rendered="{!NOT(HasCreatedChatterPost)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>Sorry - you still need to create a chatter post!</apex:outputPanel>
- For each question, I display a friendly image:
I do this by setting an apex variable for the URL of each image at the top of the page.
<apex:variable var="imageurl" value="/16/fatcow/farmfresh/accept.png"/>
<apex:variable var="cancelurl" value="/16/fatcow/farmfresh/cancel.png"/>
And then, as visible in the code in from question 1, the images are retrieved from a static resource using the image URL. As each image is loaded 6 times, perhaps there is a more efficient way of doing this.
So what Iḿ hoping to get from this question is:
how can I better dig into what is causing the 12 second page load time.
are there better / more efficient ways for q1 and q2
Two final notes
A) a friend (Bonny Hinners) taught me how ´invalid´ classes have to recompile when you open a vf page, so I have Gearset setup to run my test classes nightly, and now my invalid classes are typically zero or less than 10 on a bad day, including managed code. The long page load time persists.
B) I tried to dig in via chrome developer tools but honestly dont know what to look for. I looked at the various documents on optimizing vf page load time, but didnt see anything promising for this use case.
Full code for the Visualforce page
<apex:page standardcontroller="User" extensions="UserOnboardingValidationExtension" sidebar="False">
<style type="text/css">
p.title { font-weight: bold; font-size 1.1em; padding-top:1.5em;}
span.red {color: red;}
.check {vertical-align: bottom; margin-right:0.3em;}
</style>
<apex:variable var="imageurl" value="/16/fatcow/farmfresh/accept.png"/>
<apex:variable var="cancelurl" value="/16/fatcow/farmfresh/cancel.png"/>
<div style="padding-top: 1.3em;">
<span style="font-size:1.3em; font-weight:bold;">Training Exercise Validator</span>
<p style="font-size:1.2em;">Hi <apex:outputText value=" {!User.Name}"></apex:outputText>, <br />
This tool will review each exercise and let you know if you completed it successfully. <br />
Once all are complete, you can request a full profile via chatter<br />
Use the 'Refresh page' button at the bottom to re-calculate the status as you complete the exercises.
</p>
</div>
<apex:form >
<apex:outputPanel >
<p class="title">Exercise 1 - Create Chatter Post</p>
<apex:outputPanel rendered="{!HasCreatedChatterPost}"><apex:image url="{!URLFOR($Resource.GraphicsPack, imageurl)}" height="16px" styleClass="check"/>Nice Work! Chatter post created succesfully</apex:outputPanel>
<apex:outputPanel rendered="{!NOT(HasCreatedChatterPost)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>Sorry - you still need to create a chatter post!</apex:outputPanel>
</apex:outputPanel>
<apex:outputPanel >
<p class="title">Exercise 2 - Create Contact And Account</p>
<apex:outputPanel rendered="{!HasCreatedContact}"><apex:image url="{!URLFOR($Resource.GraphicsPack, imageurl)}" height="16px" styleClass="check"/>Nice Work! Contact created</apex:outputPanel>
<apex:outputPanel rendered="{!NOT(HasCreatedContact)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>Sorry - you still need to create a contact </apex:outputPanel>
<br />
<apex:outputPanel rendered="{!HasCreatedAccount}"><apex:image url="{!URLFOR($Resource.GraphicsPack, imageurl)}" height="16px" styleClass="check"/>Nice work! Organization created</apex:outputPanel>
<apex:outputPanel rendered="{!NOT(HasCreatedAccount)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>Sorry - you still need to create an organization </apex:outputPanel>
</apex:outputPanel>
<apex:outputPanel >
<p class="title">Exercise 3 - Share Contact</p>
<apex:outputPanel rendered="{!HasCreatedSharedContact}"><apex:image url="{!URLFOR($Resource.GraphicsPack, imageurl)}" height="16px" styleClass="check"/>Nice Work! Contact shared</apex:outputPanel>
<apex:outputPanel rendered="{!NOT(HasCreatedSharedContact)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>Sorry you still need to share a contact </apex:outputPanel>
</apex:outputPanel>
<apex:outputPanel >
<p class="title">Exercise 4 - Search for Yourself</p>
<p>We cant check this one automatically, but its good to become familiar with searching - its quite powerful, as it searches everything - including attachments!
</p>
</apex:outputPanel>
<apex:outputPanel >
<p class="title">Exercise 5 - Update Profile Photo and Settings</p>
<apex:outputPanel rendered="{!HasAddedPhoto}"><apex:image url="{!URLFOR($Resource.GraphicsPack, imageurl)}" height="16px" styleClass="check"/>Nice Work! Profile photo added
</apex:outputPanel>
<apex:outputPanel rendered="{!NOT(HasAddedPhoto)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>Sorry you still need to add a profile photo </apex:outputPanel>
<br />
<apex:outputPanel rendered="{!HasAddedBio}"><apex:image url="{!URLFOR($Resource.GraphicsPack, imageurl)}" height="16px" styleClass="check"/>Nice work! Bio added</apex:outputPanel>
<apex:outputPanel rendered="{!NOT(HasAddedBio)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>Sorry you still need to add a bio </apex:outputPanel>
</apex:outputPanel>
<apex:outputPanel >
<p class="title">Exercise 6 - Mark Training Task Completed</p>
<apex:outputPanel rendered="{!hasClosedTask && (remainingTasks = 0)}"><apex:image url="{!URLFOR($Resource.GraphicsPack, imageurl)}" height="16px" styleClass="check"/>Nice work! All exercises completed and training task marked closed</apex:outputPanel>
<apex:outputPanel rendered="{!NOT(hasClosedTask) && (remainingTasks = 1)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>All exercises completed - you just need to mark the training task 'closed'</apex:outputPanel>
<apex:outputPanel rendered="{!(hasClosedTask && remainingTasks = 1)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>Sorry - you have marked the training task 'closed' but still have {!remainingTasks} exercises remaining</apex:outputPanel>
<apex:outputPanel rendered="{!remainingTasks > 1}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>Sorry - you still have {!remainingTasks} exercises remaining before you should mark the training task 'closed'</apex:outputPanel>
</apex:outputPanel>
<apex:outputPanel >
<p class="title">Exercise 7 - Request Full Profile</p>
<apex:outputPanel rendered="{!completedStatus}"><apex:image url="{!URLFOR($Resource.GraphicsPack, imageurl)}" height="16px" styleClass="check"/>All training exercises complete - request update via chatter message to below (you must @ mention salesforce support as per the exercise to get a response)!</apex:outputPanel>
<apex:outputPanel rendered="{!NOT(completedStatus)}" styleClass="red"><apex:image url="{!URLFOR($Resource.GraphicsPack, cancelurl)}" height="16px" styleClass="check"/>{!remainingTasks} exercises remaining! (Refresh page to update total)
</apex:outputPanel>
</apex:outputPanel>
<p>
<apex:commandButton rendered="{!NOT(completedStatus)}" action="{!refreshValues}" value="Refresh Page"/>
</p>
</apex:form>
<apex:outputPanel >
<chatter:feed rendered="{!completedStatus}" entityId="{!completedTask.Id}"/>
</apex:outputPanel>
</apex:page>
UPDATE
Per Eric's suggestion, I ran with increased logging levels - apex profiling set to Finest and Visualforce set to Finer, and that made it apparent that the issue is in querying the ContactShare table.
Class.UserOnboardingValidationExtension.calculateStatus: line 39, column 1: [SELECT COUNT() FROM ContactShare WHERE RowCause='Manual' AND ContactId IN (SELECT Id FROM Contact Where CreatedById =: thisuser.Id) LIMIT 1]: executed 2 times in 12063 ms
It also appears that a number of queries executed twice. I've added the full apex code for the extension to pastebin here in case that helps
08:48:01.452 (12542831311)|CODE_UNIT_FINISHED|VF:
/apex/UserOnboardingValidation
08:48:01.452 (12543884632)|EXECUTION_FINISHED
08:48:01.546 (12546355334)|CUMULATIVE_PROFILING_BEGIN
08:48:01.546 (12546355334)|CUMULATIVE_PROFILING|SOQL operations|
Class.UserOnboardingValidationExtension.calculateStatus: line 39, column 1: [SELECT COUNT() FROM ContactShare WHERE RowCause='Manual' AND ContactId IN (SELECT Id FROM Contact Where CreatedById =: thisuser.Id) LIMIT 1]: executed 2 times in 12063 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 38, column 1: [SELECT COUNT() FROM Account WHERE CreatedById = :thisUser.Id LIMIT 1]: executed 2 times in 217 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 37, column 1: [SELECT COUNT() FROM Contact WHERE CreatedById = :thisUser.Id LIMIT 1]: executed 2 times in 116 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 36, column 1: [SELECT COUNT() FROM FeedItem WHERE InsertedById = :thisUser.Id LIMIT 1]: executed 2 times in 45 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 42, column 1: [SELECT COUNT() FROM Task WHERE OwnerId =: thisUser.Id AND IsClosed = TRUE LIMIT 1]: executed 2 times in 22 ms
08:48:01.546 (12546355334)|CUMULATIVE_PROFILING|No profiling information for SOSL operations
08:48:01.546 (12546355334)|CUMULATIVE_PROFILING|No profiling information for DML operations
08:48:01.546 (12546355334)|CUMULATIVE_PROFILING|method invocations|
Class.UserOnboardingValidationExtension.<init>: line 26, column 1: public void calculateStatus(): executed 1 time in 12471 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 31, column 1: global static String getUserId(): executed 2 times in 5 ms
Class.UserOnboardingValidationExtension.<init>: line 7, column 1: global public static System.PageReference currentPage(): executed 3 times in 1 ms
External entry point: public User getUser(): executed 1 time in 0 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 40, column 1: public Boolean endsWith(String): executed 2 times in 0 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 41, column 1: public void __sfdc_hasAddedBio(Boolean): executed 1 time in 0 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 43, column 1: public Boolean __sfdc_hasClosedTask(): executed 1 time in 0 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 46, column 1: public void __sfdc_remainingTasks(Integer): executed 1 time in 0 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 47, column 1: public Boolean __sfdc_hasCreatedChatterPost(): executed 2 times in 0 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 48, column 1: public Boolean __sfdc_hasCreatedAccount(): executed 2 times in 0 ms
Class.UserOnboardingValidationExtension.calculateStatus: line 49, column 1: public Boolean __sfdc_hasAddedPhoto(): executed 2 times in 0 ms