diff --git a/.github/workflows/cargo_fmt.yml b/.github/workflows/cargo_fmt.yml index df466b3..72dec08 100644 --- a/.github/workflows/cargo_fmt.yml +++ b/.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 diff --git a/.github/workflows/heapviz_test.yml b/.github/workflows/heapviz_test.yml new file mode 100644 index 0000000..6e7fb4f --- /dev/null +++ b/.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 diff --git a/README.md b/README.md index 6e68ba1..9385fbc 100644 --- a/README.md +++ b/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). diff --git a/reproducible/reference_binaries_macos-10.15.sha256sum b/reproducible/reference_binaries_macos-10.15.sha256sum index ee54c1f..5d79023 100644 --- a/reproducible/reference_binaries_macos-10.15.sha256sum +++ b/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 -9fcc808b6df7d773cbe8740fbe33fa6522011991a9ed777656ba0ae67d6e8767 target/tab/ctap2.tab +ee2ba07f4de6cbabd5086f18e7774dab03ad4ba9cc1e0a40c4b512de71eb1e27 target/nrf52840_mdk_dfu_merged.hex +fcebf94765240c91fc9af727470bad5179f4b41fca49a6afdc09899eab25c0cd target/tab/ctap2.tab diff --git a/reproducible/reference_binaries_ubuntu-18.04.sha256sum b/reproducible/reference_binaries_ubuntu-18.04.sha256sum index bed5f19..ca4a333 100644 --- a/reproducible/reference_binaries_ubuntu-18.04.sha256sum +++ b/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 -f96c01efac9382c001d0e277247ff20f9b17b0bb34b98a38f0e4e9cc5c3c0b90 target/tab/ctap2.tab +4e507329a04f16928ae02e39a4e4984783cfe8ed20a56988250d57d64c0ab848 target/nrf52840_mdk_dfu_merged.hex +cd262c3ef11ba5e69cf8033271b15c91ef6b88e25e9ec25af1b39248fb0a0574 target/tab/ctap2.tab diff --git a/reproducible/reference_elf2tab_macos-10.15.txt b/reproducible/reference_elf2tab_macos-10.15.txt index 1972223..e86f0fe 100644 --- a/reproducible/reference_elf2tab_macos-10.15.txt +++ b/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 .stack section. Offset: 179300 (0x2bc64). Length: 16384 (0x4000) bytes. + Adding .text section. Offset: 128 (0x80). Length: 178804 (0x2ba74) 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 .stack section. Offset: 179300 (0x2bc64). Length: 16384 (0x4000) bytes. + Adding .text section. Offset: 128 (0x80). Length: 178804 (0x2ba74) 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 .stack section. Offset: 179300 (0x2bc64). Length: 16384 (0x4000) bytes. + Adding .text section. Offset: 128 (0x80). Length: 178804 (0x2ba74) 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 .stack section. Offset: 179300 (0x2bc64). Length: 16384 (0x4000) bytes. + Adding .text section. Offset: 128 (0x80). Length: 178804 (0x2ba74) bytes. + Adding .stack section. Offset: 178932 (0x2baf4). Length: 16384 (0x4000) bytes. Searching for .rel.X sections to add. TBF Header: version: 2 0x2 diff --git a/reproducible/reference_elf2tab_ubuntu-18.04.txt b/reproducible/reference_elf2tab_ubuntu-18.04.txt index 2571f3b..c57cb24 100644 --- a/reproducible/reference_elf2tab_ubuntu-18.04.txt +++ b/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 .stack section. Offset: 178868 (0x2bab4). Length: 16384 (0x4000) bytes. + Adding .text section. Offset: 128 (0x80). Length: 180148 (0x2bfb4) 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 .stack section. Offset: 178868 (0x2bab4). Length: 16384 (0x4000) bytes. + Adding .text section. Offset: 128 (0x80). Length: 180148 (0x2bfb4) 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 .stack section. Offset: 178868 (0x2bab4). Length: 16384 (0x4000) bytes. + Adding .text section. Offset: 128 (0x80). Length: 180148 (0x2bfb4) 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 .stack section. Offset: 178868 (0x2bab4). Length: 16384 (0x4000) bytes. + Adding .text section. Offset: 128 (0x80). Length: 180148 (0x2bfb4) bytes. + Adding .stack section. Offset: 180276 (0x2c034). Length: 16384 (0x4000) bytes. Searching for .rel.X sections to add. TBF Header: version: 2 0x2 diff --git a/run_desktop_tests.sh b/run_desktop_tests.sh index 07b652e..d812b22 100755 --- a/run_desktop_tests.sh +++ b/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 diff --git a/tools/heapviz/Cargo.toml b/tools/heapviz/Cargo.toml new file mode 100644 index 0000000..4300f7e --- /dev/null +++ b/tools/heapviz/Cargo.toml @@ -0,0 +1,14 @@ +[package] +name = "heapviz" +version = "0.1.0" +authors = [ + "Guillaume Endignoux ", +] +license = "Apache-2.0" +edition = "2018" + +[dependencies] +clap = "2.33.1" +lazy_static = "1.4.0" +ncurses = "5.99.0" +regex = "1" diff --git a/tools/heapviz/src/main.rs b/tools/heapviz/src/main.rs new file mode 100644 index 0000000..86dcb1e --- /dev/null +++ b/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 ") + .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::() + .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 { + // 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::().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 + ); + } +}