Time Profiling

    Familiarize yourself with the available tools for time profiling Rust andWebAssembly code before continuing.

    This FPS timer will be useful as we investigate speeding up our Game of Life'srendering.

    We start by adding an object to wasm-game-of-life/www/index.js:

    Next we call the fps render function on each iteration of renderLoop:

    1. const renderLoop = () => {
    2.     fps.render(); //new
    4.     universe.tick();
    5.     drawGrid();
    6.     drawCells();
    8.     animationId = requestAnimationFrame(renderLoop);
    9. };

    Finally, don't forget to add the fps element towasm-game-of-life/www/index.html, just above the <canvas>:

    1. <div id="fps"></div>

    And add CSS to make its formatting nice:

    1. #fps {
    2.   white-space: pre;
    3.   font-family: monospace;
    4. }

    And voila! Refresh and now wehave an FPS counter!

    To measure how long each invocation of Universe::tick takes, we can useconsole.time and console.timeEnd via the web-sys crate.

    First, add web-sys as a dependency to wasm-game-of-life/Cargo.toml:

    1. [dependencies.web-sys]
    2. version = "0.3"
    3. features = [
    4.   "console",
    5. ]

    Because there should be a corresponding console.timeEnd invocation for everyconsole.time call, it is convenient to wrap them both up in an RAII type:

    2. # #![allow(unused_variables)]
    3. #fn main() {
    4. extern crate web_sys;
    5. use web_sys::console;
    7. pub struct Timer<'a> {
    8.     name: &'a str,
    9. }
    11. impl<'a> Timer<'a> {
    12.     pub fn new(name: &'a str) -> Timer<'a> {
    13.         console::time_with_label(name);
    14.         Timer { name }
    15.     }
    16. }
    18. impl<'a> Drop for Timer<'a> {
    19.     fn drop(&mut self) {
    20.         console::time_end_with_label(self.name);
    21.     }
    22. }
    23. #}

    Then, we can time how long each Universe::tick takes by adding this snippet tothe top of the method:

    The time of how long each call to Universe::tick took are now logged in theconsole:

    Additionally, console.time and console.timeEnd pairs will show up in yourbrowser's profiler's "timeline" or "waterfall" view:ppScreenshot of console.time logs

    What happens if we make our Game of Life universe larger? Replacing the 64 by 64universe with a 128 by 128 universe (by modifying Universe::new inwasm-game-of-life/src/lib.rs) results in FPS dropping from a smooth 60 to achoppy 40-ish on my machine.

    If we record a profile and look at the waterfall view, we see that eachanimation frame is taking over 20 milliseconds. Recall that 60 frames per secondleaves sixteen milliseconds for the whole process of rendering a frame. That'snot just our JavaScript and WebAssembly, but also everything else the browser isdoing, such as painting.

    If we look at what happens within a single animation frame, we see that theCanvasRenderingContext2D.fillStyle setter is very expensive!

    Screenshot of a flamegraph view of rendering a frame

    And we can confirm that this isn't an abnormality by looking at the call tree'saggregation of many frames:

    Nearly 40% of our time is spent in this setter!

    In the drawCells function in wasm-game-of-life/www/index.js, the fillStyleproperty is set once for every cell in the universe, on every animation frame:

    1. for (let row = 0; row < height; row++) {
    2.   for (let col = 0; col < width; col++) {
    3.     const idx = getIndex(row, col);
    5.     ctx.fillStyle = cells[idx] === DEAD
    6.       ? DEAD_COLOR
    7.       : ALIVE_COLOR;
    9.     ctx.fillRect(
    10.       col * (CELL_SIZE + 1) + 1,
    11.       row * (CELL_SIZE + 1) + 1,
    12.       CELL_SIZE,
    13.       CELL_SIZE
    14.     );
    15.   }
    16. }

    Now that we have discovered that setting fillStyle is so expensive, what canwe do to avoid setting it so often? We need to change fillStyle depending onwhether a cell is alive or dead. If we set fillStyle = ALIVE_COLOR and thendraw every alive cell in one pass, and then set fillStyle = DEAD_COLOR anddraw every dead cell in another pass, then we only end setting fillStyletwice, rather than once for every cell.

    1. // Alive cells.
    2. ctx.fillStyle = ALIVE_COLOR;
    3. for (let row = 0; row < height; row++) {
    4.   for (let col = 0; col < width; col++) {
    5.     const idx = getIndex(row, col);
    6.     if (cells[idx] !== Cell.Alive) {
    7.       continue;
    8.     }
    10.     ctx.fillRect(
    11.       col * (CELL_SIZE + 1) + 1,
    12.       row * (CELL_SIZE + 1) + 1,
    13.       CELL_SIZE,
    14.       CELL_SIZE
    15.     );
    16.   }
    17. }
    19. // Dead cells.
    20. ctx.fillStyle = DEAD_COLOR;
    21. for (let row = 0; row < height; row++) {
    23.     const idx = getIndex(row, col);
    24.     if (cells[idx] !== Cell.Dead) {
    25.       continue;
    26.     }
    27.     ctx.fillRect(
    28.       col * (CELL_SIZE + 1) + 1,
    29.       row * (CELL_SIZE + 1) + 1,
    30.       CELL_SIZE,
    31.       CELL_SIZE
    32.     );
    33.   }
    34. }

    After saving these changes and refreshinghttp://localhost:8080/, rendering is back to a smooth60 frames per second.

    If we take another profile, we can see that only about ten milliseconds arespent in each animation frame now.

    Breaking down a single frame, we see that the fillStyle cost is gone, and mostof our frame's time is spent within fillRect, drawing each cell's rectangle.

    Some folks don't like waiting around, and would prefer if instead of one tick ofthe universe occurred per animation frame, nine ticks did. We can modify therenderLoop function in wasm-game-of-life/www/index.js to do this quiteeasily:

    1. for (let i = 0; i < 9; i++) {
    2.   universe.tick();
    3. }

    On my machine, this brings us back down to only 35 frames per second. Nogood. We want that buttery 60!

    Now we know that time is being spent in Universe::tick, so let's add someTimers to wrap various bits of it in console.time and console.timeEndcalls, and see where that leads us. My hypothesis is that allocating a newvector of cells and freeing the old vector on every tick is costly, and takingup a significant portion of our time budget.

    2. # #![allow(unused_variables)]
    3. #fn main() {
    4. pub fn tick(&mut self) {
    5.     let _timer = Timer::new("Universe::tick");
    7.     let mut next = {
    8.         let _timer = Timer::new("allocate next cells");
    9.         self.cells.clone()
    10.     };
    12.     {
    13.         let _timer = Timer::new("new generation");
    14.         for row in 0..self.height {
    15.             for col in 0..self.width {
    16.                 let idx = self.get_index(row, col);
    17.                 let cell = self.cells[idx];
    18.                 let live_neighbors = self.live_neighbor_count(row, col);
    20.                 let next_cell = match (cell, live_neighbors) {
    21.                     // Rule 1: Any live cell with fewer than two live neighbours
    22.                     // dies, as if caused by underpopulation.
    23.                     (Cell::Alive, x) if x < 2 => Cell::Dead,
    24.                     // Rule 2: Any live cell with two or three live neighbours
    25.                     // lives on to the next generation.
    26.                     (Cell::Alive, 2) | (Cell::Alive, 3) => Cell::Alive,
    27.                     // Rule 3: Any live cell with more than three live
    28.                     // neighbours dies, as if by overpopulation.
    29.                     (Cell::Alive, x) if x > 3 => Cell::Dead,
    30.                     // Rule 4: Any dead cell with exactly three live neighbours
    31.                     // becomes a live cell, as if by reproduction.
    32.                     (Cell::Dead, 3) => Cell::Alive,
    33.                     // All other cells remain in the same state.
    34.                     (otherwise, _) => otherwise,
    35.                 };
    37.                 next[idx] = next_cell;
    38.             }
    39.         }
    40.     }
    42.     let _timer = Timer::new("free old cells");
    43.     self.cells = next;
    44. }
    45. #}

    Looking at the timings, it is clear that my hypothesis is incorrect: the vastmajority of time is spent actually calculating the next generation ofcells. Allocating and freeing a vector on every tick appears to have negligiblecost, surprisingly. Another reminder to always guide our efforts with profiling!

    The next section requires the nightly compiler. It's required because ofthe test feature gatewe're going to use for the benchmarks. Another tool we will install is .It's a small utility for comparing micro-benchmarks produced by cargo bench.

    2. # #![allow(unused_variables)]
    3. #![feature(test)]
    5. #fn main() {
    6. extern crate test;
    7. extern crate wasm_game_of_life;
    9. #[bench]
    10. fn universe_ticks(b: &mut test::Bencher) {
    11.     let mut universe = wasm_game_of_life::Universe::new();
    13.     b.iter(|| {
    14.         universe.tick();
    15.     });
    16. }
    17. #}

    We also have to comment out all the #[wasm_bindgen] annotations, and the"cdylib" bits from Cargo.toml or else building native code will fail andhave link errors.

    With all that in place, we can run cargo bench | tee before.txt to compile and run ourbenchmark! The | tee before.txt part will take the output from cargo bench and put in a filecalled before.txt.

    This also tells us where the binary lives, and we can run the benchmarks again,but this time under our operating system's profiler. In my case, I'm runningLinux, so perf is the profiler I'll use:

    1. $ perf record -g target/release/deps/bench-8474091a05cfa2d9 --bench
    2. running 1 test
    3. test universe_ticks ... bench:     635,061 ns/iter (+/- 38,764)
    5. test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out
    7. [ perf record: Woken up 1 times to write data ]
    8. [ perf record: Captured and wrote 0.178 MB perf.data (2349 samples) ]

    Loading up the profile with perf report shows that all of our time is spent inUniverse::tick, as expected:

    perf will annotate which instructions in a function time is being spent at ifyou press a:

    Screenshot of perf's instruction annotation

    This tells us that 26.67% of time is being spent summing neighboring cells'values, 23.41% of time is spent getting the neighbor's column index, and another15.42% of time is spent getting the neighbor's row index. Of these top threemost expensive instructions, the second and third are both costly divinstructions. These s implement the modulo indexing logic inUniverse::live_neighbor_count.

    Recall the live_neighbor_count definition insidewasm-game-of-life/src/lib.rs:

    2. # #![allow(unused_variables)]
    3. #fn main() {
    4. fn live_neighbor_count(&self, row: u32, column: u32) -> u8 {
    5.     let mut count = 0;
    6.     for delta_row in [self.height - 1, 0, 1].iter().cloned() {
    7.         for delta_col in [self.width - 1, 0, 1].iter().cloned() {
    8.             if delta_row == 0 && delta_col == 0 {
    9.             }
    11.             let neighbor_row = (row + delta_row) % self.height;
    12.             let neighbor_col = (column + delta_col) % self.width;
    13.             let idx = self.get_index(neighbor_row, neighbor_col);
    14.             count += self.cells[idx] as u8;
    15.         }
    16.     }
    17.     count
    18. }
    19. #}

    The reason we used modulo was to avoid cluttering up the code with if branchesfor the first or last row or column edge cases. But we are paying the cost of adiv instruction even for the most common case, when neither row nor columnis on the edge of the universe and they don't need the modulo wrappingtreatment. Instead, if we use ifs for the edge cases and unroll this loop, thebranches should be very well-predicted by the CPU's branch predictor.

    Let's rewrite live_neighbor_count like this:

    2. # #![allow(unused_variables)]
    3. #fn main() {
    4. fn live_neighbor_count(&self, row: u32, column: u32) -> u8 {
    5.     let mut count = 0;
    7.     let north = if row == 0 {
    8.         self.height - 1
    9.     } else {
    10.         row - 1
    11.     };
    13.     let south = if row == self.height - 1 {
    14.         0
    15.     } else {
    16.         row + 1
    17.     };
    19.     let west = if column == 0 {
    20.         self.width - 1
    21.     } else {
    22.         column - 1
    23.     };
    25.     let east = if column == self.width - 1 {
    26.         0
    27.     } else {
    28.         column + 1
    29.     };
    31.     let nw = self.get_index(north, west);
    32.     count += self.cells[nw] as u8;
    34.     let n = self.get_index(north, column);
    35.     count += self.cells[n] as u8;
    37.     let ne = self.get_index(north, east);
    38.     count += self.cells[ne] as u8;
    40.     let w = self.get_index(row, west);
    41.     count += self.cells[w] as u8;
    43.     let e = self.get_index(row, east);
    44.     count += self.cells[e] as u8;
    46.     let sw = self.get_index(south, west);
    47.     count += self.cells[sw] as u8;
    49.     let s = self.get_index(south, column);
    50.     count += self.cells[s] as u8;
    52.     let se = self.get_index(south, east);
    53.     count += self.cells[se] as u8;
    55.     count
    56. }
    57. #}

    Now let's run the benchmarks again! This time output it to after.txt.

    1. $ cargo bench | tee after.txt
    2.    Compiling wasm_game_of_life v0.1.0 (file:///home/fitzgen/wasm_game_of_life)
    3.     Finished release [optimized + debuginfo] target(s) in 0.82 secs
    4.      Running target/release/deps/wasm_game_of_life-91574dfbe2b5a124
    6. running 0 tests
    8. test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
    10.      Running target/release/deps/bench-8474091a05cfa2d9
    12. running 1 test
    13. test universe_ticks ... bench:      87,258 ns/iter (+/- 14,632)
    15. test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out

    That looks a whole lot better! We can see just how much better it is with the benchcmp tool and the two text files we created before:

    1. $ cargo benchcmp before.txt after.txt
    2.  name            before.txt ns/iter  after.txt ns/iter  diff ns/iter   diff %  speedup
    3.  universe_ticks  664,421             87,258                 -577,163  -86.87%   x 7.61

    Wow! 7.61x speed up!

    WebAssembly intentionally maps closely to common hardware architectures, but wedo need to make sure that this native code speed up translates into aWebAssembly speed up as well.

    Let's rebuild the .wasm with wasm-pack build and refresh. On my machine, the page isrunning at 60 frames per second again, and recording another profile with thebrowser's profiler reveals that each animation frame is taking about tenmilliseconds.

    Success!

    • At this point, the next lowest hanging fruit for speeding up Universe::tickis removing the allocation and free. Implement double buffering of cells,where the Universe maintains two vectors, never frees either of them, andnever allocates new buffers in tick.

    • As our profiling has shown us, 2D <canvas> rendering is not particularlyfast. Replace the 2D canvas renderer with a renderer. How much faster isthe WebGL version? How large can you make the universe before WebGL renderingis a bottleneck?