2

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.

screenshot of debug log page

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.

  1. 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>
  1. For each question, I display a friendly image:

example of image usage

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:

  1. how can I better dig into what is causing the 12 second page load time.

  2. 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
  • 1
    And yet you don't share the relevant Apex? How are we supposed to assess load time without that? – Adrian Larson Jan 15 '17 at 0:19
  • 1
    It's linked to in the post, I can add it in but the post is quite long already and since sfdc Fox helped me with it I think it's pretty tight – gorav Jan 15 '17 at 0:42
  • The link is in the lne: The code for the extension is almost verbatim what SFDCFox helped me out with on this post. salesforce.stackexchange.com/a/109124/10062 – gorav Jan 15 '17 at 0:48
  • Did you use dev console and do any profiling? – Eric Jan 15 '17 at 1:20
  • 1
    There is a profiling level. Tells u where the time is spent. Though if subsequent loads are fine it could just be the org cache rebuilding. How are 2, 3, and 4 th loads. What if u wait 5 mins then how is first load. Keep in mind have not reviewed your code – Eric Jan 15 '17 at 1:29
0

If the issues persists, perhaps consider migrating your data to a Hierarchy Custom Setting and writing a job in Apex to calculate the values. Then you won't even need a controller at all!

rendered="{!$Setup.MyTrailheadSetting__c.HasCreatedChatterPost__c}"

If you wanted to, you could hook up a Recalculate button, which would require a controller. But I would personally just run the calculation job via Execute Anonymous whenever I needed to update the results. That way you can keep code out of your UI and use 100% markup.

|improve this answer|||||
  • that is an interesting idea, thanks. its clear that two of the queries are the issue - so i'll need to see if i can find a way to better optimize them, or perhaps run those two asynchronously so the whole page doesnt time out. I think the issue might be more for my user, since i have a lot of data and posts, vs new users, so i'll do some testing as other users to see if i can just ignore it. – gorav Jan 16 '17 at 14:41
0

Thanks to all for the ideas.

Setting apex profiling on debug logs made it clear that there are two long running queries - feed item and contact share - which I need to better optimize.

I used the 'explain' parameter on SOQL queries to try to isolate what, if anything, I can do to improve the performance of these two queries, but seemed like there were no major improvements I could make, so I had to move the FeedItem query and the ContactShare query to an asynchronous method. I followed this recipe in the 'visualforce development cookbook' by Kier Bowden which is working.

I cant paste the full code since its very closely based on the example in the book, which requires purchase, but the approach is to add an actionFunction to the page that calls a controller method to calculate the values for the long-running queries.

The sections that display these values are only rendered once that method has returned, via a rerender.

<apex:actionFunction name="loadSharesJS" action="{!loadShares}" rerender="sharesPanel, SharesJS, tasks, fullProfile, refresher, completed, currStatus"/>

A small script placed at the end of the page calls the actionFunction

 <script>
     loadSharesJS();
   </script>

In the end I mainly needed to better understand how to properly use debug levels and the capabilities of the developer console to get more insight into the issue, and the 'explain' parameter to get more insight into the query optimizer.

|improve this answer|||||
  • You should link to that recipe... – Adrian Larson Feb 4 '17 at 21:45
  • Thanks, done. It requires purchase but some preview content is available – gorav Feb 4 '17 at 22:26
  • Can you sketch out the basic idea of the solution? As it stands this answer wouldn't really help someone else facing the same problem. – Adrian Larson Feb 4 '17 at 22:28
  • Absolutely thx for the suggestion, will do. – gorav Feb 4 '17 at 22:29

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.