Add/update various profiling and reporting code

index.js

@@ -22,6 +22,7 @@ module.exports = Engine
 
 // profiling flag
 var PROFILE = 0
+var PROFILE_RENDER = 0
 
 
 
@@ -259,6 +260,7 @@ function debugQueues(self) {
 
 Engine.prototype.render = function (framePart) {
   if (this._paused) return
+  profile_hook_render('start')
   var dt = framePart * this._tickRate // ms since last tick
   // only move camera during pointerlock or mousedown, or if pointerlock is unsupported
   if (this.container.hasPointerLock ||
@@ -270,10 +272,12 @@ Engine.prototype.render = function (framePart) {
   this.inputs.state.dx = this.inputs.state.dy = 0
   // events and render
   this.emit('beforeRender', dt)
-  // t0()
+  profile_hook_render('before render')
   this.rendering.render(dt)
-  // t1('render')
+  profile_hook_render('render')
   this.emit('afterRender', dt)
+  profile_hook_render('after render')
+  profile_hook_render('end')
 }
 
 
@@ -438,14 +442,22 @@ var _prevTargetHash = ''
 
 
 var profile_hook = function (s) { }
+var profile_hook_render = function (s) { }
 if (PROFILE) (function () {
-    var every = 200
-    var timer = new (require('./lib/util').Timer)(every)
-    profile_hook = function (state) {
-        if (state === 'start') timer.start()
-        else if (state === 'end') timer.report()
-        else timer.add(state)
-    }
+  var timer = new (require('./lib/util').Timer)(100, 'tick')
+  profile_hook = function (state) {
+    if (state === 'start') timer.start()
+    else if (state === 'end') timer.report()
+    else timer.add(state)
+  }
+})()
+if (PROFILE_RENDER) (function () {
+  var timer = new (require('./lib/util').Timer)(200, 'render')
+  profile_hook_render = function (state) {
+    if (state === 'start') timer.start()
+    else if (state === 'end') timer.report()
+    else timer.add(state)
+  }
 })()
 
 

lib/rendering.js

@@ -70,6 +70,7 @@ function Rendering(noa, _opts, canvas) {
     this.useAO = !!opts.useAO
     this.aoVals = opts.AOmultipliers
     this.revAoVal = opts.reverseAOmultiplier
+    this.meshingCutoffTime = 6 // ms
 
     // for debugging
     window.scene = this._scene
@@ -155,11 +156,17 @@ Rendering.prototype.getScene = function () {
 
 // tick function manages deferred meshing
 Rendering.prototype.tick = function (dt) {
+    profile_hook('start')
+
     // chunk a mesh, or a few if they're fast
-    var cutoff = 6 + performance.now()
+    var cutoff = performance.now() + this.meshingCutoffTime
+
     while (this._chunksToMesh.length && (performance.now() < cutoff)) {
         doDeferredMeshing(this)
     }
+
+    profile_hook('mesh chunking')
+    profile_hook('end')
 }
 
 
@@ -302,7 +309,6 @@ function onChunkRemoved(self, i, j, k) {
 }
 
 function doDeferredMeshing(self) {
-    profile_hook('start')
     var chunk = null
 
     // find a chunk to mesh, starting from front, skipping if not meshable
@@ -327,8 +333,6 @@ function doDeferredMeshing(self) {
         }
     }
 
-    profile_hook('chunked mesh')
-    profile_hook('end')
 }
 
 /*
@@ -648,7 +652,7 @@ function createOctreeBlock(self, mesh, chunk, x, y, z) {
 var profile_hook = function (s) { }
 if (PROFILE) (function () {
     var every = 200
-    var timer = new (require('./util').Timer)(every)
+    var timer = new (require('./util').Timer)(every, 'render internals')
     profile_hook = function (state) {
         if (state === 'start') timer.start()
         else if (state === 'end') timer.report()

lib/util.js

@@ -9,7 +9,8 @@ module.exports = {
 
 
 // simple thing for reporting time split up between several activities
-function Timer(_every) {
+function Timer(_every, _title) {
+    var title = _title || ''
     var every = _every || 1
     var times = []
     var names = []
@@ -35,7 +36,7 @@ function Timer(_every) {
     }
     this.report = function () {
         if (iter === every) {
-            console.log(names.map(function (name, i) {
+            console.log(title + ':', names.map(function (name, i) {
                 return name + ': ' + (times[i] / every).toFixed(2) + 'ms    '
             }).join(''), (every > 1) ? '  (avg over ' + every + ' runs)' : '')
             clearNext = true

lib/world.js

@@ -12,11 +12,13 @@ module.exports = function(noa, opts) {
 }
 
 
+var PROFILE = 0
+
+
 var defaultOptions = {
   chunkSize: 24,
   chunkAddDistance: 3,
   chunkRemoveDistance: 4
-
 }
 
 /**
@@ -48,8 +50,9 @@ function World(noa, _opts) {
   this._chunkIDsToRemove = []
   this._chunkIDsInMemory = []
   this._chunkIDsPendingCreation = []
-  this._maxChunksPendingCreation = 4
-  this._maxChunksPendingMeshing = 15
+  this._maxChunksPendingCreation = 6
+  this._maxChunksPendingMeshing = 12
+  this._processingCutoffTime = 6 // ms
 
   // actual chunk storage - hash size hard coded for now
   this._chunkHash = ndHash([1024, 1024, 1024])
@@ -173,11 +176,13 @@ World.prototype.tick = function() {
   this._lastPlayerChunkID = chunkID
 
   // add or remove one chunk if needed. If fast, do a couple.
-  var cutoff = 2 + performance.now()
+  profile_hook(this, 'start')
+  var cutoff = performance.now() + this._processingCutoffTime
   var done = false
   while(!done && (performance.now() < cutoff)) {
     done = processChunkQueues(this, i, j, k)
   }
+  profile_hook(this, 'end')
 
   // track whether the player's local chunk is loaded and ready or not
   var pChunk = getChunk(this, i, j, k)
@@ -194,6 +199,7 @@ World.prototype.tick = function() {
  * @param userData
  */
 World.prototype.setChunkData = function(id, array, userData) {
+  profile_hook(this, 'received')
   var arr = parseChunkID(id)
   var chunk = getChunk(this, arr[0], arr[1], arr[2])
   // ignore if chunk was invalidated while being prepared
@@ -231,12 +237,12 @@ World.prototype.report = function() {
   console.log('World report - playerChunkLoaded: ', this.playerChunkLoaded)
   _report(this, '  to add     ', this._chunkIDsToAdd)
   _report(this, '  to remove: ', this._chunkIDsToRemove)
-  _report(this, '  in memory: ', this._chunkIDsInMemory)
+  _report(this, '  in memory: ', this._chunkIDsInMemory, true)
   _report(this, '  creating:  ', this._chunkIDsPendingCreation)
   _report(this, '  meshing:   ', this.noa.rendering._chunksToMesh)
 }
-function _report(world, name, arr) {
-  var ct = 0
+function _report(world, name, arr, ext) {
+  var ct = 0, full = 0, empty = 0
   for (var id of arr) {
     if (id.size) {
       if (id.isInvalid) ct++
@@ -245,8 +251,11 @@ function _report(world, name, arr) {
     var loc = parseChunkID(id)
     var chunk = getChunk(world, loc[0], loc[1], loc[2])
     if (chunk.isInvalid) ct++
+    if (chunk.isFull) full++
+    if (chunk.isEmpty) empty++
   }
-  console.log(name, arr.length, '   ' + ct, 'invalid')
+  var es = (ext) ? [', ', full, ' full, ', empty, ' empty'].join('') : ''
+  console.log(name, arr.length, '   ' + ct, 'invalid' + es)
 }
 
 
@@ -304,6 +313,7 @@ function processChunkQueues(self, i, j, k) {
   if (self._chunkIDsToRemove.length) {
     var remove = parseChunkID( self._chunkIDsToRemove.pop() )
     removeChunk( self, remove[0], remove[1], remove[2] )
+    profile_hook(self, 'removed')
     done = false
   }
   if (self._chunkIDsPendingCreation.length >= self._maxChunksPendingCreation) return done
@@ -312,6 +322,7 @@ function processChunkQueues(self, i, j, k) {
     var id = self._chunkIDsToAdd.shift()
     var toadd = parseChunkID(id)
     requestNewChunk( self, id, toadd[0], toadd[1], toadd[2] )
+    profile_hook(self, 'requested')
     done = false
   }
   return done
@@ -480,6 +491,61 @@ function unenqueueID( id, queue ) {
 
 
 
-
+var profile_hook = function (w, s) { }
+if (PROFILE) (function () {
+  var every = 100
+  var iter = 0
+  var t, nrem, nreq, totalrec
+  var temprem, tempreq
+  var reqcts, remcts
+  var qadd, qrem, qmem, qpend, qmesh
+  profile_hook = function (world, state) {
+    if (state === 'start') {
+      if (iter===0) {
+        t = performance.now()
+        qadd = qrem = qmem = qpend = qmesh = 0
+        totalrec = 0
+        remcts = []
+        reqcts = []
+      }
+      iter++
+      nrem = nreq = 0
+    } else if (state === 'removed') {
+      nrem++
+    } else if (state === 'received') {
+      totalrec++
+    } else if (state === 'requested') {
+      nreq++
+    } else if (state === 'end') {
+      // counts for frames that were fully worked
+      if (world._chunkIDsToAdd.length) reqcts.push(nreq)
+      if (world._chunkIDsToRemove.length) remcts.push(nrem)
+      // avg queue sizes
+      qadd += world._chunkIDsToAdd.length
+      qrem += world._chunkIDsToRemove.length
+      qmem += world._chunkIDsInMemory.length
+      qpend += world._chunkIDsPendingCreation.length
+      qmesh += world.noa.rendering._chunksToMesh.length
+      // on end
+      if (iter===every) {
+        var dt = (performance.now()-t)/1000
+        console.log('world chunk queues:',
+          'made', Math.round(totalrec/dt), 'cps',
+          '- avg queuelen: ',
+          'add', qadd/every, 
+          'rem', qrem/every, 
+          'mem', qmem/every, 
+          'pend', qpend/every, 
+          'mesh', qmesh/every,
+          '- work/frame: ',
+          'req', Math.round(reqcts.reduce(sum, 0)/reqcts.length*10)/10,
+          'rem', Math.round(remcts.reduce(sum, 0)/remcts.length*10)/10
+        )
+        iter = 0
+      }
+    }
+  }
+  var sum = function(num, prev) { return num+prev }
+})()