HS58: Linux occasionally does not boot with ATLD implementation of atomics

[gmazurki]

After switching to ATLD atomics we see occasional hangs while the Linux boots. The last message that is seen on the console is:

Advanced Linux Sound Architecture Driver Initialized.

The behavior was first described here: #162

If I attach OpenOCD JTAG to the LPU the Linux continues booting.

For 2177 resets the issue happened 626 times, so repro rate is quite high 28%.

This seems to be buildroot (Linux) build specific, as this is quite easily reproducible with one buildroot build, but didn’t happen with another one (with changes not related to this issue).

[gmazurki]

I started the OpenOCD session and then restarted the board. It stopped booting at the “Advanced Linux Sound Architecture Driver Initialized." message. I opened OpenOCD console and typed few command:

> reg pc
pc (/32): 0x814e0c42

> targets
    TargetName         Type       Endian TapName            State
--  ------------------ ---------- ------ ------------------ ------------
 0* arc-em.lpu0        arcv3      little arc-em.lpu0        running
 1  arc-em.lpu1        arcv3      little arc-em.lpu1        running
 2  arc-em.lpu2        arcv3      little arc-em.lpu2        running

> reg pc
pc (/32): 0x814e0c42

>
>
> reg pc
pc (/32): 0x814e0c42

> targets 1
use 'arc-em.lpu1' as target identifier, not '1'
> reg pc
pc (/32): 0x81aa5b82

>

The last command (reg pc on the CPU 1) caused Linux to continue booting.

[gmazurki]

I was able to gather the CPU trace (smart trace). Interestingly, reading AUX regs needed to gather the trace didn’t cause the Linux to continue, unlike “reg pc“ command.

The last entry in the smart trace is:

entry 0:
	SRC = 0x814E0C42
	DST = 0x814E0C3E
	FLAGS = 0x80000400

and corresponds to the following instructions from the vmlinux listing assembler code (function multi_cpu_stop):

814e0c34:	272f 00bf           	clri	r2
814e0c38:	236f 10ff           	dmb	0x3
814e0c3c:	4082                	mov_s	r0,r20
814e0c3e:	202f 048c           	ex	r0,[r18]                                            <<<< DST
814e0c42:	08ff 8050           	breq	r0,0x1,-2	;814e0c3e <multi_cpu_stop+0xa2>     <<<< SRC
814e0c46:	236f 10ff           	dmb	0x3
814e0c4a:	4103                	mov_s	r1,r24
814e0c4c:	212f 0430           	atld.add	r1,[r16]

FLAGS = 0x80000400 means that the bit repeat (0x400) is set, so the CPU spins in the loop.

An ex instruction is one of the “Atomic Memory Operations (AMOs) - 32 bit“.

Could it be a prove that this is some kind of a deadlock?

[gmazurki]

hs58_defconfig.txt

I'm attaching example Linux defconfig that is used in our tests.

[jzbydniewski]

I attach SmaRT trace for all cores, as read by the Metaware Debugger

core-0-smart.txt
core-1-smart.txt
core-2-smart.txt

[gmazurki]

Thanks Jakub,

Looks like the other 2 cores stopped execution somewhere in the function rcu_dynticks_inc:

81aa5b28 <rcu_dynticks_inc>:
81aa5b28:	1cf8 b38e           	std.aw	r14r15,[sp,-8]
81aa5b2c:	c0f1                	push_s	blink
81aa5b2e:	46cb 8143 c680      	mov_s	r14,0x8143c680
81aa5b34:	0be6 0020           	bl.d	996	;81aa5f18 <debug_smp_processor_id>
81aa5b38:	4708                	mov_s	r15,r0
81aa5b3a:	41c3 81d3 eb84      	mov_s	r1,0x81d3eb84
81aa5b40:	2655 194e           	add2	r14,r14,0x25
81aa5b44:	21f0 0000           	ld.as	r0,[r1,r0]
81aa5b48:	661e                	add_s	r14,r14,r0
81aa5b4a:	236f 10ff           	dmb	0x3
81aa5b4e:	272f 00ff           	clri	r3
81aa5b52:	236f 10ff           	dmb	0x3
81aa5b56:	42c3 81d1 609c      	mov_s	r2,0x81d1609c
81aa5b5c:	710c                	mov_s	r0,1
81aa5b5e:	202f 008c           	ex	r0,[r2]
81aa5b62:	08ff 8050           	breq	r0,0x1,-2	;81aa5b5e <rcu_dynticks_inc+0x36>   <<<<<<<<<<<<<<<<< core2
81aa5b66:	236f 10ff           	dmb	0x3
81aa5b6a:	40e1                	mov_s	r0,r15
81aa5b6c:	202f 03b0           	atld.add	r0,[r14]
81aa5b70:	2000 03c0           	add	r0,r0,r15
81aa5b74:	236f 10ff           	dmb	0x3
81aa5b78:	702c                	mov_s	r1,0
81aa5b7a:	212f 008c           	ex	r1,[r2]
81aa5b7e:	236f 10ff           	dmb	0x3
81aa5b82:	262f 00ff           	seti	r3                      <<<<<<<<<<<<<<<<< core1
81aa5b86:	236f 10ff           	dmb	0x3
81aa5b8a:	c0d1                	pop_s	blink
81aa5b8c:	7fe0                	j_s.d	[blink]
81aa5b8e:	1408 358e           	ldd.ab	r14r15,[sp,8]
81aa5b92:	78e0                	nop_s

[gmazurki]

I added defconfig options for additional checking of the locking mechanisms:

CONFIG_TEST_LOCKUP=m
CONFIG_PROVE_LOCKING=y
CONFIG_PROVE_RAW_LOCK_NESTING=y
CONFIG_LOCK_STAT=y
CONFIG_DEBUG_LOCKDEP=y
CONFIG_DEBUG_LOCKING_API_SELFTESTS=y

The boot log:
linux_boot_log_selftest.txt

The boot stalls after Advanced Linux Sound Architecture Driver Initialized. message.

The tests seem to pass: Good, all 391 testcases passed! |

This part shows some errors:

unwinder looping too long, aborting !
unwinder looping too long, aborting !
unwinder looping too long, aborting !
unwinder looping too long, aborting !
INFO: trying to register non-static key.
The code is fine but needs lockdep annotation, or maybe
you didn't initialize this object before use?
turning off the locking correctness validator.
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.15.127 #10

Stack Trace:
  arc_unwind_core+0xf4/0x110
  dump_stack_lvl+0x4c/0x74
  register_lock_class+0x7f0/0x7f4
  __lock_acquire+0x68/0x2ae8
  lock_acquire+0xfc/0x34c
  _raw_spin_lock_irqsave+0x36/0x70
  complete+0x16/0x40
  rest_init+0x118/0x21c
  0x8158ffa4

[gmazurki]

Another symptom of the issue is that with ATLD the rcutorture module shows "process hang" warning. With previous LLSC option the rcutorture was working fine.

# modprobe rcutorture
rcu-torture:--- Start of test: nreaders=2 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 stall_cpu_block=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0 read_exit_delay=13 read_exit_burst=16 nocbs_nthreads=0 nocbs_toggle=1000
rcu:  Start-test grace-period state: g26265 f0x0
rcu_torture_write_types: Testing conditional GPs.
rcu_torture_write_types: Testing expedited GPs.
rcu_torture_write_types: Testing asynchronous GPs.
rcu_torture_write_types: Testing polling GPs.
rcu_torture_write_types: Testing normal GPs.
rcu-torture: Creating rcu_torture_writer task
rcu-torture: Creating rcu_torture_fakewriter task
rcu-torture: rcu_torture_writer task started
rcu-torture: Creating rcu_torture_fakewriter task
rcu-torture: rcu_torture_fakewriter task started
rcu-torture: Creating rcu_torture_fakewriter task
rcu-torture: rcu_torture_fakewriter task started
rcu-torture: Creating rcu_torture_fakewriter task
rcu-torture: rcu_torture_fakewriter task started
rcu-torture: Creating rcu_torture_reader task
rcu-torture: rcu_torture_fakewriter task started
rcu-torture: Creating rcu_torture_reader task
rcu-torture: rcu_torture_reader task started
rcu-torture: Creating rcu_torture_stats task
rcu-torture: rcu_torture_reader task started
rcu-torture: Creating torture_shuffle task
rcu-torture: rcu_torture_stats task started
rcu-torture: Creating torture_stutter task
rcu-torture: torture_shuffle task started
rcu-torture: torture_stutter task started
rcu-torture: Creating rcu_torture_fwd_prog task
rcu-torture: Creating rcu_torture_read_exit task
rcu-torture: rcu_torture_fwd_progress task started
rcu-torture: rcu_torture_read_exit: Start of test
#
#
#
# rcu-torture: rcu_torture_read_exit: End of episode
rcu-torture: rcu_torture_read_exit: Start of episode
rcu-torture: rcu_torture_read_exit: End of episode
INFO: task torture_stutter:2207 blocked for more than 10 seconds.
      Tainted: G           O      5.15.127 #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:torture_stutter state:D stack:    0 pid: 2207 ppid:     2 flags:0x00000000

Stack Trace:
  __switch_to+0x0/0xa8
  __schedule+0x2c8/0x6c4
  schedule+0x50/0xf0
  schedule_hrtimeout_range_clock+0xd8/0x138
  torture_stutter+0x15a/0x1c0 [torture]
  kthread+0x10e/0x144
  ret_from_fork+0x14/0x18
rcu-torture: rcu_torture_read_exit: Start of episode
rcu-torture: rcu_torture_read_exit: End of episode
INFO: task torture_stutter:2207 blocked for more than 10 seconds.
      Tainted: G           O      5.15.127 #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:torture_stutter state:D stack:    0 pid: 2207 ppid:     2 flags:0x00000000

Stack Trace:
  __switch_to+0x0/0xa8
  __schedule+0x2c8/0x6c4
  schedule+0x50/0xf0
  schedule_hrtimeout_range_clock+0xd8/0x138
  torture_stutter+0x15a/0x1c0 [torture]
  kthread+0x10e/0x144
  ret_from_fork+0x14/0x18
rcu-torture: rcu_torture_read_exit: Start of episode
rcu-torture: rcu_torture_read_exit: End of episode

#
#
# rcu-torture: rtc: 36277d34 ver: 705 tfle: 0 rta: 706 rtaf: 0 rtf: 694 rtmbe: 0 rtmbkf: 0/537 rtbe: 0 rtbke: 0 rtbre: 0 rtbf: 0 rtb: 0 nt: 3520 barrier: 0/0:0 read-exits: 67 nocb-toggles: 0:0
rcu-torture: Reader Pipe:  16053121 784 0 0 0 0 0 0 0 0 0
rcu-torture: Reader Batch:  16051820 2085 0 0 0 0 0 0 0 0 0
rcu-torture: Free-Block Circulation:  705 704 703 700 699 698 697 696 695 694 0
rcu-torture: rcu_torture_read_exit: Start of episode
rcu-torture: rcu_torture_read_exit: End of episode

#
#
#
#
#
# INFO: task torture_stutter:2207 blocked for more than 10 seconds.
      Tainted: G           O      5.15.127 #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:torture_stutter state:D stack:    0 pid: 2207 ppid:     2 flags:0x00000000

Stack Trace:
  __switch_to+0x0/0xa8
  __schedule+0x2c8/0x6c4
  schedule+0x50/0xf0
  schedule_hrtimeout_range_clock+0xd8/0x138
  torture_stutter+0x15a/0x1c0 [torture]
  kthread+0x10e/0x144
  ret_from_fork+0x14/0x18

#
# rcu-torture: rcu_torture_read_exit: Start of episode
rcu-torture: rcu_torture_read_exit: End of episode

#
#
#
# rcu_torture_fwd_prog_nr: Duration 1431 cver 240 gps 455
rcu_torture_fwd_prog_cr Duration 12 barrier: 6 pending 37078 n_launders: 87940 n_launders_sa: 8925 n_max_gps: 100 n_max_cbs: 64339 cver 0 gps 9
rcu_torture_fwd_cb_hist: Callback-invocation histogram (duration 19 jiffies): 1s/10: 79016:6 2s/10: 73263:4
rcu-torture: rcu_torture_read_exit: Start of episode
rcu-torture: rcu_torture_read_exit: End of episode
INFO: task torture_stutter:2207 blocked for more than 10 seconds.
      Tainted: G           O      5.15.127 #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:torture_stutter state:D stack:    0 pid: 2207 ppid:     2 flags:0x00000000

Stack Trace:
  __switch_to+0x0/0xa8
  __schedule+0x2c8/0x6c4
  schedule+0x50/0xf0
  schedule_hrtimeout_range_clock+0xd8/0x138
  torture_stutter+0x15a/0x1c0 [torture]
  kthread+0x10e/0x144
  ret_from_fork+0x14/0x18
rcu-torture: rcu_torture_read_exit: Start of episode
rcu-torture: rcu_torture_read_exit: End of episode
INFO: task torture_stutter:2207 blocked for more than 20 seconds.
      Tainted: G           O      5.15.127 #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:torture_stutter state:D stack:    0 pid: 2207 ppid:     2 flags:0x00000000

Stack Trace:
  __switch_to+0x0/0xa8
  __schedule+0x2c8/0x6c4
  schedule+0x50/0xf0
  schedule_hrtimeout_range_clock+0xd8/0x138
  torture_stutter+0x15a/0x1c0 [torture]
  kthread+0x10e/0x144
  ret_from_fork+0x14/0x18
rcu-torture: rcu_torture_read_exit: Start of episode
rcu-torture: rcu_torture_read_exit: End of episode

#
#
#
#
#
#
#
# rmmod rcutorture
rcu-torture: Stopping torture_shuffle task
rcu-torture: Stopping rcu_torture_reader
rcu-torture: Stopping rcu_torture_reader
rcu-torture: Stopping torture_shuffle
rcu-torture: Stopping torture_stutter task
rcu-torture: Stopping torture_stutter
rcu: rcu_preempt: wait state: RCU_GP_WAIT_FQS(5) ->state: 0x402 ->rt_priority 0 delta ->gp_start 1 ->gp_activity 1 ->gp_req_activity 1 ->gp_wake_time 1 ->gp_wake_seq 39469 ->gp_seq 39473 ->gp_seq_needed 39480 ->gp_max 33 ->gp_flags 0x0
rcu-torture: Stopping rcu_torture_fakewriter
rcu:    rcu_node 0:2 ->gp_seq 39473 ->gp_seq_needed 39480 ->qsmask 0x0 .... ->n_boosts 0
rcu:    cpu 0 ->gp_seq_needed 39480
rcu:    cpu 1 ->gp_seq_needed 39480
rcu:    cpu 2 ->gp_seq_needed 39480
rcu: RCU callbacks invoked since boot: 278378
rcu_tasks: RTGS_WAIT_CBS(11) since 131868 g:0 i:0/0 k.
rcu_tasks_rude: RTGS_WAIT_CBS(11) since 131868 g:0 i:0/0 k.
rcu_tasks_trace: RTGS_WAIT_CBS(11) since 131868 g:0 i:0/0 k. N0 h:0/0/0
rcu-torture: Stopping rcu_torture_fakewriter
rcu-torture: Stopping rcu_torture_writer
rcu-torture: Stopping rcu_torture_fakewriter
rcu-torture: rtc: 00000000 VER: 1631 tfle: 0 rta: 1631 rtaf: 0 rtf: 1621 rtmbe: 0 rtmbkf: 0/1175 rtbe: 0 rtbke: 0 rtbre: 0 rtbf: 0 rtb: 0 nt: 7924 barrier: 0/0:0 read-exits: 152 nocb-toggles: 0:0
rcu-torture: Reader Pipe:  34942090 1744 0 0 0 0 0 0 0 0 0
rcu-torture: Reader Batch:  34939104 4728 0 0 0 0 0 0 0 0 0
rcu-torture: Free-Block Circulation:  1630 1630 1629 1628 1627 1625 1624 1623 1622 1621 0
rcu-torture: Stopping rcu_torture_stats
rcu-torture: Stopping rcu_torture_fakewriter
rcu-torture: Stopping rcu_torture_read_exit
rcu-torture: Stopping rcutorture_read_exit task
rcu-torture: Stopping rcu_torture_fwd_prog task
rcu_torture_fwd_prog: tested 1 tested_tries 2
rcu-torture: Stopping rcu_torture_fwd_prog
rcu-torture: Stopping rcu_torture_writer task
rcu-torture: Stopping rcu_torture_reader task
rcu-torture: Stopping rcu_torture_reader task
rcu-torture: Stopping rcu_torture_fakewriter task
rcu-torture: Stopping rcu_torture_fakewriter task
rcu-torture: Stopping rcu_torture_fakewriter task
rcu-torture: Stopping rcu_torture_fakewriter task
rcu:  End-test grace-period state: g39505 f0x0 total-gps=3310
rcu-torture: Stopping rcu_torture_stats task
mem_dump_obj() slab test: rcu_torture_stats = 00000000, &rhp = 86707f08, rhp = 880567f8, &z = ac1d9580
mem_dump_obj(ZERO_SIZE_PTR): zero-size pointer
mem_dump_obj(NULL): NULL pointer
mem_dump_obj(86707f08): non-slab/vmalloc memory
mem_dump_obj(880567f8): slab rcuscale start 880567f8 pointer offset 0
mem_dump_obj(880567fc): slab rcuscale start 880567f8 pointer offset 4
mem_dump_obj(ac1d9580): 11-page vmalloc region starting at 0xac1d1000 allocated at load_module+0xa1e/0x1ff8
mem_dump_obj() kmalloc test: rcu_torture_stats = 00000000, &rhp = 86707f08, rhp = 87533680
mem_dump_obj(kmalloc 87533680): slab kmalloc-128 start 87533680 pointer offset 0 size 128
mem_dump_obj(kmalloc 87533684): slab kmalloc-128 start 87533680 pointer offset 4 size 128
mem_dump_obj() vmalloc test: rcu_torture_stats = 00000000, &rhp = 86707f08, rhp = ac02c000
mem_dump_obj(vmalloc ac02c000): 1-page vmalloc region starting at 0xac02c000 allocated at rcu_torture_cleanup+0x49a/0x6b0 [rcutorture]
mem_dump_obj(vmalloc ac02c004): 1-page vmalloc region starting at 0xac02c000 allocated at rcu_torture_cleanup+0x49a/0x6b0 [rcutorture]
rcu-torture: rtc: 00000000 VER: 1631 tfle: 0 rta: 1631 rtaf: 0 rtf: 1621 rtmbe: 0 rtmbkf: 0/1175 rtbe: 0 rtbke: 0 rtbre: 0 rtbf: 0 rtb: 0 nt: 7924 barrier: 0/0:0 read-exits: 152 nocb-toggles: 0:0
rcu-torture: Reader Pipe:  34942090 1744 0 0 0 0 0 0 0 0 0
rcu-torture: Reader Batch:  34939104 4728 0 0 0 0 0 0 0 0 0
rcu-torture: Free-Block Circulation:  1630 1630 1629 1628 1627 1625 1624 1623 1622 1621 0
rcu-torture:--- End of test: SUCCESS: nreaders=2 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 stall_cpu_block=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0 read_exit_delay=13 read_exit_burst=16 nocbs_nthreads=0 nocbs_toggle=1000
#
#
#

[gmazurki]

I tried reproducing on nSim (multicore), but no luck so far.

[gmazurki]

I'm not sure how the mdb was able to read the smart trace data from all the cores, because from my observation if I read (using OpenOCD) SMART_CONTROL or SMART_DATA registers from core 1 or 2 the Linux immediately resumes booting. It does not have any effect only with core 0. So using OpenOCD I can grab only smart trace from core 0.

Reading status32 register on any core does not resume the Linux boot.

> reg status32
status32 (/32): 0x00080002

> targets 1
use 'arc-em.lpu1' as target identifier, not '1'
> reg status32
status32 (/32): 0x00080002

> targets 2
use 'arc-em.lpu2' as target identifier, not '2'
> reg status32
status32 (/32): 0x00080002

> targets 0
use 'arc-em.lpu0' as target identifier, not '0'
> reg pc
pc (/32): 0x814e0c42

> targets 2
use 'arc-em.lpu2' as target identifier, not '2'
> reg pc
pc (/32): 0x81aa5b82

>

After the last command on core 2 the CPUs were resumed.

[gmazurki]

Reading AUX regs 0x4, 0x6 (IDENTITY, PC) even on core 0 resumes the CPUs.
Reading AUX reg 0xA (STATUS32) on any core does not have any effect - the cluster is stalled.

My suspicion is that OpenOCD in case of some commands triggers another read or write, which has the effect described above.

There is the hypothesis that it could be a lockup in the CPU pipeline and JTAG read/write fills/flushes the pipeline and unlocks the CPUs. This hypothesis is still valid.

@abrodkin @xxkent are you able to reproduce it on your side on your FPGA system?

[xxkent]

I ran Linux on HAPS and in nSIM with options you provided:
CONFIG_TEST_LOCKUP=m
CONFIG_PROVE_LOCKING=y
CONFIG_PROVE_RAW_LOCK_NESTING=y
CONFIG_LOCK_STAT=y
CONFIG_DEBUG_LOCKDEP=y
CONFIG_DEBUG_LOCKING_API_SELFTESTS=y

In both cases there is "Stack Trace message" during boot, this means that this is SW issue:

Stack Trace:
  arc_unwind_core+0xf4/0x110
  dump_stack_lvl+0x4e/0x78
  register_lock_class+0x630/0x634
  __lock_acquire+0x68/0x1bfc
  lock_acquire+0xee/0x32c
  _raw_spin_lock_irqsave+0x40/0x78
  complete+0x16/0x40
  rest_init+0x118/0x21c
  0x81298eac
Running RCU-tasks wait API self tests 

Linux_boot_HAPS.txt
Linux_boot_nSIM.txt

It is quite strange that the deadlock test runs on only core_0 while core_1 and core_2 are in the boot loop. Thus, core_1 and core_2 don't participate in this test.

[xxkent]

I will conduct this test with your hs58_defconfig.txt as the next step.

[xxkent]

The issue (Linux occasionally does not boot with ATLD implementation of atomics) is not reproduced on HAPS. I see some other issue with boot, but it is most likely SW because it exists in nSIM too.

HAPS_Linux_boot.txt
nSIM_Linux_boot.txt

[gmazurki]

Thanks for checking this. How many resets have you performed? In our case repro rate is not 100%, so to be sure you will need to perform tens of resets.
Have you enabled similar defconfig options as per the defconfig I attached? I can do the opposite - to cut down the defconfig and see if there is any change.

[xxkent]

I took exactly config you provided (hs58_defconfig.txt) and changed only CONFIG_LINUX_LINK_BASE=0x0, CONFIG_LINUX_RAM_BASE=0x0, CONFIG_LINUX_MAP_SIZE=0x60000000 and CONFIG_ARC_BUILTIN_DTB_NAME=haps_hs5x_idu.

I did about 6 attempts on HAPS. Ok, then I'll be running this throughout the day to get more attempts and if anything changes, I'll let you know.