koInstrumentation.js

/// <reference path="../Scripts/jquery-1.8.3.js"/>
/// <reference path="../Scripts/knockout-2.2.0.debug.js"/>
/// <reference path="../Scripts/linq.js" src="http://linqjs.codeplex.com/" /> 
/// <reference path="glimpse.js" />

var koInstrumentation = (function(window, ko, glimspe) {

    // Sanity check dependencies
    if (ko === undefined || ko === null ) {
        console.log("Knockout library missing or not loaded before KnockoutInstrumentration");
        return undefined;
    }

    if (glimspe === undefined || glimspe === null) {
        console.log("glimspe library missing or not loaded before KnockoutInstrumentration");
        return undefined;
    }

    var koInternal = ko;
    var bindings = [];              // Holds the patch bindings so we can reverse it

    var loggingLevel = 2;           // Default to Info level
    var timeMatcher = /[0-9]{2}$/;  // Quick hack for formatting time to force leading zeros

    var render = glimpse.render;
    var events = [];                // Holds the events raised from the binding calls, as the load into glimpse is async.
    var firstRow = true;            // Flag for insert / append

    var bindingStack = [];
    var identifier = 0;
    
    // Subscribe to the tab render so we can set up the setTimeout loop
    glimspe.pubsub.subscribe('action.panel.rendered.Knockout', function(args) {
        var callback = function() {
            setTimeout(function () {
                
                // Probably don't need to splice the events as JS is single-threaded and nothing else will update the events array.
                // But I'm a pessimist ;)
                var length = events.length;
                
                // Convert the items of the event to array elements, as this is what glimpse expects.  I could create a renderer per field but it seems to be overkill.
                var newEvents = Enumerable.From(events.splice(0, length)).Select( function(item) {
                    return [getDatePrefix(item.Start), item.Id, item.IsRoot ? '' : item.BindingStack.join(','), item.Binding, item.Event, item.Element, item.End - item.Start, item.Arguments];
                }).ToArray();

                if (newEvents.length > 0) {
                    // Add the item(s) the glimpse tab.  Note the separation of insert and append as insert will replace all data
                    // and append doesn't add if insert hasn't been called once.
                    console.log("Adding " + newEvents.length + " to glimpse");

                    // Insert the header row at the start.
                    newEvents.unshift(['Time', 'Id', 'Parent(s)', 'Binding', 'Event', 'Element', 'Elasped (ms)', 'Arguments']);
                    if (firstRow) {
                        render.engine.insert(args.panel, newEvents);
                        firstRow = false;
                    } else {
                        render.engine.append(args.panel, newEvents);
                    }
                }

                // .. and set it to fire again
                callback();
            }, 2000);
        };

        // Init the setTimeout loop
        callback();
    });
    
    // Register the tab.  Note subscriptions must initialised before otherwise we miss the event if the glimpse window is already shown
    glimpse.tab.register({
        key: 'Knockout',
        payload: {
            name: 'Knockout',
            isPermanent: true,
            data: [['Time', 'Id', 'Parent(s)', 'Binding', 'Event', 'Element', 'Elasped (ms)', 'Arguments']]
        }
    });

    // Log levels
    var logger = (function () {
        return {
            LogLevels: {
                debugPlusParams: 0,
                debug: 1,
                info: 2,
                warning: 3,
                critical: 4
            }
        };
    })();

    var koUtils = (function () {
        
        // Ported from internal Knockout.  Cannot change ko's inner function to use peek to avoid setting a dependency
        var maxNestedObservableDepth = 10; // Escape the pathalogical case where an observable's current value is itself (or similar reference cycle)

        function toJS(rootObject) {
            if (arguments.length == 0)
                throw new Error("When calling koUtils.toJS, pass the object you want to convert.");

            // We just unwrap everything at every level in the object graph
            return mapJsObjectGraph(rootObject, function (valueToMap) {
                // Loop because an observable's value might in turn be another observable wrapper
                for (var i = 0; koInternal.isObservable(valueToMap) && (i < maxNestedObservableDepth) ; i++)
                    valueToMap = valueToMap.peek();
                return valueToMap;
            });
        }
        
        function mapJsObjectGraph(rootObject, mapInputCallback, visitedObjects) {
            visitedObjects = visitedObjects || new objectLookup();

            rootObject = mapInputCallback(rootObject);
            var canHaveProperties = (typeof rootObject == "object") && (rootObject !== null) && (!(rootObject instanceof Date));
            if (!canHaveProperties)
                return rootObject;

            var outputProperties = rootObject instanceof Array ? [] : {};
            visitedObjects.save(rootObject, outputProperties);

            visitPropertiesOrArrayEntries(rootObject, function (indexer) {
                var propertyValue = mapInputCallback(rootObject[indexer]);

                switch (typeof propertyValue) {
                    case "boolean":
                    case "number":
                    case "string":
                    case "function":
                        outputProperties[indexer] = propertyValue;
                        break;
                    case "object":
                    case "undefined":
                        var previouslyMappedValue = visitedObjects.get(propertyValue);
                        outputProperties[indexer] = (previouslyMappedValue !== undefined)
                            ? previouslyMappedValue
                            : mapJsObjectGraph(propertyValue, mapInputCallback, visitedObjects);
                        break;
                }
            });

            return outputProperties;
        }

        function visitPropertiesOrArrayEntries(rootObject, visitorCallback) {
            if (rootObject instanceof Array) {
                for (var i = 0; i < rootObject.length; i++)
                    visitorCallback(i);

                // For arrays, also respect toJSON property for custom mappings (fixes #278)
                if (typeof rootObject['toJSON'] == 'function')
                    visitorCallback('toJSON');
            } else {
                for (var propertyName in rootObject)
                    visitorCallback(propertyName);
            }
        };

        function objectLookup() {
            var keys = [];
            var values = [];
            this.save = function (key, value) {
                var existingIndex = koInternal.utils.arrayIndexOf(keys, key);
                if (existingIndex >= 0)
                    values[existingIndex] = value;
                else {
                    keys.push(key);
                    values.push(value);
                }
            };
            this.get = function (key) {
                var existingIndex = koInternal.utils.arrayIndexOf(keys, key);
                return (existingIndex >= 0) ? values[existingIndex] : undefined;
            };
        };
        
        return {
            peekToJSON: function(rootObject, replacer, space) {
                var plainJavaScriptObject = toJS(rootObject);
                return koInternal.utils.stringifyJson(plainJavaScriptObject, replacer, space);
            }
        };
    })();
    
    //  Formats the current date to "HH:mm:ss" with leading zeros.
    function getDatePrefix(theDate) {
        return ('0' + theDate.getHours()).match(timeMatcher)[0] + ':' +  ('0' + theDate.getMinutes()).match(timeMatcher)[0] + ':' + ('0' + theDate.getSeconds()).match(timeMatcher)[0];
    }
    
    // Replace all ko bindings with a double    
    function patchAllBindings() {
        // Monkey patch bindings
        for (var binding in koInternal.bindingHandlers) {
            patchBinding(koInternal.bindingHandlers, binding);
        }
    }

    // Reset all patched bindings back to the original
    function removeAllPatchedBindings() {
        // Monkey patch bindings
        for (var binding in koInternal.bindingHandlers) {
            removePatch(koInternal.bindingHandlers, binding);
        }

        bindings = [];
    }

    // Patchs an individual binding
    function patchBinding(bindingHandlers, bindingName) {

        var originalBinding = bindingHandlers[bindingName];
        
        var newBinding = {
            original: originalBinding
        };

        // copy over all external facing functions
        for (var extraFunctions in originalBinding) {
            newBinding[extraFunctions] = originalBinding[extraFunctions];
        }
        
        // Handle init function
        if (originalBinding.init !== undefined) {
            newBinding.init = function (element, valueAccessor, allBindingsAccessor, viewModel, bindingContext) {
                var eventData = buildEventData(bindingName, 'init', element, originalBinding.init.length, valueAccessor, allBindingsAccessor);
                var result = originalBinding.init(element, valueAccessor, allBindingsAccessor, viewModel, bindingContext);

                publishEventData(eventData);
                return result;
            };
        }

        // Handle update function
        if (originalBinding.update !== undefined) {
            newBinding.update = function (element, valueAccessor, allBindingsAccessor, viewModel, bindingContext) {
                var eventData = buildEventData(bindingName, 'update', element, originalBinding.update.length, valueAccessor, allBindingsAccessor);
                var result = originalBinding.update(element, valueAccessor, allBindingsAccessor, viewModel, bindingContext);

                publishEventData(eventData);
                return result;
            };
        }

        bindings.push(newBinding);
        bindingHandlers[bindingName] = newBinding;
    }

    function buildEventData(bindingName, methodName, element, bindingArgCount, valueAccessor, allBindingsAccessor) {

        var currentStack = bindingStack.slice();
        bindingStack.push(++identifier);
        
        var eventData = {
            'Start': undefined,
            'End': undefined,
            'Id' : identifier,
            'IsRoot' : bindingStack.length === 1,
            'BindingStack': currentStack,
            'Binding': bindingName,
            'Event': methodName,
            'Element': buildElementDisplay(element),
            'Arguments': logBindingArguments(bindingArgCount, valueAccessor, allBindingsAccessor)
        };

        // Get the timer after we log elements and arguments otherwise the timing can be noticably influenced!
        eventData.Start = new Date();
        
        return eventData;
    }
    
    function publishEventData(eventData) {
        eventData.End = new Date();
        events.push(eventData);

        var id = bindingStack.pop();
        
        if (eventData.Id !== id) {
            console.log('Push with no pop ' + eventData.Id + ' !== ' + id);
        }
    }
    
    function logBindingArguments(bindingArgCount, valueAccessor, allBindingsAccessor) { //}, viewModel, bindingContext) {
        if (loggingLevel > logger.LogLevels.debugPlusParams) {
            return {};
        }
        
        var data = { 'Value': getAccessorForDisplay(valueAccessor, 'value') };
        
        // Some bindings only have 2 arguments element and valueAccessor - like text
        if (bindingArgCount >= 3) {
            data['Bindings'] = getAccessorForDisplay(allBindingsAccessor, 'allBindings');
        }
        return data;
    }

    function buildElementDisplay(element) {

        if (loggingLevel <= logger.LogLevels.debug) {
            if (element.nodeType === 8) {
                return buildCommentDisplay(element);
            } else if (element.nodeType === 1) {
                return buildNodeDisplay(element);
            }
        }
        return '';
    }
    
    // formats a Virtual ko comment node
    function buildCommentDisplay(element) {
        return ('Virtual element <!-- ' + element.textContent + ' -->');
    }
    
    // formats a standard node with ko bindings
    function buildNodeDisplay(element) {
        var display = '<' + element.nodeName;
        
        if (element.id !== '') {
            display += (' id = "' + element.id + '"');
        }
        
        if (element.attributes['data-bind'] !== undefined ) {
            display += (' data-bind = "' + element.attributes['data-bind'].value + '"');
        }

        display += ' >';

        return display;
    }
    
    function getAccessorForDisplay( accessor, name) {
        if (accessor === undefined) {
            console.log('parameter: ' + name + 'Accessor is undefined');
            return {};
        }

        if (typeof accessor !== "function") {
            console.log('parameter: ' + name + 'Accessor is not a function');
            return {};
        }
        
        try {
            return koUtils.peekToJSON(accessor(), customJsonReplacerForCircularReferences());
        }
        catch (ex) {
            // Most likely a recursive object model.  Log top level items
            return 'Cannot log "' + name + '" : ' + ex;
        }
    }
    
    var customJsonReplacerForCircularReferences = function() {
        var cache = [];

        return function(key, value) {
            if (typeof value === "object") {
                if (cache.indexOf(value) !== -1) {
                    return undefined; // Circular reference found... drop value
                }
                cache.push(value);
            }
            return value;
        };
    };
    
    function removePatch(bindingHandlers, bindingName) {
        var patchedBinding = bindingHandlers[bindingName];
        
        if (patchedBinding.original === undefined) {
            console.log('warning.... binding ' + bindingName + ' ignored as it wasn\'t patched');
        }

        bindingHandlers[bindingName] = patchedBinding.original;
    }
    
    return {
        Clear: function() {
            firstRow = true;
        },
        Instrument: function (logLevel) {
            
            if (logLevel === undefined || typeof logLevel !== "number") {
                logLevel = logger.LogLevels.info;
            }

            loggingLevel = logLevel;
            
            if (bindings.length !== 0 ) {
                console.log('Bindings are already instrumented');
                return;
            }
            
            if (logLevel > logger.LogLevels.info) {
                console.log('Bypassing instrumentation.  Log level to too high, you won\'t see any messages');
                return;
            }

            console.log('Monkey patching knockout bindings.');
            
            patchAllBindings();
            
            if (bindings.length >= 0 ) {
                console.log(bindings.length + ' bindings have been patched.');
            }

            console.log('Completed.  Run koInstrumentation.Remove() to reverse changes.');
        },
        Remove: function() {
            if (bindings.length === 0) {
                console.log('Bindings are haven\'t been instrumented.');
                return;
            }
            
            console.log('Removing monkey patched knockout bingings.');

            removeAllPatchedBindings();
            
            if (bindings.length === 0) {
                console.log('All patched bindings have removed.');
            }
            
            console.log('Completed.  Run koInstrumentation.Instrument() to re-instrument changes.');
        },
        LogLevels: logger.LogLevels
        
    };

})(window, ko, glimpse);

Out of curiosity why are you using a 2 second timeout to get new events? Would it be better to extend the knockout observables as per http://knockoutjs.com/documentation/extenders.html to catch events in realtime, or does that just kill the performance?