1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
|
/* Any copyright is dedicated to the Public Domain.
* http://creativecommons.org/publicdomain/zero/1.0/ */
/* eslint-disable mozilla/no-arbitrary-setTimeout */
"use strict";
// Test that the Shutdown Terminator records durations correctly
const { setTimeout } = ChromeUtils.importESModule(
"resource://gre/modules/Timer.sys.mjs"
);
var PATH;
var PATH_TMP;
var terminator;
var HEARTBEAT_MS = 100;
let KEYS = [
"quit-application",
"profile-change-net-teardown",
"profile-change-teardown",
"profile-before-change",
"profile-before-change-qm",
"xpcom-will-shutdown",
"xpcom-shutdown",
"xpcom-shutdown-threads",
"XPCOMShutdownFinal",
"CCPostLastCycleCollection",
];
let DATA = [];
let MeasuredDurations = [];
add_task(async function init() {
do_get_profile();
PATH = PathUtils.join(PathUtils.localProfileDir, "ShutdownDuration.json");
PATH_TMP = PATH + ".tmp";
// Initialize the terminator
// (normally, this is done through the manifest file, but xpcshell
// doesn't take them into account).
info("Initializing the Terminator");
terminator = Cc["@mozilla.org/toolkit/shutdown-terminator;1"].createInstance(
Ci.nsIObserver
);
});
var promiseShutdownDurationData = async function () {
// Wait until PATH exists.
// Timeout if it is never created.
while (true) {
if (await IOUtils.exists(PATH)) {
break;
}
// Wait just a very short period to not increase measured values.
// Usually the file should appear almost immediately.
await new Promise(resolve => setTimeout(resolve, 50));
}
return IOUtils.readJSON(PATH);
};
var currentPhase = 0;
var advancePhase = async function () {
let key = "terminator-test-" + KEYS[currentPhase];
let msDuration = 200 + HEARTBEAT_MS * currentPhase;
info("Advancing shutdown phase to " + KEYS[currentPhase]);
terminator.observe(null, key, null);
await new Promise(resolve => setTimeout(resolve, msDuration));
let data = await promiseShutdownDurationData();
Assert.ok(KEYS[currentPhase] in data, "The file contains the expected key");
Assert.equal(
Object.keys(data).length,
currentPhase + 1,
"File does not contain more durations than expected"
);
DATA[currentPhase] = data;
currentPhase++;
if (currentPhase < KEYS.length) {
return true;
}
return false;
};
// This is a timing affected test, as we want to check if the time measurements
// from the terminator are reasonable. Bug 1768795 assumes that they tend to
// be lower than wall-clock, in particular on MacOS, confirmed by the logs on
// intermittent bug 1760094. This is not a big deal for the terminator's
// general functionality (timeouts might just come a little later than
// expected nominally), but it makes testing harder and the transferred
// telemetry data slightly less reliable (shutdowns might appear shorter than
// they really were). So this test is just happy if there is any data that
// is not too long wrt what we expect. If we ever want to fix bug 1768795,
// we can check for a more reasonable lower boundary, too.
add_task(async function test_record() {
info("Collecting duration data for all known phases");
let morePhases = true;
while (morePhases) {
let beforeWait = Date.now();
morePhases = await advancePhase();
await IOUtils.remove(PATH);
await IOUtils.remove(PATH_TMP);
// We measure the effective time that passed as wall-clock and include all
// file IO overhead as the terminator will do so in its measurement, too.
MeasuredDurations[currentPhase - 1] = Math.floor(
(Date.now() - beforeWait) / HEARTBEAT_MS
);
}
Assert.equal(DATA.length, KEYS.length, "We have data for each phase");
for (let i = 0; i < KEYS.length; i++) {
let lastDuration = DATA[KEYS.length - 1][KEYS[i]];
Assert.equal(
typeof lastDuration,
"number",
"Duration of phase " + i + ":" + KEYS[i] + " is a number"
);
// The durations are only meaningful after we advanced to the next phase.
if (i < KEYS.length - 1) {
// So we read it from the data written for the following phase.
let ticksDuration = DATA[i + 1][KEYS[i]];
let measuredDuration = MeasuredDurations[i];
info(
"measuredDuration:" + measuredDuration + " - " + typeof measuredDuration
);
Assert.lessOrEqual(
ticksDuration,
measuredDuration + 2,
"Duration of phase " + i + ":" + KEYS[i] + " is not too long"
);
Assert.greaterOrEqual(
ticksDuration,
0, // TODO: Raise the lower boundary after bug 1768795.
"Duration of phase " + i + ":" + KEYS[i] + " is not too short"
);
}
// This check is done only for phases <= xpcom-shutdown-threads
// where we have two data points.
if (i < KEYS.length - 2) {
let ticksDuration = DATA[i + 1][KEYS[i]];
Assert.equal(
ticksDuration,
DATA[KEYS.length - 1][KEYS[i]],
"Duration of phase " + i + ":" + KEYS[i] + " hasn't changed"
);
}
}
// Note that after this check the KEYS array remains sorted, so this
// must be the last check to not get confused.
Assert.equal(
Object.keys(DATA[KEYS.length - 1])
.sort()
.join(", "),
KEYS.sort().join(", "),
"The last file contains all expected keys"
);
});
|
