Bug: cannot print a big slice

ValouBambou commented 3 months ago

The log of a big Vec is buggy (it doesn't happen for a small one), for example, with this example code the log is not displayed.

#![no_std]
#![no_main]

extern crate alloc;
use alloc::vec;
use core::mem::MaybeUninit;
use embedded_alloc::Heap;
use embassy_executor::Spawner;
use defmt::println;
use {defmt_rtt as _, panic_probe as _};

#[global_allocator]
static HEAP: Heap = Heap::empty();

#[embassy_executor::main]
async fn main(_spawner: Spawner) {
    {
        // initialize the HEAP before using it
        const HEAP_SIZE: usize = 1024 * 100; // 100 kiB
        static mut HEAP_MEM: [MaybeUninit<u8>; HEAP_SIZE] = [MaybeUninit::uninit(); HEAP_SIZE];
        unsafe { HEAP.init(HEAP_MEM.as_ptr() as usize, HEAP_SIZE) }
    }
    let _p = embassy_rp::init(Default::default());

    let slice = vec![(i32::MAX, i32::MAX); 100];
    println!("slice = {:?}", slice);
    loop {}
}

The test setup that I used is a Raspberry Pi Pico with a debug probe using probe-rs and embassy. The version and features of the dependencies are these one:

defmt = { version = "0.3", features = ["alloc"] }
defmt-rtt = "0.4"
embedded-alloc = "0.5.1"

and embassy in patched with this commit hash "ad7d4494fad12f98c7e8e2b776bc12453a66be9a".

Urhengulas commented 3 months ago

Thank you for reporting the issue @ValouBambou. The vec format implementation just delegates to the slice implementation. Can you also observe the problem with a big slice?

I do not have the hardware at hand to test it, so I will try to reproduce it next week.

MathiasKoch commented 3 months ago

The default rtt buffer size in defmt is 1024 bytes. If you log more than this, the output is silently discarded. I think this is what you are seeing here.. You can configure the buffer size using the environment variable DEFMT_RTT_BUFFER_SIZE

See more here https://defmt.ferrous-systems.com/setup.html?highlight=Buffer#memory-use

ValouBambou commented 3 months ago

I can confirm that it is reproducible with slice instead of Vec.

Also, it doesn't really just silently discarded stuff (which is not a perfect solution in my mind, maybe truncating will be better behavior) but also alter some of the logs that came before. This is probably due to the fact that the buffer is not sent while it is not filled or something like so depending on the way it is implemented.

For example, adding these prints:

    let slice = &[(i32::MAX, i32::MAX); 100];
    println!("HELLO");
    println!("slice = {:?}", slice);
    println!("BYE");

leads to this output:

BYE

And I don't think this is the desirable behavior, it makes loses of the preceding logs and makes it harder to follow the chronological events when debugging for instance.

Urhengulas commented 3 months ago

@ValouBambou Does increasing the buffer size (as pointed out by @MathiasKoch) solve your problem?

ValouBambou commented 3 months ago

Yes it does. But in a more general way, maybe truncating will be a more desirable behavior. Also, there is a similar catch when trying to print inside a loop, where some logs are silently ignored.

Urhengulas commented 3 months ago

But in a more general way, maybe truncating will be a more desirable behavior. Also, there is a similar catch when trying to print inside a loop, where some logs are silently ignored.

I agree. Don't have capacity to work on it, but I am happy to review a PR :D

ValouBambou commented 3 months ago

I would be really happy to do it, but I may need some help to fully understand the code base and what part should be modified to implement this behavior.

ValouBambou commented 3 months ago

I'm not sure if it should be a modification in the defmt_rtt crate because that's the only place where the size of the buffer and the available size in the buffer is known. Or in the defmt crate because it is where slice are serialized.

Urhengulas commented 3 months ago

I actually do not know as well, I assume it needs to happen in the serialization process. Maybe @Dirbaio could give a hint, as the person who did the last overhaul of the serialization format?

Dirbaio commented 3 months ago

The default rtt buffer size in defmt is 1024 bytes. If you log more than this, the output is silently discarded. I think this is what you are seeing here..

this is not true at all (or shouldn't). what should be happening is:

println! call starts writing the huge slice to the buffer.
the buffer fills up
the println! sees buffer is full, and blocks. it stops writing more data to the buffer, but doesn't return.
the probe pops some data from the buffer
the println! sees there's now free space in the buffer, it fills it up and blocks again
the probe pops some data from the buffer
etc, until the whole frame is transferred

if this is not what's happening then there's a bug somewhere. Truncating the slice is not a fix, it's a workaround.

ValouBambou commented 1 month ago

I can't observe this correct behavior you described on my setup in some circumstances. The bug is triggered by trying to print too quickly a lot of messages, or with big slices. For example, this simple loop only prints the last iterations and skip the first ones.

for i in 0..1000 {
    println!("{}", i);
}

Produces these logs when using probe-rs run.

ValouBambou commented 1 month ago

And when doing 10x more iterations, the logs are even weirder:

Urhengulas commented 1 month ago

It might be the case that probe-rs does not put the RTT channel into blocking mode, which is the behaviour probe-run had. That could cause this problem, could it not?

ValouBambou commented 1 month ago

That's weird, from what I see in probe-rs source code (with grep) the only ChannelMode created is BlockIfFull which seems to be the default. I guess that this mode is supposed to have the same meaning as the previous blocking behavior of probe-run.

ValouBambou commented 1 month ago

I updated probe-rs and now got a similar behavior but with different logs. Here, instead of 10_000 lines, there are only 9_394. The missing one are the first 228 lines, which are skipped. And the rest are dropped randomly every 25 iterations in average (worst delta is 14 and best is 83).

Here is a little python script I used to get the numbers from the logs.

with open("tmp.log", "r") as f:
    nums = list(map(int, f.readlines()))
    print(f"{len(nums)} / 10_000 lines expected")
    first = nums[0]
    print(f"missing first {first} lines")
    missed = [miss for a, b in zip(nums, nums[1:]) for miss in range(a + 1, b)]
    print(f"and {len(missed)} lines during all other logs")
    step_miss = [b - a for a, b in zip(missed, missed[1:])]
    avg_miss = sum(step_miss) / len(step_miss)
    print(f"in average 1 miss every {int(avg_miss)} lines")
    print(f"at best 1 miss every {max(step_miss)} lines")
    print(f"at worst 1 miss every {min(step_miss)} lines")
    print(f"missed lines => {missed}")

and the logs used in attached file.

tmp.log

knurling-rs / defmt

Bug: cannot print a big slice #825