4 ms·

I've used DEBUG trace in a production system by capturing it into a circular buffer. If you hit an error you dump it, otherwise it's thrown away. It's gives y

I've used DEBUG trace in a production system by capturing it into a circular buffer. If you hit an error you dump it, otherwise it's thrown away. It's gives you wonderful visibility when just when you need it: which is when the system fails. The difficulty is the run time cost. While capturing the raw data into a circular buffer is pretty cheap, formatting it the way the logging system needs is expensive. The workaround is to defer the formatting until you need to spit it out. Most logging systems don't let you defer formatting, so you end up having to roll you own. It's worthwhile to do that IMO. As for the articles thesis you own need two debug levels: seems wrong to me. If you look at it from the perspective of target uses, there seem to be at least three levels. There is "I've died for this reason". That's CRITICAL. Then there is the user of your code, who is trying to debug it's interactions with other systems. That's INFO. Finally there is the person trying to debug the internals. That's DEBUG. In reality there seems to be a fourth useful level: I've got bad inputs or in a bad state, but I'm continuing anyway. Examples are API calls with bad parameters or a storage system running low of space. That's WARN.

talldrinkofwhat 3y ago
This sounds extremely appealing as I either have to take the performance hit and nose through the entire debug log to get to where the error occurred, or have errors occur and not be able to reconstruct the events that drove them. Any tips on rolling your own? My first whack would probably be treating it like a packed message, e.g. <start_char> <n_packed_bytes> <time> <file> <line> <n_args> <arg1_type><arg1_raw_dump> ... <format_str> with everything aside from the format string having agreed upon byte-counts, and probably have the file names getting dumped to a lookup chart. There's probably something more elegant, but I've never been good at straying too far eclectic.
- SAI_Peregrinus 3y ago
  Ferrous Systems made defmt[1] for Rust. The linked design page details the inner workings. One trick is that even the format string is packed into a lookup table. They're all stored in a lookup table in a special .elf section, and only the index into that table is logged. So it's more like <format string index> <[length], n packed bytes for first variable> <[length], n packed bytes for second variable>… etc. Some types don't need a length, if not needed it is omitted. There's no need to transmit the file, line, or number of args because that's all in the lookup table, indexed just like the format string! E.g. a slice needs a length. defmt::error!("Data: {=[u8]}!", [0, 1, 2]); // on the wire: [1, 3, 0, 1, 2] // string index ^ ^ ^^^^^^^ the slice data // LEB128(length) ^ LEB128[2] is the same compressed integer encoding scheme used by DWARF & WASM. The entire "Data: {=[u8]}!" format string is just one byte on the wire (assuming it's in the first 255 or fewer log statements, the index is also LEB128 compressed.) [1] https://defmt.ferrous-systems.com/design https://defmt.ferrous-systems.com/design [2] https://en.wikipedia.org/wiki/LEB128 https://en.wikipedia.org/wiki/LEB128
withinboredom 3y ago
Came here to say exactly this. Seeing how an error came about is exceptional.

talldrinkofwhat 3y ago

This sounds extremely appealing as I either have to take the performance hit and nose through the entire debug log to get to where the error occurred, or have errors occur and not be able to reconstruct the events that drove them. Any tips on rolling your own? My first whack would probably be treating it like a packed message, e.g. <start_char> <n_packed_bytes> <time> <file> <line> <n_args> <arg1_type><arg1_raw_dump> ... <format_str> with everything aside from the format string having agreed upon byte-counts, and probably have the file names getting dumped to a lookup chart. There's probably something more elegant, but I've never been good at straying too far eclectic.

SAI_Peregrinus 3y ago
Ferrous Systems made defmt[1] for Rust. The linked design page details the inner workings. One trick is that even the format string is packed into a lookup table. They're all stored in a lookup table in a special .elf section, and only the index into that table is logged. So it's more like <format string index> <[length], n packed bytes for first variable> <[length], n packed bytes for second variable>… etc. Some types don't need a length, if not needed it is omitted. There's no need to transmit the file, line, or number of args because that's all in the lookup table, indexed just like the format string! E.g. a slice needs a length. defmt::error!("Data: {=[u8]}!", [0, 1, 2]); // on the wire: [1, 3, 0, 1, 2] // string index ^ ^ ^^^^^^^ the slice data // LEB128(length) ^ LEB128[2] is the same compressed integer encoding scheme used by DWARF & WASM. The entire "Data: {=[u8]}!" format string is just one byte on the wire (assuming it's in the first 255 or fewer log statements, the index is also LEB128 compressed.) [1] https://defmt.ferrous-systems.com/design https://defmt.ferrous-systems.com/design [2] https://en.wikipedia.org/wiki/LEB128 https://en.wikipedia.org/wiki/LEB128

withinboredom 3y ago

Came here to say exactly this. Seeing how an error came about is exceptional.