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

Proposed by Mike Pontillo
Status: Rejected
Rejected by: MAAS Lander
Proposed branch: lp:~mpontillo/maas/js-metrics-service
Merge into: lp:~maas-committers/maas/trunk
Diff against target: 200 lines (+169/-0)
4 files modified
src/maasserver/static/js/angular/maas.js (+6/-0)
src/maasserver/static/js/angular/services/metrics.js (+94/-0)
src/maasserver/static/js/angular/services/tests/test_metrics.js (+68/-0)
src/maasserver/views/combo.py (+1/-0)
To merge this branch: bzr merge lp:~mpontillo/maas/js-metrics-service
Reviewer Review Type Date Requested Status
Blake Rouse (community) Needs Fixing
Review via email: mp+322495@code.launchpad.net

Commit message

Add JavaScript logging for $digest metrics and $routeChangeSuccess.

Description of the change

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.

To post a comment you must log in.
Revision history for this message
Blake Rouse (blake-rouse) wrote :

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
Revision history for this message
Mike Pontillo (mpontillo) wrote :

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.

Revision history for this message
Blake Rouse (blake-rouse) wrote :

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

Revision history for this message
Mike Pontillo (mpontillo) wrote :

Good idea. I'll check into it.

Revision history for this message
MAAS Lander (maas-lander) wrote :

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

Merge trunk.

5958. By Mike Pontillo

Add metrics service.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
=== 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 @@
158 }158 }
159 });159 });
160160
161// Make sure the MetricsService is created for every run, so we can get
162// accurate numbers.
163angular.module('MAAS').run(['MetricsService', function (MetricsService) {
164 MetricsService.setConfigDone();
165}]);
166
161// Force users to #/intro when it has not been completed.167// Force users to #/intro when it has not been completed.
162angular.module('MAAS').run(['$rootScope', '$location',168angular.module('MAAS').run(['$rootScope', '$location',
163 function ($rootScope, $location) {169 function ($rootScope, $location) {
164170
=== 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 @@
1/* Copyright 2017 Canonical Ltd. This software is licensed under the
2 * GNU Affero General Public License version 3 (see the file LICENSE).
3 *
4 * Metrics Service
5 *
6 * Records and logs metrics about various events. Currently, that includes:
7 * - The $digest lifecycle.
8 * - Any route changes (navigations).
9 */
10
11angular.module('MAAS').service('MetricsService', [
12 '$rootScope', '$window', '$timeout', 'LogService', function(
13 $rootScope, $window, $timeout, LogService) {
14
15 var self = this;
16
17 self.metrics = {};
18
19 // Initial metric values.
20 self.metrics.digestCount = 0;
21 self.metrics.openDigests = [];
22 self.metrics.digestCycles = 0;
23
24 this.info = LogService.info;
25 this.debug = LogService.debug;
26
27 this.formatMilliseconds = LogService.formatMilliseconds;
28
29 // Returns a monotonic time in milliseconds.
30 this.now = function() {
31 return LogService.now();
32 };
33
34 // Returns the current URL string.
35 this.location = function() {
36 return $window.location;
37 };
38
39 // Called when the MAAS module starts running, to record the time it
40 // took to initialize.
41 this.setConfigDone = function() {
42 self.metrics.configDone = self.now();
43 };
44
45 // Called from $rootScope on $digest every $watch cycle.
46 this.updateDigestMetrics = function() {
47 var now = self.now();
48 var digestCount = ++self.metrics.digestCount;
49 // Keep a stack of "open" $digest calls. A $digest cycle is
50 // considered done after Angular has a chance to process all the
51 // timeouts generated by each call to $digest.
52 self.metrics.openDigests.push({'time': now, 'count': digestCount});
53 self.metrics.lastDigest = now;
54 // Since we're interested in how long $digest cycles are taking,
55 // ask Angular to call us back at its earliest convenience.
56 // The result is that if multiple $digest calls kick off in
57 // succession, the last $timeout will be called after they are
58 // *all*, complete, which allows us to calculate a rough estimate
59 // of how long the complete cycle took.
60 $timeout(function() {
61 var digest = self.metrics.openDigests.pop();
62 // If we've popped the last $digest call off the stack, that
63 // means we're done with a complete cycle.
64 if(self.metrics.openDigests.length == 0) {
65 var cycles = ++self.metrics.digestCycles;
66 var finished = self.now();
67 var started = digest.time;
68 var duration = finished - started;
69 var startCount = digest.count;
70 var finishCount = self.metrics.digestCount;
71 var count = finishCount - startCount + 1;
72 var countMessage = (count == 1) ?
73 count + " digest" : count + " digests";
74 var seconds = self.formatMilliseconds(duration);
75 self.debug("$digest cycle " + cycles + ": " +
76 countMessage + " completed in ~" +
77 seconds + " seconds.");
78 }
79 }, 0, false);
80 };
81
82 this.logRouteChange = function(event, current, previous) {
83 var currentLocation = self.location();
84 self.info(
85 "$routeChangeSuccess: " + currentLocation +
86 "; templateURL=" + current.templateUrl);
87 };
88
89 // Add the MetricsService to the $rootScope so that $watch works.
90 $rootScope.MetricsService = this;
91 $rootScope.$watch('MetricsService.updateDigestMetrics()');
92 $rootScope.$on("$routeChangeSuccess", this.logRouteChange);
93}]);
94
095
=== 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 @@
1/* Copyright 2015 Canonical Ltd. This software is licensed under the
2 * GNU Affero General Public License version 3 (see the file LICENSE).
3 *
4 * Unit tests for MetricsService.
5 */
6
7describe("MetricsService", function() {
8
9 // Load the MAAS module.
10 beforeEach(module("MAAS"));
11
12 // Get the $injector so the test can grab the MetricsService.
13 var $injector;
14 var $rootScope;
15 beforeEach(inject(function(_$injector_) {
16 $injector = _$injector_;
17 $rootScope = $injector.get("$rootScope");
18 }));
19
20 describe("init", function() {
21 // Note: we can't use spyOn() here to check if $watch and/or $on were
22 // called, since the init happens too early for that.
23
24 it("addsWorkingWatchToRootScope", function () {
25 var MetricsService = $injector.get("MetricsService");
26 expect($rootScope.MetricsService).toBe(MetricsService);
27 spyOn(MetricsService, 'updateDigestMetrics');
28 // Check if the $watch worked.
29 $rootScope.$apply();
30 expect(MetricsService.updateDigestMetrics).toHaveBeenCalled();
31 });
32
33 it("logsRouteChangeAsInformational", function () {
34 var MetricsService = $injector.get("MetricsService");
35 spyOn(MetricsService, 'info');
36 // Getting the actual route to change in a unit test is annoying,
37 // so we'll just call logRouteChange directly.
38 MetricsService.logRouteChange({}, {'templateUrl': 'test.html'});
39 expect(MetricsService.info).toHaveBeenCalled();
40 });
41
42 it("setsConfigDone", function () {
43 var MetricsService = $injector.get("MetricsService");
44 // This is called via run() on the MAAS module.
45 expect(MetricsService.metrics.configDone).toBeDefined();
46 });
47
48 });
49
50 describe("updateDigestMetrics", function() {
51 it("updatesOpenDigests", function() {
52 var $timeout = $injector.get("$timeout");
53 var MetricsService = $injector.get("MetricsService");
54 // Calling updateDigestMetrics() for the first time should queue
55 // an open $digest.
56 MetricsService.updateDigestMetrics();
57 expect(
58 MetricsService.metrics.openDigests.length).toBe(1);
59 // The $apply should queue another open $digest.
60 $rootScope.$apply();
61 expect(
62 MetricsService.metrics.openDigests.length).toBeGreaterThan(1);
63 // This should close all the open $digests.
64 $timeout.flush();
65 expect(MetricsService.metrics.openDigests.length).toEqual(0);
66 });
67 });
68});
069
=== 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 @@
94 "js/angular/services/converter.js",94 "js/angular/services/converter.js",
95 "js/angular/services/json.js",95 "js/angular/services/json.js",
96 "js/angular/services/log.js",96 "js/angular/services/log.js",
97 "js/angular/services/metrics.js",
97 "js/angular/directives/accordion.js",98 "js/angular/directives/accordion.js",
98 "js/angular/directives/boot_images.js",99 "js/angular/directives/boot_images.js",
99 "js/angular/directives/call_to_action.js",100 "js/angular/directives/call_to_action.js",