Hi All,
While testing linux-next (next-20140625) on Exynos4412-based TRATS2
board, from time to time I hit a deadlock between clk_disable_unused()
of Common Clock Framework and parallel clk_prepare() from s3c24xx-i2c
driver.
I believe the following is happening (in processes 1 and 2):
1: clk_disable_unused()
1: clk_prepare_lock()
1: mutex_lock(clk prepare mutex) // lock A
1: max77686_clk_is_prepared()
1: regmap_read()
2: regulator_set_voltage()
2: regmap_read()
2: mutex_lock(max77686 regmap mutex) // lock B
2: i2c_transfer()
2: s3c24xx_i2c_xfer()
2: clk_unprepare()
2: clk_prepare_lock()
2: mutex_lock(clk prepare mutex) // lock A
1: mutex_lock(max77686 regmap mutex) // lock B
1,2: BOOM!
I suppose this is a general problem affecting any MFD device that is
also a clock provider, but I clearly don't have a good idea what to do
about it.
Full boot log below:
> Uncompressing Linux... done, booting the kernel.
> [ 0.000000] Booting Linux on physical CPU 0xa00
> [ 0.000000] Linux version 3.16.0-rc2-next-20140625-00007-g993e726d-dirty (t.figa@AMDC1227) (gcc version 4.8.2 (Gentoo 4.8.2 p1.1, pie-0.5.8) ) #905 SMP PREEMPT Tue Jul 1 17:48:42 CEST 2014
> [ 0.000000] CPU: ARMv7 Processor [413fc090] revision 0 (ARMv7), cr=10c5387d
> [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
> [ 0.000000] Machine model: Samsung Trats 2 based on Exynos4412
> [ 0.000000] bootconsole [earlycon0] enabled
> [ 0.000000] debug: ignoring loglevel setting.
> [ 0.000000] Memory policy: Data cache writealloc
> [ 0.000000] On node 0 totalpages: 262144
> [ 0.000000] free_area_init_node: node 0, pgdat c063bc00, node_mem_map eeff0000
> [ 0.000000] Normal zone: 1520 pages used for memmap
> [ 0.000000] Normal zone: 0 pages reserved
> [ 0.000000] Normal zone: 194560 pages, LIFO batch:31
> [ 0.000000] HighMem zone: 528 pages used for memmap
> [ 0.000000] HighMem zone: 67584 pages, LIFO batch:15
> [ 0.000000] Running under secure firmware.
> [ 0.000000] PERCPU: Embedded 7 pages/cpu @eefa3000 s7744 r8192 d12736 u32768
> [ 0.000000] pcpu-alloc: s7744 r8192 d12736 u32768 alloc=8*4096
> [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
> [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 260624
> [ 0.000000] Kernel command line: root=/dev/mmcblk0p5 rootwait console=ttySAC2,115200n8 earlyprintk ignore_loglevel no_console_suspend
> [ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
> [ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
> [ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
> [ 0.000000] Memory: 1032564K/1048576K available (4329K kernel code, 266K rwdata, 1480K rodata, 275K init, 272K bss, 16012K reserved, 270336K highmem)
> [ 0.000000] Virtual kernel memory layout:
> [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
> [ 0.000000] fixmap : 0xffc00000 - 0xffe00000 (2048 kB)
> [ 0.000000] vmalloc : 0xf0000000 - 0xff000000 ( 240 MB)
> [ 0.000000] lowmem : 0xc0000000 - 0xef800000 ( 760 MB)
> [ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
> [ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
> [ 0.000000] .text : 0xc0008000 - 0xc05b47c0 (5810 kB)
> [ 0.000000] .init : 0xc05b5000 - 0xc05f9e40 ( 276 kB)
> [ 0.000000] .data : 0xc05fa000 - 0xc063c800 ( 266 kB)
> [ 0.000000] .bss : 0xc063c80c - 0xc0680a00 ( 273 kB)
> [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
> [ 0.000000] Preemptible hierarchical RCU implementation.
> [ 0.000000] RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=4.
> [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
> [ 0.000000] NR_IRQS:16 nr_irqs:16 16
> [ 0.000000] L2C: failed to init: -19
> [ 0.000000] Exynos4x12 clocks: sclk_apll = 800000000, sclk_mpll = 800000000
> [ 0.000000] sclk_epll = 96000000, sclk_vpll = 108000000, arm_clk = 800000000
> [ 0.000012] sched_clock: 64 bits at 24MHz, resolution 41ns, wraps every 2863311519744ns
> [ 0.008211] Console: colour dummy device 80x30
> [ 0.012619] Calibrating delay loop... 1590.88 BogoMIPS (lpj=3977216)
> [ 0.037727] pid_max: default: 32768 minimum: 301
> [ 0.042578] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
> [ 0.049146] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
> [ 0.056985] CPU: Testing write buffer coherency: ok
> [ 0.062107] missing device node for CPU 0
> [ 0.066114] missing device node for CPU 1
> [ 0.070169] missing device node for CPU 2
> [ 0.074212] missing device node for CPU 3
> [ 0.078298] CPU0: thread -1, cpu 0, socket 10, mpidr 80000a00
> [ 0.084903] Setting up static identity map for 0x4041c888 - 0x4041c8e0
> [ 0.120728] CPU1: Booted secondary processor
> [ 0.140009] CPU1: thread -1, cpu 1, socket 10, mpidr 80000a01
> [ 0.150709] CPU2: Booted secondary processor
> [ 0.170010] CPU2: thread -1, cpu 2, socket 10, mpidr 80000a02
> [ 0.180722] CPU3: Booted secondary processor
> [ 0.200010] CPU3: thread -1, cpu 3, socket 10, mpidr 80000a03
> [ 0.200156] Brought up 4 CPUs
> [ 0.233514] SMP: Total of 4 processors activated.
> [ 0.238302] CPU: All CPU(s) started in SVC mode.
> [ 0.243984] devtmpfs: initialized
> [ 0.252902] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 4
> [ 0.261509] pinctrl core: initialized pinctrl subsystem
> [ 0.267742] regulator-dummy: no parameters
> [ 0.287447] NET: Registered protocol family 16
> [ 0.292766] DMA: preallocated 256 KiB pool for atomic coherent allocations
> [ 0.307018] exynos-audss-clk 3810000.clock-controller: setup completed
> [ 0.332875] gpiochip_add: registered GPIOs 0 to 7 on device: gpa0
> [ 0.338935] gpiochip_add: registered GPIOs 8 to 13 on device: gpa1
> [ 0.345185] gpiochip_add: registered GPIOs 14 to 21 on device: gpb
> [ 0.351419] gpiochip_add: registered GPIOs 22 to 26 on device: gpc0
> [ 0.357762] gpiochip_add: registered GPIOs 27 to 31 on device: gpc1
> [ 0.364087] gpiochip_add: registered GPIOs 32 to 35 on device: gpd0
> [ 0.370433] gpiochip_add: registered GPIOs 36 to 39 on device: gpd1
> [ 0.376762] gpiochip_add: registered GPIOs 40 to 47 on device: gpf0
> [ 0.383106] gpiochip_add: registered GPIOs 48 to 55 on device: gpf1
> [ 0.389434] gpiochip_add: registered GPIOs 56 to 63 on device: gpf2
> [ 0.395780] gpiochip_add: registered GPIOs 64 to 69 on device: gpf3
> [ 0.402108] gpiochip_add: registered GPIOs 70 to 77 on device: gpj0
> [ 0.408440] gpiochip_add: registered GPIOs 78 to 82 on device: gpj1
> [ 0.416519] gpiochip_add: registered GPIOs 83 to 89 on device: gpk0
> [ 0.422750] gpiochip_add: registered GPIOs 90 to 96 on device: gpk1
> [ 0.429083] gpiochip_add: registered GPIOs 97 to 103 on device: gpk2
> [ 0.435492] gpiochip_add: registered GPIOs 104 to 110 on device: gpk3
> [ 0.442009] gpiochip_add: registered GPIOs 111 to 117 on device: gpl0
> [ 0.448510] gpiochip_add: registered GPIOs 118 to 119 on device: gpl1
> [ 0.455081] gpiochip_add: registered GPIOs 120 to 127 on device: gpl2
> [ 0.461548] gpiochip_add: registered GPIOs 128 to 135 on device: gpm0
> [ 0.468044] gpiochip_add: registered GPIOs 136 to 142 on device: gpm1
> [ 0.474548] gpiochip_add: registered GPIOs 143 to 147 on device: gpm2
> [ 0.481055] gpiochip_add: registered GPIOs 148 to 155 on device: gpm3
> [ 0.487563] gpiochip_add: registered GPIOs 156 to 163 on device: gpm4
> [ 0.494074] gpiochip_add: registered GPIOs 164 to 169 on device: gpy0
> [ 0.500584] gpiochip_add: registered GPIOs 170 to 173 on device: gpy1
> [ 0.507094] gpiochip_add: registered GPIOs 174 to 179 on device: gpy2
> [ 0.513603] gpiochip_add: registered GPIOs 180 to 187 on device: gpy3
> [ 0.520113] gpiochip_add: registered GPIOs 188 to 195 on device: gpy4
> [ 0.526623] gpiochip_add: registered GPIOs 196 to 203 on device: gpy5
> [ 0.533134] gpiochip_add: registered GPIOs 204 to 211 on device: gpy6
> [ 0.539659] gpiochip_add: registered GPIOs 212 to 219 on device: gpx0
> [ 0.546159] gpiochip_add: registered GPIOs 220 to 227 on device: gpx1
> [ 0.552667] gpiochip_add: registered GPIOs 228 to 235 on device: gpx2
> [ 0.559174] gpiochip_add: registered GPIOs 236 to 243 on device: gpx3
> [ 0.567567] gpiochip_add: registered GPIOs 244 to 250 on device: gpz
> [ 0.574712] gpiochip_add: registered GPIOs 251 to 258 on device: gpv0
> [ 0.581130] gpiochip_add: registered GPIOs 259 to 266 on device: gpv1
> [ 0.587615] gpiochip_add: registered GPIOs 267 to 274 on device: gpv2
> [ 0.594130] gpiochip_add: registered GPIOs 275 to 282 on device: gpv3
> [ 0.600629] gpiochip_add: registered GPIOs 283 to 284 on device: gpv4
> [ 0.616275] EXYNOS4x12 PMU Initialize
> [ 0.667979] of_get_named_gpiod_flags exited with status 0
> [ 0.673790] VMEM_VDD_2.8V: 2800 mV
> [ 0.677531] of_get_named_gpiod_flags exited with status 0
> [ 0.683339] CAM_SENSOR_A: 2800 mV
> [ 0.686996] of_get_named_gpiod_flags exited with status 0
> [ 0.692796] LCD_VDD_2.2V: 2200 mV
> [ 0.696455] of_get_named_gpiod_flags exited with status 0
> [ 0.702256] CAM_AF: 2800 mV
> [ 0.705409] of_get_named_gpiod_flags exited with status 0
> [ 0.711172] CAM_ISP_CORE_1.2V_EN: 1200 mV
> [ 0.715489] of_get_named_gpiod_flags exited with status 0
> [ 0.721255] LED_A_3.0V: 3000 mV
> [ 0.729652] SCSI subsystem initialized
> [ 0.734917] usbcore: registered new interface driver usbfs
> [ 0.740658] usbcore: registered new interface driver hub
> [ 0.746302] usbcore: registered new device driver usb
> [ 0.752844] s3c-i2c 13860000.i2c: slave address 0x10
> [ 0.757776] s3c-i2c 13860000.i2c: bus frequency set to 390 KHz
> [ 0.764887] s3c-i2c 13860000.i2c: i2c-0: S3C I2C adapter
> [ 0.770462] s3c-i2c 13890000.i2c: slave address 0x10
> [ 0.775409] s3c-i2c 13890000.i2c: bus frequency set to 390 KHz
> [ 0.782528] s3c-i2c 13890000.i2c: i2c-3: S3C I2C adapter
> [ 0.788120] s3c-i2c 138d0000.i2c: slave address 0x10
> [ 0.793048] s3c-i2c 138d0000.i2c: bus frequency set to 97 KHz
> [ 0.800838] max77686 7-0009: device found
> [ 0.809622] VALIVE_1.0V_AP: 1000 mV
> [ 0.815406] VM1M2_1.2V_AP: 1200 mV
> [ 0.820988] VCC_1.8V_AP: 1800 mV
> [ 0.826434] VCC_2.8V_AP: 2800 mV
> [ 0.831844] VCC_1.8V_IO: 1800 mV
> [ 0.839038] VMPLL_1.0V_AP: 1000 mV
> [ 0.846363] VPLL_1.0V_AP: 1000 mV
> [ 0.851106] VMIPI_1.0V: 1000 mV
> [ 0.856936] CAM_ISP_MIPI_1.2V: 1200 mV
> [ 0.862121] VMIPI_1.8V: 1800 mV
> [ 0.869222] VABB1_1.95V: 1950 mV
> [ 0.873902] VUOTG_3.0V: 3000 mV
> [ 0.878469] NFC_AVDD_1.8V: 1800 mV
> [ 0.885868] VABB2_1.95V: 1950 mV
> [ 0.890618] VHSIC_1.0V: 1000 mV
> [ 0.895185] VHSIC_1.8V: 1800 mV
> [ 0.899714] CAM_SENSOR_CORE_1.2V: 1200 mV
> [ 0.905197] CAM_ISP_SEN_IO_1.8V: 1800 mV
> [ 0.910585] VT_CAM_1.8V: 1800 mV
> [ 0.915257] VDDQ_PRE_1.8V: 1800 mV
> [ 0.920072] VTF_2.8V: 2800 mV
> [ 0.925274] VMEM_VDD_2.8V: 2800 mV
> [ 0.929233] VMEM_VDD_2.8V: Failed to create debugfs directory
> [ 0.935810] TSP_AVDD_3.3V: 3300 mV
> [ 0.940670] TSP_VDD_1.8V: 1800 mV
> [ 0.947112] LCD_VCC_3.3V: 2800 mV
> [ 0.951896] MOTOR_VCC_3.0V: 3000 mV
> [ 0.957637] vdd_mif: 850 <--> 1100 mV at 1000 mV
> [ 0.964138] vdd_arm: 850 <--> 1500 mV at 1100 mV
> [ 0.970659] vdd_int: 850 <--> 1150 mV at 1000 mV
> [ 0.977176] vdd_g3d: 850 <--> 1150 mV at 1000 mV
> [ 0.983693] VMEM_1.2V_AP: 1200 mV
> [ 0.988888] VCC_SUB_1.35V: 1350 mV
> [ 0.994170] VCC_SUB_2.0V: 2000 mV
> [ 0.999704] VMEM_VDDF_3.0V: 2850 mV
> [ 1.004672] CAM_ISP_CORE_1.2V: 1000 <--> 1200 mV at 1200 mV
> [ 1.011624] s3c-i2c 138d0000.i2c: i2c-7: S3C I2C adapter
> [ 1.017264] media: Linux media interface: v0.10
> [ 1.022084] Linux video capture interface: v2.00
> [ 1.034087] Switched to clocksource mct-frc
> [ 1.065452] NET: Registered protocol family 2
> [ 1.070751] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
> [ 1.077876] TCP bind hash table entries: 8192 (order: 5, 163840 bytes)
> [ 1.084607] TCP: Hash tables configured (established 8192 bind 8192)
> [ 1.091055] TCP: reno registered
> [ 1.094259] UDP hash table entries: 512 (order: 2, 24576 bytes)
> [ 1.100265] UDP-Lite hash table entries: 512 (order: 2, 24576 bytes)
> [ 1.106941] NET: Registered protocol family 1
> [ 1.114343] futex hash table entries: 1024 (order: 4, 65536 bytes)
> [ 1.136661] romfs: ROMFS MTD (C) 2007 Red Hat, Inc.
> [ 1.141805] msgmni has been set to 1488
> [ 1.146841] bounce: pool size: 64 pages
> [ 1.150668] io scheduler noop registered
> [ 1.154646] io scheduler deadline registered
> [ 1.159350] io scheduler cfq registered (default)
> [ 1.174939] dma-pl330 12680000.pdma: Loaded driver for PL330 DMAC-1315632
> [ 1.181696] dma-pl330 12680000.pdma: DBUFF-32x4bytes Num_Chans-8 Num_Peri-32 Num_Events-32
> [ 1.197223] dma-pl330 12690000.pdma: Loaded driver for PL330 DMAC-1315632
> [ 1.204000] dma-pl330 12690000.pdma: DBUFF-32x4bytes Num_Chans-8 Num_Peri-32 Num_Events-32
> [ 1.214521] dma-pl330 12850000.mdma: Loaded driver for PL330 DMAC-1315632
> [ 1.221275] dma-pl330 12850000.mdma: DBUFF-64x8bytes Num_Chans-8 Num_Peri-1 Num_Events-32
> [ 1.397474] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
> [ 1.406862] 13800000.serial: ttySAC0 at MMIO 0x13800000 (irq = 84, base_baud = 0) is a S3C6400/10
> [ 1.416444] 13810000.serial: ttySAC1 at MMIO 0x13810000 (irq = 85, base_baud = 0) is a S3C6400/10
> [ 1.426041] 13820000.serial: ttySAC2 at MMIO 0x13820000 (irq = 86, base_baud = 0) is a S3C6400/10
> [ 1.434949] console [tt[SAC2] enabled
> 1.434949] console [ttySAC2] enabled
> [ 1.442166] bootconsole [early[on0] disabled
> 1.442166] bootconsole [earlycon0] disabled
> [ 1.451388] 13830000.serial: ttySAC3 at MMIO 0x13830000 (irq = 87, base_baud = 0) is a S3C6400/10
> [ 1.461017] [drm] Initialized drm 1.1.0 20060810
> [ 1.467495] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
> [ 1.472686] [drm] No driver support for vblank timestamp query.
> [ 1.478649] exynos-drm exynos-drm: bound 11c00000.fimd (ops fimd_component_ops)
> [ 1.486503] exynos-drm exynos-drm: bound 11c80000.dsi (ops exynos_dsi_component_ops)
> [ 1.493678] [drm] Initialized exynos 1.0.0 20110530 on minor 0
> [ 1.499943] panel_s6e8aa0 11c80000.dsi.0: GPIO lookup for consumer reset
> [ 1.506120] panel_s6e8aa0 11c80000.dsi.0: using device tree for GPIO lookup
> [ 1.513071] of_get_named_gpiod_flags exited with status 0
> [ 1.721532] panel_s6e8aa0 11c80000.dsi.0: ID: 0xa2, 0x60, 0x90
> [ 1.894152] [drm:drm_calc_timestamping_constants] *ERROR* crtc 12: Can't calculate constants, dotclock = 0!
> [ 1.927913] Console: switching to colour frame buffer device 102x91
> [ 1.980431] exynos-drm exynos-drm: fb0: frame buffer device
> [ 1.986071] exynos-drm exynos-drm: registered panic notifier
> [ 2.019291] brd: module loaded
> [ 2.028936] loop: module loaded
> [ 2.031779] s3c64xx-spi 13930000.spi: spi bus clock parent not specified, using clock at index 0 as parent
> [ 2.040311] s3c64xx-spi 13930000.spi: number of chip select lines not specified, assuming 1 chip select line
> [ 2.052146] usbcore: registered new interface driver asix
> [ 2.056299] usbcore: registered new interface driver ax88179_178a
> [ 2.062390] usbcore: registered new interface driver cdc_ether
> [ 2.068182] usbcore: registered new interface driver smsc75xx
> [ 2.073907] usbcore: registered new interface driver smsc95xx
> [ 2.079624] usbcore: registered new interface driver net1080
> [ 2.085248] usbcore: registered new interface driver cdc_subset
> [ 2.091127] usbcore: registered new interface driver zaurus
> [ 2.096769] usbcore: registered new interface driver cdc_ncm
> [ 2.103145] s3c-hsotg 12480000.hsotg: regs f04c0000, irq 103
> [ 2.109441] s3c-hsotg 12480000.hsotg: EPs:15
> [ 2.112241] s3c-hsotg 12480000.hsotg: dedicated fifos
> [ 2.120254] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> [ 2.125422] ehci-exynos: EHCI EXYNOS driver
> [ 2.130271] usbcore: registered new interface driver usb-storage
> [ 2.136516] mousedev: PS/2 mouse device common for all mice
> [ 2.144388] ERROR: could not get clock /i2c@13860000/s5c73m3@3c:cis_extclk(0)
> [ 2.150125] i2c 0-003c: Driver S5C73M3 requests probe deferral
> [ 2.156957] s5p-mipi-csis 11880000.csis: lanes: 4, hs_settle: 12, wclk: 0, freq: 176000000
> [ 2.164836] s5p-mipi-csis 11890000.csis: lanes: 1, hs_settle: 18, wclk: 1, freq: 160000000
> [ 2.175582] ERROR: could not get clock /camera/fimc-is@12000000/i2c-isp@12140000/s5k6a3@10:extclk(0)
> [ 2.183306] i2c 1-0010: Driver S5K6A3 requests probe deferral
> [ 2.191900] exynos4-fimc-is 12000000.fimc-is: Direct firmware load failed with error -2
> [ 2.198501] exynos4-fimc-is 12000000.fimc-is: Falling back to user helper
> [ 2.198865] isp-power-domain: Power-off latency exceeded, new value 285125 ns
> [ 2.213436] s5p-fimc-md: Registered fimc.0.m2m as /dev/video0
> [ 2.218521] s5p-fimc-md: Registered fimc.0.capture as /dev/video1
> [ 2.224563] s5p-fimc-md: Registered fimc.1.m2m as /dev/video2
> [ 2.230371] s5p-fimc-md: Registered fimc.1.capture as /dev/video3
> [ 2.236463] s5p-fimc-md: Registered fimc-lite.0.capture as /dev/video4
> [ 2.242875] s5p-fimc-md: Registered fimc-lite.1.capture as /dev/video5
> [ 2.249499] s5p-fimc-md: Registered fimc-is-isp.capture as /dev/video6
> [ 2.255932] cam-power-domain: Power-off latency exceeded, new value 271875 ns
> [ 2.264529] device-mapper: ioctl: 4.27.0-ioctl (2013-10-30) initialised: [email protected]
> [ 2.275629] sdhci: Secure Digital Host Controller Interface driver
> [ 2.280418] sdhci: Copyright(c) Pierre Ossman
> [ 2.285026] Synopsys Designware Multimedia Card Interface Driver
> [ 2.291612] dwmmc_exynos 12550000.mmc: Using internal DMA controller.
> [ 2.297169] dwmmc_exynos 12550000.mmc: Version ID is 240a
> [ 2.302814] dwmmc_exynos 12550000.mmc: DW MMC controller at irq 109, 32 bit host data width, 128 deep fifo
> [ 2.312220] of_get_named_gpiod_flags: can't parse gpios property of node '/mmc@12550000[0]'
> [ 2.349217] dwmmc_exynos 12550000.mmc: 1 slots initialized
> [ 2.355245] usbcore: registered new interface driver usbhid
> [ 2.359407] usbhid: USB HID core driver
> [ 2.363404] TCP: cubic registered
> [ 2.366559] NET: Registered protocol family 17
> [ 2.371013] NET: Registered protocol family 15
> [ 2.375637] Registering SWP/SWPB emulation handler
> [ 2.380170] gps-alive-power-domain: Power-off latency exceeded, new value 4634500 ns
> [ 2.387932] gps-power-domain: Power-off latency exceeded, new value 12171083 ns
> [ 2.389617] of_get_named_gpiod_flags exited with status 0
> [ 2.389637] of_get_named_gpiod_flags exited with status 0
> [ 2.390364] S5C73M3: S5C73M3 SPI probed successfully
> [ 2.411122] tv-power-domain: Power-off latency exceeded, new value 178625 ns
> [ 2.417923] g3d-power-domain: Power-off latency exceeded, new value 6944459 ns
> [ 2.425415] mfc-power-domain: Power-off latency exceeded, new value 179542 ns
> [ 2.436992] cam-power-domain: Power-on latency exceeded, new value 434833 ns
> [ 2.455453] S5C73M3: Sensor type: CML0801-M080, FW version: ZHFJ02
> [ 2.460833] cam-power-domain: Power-off latency exceeded, new value 274084 ns
> [ 2.471060] s5p-fimc-md: Registered sensor subdevice: S5C73M3-OIF (0)
> [ 2.476069] S5C73M3: s5c73m3_probe: completed successfully
> [ 2.481721] of_get_named_gpiod_flags exited with status 0
> [ 2.487347] s5p-fimc-md: Registered sensor subdevice: S5K6A3 1-0010 (1)
> [ 2.493544] s5p-fimc-md: created link [S5C73M3-OIF] => [s5p-mipi-csis.0]
> [ 2.500212] s5p-fimc-md: created link [S5K6A3 1-0010] => [s5p-mipi-csis.1]
> [ 2.507065] s5p-fimc-md: created link [s5p-mipi-csis.0] => [FIMC.0]
> [ 2.513313] s5p-fimc-md: created link [s5p-mipi-csis.0] -> [FIMC.1]
> [ 2.513390] mmc_host mmc0: Bus speed (slot 0) = 50000000Hz (slot req 52000000Hz, actual 50000000HZ div = 0)
> [ 2.529361] s5p-fimc-md: created link [s5p-mipi-csis.0] -> [FIMC-LITE.0]
> [ 2.536009] s5p-fimc-md: created link [s5p-mipi-csis.0] -> [FIMC-LITE.1]
> [ 2.542689] s5p-fimc-md: created link [s5p-mipi-csis.1] -> [FIMC-LITE.0]
> [ 2.542755] mmc_host mmc0: Bus speed (slot 0) = 100000000Hz (slot req 52000000Hz, actual 50000000HZ div = 1)
> [ 2.542976] mmc0: new DDR MMC card at address 0001
> [ 2.549471] mmcblk0: mmc0:0001 VTU00M 14.6 GiB
> [ 2.549691] mmcblk0boot0: mmc0:0001 VTU00M partition 1 2.00 MiB
> [ 2.549917] mmcblk0boot1: mmc0:0001 VTU00M partition 2 2.00 MiB
> [ 2.550125] mmcblk0rpmb: mmc0:0001 VTU00M partition 3 128 KiB
> [ 2.555724] mmcblk0: p1 p2 p3 p4 p5 p6 p7
> [ 2.561000] mmcblk0boot1: unknown partition table
> [ 2.562557] mmcblk0boot0: unknown partition table
> [ 2.599618] s5p-fimc-md: created link [s5p-mipi-csis.1] -> [FIMC-LITE.1]
> [ 2.610369] of_get_named_gpiod_flags exited with status 0
> [ 2.614413] of_get_named_gpiod_flags exited with status 0
> [ 2.619804] of_get_named_gpiod_flags exited with status 0
> [ 2.625115] of_get_named_gpiod_flags exited with status 0
> [ 2.630533] gpio-239 (volume down): gpiod_set_debounce: missing set() or set_debounce() operations
> [ 2.639541] gpio-230 (volume up): gpiod_set_debounce: missing set() or set_debounce() operations
> [ 2.648314] gpio-235 (power): gpiod_set_debounce: missing set() or set_debounce() operations
> [ 2.656718] gpio-213 (ok): gpiod_set_debounce: missing set() or set_debounce() operations
> [ 2.665165] input: gpio-keys as /devices/gpio-keys/input/input0
> [ 2.671295] drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
> [ 2.693343] vdd_g3d: disabling
> [ 2.698346] VDDQ_PRE_1.8V: disabling
> [ 2.703375] VHSIC_1.8V: disabling
> [ 2.708141] LED_A_3.0V: disabling
> [ 2.710069] CAM_AF: disabling
> [ 2.712939] CAM_SENSOR_A: disabling
> [ 62.334649] exynos4-fimc-is 12000000.fimc-is: firmware request failed
> [ 240.679135] INFO: task swapper/0:1 blocked for more than 120 seconds.
> [ 240.684143] Not tainted 3.16.0-rc2-next-20140625-00007-g993e726d-dirty #905
> [ 240.691626] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 240.699408] swapper/0 D c0418014 0 1 0 0x00000000
> [ 240.705765] [<c0418014>] (__schedule) from [<c0418734>] (schedule_preempt_disabled+0x14/0x20)
> [ 240.714267] [<c0418734>] (schedule_preempt_disabled) from [<c041ac5c>] (__mutex_lock_slowpath+0x1a0/0x3e4)
> [ 240.723892] [<c041ac5c>] (__mutex_lock_slowpath) from [<c041aeac>] (mutex_lock+0xc/0x24)
> [ 240.732022] [<c041aeac>] (mutex_lock) from [<c0278170>] (regmap_read+0x30/0x60)
> [ 240.739280] [<c0278170>] (regmap_read) from [<c036d51c>] (max77686_clk_is_prepared+0x20/0x3c)
> [ 240.747768] [<c036d51c>] (max77686_clk_is_prepared) from [<c036a59c>] (clk_unprepare_unused_subtree+0x64/0x98)
> [ 240.757745] [<c036a59c>] (clk_unprepare_unused_subtree) from [<c036a654>] (clk_disable_unused+0x84/0xd8)
> [ 240.767205] [<c036a654>] (clk_disable_unused) from [<c0008990>] (do_one_initcall+0x8c/0x1c4)
> [ 240.775634] [<c0008990>] (do_one_initcall) from [<c05b5cf0>] (kernel_init_freeable+0x138/0x1d8)
> [ 240.784318] [<c05b5cf0>] (kernel_init_freeable) from [<c04132d0>] (kernel_init+0x8/0xf0)
> [ 240.792382] [<c04132d0>] (kernel_init) from [<c000e678>] (ret_from_fork+0x14/0x3c)
> [ 240.799923] INFO: task kworker/0:0:4 blocked for more than 120 seconds.
> [ 240.806513] Not tainted 3.16.0-rc2-next-20140625-00007-g993e726d-dirty #905
> [ 240.813975] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 240.821787] kworker/0:0 D c0418014 0 4 2 0x00000000
> [ 240.828118] Workqueue: events od_dbs_timer
> [ 240.832198] [<c0418014>] (__schedule) from [<c0418734>] (schedule_preempt_disabled+0x14/0x20)
> [ 240.840728] [<c0418734>] (schedule_preempt_disabled) from [<c041ac5c>] (__mutex_lock_slowpath+0x1a0/0x3e4)
> [ 240.850357] [<c041ac5c>] (__mutex_lock_slowpath) from [<c041aeac>] (mutex_lock+0xc/0x24)
> [ 240.858430] [<c041aeac>] (mutex_lock) from [<c03692c0>] (clk_prepare_lock+0x88/0xfc)
> [ 240.866159] [<c03692c0>] (clk_prepare_lock) from [<c036ac80>] (clk_unprepare+0x18/0x28)
> [ 240.874154] [<c036ac80>] (clk_unprepare) from [<c02f67ac>] (s3c24xx_i2c_xfer+0x18c/0x40c)
> [ 240.882305] [<c02f67ac>] (s3c24xx_i2c_xfer) from [<c02f127c>] (__i2c_transfer+0x78/0x90)
> [ 240.890373] [<c02f127c>] (__i2c_transfer) from [<c02f2560>] (i2c_transfer+0xa0/0xd8)
> [ 240.898096] [<c02f2560>] (i2c_transfer) from [<c027c6d4>] (regmap_i2c_read+0x48/0x64)
> [ 240.905916] [<c027c6d4>] (regmap_i2c_read) from [<c0278648>] (_regmap_raw_read+0x98/0xf4)
> [ 240.914118] [<c0278648>] (_regmap_raw_read) from [<c02786c8>] (_regmap_bus_read+0x24/0x5c)
> [ 240.922323] [<c02786c8>] (_regmap_bus_read) from [<c02780c8>] (_regmap_read+0x6c/0xe4)
> [ 240.930266] [<c02780c8>] (_regmap_read) from [<c0278180>] (regmap_read+0x40/0x60)
> [ 240.937693] [<c0278180>] (regmap_read) from [<c020a218>] (regulator_is_enabled_regmap+0x20/0x9c)
> [ 240.946463] [<c020a218>] (regulator_is_enabled_regmap) from [<c0206b14>] (_regulator_is_enabled.part.16+0x1c/0x28)
> [ 240.956785] [<c0206b14>] (_regulator_is_enabled.part.16) from [<c020705c>] (_regulator_do_set_voltage+0x2d0/0x348)
> [ 240.967105] [<c020705c>] (_regulator_do_set_voltage) from [<c0207184>] (regulator_set_voltage+0xb0/0x13c)
> [ 240.976650] [<c0207184>] (regulator_set_voltage) from [<c0337250>] (exynos_target+0x268/0x2d4)
> [ 240.985248] [<c0337250>] (exynos_target) from [<c0331680>] (__cpufreq_driver_target+0x158/0x294)
> [ 240.994020] [<c0331680>] (__cpufreq_driver_target) from [<c0336750>] (dbs_check_cpu+0x1a4/0x1e4)
> [ 241.002782] [<c0336750>] (dbs_check_cpu) from [<c0335390>] (od_dbs_timer+0x78/0x130)
> [ 241.010512] [<c0335390>] (od_dbs_timer) from [<c0032854>] (process_one_work+0x11c/0x35c)
> [ 241.018580] [<c0032854>] (process_one_work) from [<c00330c8>] (worker_thread+0x4c/0x568)
> [ 241.026649] [<c00330c8>] (worker_thread) from [<c003876c>] (kthread+0xd8/0xf0)
> [ 241.033856] [<c003876c>] (kthread) from [<c000e678>] (ret_from_fork+0x14/0x3c)
> [ 241.041060] INFO: task kworker/1:1:444 blocked for more than 120 seconds.
> [ 241.047818] Not tainted 3.16.0-rc2-next-20140625-00007-g993e726d-dirty #905
> [ 241.055278] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 241.063090] kworker/1:1 D c0418014 0 444 2 0x00000000
> [ 241.069435] Workqueue: events od_dbs_timer
> [ 241.073501] [<c0418014>] (__schedule) from [<c0418734>] (schedule_preempt_disabled+0x14/0x20)
> [ 241.082034] [<c0418734>] (schedule_preempt_disabled) from [<c041ac5c>] (__mutex_lock_slowpath+0x1a0/0x3e4)
> [ 241.091663] [<c041ac5c>] (__mutex_lock_slowpath) from [<c041aeac>] (mutex_lock+0xc/0x24)
> [ 241.099736] [<c041aeac>] (mutex_lock) from [<c033535c>] (od_dbs_timer+0x44/0x130)
> [ 241.107203] [<c033535c>] (od_dbs_timer) from [<c0032854>] (process_one_work+0x11c/0x35c)
> [ 241.115274] [<c0032854>] (process_one_work) from [<c00330c8>] (worker_thread+0x4c/0x568)
> [ 241.123342] [<c00330c8>] (worker_thread) from [<c003876c>] (kthread+0xd8/0xf0)
> [ 241.130602] [<c003876c>] (kthread) from [<c000e678>] (ret_from_fork+0x14/0x3c)
> [ 241.137758] INFO: task kworker/3:1:1154 blocked for more than 120 seconds.
> [ 241.144604] Not tainted 3.16.0-rc2-next-20140625-00007-g993e726d-dirty #905
> [ 241.152061] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 241.159874] kworker/3:1 D c0418014 0 1154 2 0x00000000
> [ 241.166221] Workqueue: events od_dbs_timer
> [ 241.170283] [<c0418014>] (__schedule) from [<c0418734>] (schedule_preempt_disabled+0x14/0x20)
> [ 241.178811] [<c0418734>] (schedule_preempt_disabled) from [<c041ac5c>] (__mutex_lock_slowpath+0x1a0/0x3e4)
> [ 241.188447] [<c041ac5c>] (__mutex_lock_slowpath) from [<c041aeac>] (mutex_lock+0xc/0x24)
> [ 241.196519] [<c041aeac>] (mutex_lock) from [<c033535c>] (od_dbs_timer+0x44/0x130)
> [ 241.203986] [<c033535c>] (od_dbs_timer) from [<c0032854>] (process_one_work+0x11c/0x35c)
> [ 241.212065] [<c0032854>] (process_one_work) from [<c00330c8>] (worker_thread+0x4c/0x568)
> [ 241.220131] [<c00330c8>] (worker_thread) from [<c003876c>] (kthread+0xd8/0xf0)
> [ 241.227331] [<c003876c>] (kthread) from [<c000e678>] (ret_from_fork+0x14/0x3c)
> [ 241.234531] INFO: task kworker/2:1:1273 blocked for more than 120 seconds.
> [ 241.241381] Not tainted 3.16.0-rc2-next-20140625-00007-g993e726d-dirty #905
> [ 241.248843] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 241.256654] kworker/2:1 D c0418014 0 1273 2 0x00000000
> [ 241.262978] Workqueue: events od_dbs_timer
> [ 241.267063] [<c0418014>] (__schedule) from [<c0418734>] (schedule_preempt_disabled+0x14/0x20)
> [ 241.275595] [<c0418734>] (schedule_preempt_disabled) from [<c041ac5c>] (__mutex_lock_slowpath+0x1a0/0x3e4)
> [ 241.285227] [<c041ac5c>] (__mutex_lock_slowpath) from [<c041aeac>] (mutex_lock+0xc/0x24)
> [ 241.293298] [<c041aeac>] (mutex_lock) from [<c033535c>] (od_dbs_timer+0x44/0x130)
> [ 241.300765] [<c033535c>] (od_dbs_timer) from [<c0032854>] (process_one_work+0x11c/0x35c)
> [ 241.308834] [<c0032854>] (process_one_work) from [<c00330c8>] (worker_thread+0x4c/0x568)
> [ 241.316905] [<c00330c8>] (worker_thread) from [<c003876c>] (kthread+0xd8/0xf0)
> [ 241.324111] [<c003876c>] (kthread) from [<c000e678>] (ret_from_fork+0x14/0x3c)
--
Best regards,
Tomasz
On Wed, Jul 02, 2014 at 12:59:04PM +0200, Tomasz Figa wrote:
> Hi All,
>
> While testing linux-next (next-20140625) on Exynos4412-based TRATS2
> board, from time to time I hit a deadlock between clk_disable_unused()
> of Common Clock Framework and parallel clk_prepare() from s3c24xx-i2c
> driver.
This is pretty sad. The Linux kernel has quite a range of truely excellent
debugging tools which can be built in, but it seems many developers don't
enable them. The important one here is lockdep (which I notice isn't on
in your kernel.)
Lockdep is a static lock checker - it tracks the dependencies and contexts
between various locks and can report whether deadlock is possible without
having to run into the deadlock. It is /highly/ recommended that all
developers should run their changes through a kernel with this feature
on before submitting them upstream - see Documentation/SubmitChecklist
point 15.
It can really catch these things before the patch is even submitted...
The recommendation is that if you're doing kernel development, always
have lockdep enabled. If you want to do performance checking, then
obviously it has an impact on that, so turn it off to do that, but
remember to turn it back on before you do further development.
--
FTTC broadband for 0.8mile line: now at 9.7Mbps down 460kbps up... slowly
improving, and getting towards what was expected from it.
On Wed, Jul 02, 2014 at 12:59:04PM +0200, Tomasz Figa wrote:
> Hi All,
>
> While testing linux-next (next-20140625) on Exynos4412-based TRATS2
> board, from time to time I hit a deadlock between clk_disable_unused()
> of Common Clock Framework and parallel clk_prepare() from s3c24xx-i2c
> driver.
>
> I believe the following is happening (in processes 1 and 2):
> 1: clk_disable_unused()
> 1: clk_prepare_lock()
> 1: mutex_lock(clk prepare mutex) // lock A
> 1: max77686_clk_is_prepared()
> 1: regmap_read()
> 2: regulator_set_voltage()
> 2: regmap_read()
> 2: mutex_lock(max77686 regmap mutex) // lock B
> 2: i2c_transfer()
> 2: s3c24xx_i2c_xfer()
> 2: clk_unprepare()
> 2: clk_prepare_lock()
> 2: mutex_lock(clk prepare mutex) // lock A
> 1: mutex_lock(max77686 regmap mutex) // lock B
> 1,2: BOOM!
>
> I suppose this is a general problem affecting any MFD device that is
> also a clock provider, but I clearly don't have a good idea what to do
> about it.
>
Or if you use notifiers which use i2c... See also
http://comments.gmane.org/gmane.linux.kernel/1553699. One workaround is to
always leave the clock of the i2c controller in a prepared state.
Cheers,
Peter.
On 02/07/14 13:49, Peter De Schrijver wrote:
> Or if you use notifiers which use i2c... See also
> http://comments.gmane.org/gmane.linux.kernel/1553699. One workaround is to
> always leave the clock of the i2c controller in a prepared state.
Keeping the clock always prepared might not be that bad, given
prepare/unprepare ops are empty on Exynos and I'd say chances
this ever changes are very low. Now we have just an overhead
of calling to the clock core before and after each single I2C
transfer.
--
Regards,
Sylwester