Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

arch/risc-v: tick timer improvements #15929

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

jlaitine
Copy link
Contributor

@jlaitine jlaitine commented Mar 3, 2025

Summary

This updates the risc-v tick timer to use oneshot timer's tick_* interface, which is meant for this purpose.

This also fixes the same clock drifting issue on risc-v, which was earlier fixed for arm 64 in 4292521, using the same mechanism: as the irq handling delay is unknown, align the next mtimecmp on the tick duration boundary.

Impact

Syncs the risc-v code with arm64, fixes the clock drift issue. Impacts all real risc-v hardware, can't be tested on qemu where the timer accuracy hides the problem.

Testing

Tested on MPFS250T hardware; this is the only risc-v HW which I have available atm.

@github-actions github-actions bot added Arch: risc-v Issues related to the RISC-V (32-bit or 64-bit) architecture Size: S The size of the change in this PR is small labels Mar 3, 2025
@nuttxpr
Copy link

nuttxpr commented Mar 3, 2025

[Experimental Bot, please feedback here]

No, this PR does not fully meet the NuttX requirements. While it provides a decent summary and explains the impact, it lacks several key elements:

  • Summary: Missing related issue references. While it mentions a related commit hash, a proper issue link is preferred for traceability. It needs to be more specific about what functional part of the code is being changed (e.g., the RISC-V timer driver, a specific file).

  • Impact: While it mentions the impact on real RISC-V hardware, it needs to explicitly answer all the YES/NO questions:

    • Is new feature added? NO
    • Is existing feature changed? YES (clock drift fix, timer implementation change)
    • Impact on user: Possibly YES if user code relies on precise timing, but this needs clarification.
    • Impact on build: Likely NO, but needs confirmation.
    • Impact on hardware: YES (RISC-V architectures) - Be more specific which boards are affected within the RISC-V architecture.
    • Impact on documentation: Likely YES if the timer behavior has changed, this needs an explicit statement and confirmation if documentation updates are included.
    • Impact on security: NO (needs explicit statement)
    • Impact on compatibility: Potentially YES, depending on the nature of the fix. This needs clarification.
  • Testing: Severely lacking. "MPFS250T hardware" is insufficient. Needs:

    • Build Host details: OS, CPU architecture, compiler version used for the build.
    • Target details: Specific RISC-V architecture and board configuration used (e.g., riscv:mpfs_icicle).
    • Crucially, it's missing the "before" and "after" testing logs. These logs are essential to demonstrate the fix and justify the PR. Quantify the clock drift before and its absence after. What tests were run?

In short, the PR needs more detail and, most importantly, the testing logs to demonstrate the effectiveness of the proposed changes.

@cederom cederom requested a review from pussuw March 3, 2025 18:46
@cederom
Copy link
Contributor

cederom commented Mar 3, 2025

@nuttxpr test milkv_duos:nsh

Copy link
Contributor

@cederom cederom left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you @jlaitine :-)

  • Nice api sync with arm64 :-)
  • Please provide build and runtime (nsh/ostest) logs even from your board for changes affecting many chips / boards :-)
  • Tested on ESP32-C6 with CROSSDEV=riscv32-esp-elf-gcc version 8.4.0:
% uname -a
FreeBSD octagon 14.2-RELEASE-p1 FreeBSD 14.2-RELEASE-p1 GENERIC amd64

% git branch
* (HEAD detached at tiiuae/riscv_tick_timer_improvements)

% git log -2
commit 30fc08aaeafa189e6d725845f48f9d8b14234ab5 (HEAD, tiiuae/riscv_tick_timer_improvements)
Author: Jukka Laitinen <[email protected]>
Date:   Mon Mar 3 11:22:40 2025 +0200

    arch/risc-v/src/common/riscv_mtimer.c: Remove clock drift from tick timer

    This is the same that was done earlier for arm64 in 429252152, and fixes the
    same issues with the tick timer:
    1) Each tick is a bit longer than the requested period
    2) after a long period of clock drift, the oneshot_callback might
       randomly advance two ticks at a time, causing wdog timers complete
       one tick too early

    Signed-off-by: Jukka Laitinen <[email protected]>

commit 01a9f006e887f774ad466e0f069128f067e82488
Author: Jukka Laitinen <[email protected]>
Date:   Mon Mar 3 11:06:04 2025 +0200

    arch/risc-v/src/common/riscv_mtimer.c: Change risc-v tick timer to use oneshot timer tick_ operations

    As the riscv_mtimer is just a OS tick timer, use the interface ment
    for the purpose.

    Signed-off-by: Jukka Laitinen <[email protected]>

% ./tools/configure.sh -B esp32c6-devkitm:nsh

% /usr/bin/time -h gmake -j8 CROSSDEV=riscv32-esp-elf-
(..)
Memory region         Used Size  Region Size  %age Used
             ROM:      240229 B        16 MB      1.43%
     iram0_0_seg:       19792 B     452112 B      4.38%
        irom_seg:      119486 B        16 MB      0.71%
     dram0_0_seg:       31008 B     452112 B      6.86%
        drom_seg:      174696 B        16 MB      1.04%
      lp_ram_seg:          16 B      16360 B      0.10%
 lp_reserved_seg:          0 GB         24 B      0.00%
CP: nuttx.hex
MKIMAGE: NuttX binary
esptool.py -c esp32c6 elf2image --ram-only-header -fs 4MB -fm dio -ff 80m -o nuttx.bin nuttx
esptool.py v4.8.1
Creating esp32c6 image...
Image has only RAM segments visible. ROM segments are hidden and SHA256 digest is not appended.
Merged 1 ELF section
Successfully created esp32c6 image.
Generated: nuttx.bin
        15,47s real             48,91s user             31,89s sys

% /usr/bin/time -h gmake flash CROSSDEV=riscv32-esp-elf-
(..)
Memory region         Used Size  Region Size  %age Used
             ROM:      240229 B        16 MB      1.43%
     iram0_0_seg:       19792 B     452112 B      4.38%
        irom_seg:      119486 B        16 MB      0.71%
     dram0_0_seg:       31008 B     452112 B      6.86%
        drom_seg:      174696 B        16 MB      1.04%
      lp_ram_seg:          16 B      16360 B      0.10%
 lp_reserved_seg:          0 GB         24 B      0.00%
CP: nuttx.hex
MKIMAGE: NuttX binary
esptool.py -c esp32c6 elf2image --ram-only-header -fs 4MB -fm dio -ff 80m -o nuttx.bin nuttx
esptool.py v4.8.1
Creating esp32c6 image...
Image has only RAM segments visible. ROM segments are hidden and SHA256 digest is not appended.
Merged 1 ELF section
Successfully created esp32c6 image.
Generated: nuttx.bin
esptool.py -c esp32c6 -p /dev/cuaU0 -b 115200  write_flash -fs 4MB -fm dio -ff 80m 0x0000 nuttx.bin
esptool.py v4.8.1
Serial port /dev/cuaU0
Connecting.........
Chip is ESP32-C6 (QFN40) (revision v0.1)
Features: WiFi 6, BT 5, IEEE802.15.4
Crystal is 40MHz
MAC: XXX
BASE MAC: XXX
MAC_EXT: ff:fe
Uploading stub...
Running stub...
Stub running...
Configuring flash size...
Flash will be erased from 0x00000000 to 0x0003dfff...
Compressed 250560 bytes to 108027...
Wrote 250560 bytes (108027 compressed) at 0x00000000 in 9.6 seconds (effective 208.0 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting via RTS pin...
        19,64s real             3,55s user              4,18s sys


nsh> uname -a
NuttX 10.4.0 30fc08aaea Mar  3 2025 20:26:32 risc-v esp32c6-devkitm

nsh> ?
help usage:  help [-v] [<cmd>]

    .           cp          exit        ls          reboot      truncate
    [           cmp         expr        mkdir       rm          uname
    ?           dirname     false       mkrd        rmdir       umount
    alias       dd          fdinfo      mount       set         unset
    unalias     df          free        mv          sleep       uptime
    basename    dmesg       help        pidof       source      usleep
    break       echo        hexdump     printf      test        watch
    cat         env         kill        ps          time        xd
    cd          exec        pkill       pwd         true        wait

Builtin Apps:
    dumpstack    getprime     nsh          ostest       sh

nsh> ostest
stdio_test: write fd=1
stdio_test: Standard I/O Check: printf
stdio_test: write fd=2
stdio_test: Standard I/O Check: fprintf to stderr
ostest_main: putenv(Variable1=BadValue3)
ostest_main: setenv(Variable1, GoodValue1, TRUE)
ostest_main: setenv(Variable2, BadValue1, FALSE)
ostest_main: setenv(Variable2, GoodValue2, TRUE)
ostest_main: setenv(Variable3, GoodValue3, FALSE)
ostest_main: setenv(Variable3, BadValue2, FALSE)
show_variable: Variable=Variable1 has value=GoodValue1
show_variable: Variable=Variable2 has value=GoodValue2
show_variable: Variable=Variable3 has value=GoodValue3
ostest_main: Started user_main at PID=3

user_main: Begin argument test
user_main: Started with argc=5
user_main: argv[0]="ostest"
user_main: argv[1]="Arg1"
user_main: argv[2]="Arg2"
user_main: argv[3]="Arg3"
user_main: argv[4]="Arg4"

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         1        1
mxordblk    730e8    730e8
uordblks     4358     4358
fordblks    730e8    730e8

user_main: getopt() test
getopt():  Simple test
getopt():  Invalid argument
getopt():  Missing optional argument
getopt_long():  Simple test
getopt_long():  No short options
getopt_long():  Argument for --option=argument
getopt_long():  Invalid long option
getopt_long():  Mixed long and short options
getopt_long():  Invalid short option
getopt_long():  Missing optional arguments
getopt_long_only():  Mixed long and short options
getopt_long_only():  Single hyphen long options

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         1        1
mxordblk    730e8    730e8
uordblks     4358     4358
fordblks    730e8    730e8

user_main: libc tests

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         1        1
mxordblk    730e8    730e8
uordblks     4358     4358
fordblks    730e8    730e8
show_variable: Variable=Variable1 has value=GoodValue1
show_variable: Variable=Variable2 has value=GoodValue2
show_variable: Variable=Variable3 has value=GoodValue3
show_variable: Variable=Variable1 has no value
show_variable: Variable=Variable2 has value=GoodValue2
show_variable: Variable=Variable3 has value=GoodValue3

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         1        2
mxordblk    730e8    730e8
uordblks     4358     4338
fordblks    730e8    73108
show_variable: Variable=Variable1 has no value
show_variable: Variable=Variable2 has no value
show_variable: Variable=Variable3 has no value

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    730e8    730e8
uordblks     4338     42c0
fordblks    73108    73180

user_main: setvbuf test
setvbuf_test: Test NO buffering
setvbuf_test: Using NO buffering
setvbuf_test: Test default FULL buffering
setvbuf_test: Using default FULL buffering
setvbuf_test: Test FULL buffering, buffer size 64
setvbuf_test: Using FULL buffering, buffer size 64
setvbuf_test: Test FULL buffering, pre-allocated buffer
setvbuf_test: Using FULL buffering, pre-allocated buffer
setvbuf_test: Test LINE buffering, buffer size 64
setvbuf_test: Using LINE buffering, buffer size 64
setvbuf_test: Test FULL buffering, pre-allocated buffer
setvbuf_test: Using FULL buffering, pre-allocated buffer

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    730e8    730e8
uordblks     42c0     42c0
fordblks    73180    73180

user_main: /dev/null test
dev_null: Read 0 bytes from /dev/null
dev_null: Wrote 1024 bytes to /dev/null

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    730e8    730e8
uordblks     42c0     42c0
fordblks    73180    73180

user_main: task_restart test

Test task_restart()
restart_main: setenv(VarName, VarValue, TRUE)
restart_main: Started restart_main at PID=4
restart_main: Started with argc=4
restart_main: argv[0]="ostest"
restart_main: argv[1]="This is argument 1"
restart_main: argv[2]="Argument 2 here"
restart_main: argv[3]="Lastly, the 3rd argument"
restart_main: Variable=VarName has value=VarValue
restart_main: I am still here
restart_main: I am still here
restart_main: Started restart_main at PID=4
restart_main: Started with argc=4
restart_main: argv[0]="ostest"
restart_main: argv[1]="This is argument 1"
restart_main: argv[2]="Argument 2 here"
restart_main: argv[3]="Lastly, the 3rd argument"
restart_main: Variable=VarName has value=VarValue
restart_main: Started with argc=4
restart_main: argv[0]="ostest"
restart_main: argv[1]="This is argument 1"
restart_main: argv[2]="Argument 2 here"
restart_main: argv[3]="Lastly, the 3rd argument"
restart_main: Variable=VarName has value=VarValue
restart_main: Exiting

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    730e8    70d10
uordblks     42c0     66d0
fordblks    73180    70d70

user_main: waitpid test

Test waitpid()
waitpid_start_child: Started waitpid_main at PID=5
waitpid_main: PID 5 Started
waitpid_start_child: Started waitpid_main at PID=6
waitpid_main: PID 6 Started
waitpid_start_child: Started waitpid_main at PID=7
waitpid_main: PID 7 Started
waitpid_test: Waiting for PID=5 with waitpid()
waitpid_main: PID 5 exitting with result=14
waitpid_test: PID 5 waitpid succeeded with stat_loc=0e00
waitpid_last: Waiting for PID=7 with waitpid()
waitpid_main: PID 6 exitting with result=14
waitpid_main: PID 7 exitting with result=14
waitpid_last: PASS: PID 7 waitpid succeeded with stat_loc=0e00

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        5
mxordblk    70d10    6c510
uordblks     66d0     a6e0
fordblks    70d70    6cd60

user_main: mutex test
Initializing mutex
Starting thread 1
Starting thread 2
                Thread1 Thread2
        Loops   32      32
        Errors  0       0

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         5        2
mxordblk    6c510    71f28
uordblks     a6e0     54b8
fordblks    6cd60    71f88

user_main: timed mutex test
mutex_test: Initializing mutex
mutex_test: Starting thread
pthread:  Started
pthread:  Waiting for lock or timeout
mutex_test: Unlocking
pthread:  Got the lock
pthread:  Waiting for lock or timeout
pthread:  Got the timeout.  Terminating
mutex_test: PASSED

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    71f28    72808
uordblks     54b8     4bd8
fordblks    71f88    72868

user_main: cancel test
cancel_test: Test 1a: Normal Cancellation
cancel_test: Starting thread
start_thread: Initializing mutex
start_thread: Initializing cond
start_thread: Starting thread
start_thread: Yielding
sem_waiter: Taking mutex
sem_waiter: Starting wait for condition
cancel_test: Canceling thread
cancel_test: Joining
cancel_test: waiter exited with result=0xffffffff
cancel_test: PASS thread terminated with PTHREAD_CANCELED
cancel_test: Test 2: Asynchronous Cancellation
... Skipped
cancel_test: Test 3: Cancellation of detached thread
cancel_test: Re-starting thread
restart_thread: Destroying cond
restart_thread: Destroying mutex
restart_thread: Re-starting thread
start_thread: Initializing mutex
start_thread: Initializing cond
start_thread: Starting thread
start_thread: Yielding
sem_waiter: Taking mutex
sem_waiter: Starting wait for condition
cancel_test: Canceling thread
cancel_test: Joining
cancel_test: PASS pthread_join failed with status=ESRCH
cancel_test: Test 5: Non-cancelable threads
cancel_test: Re-starting thread (non-cancelable)
restart_thread: Destroying cond
restart_thread: Destroying mutex
restart_thread: Re-starting thread
start_thread: Initializing mutex
start_thread: Initializing cond
start_thread: Starting thread
start_thread: Yielding
sem_waiter: Taking mutex
sem_waiter: Starting wait for condition
sem_waiter: Setting non-cancelable
cancel_test: Canceling thread
cancel_test: Joining
sem_waiter: Releasing mutex
sem_waiter: Setting cancelable
cancel_test: waiter exited with result=0xffffffff
cancel_test: PASS thread terminated with PTHREAD_CANCELED
cancel_test: Test 6: Cancel message queue wait
cancel_test: Starting thread (cancelable)
Skipped
cancel_test: Test 7: Cancel signal wait
cancel_test: Starting thread (cancelable)
Skipped

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    72808    71008
uordblks     4bd8     63d8
fordblks    72868    71068

user_main: robust test
robust_test: Initializing mutex
robust_test: Starting thread
robust_waiter: Taking mutex
robust_waiter: Exiting with mutex
robust_test: Take the lock again
robust_test: Make the mutex consistent again.
robust_test: Take the lock again
robust_test: Joining
robust_test: waiter exited with result=0
robust_test: Test complete with nerrors=0

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    71008    71008
uordblks     63d8     63d8
fordblks    71068    71068

user_main: semaphore test
sem_test: Initializing semaphore to 0
sem_test: Starting waiter thread 1
sem_test: Set thread 1 priority to 191
waiter_func: Thread 1 Started
waiter_func: Thread 1 initial semaphore value = 0
sem_test: Starting waiter thread 2
waiter_func: Thread 1 waiting on semaphore
sem_test: Set thread 2 priority to 128
waiter_func: Thread 2 Started
waiter_func: Thread 2 initial semaphore value = -1
waiter_func: Thread 2 waiting on semaphore
sem_test: Starting poster thread 3
sem_test: Set thread 3 priority to 64
poster_func: Thread 3 started
poster_func: Thread 3 semaphore value = -2
poster_func: Thread 3 posting semaphore
waiter_func: Thread 1 awakened
waiter_func: Thread 1 new semaphore value = -1
waiter_func: Thread 1 done
poster_func: Thread 3 new semaphore value = -1
poster_func: Thread 3 semaphore value = -1
poster_func: Thread 3 posting semaphore
waiter_func: Thread 2 awakened
poster_func: Thread 3 new semaphore value = 0
waiter_func: Thread 2 new semaphore value = 0
waiter_func: Thread 2 done
poster_func: Thread 3 done

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    71008    71648
uordblks     63d8     5d98
fordblks    71068    716a8

user_main: timed semaphore test
semtimed_test: Initializing semaphore to 0
semtimed_test: Waiting for two second timeout
semtimed_test: PASS: first test returned timeout
BEFORE: (40 sec, 780000000 nsec)
AFTER:  (42 sec, 790000000 nsec)
semtimed_test: Starting poster thread
semtimed_test: Set thread 1 priority to 191
semtimed_test: Starting poster thread 3
semtimed_test: Set thread 3 priority to 64
semtimed_test: Waiting for two second timeout
poster_func: Waiting for 1 second
poster_func: Posting
semtimed_test: PASS: sem_timedwait succeeded
BEFORE: (42 sec, 790000000 nsec)
AFTER:  (43 sec, 800000000 nsec)

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    71648    72808
uordblks     5d98     4bd8
fordblks    716a8    72868

user_main: condition variable test
cond_test: Initializing mutex
cond_test: Initializing cond
cond_test: Starting waiter
cond_test: Set thread 1 priority to 128
waiter_thread: Started
cond_test: Starting signaler
cond_test: Set thread 2 priority to 64
thread_signaler: Started
thread_signaler: Terminating
cond_test: signaler terminated, now cancel the waiter
cond_test:      Waiter  Signaler
cond_test: Loops        32      32
cond_test: Errors       0       0
cond_test:
cond_test: 0 times, waiter did not have to wait for data
cond_test: 0 times, data was already available when the signaler run
cond_test: 0 times, the waiter was in an unexpected state when the signaler ran

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        3
mxordblk    72808    71f28
uordblks     4bd8     4bd8
fordblks    72868    72868

user_main: pthread_exit() test
pthread_exit_test: Started pthread_exit_main at PID=25
pthread_exit_main 25: Starting pthread_exit_thread
pthread_exit_main 25: Sleeping for 5 seconds
pthread_exit_thread 26: Sleeping for 10 second
pthread_exit_main 25: Calling pthread_exit()
pthread_exit_thread 26: Still running...

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         3        2
mxordblk    71f28    70728
uordblks     4bd8     6cb8
fordblks    72868    70788

user_main: pthread_rwlock test
pthread_rwlock: Initializing rwlock
pthread_exit_thread 26: Exiting

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        3
mxordblk    70728    70728
uordblks     6cb8     4be8
fordblks    70788    72858

user_main: pthread_rwlock_cancel test
pthread_rwlock_cancel: Starting test

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         3        2
mxordblk    70728    730e8
uordblks     4be8     4308
fordblks    72858    73138

user_main: timed wait test
thread_waiter: Initializing mutex
timedwait_test: Initializing cond
timedwait_test: Starting waiter
timedwait_test: Set thread 2 priority to 177
thread_waiter: Taking mutex
timedwait_test: Joining
thread_waiter: Starting 5 second wait for condition
thread_waiter: pthread_cond_timedwait timed out
thread_waiter: Releasing mutex
thread_waiter: Exit with status 0x12345678
timedwait_test: waiter exited with result=0x12345678

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    730e8    72808
uordblks     4308     4be8
fordblks    73138    72858

user_main: message queue test
mqueue_test: Starting receiver
mqueue_test: Set receiver priority to 128
receiver_thread: Starting
mqueue_test: Starting sender
mqueue_test: Set sender thread priority to 64
mqueue_test: Waiting for sender to complete
sender_thread: Starting
receiver_thread: mq_receive succeeded on msg 0
sender_thread: mq_send succeeded on msg 0
receiver_thread: mq_receive succeeded on msg 1
sender_thread: mq_send succeeded on msg 1
receiver_thread: mq_receive succeeded on msg 2
sender_thread: mq_send succeeded on msg 2
receiver_thread: mq_receive succeeded on msg 3
sender_thread: mq_send succeeded on msg 3
receiver_thread: mq_receive succeeded on msg 4
sender_thread: mq_send succeeded on msg 4
receiver_thread: mq_receive succeeded on msg 5
sender_thread: mq_send succeeded on msg 5
receiver_thread: mq_receive succeeded on msg 6
sender_thread: mq_send succeeded on msg 6
receiver_thread: mq_receive succeeded on msg 7
sender_thread: mq_send succeeded on msg 7
receiver_thread: mq_receive succeeded on msg 8
sender_thread: mq_send succeeded on msg 8
receiver_thread: mq_receive succeeded on msg 9
sender_thread: mq_send succeeded on msg 9
sender_thread: returning nerrors=0
mqueue_test: Killing receiver
receiver_thread: mq_receive interrupted!
receiver_thread: returning nerrors=0
mqueue_test: Canceling receiver
mqueue_test: receiver has already terminated

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        3
mxordblk    72808    6ee50
uordblks     4be8     8528
fordblks    72858    6ef18

user_main: timed message queue test
timedmqueue_test: Starting sender
timedmqueue_test: Waiting for sender to complete
sender_thread: Starting
sender_thread: mq_timedsend succeeded on msg 0
sender_thread: mq_timedsend succeeded on msg 1
sender_thread: mq_timedsend succeeded on msg 2
sender_thread: mq_timedsend succeeded on msg 3
sender_thread: mq_timedsend succeeded on msg 4
sender_thread: mq_timedsend succeeded on msg 5
sender_thread: mq_timedsend succeeded on msg 6
sender_thread: mq_timedsend succeeded on msg 7
sender_thread: mq_timedsend succeeded on msg 8
sender_thread: mq_timedsend 9 timed out as expected
sender_thread: returning nerrors=0
timedmqueue_test: Starting receiver
timedmqueue_test: Waiting for receiver to complete
receiver_thread: Starting
receiver_thread: mq_timedreceive succeed on msg 0
receiver_thread: mq_timedreceive succeed on msg 1
receiver_thread: mq_timedreceive succeed on msg 2
receiver_thread: mq_timedreceive succeed on msg 3
receiver_thread: mq_timedreceive succeed on msg 4
receiver_thread: mq_timedreceive succeed on msg 5
receiver_thread: mq_timedreceive succeed on msg 6
receiver_thread: mq_timedreceive succeed on msg 7
receiver_thread: mq_timedreceive succeed on msg 8
receiver_thread: Receive 9 timed out as expected
receiver_thread: returning nerrors=0
timedmqueue_test: Test complete

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         3        2
mxordblk    6ee50    70fd8
uordblks     8528     6448
fordblks    6ef18    70ff8

user_main: sigprocmask test
sigprocmask_test: SUCCESS

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        2
mxordblk    70fd8    70fd8
uordblks     6448     6448
fordblks    70ff8    70ff8

user_main: signal handler test
sighand_test: Initializing semaphore to 0
sighand_test: Starting waiter task
sighand_test: Started waiter_main pid=42
waiter_main: Waiter started
waiter_main: Unmasking signal 32
waiter_main: Registering signal handler
waiter_main: oact.sigaction=0 oact.sa_flags=0 oact.sa_mask=0000000000000000
waiter_main: Waiting on semaphore
sighand_test: Signaling pid=42 with signo=32 sigvalue=42
waiter_main: sem_wait() successfully interrupted by signal
waiter_main: done
sighand_test: done

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        1
mxordblk    70fd8    70fc8
uordblks     6448     6478
fordblks    70ff8    70fc8

user_main: nested signal handler test
signest_test: Starting signal waiter task at priority 101
waiter_main: Waiter started
waiter_main: Setting signal mask
waiter_main: Registering signal handler
signest_test: Started waiter_main pid=43
waiter_main: Waiting on semaphore
signest_test: Starting interfering task at priority 102
interfere_main: Waiting on semaphore
signest_test: Started interfere_main pid=44
signest_test: Simple case:
  Total signalled 1240  Odd=620 Even=620
  Total handled   1240  Odd=620 Even=620
  Total nested    0    Odd=0   Even=0
signest_test: With task locking
  Total signalled 2480  Odd=1240 Even=1240
  Total handled   2480  Odd=1240 Even=1240
  Total nested    0    Odd=0   Even=0
signest_test: With intefering thread
  Total signalled 3720  Odd=1860 Even=1860
  Total handled   3720  Odd=1860 Even=1860
  Total nested    0    Odd=0   Even=0
signest_test: done

End of test memory usage:
wdtest_once 0 ns
wdtest_once 0 ns
wdtest_once 0 ns
wdtest_once 0 ns
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         1        2
mxordblk    70fc8    6e798
uordblks     6478     6bd8
fordblks    70fc8    70868

user_main: wdog test
wdog_test start...
wdtest_once 1 ns
wdtest_once 1 ns
wdtest_once 1 ns
wdtest_once 1 ns
wdtest_once 10 ns
wdtest_once 10 ns
wdtest_once 10 ns
wdtest_once 10 ns
wdtest_once 100 ns
wdtest_once 100 ns
wdtest_once 100 ns
wdtest_once 100 ns
wdtest_once 1000 ns
wdtest_once 1000 ns
wdtest_once 1000 ns
wdtest_once 1000 ns
wdtest_once 10000 ns
wdtest_once 10000 ns
wdtest_once 10000 ns
wdtest_once 10000 ns
wdtest_once 100000 ns
wdtest_once 100000 ns
wdtest_once 100000 ns
wdtest_once 100000 ns
wdtest_once 1000000 ns
wdtest_once 1000000 ns
wdtest_once 1000000 ns
wdtest_once 1000000 ns
wd_start with maximum delay, cancel OK, rest 2147483646
wdtest_recursive 1000000us
wd_start with maximum delay, cancel OK, rest 2147483646
wdtest_recursive 1000000us
wd_start with maximum delay, cancel OK, rest 2147483646
wdtest_recursive 1000000us
wd_start with maximum delay, cancel OK, rest 2147483645
wdtest_recursive 1000000us
recursive wdog triggered 6 times, elapsed tick 12
wdtest_recursive 10000000us
recursive wdog triggered 6 times, elapsed tick 12
wdtest_recursive 10000000us
recursive wdog triggered 6 times, elapsed tick 12
wdtest_recursive 10000000us
recursive wdog triggered 6 times, elapsed tick 12
wdtest_recursive 10000000us
recursive wdog triggered 6 times, elapsed tick 12
recursive wdog triggered 6 times, elapsed tick 12
recursive wdog triggered 6 times, elapsed tick 12
recursive wdog triggered 6 times, elapsed tick 12
wdog_test end...

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         2        3
mxordblk    6e798    6e798
uordblks     6bd8     6e78
fordblks    70868    705c8

user_main: POSIX timer test
timer_test: Initializing semaphore to 0
timer_test: Unmasking signal 32
timer_test: Registering signal handler
timer_test: oact.sigaction=0x42016ce0 oact.sa_flags=0 oact.sa_mask=aaaaaaaaaaaaaaaa
timer_test: Creating timer
timer_test: Starting timer
timer_test: Waiting on semaphore
timer_expiration: Received signal 32
timer_expiration: sival_int=42
timer_expiration: si_code=2 (SI_TIMER)
timer_expiration: ucontext=0
timer_test: sem_wait() successfully interrupted by signal
timer_test: g_nsigreceived=1
timer_test: Waiting on semaphore
timer_expiration: Received signal 32
timer_expiration: sival_int=42
timer_expiration: si_code=2 (SI_TIMER)
timer_expiration: ucontext=0
timer_test: sem_wait() successfully interrupted by signal
timer_test: g_nsigreceived=2
timer_test: Waiting on semaphore
timer_expiration: Received signal 32
timer_expiration: sival_int=42
timer_expiration: si_code=2 (SI_TIMER)
timer_expiration: ucontext=0
timer_test: sem_wait() successfully interrupted by signal
timer_test: g_nsigreceived=3
timer_test: Waiting on semaphore
timer_expiration: Received signal 32
timer_expiration: sival_int=42
timer_expiration: si_code=2 (SI_TIMER)
timer_expiration: ucontext=0
timer_test: sem_wait() successfully interrupted by signal
timer_test: g_nsigreceived=4
timer_test: Waiting on semaphore
timer_expiration: Received signal 32
timer_expiration: sival_int=42
timer_expiration: si_code=2 (SI_TIMER)
timer_expiration: ucontext=0
timer_test: sem_wait() successfully interrupted by signal
timer_test: g_nsigreceived=5
timer_test: Deleting timer
timer_test: done

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         3        4
mxordblk    6e798    6e798
uordblks     6e78     4ad8
fordblks    705c8    72968

user_main: round-robin scheduler test
rr_test: Set thread priority to 1
rr_test: Set thread policy to SCHED_RR
rr_test: Starting first get_primes_thread
         First get_primes_thread: 53
rr_test: Starting second get_primes_thread
         Second get_primes_thread: 54
rr_test: Waiting for threads to complete -- this should take awhile
         If RR scheduling is working, they should start and complete at
         about the same time
get_primes_thread id=1 started, looking for primes < 10000, doing 10 run(s)
get_primes_thread id=2 started, looking for primes < 10000, doing 10 run(s)
get_primes_thread id=1 finished, found 1230 primes, last one was 9973
get_primes_thread id=2 finished, found 1230 primes, last one was 9973
rr_test: Done

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         4        4
mxordblk    6e798    6e798
uordblks     4ad8     5c98
fordblks    72968    717a8

user_main: barrier test
barrier_test: Initializing barrier
barrier_test: Thread 0 created
barrier_test: Thread 1 created
barrier_test: Thread 2 created
barrier_test: Thread 3 created
barrier_func: Thread 0 started
barrier_func: Thread 1 started
barrier_func: Thread 2 started
barrier_func: Thread 3 started
barrier_test: Thread 4 created
barrier_func: Thread 4 started
barrier_test: Thread 5 created
barrier_func: Thread 5 started
barrier_test: Thread 6 created
barrier_func: Thread 6 started
barrier_test: Thread 7 created
barrier_func: Thread 7 started
barrier_func: Thread 0 calling pthread_barrier_wait()
barrier_func: Thread 1 calling pthread_barrier_wait()
barrier_func: Thread 2 calling pthread_barrier_wait()
barrier_func: Thread 3 calling pthread_barrier_wait()
barrier_func: Thread 4 calling pthread_barrier_wait()
barrier_func: Thread 5 calling pthread_barrier_wait()
barrier_func: Thread 6 calling pthread_barrier_wait()
barrier_func: Thread 7 calling pthread_barrier_wait()
barrier_func: Thread 7, back with status=PTHREAD_BARRIER_SERIAL_THREAD (I AM SPECIAL)
barrier_func: Thread 0, back with status=0 (I am not special)
barrier_func: Thread 1, back with status=0 (I am not special)
barrier_func: Thread 2, back with status=0 (I am not special)
barrier_func: Thread 3, back with status=0 (I am not special)
barrier_func: Thread 4, back with status=0 (I am not special)
barrier_func: Thread 5, back with status=0 (I am not special)
barrier_func: Thread 6, back with status=0 (I am not special)
barrier_func: Thread 7 done
barrier_func: Thread 0 done
barrier_func: Thread 1 done
barrier_test: Thread 0 completed with result=0
barrier_test: Thread 1 completed with result=0
barrier_func: Thread 2 done
barrier_func: Thread 3 done
barrier_test: Thread 2 completed with result=0
barrier_test: Thread 3 completed with result=0
barrier_func: Thread 4 done
barrier_func: Thread 5 done
barrier_test: Thread 4 completed with result=0
barrier_test: Thread 5 completed with result=0
barrier_func: Thread 6 done
barrier_test: Thread 6 completed with result=0
barrier_test: Thread 7 completed with result=0

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         4        6
mxordblk    6e798    6e798
uordblks     5c98     5c98
fordblks    717a8    717a8

user_main: scheduler lock test
sched_lock: Starting lowpri_thread at 97
sched_lock: Set lowpri_thread priority to 97
sched_lock: Starting highpri_thread at 98
sched_lock: Set highpri_thread priority to 98
sched_lock: Waiting...
sched_lock: PASSED No pre-emption occurred while scheduler was locked.
sched_lock: Starting lowpri_thread at 97
sched_lock: Set lowpri_thread priority to 97
sched_lock: Starting highpri_thread at 98
sched_lock: Set highpri_thread priority to 98
sched_lock: Waiting...
sched_lock: PASSED No pre-emption occurred while scheduler was locked.
sched_lock: Finished

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         6        5
mxordblk    6e798    6e798
uordblks     5c98     53b8
fordblks    717a8    72088

user_main: vfork() test
vfork_test: Child 71 ran successfully

Final memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena       77440    77440
ordblks         1        4
mxordblk    730e8    6e798
uordblks     4358     6ae0
fordblks    730e8    70960
user_main: Exiting
ostest_main: Exiting with status 0

@cederom
Copy link
Contributor

cederom commented Mar 3, 2025

@jlaitine you may want to sync your local fork https://github.com/jlaitine/incubator-nuttx with the upstream https://github.com/apache/nuttx and the tags :-)

@nuttxpr
Copy link

nuttxpr commented Mar 3, 2025

[Experimental Bot, please feedback here]

Build and Test Successful (milkv_duos:nsh)
https://gitlab.com/lupyuen/nuttx-build-log/-/snippets/4816455

$ git clone https://github.com/tiiuae/nuttx nuttx --branch riscv_tick_timer_improvements
$ git clone https://github.com/apache/nuttx-apps apps --branch master
$ pushd nuttx
$ git reset --hard HEAD
HEAD is now at 30fc08aaea arch/risc-v/src/common/riscv_mtimer.c: Remove clock drift from tick timer
$ popd
$ pushd apps
$ git reset --hard HEAD
HEAD is now at 844b9c657 apps/testing:fix uclibc atomic make.defs error
$ popd
NuttX Source: https://github.com/apache/nuttx/tree/30fc08aaeafa189e6d725845f48f9d8b14234ab5
NuttX Apps: https://github.com/apache/nuttx-apps/tree/844b9c657dff153cde82373c19c65f046a4a7f26
$ cd nuttx
$ tools/configure.sh milkv_duos:nsh
$ make -j
$ make -j export
$ pushd ../apps
$ ./tools/mkimport.sh -z -x ../nuttx/nuttx-export-10.4.0.tar.gz
$ make -j import
$ popd
$ genromfs -f initrd -d ../apps/bin -V NuttXBootVol
$ head -c 65536 /dev/zero
$ cat nuttx.bin /tmp/nuttx.pad initrd
$ scp Image tftpserver:/tftpboot/Image-sg2000
$ ssh tftpserver ls -l /tftpboot/Image-sg2000
$ cd /home/luppy/nuttx-build-farm
$ ssh tftpserver
OpenSBI v0.9
nsh> uname -a
NuttX 10.4.0 30fc08aaea Mar  4 2025 06:10:45 risc-v milkv_duos
nsh> ostest
arena       81000    81000
ordblks         2        3
mxordblk    7cff8    78ff8
uordblks     2660     4570
fordblks    7e9a0    7ca90
user_main: Exiting
ostest_main: Exiting with status 0
nsh> Now running https://github.com/lupyuen/nuttx-build-farm/blob/main/oz64-power.sh off
----- Power off Oz64
[]

Copy link
Member

@lupyuen lupyuen left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tested OK with OSTest on Real Hardware: Oz64 SG2000 64-bit RISC-V SBC. Thanks :-)

@jerpelea jerpelea changed the title Riscv tick timer improvements arch/risc-v: tick timer improvements Mar 4, 2025
@jlaitine jlaitine force-pushed the riscv_tick_timer_improvements branch from 30fc08a to 6838f8c Compare March 6, 2025 06:28
@jlaitine
Copy link
Contributor Author

jlaitine commented Mar 6, 2025

@xiaoxiang781216 I believe it is possible to combine my effort of aligning the tick starts properly (to avoid clock drift) and your concern of measuring long intervals with ticks when the tick time is not aligned to the underlying hw timer.

Please see the current proposal. Attached ostest on mfps, with SMP (4 harts), CONFIG_BUILD_FLAT.

mpfs_ostest.txt

@jlaitine
Copy link
Contributor Author

jlaitine commented Mar 6, 2025

Here are ostest results for rv_virt:nsh and rv_virt:nsh64:
rv-virt_nsh_ostest.txt
rv-virt_nsh64_ostest.txt

All tests pass.

@jlaitine jlaitine requested a review from xiaoxiang781216 March 6, 2025 07:15
@lupyuen
Copy link
Member

lupyuen commented Mar 6, 2025

@nuttxpr test milkv_duos:nsh

@nuttxpr
Copy link

nuttxpr commented Mar 6, 2025

[Experimental Bot, please feedback here]

Build and Test Successful (milkv_duos:nsh)
https://gitlab.com/lupyuen/nuttx-build-log/-/snippets/4819154

$ git clone https://github.com/tiiuae/nuttx nuttx --branch riscv_tick_timer_improvements
$ git clone https://github.com/apache/nuttx-apps apps --branch master
$ pushd nuttx
$ git reset --hard HEAD
HEAD is now at 6838f8c595 arch/risc-v/src/common/riscv_mtimer.c: Change risc-v tick timer to use oneshot timer tick_ operations
$ popd
$ pushd apps
$ git reset --hard HEAD
HEAD is now at a7020e45c benchmarks/osperf: fix warning maybe-uninitialized
$ popd
NuttX Source: https://github.com/apache/nuttx/tree/6838f8c595716e49feacd5ddc6b569a5a4bf3118
NuttX Apps: https://github.com/apache/nuttx-apps/tree/a7020e45cc21ad01ab31439fa2586dd2a538f9aa
$ cd nuttx
$ tools/configure.sh milkv_duos:nsh
$ make -j
$ make -j export
$ pushd ../apps
$ ./tools/mkimport.sh -z -x ../nuttx/nuttx-export-10.4.0.tar.gz
$ make -j import
$ popd
$ genromfs -f initrd -d ../apps/bin -V NuttXBootVol
$ head -c 65536 /dev/zero
$ cat nuttx.bin /tmp/nuttx.pad initrd
$ scp Image tftpserver:/tftpboot/Image-sg2000
$ ssh tftpserver ls -l /tftpboot/Image-sg2000
$ cd /home/luppy/nuttx-build-farm
$ ssh tftpserver
OpenSBI v0.9
nsh> uname -a
NuttX 10.4.0 6838f8c595 Mar  6 2025 15:19:47 risc-v milkv_duos
nsh> ostest
arena       81000    81000
ordblks         2        3
mxordblk    7cff8    78ff8
uordblks     2660     4570
fordblks    7e9a0    7ca90
user_main: Exiting
ostest_main: Exiting with status 0
nsh> Now running https://github.com/lupyuen/nuttx-build-farm/blob/main/oz64-power.sh off
----- Power off Oz64
[]

Copy link
Member

@lupyuen lupyuen left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tested OK with OSTest on Real Hardware: Oz64 SG2000 64-bit RISC-V SBC. Thanks :-)

Add the mtimer _tick operations for use when tickless mode is not used.
This corrects the tick-based timing calculations, removing tick timer drift
and rounding errors causing early wdog expirations.

Signed-off-by: Jukka Laitinen <[email protected]>
@jlaitine jlaitine force-pushed the riscv_tick_timer_improvements branch from 6838f8c to 695a987 Compare March 7, 2025 06:54
@github-actions github-actions bot added Size: M The size of the change in this PR is medium and removed Size: S The size of the change in this PR is small labels Mar 7, 2025
@jlaitine
Copy link
Contributor Author

jlaitine commented Mar 7, 2025

@xiaoxiang781216 I kept all the previous oneshot interfaces unmodified, but added the "tick" functions for tick based operations.

This should address your concern of tickless mode, I believe. And when using tick-based mode, the time calculations should work properly without drift in ticks or time.

@jlaitine
Copy link
Contributor Author

jlaitine commented Mar 7, 2025

Re tested the latest patch.

Ostest passes for mpfs (flat build, smp w. 4 harts), rv-virt:nsh and rv-virt:nsh64, also verified that the tick timer doesn't have the previous errors on the mpfs.

@lupyuen
Copy link
Member

lupyuen commented Mar 7, 2025

@nuttxpr test milkv_duos:nsh

@nuttxpr
Copy link

nuttxpr commented Mar 7, 2025

[Experimental Bot, please feedback here]

Build and Test Successful (milkv_duos:nsh)
https://gitlab.com/lupyuen/nuttx-build-log/-/snippets/4819708

$ git clone https://github.com/tiiuae/nuttx nuttx --branch riscv_tick_timer_improvements
$ git clone https://github.com/apache/nuttx-apps apps --branch master
$ pushd nuttx
$ git reset --hard HEAD
HEAD is now at 695a9873a3 arch/risc-v/src/common/riscv_mtimer.c: Add risc-v tick timer operations
$ popd
$ pushd apps
$ git reset --hard HEAD
HEAD is now at 9c829f665 examples: Add depends to different test cases
$ popd
NuttX Source: https://github.com/apache/nuttx/tree/695a9873a3c4dfc3c16841856a7e04237f33f21b
NuttX Apps: https://github.com/apache/nuttx-apps/tree/9c829f66507165b61df67dd0ec251184bbfb5a06
$ cd nuttx
$ tools/configure.sh milkv_duos:nsh
$ make -j
$ make -j export
$ pushd ../apps
$ ./tools/mkimport.sh -z -x ../nuttx/nuttx-export-10.4.0.tar.gz
$ make -j import
$ popd
$ genromfs -f initrd -d ../apps/bin -V NuttXBootVol
$ head -c 65536 /dev/zero
$ cat nuttx.bin /tmp/nuttx.pad initrd
$ scp Image tftpserver:/tftpboot/Image-sg2000
$ ssh tftpserver ls -l /tftpboot/Image-sg2000
$ cd /home/luppy/nuttx-build-farm
$ ssh tftpserver
OpenSBI v0.9
nsh> uname -a
NuttX 10.4.0 695a9873a3 Mar  7 2025 15:42:19 risc-v milkv_duos
nsh> ostest
arena       81000    81000
ordblks         2        3
mxordblk    7cff8    78ff8
uordblks     2660     4570
fordblks    7e9a0    7ca90
user_main: Exiting
ostest_main: Exiting with status 0
nsh> Now running https://github.com/lupyuen/nuttx-build-farm/blob/main/oz64-power.sh off
----- Power off Oz64
[]

Copy link
Member

@lupyuen lupyuen left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tested OK with OSTest on Real Hardware: Oz64 SG2000 64-bit RISC-V SBC. Thanks :-)

@jerpelea jerpelea requested a review from acassis March 7, 2025 09:53
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Arch: risc-v Issues related to the RISC-V (32-bit or 64-bit) architecture Size: M The size of the change in this PR is medium
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants