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

Proposed by Mike Pontillo
Status: Rejected
Rejected by: MAAS Lander
Proposed branch: lp:~mpontillo/maas/js-metrics-service
Merge into: lp: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.
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
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.

Blake Rouse (blake-rouse) wrote :

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

Mike Pontillo (mpontillo) wrote :

Good idea. I'll check into it.

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 on 2017-04-13

Merge trunk.

5958. By Mike Pontillo on 2017-04-13

Add metrics service.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'src/maasserver/static/js/angular/maas.js'
2--- src/maasserver/static/js/angular/maas.js 2017-03-10 18:38:46 +0000
3+++ src/maasserver/static/js/angular/maas.js 2017-04-13 20:57:48 +0000
4@@ -158,6 +158,12 @@
5 }
6 });
7
8+// Make sure the MetricsService is created for every run, so we can get
9+// accurate numbers.
10+angular.module('MAAS').run(['MetricsService', function (MetricsService) {
11+ MetricsService.setConfigDone();
12+}]);
13+
14 // Force users to #/intro when it has not been completed.
15 angular.module('MAAS').run(['$rootScope', '$location',
16 function ($rootScope, $location) {
17
18=== added file 'src/maasserver/static/js/angular/services/metrics.js'
19--- src/maasserver/static/js/angular/services/metrics.js 1970-01-01 00:00:00 +0000
20+++ src/maasserver/static/js/angular/services/metrics.js 2017-04-13 20:57:48 +0000
21@@ -0,0 +1,94 @@
22+/* Copyright 2017 Canonical Ltd. This software is licensed under the
23+ * GNU Affero General Public License version 3 (see the file LICENSE).
24+ *
25+ * Metrics Service
26+ *
27+ * Records and logs metrics about various events. Currently, that includes:
28+ * - The $digest lifecycle.
29+ * - Any route changes (navigations).
30+ */
31+
32+angular.module('MAAS').service('MetricsService', [
33+ '$rootScope', '$window', '$timeout', 'LogService', function(
34+ $rootScope, $window, $timeout, LogService) {
35+
36+ var self = this;
37+
38+ self.metrics = {};
39+
40+ // Initial metric values.
41+ self.metrics.digestCount = 0;
42+ self.metrics.openDigests = [];
43+ self.metrics.digestCycles = 0;
44+
45+ this.info = LogService.info;
46+ this.debug = LogService.debug;
47+
48+ this.formatMilliseconds = LogService.formatMilliseconds;
49+
50+ // Returns a monotonic time in milliseconds.
51+ this.now = function() {
52+ return LogService.now();
53+ };
54+
55+ // Returns the current URL string.
56+ this.location = function() {
57+ return $window.location;
58+ };
59+
60+ // Called when the MAAS module starts running, to record the time it
61+ // took to initialize.
62+ this.setConfigDone = function() {
63+ self.metrics.configDone = self.now();
64+ };
65+
66+ // Called from $rootScope on $digest every $watch cycle.
67+ this.updateDigestMetrics = function() {
68+ var now = self.now();
69+ var digestCount = ++self.metrics.digestCount;
70+ // Keep a stack of "open" $digest calls. A $digest cycle is
71+ // considered done after Angular has a chance to process all the
72+ // timeouts generated by each call to $digest.
73+ self.metrics.openDigests.push({'time': now, 'count': digestCount});
74+ self.metrics.lastDigest = now;
75+ // Since we're interested in how long $digest cycles are taking,
76+ // ask Angular to call us back at its earliest convenience.
77+ // The result is that if multiple $digest calls kick off in
78+ // succession, the last $timeout will be called after they are
79+ // *all*, complete, which allows us to calculate a rough estimate
80+ // of how long the complete cycle took.
81+ $timeout(function() {
82+ var digest = self.metrics.openDigests.pop();
83+ // If we've popped the last $digest call off the stack, that
84+ // means we're done with a complete cycle.
85+ if(self.metrics.openDigests.length == 0) {
86+ var cycles = ++self.metrics.digestCycles;
87+ var finished = self.now();
88+ var started = digest.time;
89+ var duration = finished - started;
90+ var startCount = digest.count;
91+ var finishCount = self.metrics.digestCount;
92+ var count = finishCount - startCount + 1;
93+ var countMessage = (count == 1) ?
94+ count + " digest" : count + " digests";
95+ var seconds = self.formatMilliseconds(duration);
96+ self.debug("$digest cycle " + cycles + ": " +
97+ countMessage + " completed in ~" +
98+ seconds + " seconds.");
99+ }
100+ }, 0, false);
101+ };
102+
103+ this.logRouteChange = function(event, current, previous) {
104+ var currentLocation = self.location();
105+ self.info(
106+ "$routeChangeSuccess: " + currentLocation +
107+ "; templateURL=" + current.templateUrl);
108+ };
109+
110+ // Add the MetricsService to the $rootScope so that $watch works.
111+ $rootScope.MetricsService = this;
112+ $rootScope.$watch('MetricsService.updateDigestMetrics()');
113+ $rootScope.$on("$routeChangeSuccess", this.logRouteChange);
114+}]);
115+
116
117=== added file 'src/maasserver/static/js/angular/services/tests/test_metrics.js'
118--- src/maasserver/static/js/angular/services/tests/test_metrics.js 1970-01-01 00:00:00 +0000
119+++ src/maasserver/static/js/angular/services/tests/test_metrics.js 2017-04-13 20:57:48 +0000
120@@ -0,0 +1,68 @@
121+/* Copyright 2015 Canonical Ltd. This software is licensed under the
122+ * GNU Affero General Public License version 3 (see the file LICENSE).
123+ *
124+ * Unit tests for MetricsService.
125+ */
126+
127+describe("MetricsService", function() {
128+
129+ // Load the MAAS module.
130+ beforeEach(module("MAAS"));
131+
132+ // Get the $injector so the test can grab the MetricsService.
133+ var $injector;
134+ var $rootScope;
135+ beforeEach(inject(function(_$injector_) {
136+ $injector = _$injector_;
137+ $rootScope = $injector.get("$rootScope");
138+ }));
139+
140+ describe("init", function() {
141+ // Note: we can't use spyOn() here to check if $watch and/or $on were
142+ // called, since the init happens too early for that.
143+
144+ it("addsWorkingWatchToRootScope", function () {
145+ var MetricsService = $injector.get("MetricsService");
146+ expect($rootScope.MetricsService).toBe(MetricsService);
147+ spyOn(MetricsService, 'updateDigestMetrics');
148+ // Check if the $watch worked.
149+ $rootScope.$apply();
150+ expect(MetricsService.updateDigestMetrics).toHaveBeenCalled();
151+ });
152+
153+ it("logsRouteChangeAsInformational", function () {
154+ var MetricsService = $injector.get("MetricsService");
155+ spyOn(MetricsService, 'info');
156+ // Getting the actual route to change in a unit test is annoying,
157+ // so we'll just call logRouteChange directly.
158+ MetricsService.logRouteChange({}, {'templateUrl': 'test.html'});
159+ expect(MetricsService.info).toHaveBeenCalled();
160+ });
161+
162+ it("setsConfigDone", function () {
163+ var MetricsService = $injector.get("MetricsService");
164+ // This is called via run() on the MAAS module.
165+ expect(MetricsService.metrics.configDone).toBeDefined();
166+ });
167+
168+ });
169+
170+ describe("updateDigestMetrics", function() {
171+ it("updatesOpenDigests", function() {
172+ var $timeout = $injector.get("$timeout");
173+ var MetricsService = $injector.get("MetricsService");
174+ // Calling updateDigestMetrics() for the first time should queue
175+ // an open $digest.
176+ MetricsService.updateDigestMetrics();
177+ expect(
178+ MetricsService.metrics.openDigests.length).toBe(1);
179+ // The $apply should queue another open $digest.
180+ $rootScope.$apply();
181+ expect(
182+ MetricsService.metrics.openDigests.length).toBeGreaterThan(1);
183+ // This should close all the open $digests.
184+ $timeout.flush();
185+ expect(MetricsService.metrics.openDigests.length).toEqual(0);
186+ });
187+ });
188+});
189
190=== modified file 'src/maasserver/views/combo.py'
191--- src/maasserver/views/combo.py 2017-04-06 15:11:01 +0000
192+++ src/maasserver/views/combo.py 2017-04-13 20:57:48 +0000
193@@ -94,6 +94,7 @@
194 "js/angular/services/converter.js",
195 "js/angular/services/json.js",
196 "js/angular/services/log.js",
197+ "js/angular/services/metrics.js",
198 "js/angular/directives/accordion.js",
199 "js/angular/directives/boot_images.js",
200 "js/angular/directives/call_to_action.js",