Hi Genodians,
I'm currently writing a time sensitive-program using Fiasco.OC as a kernel. For debugging purposes I wanted to use Genode::raw in order to avoid the overhead of Genode::log. However, my calls to raw() don't seem to print anything on the console. Is there something I need to enable/configure first?
Thanks in advance!
Cheers, Simon
Hello Simon,
On Thu, Oct 01, 2020 at 19:04:48 CEST, Simon Himmelbauer wrote:
I'm currently writing a time sensitive-program using Fiasco.OC as a kernel. For debugging purposes I wanted to use Genode::raw in order to avoid the overhead of Genode::log. However, my calls to raw() don't seem to print anything on the console. Is there something I need to enable/configure first?
For Genode::raw() to work on Fiasco.OC, the component needs the debug capability to access the kernel debugger for output. This may be a robustness/security risk in production systems and is, therefore, not enabled by default. The access can be enabled by adapting the code [1] and after recompilation all components can access the Fiasco kernel debugger.
[1] https://github.com/genodelabs/genode/blob/master/repos/base-foc/src/core/pla...
Happy coding
Simon Himmelbauer himmelba@in.tum.de writes:
I'm currently writing a time sensitive-program using Fiasco.OC as a kernel. For debugging purposes I wanted to use Genode::raw in order to avoid the overhead of Genode::log.
Although you confirmed that Christian's answer solved your problem you can look at trace logger and a feature to redirect logs to trace buffer. I used it to diagnose timing problems in USB driver for RPI and it may be useful for you too.
It is described in section "Redirection of LOG output to TRACE events" in release notes for versoin 20.05. In this case calls to log just write to memory eliminating any overhead and trace logger can read it asynchronously later and output to console.
Cheers, Tomasz
Hi Tomasz,
Thanks for your input! I plan on testing the software on an RPI in the future as well so this might prove useful.
Anyways, regarding your timing problems, how exactly did you measure them? My current setup consists of taking a start and stop timestamp via a timer-connection but I only seem to get milliseconds-precision (I tried using elapsed_us() but it seems to always produce "microsecond"-values ending with three zeroes.). I currently run everything inside QEMU so I don't know whether real hardware will simply fix this.
Cheers, Simon
On 02.10.20 14:32, Tomasz Gajewski wrote:
Simon Himmelbauer himmelba@in.tum.de writes:
I'm currently writing a time sensitive-program using Fiasco.OC as a kernel. For debugging purposes I wanted to use Genode::raw in order to avoid the overhead of Genode::log.
Although you confirmed that Christian's answer solved your problem you can look at trace logger and a feature to redirect logs to trace buffer. I used it to diagnose timing problems in USB driver for RPI and it may be useful for you too.
It is described in section "Redirection of LOG output to TRACE events" in release notes for versoin 20.05. In this case calls to log just write to memory eliminating any overhead and trace logger can read it asynchronously later and output to console.
Cheers, Tomasz
Simon Himmelbauer himmelba@in.tum.de writes:
Anyways, regarding your timing problems, how exactly did you measure them? My current setup consists of taking a start and stop timestamp via a timer-connection but I only seem to get milliseconds-precision (I tried using elapsed_us() but it seems to always produce "microsecond"-values ending with three zeroes.).
I didn't really need measuring elapsed time but the problem was that I needed logs to understand what is going on and enabling them was changing behavior. I thought it was important to not influence behavior with logs in your case too.
Cheers Tomasz
I see, thank you anyways!
Cheers, Simon
On 02.10.20 21:39, Tomasz Gajewski wrote:
Simon Himmelbauer himmelba@in.tum.de writes:
Anyways, regarding your timing problems, how exactly did you measure them? My current setup consists of taking a start and stop timestamp via a timer-connection but I only seem to get milliseconds-precision (I tried using elapsed_us() but it seems to always produce "microsecond"-values ending with three zeroes.).
I didn't really need measuring elapsed time but the problem was that I needed logs to understand what is going on and enabling them was changing behavior. I thought it was important to not influence behavior with logs in your case too.
Cheers Tomasz
Hi Simon,
On 02.10.20 15:24, Simon Himmelbauer wrote:
Anyways, regarding your timing problems, how exactly did you measure them? My current setup consists of taking a start and stop timestamp via a timer-connection but I only seem to get milliseconds-precision (I tried using elapsed_us() but it seems to always produce "microsecond"-values ending with three zeroes.). I currently run everything inside QEMU so I don't know whether real hardware will simply fix this.
apart from the lack of precision, the 'Timer::Session::elapsed_ms()' RPC function induces unwelcome overhead, in particular the context switch forth-and-back between your component and the timer driver and the timer driver's interaction with the physical timer device.
For capturing timing behavior at a higher precision and with much less overhead, you may find the 'Trace::timestamp()' utility useful. The function returns a platform-dependent timer tick value. On x86, this would be the time-stamp counter (TCS), on ARM it returns a CPU counter value.
As the value returned by 'Trace::timestamp()' depends on the platform (e.g., the CPU frequency), you will need to apply some kind of calibration. To determine the calibration factor, you may use the 'Timer::elapsed_ms' or 'Timer::elapsed_us' functions before running your actual tests, e.g., by measuring the number of timer ticks passed within one second.
As a heads-up, please regard the 'Trace::timestamp()' with a healthy dose of skepticism. In our experience, the values are not always perfectly proportional to real-world time. In particular,
- On the ARMv6-based Raspberry Pi, the counter value is increased only if the CPU is not idle.
- On some x86 platforms, the TCS values are not perfectly stable. In particular, the TCS values taken with different CPU cores cannot be assumed to correlate.
You can find the implementations of the 'Trace::timestamp' function at the base/include/spec/<arch>/trace/timestamp.h header, where <arch> is the CPU architecture (like arm_64 or x86_64).
Cheers Norman
-
Christian Helmuth -
Norman Feske -
Simon Himmelbauer -
Tomasz Gajewski