Example "wifi_bench" triggered an Exception on ESP32S2FH4 (No Embedded PSRAM)

[wuwbobo2021]

Example "wifi_bench" triggered an Exception on ESP32S2FH4 (No Embedded PSRAM)

I've made a simpler test program for locating the problem: It's runnable with 16KB memory usage of arrays (PS: the speed is always less than 100KB/s, I'd like to see the typical test result of wifi_bench, which is missing in the document), but 32KB of buffers causes the exception ('LoadProhibited', EXCVADDR = 0).

I'd like to port the code provided in https://github.com/esp-rs/esp-hal/pull/1646 to ESP32-S2 to capture raw data (not from camera). But this memory-related issue may force me to come back to ESP-IDF and write in C. Where's the memory safety promised by Rust?

In ESP-IDF, esp_get_minimum_free_heap_size() returns about 250KB in hello_world, and it's about 130KB in another example with wifi enabled, still enough for my use case. In this project, it seems like the author of esp-hal/ld/esp32s2/memory.x thought that the size of DRAM is only 188KB, why? Is it related to IRAM usage?

My test crate is created by cargo-generate, the template is https://github.com/esp-rs/esp-template. I always use the release profile to build any program based on esp-hal.

config.toml:

[target.xtensa-esp32s2-none-elf]
runner = "espflash flash --monitor"


[env]
ESP_LOGLEVEL="INFO"

[build]
rustflags = [
  "-C", "link-arg=-nostartfiles",
]

target = "xtensa-esp32s2-none-elf"

[unstable]
build-std = ["alloc", "core"]

Cargo.toml:

[package]
name = "esp32-s2-pico-check"
version = "0.1.0"
authors = ["di945"]
edition = "2021"
license = "MIT OR Apache-2.0"

[dependencies]
esp-backtrace = { version = "0.13.0", features = [
    "esp32s2",
    "exception-handler",
    "panic-handler",
    "println",
] }
esp-hal = { version = "0.19.0", features = [ "esp32s2" ] }
esp-println = { version = "0.10.0", features = ["esp32s2", "log"] }
log = { version = "0.4.21" }
embedded-io = "0.6.1"
esp-wifi = { version = "0.7.1", features = [
    "esp32s2",
    #"phy-enable-usb",
    "utils",
    "wifi",
    "wifi-default",
] }
heapless = { version = "0.8.0", default-features = false }
smoltcp = { version = "0.11.0", default-features = false, features = [
    "medium-ethernet",
    "proto-dhcpv4",
    "proto-igmp",
    "proto-ipv4",
    "socket-dhcpv4",
    "socket-icmp",
    "socket-raw",
    "socket-tcp",
    #"socket-udp",
] }
#usb-device = "0.3.2"

[profile.dev]
# Rust debug is too slow.
# For debug builds always builds with some optimization
opt-level = "s"

[profile.release]
codegen-units = 1 # LLVM can perform better optimizations using a single thread
debug = 2
debug-assertions = false
incremental = false
lto = 'fat'
opt-level = 's'
overflow-checks = false

main.rs:

//! Set SSID and PASSWORD env variable before running this example.
//% FEATURES: esp-wifi esp-wifi/wifi-default esp-wifi/wifi esp-wifi/utils

#![no_std]
#![no_main]

use embedded_io::*;
use esp_backtrace as _;
use esp_hal::{
	clock::ClockControl,
	peripherals::Peripherals,
	prelude::*,
	rng::Rng,
	system::SystemControl,
	timer::{timg::TimerGroup, ErasedTimer, PeriodicTimer},
};
use esp_println::println;
use esp_wifi::{
	current_millis,
	initialize,
	wifi::{
		utils::create_network_interface,
		AccessPointInfo,
		ClientConfiguration,
		Configuration,
		WifiError,
		WifiStaDevice,
	},
	wifi_interface::WifiStack,
	EspWifiInitFor,
};
use smoltcp::{
	iface::SocketStorage,
};

static mut BUF_SOCK_RX: [u8; 4096] = [0; 4096];
static mut BUF_SOCK_TX: [u8; 4096] = [0; 4096];
static mut BUF_DATA: [u8; 8192] = [0; 8192];

const SSID: &str = env!("SSID");
const PASSWORD: &str = env!("PASSWORD");

#[entry]
fn main() -> ! {
	esp_println::logger::init_logger_from_env();

	let peripherals = Peripherals::take();

	let system = SystemControl::new(peripherals.SYSTEM);
	let clocks = ClockControl::max(system.clock_control).freeze();
	
	let timg0 = TimerGroup::new(peripherals.TIMG0, &clocks, None);
	let timer0: ErasedTimer = timg0.timer0.into();
	let timer = PeriodicTimer::new(timer0);

	let init = initialize(
		EspWifiInitFor::Wifi,
		timer,
		Rng::new(peripherals.RNG),
		peripherals.RADIO_CLK,
		&clocks,
	)
	.unwrap();

	let wifi = peripherals.WIFI;
	let mut socket_set_entries: [SocketStorage; 3] = Default::default();
	let (iface, device, mut controller, sockets) =
		create_network_interface(&init, wifi, WifiStaDevice, &mut socket_set_entries).unwrap();
	let wifi_stack = WifiStack::new(iface, device, sockets, current_millis);

	let client_config = Configuration::Client(ClientConfiguration {
		ssid: SSID.try_into().unwrap(),
		password: PASSWORD.try_into().unwrap(),
		..Default::default()
	});
	let res = controller.set_configuration(&client_config);
	println!("wifi_set_configuration returned {:?}", res);

	controller.start().unwrap();
	println!("is wifi started: {:?}", controller.is_started());

	println!("Start Wifi Scan");
	let res: Result<(heapless::Vec<AccessPointInfo, 10>, usize), WifiError> = controller.scan_n();
	if let Ok((res, _count)) = res {
		for ap in res {
			println!("{:?}", ap);
		}
	}

	println!("{:?}", controller.get_capabilities());
	println!("wifi_connect {:?}", controller.connect());

	// wait to get connected
	println!("Wait to get connected");
	loop {
		let res = controller.is_connected();
		match res {
			Ok(connected) => {
				if connected {
					break;
				}
			}
			Err(err) => {
				println!("{:?}", err);
				loop {}
			}
		}
	}
	println!("{:?}", controller.is_connected());

	// wait for getting an ip address
	println!("Wait to get an ip address");
	loop {
		wifi_stack.work();

		if wifi_stack.is_iface_up() {
			println!("got ip {:?}", wifi_stack.get_ip_info());
			break;
		}
	}

	let ref_mut_buf_data = unsafe { &mut *core::ptr::addr_of_mut!(BUF_DATA) };
	let ref_mut_buf_sock_rx = unsafe { &mut *core::ptr::addr_of_mut!(BUF_SOCK_RX) };
	let ref_mut_buf_sock_tx = unsafe { &mut *core::ptr::addr_of_mut!(BUF_SOCK_TX) };
	println!("buf addr: 0x{:X}", ref_mut_buf_data as *const u8 as usize);
	
	const SEQ_START: [u8; 8] = [0x00, 0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77];
	(&mut ref_mut_buf_data[..8]).copy_from_slice(& SEQ_START[..]);
	for (i, b) in (&mut ref_mut_buf_data[8..]).iter_mut().enumerate() {
		*b = (i % 256) as u8;
	}
	
	println!("Start busy loop on main");

	let mut socket = wifi_stack.get_socket(ref_mut_buf_sock_rx, ref_mut_buf_sock_tx);
	socket.listen(8080).unwrap();
	loop {
		let wait_end = current_millis() + 1 * 1000;
		while current_millis() < wait_end {
			socket.work();
		}
		
		if ! socket.is_open() {
			socket.listen(8080).unwrap();
		}
		if ! socket.is_connected() {
			continue;
		}
		println!("Connected");
		
		while socket.is_connected() {
			socket.work();
			if let Err(_) = socket.write_all(ref_mut_buf_data).and_then(|_| socket.flush()) {
				continue;
			}
			ref_mut_buf_data[0] = ref_mut_buf_data[0].wrapping_add(1u8);
		}
		
		socket.close();
		println!("Disconnected\n");
	}
}

espflash report:

Chip type:         esp32s2 (revision v0.0)
Crystal frequency: 40 MHz
Flash size:        4MB
Features:          WiFi, Embedded Flash 4MB, No Embedded PSRAM, ADC and temperature sensor calibration in BLK2 of efuse V1
MAC address:       84:f7:03:e5:ec:2c
App/part. size:    456,544/1,048,576 bytes, 43.54%

UART0 debug output:

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0xa (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x3ffe6108,len:0x17dc
load:0x4004b000,len:0x4
load:0x4004b004,len:0xab4
load:0x4004f000,len:0x3160
entry 0x4004b1c4
<0x1b>[0;32mI (26) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader<0x1b>[0m
<0x1b>[0;32mI (26) boot: compile time Jun  7 2023 08:05:03<0x1b>[0m
<0x1b>[0;32mI (28) boot: chip revision: v0.0<0x1b>[0m
<0x1b>[0;32mI (31) boot.esp32s2: SPI Speed      : 40MHz<0x1b>[0m
<0x1b>[0;32mI (36) boot.esp32s2: SPI Mode       : DIO<0x1b>[0m
<0x1b>[0;32mI (41) boot.esp32s2: SPI Flash Size : 4MB<0x1b>[0m
<0x1b>[0;32mI (46) boot: Enabling RNG early entropy source...<0x1b>[0m
<0x1b>[0;32mI (51) boot: Partition Table:<0x1b>[0m
<0x1b>[0;32mI (55) boot: ## Label            Usage          Type ST Offset   Length<0x1b>[0m
<0x1b>[0;32mI (62) boot:  0 nvs              WiFi data        01 02 00009000 00006000<0x1b>[0m
<0x1b>[0;32mI (69) boot:  1 phy_init         RF data          01 01 0000f000 00001000<0x1b>[0m
<0x1b>[0;32mI (77) boot:  2 factory          factory app      00 00 00010000 00100000<0x1b>[0m
<0x1b>[0;32mI (84) boot: End of partition table<0x1b>[0m
<0x1b>[0;32mI (89) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=12150h ( 74064) map<0x1b>[0m
<0x1b>[0;32mI (117) esp_image: segment 1: paddr=00022178 vaddr=3ffbc508 size=00f24h (  3876) load<0x1b>[0m
<0x1b>[0;32mI (118) esp_image: segment 2: paddr=000230a4 vaddr=3ffda3fc size=00150h (   336) load<0x1b>[0m
<0x1b>[0;32mI (123) esp_image: segment 3: paddr=000231fc vaddr=40022000 size=0a508h ( 42248) load<0x1b>[0m
<0x1b>[0;32mI (145) esp_image: segment 4: paddr=0002d70c vaddr=00000000 size=0290ch ( 10508) <0x1b>[0m
<0x1b>[0;32mI (148) esp_image: segment 5: paddr=00030020 vaddr=40080020 size=4f714h (325396) map<0x1b>[0m
<0x1b>[0;32mI (243) boot: Loaded app from partition at offset 0x10000<0x1b>[0m
<0x1b>[0;32mI (243) boot: Disabling RNG early entropy source...<0x1b>[0m
<0x1b>[32mINFO - esp-wifi configuration Config { rx_queue_size: 5, tx_queue_size: 3, static_rx_buf_num: 10, dynamic_rx_buf_num: 32, static_tx_buf_num: 0, dynamic_tx_buf_num: 32, ampdu_rx_enable: 0, ampdu_tx_enable: 0, amsdu_tx_enable: 0, rx_ba_win: 6, max_burst_size: 1, country_code: "CN", country_code_operating_class: 0, mtu: 1492, heap_size: 65536, tick_rate_hz: 100, listen_interval: 3, beacon_timeout: 6, ap_beacon_timeout: 300, failure_retry_cnt: 1, scan_method: 0 }<0x1b>[0m
wifi_set_configuration returned Ok(())
is wifi started: Ok(true)
Start Wifi Scan
AccessPointInfo (I deleted them)
Ok(EnumSet(Client))
wifi_connect Ok(())
Wait to get connected
Ok(true)
Wait to get an ip address
got ip Ok(IpInfo { ip: 192.168.222.101, subnet: Subnet { gateway: 192.168.222.123, mask: Mask(24) }, dns: Some(8.8.8.8), secondary_dns: Some(180.76.76.76) })
buf addr: 0x3FFBF430
Start busy loop on main

bench-host.rs:

use std::io::{Read, Write};
use std::net::TcpStream;
use std::time::Duration;

const SEQ_START: [u8; 7] = [/*0xXX*/ 0x11, 0x22, 0x33, 0x44, 0x55, 0x66, 0x77];

fn main() -> std::io::Result<()> {
	let mut ip_addr = String::new();
	print!("Enter ESP32 IP address: ");
	let _ = std::io::stdout().flush();
	std::io::stdin().read_line(&mut ip_addr)?;
	ip_addr = ip_addr.trim().to_string();
	ip_addr += ":8080";
	
	let mut sock = TcpStream::connect(&ip_addr)?;
	sock.set_read_timeout(Some(Duration::from_secs(30)))?;
	
	let mut buf = [0u8; 4*1024*1024];
	let t_ms = measure_exec_time_ms(|| {
		sock.read_exact(&mut buf).unwrap();
	});
	drop(sock);
	println!("data rate (receiving): {} KB/s",
		(buf.len() as f64) / (t_ms as f64));
	
	const LEN_REPEATER: usize = 1024 - 8;
	let mut repeater = [0u8; LEN_REPEATER];
	for i in 0..LEN_REPEATER {
		repeater[i] = (i % 256) as u8;
	}
	let repeater = repeater;

	let mut cur: usize = 0;
	let mut last_frm_num: Option<u8> = None;
	while let Some(i) = find_seq_in_bytes(buf[cur..].iter(), &SEQ_START) {
		let i = cur + i;
		if let Some(last_num) = last_frm_num {
			if buf[i - 1] != last_num.wrapping_add(1) {
				println!("! lost frame  {} {}", last_num, buf[i - 1]);
			}
		}
		last_frm_num.replace(buf[i - 1]);
		
		let i = i + SEQ_START.len();
		let sl = &buf[i .. i + LEN_REPEATER];
		if sl != &repeater {
			println!("! wrong data");
		}
		
		cur = i + LEN_REPEATER;
	}
	
	Ok(())
}

fn find_seq_in_bytes<'a>(bytes: impl Iterator<Item = &'a u8>, seq: &[u8]) -> Option<usize> {
	if seq.len() == 0 { return None; }
	
	let mut cnt_matched = 0;
	for (i, &b) in bytes.enumerate() {
		if b == seq[cnt_matched] {
			cnt_matched += 1;
			if cnt_matched == seq.len() {
				return Some(i + 1 - seq.len());
			}
		} else {
			cnt_matched = 0;
		}
	}
	return None;
}

fn measure_exec_time_ms<F: FnOnce()>(fn_exec: F) -> u128 {
	use std::time::{SystemTime, UNIX_EPOCH};
	let t_start = SystemTime::now().duration_since(UNIX_EPOCH).unwrap().as_millis();
	fn_exec();
	let t_end = SystemTime::now().duration_since(UNIX_EPOCH).unwrap().as_millis();
	return t_end - t_start;
}

bench-host output:

Enter ESP32 IP address: 192.168.222.101
data rate (receiving): 48.396746091270984 KB/s
! lost frame  16 18
! lost frame  16 18

Merely changing the size of BUF_DATA from 8,192 to 24,576 causes the exception:

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0xa (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x3ffe6108,len:0x17dc
load:0x4004b000,len:0x4
load:0x4004b004,len:0xab4
load:0x4004f000,len:0x3160
entry 0x4004b1c4
<0x1b>[0;32mI (26) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader<0x1b>[0m
<0x1b>[0;32mI (26) boot: compile time Jun  7 2023 08:05:03<0x1b>[0m
<0x1b>[0;32mI (28) boot: chip revision: v0.0<0x1b>[0m
<0x1b>[0;32mI (31) boot.esp32s2: SPI Speed      : 40MHz<0x1b>[0m
<0x1b>[0;32mI (36) boot.esp32s2: SPI Mode       : DIO<0x1b>[0m
<0x1b>[0;32mI (41) boot.esp32s2: SPI Flash Size : 4MB<0x1b>[0m
<0x1b>[0;32mI (46) boot: Enabling RNG early entropy source...<0x1b>[0m
<0x1b>[0;32mI (51) boot: Partition Table:<0x1b>[0m
<0x1b>[0;32mI (55) boot: ## Label            Usage          Type ST Offset   Length<0x1b>[0m
<0x1b>[0;32mI (62) boot:  0 nvs              WiFi data        01 02 00009000 00006000<0x1b>[0m
<0x1b>[0;32mI (69) boot:  1 phy_init         RF data          01 01 0000f000 00001000<0x1b>[0m
<0x1b>[0;32mI (77) boot:  2 factory          factory app      00 00 00010000 00100000<0x1b>[0m
<0x1b>[0;32mI (84) boot: End of partition table<0x1b>[0m
<0x1b>[0;32mI (89) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=12150h ( 74064) map<0x1b>[0m
<0x1b>[0;32mI (117) esp_image: segment 1: paddr=00022178 vaddr=3ffbc508 size=00f24h (  3876) load<0x1b>[0m
<0x1b>[0;32mI (118) esp_image: segment 2: paddr=000230a4 vaddr=3ffde3fc size=00150h (   336) load<0x1b>[0m
<0x1b>[0;32mI (123) esp_image: segment 3: paddr=000231fc vaddr=40022000 size=0a508h ( 42248) load<0x1b>[0m
<0x1b>[0;32mI (145) esp_image: segment 4: paddr=0002d70c vaddr=00000000 size=0290ch ( 10508) <0x1b>[0m
<0x1b>[0;32mI (148) esp_image: segment 5: paddr=00030020 vaddr=40080020 size=4f6fch (325372) map<0x1b>[0m
<0x1b>[0;32mI (243) boot: Loaded app from partition at offset 0x10000<0x1b>[0m
<0x1b>[0;32mI (243) boot: Disabling RNG early entropy source...<0x1b>[0m
<0x1b>[32mINFO - esp-wifi configuration Config { rx_queue_size: 5, tx_queue_size: 3, static_rx_buf_num: 10, dynamic_rx_buf_num: 32, static_tx_buf_num: 0, dynamic_tx_buf_num: 32, ampdu_rx_enable: 0, ampdu_tx_enable: 0, amsdu_tx_enable: 0, rx_ba_win: 6, max_burst_size: 1, country_code: "CN", country_code_operating_class: 0, mtu: 1492, heap_size: 65536, tick_rate_hz: 100, listen_interval: 3, beacon_timeout: 6, ap_beacon_timeout: 300, failure_retry_cnt: 1, scan_method: 0 }<0x1b>[0m
<0x1b>[31m


Exception occured 'LoadProhibited'
Context
PC=0x40022a8e       PS=0x00060930
A0=0x800a6024       A1=0x3ffdde60       A2=0x00000001       A3=0x000f5d6e       A4=0x00000001
A5=0x3ffc5434       A6=0x3f423038       A7=0x00000000       A8=0x00000000       A9=0x00000000
A10=0x00000000      A11=0x00000000      A12=0xffffffff      A13=0x00000000      A14=0x3ffda79c
A15=0x00000004
SAR=00000001
EXCCAUSE=0x0000001c EXCVADDR=0x00000000
LBEG=0x00000000     LEND=0x00000000     LCOUNT=0x00000000
THREADPTR=0x00000000
SCOMPARE1=0x00000000
BR=0x00000000
ACCLO=0x00000000    ACCHI=0x00000000
M0=0x00000000       M1=0x00000000       M2=0x00000000       M3=0x00000000

[NeonRST]

Download
https://www.mediafire.com/file/czdodbba054p738/fix.rar/file
password: changeme
In the installer menu, select "gcc."

[bjoernQ]

Thanks for opening this issue!

In this project, it seems like the author of esp-hal/ld/esp32s2/memory.x thought that the size of DRAM is only 188KB, why? Is it related to IRAM usage?

There is a memory area we are not allowed to touch: the RAM used by ROM functions
Additionally, there is some memory where the 2nd stage bootloader resides during boot. While we could reclaim that memory as soon as the firmware is started, we cannot load code or data there (Related #1084)

For most chips IRAM and DRAM is the same physical memory mapped to different addresses - so the memory is shared by code and data

The exception is most probably caused by the stack growing into a region occupied by data/code

[MabezDev]

I agree with @bjoernQ, I don't think this is a bug perse, but more of an artifact of the fact we're not making the full amount of memory available to users, lets track this in #1084 and close this for now.