Linux/AM3352: Linux sporadically blocked for more the 100 seconds.

0815

Part Number: AM3352

Tool/software: Linux

Hello all,

I am using a Linux build of SDK 2.00.01.07 (4.1.13) with modifications (mainly dts) for our own hardware based on beagleboneblack. Our network application is started within "init" script of initramfs. We do not have other file systems. The system works fine for a while. Sometimes the application is blocked for more than 100 seconds (often exactly 103 seconds). In this situation the cpu is used 99% in kernel space and no threading is done. The serial console can be used sometimes limited. After this starvation the system continuous normaly. In some cases a rcu_preempt stall is shown afterwards (see below).

Is there anyone who can advice?

-- Thank you in advance
-- Peter

total boot log:

U-Boot 2015.07 (Mar 16 2017 - 10:38:29 +0100)

I2C: ready
DRAM: 128 MiB
MMC: OMAP SD/MMC: 0, OMAP SD/MMC: 1
Using default environment

Net:   <ethaddr> not set. Validating first E-fuse MAC
cpsw, usb_ether
Hit any key to stop autoboot: 0
File transfer command: par = 0x10
No type test
XHIF boot
bootargs: console=ttyS0,115200n8 mem=128M init=/init fastboot rootdelay=0 ertec_boot=rel build=(94) root=/dev/ram0 rw ip=off rootfstype=ramfs
File transfer command: kernel = 0x01
Copying file to: 0x82000000 ####
Transfered size: 0x00325698
File transfer command: fdt = 0x03
Copying file to: 0x84000000 #
Transfered size: 0x00008680
File transfer command: rd = 0x02
Copying file to: 0x84080000 #######
Transfered size: 0x00600923
File transfer command: end = 0x5555
zImage: 0x82000000 initrd: 0x84080000:600923 fdt: 0x84000000
Kernel image @ 0x82000000 [ 0x000000 - 0x325698 ]
## Flattened Device Tree blob at 84000000
   Booting using the fdt blob at 0x84000000
   Loading Ramdisk to 86925000, end 86f25923 ... OK
   Loading Device Tree to 86919000, end 8692467f ... OK

Starting kernel ...

Uncompressing Linux... done, booting the kernel.
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 4.1.13 (ubuntu@ubuntu) (gcc version 4.9.3 20150413 (prerelease) (Linaro GCC 4.9-2015.05) ) #1 PREEMPT Thu Mar 16 10:47:05 CET 2017
[    0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] Machine model: xyz
[    0.000000] cma: Reserved 24 MiB at 0x85000000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] AM335X ES2.1 (neon )
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 32480
[    0.000000] Kernel command line: console=ttyS0,115200n8 mem=128M init=/init fastboot rootdelay=0 ertec_boot=rel build=(94) root=/dev/ram0 rw ip=off rootfstype=ramfs
[    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Memory: 89496K/131072K available (6379K kernel code, 259K rwdata, 2172K rodata, 268K init, 229K bss, 17000K reserved, 24576K cma-reserved, 0K highmem)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xc8800000 - 0xff000000   ( 872 MB)
[    0.000000]     lowmem : 0xc0000000 - 0xc8000000   ( 128 MB)
[    0.000000]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
[    0.000000]     modules : 0xbf000000 - 0xbfe00000   ( 14 MB)
[    0.000000]       .text : 0xc0008000 - 0xc086205c   (8553 kB)
[    0.000000]       .init : 0xc0863000 - 0xc08a6000   ( 268 kB)
[    0.000000]       .data : 0xc08a6000 - 0xc08e6d68   ( 260 kB)
[    0.000000]        .bss : 0xc08e9000 - 0xc0922708   ( 230 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] Additional per-CPU info printed with stalls.
[    0.000000] RCU kthread priority: 1.
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts
[    0.000000] OMAP clockevent source: timer2 at 25000000 Hz
[    0.000030] sched_clock: 32 bits at 25MHz, resolution 40ns, wraps every 85899345900ns
[    0.000076] clocksource timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 76450417870 ns
[    0.000103] OMAP clocksource: timer1 at 25000000 Hz
[    0.000482] Console: colour dummy device 80x30
[    0.000555] Calibrating delay loop... 298.59 BogoMIPS (lpj=1492992)
[    0.067853] pid_max: default: 32768 minimum: 301
[    0.068063] Security Framework initialized
[    0.068178] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.068208] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.069745] Initializing cgroup subsys blkio
[    0.069803] Initializing cgroup subsys memory
[    0.069899] Initializing cgroup subsys devices
[    0.069939] Initializing cgroup subsys freezer
[    0.069977] Initializing cgroup subsys perf_event
[    0.070037] CPU: Testing write buffer coherency: ok
[    0.070797] Setting up static identity map for 0x80008240 - 0x800082b0
[    0.074631] devtmpfs: initialized
[    0.101650] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[    0.125570] omap_hwmod: tptc0 using broken dt data from edma
[    0.125869] omap_hwmod: tptc1 using broken dt data from edma
[    0.126133] omap_hwmod: tptc2 using broken dt data from edma
[    0.133372] omap_hwmod: debugss: _wait_target_disable failed
[    0.203280] clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.208174] pinctrl core: initialized pinctrl subsystem
[    0.211113] NET: Registered protocol family 16
[    0.216652] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.247946] cpuidle: using governor ladder
[    0.277902] cpuidle: using governor menu
[    0.287050] OMAP GPIO hardware version 0.1
[    0.303482] omap-gpmc 50000000.gpmc: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_xhif_pins, deferring probe
[    0.308808] No ATAGs?
[    0.308869] hw-breakpoint: debug architecture 0x4 unsupported.
[    0.379206] edma-dma-engine edma-dma-engine.0: TI EDMA DMA engine driver
[    0.386601] vgaarb: loaded
[    0.388020] SCSI subsystem initialized
[    0.389349] media: Linux media interface: v0.10
[    0.389534] Linux video capture interface: v2.00
[    0.389682] pps_core: LinuxPPS API ver. 1 registered
[    0.389705] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.389788] PTP clock support registered
[    0.391778] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400
[    0.392294] Advanced Linux Sound Architecture Driver Initialized.
[    0.394387] Switched to clocksource timer1
[    0.421957] NET: Registered protocol family 2
[    0.423864] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.423929] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)
[    0.423979] TCP: Hash tables configured (established 1024 bind 1024)
[    0.424142] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.424199] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.424756] NET: Registered protocol family 1
[    0.425558] RPC: Registered named UNIX socket transport module.
[    0.425589] RPC: Registered udp transport module.
[    0.425607] RPC: Registered tcp transport module.
[    0.425626] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.426800] Trying to unpack rootfs image as initramfs...
[    1.677577] Freeing initrd memory: 6148K (c6925000 - c6f26000)
[    1.678552] CPU PMU: Failed to parse /pmu/interrupt-affinity[0]
[    1.678660] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[    1.683206] futex hash table entries: 256 (order: -1, 3072 bytes)
[    1.683419] audit: initializing netlink subsys (disabled)
[    1.683567] audit: type=2000 audit(1.670:1): initialized
[    1.703302] VFS: Disk quotas dquot_6.6.0
[    1.703820] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.709613] NFS: Registering the id_resolver key type
[    1.709764] Key type id_resolver registered
[    1.709786] Key type id_legacy registered
[    1.709955] jffs2: version 2.2. (NAND) (SUMMARY) © 2001-2006 Red Hat, Inc.
[    1.716593] NET: Registered protocol family 38
[    1.716762] io scheduler noop registered
[    1.716801] io scheduler deadline registered
[    1.716948] io scheduler cfq registered (default)
[    1.719367] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568
[    1.724196] wkup_m3_ipc 44e11324.wkup_m3_ipc: could not get rproc handle
[    1.726892] Serial: 8250/16550 driver, 10 ports, IRQ sharing enabled
[    1.736129] console [ttyS0] disabled
[    1.736303] 44e09000.serial: ttyS0 at MMIO 0x44e09000 (irq = 155, base_baud = 3000000) is a 8250
[    2.388560] console [ttyS0] enabled
[    2.394487] [drm] Initialized drm 1.1.0 20060810
[    2.426381] brd: module loaded
[    2.442705] loop: module loaded
[    2.448175] mtdoops: mtd device (mtddev=name/number) must be supplied
[    2.481682] davinci_mdio 4a101000.mdio: enable phy with ret = 0
[    2.554443] davinci_mdio 4a101000.mdio: davinci mdio revision 1.6
[    2.560596] davinci_mdio 4a101000.mdio: detected phy mask fffffffd
[    2.583031] libphy: 4a101000.mdio: probed
[    2.587432] davinci_mdio 4a101000.mdio: phy[1]: device 4a101000.mdio:01, driver unknown
[    2.597320] cpsw 4a100000.ethernet: Detected MACID = 40:ec:f8:09:e9:e5
[    2.608120] mousedev: PS/2 mouse device common for all mice
[    2.613787] i2c /dev entries driver
[    2.620020] ledtrig-cpu: registered to indicate activity on CPUs
[    2.626942] omap-aes 53500000.aes: OMAP AES hw accel rev: 3.2
[    2.635921] omap-sham 53100000.sham: hw accel on OMAP rev 4.3
[    2.645433] remoteproc0: wkup_m3 is available
[    2.649940] remoteproc0: Note: remoteproc is still under development and considered experimental.
[    2.659412] remoteproc0: THE BINARY FORMAT IS NOT YET FINALIZED, and backward compatibility isn't yet guaranteed.
[    2.676640] oprofile: using arm/armv7
[    2.681165] Initializing XFRM netlink socket
[    2.685925] NET: Registered protocol family 17
[    2.690508] NET: Registered protocol family 15
[    2.695379] Key type dns_resolver registered
[    2.700474] omap_voltage_late_init: Voltage driver support not added
[    2.707783] cpu cpu0: of_pm_voltdm_notifier_register: Failed to get cpu0 regulator/voltdm: -517
[    2.716730] cpu cpu0: cpu0 clock notifier not ready, retry
[    2.723019] ThumbEE CPU extension supported.
[    2.727540] Registering SWP/SWPB emulation handler
[    2.737708] omap-gpmc 50000000.gpmc: GPMC revision 6.0
[    2.742933] gpmc_mem_init: disabling cs 0 mapped at 0x0-0x1000000
[    2.753067] cpu cpu0: of_pm_voltdm_notifier_register: Failed to get cpu0 regulator/voltdm: -517
[    2.762108] remoteproc0: powering up wkup_m3
[    2.768721] remoteproc0: Booting fw image am335x-pm-firmware.elf, size 219803
[    2.776396] cpu cpu0: cpu0 clock notifier not ready, retry
[    2.782960] hctosys: unable to open rtc device (rtc0)
[    2.788774] remoteproc0: remote processor wkup_m3 is now up
[    2.794516] wkup_m3_ipc 44e11324.wkup_m3_ipc: CM3 Firmware Version = 0x191
[    2.810741] vmmcsd_fixed: disabling
[    2.815171] ALSA device list:
[    2.818183]   No soundcards found.
[    2.823277] Freeing unused kernel memory: 268K (c0863000 - c08a6000)
Loading, please wait...
[    2.982820] init: Boot from ERTEC with rel
[    2.987892] init: Build number is (94)
[    3.064103] systemd-udevd[98]: starting version 215
[    3.090944] random: systemd-udevd urandom read with 4 bits of entropy available
Begin: Loading essential drivers
... [    4.338142] cpu cpu0: of_pm_voltdm_notifier_register: Failed to get cpu0 regulator/voltdm: -517
[    4.364911] cpu cpu0: cpu0 clock notifier not ready, retry
[    4.493304] m25p80: Unknown symbol spi_nor_scan (err 0)
[    4.562921] m25p80 spi1.0: m25p80 (1024 Kbytes)
[    4.567858] 1 ofpart partitions found on MTD device spi1.0
[    4.573392] Creating 1 MTD partitions on "spi1.0":
[    4.578500] 0x000000000000-0x000000100000 : "spi-nor"
[    4.601053] cpu cpu0: of_pm_voltdm_notifier_register: Failed to get cpu0 regulator/voltdm: -517
done.
Begin: Running /scripts/init-premount ... done.
Begin: Mounting root file system ... Begin: Running /scripts/local-top ... [    4.626218] cpu cpu0: cpu0 clock notifier not ready, retry
done.
Begin: Running /scripts/local-premount ... done.
done.
[    4.740145] net eth0: initializing cpsw version 1.12 (0)
[    4.750449] cpu cpu0: of_pm_voltdm_notifier_register: Failed to get cpu0 regulator/voltdm: -517
[    4.759608] cpu cpu0: cpu0 clock notifier not ready, retry
[    4.834831] net eth0: phy found : id is : 0x20005c90
[    4.969931] init: no spi path set, no spi flash mounted
[    4.986874] syslogd started: BusyBox v1.21.1
[    4.991988] init: Starting application /app/gw_app with

Sometimes shown:

[16896.185613] INFO: rcu_preempt self-detected stall on CPU

[16896.191042] 0: (1 ticks this GP) idle=963/1/0 softirq=269972/269972 fqs=0

[16896.198049] (t=10308 jiffies g=169238 c=169237 q=4)

[16896.203152] rcu_preempt kthread starved for 10308 jiffies!

[16896.208676] Task dump for CPU 0:

[16896.211930] swapper R running 0 0 0 0x00000002

[16896.218351] Backtrace:

[16896.220895] [<c0012bb8>] (dump_backtrace) from [<c0012dd8>] (show_stack+0x18/0x1c)

[16896.228512] r7:c08b2cf0 r6:80030193 r5:00000000 r4:c08a8878

[16896.234292] [<c0012dc0>] (show_stack) from [<c0059e7c>] (sched_show_task+0xac/0x108)

[16896.242103] [<c0059dd0>] (sched_show_task) from [<c005b080>] (dump_cpu_task+0x24/0x30)

[16896.250066] r5:c08b2cf0 r4:00000000

[16896.253724] [<c005b05c>] (dump_cpu_task) from [<c0071ca4>] (rcu_dump_cpu_stacks+0xa0/0x100)

[16896.262151] [<c0071c04>] (rcu_dump_cpu_stacks) from [<c00752cc>] (rcu_check_callbacks+0x448/0x890)

[16896.271159] r9:c08b3310 r8:c08a6138 r7:c08b3050 r6:c08a6140 r5:c08b2cf0 r4:c08b30cc

[16896.279038] [<c0074e84>] (rcu_check_callbacks) from [<c00786bc>] (update_process_times+0x40/0x6c)

[16896.287960] r10:00000001 r9:c08b3318 r8:c08a4000 r7:00000f5d r6:f2e02ec8 r5:00000000

[16896.295900] r4:c08a8878

[16896.298494] [<c007867c>] (update_process_times) from [<c0087334>] (tick_sched_handle+0x50/0x5c)

[16896.307242] r5:c08a5f20 r4:c08b3a80

[16896.310885] [<c00872e4>] (tick_sched_handle) from [<c0087388>] (tick_sched_timer+0x48/0x90)

[16896.319304] [<c0087340>] (tick_sched_timer) from [<c00792fc>] (__run_hrtimer+0x6c/0x130)

[16896.327441] r7:00000000 r6:c0087340 r5:c08b3350 r4:c08b3a80

[16896.333203] [<c0079290>] (__run_hrtimer) from [<c0079698>] (hrtimer_interrupt+0x11c/0x2e8)

[16896.341514] r7:00000000 r6:c08b3318 r5:00000f5d r4:f2dfc820

[16896.347279] [<c007957c>] (hrtimer_interrupt) from [<c0024d6c>] (omap2_gp_timer_interrupt+0x2c/0x3c)

[16896.356376] r10:c08e445a r9:c7004c00 r8:00000010 r7:00000000 r6:00000000 r5:c08aa974

[16896.364314] r4:c08aa974

[16896.366914] [<c0024d40>] (omap2_gp_timer_interrupt) from [<c006a770>] (handle_irq_event_percpu+0x7c/0x148)

[16896.376647] [<c006a6f4>] (handle_irq_event_percpu) from [<c006a8a4>] (handle_irq_event+0x68/0x90)

[16896.385569] r10:00000001 r9:c08a6110 r8:c7006000 r7:00000001 r6:00000000 r5:c08aa974

[16896.393507] r4:c7004c00

[16896.396091] [<c006a83c>] (handle_irq_event) from [<c006d3f0>] (handle_level_irq+0xa8/0x154)

[16896.404490] r5:c08bcf94 r4:c7004c00

[16896.408133] [<c006d348>] (handle_level_irq) from [<c0069e98>] (generic_handle_irq+0x30/0x44)

[16896.416619] r5:c08bcf94 r4:00000010

[16896.420266] [<c0069e68>] (generic_handle_irq) from [<c006a0f8>] (__handle_domain_irq+0x50/0xb0)

[16896.429014] r5:c08bcf94 r4:00000010

[16896.432658] [<c006a0a8>] (__handle_domain_irq) from [<c000947c>] (omap_intc_handle_irq+0xc8/0xd8)

[16896.441579] r9:c08a6110 r8:00000000 r7:00000044 r6:c08a5f20 r5:c090f900 r4:c08bd200

[16896.449465] [<c00093b4>] (omap_intc_handle_irq) from [<c063ef40>] (__irq_svc+0x40/0x74)

[16896.457519] Exception stack(0xc08a5f20 to 0xc08a5f68)

[16896.462620] 5f20: 00000001 00000000 00000000 c0020140 c08a4000 c08a6110 00000000 00000000

[16896.470858] 5f40: 00000000 c08a6110 00000001 c08a5f74 c08a5f78 c08a5f68 c00102bc c00102c0

[16896.479085] 5f60: 60030013 ffffffff

[16896.482598] r7:c08a5f54 r6:ffffffff r5:60030013 r4:c00102c0

[16896.488365] [<c0010288>] (arch_cpu_idle) from [<c0061c70>] (cpu_startup_entry+0x194/0x214)

[16896.496714] [<c0061adc>] (cpu_startup_entry) from [<c0636898>] (rest_init+0x78/0x90)

[16896.504502] r7:c08a6000

[16896.507106] [<c0636820>] (rest_init) from [<c0862c90>] (start_kernel+0x358/0x3c8)

[16896.514632] r5:00000001 r4:c08e7050

[16896.518285] [<c0862938>] (start_kernel) from [<80008078>] (0x80008078)

over 7 years ago

0 Cvetolin Shulev-XID over 7 years ago

TI__Guru 65405 points

Hi Peter,

According to the kernel log a application loads the CPU for loag time and causing stall then the kernel CPU stall detector activates.
I suggest you to read instruction in ../<Linux_dir>/Documentation/RCU/stallwarn.txt which can help to make optimal kernel configuration from minimizing CPU stall time.

BR
Tsvetolin Shulev

0 0815 over 7 years ago in reply to Cvetolin Shulev-XID

Prodigy 130 points

Thank you Tsvetolin,

I configured the kernel from scratch and not based on BBB and it seems to work. No stalls while the night.

-- best regards
-- Peter

0 Cvetolin Shulev-XID over 7 years ago in reply to 0815

TI__Guru 65405 points

Peter,

Thank you for feedback. Can I count the issue for solved?

BR
Tsvetolin Shulev

0 0815 over 7 years ago in reply to Cvetolin Shulev-XID

Prodigy 130 points

Hi Tsvetolin,

unfortunately not, but I have more details. In the blocking situation, the thread "rcub" is in state "D" and has a different backtrace with "rt_mutex_lock" as normal.

-- regards
-- Peter

[53455.875701] rcuc/0          S c06082e4     0    10      2 0x00000000
[53455.882170] Backtrace:
[53455.884681] [<c0608124>] (__schedule) from [<c0608628>] (schedule+0x44/0x9c)
[53455.891825] r9:00000000 r8:00000002 r7:c08649ac r6:00000001 r5:c7042180 r4:c706e000
[53455.899850] [<c06085e4>] (schedule) from [<c0053f60>] (smpboot_thread_fn+0x1c0/0x230)
[53455.907781] r5:c7042180 r4:c706e000
[53455.911462] [<c0053da0>] (smpboot_thread_fn) from [<c0050884>] (kthread+0xd4/0xf0)
[53455.919129] r9:00000000 r8:00000000 r7:c0053da0 r6:c7042180 r5:c7042300 r4:00000000
[53455.927138] [<c00507b0>] (kthread) from [<c000f8e8>] (ret_from_fork+0x14/0x2c)
[53455.934421] r7:00000000 r6:00000000 r5:c00507b0 r4:c7042300
[53455.940267] rcub/0          D c06082e4     0    11      2 0x00000000
[53455.946780] Backtrace:
[53455.949297] [<c0608124>] (__schedule) from [<c0608628>] (schedule+0x44/0x9c)
[53455.956442] r9:c38b7a80 r8:c7071ed4 r7:00000000 r6:00000002 r5:c08645c0 r4:c7070000
[53455.964409] [<c06085e4>] (schedule) from [<c060a804>] (__rt_mutex_slowlock+0x54/0x10c)
[53455.972424] r5:c08645c0 r4:c7070000
[53455.976158] [<c060a7b0>] (__rt_mutex_slowlock) from [<c060a970>] (rt_mutex_slowlock+0xb4/0x240)
[53455.984923] r9:00000000 r8:00000002 r7:00000000 r6:c7071ed4 r5:00000000 r4:c08645c0
[53455.992932] [<c060a8bc>] (rt_mutex_slowlock) from [<c060ab18>] (rt_mutex_lock+0x1c/0x20)
[53456.001123] r10:c7070000 r9:00000000 r8:a0030013 r7:00000000 r6:c08645c0 r5:00000001
[53456.009197] r4:c0864580
[53456.011816] [<c060aafc>] (rt_mutex_lock) from [<c006f428>] (rcu_boost_kthread+0xec/0x1a0)
[53456.020116] [<c006f33c>] (rcu_boost_kthread) from [<c0050884>] (kthread+0xd4/0xf0)
[53456.027784] r10:00000000 r9:00000000 r8:00000000 r7:c006f33c r6:c0864580 r5:c7042300
[53456.035853] r4:00000000 r3:c7046d00
[53456.039532] [<c00507b0>] (kthread) from [<c000f8e8>] (ret_from_fork+0x14/0x2c)
[53456.046854] r7:00000000 r6:00000000 r5:c00507b0 r4:c7042300
[53456.052666] khelper         S c06082e4     0    12      2 0x00000000
[53456.059184] Backtrace:
[53456.061699] [<c0608124>] (__schedule) from [<c0608628>] (schedule+0x44/0x9c)
[53456.068843] r9:00000000 r8:c7072000 r7:c704323c r6:c7040700 r5:c7043200 r4:c7072000
[53456.076858] [<c06085e4>] (schedule) from [<c004bd14>] (rescuer_thread+0x2f4/0x364)
[53456.084491] r5:c7043200 r4:c7040700
[53456.088209] [<c004ba20>] (rescuer_thread) from [<c0050884>] (kthread+0xd4/0xf0)
[53456.095579] r10:00000000 r9:00000000 r8:00000000 r7:c004ba20 r6:c7040700 r5:c70423c0
[53456.103650] r4:00000000
[53456.106284] [<c00507b0>] (kthread) from [<c000f8e8>] (ret_from_fork+0x14/0x2c)
[53456.113567] r7:00000000 r6:00000000 r5:c00507b0 r4:c70423c0

0 0815 over 7 years ago in reply to 0815

Prodigy 130 points

Hi all,

an interessting detail is that while this blocking Situation the heartbeat led flashes more then twice as fast as normal. After the blockade this flashing frequency reduces over many seconds slowly to normal mode.

-- Peter

0 Ravikumar Kattekola over 7 years ago in reply to 0815

TI__Expert 4230 points

Hi,
Are you saying the block happens and unblock after sometime ?

You may enable DETECT_HUNG_TASK and set DEFAULT_HUNG_TASK_TIMEOUT to a lower value say 60,
also enable LOCKUP_DETECTOR and WQ_WATCHDOG to get more details on which exact task/workque is hung and if it's due to a lock up.

Regards,
RK

0 0815 over 6 years ago in reply to Ravikumar Kattekola

Prodigy 130 points

Hi all,

first thanks to all for support. After I have instrumented and debugged the kernel, Now I know that the error comes form reading the counter register of the wall clock (DMTimer 1ms) in "__omap_dm_timer_read". The result of this access leads sporadicly to a nonmonotonic value (lower 16 bits are 0000) and to a negative time delta. This causes this long sleep periode (103sec) of the cpu.

Is this a known errata of AM3352 and if yes, is a workaround possible?

-- Thanks in advance
-- Peter

0 0815 over 6 years ago in reply to 0815

Prodigy 130 points

Hi all,

now we solved the problem. Our Linux build (derived from beaglebone) uses DMTimer_1ms for the wall clock. This timer is in POSTED mode after power on per default. But this is only allowed when 32k clk is used. We are using 25 mhz clk. The initialisation of Linux persumes a NONPOSTED mode, which is correct for other timer types, and do not change the mode. So counter reads are sometimes incorrect.

I added a "disable_posted" function in "timer.c" and "dmtimer.h" and the counter system works fine

-- Best regards
-- Peter

0 one and zero over 6 years ago in reply to 0815

TI__Genius 17676 points

Hi Camps,

I have an additional comment on that:

In the TRM Section 20.2.4.14 TSICR Register, Figure 20-45 we state the POSTED bit is 0 after reset. However Table 20-49 states the POSTED bit is 1 after reset.

It seems 1 is correct ....

And I have an additional question:

It seems that ERRATA patch I103_I767 in „timer.h“ and „dmtimer.h“ doesn't address this issue automatically. What needs to be done to "enable" this patch?

Kind regards,

one and zero

0 0815 over 6 years ago in reply to one and zero

Prodigy 130 points

Hi one and zero,

after reset the POSTED bit in TSICR (at offset 0x40) is definitely 1 on AM3352 as the table 20-49 states.

The errata patch I103_I767 prohibits to set POSTED mode on certain platforms, but it could not be used for resetting timers to NONPOSTED mode. To correct this the initialization of the timer have to clear the POSTED bit in case of platforms addressed by the patch I103_I767.

-- Peter

0 Steve Kipisz over 6 years ago in reply to 0815

TI__Genius 15510 points

Can you post your code changes?

Steve K.

0 0815 over 6 years ago in reply to Steve Kipisz

Prodigy 130 points

Hello Steve,

here are the modification:

dmtimer.h:
/*
* __omap_dm_timer_enable_posted - enables write posted mode
* @timer:      pointer to timer instance handle
*
* Enables the write posted mode for the timer. When posted mode is enabled
* writes to certain timer registers are immediately acknowledged by the
* internal bus and hence prevents stalling the CPU waiting for the write to
* complete. Enabling this feature can improve performance for writing to the
* timer registers.
*/
static inline void __omap_dm_timer_enable_posted(struct omap_dm_timer *timer)
{
- if (timer->posted)
-  return;
-
if (timer->errata & OMAP_TIMER_ERRATA_I103_I767) {
  timer->posted = OMAP_TIMER_NONPOSTED;
  __omap_dm_timer_write(timer, OMAP_TIMER_IF_CTRL_REG, 0, 0);
  return;
}

__omap_dm_timer_write(timer, OMAP_TIMER_IF_CTRL_REG,
OMAP_TIMER_CTRL_POSTED, 0);
timer->context.tsicr = OMAP_TIMER_CTRL_POSTED;
timer->posted = OMAP_TIMER_POSTED;
}

+/*
+ * __omap_dm_timer_disable_posted - disables write posted mode
+ * @timer:      pointer to timer instance handle
+ *
+ * disables the write posted mode for the timer. When posted mode is enabled
+ * writes to certain timer registers are immediately acknowledged by the
+ * internal bus and hence prevents stalling the CPU waiting for the write to
+ * complete. Enabling this feature can improve performance for writing to the
+ * timer registers.
+ */
+static inline void __omap_dm_timer_disable_posted(struct omap_dm_timer *timer)
+{
+    __omap_dm_timer_write(timer, OMAP_TIMER_IF_CTRL_REG, 0, 0);
+    timer->context.tsicr = 0;
+    timer->posted = OMAP_TIMER_NONPOSTED;
+}

timer.c:
if (posted)
__omap_dm_timer_enable_posted(timer);
+ else
+ __omap_dm_timer_disable_posted(timer);

/* Check that the intended posted configuration matches the actual */
if (posted != timer->posted)
return -EINVAL;

You can check your environment if you need these changes with the console command:

busybox devmem 0x44e31040

If you get 0x4 then the timer (DMTimer_1ms) is in POSTED mode. You can also do a "dirty" patch at startup script by resetting the register:

busybox devmem 0x44e31040 32 0

-- Peter

Processors

Processors forum

Linux/AM3352: Linux sporadically blocked for more the 100 seconds.