Error in timertool example

[darnuria]

Hello, thanks for the work I used it for an processor and assembler introduction course it's great. :)

PR: #79
I got an error while trying to execute example/timertool.s

Error in /home/darnuria/blog_perso/cours_riscV/timer.asm line 26 column 10: "time": operand is of incorrect type
Error in /home/darnuria/blog_perso/cours_riscV/timer.asm line 50 column 9: "time": operand is of incorrect type

So I fixed the example at least the syntax error. The error may be du to the fact that a CSR is called time.

But after that the example seems to make rars unresponsive.

Here a small contribution for at least fixing the name issue

[darnuria]

I just fixed the naming error the unresponsive problem is still here, and maybe it's a more complex problem in the way Rars manage label and internal names.

[TheThirdOne]

Thanks for making a pull request to update the example. I didn't notice i broke it when I introduced the time control and status register in f0d67c2.

I am not sure I see the same unresponsiveness as you do, but I have seen some behavior that is not correct and will investigate.

@zacharyselk, this breaking is probably my fault, but if you want to investigate your help would be appreciated.

[TheThirdOne]

An error log from my terminal:

Exception in thread "Timer-3" java.util.ConcurrentModificationException
	at java.util.Vector$Itr.checkForComodification(Vector.java:1210)
	at java.util.Vector$Itr.next(Vector.java:1163)
	at rars.riscv.hardware.Memory.notifyAnyObservers(Memory.java:1154)
	at rars.riscv.hardware.Memory.setRawWord(Memory.java:479)
	at rars.tools.TimerTool.updateMMIOControlAndData(TimerTool.java:283)
	at rars.tools.TimerTool.access$700(TimerTool.java:50)
	at rars.tools.TimerTool$Tick.run(TimerTool.java:244)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
Exception in thread "RISCV" java.lang.AssertionError: Traps cannot be handled by the interupt handler
	at rars.simulator.Simulator$SimThread.handleInterrupt(Simulator.java:292)
	at rars.simulator.Simulator$SimThread.run(Simulator.java:419)
	at java.lang.Thread.run(Thread.java:748)
Exception in thread "RISCV" java.lang.AssertionError: Traps cannot be handled by the interupt handler
	at rars.simulator.Simulator$SimThread.handleInterrupt(Simulator.java:292)
	at rars.simulator.Simulator$SimThread.run(Simulator.java:419)
	at java.lang.Thread.run(Thread.java:748)

[TheThirdOne]

It seems that these two assertions are wrong, and are the reason this doesn't work. Running rars without assertions enabled or fixing these to test for 0x80000000 instead of 0x10000000 and != instead of == seems to restore the intended behavior.

rars/src/rars/simulator/Simulator.java

Lines 292 to 296 in 30a8ed4

	assert (cause & 0x10000000) != 0 : "Traps cannot be handled by the interupt handler";
	int code = cause & 0x7FFFFFFF;
	// Don't handle cases where that interrupt isn't enabled
	assert ((ControlAndStatusRegisterFile.getValue("ustatus") & 0x1) == 0 && (ControlAndStatusRegisterFile.getValue("uie") & (1 << code)) == 0) : "The interrupt handler must be enabled";

Ideally, an assertion failure should not make the UI only partially stop working though.

[TheThirdOne]

This should be fixed. Check out the release, and let me know if this fixes the problem for you.

[darnuria]

Thanks sorry for the delay I got caught by the work but maybe next time for sure I would ask to be mentored for fixing a bug. :)

I will try the reproduction steps today I post the result here.

[darnuria]

Sorry I got caught by life and work. I tested on 1.5. and it look like the handle is never called and also it seems we never increment the counter in the handle if I understand the code.

        # Set cmp to time + 5000
	lw a0 timeNow
	lw t2 0(a0)
	li t1 5000
	add t1 t2 t1
	lw t0 cmp
	sw t1 0(t0)
# (note) is it normal to do not increment timeNow?

I can make make some changes if I mentored I think. :)

Code just print 0 and never "hello".

But no more hangs.

[TheThirdOne]

The handler is set to be called when a timer interrupt is triggered. For me it is called periodically.

  	# Set the handler address and enable interrupts
	la	t0, handle
	csrrs	zero, 5, t0
	csrrsi	zero, 4, 0x10
	csrrsi	zero, 0, 0x1

timeNow is a memory mapped address that the Timertool tool updates. You cannot actually change it and expect the value to not get overwritten.

I suspect you are not using the Timertool tool correctly. RARS does not by default support timer interrupts or MMIO without a tool providing extra logic. This information should probably be added to the example in the form of a comment at the top.

[darnuria]

Hello, thanks! I forgot to enable the timer tool in the tools settings.

After setting the timer the program seems to hang strangely:

Like if doing all the heavy printing of the time is saturating something.

Here a glance at a htop view of rars while stuck in the example:

If I remove the printing of the time and replace the loop by

loop:
     nop
     j loop

It's OK and no more hanging.

Edit: Sorry if my English is imperfect, it's not my mother tongue. :)

[TheThirdOne]

After setting the timer the program seems to hang strangely:

In my testing it doesn't actually hang. Instead it is not super responsive, but you can manage to pause execution if you spam-click the pause button. If you change the execution speed to be below maximum, there isn't any weirdness.

Like if doing all the heavy printing of the time is saturating something.

It does seem like the printing results in the weirdness. This is probably because the UI thread is spending time updating the log rather than handling click events well.

It might be possible to optimize the Run I/O to minimize issues. Alternatively, adding a Thread.yield() when running at maximum speed might fix it, but would be a hacky solution.

Edit: Sorry if my English is imperfect, it's not my mother tongue. :)

Your English is certainly good enough. Misspelling "do" as "du" in the was a little bit of a clue if someone was trying to guess your native language (which I would guess is French).

And your English is definitely better than I would be writing in your mother tongue. :)

[darnuria]

It might be possible to optimize the Run I/O to minimize issues. Alternatively, adding a Thread.yield() when running at maximum speed might fix it, but would be a hacky solution.

Look like a hack with backfire.

At the pedagogical lvl I think printing time in timer ?

In my humble opinion, if the main purpose of the example is showing that timer exist in user mode maybe the best is to do like a real world timer and sleep in main loop. The actual printing of time in each loop pass also hide the "hello" message at full speed.

On mars we always used full speed at Université Pierre et Marie Curie (Paris now Sorbonne Université) and In Rars my students use always full speed or step by step.

I can make a PR with a message on stdout or comment about enable timer from tools > Timer tools and maybe add a nop loop in main.

[TheThirdOne]

In my humble opinion, if the main purpose of the example is showing that timer exist in user mode maybe the best is to do like a real world timer and sleep in main loop. The actual printing of time in each loop pass also hide the "hello" message at full speed.

It probably is appropriate to add a sleep into the example. That would certainly solve the problem.

However, I would like to make sure that RARS handles poorly behaved programs as well. In this case the example reveals that RARS can't handle lots of small prints to the console. I suspect this is because the GUI tries to update whenever input happens rather than wait for a new frame to repaint.

I came up with a simple fix for that which is to keep a small buffer so that system calls don't access the GUI directly, but can all add to a buffer that dumps to the GUI every tenth of a second. This makes the experience much better for this example and shouldn't affect other code much at all. Making it send it every hundredth doesn't quite fix the unresponsiveness for me, but definitely makes it better.

I'll give myself a week to see if anything better comes to mind, but after that I plan to add the code below to make sure there aren't performance problems with the GUI console.

    private static String buffer = "";
    private static long lasttime = 0;
    private static void print2Gui(String output){
        long time = System.currentTimeMillis();
        if (time > lasttime) {
            Globals.getGui().getMessagesPane().postRunMessage(buffer+output);
            buffer = "";
            lasttime = time + 100;
        } else {
            buffer += output;
        }
    }

I can make a PR with a message on stdout or comment about enable timer from tools > Timer tools and maybe add a nop loop in main.

If you want to add a comment to the top of the example, I would be willing to merge a PR. Rather than a nop loop, I would accept a call to the sleep (32) system call.

[cypok]

It looks like you have broken something in printing in the 41fff8f.

.data
msg:	.asciz	"Hello!\n"
.text
	li	x17, 4
	la	x10, msg
	ecall
	
	li	x17, 1
	ecall

Assemble, go:

Hello!

-- program is finished running (dropped off bottom) --

Reset, go:

Reset: reset completed.

268500992Hello!

-- program is finished running (dropped off bottom) --

Expected result:

Hello!
268500992

[TheThirdOne]

I understand why this is happening. The print buffering does not allow the buffered output through until the next message is sent.

There are a few possible solutions to this for @cypok's example program:

1. Always flush the buffer at program end
2. Only have the buffering enable if a lot of text is moving.
3. Have a periodic flush of the buffer.

(1) on its own has problems with long running programs that have some initial output. (2) mostly just masks the problems. However the two together should mostly solve this except for pathological cases where a program switches from little output to lots.

(3) is probably the most correct, but is somewhat technically challenging.

[TheThirdOne]

97fe0d0 implements (1) and checks to flush the buffer every instruction run. That should fix the issue @cypok brought up.

[darnuria]

@TheThirdOne (triaging my own issues) maybe it's closable? :)