On 02/20/2013 06:01 PM, John Stultz wrote: > Hey Kukjin, Andrzej, > I recently started playing around with functionfs, and have > noticed some strange behavior with my origen board. > > If I enable the FunctionFS gadget driver, I see the board hang at boot > here: > > [ 2.360000] USB Mass Storage support registered. > [ 2.365000] s3c-hsotg s3c-hsotg: regs f0040000, irq 103 > [ 2.375000] s3c-hsotg s3c-hsotg: EPs:15 > [ 2.380000] s3c-hsotg s3c-hsotg: dedicated fifos > [ 2.385000] g_ffs: file system registered > [ 2.390000] mousedev: PS/2 mouse device common for all mice > [ 2.395000] s5p-fimc exynos4-fimc.0: start latency exceeded, new > value 792 ns > [ 2.400000] s5p-fimc exynos4-fimc.0: state restore latency > exceeded, new vals > [ 2.410000] s5p-fimc exynos4-fimc.0: stop latency exceeded, new > value 667 ns > [ 2.420000] s5p-fimc exynos4-fimc.0: state save latency exceeded, > new value s > [ 2.425000] s5p-fimc exynos4-fimc.1: start latency exceeded, new > value 625 ns > [ 2.435000] s5p-fimc exynos4-fimc.1: state restore latency > exceeded, new vals > [ 2.440000] s5p-fimc exynos4-fimc.1: stop latency exceeded, new > value 750 ns > [ 2.450000] s5p-fimc exynos4-fimc.1: start latency exceeded, new > value 667 ns > [ 2.455000] s5p-fimc exynos4-fimc.1: state save latency exceeded, > new value s > > > And it gets no further. Trying to send a sysrq-t (or anything after a > break) doesn't seem to do anything either. > > Trying to debug this a bit more, I added "initcall_debug > ignore_loglevel" to the boot arguments, but strangely, that allows it > to boot and everything seems to be fine. I added a number of printks > to the g_ffs driver, but it doesn't seem like the hang is happening in > that code (though de-configuring it does avoid the issue - so maybe > not?). So I also enabled lockdep to see if it might show a locking problem even when initcall_debug avoids the race. Unfortunately nothing shows up at boot, but when I try to use FunctionFS I got the following lockdep splat, which then triggered a warning and then finally an oops all in succession. The core lockdep parts are below, and the full log is attached. (Sorry its cropped at 80 lines, I wasn't logging my screen session at the time, so its all copy-pasted. Let me know if you'd need me to recreate the problem.) [ 109.290000] ========================================================= [ 109.295000] [ INFO: possible irq lock inversion dependency detected ] [ 109.305000] 3.8.0-dirty #199 Not tainted [ 109.310000] --------------------------------------------------------- [ 109.315000] swapper/0/0 just changed the state of lock: [ 109.320000] (&(&hsotg->lock)->rlock){-.....}, at: [] s3c_hsotg_ir8 [ 109.325000] but this lock took another, HARDIRQ-unsafe lock in the past: [ 109.335000] (clocks_mutex){+.+...} and interrupts could create inverse lock ordering between them. [ 109.345000] [ 109.345000] other info that might help us debug this: [ 109.350000] Possible interrupt unsafe locking scenario: [ 109.350000] [ 109.355000] CPU0 CPU1 [ 109.360000] ---- ---- [ 109.365000] lock(clocks_mutex); [ 109.370000] local_irq_disable(); [ 109.375000] lock(&(&hsotg->lock)->rlock); [ 109.380000] lock(clocks_mutex); [ 109.390000] [ 109.390000] lock(&(&hsotg->lock)->rlock); [ 109.395000] [ 109.395000] *** DEADLOCK *** [ 109.395000] [ 109.400000] no locks held by swapper/0/0. [ 109.405000] [ 109.405000] the shortest dependencies between 2nd lock and 1st lock: [ 109.410000] -> (clocks_mutex){+.+...} ops: 221 { [ 109.415000] HARDIRQ-ON-W at: [ 109.420000] [] __lock_acquire+0x560/0xa94 [ 109.425000] [] lock_acquire+0x60/0x74 [ 109.435000] [] mutex_lock_nested+0x54/0x3a8 [ 109.440000] [] clk_get_sys+0x24/0xf4 [ 109.445000] [] exynos_pm_drvinit+0x2c/0x64 [ 109.455000] [] do_one_initcall+0x50/0x164 [ 109.460000] [] kernel_init_freeable+0x118/0xc [ 109.470000] [] kernel_init+0x8/0xe4 [ 109.475000] [] ret_from_fork+0x14/0x24 [ 109.480000] SOFTIRQ-ON-W at: [ 109.485000] [] __lock_acquire+0x584/0xa94 [ 109.490000] [] lock_acquire+0x60/0x74 [ 109.495000] [] mutex_lock_nested+0x54/0x3a8 [ 109.505000] [] clk_get_sys+0x24/0xf4 [ 109.510000] [] exynos_pm_drvinit+0x2c/0x64 [ 109.515000] [] do_one_initcall+0x50/0x164 [ 109.525000] [] kernel_init_freeable+0x118/0xc [ 109.530000] [] kernel_init+0x8/0xe4 [ 109.535000] [] ret_from_fork+0x14/0x24 [ 109.545000] INITIAL USE at: [ 109.545000] [] __lock_acquire+0x298/0xa94 [ 109.555000] [] lock_acquire+0x60/0x74 [ 109.560000] [] mutex_lock_nested+0x54/0x3a8 [ 109.565000] [] clkdev_add+0x1c/0x3c [ 109.575000] [] s3c24xx_register_clock+0x34/0x0 [ 109.580000] [] s3c24xx_register_baseclocks+0x4 [ 109.590000] [] exynos4_init_clocks+0x1c/0x80 [ 109.595000] [] s3c24xx_init_clocks+0x44/0x54 [ 109.600000] [] origen_map_io+0x1c/0x34 [ 109.610000] [] paging_init+0x5ec/0x798 [ 109.615000] [] setup_arch+0x3c8/0x65c [ 109.620000] [] start_kernel+0x7c/0x384 [ 109.625000] [<40008078>] 0x40008078 [ 109.630000] }