Merge pull request #124 from gendx/heapviz-tool

Add a heap visualization tool.

.github/workflows/cargo_fmt.yml

@@ -5,6 +5,7 @@ on:
       - 'examples/*.rs'
       - 'libraries/**/*.rs'
       - 'src/**/*.rs'
+      - 'tools/**/*.rs'
       - 'patches/**'
       - '**/Cargo.toml'
       - '.cargo/config'
@@ -46,3 +47,9 @@ jobs:
         with:
           command: fmt
           args: --manifest-path libraries/crypto/Cargo.toml --all -- --check
+
+      - name: Cargo format tools/heapviz
+        uses: actions-rs/cargo@v1
+        with:
+          command: fmt
+          args: --manifest-path tools/heapviz/Cargo.toml --all -- --check

.github/workflows/heapviz_test.yml

@@ -0,0 +1,34 @@
+---
+name: Heapviz tool tests
+on:
+  push:
+    paths:
+      - 'tools/heapviz/**'
+  pull_request:
+    types: [opened, synchronize, reopened]
+
+jobs:
+  heapviz_test:
+    runs-on: ubuntu-18.04
+    steps:
+      - uses: actions/checkout@v2
+      - name: Install ncurses
+        run: sudo apt-get install libncurses-dev
+
+      - name: Check heapviz tool
+        uses: actions-rs/cargo@v1
+        with:
+          command: check
+          args: --manifest-path tools/heapviz/Cargo.toml
+
+      - name: Unit testing of heapviz tool (debug mode)
+        uses: actions-rs/cargo@v1
+        with:
+          command: test
+          args: --manifest-path tools/heapviz/Cargo.toml
+
+      - name: Unit testing of heapviz tool (release mode)
+        uses: actions-rs/cargo@v1
+        with:
+          command: test
+          args: --manifest-path tools/heapviz/Cargo.toml --release

README.md

@@ -115,6 +115,70 @@ All the required files can be downloaded from
 file, allowing you to easily make the modifications you need to further
 customize it.
 
+## Development and testing
+
+### Printing panic messages to the console
+
+By default, libtock-rs blinks some LEDs when the userspace application panicks.
+This is not always convenient as the panic message is lost. In order to enable
+a custom panic handler that first writes the panic message via Tock's console
+driver, before faulting the app, you can use the `--panic-console` flag of the
+`deploy.py` script.
+
+```shell
+# Example on Nordic nRF52840-DK board
+./deploy.py --board=nrf52840dk --opensk --panic-console
+```
+
+### Debugging memory allocations
+
+You may want to track memory allocations to understand the heap usage of
+OpenSK. This can be useful if you plan to port it to a board with fewer
+available RAM for example. To do so, you can enable the `--debug-allocations`
+flag of the `deploy.py` script. This enables a custom (userspace) allocator
+that prints a message to the console for each allocation and deallocation
+operation.
+
+The additional output looks like the following.
+
+```
+# Allocation of 256 byte(s), aligned on 1 byte(s). The allocated address is
+# 0x2002401c. After this operation, 2 pointers have been allocated, totalling
+# 384 bytes (the total heap usage may be larger, due to alignment and
+# fragmentation of allocations within the heap).
+alloc[256, 1] = 0x2002401c (2 ptrs, 384 bytes)
+# Deallocation of 64 byte(s), aligned on 1 byte(s), from address 0x2002410c.
+# After this operation, 1 pointers are allocated, totalling 512 bytes.
+dealloc[64, 1] = 0x2002410c (1 ptrs, 512 bytes)
+```
+
+A tool is provided to analyze such reports, in `tools/heapviz`. This tool
+parses the console output, identifies the lines corresponding to (de)allocation
+operations, and first computes some statistics:
+
+- Address range used by the heap over this run of the program,
+- Peak heap usage (how many useful bytes are allocated),
+- Peak heap consumption (how many bytes are used by the heap, including
+  unavailable bytes between allocated blocks, due to alignment constraints and
+  memory fragmentation),
+- Fragmentation overhead (difference between heap consumption and usage).
+
+Then, the `heapviz` tool displays an animated "movie" of the allocated bytes in
+heap memory. Each frame in this "movie" shows bytes that are currently
+allocated, that were allocated but are now freed, and that have never been
+allocated. A new frame is generated for each (de)allocation operation. This tool
+uses the `ncurses` library, that you may have to install beforehand.
+
+You can control the tool with the following parameters:
+- `--logfile` (required) to provide the file which contains the console output
+  to parse,
+- `--fps` (optional) to customize the number of frames per second in the movie
+  animation.
+
+```shell
+cargo run --manifest-path tools/heapviz/Cargo.toml -- --logfile console.log --fps 50
+```
+
 ## Contributing
 
 See [Contributing.md](docs/contributing.md).

reproducible/reference_binaries_macos-10.15.sha256sum

@@ -1,9 +1,9 @@
 0b54df6d548849e24d67b9b022ca09cb33c51f078ce85d0c9c4635ffc69902e1	third_party/tock/target/thumbv7em-none-eabi/release/nrf52840dk.bin
-136480e054c13cb3502a78f47b6496f0488adc001a568508f6fbb0bb92715317	target/nrf52840dk_merged.hex
+8a804b9a1f60f47c315cf5b41e0457f43c74c9e8a4809d22d40d7696f927e41a	target/nrf52840dk_merged.hex
 052eec0ae526038352b9f7573468d0cf7fb5ec331d4dc1a2df75fdbd514ea5ca	third_party/tock/target/thumbv7em-none-eabi/release/nrf52840_dongle.bin
-21602fe8f25e329e80989e97c637ec8a2f1b02d2a88de636a06632465012a9c9	target/nrf52840_dongle_merged.hex
+557fc612af0cd8f7684a4016fe73f1db64da1b4786b4621149f66084426b2b79	target/nrf52840_dongle_merged.hex
 908d7f4f40936d968b91ab6e19b2406612fe8c2c273d9c0b71ef1f55116780e0	third_party/tock/target/thumbv7em-none-eabi/release/nrf52840_dongle_dfu.bin
-40d176b43006dc3b2aaabfffab6210153d99641d9835e953cb48769f58d4cc48	target/nrf52840_dongle_dfu_merged.hex
+e101d1b0c61bff363279c4cef61d10fd1ca1d9626fb5106bc7dacea29678a611	target/nrf52840_dongle_dfu_merged.hex
 34ecbecaebf1188277f2310fe769c8c60310d8576493242712854deb4ba1036e	third_party/tock/target/thumbv7em-none-eabi/release/nrf52840_mdk_dfu.bin
-a3cf456e2f8e8216be891d7d4153c72535029c538612395a843bee65e573f8ba	target/nrf52840_mdk_dfu_merged.hex
+ee2ba07f4de6cbabd5086f18e7774dab03ad4ba9cc1e0a40c4b512de71eb1e27	target/nrf52840_mdk_dfu_merged.hex
-9fcc808b6df7d773cbe8740fbe33fa6522011991a9ed777656ba0ae67d6e8767	target/tab/ctap2.tab
+fcebf94765240c91fc9af727470bad5179f4b41fca49a6afdc09899eab25c0cd	target/tab/ctap2.tab

reproducible/reference_binaries_ubuntu-18.04.sha256sum

@@ -1,9 +1,9 @@
 29382e72d0f3c6a72ce9517211952ff29ea270193d7f0ddc48ca69009ee29925	third_party/tock/target/thumbv7em-none-eabi/release/nrf52840dk.bin
-0c2732e9051d2a920a1b0c8ef1094d920145e34a169af24b25109685b913ba6a	target/nrf52840dk_merged.hex
+40ac6af2fd714c0edd8dded04ca86a13f0d99eb7ec4342e417e0786a97971f2b	target/nrf52840dk_merged.hex
 30f239390ae9bef0825731e4c82d40470fc5e9bded2bf0d942e92dbb5d4faba1	third_party/tock/target/thumbv7em-none-eabi/release/nrf52840_dongle.bin
-d99d216f5c231b87e50b193dcb2cbdd8e09c5cee605abd72456da905832fece3	target/nrf52840_dongle_merged.hex
+67e98f4e5d3905870ea56dffb0be98609b15d571ebc5281bee14e580daf0f972	target/nrf52840_dongle_merged.hex
 e3acf15d5ae3a22aecff6cc58db5fc311f538f47328d348b7ad7db7f9ab5e72c	third_party/tock/target/thumbv7em-none-eabi/release/nrf52840_dongle_dfu.bin
-56845828e90e595388a0a219b5a9a5eda6f768d0e5cc7e2b1712ce5b4b2f848d	target/nrf52840_dongle_dfu_merged.hex
+e86d6eb6aa23b71deee451dbf927ae29cce3c0f8fa4463620188e9adfdec968d	target/nrf52840_dongle_dfu_merged.hex
 cae312a26a513ada6c198fdc59b2bba3860c51726b817a9fd17a4331ee12c882	third_party/tock/target/thumbv7em-none-eabi/release/nrf52840_mdk_dfu.bin
-7028d2253d30e5a809f4d3c2deb4cb46953a9de31978834f01a3b1392da38291	target/nrf52840_mdk_dfu_merged.hex
+4e507329a04f16928ae02e39a4e4984783cfe8ed20a56988250d57d64c0ab848	target/nrf52840_mdk_dfu_merged.hex
-f96c01efac9382c001d0e277247ff20f9b17b0bb34b98a38f0e4e9cc5c3c0b90	target/tab/ctap2.tab
+cd262c3ef11ba5e69cf8033271b15c91ef6b88e25e9ec25af1b39248fb0a0574	target/tab/ctap2.tab

reproducible/reference_elf2tab_macos-10.15.txt

@@ -5,8 +5,8 @@ Min RAM size from sections in ELF: 16 bytes
 Number of writeable flash regions: 0
   Adding .crt0_header section. Offset: 64 (0x40). Length: 64 (0x40) bytes.
 Entry point is in .text section
-  Adding .text section. Offset: 128 (0x80). Length: 179172 (0x2bbe4) bytes.
+  Adding .text section. Offset: 128 (0x80). Length: 178804 (0x2ba74) bytes.
-  Adding .stack section. Offset: 179300 (0x2bc64). Length: 16384 (0x4000) bytes.
+  Adding .stack section. Offset: 178932 (0x2baf4). Length: 16384 (0x4000) bytes.
 Searching for .rel.X sections to add.
 TBF Header:
                version:        2        0x2
@@ -24,8 +24,8 @@ Min RAM size from sections in ELF: 16 bytes
 Number of writeable flash regions: 0
   Adding .crt0_header section. Offset: 64 (0x40). Length: 64 (0x40) bytes.
 Entry point is in .text section
-  Adding .text section. Offset: 128 (0x80). Length: 179172 (0x2bbe4) bytes.
+  Adding .text section. Offset: 128 (0x80). Length: 178804 (0x2ba74) bytes.
-  Adding .stack section. Offset: 179300 (0x2bc64). Length: 16384 (0x4000) bytes.
+  Adding .stack section. Offset: 178932 (0x2baf4). Length: 16384 (0x4000) bytes.
 Searching for .rel.X sections to add.
 TBF Header:
                version:        2        0x2
@@ -43,8 +43,8 @@ Min RAM size from sections in ELF: 16 bytes
 Number of writeable flash regions: 0
   Adding .crt0_header section. Offset: 64 (0x40). Length: 64 (0x40) bytes.
 Entry point is in .text section
-  Adding .text section. Offset: 128 (0x80). Length: 179172 (0x2bbe4) bytes.
+  Adding .text section. Offset: 128 (0x80). Length: 178804 (0x2ba74) bytes.
-  Adding .stack section. Offset: 179300 (0x2bc64). Length: 16384 (0x4000) bytes.
+  Adding .stack section. Offset: 178932 (0x2baf4). Length: 16384 (0x4000) bytes.
 Searching for .rel.X sections to add.
 TBF Header:
                version:        2        0x2
@@ -62,8 +62,8 @@ Min RAM size from sections in ELF: 16 bytes
 Number of writeable flash regions: 0
   Adding .crt0_header section. Offset: 64 (0x40). Length: 64 (0x40) bytes.
 Entry point is in .text section
-  Adding .text section. Offset: 128 (0x80). Length: 179172 (0x2bbe4) bytes.
+  Adding .text section. Offset: 128 (0x80). Length: 178804 (0x2ba74) bytes.
-  Adding .stack section. Offset: 179300 (0x2bc64). Length: 16384 (0x4000) bytes.
+  Adding .stack section. Offset: 178932 (0x2baf4). Length: 16384 (0x4000) bytes.
 Searching for .rel.X sections to add.
 TBF Header:
                version:        2        0x2

reproducible/reference_elf2tab_ubuntu-18.04.txt

@@ -5,8 +5,8 @@ Min RAM size from sections in ELF: 16 bytes
 Number of writeable flash regions: 0
   Adding .crt0_header section. Offset: 64 (0x40). Length: 64 (0x40) bytes.
 Entry point is in .text section
-  Adding .text section. Offset: 128 (0x80). Length: 178740 (0x2ba34) bytes.
+  Adding .text section. Offset: 128 (0x80). Length: 180148 (0x2bfb4) bytes.
-  Adding .stack section. Offset: 178868 (0x2bab4). Length: 16384 (0x4000) bytes.
+  Adding .stack section. Offset: 180276 (0x2c034). Length: 16384 (0x4000) bytes.
 Searching for .rel.X sections to add.
 TBF Header:
                version:        2        0x2
@@ -24,8 +24,8 @@ Min RAM size from sections in ELF: 16 bytes
 Number of writeable flash regions: 0
   Adding .crt0_header section. Offset: 64 (0x40). Length: 64 (0x40) bytes.
 Entry point is in .text section
-  Adding .text section. Offset: 128 (0x80). Length: 178740 (0x2ba34) bytes.
+  Adding .text section. Offset: 128 (0x80). Length: 180148 (0x2bfb4) bytes.
-  Adding .stack section. Offset: 178868 (0x2bab4). Length: 16384 (0x4000) bytes.
+  Adding .stack section. Offset: 180276 (0x2c034). Length: 16384 (0x4000) bytes.
 Searching for .rel.X sections to add.
 TBF Header:
                version:        2        0x2
@@ -43,8 +43,8 @@ Min RAM size from sections in ELF: 16 bytes
 Number of writeable flash regions: 0
   Adding .crt0_header section. Offset: 64 (0x40). Length: 64 (0x40) bytes.
 Entry point is in .text section
-  Adding .text section. Offset: 128 (0x80). Length: 178740 (0x2ba34) bytes.
+  Adding .text section. Offset: 128 (0x80). Length: 180148 (0x2bfb4) bytes.
-  Adding .stack section. Offset: 178868 (0x2bab4). Length: 16384 (0x4000) bytes.
+  Adding .stack section. Offset: 180276 (0x2c034). Length: 16384 (0x4000) bytes.
 Searching for .rel.X sections to add.
 TBF Header:
                version:        2        0x2
@@ -62,8 +62,8 @@ Min RAM size from sections in ELF: 16 bytes
 Number of writeable flash regions: 0
   Adding .crt0_header section. Offset: 64 (0x40). Length: 64 (0x40) bytes.
 Entry point is in .text section
-  Adding .text section. Offset: 128 (0x80). Length: 178740 (0x2ba34) bytes.
+  Adding .text section. Offset: 128 (0x80). Length: 180148 (0x2bfb4) bytes.
-  Adding .stack section. Offset: 178868 (0x2bab4). Length: 16384 (0x4000) bytes.
+  Adding .stack section. Offset: 180276 (0x2c034). Length: 16384 (0x4000) bytes.
 Searching for .rel.X sections to add.
 TBF Header:
                version:        2        0x2

run_desktop_tests.sh

@@ -23,9 +23,16 @@ cd ../..
 cd libraries/crypto
 cargo fmt --all -- --check
 cd ../..
+cd tools/heapviz
+cargo fmt --all -- --check
+cd ../..
 
 echo "Building sha256sum tool..."
 cargo build --manifest-path third_party/tock/tools/sha256sum/Cargo.toml
+echo "Checking that heapviz tool builds properly..."
+cargo build --manifest-path tools/heapviz/Cargo.toml
+echo "Testing heapviz tool..."
+cargo test --manifest-path tools/heapviz/Cargo.toml
 
 echo "Checking that CTAP2 builds properly..."
 cargo check --release --target=thumbv7em-none-eabi

tools/heapviz/Cargo.toml

@@ -0,0 +1,14 @@
+[package]
+name = "heapviz"
+version = "0.1.0"
+authors = [
+  "Guillaume Endignoux <guillaumee@google.com>",
+]
+license = "Apache-2.0"
+edition = "2018"
+
+[dependencies]
+clap = "2.33.1"
+lazy_static = "1.4.0"
+ncurses = "5.99.0"
+regex = "1"

tools/heapviz/src/main.rs

@@ -0,0 +1,217 @@
+// Copyright 2020 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//      http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+use clap::{App, Arg};
+use lazy_static::lazy_static;
+use regex::Regex;
+use std::fs::File;
+use std::io::{BufRead, BufReader, Read, Write};
+use std::thread::sleep;
+use std::time::Duration;
+
+/// Configuration, built from CLI parameters.
+struct Config {
+    /// Handle to the log file containing allocation operations.
+    logfile: File,
+    /// Number of allocation operations to show per second.
+    fps: u64,
+}
+
+fn parse_cli() -> Config {
+    let matches = App::new("Heap visualizer")
+                          .version("0.1")
+                          .author("Guillaume Endignoux <guillaumee@google.com>")
+                          .about("Tool to visualize heap usage of libtock-rs applications")
+                          .arg(Arg::with_name("logfile")
+                               .short("f")
+                               .long("logfile")
+                               .value_name("FILE")
+                               .help("Log file containing allocation info (deploy OpenSK with --debug-allocations to obtain it)")
+                               .takes_value(true)
+                               .required(true))
+                          .arg(Arg::with_name("fps")
+                               .long("fps")
+                               .value_name("FPS")
+                               .help("Number of allocation operations to show per second")
+                               .takes_value(true)
+                               .default_value("20"))
+                          .get_matches();
+
+    let logpath = matches.value_of("logfile").unwrap();
+    let fps = matches
+        .value_of("fps")
+        .unwrap()
+        .parse::<u64>()
+        .expect("The --fps parameter must be an integer");
+    let logfile = File::open(logpath).expect("Couldn't open --logfile for reading");
+
+    Config { logfile, fps }
+}
+
+/// An allocation or deallocation event.
+#[cfg_attr(test, derive(Debug, PartialEq))]
+struct Event {
+    /// Whether this even is an allocation (true) or a deallocation (false).
+    is_alloc: bool,
+    /// The start address of the (de)allocated block, in bytes.
+    start: usize,
+    /// The length of the (de)allocated block, in bytes.
+    len: usize,
+}
+
+fn parse_event(line: &str) -> Option<Event> {
+    // The following regex matches lines looking like the following from OpenSK's output. Such lines
+    // are printed to the console when the `--debug-allocations` feature is enabled in the deploy
+    // script.
+    //
+    // ```
+    // alloc[256, 1] = 0x2002401c (2 ptrs, 384 bytes)
+    // dealloc[64, 1] = 0x2002410c (1 ptrs, 512 bytes)
+    // ```
+    //
+    // The two integers between square brackets after the (de)alloc keywords represent the length
+    // and alignement of the allocated block, respectively. The integer serialized in hexadecimal
+    // after the equal sign represents the starting address of the allocated block. The two
+    // integers within parentheses represent statistics about the total number of allocated blocks
+    // and the total number of allocated bytes after the (de)allocation operation, respectively.
+    //
+    // This regex captures three elements, in this order.
+    // - The keyword to know whether this operation is an allocation or a deallocation.
+    // - The length of the allocated block.
+    // - The starting address of the allocated block.
+    lazy_static! {
+        static ref RE: Regex =
+            Regex::new(r"^(alloc|dealloc)\[(\d+), \d+\] = 0x([0-9a-f]+) \(\d+ ptrs, \d+ bytes\)$")
+                .unwrap();
+    }
+
+    RE.captures(line).map(|caps| {
+        let typ = caps.get(1).unwrap().as_str();
+        let len = caps.get(2).unwrap().as_str().parse::<usize>().unwrap();
+        let start = usize::from_str_radix(&caps.get(3).unwrap().as_str(), 16).unwrap();
+        Event {
+            is_alloc: typ == "alloc",
+            start,
+            len,
+        }
+    })
+}
+
+fn main() {
+    let config = parse_cli();
+
+    let mut events = Vec::new();
+    for line in BufReader::new(config.logfile).lines() {
+        if let Some(event) = parse_event(&line.unwrap()) {
+            events.push(event);
+        }
+    }
+
+    let count_alloc = events.iter().filter(|e| e.is_alloc).count();
+    let count_dealloc = events.len() - count_alloc;
+    let start = events.iter().map(|e| e.start).min().unwrap_or(0);
+    let end = events.iter().map(|e| e.start + e.len).max().unwrap_or(0);
+    let mut usage = 0;
+    let peak = events
+        .iter()
+        .map(|e| {
+            if e.is_alloc {
+                usage += e.len;
+            } else {
+                usage -= e.len;
+            }
+            usage
+        })
+        .max()
+        .unwrap_or(0);
+    let len = end - start;
+    println!(
+        "Observed {} allocations and {} deallocations",
+        count_alloc, count_dealloc
+    );
+    println!("Start address: {:08x}", start);
+    println!("End address: {:08x}", end);
+    println!("Peak usage: {0} = {0:08x} bytes", peak);
+    println!("Peak consumption: {0} = {0:08x} bytes", len);
+    println!("Fragmentation overhead: {0} = {0:08x} bytes", len - peak);
+
+    print!("\nPress ENTER to start the visualization...");
+    std::io::stdout().flush().unwrap();
+    // Wait for ENTER, by reading a single byte and discarding it.
+    let _ = std::io::stdin().lock().read(&mut [0u8]).unwrap();
+
+    let window = ncurses::initscr();
+    ncurses::cbreak();
+    ncurses::noecho();
+    ncurses::intrflush(window, false);
+    ncurses::curs_set(ncurses::CURSOR_VISIBILITY::CURSOR_INVISIBLE);
+
+    let width = ncurses::getmaxx(window) as usize;
+
+    for e in events.iter() {
+        let position = e.start - start;
+        ncurses::wmove(window, (position / width) as i32, (position % width) as i32);
+
+        let mut s = Vec::with_capacity(e.len);
+        if e.is_alloc {
+            s.resize(e.len, b'#');
+        } else {
+            s.resize(e.len, b'.');
+        }
+        ncurses::addstr(std::str::from_utf8(s.as_slice()).unwrap());
+        ncurses::refresh();
+        sleep(Duration::from_nanos(1_000_000_000 / config.fps));
+    }
+
+    ncurses::endwin();
+}
+
+#[cfg(test)]
+mod test {
+    use super::*;
+
+    #[test]
+    fn test_parse_event_alloc() {
+        assert_eq!(
+            parse_event("alloc[256, 1] = 0x2002401c (2 ptrs, 384 bytes)"),
+            Some(Event {
+                is_alloc: true,
+                start: 0x2002401c,
+                len: 256,
+            })
+        );
+    }
+
+    #[test]
+    fn test_parse_event_dealloc() {
+        assert_eq!(
+            parse_event("dealloc[64, 1] = 0x2002410c (1 ptrs, 512 bytes)"),
+            Some(Event {
+                is_alloc: false,
+                start: 0x2002410c,
+                len: 64,
+            })
+        );
+    }
+
+    #[test]
+    fn test_parse_event_none() {
+        assert_eq!(
+            parse_event(
+                "NRF52 HW INFO: Variant: AAD0, Part: N52840, Package: QI, Ram: K256, Flash: K1024"
+            ),
+            None
+        );
+    }
+}