Quick and easy extension performance measurement

[UnknownJ]

Just mucking about with something and thought I'd share it with the group...

var tolerance = 5;
utag.handler.extend = utag.handler.extend.map(function(extension, extensionIndex){
  return function(){
    var perfStart = performance.now();
    extension.apply(this, arguments);
    var perfEnd = performance.now();
    var extObj = utag.handler.cfg_extend[extensionIndex];
    var extType = extObj.blr ? "blr" : extObj.alr ? "alr" : extObj.end ? "end" : "other";
    var perfLength = perfEnd - perfStart;
    console.log(extType, extObj.id, perfLength);
    if(perfLength > tolerance) console.log(extension.toString());
  };
});

This will give you a console output (scope, extension ID, execution time) upon the run of each event extension (Before Load Rules, After Load Rules, After Tags) and in this case any extension that takes more than five milliseconds to execute gets its stringified function definition (albeit minified, sorry!) output as well to help get a feel for what that extension is doing.

So if you drop that into your console and then fire a utag.view call, it'll let you know how your extensions are going.

I'm speaking as somebody who's just found an extension that takes >50ms to run on Chrome's "low-end mobile" emulation and feeling more than a little shame at having put that into production, so yeah, have fun with it!

[UnknownJ]

Or, if you want an absolutely nuclear way of doing this stuff....

var perfTotals = {};

function pwrap(owner,fname,rname){

    var original = owner[fname];
    owner[fname] = function(){
        var perfStart = performance.now();
        var r = original.apply(this,arguments);
        var perfEnd = performance.now();
        perfTotals[rname] = (perfTotals[rname] || 0) + perfEnd - perfStart;
        // if(perfEnd - perfStart > 10) console.log(rname,perfEnd-perfStart);
        return r;
    }
        
};

var exclusions = [window,utag.o];

function rwrap(obj,prefix,depth){
  if(depth > 4) return;
  if(exclusions.indexOf(obj) >= 0) return;
  for(var k in obj){
    if(typeof obj[k] === "function"){
      pwrap(obj,k,prefix + "." + k);
    } else if(Array.isArray(obj)){
      obj.forEach(function(item){
        rwrap(item,prefix + "." + k,(depth || 0) + 1);
      });
    } else if(typeof obj[k] === "object"){
      rwrap(obj[k],prefix + "." + k,(depth || 0) + 1);
    }
  }
}

rwrap(utag,"utag");

utag.view({});

var maxlength = 0;
for(var k in perfTotals){
  if(k.length > maxlength) maxlength = k.length;
}

console.log(
  Object.keys(perfTotals)
    .sort(function(a,b){
      return perfTotals[b] - perfTotals[a];
    })
    .reduce(function(c,v){
      c += v;
      c += (function(stringToPad){
        var output = "";
        for(var i = stringToPad.length; i < maxlength + 2; i++) output += " ";
        return output;
      })(v);
      c += Math.floor(perfTotals[v]);
      c += "\n";
      return c;
    },"")
);

This will recursively wrap all the functions found within the utag object or its descendants up to a depth of four, and then fire an event, and tell you how long everything took (with repeat invocations adding to the total):

utag.view                                                 937
utag.track                                                937
utag.handler.trigger                                      937
utag.handler.RE                                           203
utag.sender.928.send                                      146
utag.tagsettings.adobe.visitorAPI.getInstance             131
utag.sender.1428.send                                     115
utag.sender.1428.o                                        106
utag.handler.C                                            106
utag.sender.1216.send                                     93
utag.sender.1216.o                                        92
utag.sender.928.o.t                                       68
utag.handler.LR                                           66
utag.sender.1024.send                                     50
utag.sender.1024.o                                        49
utag.loader.loadrules                                     46
utag.sender.928.o.Ea                                      41
utag.sender.928.o.d.querySelectorAll                      40
utag.sender.1459.send                                     39
utag.ut.typeOf                                            33
utag.loader.GV                                            31
utag.loader.RD                                            30
utag.sender.911.send                                      29
utag.sender.928.o.isReadyToTrack                          27
utag.sender.928.o.pb                                      26
utag.handler.extend.59                                    26

With the evident caveat that if function a invokes function b, the total execution time for b will be included in a, hence why utag.view, utag.track and utag.handler.trigger have roughly the same duration here - view invokes track, track invokes trigger, but the end to end execution time remains 937ms.