TehNrd

This story starts some time ago. I have been complaining about the system/debug log in salesforce.com ever since they released what I would consider version 1.1. You can see my post here, Please fix the Debug Log!, pleading for salesforce to fix the debug log. This was back in July of 2008! From what I can tell there has only been two noticeable changes with this debug log. I will refer to them as version 1.1 which was implemented around the time of the message board post above and the the most recent Spring ’10 incarnation which I will refer to as version 2.0.

I still remember the good old days of the debug log, version 1.0 . Everything was so peachy! Apex was brand new. The debug log output was concise and easy to use. Times where good. Version 1.0 was the best! Sigh…… (this is a sigh of fond happy memories). It’s pretty sad version 1.0 is what I consider to be the best, usually software is supposed to get better with subsequent releases right? Right?!?!?

The clouds became dark (pun intended ) with version 1.1. Now the debug log could log workflow and validation rules! Great! Now my debug logs are incredibly long and full of junk that I rarely, and 99% of the time, never care about when debugging Apex. In orgs that have a lot of workflow rules this makes it terribly painful to do bulk debugging. But Jason, simply set the Log Category to Apex Code and it will only show Apex related output.

BWAHAHHAAHHAHA, oh man, that’s a good one. Up until version 2.0 this had never worked right. It doesn’t matter what you set the Log Category to as it never outputs what you want it to.

I remember attending the “Meet the Developers” session at Dreamforce 09 and hearing the salesforce team say that a new and improved debug log was coming. The room literally roared with applause. I was one of those clapping with excitement. When I finally was able to access the new debug log I was giddy with excitement. Will this be everything I have hoped and dreamed for? Will it save me tons of time? Will it make me a hot breakfast every morning? To my amazement and surprise it has fallen short on nearly all of my expectations.

You can’t re-size the input box. This was an incredibly useful feature. Why would a useful feature be removed? It makes no sense. Yes, there are work arounds using browser plugins such as Gresemonkey and Stylish but people don’t want workarounds. They want it to just work.

I may be on a pretty good rant but I have no right to complain if I make no attempt to help improve the tool. I decided to take a stab and building this re-size functionality and it literally took me less than 10 minutes to get a working prototype using jQueryUI. You can check it out here. It is a little rough around the edges but if I can build a working demo this quick there is absolutely no reason salesforce shouldn’t be able to incorporate this functionality.

The output is also hideous. Perhaps this is the way Java code typically outputs debug logs. I don’t have enough experience to know. What I do know is this new version makes my life less happy. From a usability perspective the old version was much easier to quickly scan and find what you were looking for. Let’s compare.

Below I will show the debug outputs for a very simple piece of code. Here is the code:

for(Opportunity opp : [select Id, Name, Amount from Opportunity]){
	system.debug(opp);
}

First let’s look at version 1.1, pre Spring 10.

20100210185937.897:AnonymousBlock: line 1, column 1: SelectLoop:LIST:SOBJECT:Opportunity
20100210185937.897:AnonymousBlock: line 1, column 23: SOQL query with 6 rows finished in 5 ms
20100210185937.897:AnonymousBlock: line 2, column 1: Opportunity:{Name=Territory Test, Amount=152989.18, Id=00660000008gWE1AAM}
20100210185937.897:AnonymousBlock: line 2, column 1: Opportunity:{Name=Pipeline Date Test, Amount=5000.00, Id=00660000008gpbDAAQ}
20100210185937.897:AnonymousBlock: line 2, column 1: Opportunity:{Name=Product Alert Test 123, Amount=555000.00, Id=00660000008gCQ7AAM}
20100210185937.897:AnonymousBlock: line 2, column 1: Opportunity:{Name=Giant Product List, Amount=0.00, Id=00660000009lsB7AAI}
20100210185937.897:AnonymousBlock: line 2, column 1: Opportunity:{Name=Silver Error, Amount=150000.00, Id=00660000009lx17AAA}
20100210185937.897:AnonymousBlock: line 2, column 1: Opportunity:{Name=Visual Force, Amount=0.00, Id=0066000000AFuB8AAL}
20100210185937.897:AnonymousBlock: line 1, column 1:     Number of iterations: 1
 
Cumulative resource usage:
 
Resource usage for namespace: (default)
Number of SOQL queries: 1 out of 100
Number of query rows: 6 out of 10000
Number of SOSL queries: 0 out of 20
Number of DML statements: 0 out of 100
Number of DML rows: 0 out of 10000
Number of script statements: 6 out of 200000
Maximum heap size: 0 out of 2000000
Number of callouts: 0 out of 10
Number of Email Invocations: 0 out of 10
Number of fields describes: 0 out of 10
Number of record type describes: 0 out of 10
Number of child relationships describes: 0 out of 10
Number of picklist describes: 0 out of 10
Number of future calls: 0 out of 10
Number of find similar calls: 0 out of 10
Number of System.runAs() invocations: 0 out of 20
 
Total email recipients queued to be sent : 0
Cumulative profiling information:
 
1 most expensive SOQL operations:
AnonymousBlock: line 1, column 23: [select Id, Name, Amount from Opportunity]: executed 1 time in 5 ms
 
No profiling information for SOSL operations.
 
No profiling information for DML operations.
 
No profiling information for method invocations.

Why do I like this? It is incredibly easy to identify line and column numbers. When debugging I am usually focused on a specific area. In any browser I can hit CTRL-F, enter “line 142″, and be taken straight to the area I am debugging. The output is very clean and concise with no unwanted garbage. It simply has my debug statements. It also provides a nice clean summary of limits and the most expensive methods, SOQL, SOSL, and DML statements. This is great information to know when optimizing code. For me this is perfect. The only issue I had with version 1.1 was that if my code had any DML statements it would output all of the work flow and validation criteria because the filters did not work as mentioned above.

Now lets take a look at version 2.0 released with Spring 10.

Below are the filter settings I used for this:

11:03:30.381|EXECUTION_STARTED
11:03:30.381|CODE_UNIT_STARTED|[EXTERNAL]System Log Window
11:03:30.393|METHOD_ENTRY|[2,2]|system.debug(SOBJECT:Opportunity)
11:03:30.393|USER_DEBUG|[2,2]|DEBUG|Opportunity:{Name=Edge SLA, Amount=60000.00, Id=006A0000002YZZ9IAO}
11:03:30.393|METHOD_EXIT|[2,2]|debug(ANY)
11:03:30.393|METHOD_ENTRY|[2,2]|system.debug(SOBJECT:Opportunity)
11:03:30.393|USER_DEBUG|[2,2]|DEBUG|Opportunity:{Name=Grand Hotels Kitchen Generator, Amount=15000.00, Id=006A0000002YZZAIA4}
11:03:30.393|METHOD_EXIT|[2,2]|debug(ANY)
11:03:30.394|METHOD_ENTRY|[2,2]|system.debug(SOBJECT:Opportunity)
11:03:30.394|USER_DEBUG|[2,2]|DEBUG|Opportunity:{Name=Grand Hotels SLA, Amount=90000.00, Id=006A0000002YZZBIA4}
11:03:30.394|METHOD_EXIT|[2,2]|debug(ANY)
11:03:30.394|METHOD_ENTRY|[2,2]|system.debug(SOBJECT:Opportunity)
11:03:30.394|USER_DEBUG|[2,2]|DEBUG|Opportunity:{Name=Express Logistics Portable Truck Generators, Amount=80000.00, Id=006A0000002YZZCIA4}
11:03:30.394|METHOD_EXIT|[2,2]|debug(ANY)
11:03:30.394|METHOD_ENTRY|[2,2]|system.debug(SOBJECT:Opportunity)
11:03:30.394|USER_DEBUG|[2,2]|DEBUG|Opportunity:{Name=Express Logistics SLA, Amount=120000.00, Id=006A0000002YZZDIA4}
11:03:30.394|METHOD_EXIT|[2,2]|debug(ANY)
11:03:30.394|METHOD_ENTRY|[2,2]|system.debug(SOBJECT:Opportunity)
11:03:30.394|USER_DEBUG|[2,2]|DEBUG|Opportunity:{Name=Express Logistics Standby Generator, Amount=220000.00, Id=006A0000002YZZEIA4}
11:03:30.394|METHOD_EXIT|[2,2]|debug(ANY)
11:03:30.394|CODE_UNIT_FINISHED
11:03:30.394|EXECUTION_FINISHED

And this brings us back to the title of this post. If computers could barf I’m pretty sure it would look like the output above. Basically every pro in the previous example has now become a con. The noisy output makes it difficult to isolate line numbers and specific areas. This small example is not so bad but imagine a debug log with hundreds if not thousands of lines. What was done in 9 output lines now takes 22 lines!

What is the point of this line: “11:03:30.394|METHOD_EXIT|[2,2]|debug(ANY)” when the line that is actually a debug statement says “|DEBUG|”. I’d really like to know as it looks pretty pointless.

This line is also unnecessary, “11:03:30.394|METHOD_ENTRY|[2,2]|system.debug(SOBJECT:Opportunity)”. Yes, thank you for letting me know I am debugging an Opportunity. I was the one who wrote this debug statement so I know what I am debugging. The next line that says, “Opportunity:{Name=Express Logistics” also lets me know I am debugging an Opportunity. I see how this could be helpful for someone looking at new or unfamiliar code but for me it does nothing more than get in the way.

You will also notice the limit and performance metrics are gone. The only way to get these metrics back is to enable Database logging but then the output starts to includes items that I may not want, again making the output even longer.

Not all is bad with version 2.0. The ability to save the debug logs is useful and the logging criteria actually works.

What I want to be able to do is get a very clean and easy to read output that only displays system.debug() statements with limit and performance metrics. Nearly 2.5 years after I started developing Apex I still don’t have this and it makes me sad.

Salesforce.com usually gets it right but with this particular feature I feel like they keep striking out. It feels like this tool received little to no customer usability testing. The CRM piece of salesforce is always having usability testing done but I have never been approached to give feedback on the developer tools. I would encourage the salesforce.com dev group to reach out and do a little usability testing. It doesn’t need to be super formal usability testing. Quick online group meetings with force.com developers would suffice. There are plenty of good force.com developers out here that are more than willing to give constructive feedback on features like this.

The issues I have expressed concern about may eventually be fixed but we are at least four months away from the next release and based on past changes (or lack there of) to this tool I can’t be optimistic that improvements will be made quickly. This tool is was close to being perfect and I think it could have hit a home run if it incorporated some user feedback before it was rolled out.

</end rant>