| 1 | package check |
| 2 | |
| 3 | import ( |
| 4 | "encoding/json" |
| 5 | "fmt" |
| 6 | "math" |
| 7 | "strings" |
| 8 | "testing" |
| 9 | |
| 10 | "amadan.net/rastrillo/fiesta" |
| 11 | ) |
| 12 | |
| 13 | // lightJS is js/light.js as the tree ships it. A tree without it is a |
| 14 | // broken build, not a condition to report, as fiesta.Script's own |
| 15 | // readers treat a missing file. |
| 16 | func lightJS() []byte { |
| 17 | js, ok := fiesta.Script("light.js") |
| 18 | if !ok { |
| 19 | panic("light.js is not shipped") |
| 20 | } |
| 21 | return js |
| 22 | } |
| 23 | |
| 24 | // light.js holds to the contract every scaffolded script does, with a |
| 25 | // 12 KiB cap of its own (select.js's precedent; the header comment is |
| 26 | // its contract and is a third of the file): the properties it writes, |
| 27 | // named; reduced motion and forced colours read as live queries; one |
| 28 | // frame loop; a WeakMap for the cards; the hour; the hook; and nothing |
| 29 | // it must never do. Startup order is behaviour, not text: |
| 30 | // TestReducedMotionIsTotal proves nothing is scheduled under reduce. |
| 31 | func TestLightContract(t *testing.T) { |
| 32 | js := string(lightJS()) |
| 33 | for _, want := range []string{ |
| 34 | "--rst-light-x", "--rst-light-y", "--rst-mx", "--rst-my", "--rst-px", "--rst-py", "--rst-card-x", "--rst-card-y", "--rst-card-lit", |
| 35 | `matchMedia("(prefers-reduced-motion: reduce)")`, `matchMedia("(forced-colors: active)")`, `.addEventListener("change"`, |
| 36 | "new WeakMap()", "requestAnimationFrame", "visibilitychange", "5 * 60 * 1000", "clearTimeout", |
| 37 | `"rst:light"`, "pointerType", "isConnected", `querySelectorAll('[style*="--rst-"]')`, |
| 38 | "var FOLLOW = ", |
| 39 | } { |
| 40 | if !strings.Contains(js, want) { |
| 41 | t.Errorf("light.js does not mention %q", want) |
| 42 | } |
| 43 | } |
| 44 | for _, bad := range []string{"setPointerCapture", "AmbientLightSensor", "deviceorientation", "touchstart", "rst-switch-track", "rst-switch-p", "rst-switch-on"} { |
| 45 | if strings.Contains(js, bad) { |
| 46 | t.Errorf("light.js mentions %q, which it must never do", bad) |
| 47 | } |
| 48 | } |
| 49 | if !strings.HasPrefix(strings.TrimSpace(js), "/*") || !strings.Contains(js, "(function () {") || !strings.HasSuffix(strings.TrimSpace(js), "})();") { |
| 50 | t.Error("light.js should be its contract comment and a single IIFE") |
| 51 | } |
| 52 | if strings.Contains(js, "eval(") || strings.Contains(js, "new Function") || strings.Contains(js, "\t") { |
| 53 | t.Error("light.js must stay CSP-clean and use two-space indentation") |
| 54 | } |
| 55 | if n := len(js); n > 12*1024 { |
| 56 | t.Fatalf("light.js is %d bytes; keep it readable in one sitting (12 KiB)", n) |
| 57 | } |
| 58 | } |
| 59 | |
| 60 | // traceWindow is what traceTotals reads from one marked window. |
| 61 | type traceWindow struct { |
| 62 | Thread float64 // the named events' thread (CPU) time, µs |
| 63 | Wall float64 // the same events' wall-clock time, µs, for the log |
| 64 | Counts map[string]int // the named events, by name |
| 65 | Sums map[string]float64 // their thread time by name, ms, for the log |
| 66 | Tasks int // RunTask slices on the page's main thread |
| 67 | Long int // of those, the ones over 50ms of thread time |
| 68 | } |
| 69 | |
| 70 | // longTaskUS is the long-task line, 50ms, applied to a task's thread |
| 71 | // time rather than its wall time. |
| 72 | const longTaskUS = 50000 |
| 73 | |
| 74 | // traceTotals sums the thread time of the named events that begin |
| 75 | // inside the window between two console.timeStamp() marks (TimeStamp |
| 76 | // events in devtools.timeline, on the trace's own clock): complete |
| 77 | // events ("X") by their tdur, and begin/end pairs ("B"/"E") by the |
| 78 | // difference of their tts. Thread time, not wall time, because wall |
| 79 | // time counts the moments the renderer waited for a CPU: on a fleet |
| 80 | // runner beside thirty other shards a 2.3ms frame read 6 to 12ms and a |
| 81 | // task of 2 to 11ms of work read 50 to 123ms, so the budget and the |
| 82 | // long-task rule failed on the machine's load, never the page's (#118). |
| 83 | // An event that carries no thread clock is an error rather than a |
| 84 | // zero, so a trace without one never passes as a cheap figure. |
| 85 | // |
| 86 | // The pairs are matched on a stack per thread (pid and tid), the way |
| 87 | // the trace nests them (a Layout inside an UpdateLayoutTree), and an |
| 88 | // "E" that carries no name closes whichever "B" is open on its thread. |
| 89 | // Inside the window the accounting has to close: a named "B" with no |
| 90 | // "E", an "E" with nothing open, or an "E" whose name is not the open |
| 91 | // "B"'s is an error rather than a smaller total, so an undercount never |
| 92 | // passes as a figure. Outside the window nothing is summed or checked: |
| 93 | // Tracing.end lands wherever it lands, and this Chromium reports |
| 94 | // whatever slice it cut as a lone "B". It also counts each name, so a |
| 95 | // trace that carried none of them fails rather than measuring nothing. |
| 96 | // A slice nested inside one of the same name is summed twice, which |
| 97 | // errs toward a larger figure. |
| 98 | // |
| 99 | // It also counts the RunTask slices ("X", disabled-by-default- |
| 100 | // devtools.timeline) that begin inside the window on the page's main |
| 101 | // thread, the one that carried the most named events, and the long |
| 102 | // ones among them by thread time: a task that did 50ms of work is a |
| 103 | // long task on any machine, and one that only waited is not. |
| 104 | func traceTotals(events []json.RawMessage, from, to string, names ...string) (w traceWindow, err error) { |
| 105 | type event struct { |
| 106 | Name string `json:"name"` |
| 107 | Ph string `json:"ph"` |
| 108 | Dur float64 `json:"dur"` |
| 109 | Tdur *float64 `json:"tdur"` |
| 110 | Ts float64 `json:"ts"` |
| 111 | Tts *float64 `json:"tts"` |
| 112 | Pid json.RawMessage `json:"pid"` |
| 113 | Tid json.RawMessage `json:"tid"` |
| 114 | Args struct { |
| 115 | Data struct { |
| 116 | Message string `json:"message"` |
| 117 | } `json:"data"` |
| 118 | } `json:"args"` |
| 119 | } |
| 120 | var evs []event |
| 121 | marks := map[string]float64{} |
| 122 | for _, raw := range events { |
| 123 | var e event |
| 124 | if json.Unmarshal(raw, &e) != nil { |
| 125 | continue |
| 126 | } |
| 127 | evs = append(evs, e) |
| 128 | if e.Name == "TimeStamp" { |
| 129 | marks[e.Args.Data.Message] = e.Ts |
| 130 | } |
| 131 | } |
| 132 | lo, hi := marks[from], marks[to] |
| 133 | if lo == 0 || hi == 0 || hi <= lo { |
| 134 | return w, fmt.Errorf("the trace carries no window %q..%q (marks %v)", from, to, marks) |
| 135 | } |
| 136 | inside := func(ts float64) bool { return ts >= lo && ts <= hi } |
| 137 | want := map[string]bool{} |
| 138 | for _, n := range names { |
| 139 | want[n] = true |
| 140 | } |
| 141 | w.Counts, w.Sums = map[string]int{}, map[string]float64{} |
| 142 | perThread := map[string]int{} |
| 143 | add := func(name, thread string, wall, cpu float64) { |
| 144 | w.Wall += wall |
| 145 | w.Thread += cpu |
| 146 | w.Counts[name]++ |
| 147 | w.Sums[name] += cpu / 1000 |
| 148 | perThread[thread]++ |
| 149 | } |
| 150 | type span struct { |
| 151 | name string |
| 152 | ts float64 |
| 153 | tts *float64 |
| 154 | } |
| 155 | open := map[string][]span{} |
| 156 | for _, e := range evs { |
| 157 | thread := string(e.Pid) + "/" + string(e.Tid) |
| 158 | switch e.Ph { |
| 159 | case "X": |
| 160 | if want[e.Name] && inside(e.Ts) { |
| 161 | if e.Tdur == nil { |
| 162 | return w, fmt.Errorf("an X event %q at %v on thread %s carries no tdur, so its thread time is unknown", e.Name, e.Ts, thread) |
| 163 | } |
| 164 | add(e.Name, thread, e.Dur, *e.Tdur) |
| 165 | } |
| 166 | case "B": |
| 167 | open[thread] = append(open[thread], span{e.Name, e.Ts, e.Tts}) |
| 168 | case "E": |
| 169 | n := len(open[thread]) |
| 170 | if n == 0 { |
| 171 | if inside(e.Ts) && (e.Name == "" || want[e.Name]) { |
| 172 | return w, fmt.Errorf("an E event %q at %v on thread %s has no B", e.Name, e.Ts, thread) |
| 173 | } |
| 174 | continue |
| 175 | } |
| 176 | top := open[thread][n-1] |
| 177 | if e.Name != "" && e.Name != top.name { |
| 178 | if inside(e.Ts) { |
| 179 | return w, fmt.Errorf("an E event %q at %v on thread %s closes a B named %q", e.Name, e.Ts, thread, top.name) |
| 180 | } |
| 181 | continue |
| 182 | } |
| 183 | open[thread] = open[thread][:n-1] |
| 184 | if want[top.name] && inside(top.ts) { |
| 185 | if top.tts == nil || e.Tts == nil { |
| 186 | return w, fmt.Errorf("a %q pair at %v on thread %s carries no tts, so its thread time is unknown", top.name, top.ts, thread) |
| 187 | } |
| 188 | add(top.name, thread, e.Ts-top.ts, *e.Tts-*top.tts) |
| 189 | } |
| 190 | } |
| 191 | } |
| 192 | for thread, spans := range open { |
| 193 | for _, s := range spans { |
| 194 | if want[s.name] && inside(s.ts) { |
| 195 | return w, fmt.Errorf("a B event %q at %v on thread %s has no E", s.name, s.ts, thread) |
| 196 | } |
| 197 | } |
| 198 | } |
| 199 | for n, ms := range w.Sums { |
| 200 | w.Sums[n] = math.Round(ms*10) / 10 |
| 201 | } |
| 202 | main, most := "", 0 |
| 203 | for thread, n := range perThread { |
| 204 | if n > most { |
| 205 | main, most = thread, n |
| 206 | } |
| 207 | } |
| 208 | for _, e := range evs { |
| 209 | if e.Ph != "X" || e.Name != "RunTask" || !inside(e.Ts) || string(e.Pid)+"/"+string(e.Tid) != main { |
| 210 | continue |
| 211 | } |
| 212 | if e.Tdur == nil { |
| 213 | return w, fmt.Errorf("a RunTask at %v on the main thread carries no tdur, so a long task would go unseen", e.Ts) |
| 214 | } |
| 215 | w.Tasks++ |
| 216 | if *e.Tdur > longTaskUS { |
| 217 | w.Long++ |
| 218 | } |
| 219 | } |
| 220 | return w, nil |
| 221 | } |
| 222 | |
| 223 | // TestTraceTotalsAccounting holds traceTotals to its rules on synthetic |
| 224 | // events, since the real traces only ever show it one shape: two |
| 225 | // threads interleaved, an unnamed E, a lone B inside the window and |
| 226 | // one outside it, a mismatched E, an orphan E, a missing mark, an event |
| 227 | // with no thread clock, and tasks that waited against tasks that worked. |
| 228 | func TestTraceTotalsAccounting(t *testing.T) { |
| 229 | ev := func(items ...string) []json.RawMessage { |
| 230 | var out []json.RawMessage |
| 231 | for _, s := range items { |
| 232 | out = append(out, json.RawMessage(s)) |
| 233 | } |
| 234 | return out |
| 235 | } |
| 236 | mark := func(name string, ts float64) string { |
| 237 | return fmt.Sprintf(`{"name":"TimeStamp","ph":"I","ts":%v,"pid":1,"tid":1,"args":{"data":{"message":%q}}}`, ts, name) |
| 238 | } |
| 239 | marks := []string{mark("a", 1000), mark("b", 2000)} |
| 240 | ok := append(marks, |
| 241 | `{"name":"Paint","ph":"X","ts":1100,"dur":300,"tdur":200,"pid":1,"tid":1}`, |
| 242 | `{"name":"Paint","ph":"X","ts":900,"dur":300,"pid":1,"tid":1}`, |
| 243 | `{"name":"Layout","ph":"B","ts":1200,"tts":50,"pid":1,"tid":1}`, |
| 244 | `{"name":"Layout","ph":"B","ts":1210,"tts":500,"pid":1,"tid":2}`, |
| 245 | `{"name":"","ph":"E","ts":1250,"tts":530,"pid":1,"tid":2}`, |
| 246 | `{"name":"Layout","ph":"E","ts":1300,"tts":110,"pid":1,"tid":1}`, |
| 247 | `{"name":"Other","ph":"B","ts":1400,"pid":1,"tid":1}`, |
| 248 | `{"name":"","ph":"E","ts":1500,"pid":1,"tid":1}`, |
| 249 | `{"name":"Layout","ph":"B","ts":2100,"pid":1,"tid":1}`, |
| 250 | `{"name":"Paint","ph":"E","ts":800,"pid":1,"tid":3}`, |
| 251 | // Tasks: on the main thread (tid 1, two named events) one that |
| 252 | // waited 120ms but worked 9, one that worked 60, one outside the |
| 253 | // window; on tid 2 a long one that is not the page's. |
| 254 | `{"name":"RunTask","ph":"X","ts":1050,"dur":120000,"tdur":9000,"pid":1,"tid":1}`, |
| 255 | `{"name":"RunTask","ph":"X","ts":1600,"dur":61000,"tdur":60000,"pid":1,"tid":1}`, |
| 256 | `{"name":"RunTask","ph":"X","ts":2500,"dur":90000,"tdur":90000,"pid":1,"tid":1}`, |
| 257 | `{"name":"RunTask","ph":"X","ts":1700,"dur":90000,"tdur":90000,"pid":1,"tid":2}`, |
| 258 | ) |
| 259 | w, err := traceTotals(ev(ok...), "a", "b", "Paint", "Layout") |
| 260 | if err != nil { |
| 261 | t.Fatalf("a closed window errored: %v", err) |
| 262 | } |
| 263 | if w.Thread != 290 || w.Wall != 440 || w.Counts["Paint"] != 1 || w.Counts["Layout"] != 2 || w.Sums["Layout"] != 0.1 { |
| 264 | t.Errorf("thread %v wall %v counts %v sums %v; want thread 290 (a Paint of 200 inside the window, Layouts of 60 and 30 on two threads), wall 440, Paint 1, Layout 2, Layout 0.1ms", w.Thread, w.Wall, w.Counts, w.Sums) |
| 265 | } |
| 266 | if w.Tasks != 2 || w.Long != 1 { |
| 267 | t.Errorf("tasks %d, long %d; want 2 tasks on the main thread inside the window, 1 long by thread time (the 120ms wait that worked 9ms is not)", w.Tasks, w.Long) |
| 268 | } |
| 269 | for name, bad := range map[string][]string{ |
| 270 | "a lone B inside the window": append(marks, `{"name":"Layout","ph":"B","ts":1500,"pid":1,"tid":1}`), |
| 271 | "an orphan named E inside": append(marks, `{"name":"Layout","ph":"E","ts":1500,"pid":1,"tid":1}`), |
| 272 | "an orphan unnamed E inside": append(marks, `{"name":"","ph":"E","ts":1500,"pid":1,"tid":1}`), |
| 273 | "a mismatched E inside": append(marks, `{"name":"Other","ph":"B","ts":1400,"pid":1,"tid":1}`, `{"name":"Layout","ph":"E","ts":1500,"pid":1,"tid":1}`), |
| 274 | "no end mark": {mark("a", 1000)}, |
| 275 | "an X with no thread clock": append(marks, `{"name":"Paint","ph":"X","ts":1100,"dur":300,"pid":1,"tid":1}`), |
| 276 | "a pair with no thread clock": append(marks, `{"name":"Layout","ph":"B","ts":1200,"pid":1,"tid":1}`, `{"name":"Layout","ph":"E","ts":1300,"pid":1,"tid":1}`), |
| 277 | "a main-thread task with no thread clock": append(marks, `{"name":"Paint","ph":"X","ts":1100,"dur":300,"tdur":200,"pid":1,"tid":1}`, |
| 278 | `{"name":"RunTask","ph":"X","ts":1050,"dur":120000,"pid":1,"tid":1}`), |
| 279 | } { |
| 280 | if _, err := traceTotals(ev(bad...), "a", "b", "Paint", "Layout"); err == nil { |
| 281 | t.Errorf("%s: no error; the figure would undercount", name) |
| 282 | } |
| 283 | } |
| 284 | } |
| 285 | |
| 286 | // budgetWindow is one measured window of TestTheLightStaysWithinItsFrameBudget: |
| 287 | // a page, its style+layout+paint per frame, and the trace's counts. |
| 288 | type budgetWindow struct { |
| 289 | path string |
| 290 | perFrame float64 |
| 291 | frames int |
| 292 | counts map[string]int |
| 293 | } |
| 294 | |
| 295 | // cheapestWindows measures the bare page and the lit page in turn, |
| 296 | // tries times each, and returns each side's cheapest window, the way a |
| 297 | // benchmark reports its best run. Every window is taken before the two |
| 298 | // minima are compared: the absolute drive stopped at the first window |
| 299 | // within budget, and for a difference that is unsafe, because load |
| 300 | // that inflates a bare window makes the subtraction pass more easily |
| 301 | // (from rastrillo's day follow-ups review). |
| 302 | func cheapestWindows(measure func(path string) budgetWindow, tries int) (with, without budgetWindow) { |
| 303 | sides := map[string]*budgetWindow{} |
| 304 | for try := 1; try <= tries; try++ { |
| 305 | for _, path := range []string{"/bare", "/"} { |
| 306 | w := measure(path) |
| 307 | if b := sides[path]; b == nil || w.perFrame < b.perFrame { |
| 308 | sides[path] = &w |
| 309 | } |
| 310 | } |
| 311 | } |
| 312 | return *sides["/"], *sides["/bare"] |
| 313 | } |
| 314 | |
| 315 | // TestCheapestWindowsTakeEveryWindow: |
| 316 | // load that inflates a bare window makes a subtraction pass more |
| 317 | // easily, so a selection that stops at the first pair within budget |
| 318 | // accepts 3.2 minus an inflated 2.0 where the cheapest windows say 3.2 |
| 319 | // minus 0.8. Every window of both sides is measured before the minima |
| 320 | // are compared. |
| 321 | func TestCheapestWindowsTakeEveryWindow(t *testing.T) { |
| 322 | seq := []budgetWindow{{path: "/bare", perFrame: 2.0}, {path: "/", perFrame: 3.2}, {path: "/bare", perFrame: 0.8}, {path: "/", perFrame: 3.3}, {path: "/bare", perFrame: 0.85}, {path: "/", perFrame: 3.25}} |
| 323 | i := 0 |
| 324 | measure := func(path string) budgetWindow { |
| 325 | if i >= len(seq) { |
| 326 | t.Fatalf("a %dth window was asked for; the sequence has %d", i+1, len(seq)) |
| 327 | } |
| 328 | w := seq[i] |
| 329 | if w.path != path { |
| 330 | t.Fatalf("window %d is for %s, want %s: the sides are not interleaved bare, lit", i+1, path, w.path) |
| 331 | } |
| 332 | i++ |
| 333 | return w |
| 334 | } |
| 335 | with, without := cheapestWindows(measure, 3) |
| 336 | if i != len(seq) { |
| 337 | t.Errorf("%d of %d windows were measured; a selection that stops early accepts an inflated baseline", i, len(seq)) |
| 338 | } |
| 339 | if delta := with.perFrame - without.perFrame; with.perFrame != 3.2 || without.perFrame != 0.8 || math.Abs(delta-2.4) > 1e-9 { |
| 340 | t.Errorf("cheapest windows %.2f with and %.2f without, a difference of %.2f; want 3.20 and 0.80, 2.40", with.perFrame, without.perFrame, delta) |
| 341 | } |
| 342 | } |
| 343 | |
amadan