arch/arm64: fix boot stage prints with CONFIG_ARCH_EARLY_PRINT=y #15901

gpoulios · 2025-02-24T15:50:27Z

Summary

boot_stage_puts used by early assembly head, calls arm64_lowputc() for each character of the string to be printed in a loop. During that loop it uses x1 as the pointer to the next character to be printed. However, x1 is clobbered^[1] by arm64_lowputc(), resulting in undefined behaviour (only the first character of the string is guaranteed to be printed).

Fix this by using x19 instead.

[1] Observed clobbering behaviour with arm-gnu-toolchain-13.2.Rel1-x86_64-aarch64.

Impact

The change does not affect users, build processes, hardware, documentation or security compatibility.

The only notable effect should be the early console messages in arm64 builds being fully (and more reliably) visible when configured with CONFIG_ARCH_EARLY_PRINT=y.

Testing

Toolchain: arm-gnu-toolchain-13.2.Rel1-x86_64-aarch64
Target: imx93evk:nsh
Extra config: CONFIG_ARCH_EARLY_PRINT=y

WIthout the change, early boot stage messages would appear as:

---[other messages here]

With the change, early boot stage messages are:

- Boot from EL2
- Boot from EL1
- Boot to C runtime for OS Initialize
[other messages here]

arch/arm64/src/common/arm64_head.S

`boot_stage_puts` used by early asm calls arm64_lowputc() for each character in a loop. During that loop it uses x1 as the pointer to the next character to be printed. However, x1 is clobbered by arm64_lowputc(), resulting in undefined behaviour (only the first character of the string is guaranteed to be printed). Fix this by using x19 instead. Signed-off-by: George Poulios <[email protected]>

lupyuen · 2025-02-25T14:44:33Z

@nuttxpr test qemu-armv8a:netnsh

nuttxpr · 2025-02-25T14:53:53Z

[Experimental Bot, please feedback here]

Build and Test Successful (qemu-armv8a:netnsh)
https://gitlab.com/lupyuen/nuttx-build-log/-/snippets/4810752

$ git clone https://github.com/gpoulios/nuttx nuttx --branch master
$ git clone https://github.com/apache/nuttx-apps apps --branch master
$ pushd nuttx
$ git reset --hard HEAD
HEAD is now at b9191c9498 arch/arm64: fix boot stage prints with CONFIG_ARCH_EARLY_PRINT=y
$ popd
$ pushd apps
$ git reset --hard HEAD
HEAD is now at b84f93c4d [nxstyle] fix Relative file path
$ popd
NuttX Source: https://github.com/apache/nuttx/tree/b9191c9498521b94cf6a4695ca1d3dc08e6284f0
NuttX Apps: https://github.com/apache/nuttx-apps/tree/b84f93c4df4d52a2d93134d91223e8c757106d9f
$ cd nuttx
$ tools/configure.sh qemu-armv8a:netnsh
$ make -j
$ dd if=/dev/zero of=./mydisk-1gb.img bs=1M count=1024
$ qemu-system-aarch64 --version
QEMU emulator version 8.2.2 (Debian 1:8.2.2+ds-0ubuntu1.5)
$ qemu-system-aarch64 -cpu cortex-a53 -nographic -machine virt,virtualization=on,gic-version=3 -chardev stdio,id=con,mux=on -serial chardev:con -global virtio-mmio.force-legacy=false -device virtio-serial-device,bus=virtio-mmio-bus.0 -chardev socket,telnet=on,host=127.0.0.1,port=3450,server=on,wait=off,id=foo -device virtconsole,chardev=foo -device virtio-rng-device,bus=virtio-mmio-bus.1 -netdev user,id=u1,hostfwd=tcp:127.0.0.1:10023-10.0.2.15:23,hostfwd=tcp:127.0.0.1:15001-10.0.2.15:5001 -device virtio-net-device,netdev=u1,bus=virtio-mmio-bus.2 -drive file=./mydisk-1gb.img,if=none,format=raw,id=hd -device virtio-blk-device,bus=virtio-mmio-bus.3,drive=hd -mon chardev=con,mode=readline -kernel ./nuttx
nsh> uname -a
NuttX  0.0.0 b9191c9498 Feb 25 2025 22:51:33 arm64 qemu-armv8a
nsh> ostest
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         8        6
mxordblk  7b91f38  7b8fef8
uordblks    51878    54c48
fordblks  7b95788  7b923b8
user_main: Exiting
ostest_main: Exiting with status 0

lupyuen

Tested OK with OSTest on Arm64 QEMU. Thanks :-)

arch/arm64: fix boot stage prints with CONFIG_ARCH_EARLY_PRINT=y #15901 (comment)

pussuw

LGTM, nice catch

gpoulios · 2025-02-25T15:16:05Z

@nuttxpr test qemu-armv8a:netnsh

Patched block gets compiled out without CONFIG_ARCH_EARLY_PRINT=y so I did also a qemu-armv8a:netnsh test with that enabled:

ostest result

- Ready to Boot Primary CPU
- Boot from EL2
- Boot from EL1
- Boot to C runtime for OS Initialize
telnetd [4:100]

NuttShell (NSH)
nsh> uname -a
NuttX  0.0.0 b9191c9498-dirty Feb 25 2025 17:31:44 arm64 qemu-armv8a
nsh> free
    total       used       free    maxused    maxfree  nused  nfree name
129921024     315040  129605984     315720  129589176     66      7 Umem
nsh> ps
PID GROUP PRI POLICY   TYPE    NPX STATE    EVENT     SIGMASK            STACK    USED FILLED COMMAND
  0     0   0 FIFO     Kthread   - Ready              0000000000000000 0008176 0001024  12.5%  Idle_Task
  1     0 192 RR       Kthread   - Waiting  Semaphore 0000000000000000 0008112 0000976  12.0%  hpwork 0x403eb508 0x403eb550
  2     0 100 RR       Kthread   - Waiting  Semaphore 0000000000000000 0008112 0000976  12.0%  lpwork 0x403eb490 0x403eb4d8
  3     3 100 RR       Task      - Running            0000000000000000 0008144 0003344  41.0%  nsh_main
  4     4 100 RR       Task      - Waiting  Semaphore 0000000000020000 0008144 0001824  22.3%  telnetd
nsh> ls -l /dev
/dev:
crw-rw-rw-           0 console
crw-rw-rw-           0 null
cr--r--r--           0 random
crw-rw-rw-           0 telnet
crw-rw-rw-           0 ttyS1
crw-rw-rw-           0 ttyV0
brw-rw-rw-  1073741824 virtblk0
crw-rw-rw-           0 zero
nsh> hello
Hello, World!!
nsh> getprime
Set thread priority to 10
Set thread policy to SCHED_RR
Start thread #0
thread #0 started, looking for primes < 10000, doing 10 run(s)
thread #0 finished, found 1230 primes, last one was 9973
Done
getprime took 500 msec
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=9

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     7be7000  7be7000
ordblks         8        8
mxordblk  7b91f38  7b91f38
uordblks    51878    51878
fordblks  7b95788  7b95788

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     7be7000  7be7000
ordblks         8        8
mxordblk  7b91f38  7b91f38
uordblks    51878    51878
fordblks  7b95788  7b95788

user_main: libc tests

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         8        8
mxordblk  7b91f38  7b91f38
uordblks    51878    51878
fordblks  7b95788  7b95788
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     7be7000  7be7000
ordblks         8        9
mxordblk  7b91f38  7b91f38
uordblks    51878    51858
fordblks  7b95788  7b957a8
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     7be7000  7be7000
ordblks         9        8
mxordblk  7b91f38  7b91f38
uordblks    51858    517a8
fordblks  7b957a8  7b95858

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     7be7000  7be7000
ordblks         8        8
mxordblk  7b91f38  7b91f38
uordblks    517a8    517a8
fordblks  7b95858  7b95858

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     7be7000  7be7000
ordblks         8        8
mxordblk  7b91f38  7b91f38
uordblks    517a8    517a8
fordblks  7b95858  7b95858

user_main: FPU test
Starting task FPU#1
fpu_test: Started task FPU#1 at PID=10
FPU#1: pass 1
Starting task FPU#2
fpu_test: Started task FPU#2 at PID=11
FPU#2: pass 1
FPU#1: pass 2
FPU#2: pass 2
FPU#1: pass 3
FPU#2: pass 3
FPU#1: pass 4
FPU#2: pass 4
FPU#1: pass 5
FPU#2: pass 5
FPU#1: pass 6
FPU#2: pass 6
FPU#1: pass 7
FPU#2: pass 7
FPU#1: pass 8
FPU#2: pass 8
FPU#1: pass 9
FPU#2: pass 9
FPU#1: pass 10
FPU#2: pass 10
FPU#1: pass 11
FPU#2: pass 11
FPU#1: pass 12
FPU#2: pass 12
FPU#1: pass 13
FPU#2: pass 13
FPU#1: pass 14
FPU#2: pass 14
FPU#1: pass 15
FPU#2: pass 15
FPU#1: pass 16
FPU#2: pass 16
FPU#1: Succeeded
FPU#2: Succeeded
fpu_test: Returning

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         8       10
mxordblk  7b91f38  7b8deb8
uordblks    517a8    56400
fordblks  7b95858  7b90c00

user_main: task_restart test

Test task_restart()
restart_main: setenv(VarName, VarValue, TRUE)
restart_main: Started restart_main at PID=12
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=12
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     7be7000  7be7000
ordblks        10        8
mxordblk  7b8deb8  7b8fef0
uordblks    56400    53e40
fordblks  7b90c00  7b931c0

user_main: waitpid test

Test waitpid()
waitpid_start_child: Started waitpid_main at PID=13
waitpid_start_child: Started waitpid_main at PID=14
waitpid_start_child: Started waitpid_main at PID=15
waitpid_test: Waiting for PID=13 with waitpid()
waitpid_main: PID 13 Started
waitpid_main: PID 14 Started
waitpid_main: PID 15 Started
waitpid_main: PID 13 exitting with result=14
waitpid_main: PID 14 exitting with result=14
waitpid_main: PID 15 exitting with result=14
waitpid_test: PID 13 waitpid succeeded with stat_loc=0e00
waitpid_last: Waiting for PID=15 with waitpid()
waitpid_last: PASS: PID 15 waitpid failed with ECHILD.  That may be
            acceptable because child status is disabled on this thread.

Test waitid(P_PID)
waitpid_start_child: Started waitpid_main at PID=21
waitpid_start_child: Started waitpid_main at PID=22
waitpid_start_child: Started waitpid_main at PID=23
waitpid_test: Waiting for PID=21 with waitid()
waitpid_main: PID 21 Started
waitpid_main: PID 22 Started
waitpid_main: PID 23 Started
waitpid_main: PID 21 exitting with result=14
waitpid_main: PID 22 exitting with result=14
waitpid_main: PID 23 exitting with result=14
waitpid_test: waitid PID 21 succeeded with si_status=14
waitpid_last: Waiting for PID=23 with waitpid()
waitpid_last: PASS: PID 23 waitpid failed with ECHILD.  That may be
            acceptable because child status is disabled on this thread.

Test waitid(P_ALL)
waitpid_start_child: Started waitpid_main at PID=26
waitpid_start_child: Started waitpid_main at PID=27
waitpid_start_child: Started waitpid_main at PID=28
waitpid_test: Waiting for any child with waitid()
waitpid_main: PID 26 Started
waitpid_main: PID 27 Started
waitpid_main: PID 28 Started
waitpid_main: PID 26 exitting with result=14
waitpid_main: PID 27 exitting with result=14
waitpid_main: PID 28 exitting with result=14
waitpid_test: PID 26 waitid succeeded with si_status=14
waitpid_last: Waiting for PID=28 with waitpid()
waitpid_last: PASS: PID 28 waitpid failed with ECHILD.  That may be
            acceptable because child status is disabled on this thread.

Test wait()
waitpid_start_child: Started waitpid_main at PID=29
waitpid_start_child: Started waitpid_main at PID=30
waitpid_start_child: Started waitpid_main at PID=31
waitpid_test: Waiting for any child with wait()
waitpid_main: PID 29 Started
waitpid_main: PID 30 Started
waitpid_main: PID 31 Started
waitpid_main: PID 29 exitting with result=14
waitpid_main: PID 30 exitting with result=14
waitpid_main: PID 31 exitting with result=14
waitpid_test: PID 29 wait succeeded with stat_loc=0e00
waitpid_last: Waiting for PID=31 with waitpid()
waitpid_last: PASS: PID 31 waitpid failed with ECHILD.  That may be
            acceptable because child status is disabled on this thread.

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         8       10
mxordblk  7b8fef0  7b8be70
uordblks    53e40    58a98
fordblks  7b931c0  7b8e568

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     7be7000  7be7000
ordblks        10        9
mxordblk  7b8be70  7b8deb8
uordblks    58a98    55af8
fordblks  7b8e568  7b91508

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     7be7000  7be7000
ordblks         9        8
mxordblk  7b8deb8  7b8fef0
uordblks    55af8    53988
fordblks  7b91508  7b93678

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=0xffffffffffffffff
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=0xffffffffffffffff
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     7be7000  7be7000
ordblks         8        8
mxordblk  7b8fef0  7b8fef0
uordblks    53988    53988
fordblks  7b93678  7b93678

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     7be7000  7be7000
ordblks         8        8
mxordblk  7b8fef0  7b8fef0
uordblks    53988    53988
fordblks  7b93678  7b93678

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
waiter_func: Thread 1 waiting on semaphore
sem_test: Starting waiter thread 2
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
waiter_func: Thread 2 new semaphore value = 0
waiter_func: Thread 2 done
poster_func: Thread 3 new semaphore value = 0
poster_func: Thread 3 done

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         8       10
mxordblk  7b8fef0  7b8be70
uordblks    53988    57c70
fordblks  7b93678  7b8f390

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: (103 sec, 630000000 nsec)
AFTER:  (105 sec, 640000000 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: (105 sec, 640000000 nsec)
AFTER:  (106 sec, 650000000 nsec)

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks        10        8
mxordblk  7b8be70  7b8fef0
uordblks    57c70    53988
fordblks  7b8f390  7b93678

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     7be7000  7be7000
ordblks         8        9
mxordblk  7b8fef0  7b8deb8
uordblks    53988    53980
fordblks  7b93678  7b93680

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

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         9        9
mxordblk  7b8deb8  7b8deb8
uordblks    53980    55af8
fordblks  7b93680  7b91508

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

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         9        9
mxordblk  7b8deb8  7b8deb8
uordblks    55af8    539a0
fordblks  7b91508  7b93660

user_main: pthread_rwlock_cancel test
pthread_rwlock_cancel: Starting test

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         9        8
mxordblk  7b8deb8  7b91f38
uordblks    539a0    51830
fordblks  7b93660  7b957d0

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
thread_waiter: Starting 5 second wait for condition
timedwait_test: Joining
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     7be7000  7be7000
ordblks         8        9
mxordblk  7b91f38  7b8fef0
uordblks    51830    539a8
fordblks  7b957d0  7b93658

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     7be7000  7be7000
ordblks         9        9
mxordblk  7b8fef0  7b8deb8
uordblks    539a8    55bb8
fordblks  7b93658  7b91448

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     7be7000  7be7000
ordblks         9        8
mxordblk  7b8deb8  7b8fef0
uordblks    55bb8    53a48
fordblks  7b91448  7b935b8

user_main: sigprocmask test
sigprocmask_test: SUCCESS

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         8        8
mxordblk  7b8fef0  7b8fef0
uordblks    53a48    53a48
fordblks  7b935b8  7b935b8

user_main: signal handler test
sighand_test: Initializing semaphore to 0
sighand_test: Unmasking SIGCHLD
sighand_test: Registering SIGCHLD handler
sighand_test: Starting waiter task
sighand_test: Started waiter_main pid=79
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=79 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     7be7000  7be7000
ordblks         8        7
mxordblk  7b8fef0  7b8fef0
uordblks    53a48    53ab8
fordblks  7b935b8  7b93548

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
waiter_main: Waiting on semaphore
signest_test: Started waiter_main pid=85
signest_test: Starting interfering task at priority 102
interfere_main: Waiting on semaphore
signest_test: Started interfere_main pid=86
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:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         7        6
mxordblk  7b8fef0  7b8deb0
uordblks    53ab8    547d0
fordblks  7b93548  7b92830

user_main: wdog test
wdog_test start...
[  144.620000] wdtest_once 0 ns
[  144.620000] wdtest_once 0 ns
[  144.620000] wdtest_once 0 ns
[  144.620000] wdtest_once 0 ns
[  144.640000] wdtest_once 1 ns
[  144.640000] wdtest_once 1 ns
[  144.640000] wdtest_once 1 ns
[  144.640000] wdtest_once 1 ns
[  144.660000] wdtest_once 10 ns
[  144.660000] wdtest_once 10 ns
[  144.660000] wdtest_once 10 ns
[  144.660000] wdtest_once 10 ns
[  144.680000] wdtest_once 100 ns
[  144.680000] wdtest_once 100 ns
[  144.680000] wdtest_once 100 ns
[  144.680000] wdtest_once 100 ns
[  144.700000] wdtest_once 1000 ns
[  144.700000] wdtest_once 1000 ns
[  144.700000] wdtest_once 1000 ns
[  144.700000] wdtest_once 1000 ns
[  144.720000] wdtest_once 10000 ns
[  144.720000] wdtest_once 10000 ns
[  144.720000] wdtest_once 10000 ns
[  144.720000] wdtest_once 10000 ns
[  144.740000] wdtest_once 100000 ns
[  144.740000] wdtest_once 100000 ns
[  144.740000] wdtest_once 100000 ns
[  144.740000] wdtest_once 100000 ns
[  144.760000] wdtest_once 1000000 ns
[  144.760000] wdtest_once 1000000 ns
[  144.760000] wdtest_once 1000000 ns
[  144.760000] wdtest_once 1000000 ns
[  144.800000] wd_start with maximum delay, cancel OK, rest 9223372036854775806
[  144.800000] wdtest_recursive 1000000us
[  144.800000] wd_start with maximum delay, cancel OK, rest 9223372036854775806
[  144.800000] wdtest_recursive 1000000us
[  144.800000] wd_start with maximum delay, cancel OK, rest 9223372036854775806
[  144.800000] wdtest_recursive 1000000us
[  144.800000] wd_start with maximum delay, cancel OK, rest 9223372036854775806
[  144.800000] wdtest_recursive 1000000us
[  144.920000] recursive wdog triggered 6 times, elapsed tick 12
[  144.920000] wdtest_recursive 10000000us
[  144.920000] recursive wdog triggered 6 times, elapsed tick 12
[  144.920000] wdtest_recursive 10000000us
[  144.920000] recursive wdog triggered 6 times, elapsed tick 12
[  144.920000] wdtest_recursive 10000000us
[  144.920000] recursive wdog triggered 6 times, elapsed tick 12
[  144.920000] wdtest_recursive 10000000us
[  145.040000] recursive wdog triggered 6 times, elapsed tick 12
[  145.040000] recursive wdog triggered 6 times, elapsed tick 12
[  145.040000] recursive wdog triggered 6 times, elapsed tick 12
[  145.040000] recursive wdog triggered 6 times, elapsed tick 12
wdog_test end...

End of test memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         6        8
mxordblk  7b8deb0  7b89e30
uordblks    547d0    58ab8
fordblks  7b92830  7b8e548

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=0x402c5654 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     7be7000  7be7000
ordblks         8        9
mxordblk  7b89e30  7b89e30
uordblks    58ab8    58a80
fordblks  7b8e548  7b8e580

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: 93
rr_test: Starting second get_primes_thread
       Second get_primes_thread: 94
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     7be7000  7be7000
ordblks         9        6
mxordblk  7b89e30  7b8deb0
uordblks    58a80    56908
fordblks  7b8e580  7b906f8

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_test: Thread 4 created
barrier_test: Thread 5 created
barrier_test: Thread 6 created
barrier_test: Thread 7 created
barrier_func: Thread 0 started
barrier_func: Thread 1 started
barrier_func: Thread 2 started
barrier_func: Thread 3 started
barrier_func: Thread 4 started
barrier_func: Thread 5 started
barrier_func: Thread 6 started
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_func: Thread 2 done
barrier_func: Thread 3 done
barrier_func: Thread 4 done
barrier_func: Thread 5 done
barrier_test: Thread 0 completed with result=0
barrier_test: Thread 1 completed with result=0
barrier_test: Thread 2 completed with result=0
barrier_test: Thread 3 completed with result=0
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     7be7000  7be7000
ordblks         6        9
mxordblk  7b8deb0  7b83d78
uordblks    56908    56908
fordblks  7b906f8  7b906f8

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     7be7000  7be7000
ordblks         9        7
mxordblk  7b83d78  7b8deb0
uordblks    56908    54798
fordblks  7b906f8  7b92868

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

Final memory usage:
VARIABLE  BEFORE   AFTER
======== ======== ========
arena     7be7000  7be7000
ordblks         8        6
mxordblk  7b91f38  7b8fef8
uordblks    51878    54c48
fordblks  7b95788  7b923b8
user_main: Exiting
ostest_main: Exiting with status 0

github-actions bot added Arch: arm64 Issues related to ARM64 (64-bit) architecture Size: XS The size of the change in this PR is very small labels Feb 24, 2025

jerpelea approved these changes Feb 25, 2025

View reviewed changes

pussuw reviewed Feb 25, 2025

View reviewed changes

arch/arm64/src/common/arm64_head.S Outdated Show resolved Hide resolved

gpoulios force-pushed the master branch from 99fec82 to f77a6f4 Compare February 25, 2025 14:36

gpoulios force-pushed the master branch from f77a6f4 to b9191c9 Compare February 25, 2025 14:37

lupyuen approved these changes Feb 25, 2025

View reviewed changes

pussuw approved these changes Feb 25, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

arch/arm64: fix boot stage prints with CONFIG_ARCH_EARLY_PRINT=y #15901

arch/arm64: fix boot stage prints with CONFIG_ARCH_EARLY_PRINT=y #15901

gpoulios commented Feb 24, 2025 •

edited

Loading

lupyuen commented Feb 25, 2025

nuttxpr commented Feb 25, 2025

lupyuen left a comment

pussuw left a comment

gpoulios commented Feb 25, 2025 •

edited

Loading

arch/arm64: fix boot stage prints with CONFIG_ARCH_EARLY_PRINT=y #15901

Are you sure you want to change the base?

arch/arm64: fix boot stage prints with CONFIG_ARCH_EARLY_PRINT=y #15901

Conversation

gpoulios commented Feb 24, 2025 • edited Loading

Summary

Impact

Testing

lupyuen commented Feb 25, 2025

nuttxpr commented Feb 25, 2025

lupyuen left a comment

Choose a reason for hiding this comment

pussuw left a comment

Choose a reason for hiding this comment

gpoulios commented Feb 25, 2025 • edited Loading

gpoulios commented Feb 24, 2025 •

edited

Loading

gpoulios commented Feb 25, 2025 •

edited

Loading