Closed m42uko closed 9 months ago
Quoting your reply on #111 (to keep the msleep discussion in one thread):
I haven't had time to look at your work yet, but regarding the msleep issue, there's one thing I would check first. At least in Zephyr 2.4.0, there's a bug that causes mul operations to be emitted in the library code even if the Kconfig settings says not to use hard mul and div. Not sure if this is the problem, but you can e.g. check the compiled zephyr.lst and see if there are any mul operations present.
I first tried on v2.4.0 and ran into the MUL bug. Without any fix (i.e. with "illegal" MULs in the binary), k_msleep
sleeps for zero time (returns immediately), with your fix from https://github.com/olofk/serv/issues/102#issuecomment-1667263644, it shows the same behavior as vanilla 3.5.0. I haven't checked that there are really no more MULs present. I can look into that in the upcoming days just to make sure.
I checked now with 2.4.0 and I can reproduce the issue. TBH, I never really understood how this timer API is supposed to work, so there's a fair chance I'm doing something strange but I can't see what it is right away. Will need some debugging. In case you haven't seen already, you can run with --trace_pc
and --vcd
to dump the PC and waveform of all signals respectively.
--trace_pc
generates a trace.bin
in the work root. You can this Python script by passing the Zephyr .elf file as the first argument and trace.bin as the second to generate a listing of how SERV jumps between functions. It's not the best debug tool out there but can be helpful.
Ooooh nice, thanks for the tips with debugging this. I'll see whether I can figure something out. (I'll probably get to it only next weekend though.)
I think I found the issue. sys_clock_driver_init
(formerly `z_clock_driver_init') is never called. I added the corresponding macro as part of my v3.5.0 PR.
diff --git a/zephyr/drivers/timer/serv_timer.c b/zephyr/drivers/timer/serv_timer.c
index 1691fa1..2039217 100644
--- a/zephyr/drivers/timer/serv_timer.c
+++ b/zephyr/drivers/timer/serv_timer.c
@@ -122,3 +122,6 @@ uint32_t sys_timer_cycle_get_32(void)
{
return mtime();
}
+
+SYS_INIT(sys_clock_driver_init, PRE_KERNEL_2,
+ CONFIG_SYSTEM_CLOCK_INIT_PRIORITY);
I haven't verified that the timing checks out yet though.
Verified timing on CMOD-A7 HW (Xilinx Artix-7 15T): Looks good! Checked only by looking at a blinking LED, so I didn't check down to the microsecond, but I think that's good enough (for now).
Well spotted! I'll do a proper review of #111 as soon as I can
Cool, thanks!
Oh oh, actually it's not quite fixed yet. After running the design for a few minutes (~10 minutes is enough, probably less), the application freezes again. Probably something to do with the timer overflowing. I haven't had the time to look at the code yet though.
I think this is a problem in the Verilog timer. Take the following example which resets the Verilog timer close to its overflow value (and adds some debugging):
diff --git a/servant/servant_timer.v b/servant/servant_timer.v
index 45306e9..656c1cd 100644
--- a/servant/servant_timer.v
+++ b/servant/servant_timer.v
@@ -23,15 +23,21 @@ module servant_timer
o_wb_dat[HIGH:0] = mtimeslice;
end
+ always @(posedge o_irq) begin
+ $display("IRQ @0x%x | 0x%x", mtime, mtimecmp);
+ end
+
always @(posedge i_clk) begin
- if (i_wb_cyc & i_wb_we)
+ if (i_wb_cyc & i_wb_we) begin
mtimecmp <= i_wb_dat[HIGH:0];
+ $display("set irq = 0x%x", i_wb_dat[HIGH:0]);
+ end
mtime <= mtime + 'd1;
o_irq <= (mtimeslice - mtimecmp >= 0);
if (RESET_STRATEGY != "NONE")
if (i_rst) begin
- mtime <= 0;
- mtimecmp <= 0;
+ mtime <= 4293916296;
+ mtimecmp <= 4293916296;
end
end
endmodule
If you then run my loopy hello_world
, you get:
make: Nothing to be done for 'all'.
Loading RAM from /home/markus/workspace/hello.hex
IRQ @0xffeff688 | 0xffeff688
set irq = 0xfff16059
set irq = 0xfff16059
IRQ @0xfff1605a | 0xfff16059
*** Booting Zephyr OS build zephyr-v3.5.0 ***
Hello World! service
set irq = 0xfffffc80
set irq = 0xfffffc80
IRQ @0xfffffc81 | 0xfffffc80
set irq = 0x00000900
set irq = 0x00000900
set irq = 0x00009280
set irq = 0x00009280
set irq = 0x00012240
set irq = 0x00012240
set irq = 0x0001abc0
set irq = 0x0001abc0
set irq = 0x00023b80
set irq = 0x00023b80
set irq = 0x0002cb40
set irq = 0x0002cb40
set irq = 0x00035b00
set irq = 0x00035b00
set irq = 0x0003eac0
set irq = 0x0003eac0
set irq = 0x00047a80
set irq = 0x00047a80
set irq = 0x00050a40
set irq = 0x00050a40
set irq = 0x00059a00
set irq = 0x00059a00
set irq = 0x00062380
set irq = 0x00062380
set irq = 0x0006b340
set irq = 0x0006b340
set irq = 0x00074300
set irq = 0x00074300
set irq = 0x0007d2c0
set irq = 0x0007d2c0
set irq = 0x00086280
set irq = 0x00086280
[... many more, they are printed immediately, IRQ is permanently active]
PS: I think #109 was supposed to address this, but I do not see how this makes a difference. Example 4-bit timer, max count 15.
Without having thought it through, wouldn't the following be the proper fix (and even reduce logic):
mtime
always increments 1 (no change)mtime
== mtimecmp
-> set IRQ (compare equal, set latching IRQ flag)OR: As a more extreme alternative, change the timer to a self-resetting kind when it reaches cmp (auto retrigger). Advantage: In a tickful kernel, we wouldn't have to do any math in the IRQ (which is important, because there are divisions and multiplications!) Disadvantage: I'll have to check, but we might lose support of tickless kernels, but I'm not sure.
Good debugging! Yes, #109 was supposed to fix this, but in hindsight I should definitely have checked myself that it worked correctly. I don't have any strong opinions on what kind of timer we want to have. The idea was to have a 32-bit timer, but otherwise follow the RISC-V machine timer as closely as possible to make the software support easier. Not sure if I succeeded in that. I agree there's an alarming number of math operations in the IRQ handler, and avoiding those sounds like a good idea. And I'm not sure I understand the implications of a tickless kernel, tbh. Power savings seems to be one thing, but there might be other benefits as well?
A third option could be to just implement a proper 64-bit RISC-V machine timer instead. It will cost a little bit more, but since it's an optional feature outside of the CPU, it's not the end of the world. The 2018 SoftCPU contest is already over by now and that was really the main reason for keeping down the size of the whole SoC.
Actually, #109 may be correct after all, and the report above might just be related to flawed testing. If I initialize the last_count
variable properly upon boot (instead of assuming it to be zero), it seems to work fine. Doesn't explain the "stops working after 10 mins" though....
diff --git a/zephyr/drivers/timer/serv_timer.c b/zephyr/drivers/timer/serv_timer.c
index 2039217..d48b771 100644
--- a/zephyr/drivers/timer/serv_timer.c
+++ b/zephyr/drivers/timer/serv_timer.c
@@ -60,7 +60,8 @@ static void timer_isr(void *arg)
int sys_clock_driver_init()
{
IRQ_CONNECT(RISCV_MACHINE_TIMER_IRQ, 0, timer_isr, NULL, 0);
- set_mtimecmp(mtime() + (uint32_t)CYC_PER_TICK);
+ last_count = mtime();
+ set_mtimecmp(last_count + (uint32_t)CYC_PER_TICK);
irq_enable(RISCV_MACHINE_TIMER_IRQ);
return 0;
}
(Added that change to my PR.)
I can think of a couple of different strategies. One would be to bisect between 2.4 and 3.5 to figure out where it stops working. Or did you say it's not working with 2.4 either? It sucks if we need to wait ten minutes for it to display the problem.
Another way would be to compare the soc support files in serv with the ones upstream and see if there is some issue there.
Replacing the serv_timer with a real risc-v machine timer is probably also a good idea to avoid having to carry our own driver. I started working on that a bit. Will push something later. Also just pushed a branch with some helpful debug registers to make troubleshooting with waveforms slightly less awful https://github.com/olofk/serv/tree/dbg
As noted in PR #111 (https://github.com/olofk/serv/pull/111#issuecomment-1847374609), this problems seems to be related to the toolchain emitting invalid MUL instructions (as part of picolibc, even if disabled), breaking the timing calculations. The driver and Verilog appears to be fine.
Hi,
I modified the default
hello_world
sample program to print the Hello World! message in a loop with a delay as follows:However, when I run this, I only get a single Hello World printout (this happens for both Zephyr v3.5.0 and v2.4.0):
Can you reproduce this / is this a known limitation of servant/service?
Thanks! Markus