1 // ==========================================================================
  2 // Project:   SproutCore - JavaScript Application Framework
  3 // Copyright: ©2006-2011 Strobe Inc. and contributors.
  4 //            Portions ©2008-2011 Apple Inc. All rights reserved.
  5 // License:   Licensed under MIT license (see license.js)
  6 // ==========================================================================
  7 /*globals $A */
  8 
  9 /** @namespace
 10 
 11   This bit of meta-programming magic can install a benchmark handler on any
 12   object method.  When a benchmark is installed, the time required to execute
 13   the method will be printed to the console log every time the method is
 14   called.
 15 
 16   This class can be used to implement benchmarking.  To use this object, just
 17   call start() with a key name and end() with a keyname.  The benchmark will
 18   be logged.  If you set verbose = true, then benchmark will log every time it
 19   saves a bench.  Otherwise, it just keeps stats.  You can get the stats by
 20   calling report().
 21 
 22   Benchmark does not require anything other than the date.js class.  It also
 23   does not rely on SC.Object so that you can benchmark code in that area as
 24   well.
 25 
 26   The benchmark has three types of reports.
 27 
 28     - report(): Returns an abbreviated list with just the durations of the bench.
 29               Also, it averages multiple runs. Everything is reported on the top
 30               level only.
 31     - timelineReport(): Returns an list of benchmarks and sub-benchmarks. If the
 32                       the globalStartTime is set, then it will show relative
 33                       time from that time.
 34     - timelineChart(): Displays a chart of all the benchmarks (not sub-benchmarks)
 35                      relative to the first time capture or to the globalStartTime.
 36                      Hide this by calling hideChart()
 37 
 38   @since SproutCore 1.0
 39 */
 40 SC.Benchmark = {
 41 
 42   /**
 43     If true, then benchmarks will be logged to the console as they are
 44     recorded.
 45 
 46     @type Boolean
 47     @default NO
 48   */
 49   verbose: NO,
 50 
 51   /**
 52     If false, benchmarking will be disabled.  You might want to disable this
 53     during production to maximize performance.
 54 
 55     @type Boolean
 56     @default YES
 57   */
 58   enabled: YES,
 59 
 60   /**
 61     Events are a way of assigning specific, individual times to names, rather than
 62     durations of time. A benchmark event can only occur once—if it occurs again, it
 63     will overwrite the old event.
 64 
 65     The purpose of events is different than the purpose for normal benchmarks. Normal
 66     benchmarks may be used to benchmark a specific process, and may do so repeatedly;
 67     events, conversely, are usually used to benchmark things like startup time, and
 68     occur only once. For instance, an 'event' is registered when the document is ready.
 69 
 70     Events are kept as a hash of names to timestamps. To add an event, just set it:
 71 
 72         SC.Benchmark.events['myEventName'] = new Date().getTime();
 73 
 74         // Or, more conveniently:
 75         SC.Benchmark.addEvent('myEventName', [optional time]);
 76 
 77     On a timeline chart, events are usually represented as lines rather than bars. However,
 78     if you add eventNameStart and eventNameEnd, they will be automatically added as standard
 79     benchmarks.
 80 
 81     This is useful when adding preload events to SC.benchmarkPreloadEvents; as SC.Benchmark
 82     does not yet exist, you cannot call .start() and .end(), but adding the items to
 83     SC.benchmarkPreloadEvents will ensure they are included.
 84 
 85     @type Object
 86     @default {}
 87   */
 88   events: {},
 89 
 90   /**
 91     This hash stores collected stats.  It contains key value pairs.  The value
 92     will be a hash with the following properties:
 93 
 94       - *runs*: the number of times this stat has run
 95       - *amt*: the total time consumed by this (divide by runs to get avg)
 96       - *name*: an optional longer name you assigned to the stat key.  Set this  using name().
 97 
 98     @type Object
 99     @default {}
100   */
101   stats: {},
102 
103   /**
104     If set, one can tell when the benchmark is started relatively to the global start time.
105 
106     This property is set to a default automatically (from HTML5 NavigationTiming if possible,
107     otherwise the SC bootstrap).
108 
109     @type Number
110     @default null
111   */
112   globalStartTime: null,
113 
114   /**
115     Adds an 'event' to the events hash.
116 
117     Unlike normal benchmarks, recorded with start/end and that represent a block of time,
118     events represent a single instance in time. Further, unlike normal benchmarks, which
119     may be run more than once for the same benchmark name, only one instance in time
120     will be recorded for any event name.
121 
122     @param {String} name
123       A name that identifies the event. If addEvent is called again with the same name,
124       the previous call's timestamp will be overwritten.
125     @param {Number} time
126       Optional. The timestamp to record for the event.
127   */
128   addEvent: function(name, time) {
129     if (!time) time = new Date().getTime();
130     this.events[name] = time;
131   },
132 
133   /**
134     Call this method at the start of whatever you want to collect.
135     If a parentKey is passed, then you will attach the stat to the parent,
136     otherwise it will be on the top level. If topLevelOnly is passed, then
137     recursive calls to the start will be ignored and only the top level call
138     will be benchmarked.
139 
140     @param {String} key
141       A unique key that identifies this benchmark.  All calls to start/end
142       with the same key will be groups together.
143     @param {String} parentKey
144       A unique key that identifies the parent benchmark.  All calls to
145       start/end with the same key will be groups together.
146     @param {Number} time
147       Only pass if you want to explicitly set the start time.  Otherwise the
148       start time is now.
149     @param {Boolean} topLevelOnly
150       If true then recursive calls to this method with the same key will be
151       ignored.
152     @returns {String} the passed key
153   */
154   start: function(key, parentKey, time, topLevelOnly) {
155     var start,
156         stat;
157 
158     if (this.enabled) {
159       start = time || Date.now();
160 
161       if (parentKey) stat = this._subStatFor(key, parentKey);
162       else stat = this._statFor(key);
163 
164       if (stat) {
165         if (topLevelOnly && stat._starts.length > 0) stat._starts.push('ignore');
166         else stat._starts.push(start);
167 
168         stat._times.push({ start: start, _subStats: {} });
169       }
170     }
171     return key;
172   },
173 
174   /**
175     Call this method at the end of whatever you want to collect.  This will
176     save the collected benchmark.
177 
178     @param {String} key
179       The benchmark key you used when you called start()
180     @param {String} parentKey
181       The benchmark parent key you used when you called start()
182     @param {Number} time
183       Only pass if you want to explicitly set the end time.  Otherwise start
184       time is now.
185   */
186   end: function(key, parentKey, time) {
187     var stat,
188         start,
189         end,
190         dur;
191 
192     if (!this.enabled) { return; }
193 
194     if (parentKey) {
195       stat = this._subStatFor(key, parentKey);
196     } else {
197       stat = this._statFor(key);
198     }
199 
200     if (stat && stat._starts.length) {
201       start = stat._starts.pop();
202 
203       // top level only.
204       if (start !== 'ignore') {
205         end = (time || Date.now());
206         dur = end - start;
207 
208         stat._times[stat._times.length-1].end = end;
209         stat._times[stat._times.length-1].dur = dur;
210 
211         stat.amt += dur;
212         stat.runs++;
213 
214         if (this.verbose) { this.log(key); }
215       }
216     } else {
217       SC.Logger.log('SC.Benchmark "%@" ended without a matching start.  No information was saved.'.fmt(key));
218     }
219   },
220 
221   /**
222     Set the inital global start time.
223 
224     @param {Number} time global start time
225   */
226   setGlobalStartTime: function(time) {
227     this.globalStartTime = time;
228   },
229 
230   /**
231     This is a simple way to benchmark a function.  The function will be
232     run with the name you provide the number of times you indicate.  Only the
233     function is a required param.
234 
235     @param {Function} func function to benchmark
236     @param {String} [key] benchmark key
237     @param {Number} [reps] how many times to run the function
238     @returns {*} Most recent return value from func
239   */
240   bench: function(func, key, reps) {
241     var ret;
242     if (!key) { key = "bench%@".fmt(this._benchCount++); }
243     if (!reps) { reps = 1; }
244 
245     while (--reps >= 0) {
246       SC.Benchmark.start(key);
247       ret = func();
248       SC.Benchmark.end(key);
249     }
250 
251     return ret ;
252   },
253 
254   /**
255     Install a wrapper around a method to benchmark it whenever it is run.
256 
257     @param {Object} object target object to install on
258     @param {String} method name of the method on object
259     @param {Boolean} topLevelOnly should recursive calls to this method
260                                   with the same key will be ignored
261   */
262   install: function(object, method, topLevelOnly) {
263     // save the original method.
264     var fn = object['b__' + method] = object[method],
265         join = Array.prototype.join;
266 
267     // replace with this helper.
268     object[method] = function() {
269       var key = '%@(%@)'.fmt(method, join.call(arguments, ', ')),
270           ret;
271       SC.Benchmark.start(key, null, null, topLevelOnly);
272       ret = fn.apply(this, arguments);
273       SC.Benchmark.end(key);
274       return ret;
275     };
276   },
277 
278   /**
279     Restore the original method, deactivating the benchmark.
280 
281     @param {Object} object the object to change
282     @param {String} method the method name as a string
283   */
284   restore: function(object, method) {
285     object[method] = object['b__' + method];
286   },
287 
288   /**
289     This method will return a string containing a report of the stats
290     collected so far.  If you pass a key, only the stats for that key will
291     be returned.  Otherwise, all keys will be used.
292   */
293   report: function(key) {
294     if (key) return this._genReport(key) ;
295     var ret = [] ;
296     for(var k in this.stats) {
297       if (!this.stats.hasOwnProperty(k)) continue ;
298       ret.push(this._genReport(k)) ;
299     }
300     return ret.join("\n") ;
301   },
302 
303   /**
304     Generate a human readable benchmark report. Pass in appName if you desire.
305 
306     @param {String} application name.
307   */
308   timelineReport: function(appName) {
309     appName = (appName) ? 'SproutCore Application' : appName;
310     var ret = [appName, 'User-Agent: %@'.fmt(navigator.userAgent), 'Report Generated: %@ (%@)'.fmt(new Date().toString(), Date.now()), ''] ;
311 
312     var chart = this._compileChartData(true);
313     for(var i=0; i<chart.length; i++)
314     {
315       if(chart[i][4])
316       {
317         ret.push(this._timelineGenSubReport(chart[i]));
318       }
319       else
320       {
321         ret.push(this._timelineGenReport(chart[i]));
322       }
323     }
324     return ret.join("\n") ;
325   },
326 
327   /**
328     Returns a hash containing the HTML representing the timeline chart, and
329     various metrics and information about the chart:
330 
331         - html
332         - totalWidth
333         - totalHeight
334         - totalCapturedTime
335         - pointsCaptured
336 
337     @returns {Hash}
338   */
339   getTimelineChartContent: function() {
340     // Compile the data.
341     var chart = this._compileChartData(false);
342     var chartLen = chart.length;
343 
344     // Return if there is nothing to draw.
345     if(chartLen === 0) return;
346 
347     // Get the global start of the graph.
348     var gStart = this.globalStartTime ? this.globalStartTime : chart[0][1];
349     var maxDur = chart[chartLen-1][2]-gStart;
350     var maxHeight = 25+chartLen*30;
351     var incr = Math.ceil(maxDur/200)+1;
352     var maxWidth = incr*50;
353     var leftPadding = 10, rightPadding = 300;
354 
355 
356     var str = "<div class = 'sc-benchmark-timeline-chart' style = 'position:relative;'>";
357     str += "<div class = 'sc-benchmark-top'></div>";
358 
359     // add tick marks
360     for (var i = 0; i < incr; i++) {
361       str += "<div class = 'sc-benchmark-tick' style = '";
362       str += "left: " + (leftPadding + i * 50) + "px; ";
363       str += "height: " + maxHeight + "px;";
364       str += "'></div>";
365 
366       str += "<div class = 'sc-benchmark-tick-label' style = '";
367       str += "left: " + (leftPadding + i * 50) + "px; ";
368       str += "'>" + (i * 200) + "ms</div>";
369     }
370 
371     // print each chart item
372     for (i = 0; i < chartLen; i++) {
373       str += "<div class = 'sc-benchmark-row ";
374       str += (i % 2 === 0) ? 'even' : 'odd';
375       str += "' style = '";
376       str += "top: " + (50 + (i * 30)) + "px; ";
377       str += "'></div>";
378 
379       var div = document.createElement('div');
380       var start = chart[i][1];
381       var end = chart[i][2];
382       var duration = chart[i][3];
383 
384 
385       str += "<div class = 'sc-benchmark-bar' style = '";
386       str += 'left:'+ (leftPadding + ((start-gStart)/4))+'px; width: '+((duration/4)) + 'px;';
387       str += 'top: '+(28+(i*30))+'px;';
388 
389       str += "' title = 'start: " + (start-gStart) + " ms, end: " + (end-gStart) + ' ms, duration: ' + duration + " ms'";
390       str += ">";
391       str += ' ' + chart[i][0] + " <span class='sc-benchmark-emphasis'>";
392       str += duration + "ms (start: " + (start - gStart) + "ms)";
393       str += "</span>";
394 
395       str += "</div>";
396     }
397 
398     // add the events
399     var events = this.events, idx = 0;
400     for (i in events) {
401       var t = events[i] - gStart;
402       str += "<div class = 'sc-benchmark-event idx" + (idx % 10) + "' style = '";
403       str += "left: " + (leftPadding + t / 4) + "px; height: " + maxHeight + "px; top: 20px;";
404       str += "' title = '" + i + ": " + t + "'></div>";
405       idx++;
406     }
407 
408     str += "</div>";
409 
410     return {
411       html: str,
412       totalCapturedTime: maxDur,
413       pointsCaptured: chartLen,
414       width: maxWidth + leftPadding + rightPadding,
415       height: maxHeight
416     };
417   },
418 
419   /**
420     Returns a view with the timeline chart. The view has a 'reload' method to
421     refresh its data.
422 
423     @returns {SC.View}
424   */
425   getTimelineChartView: function() {
426     var view = SC.ScrollView.create({
427       contentView: SC.StaticContentView.extend({
428 
429       }),
430 
431       reload: function() {
432         var content = SC.Benchmark.getTimelineChartContent();
433         this.contentView.set('content', content.html);
434         this.contentView.adjust({
435           width: content.width,
436           height: content.height
437         });
438 
439         this.chartContent = content;
440 
441         SC.RunLoop.invokeLater(SC.Benchmark, function() {
442           this.contentView.notifyPropertyChange('frame');
443         });
444       }
445     });
446 
447     view.reload();
448 
449     return view;
450   },
451 
452   /**
453     Generate a human readable benchmark chart. Pass in appName if you desire.
454   */
455   timelineChart: function(appName) {
456     SC.RunLoop.begin();
457 
458     var i=0;
459     // Hide the chart if there is an existing one.
460     this.hideChart();
461 
462     // Compile the data.
463     var chartView = this.getTimelineChartView();
464     var chartLen = chartView.chartContent.pointsCaptured,
465         chartCapturedTime = chartView.chartContent.totalCapturedTime;
466 
467     // Get the global start of the graph.
468 
469     this._benchmarkChart = SC.Pane.create({
470       classNames: ["sc-benchmark-pane"],
471       layout: { left: 20, right: 20, bottom: 20, top: 20 },
472       childViews: ["title", "exit"],
473       exit: SC.ButtonView.extend({
474         layout: { right: 20, top: 20, width: 100, height: 30 },
475         title: "Hide Chart",
476         target: this,
477         action: "hideChart"
478       }),
479 
480       title: SC.LabelView.extend({
481         classNames: ['sc-benchmark-title'],
482         layout: { left: 20, top: 23, right: 200, height: 30 },
483         value: ((appName) ? appName : 'SproutCore Application') + (' - Total Captured Time: ' + chartCapturedTime +' ms - Points Captured: ' + chartLen)
484       })
485 
486     }).append();
487 
488     chartView.set('layout', { left: 20, top: 60, bottom: 20, right: 20 });
489     this._benchmarkChart.appendChild(chartView);
490 
491     SC.RunLoop.end();
492   },
493 
494   /*
495     Hide chart.
496   */
497   hideChart: function() {
498     if (this._benchmarkChart) {
499       this._benchmarkChart.remove();
500       this._benchmarkChart = null;
501     }
502 
503     return YES;
504   },
505 
506   /** @private
507     Because we show a pane to display the chart...
508   */
509   tryToPerform: function(action, sender) {
510     if (this[action]) return this[action](sender);
511     return NO;
512   },
513 
514   /**
515     This method is just like report() except that it will log the results to
516     the console.
517   */
518   log: function(key) {
519     // log each line to make this easier to read on an iPad
520     var lines = this.report(key).split('\n'),
521         len   = lines.length, idx;
522     for(idx=0;idx<len;idx++) SC.Logger.log(lines[idx]);
523   },
524 
525   /**
526     This will activate profiling if you have Firebug installed.  Otherwise
527     does nothing.
528   */
529   startProfile: function(key) {
530     if (!this.enabled) return ;
531     SC.Logger.profile(key) ;
532   },
533 
534   endProfile: function(key) {
535     if (!this.enabled) return ;
536     SC.Logger.profileEnd(key) ;
537   },
538 
539 
540   // ..........................................................
541   // Internal Support
542   //
543 
544   /** @private
545     Loads data from both the browser's own event hash and SC's pre-load event hash.
546   */
547   loadPreloadEvents: function() {
548     var preloadEvents = SC.benchmarkPreloadEvents, events = [], idx, len, evt;
549 
550     // the browsers may have their own event hash. Ours uses the same format, so
551     // all that we need to do is mixin the browser's to our own.
552     if (typeof webkitPerformance !== 'undefined') SC.mixin(preloadEvents, webkitPerformance.timing);
553 
554     // we will attempt to find when the loading started and use that as our
555     // global start time, but only do so if the global start time is not already set.
556     if (!this.globalStartTime) {
557       // the potential events representing start time can be either from the browser
558       // or our own recordings. We prefer the browser.
559       var globalStartEvents = ['navigation', 'navigationStart', 'headStart'];
560       len = globalStartEvents.length;
561 
562       for (idx = 0; idx < len; idx++) {
563         if (preloadEvents[globalStartEvents[idx]]) {
564           this.globalStartTime = preloadEvents[globalStartEvents[idx]];
565           break;
566         }
567       }
568     }
569 
570     // the JavaScript start time will be one recorded by us
571     // we record headStart in bootstrap.
572     this.javascriptStartTime = preloadEvents['headStart'];
573 
574     // finally, mix in the events to our own events hash
575     SC.mixin(this.events, preloadEvents);
576 
577     this._hasLoadedPreloadEvents = true;
578   },
579 
580   /** @private
581     Some events represent a beginning and end. While this is not common for events
582     that take place after the app loads (as they can just use SC.Benchmark.start/end),
583     SC.Benchmark.start/end is not available before load—as such, code will add
584     *Start and *End events to the event hash.
585 
586     This method iterates over the event hash and removes those items that represent
587     starts and ends, calling .start/.end for them.
588   */
589   _loadBenchmarksFromEvents: function() {
590     if (!this._hasLoadedPreloadEvents) this.loadPreloadEvents();
591 
592     var events = this.events;
593     for (var i in events) {
594       if (i.substr(-3) !== 'End') continue;
595 
596       var stem = i.substr(0, i.length - 3);
597       if (!events[stem + 'Start']) continue;
598 
599       SC.Benchmark.start(stem, undefined, events[stem + 'Start']);
600       SC.Benchmark.end(stem, undefined, events[stem + 'End']);
601 
602       delete events[stem + 'Start'];
603       delete events[stem + 'End'];
604     }
605   },
606 
607   /** @private
608     Generates, sorts, and returns the array of all the data that has been captured.
609   */
610   _compileChartData: function(showSub) {
611     this._loadBenchmarksFromEvents();
612 
613     var chart = [], dispKey;
614     for(var key in this.stats)
615     {
616       var stat = this.stats[key];
617       for(var i=0; i<stat._times.length; i++)
618       {
619         var st = stat._times[i];
620         dispKey = (stat._times.length > 1) ? (i+1)+' - '+key : key;
621         chart.push([dispKey, st.start, st.end, st.dur, false]);
622         if(showSub)
623         {
624           var subStats = st._subStats;
625           for(var k in subStats)
626           {
627 
628             var subStat = subStats[k];
629             for(var j=0; j<subStat._times.length; j++)
630             {
631               var s = subStat._times[j];
632               dispKey = (subStat._times.length > 1) ? (j+1)+' - '+k : k;
633               chart.push([dispKey, s.start, s.end, s.dur, true]);
634 
635             }
636           }
637         }
638       }
639     }
640 
641     chart.sort(function(a,b)
642     {
643       if(a[1] < b[1])
644       {
645         return -1;
646       }
647       else if(a[1] == b[1])
648       {
649         if(a[3] && !b[3]) return -1;
650         if(!a[3] && b[3]) return 1;
651         return 0;
652       }
653       return 1;
654     });
655 
656     return chart;
657   },
658 
659   // Generate the traditional report show multiple runs averaged.
660   /** @private */
661   _genReport: function(key) {
662     var stat = this._statFor(key),
663         avg = (stat.runs > 0) ? (Math.floor(stat.amt * 1000 / stat.runs) / 1000) : 0,
664         last,
665         ret;
666 
667     if (stat._times.length) {
668       last = stat._times[stat._times.length - 1];
669       ret = 'BENCH %@ msec: %@ (%@x); latest: %@'.fmt(avg, (stat.name || key), stat.runs, last.end - last.start);
670     } else {
671       ret = 'No information for SC.Benchmark "%@".'.fmt(key);
672     }
673 
674     return ret;
675   },
676 
677   // Generate the report in the form of at time line. This returns the parent.
678   /** @private */
679   _timelineGenReport: function(val)
680   {
681     if(this.globalStartTime)
682     {
683       return 'BENCH start: %@ msec, duration: %@ msec,  %@'.fmt((val[1]-this.globalStartTime), val[3], val[0]) ;
684     }
685     else
686     {
687       return 'BENCH duration: %@ msec, %@'.fmt( val[3],  val[0]) ;
688     }
689   },
690 
691   // Generate the report in the form of at time line. This returns the children.
692   /** @private */
693   _timelineGenSubReport: function(val)
694   {
695     if(this.globalStartTime)
696     {
697       return '   CHECKPOINT BENCH start: %@ msec, duration: %@ msec,  %@'.fmt((val[1]-this.globalStartTime), val[3], val[0]) ;
698     }
699     else
700     {
701       return '   CHECKPOINT BENCH duration: %@ msec, %@'.fmt( val[3], val[0]) ;
702     }
703   },
704 
705   // returns a stats hash for the named key and parent key.  If the hash does not exist yet,
706   // creates it.
707   /** @private */
708   _subStatFor: function(key, parentKey) {
709     var parentStat = this.stats[parentKey],
710         parentTimeLen = parentStat ? parentStat._times.length : 0,
711         parentSubStats,
712         ret;
713 
714     if (!parentTimeLen) { return; }
715     parentSubStats = parentStat._times[parentTimeLen - 1]._subStats;
716     ret = parentSubStats[key];
717     if (!ret) {
718       ret = parentSubStats[key] = {
719         runs: 0, amt: 0, name: key, _starts: [], _times: []
720       };
721     }
722 
723     return ret ;
724   },
725 
726   // returns a stats hash for the named key.  If the hash does not exist yet,
727   // creates it.
728   /** @private */
729   _statFor: function(key) {
730     var ret = this.stats[key];
731     if (!ret) {
732       ret = this.stats[key] = {
733         runs: 0, amt: 0, name: key, _starts: [], _times: []
734       };
735     }
736     return ret;
737   },
738 
739   /** @private */
740   reset: function() { this.stats = {} ; },
741 
742   // This is private, but it is used in some places, so we are keeping this for
743   // compatibility.
744   /** @private */
745   _bench: function(func, name) {
746     SC.Benchmark.bench(func, name, 1) ;
747   },
748 
749   /** @private */
750   _benchCount: 1
751 
752 } ;
753 
754 SC.Benchmark = SC.Benchmark;
755