Merge pull request #1067 from brendandahl/stats

Start of the benchmark recording framework.

src/core.js

@@ -63,13 +63,8 @@ var Page = (function PageClosure() {
   function Page(xref, pageNumber, pageDict, ref) {
     this.pageNumber = pageNumber;
     this.pageDict = pageDict;
-    this.stats = {
-      create: Date.now(),
-      compile: 0.0,
-      fonts: 0.0,
-      images: 0.0,
-      render: 0.0
-    };
+    this.stats = new StatTimer();
+    this.stats.enabled = !!globalScope.PDFJS.enableStats;
     this.xref = xref;
     this.ref = ref;
 
@@ -200,6 +195,8 @@ var Page = (function PageClosure() {
         return this.IRQueue;
       }
 
+      this.stats.time('Build IR Queue');
+
       var xref = this.xref;
       var content = xref.fetchIfRef(this.content);
       var resources = xref.fetchIfRef(this.resources);
@@ -217,11 +214,14 @@ var Page = (function PageClosure() {
       var pe = this.pe = new PartialEvaluator(
                                 xref, handler, 'p' + this.pageNumber + '_');
       var IRQueue = {};
-      return (this.IRQueue = pe.getIRQueue(content, resources, IRQueue,
-                                           dependency));
+      this.IRQueue = pe.getIRQueue(content, resources, IRQueue, dependency);
+
+      this.stats.timeEnd('Build IR Queue');
+      return this.IRQueue;
     },
 
     ensureFonts: function pageEnsureFonts(fonts, callback) {
+      this.stats.time('Font Loading');
       // Convert the font names to the corresponding font obj.
       for (var i = 0, ii = fonts.length; i < ii; i++) {
         fonts[i] = this.objs.objs[fonts[i]].data;
@@ -231,7 +231,7 @@ var Page = (function PageClosure() {
       var fontObjs = FontLoader.bind(
         fonts,
         function pageEnsureFontsFontObjs(fontObjs) {
-          this.stats.fonts = Date.now();
+          this.stats.timeEnd('Font Loading');
 
           callback.call(this);
         }.bind(this),
@@ -240,6 +240,8 @@ var Page = (function PageClosure() {
     },
 
     display: function pageDisplay(gfx, callback) {
+      var stats = this.stats;
+      stats.time('Rendering');
       var xref = this.xref;
       var resources = xref.fetchIfRef(this.resources);
       var mediaBox = xref.fetchIfRef(this.mediaBox);
@@ -266,8 +268,9 @@ var Page = (function PageClosure() {
       function next() {
         startIdx = gfx.executeIRQueue(IRQueue, startIdx, next, stepper);
         if (startIdx == length) {
-          self.stats.render = Date.now();
           gfx.endDrawing();
+          stats.timeEnd('Rendering');
+          stats.timeEnd('Overall');
           if (callback) callback();
         }
       }
@@ -431,15 +434,14 @@ var Page = (function PageClosure() {
       return items;
     },
     startRendering: function pageStartRendering(ctx, callback, textLayer)  {
-      this.startRenderingTime = Date.now();
-
+      var stats = this.stats;
+      stats.time('Overall');
       // If there is no displayReadyPromise yet, then the IRQueue was never
       // requested before. Make the request and create the promise.
       if (!this.displayReadyPromise) {
         this.pdf.startRendering(this);
         this.displayReadyPromise = new Promise();
       }
-
       // Once the IRQueue and fonts are loaded, perform the actual rendering.
       this.displayReadyPromise.then(
         function pageDisplayReadyPromise() {
@@ -731,7 +733,7 @@ var PDFDoc = (function PDFDocClosure() {
         var pageNum = data.pageNum;
         var page = this.pageCache[pageNum];
         var depFonts = data.depFonts;
-
+        page.stats.timeEnd('Page Request');
         page.startRenderingFromIRQueue(data.IRQueue, depFonts);
       }, this);
 
@@ -840,6 +842,7 @@ var PDFDoc = (function PDFDocClosure() {
     startRendering: function pdfDocStartRendering(page) {
       // The worker might not be ready to receive the page request yet.
       this.workerReadyPromise.then(function pdfDocStartRenderingThen() {
+        page.stats.time('Page Request');
         this.messageHandler.send('page_request', page.pageNumber + 1);
       }.bind(this));
     },

src/util.js

@@ -416,3 +416,55 @@ var Promise = (function PromiseClosure() {
   return Promise;
 })();
 
+var StatTimer = (function StatTimerClosure() {
+  function rpad(str, pad, length) {
+    while (str.length < length)
+      str += pad;
+    return str;
+  }
+  function StatTimer() {
+    this.started = {};
+    this.times = [];
+    this.enabled = true;
+  }
+  StatTimer.prototype = {
+    time: function statTimerTime(name) {
+      if (!this.enabled)
+        return;
+      if (name in this.started)
+        throw 'Timer is already running for ' + name;
+      this.started[name] = Date.now();
+    },
+    timeEnd: function statTimerTimeEnd(name) {
+      if (!this.enabled)
+        return;
+      if (!(name in this.started))
+        throw 'Timer has not been started for ' + name;
+      this.times.push({
+        'name': name,
+        'start': this.started[name],
+        'end': Date.now()
+      });
+      // Remove timer from started so it can be called again.
+      delete this.started[name];
+    },
+    toString: function statTimerToString() {
+      var times = this.times;
+      var out = '';
+      // Find the longest name for padding purposes.
+      var longest = 0;
+      for (var i = 0, ii = times.length; i < ii; ++i) {
+        var name = times[i]['name'];
+        if (name.length > longest)
+          longest = name.length;
+      }
+      for (var i = 0, ii = times.length; i < ii; ++i) {
+        var span = times[i];
+        var duration = span.end - span.start;
+        out += rpad(span['name'], ' ', longest) + ' ' + duration + 'ms\n';
+      }
+      return out;
+    }
+  };
+  return StatTimer;
+})();