Merge lp:~mpontillo/maas/js-metrics-service into lp:~maas-committers/maas/trunk

[Mike Pontillo]

Add JavaScript logging for $digest metrics and $routeChangeSuccess.

This is a branch I used earlier this cycle while debugging some UI issues, but didn't get around to proposing separately until now.

This adds logging such as the following to the JavaScript console:

Navigated to http://192.168.0.2/MAAS/
[0.616] $routeChangeSuccess: http://192.168.0.2/MAAS/#/networks?by=fabric; templateURL=static/partials/networks-list.html?v=2.2.0~rc1(bzr5922-0ubuntu2~16.04.1)
[0.787] $digest cycle 1: 18 digests completed in ~0.251 seconds.
[0.793] $digest cycle 2: 1 digest completed in ~0.001 seconds.
[1.029] $digest cycle 3: 1 digest completed in ~0.001 seconds.
[1.034] $digest cycle 4: 1 digest completed in ~0.001 seconds.
[1.105] $digest cycle 5: 1 digest completed in ~0.002 seconds.
[1.678] $digest cycle 6: 1 digest completed in ~0.001 seconds.
[1.715] $digest cycle 7: 1 digest completed in ~0.001 seconds.
[1.905] $digest cycle 8: 1 digest completed in ~0.001 seconds.
[2.095] $digest cycle 9: 2 digests completed in ~0.002 seconds.
[2.158] $digest cycle 10: 2 digests completed in ~0.002 seconds.
[2.165] $digest cycle 11: 1 digest completed in ~0.001 seconds.
[2.248] $digest cycle 12: 1 digest completed in ~0.001 seconds.
[2.258] $digest cycle 13: 1 digest completed in ~0.001 seconds.
[2.301] $digest cycle 14: 1 digest completed in ~0.001 seconds.
[2.386] Version reloader: Monitoring MAAS "maas"; version 2.2.0~rc1 (bzr5922-0ubuntu2~16.04.1) via http://192.168.0.2/MAAS/#/networks?by=fabric
[2.393] $digest cycle 15: 5 digests completed in ~0.038 seconds.
[28.874] $digest cycle 16: 3 digests completed in ~0.010 seconds.
[28.900] $routeChangeSuccess: http://192.168.0.2/MAAS/#/nodes; templateURL=static/partials/nodes-list.html?v=2.2.0~rc1(bzr5922-0ubuntu2~16.04.1)
[29.163] $digest cycle 17: 14 digests completed in ~0.091 seconds.
[29.796] $digest cycle 18: 3 digests completed in ~0.022 seconds.
[29.820] $digest cycle 19: 5 digests completed in ~0.021 seconds.
[29.873] $digest cycle 20: 2 digests completed in ~0.003 seconds.
[29.890] $digest cycle 21: 2 digests completed in ~0.004 seconds.
[29.903] $digest cycle 22: 1 digest completed in ~0.003 seconds.
[29.908] $digest cycle 23: 1 digest completed in ~0.001 seconds.
[29.970] $digest cycle 24: 2 digests completed in ~0.042 seconds.

This logging can easily be filtered using the JavaScript console if it is unwanted, since the $digest cycles are logged at debug level.

Route changes are logged at info level.

[Blake Rouse (blake-rouse)]

This should be off in production. So you should check MAAS_config.debug, when True turn it on (dev mode), otherwise its off.

review: Needs Fixing

[Mike Pontillo (mpontillo)]

I thought you might say something about that.

I agree that we should have a way to turn it off by default, but I think it would be more useful if we had a way to use a cookie to set the log level for MAAS's JavaScript logging. I'll check into it.

[Blake Rouse (blake-rouse)]

I would recommend using a url option instead of cookies. Like ?debug=true

[Mike Pontillo (mpontillo)]

Good idea. I'll check into it.

[MAAS Lander (maas-lander)]

Transitioned to Git.

lp:maas has now moved from Bzr to Git.
Please propose your branches with Launchpad using Git.

git clone https://git.launchpad.net/maas

Unmerged revisions

5959. By Mike Pontillo on 2017-04-13

Merge trunk.

5958. By Mike Pontillo on 2017-04-13

Add metrics service.

=== modified file 'src/maasserver/static/js/angular/maas.js'
--- src/maasserver/static/js/angular/maas.js	2017-03-10 18:38:46 +0000
+++ src/maasserver/static/js/angular/maas.js	2017-04-13 20:57:48 +0000
@@ -158,6 +158,12 @@
         }
     });
 
+// Make sure the MetricsService is created for every run, so we can get
+// accurate numbers.
+angular.module('MAAS').run(['MetricsService', function (MetricsService) {
+    MetricsService.setConfigDone();
+}]);
+
 // Force users to #/intro when it has not been completed.
 angular.module('MAAS').run(['$rootScope', '$location',
     function ($rootScope, $location) {

=== added file 'src/maasserver/static/js/angular/services/metrics.js'
--- src/maasserver/static/js/angular/services/metrics.js	1970-01-01 00:00:00 +0000
+++ src/maasserver/static/js/angular/services/metrics.js	2017-04-13 20:57:48 +0000
@@ -0,0 +1,94 @@
+/* Copyright 2017 Canonical Ltd.  This software is licensed under the
+ * GNU Affero General Public License version 3 (see the file LICENSE).
+ * 
+ * Metrics Service
+ * 
+ * Records and logs metrics about various events. Currently, that includes:
+ *  - The $digest lifecycle.
+ *  - Any route changes (navigations).
+ */
+
+angular.module('MAAS').service('MetricsService', [
+    '$rootScope', '$window', '$timeout', 'LogService', function(
+        $rootScope, $window, $timeout, LogService) {
+        
+        var self = this;
+
+        self.metrics = {};
+        
+        // Initial metric values.
+        self.metrics.digestCount = 0;
+        self.metrics.openDigests = [];
+        self.metrics.digestCycles = 0;
+
+        this.info = LogService.info;
+        this.debug = LogService.debug;
+
+        this.formatMilliseconds = LogService.formatMilliseconds;
+
+        // Returns a monotonic time in milliseconds.
+        this.now = function() {
+            return LogService.now();
+        };
+
+        // Returns the current URL string.
+        this.location = function() {
+            return $window.location;
+        };
+
+        // Called when the MAAS module starts running, to record the time it
+        // took to initialize.
+        this.setConfigDone = function() {
+            self.metrics.configDone = self.now();
+        };
+
+        // Called from $rootScope on $digest every $watch cycle.
+        this.updateDigestMetrics = function() {
+            var now = self.now();
+            var digestCount = ++self.metrics.digestCount;
+            // Keep a stack of "open" $digest calls. A $digest cycle is
+            // considered done after Angular has a chance to process all the
+            // timeouts generated by each call to $digest.
+            self.metrics.openDigests.push({'time': now, 'count': digestCount});
+            self.metrics.lastDigest = now;
+            // Since we're interested in how long $digest cycles are taking,
+            // ask Angular to call us back at its earliest convenience.
+            // The result is that if multiple $digest calls kick off in
+            // succession, the last $timeout will be called after they are
+            // *all*, complete, which allows us to calculate a rough estimate
+            // of how long the complete cycle took.
+            $timeout(function() {
+                var digest = self.metrics.openDigests.pop();
+                // If we've popped the last $digest call off the stack, that
+                // means we're done with a complete cycle.
+                if(self.metrics.openDigests.length == 0) {
+                    var cycles = ++self.metrics.digestCycles;
+                    var finished = self.now();
+                    var started = digest.time;
+                    var duration = finished - started;
+                    var startCount = digest.count;
+                    var finishCount = self.metrics.digestCount;
+                    var count = finishCount - startCount + 1;
+                    var countMessage = (count == 1) ?
+                        count + " digest" : count + " digests";
+                    var seconds = self.formatMilliseconds(duration);
+                    self.debug("$digest cycle " + cycles + ": " +
+                        countMessage + " completed in ~" +
+                        seconds + " seconds.");
+                }
+            }, 0, false);
+        };
+        
+        this.logRouteChange = function(event, current, previous) {
+            var currentLocation = self.location();
+            self.info(
+                "$routeChangeSuccess: " + currentLocation +
+                "; templateURL=" + current.templateUrl);
+        };
+
+        // Add the MetricsService to the $rootScope so that $watch works.
+        $rootScope.MetricsService = this;
+        $rootScope.$watch('MetricsService.updateDigestMetrics()');
+        $rootScope.$on("$routeChangeSuccess", this.logRouteChange);
+}]);
+

=== added file 'src/maasserver/static/js/angular/services/tests/test_metrics.js'
--- src/maasserver/static/js/angular/services/tests/test_metrics.js	1970-01-01 00:00:00 +0000
+++ src/maasserver/static/js/angular/services/tests/test_metrics.js	2017-04-13 20:57:48 +0000
@@ -0,0 +1,68 @@
+/* Copyright 2015 Canonical Ltd.  This software is licensed under the
+ * GNU Affero General Public License version 3 (see the file LICENSE).
+ *
+ * Unit tests for MetricsService.
+ */
+
+describe("MetricsService", function() {
+
+    // Load the MAAS module.
+    beforeEach(module("MAAS"));
+
+    // Get the $injector so the test can grab the MetricsService.
+    var $injector;
+    var $rootScope;
+    beforeEach(inject(function(_$injector_) {
+        $injector = _$injector_;
+        $rootScope = $injector.get("$rootScope");
+    }));
+
+    describe("init", function() {
+        // Note: we can't use spyOn() here to check if $watch and/or $on were
+        // called, since the init happens too early for that.
+
+        it("addsWorkingWatchToRootScope", function () {
+            var MetricsService = $injector.get("MetricsService");
+            expect($rootScope.MetricsService).toBe(MetricsService);
+            spyOn(MetricsService, 'updateDigestMetrics');
+            // Check if the $watch worked.
+            $rootScope.$apply();
+            expect(MetricsService.updateDigestMetrics).toHaveBeenCalled();
+        });
+
+        it("logsRouteChangeAsInformational", function () {
+            var MetricsService = $injector.get("MetricsService");
+            spyOn(MetricsService, 'info');
+            // Getting the actual route to change in a unit test is annoying,
+            // so we'll just call logRouteChange directly.
+            MetricsService.logRouteChange({}, {'templateUrl': 'test.html'});
+            expect(MetricsService.info).toHaveBeenCalled();
+        });
+
+        it("setsConfigDone", function () {
+            var MetricsService = $injector.get("MetricsService");
+            // This is called via run() on the MAAS module.
+            expect(MetricsService.metrics.configDone).toBeDefined();
+        });
+
+    });
+
+    describe("updateDigestMetrics", function() {
+        it("updatesOpenDigests", function() {
+            var $timeout = $injector.get("$timeout");
+            var MetricsService = $injector.get("MetricsService");
+            // Calling updateDigestMetrics() for the first time should queue
+            // an open $digest.
+            MetricsService.updateDigestMetrics();
+            expect(
+                MetricsService.metrics.openDigests.length).toBe(1);
+            // The $apply should queue another open $digest.
+            $rootScope.$apply();
+            expect(
+                MetricsService.metrics.openDigests.length).toBeGreaterThan(1);
+            // This should close all the open $digests.
+            $timeout.flush();
+            expect(MetricsService.metrics.openDigests.length).toEqual(0);
+        });
+    });
+});

=== modified file 'src/maasserver/views/combo.py'
--- src/maasserver/views/combo.py	2017-04-06 15:11:01 +0000
+++ src/maasserver/views/combo.py	2017-04-13 20:57:48 +0000
@@ -94,6 +94,7 @@
             "js/angular/services/converter.js",
             "js/angular/services/json.js",
             "js/angular/services/log.js",
+            "js/angular/services/metrics.js",
             "js/angular/directives/accordion.js",
             "js/angular/directives/boot_images.js",
             "js/angular/directives/call_to_action.js",