Am 31.12.18 um 23:56 schrieb Andreas Färber: > Am 31.12.18 um 18:50 schrieb Mark Brown: >> On Sun, Dec 30, 2018 at 11:55:46AM +0100, Andreas Färber wrote: >>> Given that observed symptoms were CPU stalls, workqueue hangs and RCU >>> problems, requiring a power-cycle to recover, I wonder whether we are >>> running into some atomic/locking issue with clk_enable()? Is it valid at >>> all to use SPI/regmap for clk_enable()? If it is, is there a known issue >>> specific to spi-sun6i (A64) in 4.20.0? >>> I already tried setting .disable_locking = true in both regmap_configs. >>> Any suggestions how to further debug? >> >> You can't use SPI for clk_enable(), clk_enable() needs to be doable in >> atomic context since we need to wait for the bus operations to complete >> (you can start SPI transfers in atomic context but you still need to >> wait for them to complete). Any clocks that are only accessible via a >> slow bus like I2C or SPI need to do the enable/disable in the >> prepare/unprepare operations which aren't done in atomic context. >> >> regmap can be used in atomic contexts, though you need to configure it >> to use spinlocks instead of mutexes and ensure that no register cache >> allocations happen during I/O (eg, by providing defaults for all >> registers or by not using a cache). > > We have .cache_type = REGCACHE_NONE on both bus and spi regmap_configs. > > I moved the regmap_field_write() from .enable to .prepare and set > .fast_io = true on both regmap_configs to force using spinlocks, but > same hang as in .enable before... > > And same if I set .disable_locking = true on both. > > Given that it works with one SPI driver and not with the other, > independent of the locking options applied, I assume my symptoms are not > a regmap-layer issue. > > Is it allowed during a .prepare operation to call the mentioned > clk_get_rate(), which ends up calling clk_prepare_lock()? > > According to my debug output in spi-sun6i.c our hanging > regmap_field_write() ends up calling sun6i_transfer_one() three times, > the first two look okay, but the third one doesn't make it past the > clk_get_rate() [...]. SysRq still works in that state! Attached is SysRq-w output. (still with .disable_locking = true in both regmap_configs) In the very bottom you see the "ip" task, at wait_for_completion() from __spi_sync(). I trigger this issue with `ip link set lora2 up`, so that looks okay. Then there's a "spi1" task at clk_prepare_lock()' mutex_lock() coming from spi_pump_messages(). The reason for that will be that clk_prepare_lock()'s mutex_trylock() failed (because we're holding the prepare_lock from clk_prepare_enable() in the "ip" task) and that the prepare_owner == current check fails for this separate task_struct, too. So, the third invocation of sun6i_transfer_one() calling clk_get_rate() hangs at the prepare_lock instead of reference-counting, because it runs from a separate kthread, unlike the two previous calls? Besides, there's also an mmc_rescan workqueue task at clk_prepare_lock() coming from sunxi_mmc_enable() due to pm_generic_runtime_resume(). My rootfs is on microSD card. I did not find any *regmap_init_spi() based example in drivers/clk/, and all other "spi" mentions in drivers/clk/ appeared to be clock names. The closest was devm_regmap_init_i2c() based clk-cdce706.c, which uses the prepare/unprepare ops, as suggested by Mark, and does regmap_update_bits() from there. A quick grep in drivers/i2c/ does not find any mention of "kthread", so probably that's the breaking difference? Regards, Andreas -- SUSE Linux GmbH, Maxfeldstr. 5, 90409 Nürnberg, Germany GF: Felix Imendörffer, Jane Smithard, Graham Norton HRB 21284 (AG Nürnberg)
[39292.911444] sysrq: SysRq : Show Blocked State [39292.915819] task PC stack pid father [39292.921784] kworker/0:2 D 0 170 2 0x00000028 [39292.927282] Workqueue: ipv6_addrconf addrconf_verify_work [39292.932676] Call trace: [39292.935127] __switch_to+0x9c/0xd8 [39292.938530] __schedule+0x2a0/0x888 [39292.942016] schedule+0x30/0x88 [39292.945157] schedule_preempt_disabled+0x14/0x20 [39292.949770] __mutex_lock.isra.1+0x2c0/0x4b8 [39292.954036] __mutex_lock_slowpath+0x24/0x30 [39292.958302] mutex_lock+0x48/0x50 [39292.961615] rtnl_lock+0x1c/0x28 [39292.964841] addrconf_verify_work+0x14/0x28 [39292.969022] process_one_work+0x1f4/0x428 [39292.973028] worker_thread+0x44/0x4a8 [39292.976686] kthread+0x130/0x138 [39292.979912] ret_from_fork+0x10/0x18 [39292.983518] btrfs-transacti D 0 383 2 0x00000028 [39292.988998] Call trace: [39292.991444] __switch_to+0x9c/0xd8 [39292.994845] __schedule+0x2a0/0x888 [39292.998330] schedule+0x30/0x88 [39293.001472] io_schedule+0x20/0x40 [39293.004874] wbt_wait+0x1bc/0x2f8 [39293.008188] rq_qos_throttle+0x4c/0x68 [39293.011936] blk_mq_make_request+0xc4/0x4f0 [39293.016118] generic_make_request+0xf4/0x308 [39293.020384] submit_bio+0x40/0x198 [39293.023977] btrfs_map_bio+0x370/0x3f8 [btrfs] [39293.028550] btrfs_submit_bio_hook+0xa4/0x1c0 [btrfs] [39293.033727] submit_one_bio+0x78/0xb8 [btrfs] [39293.038211] flush_write_bio.isra.12+0x2c/0x48 [btrfs] [39293.043477] extent_writepages+0x60/0x70 [btrfs] [39293.048217] btrfs_writepages+0x28/0x38 [btrfs] [39293.052747] do_writepages+0x3c/0xe0 [39293.056323] __filemap_fdatawrite_range+0xc0/0x118 [39293.061109] filemap_fdatawrite_range+0x38/0x48 [39293.065764] btrfs_fdatawrite_range+0x34/0x78 [btrfs] [39293.070942] __btrfs_write_out_cache+0x400/0x450 [btrfs] [39293.076382] btrfs_write_out_cache+0xc0/0x160 [btrfs] [39293.081551] btrfs_start_dirty_block_groups+0x2dc/0x4d0 [btrfs] [39293.087591] btrfs_commit_transaction+0x554/0x940 [btrfs] [39293.093111] transaction_kthread+0x18c/0x1a8 [btrfs] [39293.098072] kthread+0x130/0x138 [39293.101298] ret_from_fork+0x10/0x18 [39293.104877] systemd-journal D 0 448 1 0x00000801 [39293.110358] Call trace: [39293.112803] __switch_to+0x9c/0xd8 [39293.116204] __schedule+0x2a0/0x888 [39293.119690] schedule+0x30/0x88 [39293.122830] io_schedule+0x20/0x40 [39293.126230] wait_on_page_bit+0x134/0x240 [39293.130366] btrfs_page_mkwrite+0x1e0/0x450 [btrfs] [39293.135240] do_page_mkwrite+0x40/0xb0 [39293.138985] do_wp_page+0x3d0/0x578 [39293.142471] __handle_mm_fault+0x484/0x528 [39293.146563] handle_mm_fault+0x10c/0x1e8 [39293.150484] do_page_fault+0x174/0x480 [39293.154229] do_mem_abort+0x50/0xa8 [39293.157713] el0_da+0x20/0x24 [39293.160676] journal-offline D 0 23928 1 0x00000801 [39293.166156] Call trace: [39293.168601] __switch_to+0x9c/0xd8 [39293.172002] __schedule+0x2a0/0x888 [39293.175487] schedule+0x30/0x88 [39293.178626] io_schedule+0x20/0x40 [39293.182025] wbt_wait+0x1bc/0x2f8 [39293.185338] rq_qos_throttle+0x4c/0x68 [39293.189085] blk_mq_make_request+0xc4/0x4f0 [39293.193266] generic_make_request+0xf4/0x308 [39293.197533] submit_bio+0x40/0x198 [39293.201064] btrfs_map_bio+0x370/0x3f8 [btrfs] [39293.205632] btrfs_submit_bio_hook+0xa4/0x1c0 [btrfs] [39293.210808] submit_one_bio+0x78/0xb8 [btrfs] [39293.215292] submit_extent_page+0xcc/0x218 [btrfs] [39293.220209] __extent_writepage_io+0x230/0x3e8 [btrfs] [39293.225472] __extent_writepage+0x114/0x2e0 [btrfs] [39293.230476] extent_write_cache_pages+0xec/0x328 [btrfs] [39293.235912] extent_writepages+0x54/0x70 [btrfs] [39293.240651] btrfs_writepages+0x28/0x38 [btrfs] [39293.245179] do_writepages+0x3c/0xe0 [39293.248751] __filemap_fdatawrite_range+0xc0/0x118 [39293.253538] filemap_fdatawrite_range+0x38/0x48 [39293.258194] btrfs_fdatawrite_range+0x34/0x78 [btrfs] [39293.263368] start_ordered_ops+0x4c/0x80 [btrfs] [39293.268110] btrfs_sync_file+0x88/0x3e0 [btrfs] [39293.272640] vfs_fsync_range+0x4c/0x88 [39293.276385] do_fsync+0x48/0x88 [39293.279525] __arm64_sys_fsync+0x24/0x38 [39293.283446] el0_svc_common+0x98/0x100 [39293.287192] el0_svc_handler+0x38/0x78 [39293.290936] el0_svc+0x8/0xc [39293.293829] wickedd D 0 713 1 0x00000000 [39293.299309] Call trace: [39293.301755] __switch_to+0x9c/0xd8 [39293.305155] __schedule+0x2a0/0x888 [39293.308641] schedule+0x30/0x88 [39293.311781] schedule_preempt_disabled+0x14/0x20 [39293.316394] __mutex_lock.isra.1+0x2c0/0x4b8 [39293.320661] __mutex_lock_slowpath+0x24/0x30 [39293.324927] mutex_lock+0x48/0x50 [39293.328243] __netlink_dump_start+0x7c/0x1d8 [39293.332511] rtnetlink_rcv_msg+0x280/0x2c0 [39293.336604] netlink_rcv_skb+0x60/0x120 [39293.340437] rtnetlink_rcv+0x28/0x38 [39293.344010] netlink_unicast+0x1a8/0x280 [39293.347928] netlink_sendmsg+0x188/0x338 [39293.351848] sock_sendmsg+0x4c/0x68 [39293.355333] ___sys_sendmsg+0x26c/0x2a0 [39293.359165] __sys_sendmsg+0x64/0xa0 [39293.362736] __arm64_sys_sendmsg+0x2c/0x38 [39293.366829] el0_svc_common+0x98/0x100 [39293.370575] el0_svc_handler+0x38/0x78 [39293.374320] el0_svc+0x8/0xc [39293.377201] ntpd D 0 1354 1 0x00000001 [39293.382681] Call trace: [39293.385126] __switch_to+0x9c/0xd8 [39293.388526] __schedule+0x2a0/0x888 [39293.392012] schedule+0x30/0x88 [39293.395151] schedule_preempt_disabled+0x14/0x20 [39293.399764] __mutex_lock.isra.1+0x2c0/0x4b8 [39293.404029] __mutex_lock_slowpath+0x24/0x30 [39293.408296] mutex_lock+0x48/0x50 [39293.411610] __netlink_dump_start+0x7c/0x1d8 [39293.415876] rtnetlink_rcv_msg+0x280/0x2c0 [39293.419969] netlink_rcv_skb+0x60/0x120 [39293.423801] rtnetlink_rcv+0x28/0x38 [39293.427374] netlink_unicast+0x1a8/0x280 [39293.431294] netlink_sendmsg+0x188/0x338 [39293.435211] sock_sendmsg+0x4c/0x68 [39293.438694] __sys_sendto+0xe8/0x150 [39293.442266] __arm64_sys_sendto+0x30/0x40 [39293.446272] el0_svc_common+0x98/0x100 [39293.450018] el0_svc_handler+0x38/0x78 [39293.453762] el0_svc+0x8/0xc [39293.456670] kworker/2:1 D 0 23762 2 0x00000028 [39293.462197] Workqueue: events_freezable mmc_rescan [mmc_core] [39293.467936] Call trace: [39293.470381] __switch_to+0x9c/0xd8 [39293.473781] __schedule+0x2a0/0x888 [39293.477267] schedule+0x30/0x88 [39293.480406] schedule_preempt_disabled+0x14/0x20 [39293.485019] __mutex_lock.isra.1+0x2c0/0x4b8 [39293.489285] __mutex_lock_slowpath+0x24/0x30 [39293.493551] mutex_lock+0x48/0x50 [39293.496865] clk_prepare_lock+0x48/0xa0 [39293.500699] clk_prepare+0x24/0x58 [39293.504105] sunxi_mmc_enable+0x40/0x220 [sunxi_mmc] [39293.509067] sunxi_mmc_runtime_resume+0x2c/0x70 [sunxi_mmc] [39293.514637] pm_generic_runtime_resume+0x3c/0x58 [39293.519251] __rpm_callback+0x118/0x208 [39293.523082] rpm_callback+0x70/0x98 [39293.526567] rpm_resume+0x65c/0x840 [39293.530052] __pm_runtime_resume+0x68/0xc8 [39293.534182] __mmc_claim_host+0x200/0x260 [mmc_core] [39293.539178] mmc_get_card+0x38/0x48 [mmc_core] [39293.543656] mmc_sd_detect+0x24/0x90 [mmc_core] [39293.548219] mmc_rescan+0x3d0/0x540 [mmc_core] [39293.552659] process_one_work+0x1f4/0x428 [39293.556665] worker_thread+0x44/0x4a8 [39293.560323] kthread+0x130/0x138 [39293.563549] ret_from_fork+0x10/0x18 [39293.567122] kworker/u8:5 D 0 23778 2 0x00000028 [39293.572608] Workqueue: writeback wb_workfn (flush-btrfs-1) [39293.578087] Call trace: [39293.580533] __switch_to+0x9c/0xd8 [39293.583933] __schedule+0x2a0/0x888 [39293.587419] schedule+0x30/0x88 [39293.590557] io_schedule+0x20/0x40 [39293.593956] wbt_wait+0x1bc/0x2f8 [39293.597269] rq_qos_throttle+0x4c/0x68 [39293.601016] blk_mq_make_request+0xc4/0x4f0 [39293.605196] generic_make_request+0xf4/0x308 [39293.609461] submit_bio+0x40/0x198 [39293.612995] btrfs_map_bio+0x370/0x3f8 [btrfs] [39293.617563] btrfs_submit_bio_hook+0xa4/0x1c0 [btrfs] [39293.622743] submit_one_bio+0x78/0xb8 [btrfs] [39293.627227] submit_extent_page+0xcc/0x218 [btrfs] [39293.632142] __extent_writepage_io+0x230/0x3e8 [btrfs] [39293.637405] __extent_writepage+0x114/0x2e0 [btrfs] [39293.642411] extent_write_cache_pages+0xec/0x328 [btrfs] [39293.647849] extent_writepages+0x54/0x70 [btrfs] [39293.652590] btrfs_writepages+0x28/0x38 [btrfs] [39293.657118] do_writepages+0x3c/0xe0 [39293.660691] __writeback_single_inode+0x48/0x438 [39293.665304] writeback_sb_inodes+0x1c8/0x478 [39293.669570] __writeback_inodes_wb+0x78/0xc8 [39293.673835] wb_writeback+0x264/0x388 [39293.677494] wb_workfn+0x304/0x4a8 [39293.680893] process_one_work+0x1f4/0x428 [39293.684898] worker_thread+0x44/0x4a8 [39293.688555] kthread+0x130/0x138 [39293.691781] ret_from_fork+0x10/0x18 [39293.695354] spi1 D 0 23857 2 0x00000028 [39293.700834] Call trace: [39293.703280] __switch_to+0x9c/0xd8 [39293.706680] __schedule+0x2a0/0x888 [39293.710165] schedule+0x30/0x88 [39293.713305] schedule_preempt_disabled+0x14/0x20 [39293.717918] __mutex_lock.isra.1+0x2c0/0x4b8 [39293.722183] __mutex_lock_slowpath+0x24/0x30 [39293.726450] mutex_lock+0x48/0x50 [39293.729763] clk_prepare_lock+0x48/0xa0 [39293.733597] clk_core_get_rate+0x1c/0x78 [39293.737515] clk_get_rate+0x28/0x38 [39293.741006] sun6i_spi_transfer_one+0x150/0x4a0 [spi_sun6i] [39293.746575] spi_transfer_one_message+0x150/0x648 [39293.751274] __spi_pump_messages+0x424/0x6f0 [39293.755541] spi_pump_messages+0x24/0x30 [39293.759460] kthread_worker_fn+0xf0/0x1f8 [39293.763465] kthread+0x130/0x138 [39293.766691] ret_from_fork+0x10/0x18 [39293.770266] kworker/u8:8 D 0 23923 2 0x00000028 [39293.775882] Workqueue: btrfs-submit btrfs_submit_helper [btrfs] [39293.781793] Call trace: [39293.784240] __switch_to+0x9c/0xd8 [39293.787640] __schedule+0x2a0/0x888 [39293.791126] schedule+0x30/0x88 [39293.794301] __mmc_claim_host+0xa8/0x260 [mmc_core] [39293.799210] mmc_get_card+0x38/0x48 [mmc_core] [39293.803658] mmc_mq_queue_rq+0x220/0x308 [mmc_block] [39293.808619] __blk_mq_try_issue_directly+0x120/0x190 [39293.813580] blk_mq_request_issue_directly+0x94/0xc0 [39293.818539] blk_mq_try_issue_list_directly+0x40/0x98 [39293.823585] blk_mq_sched_insert_requests+0x98/0xc0 [39293.828458] blk_mq_flush_plug_list+0x184/0x298 [39293.832984] blk_flush_plug_list+0xd8/0x250 [39293.837164] blk_finish_plug+0x3c/0x4c [39293.841042] run_scheduled_bios+0x2e4/0x408 [btrfs] [39293.846045] pending_bios_fn+0x20/0x30 [btrfs] [39293.850615] normal_work_helper+0x200/0x470 [btrfs] [39293.855619] btrfs_submit_helper+0x20/0x30 [btrfs] [39293.860406] process_one_work+0x1f4/0x428 [39293.864411] worker_thread+0x44/0x4a8 [39293.868068] kthread+0x130/0x138 [39293.871294] ret_from_fork+0x10/0x18 [39293.874866] ip D 0 23925 23924 0x00000000 [39293.880346] Call trace: [39293.882792] __switch_to+0x9c/0xd8 [39293.886193] __schedule+0x2a0/0x888 [39293.889679] schedule+0x30/0x88 [39293.892817] schedule_timeout+0x2c4/0x408 [39293.896823] wait_for_common+0xdc/0x1a8 [39293.900656] wait_for_completion+0x28/0x38 [39293.904750] __spi_sync+0x148/0x388 [39293.908235] spi_sync+0x34/0x58 [39293.911375] regmap_spi_write+0x84/0x98 [39293.915210] _regmap_raw_write_impl+0x794/0x8d8 [39293.919737] _regmap_bus_raw_write+0x70/0x90 [39293.924003] _regmap_write+0x70/0x128 [39293.927662] regmap_write+0x50/0x78 [39293.931155] sx130x_radio_read+0x94/0x270 [lora_sx130x] [39293.936375] _regmap_raw_read+0xd0/0x248 [39293.940295] _regmap_bus_read+0x50/0x88 [39293.944127] _regmap_read+0x6c/0x170 [39293.947700] _regmap_update_bits+0xa4/0xf0 [39293.951793] regmap_update_bits_base+0x68/0x98 [39293.956233] regmap_field_update_bits_base+0x5c/0x70 [39293.961195] sx125x_clkout_prepare+0x44/0x50 [lora_sx125x] [39293.966674] clk_core_prepare+0x64/0x1d8 [39293.970593] clk_prepare+0x2c/0x58 [39293.973995] sx130x_loradev_open+0x58/0x738 [lora_sx130x] [39293.979388] __dev_open+0xd8/0x178 [39293.982788] __dev_change_flags+0x134/0x198 [39293.986968] dev_change_flags+0x34/0x70 [39293.990800] do_setlink+0x2a8/0xbb8 [39293.994287] rtnl_newlink+0x408/0x768 [39293.997945] rtnetlink_rcv_msg+0x20c/0x2c0 [39294.002038] netlink_rcv_skb+0x60/0x120 [39294.005870] rtnetlink_rcv+0x28/0x38 [39294.009443] netlink_unicast+0x1a8/0x280 [39294.013363] netlink_sendmsg+0x188/0x338 [39294.017281] sock_sendmsg+0x4c/0x68 [39294.020766] ___sys_sendmsg+0x26c/0x2a0 [39294.024598] __sys_sendmsg+0x64/0xa0 [39294.028170] __arm64_sys_sendmsg+0x2c/0x38 [39294.032263] el0_svc_common+0x98/0x100 [39294.036009] el0_svc_handler+0x38/0x78 [39294.039753] el0_svc+0x8/0xc
