Re: [LKP] a9f38e1dec [ 245.678853] INFO: task mount:580 blocked for more than 120 seconds.

[jianchao.wang]

On 11/7/18 11:17 PM, Jens Axboe wrote:
> On 11/7/18 1:22 AM, jianchao.wang wrote:
>>
>>
>> On 11/7/18 11:16 AM, kernel test robot wrote:
>>> Greetings,
>>>
>>> 0day kernel testing robot got the below dmesg and the first bad commit is
>>>
>>> https://urldefense.proofpoint.com/v2/url?u=https-3A__git.kernel.org_pub_scm_linux_kernel_git_torvalds_linux.git&d=DwIBaQ&c=RoP1YumCXCgaWHvlZYR8PZh8Bv7qIrMUB65eapI_JnE&r=7WdAxUBeiTUTCy8v-7zXyr4qk7sx26ATvfo6QSTvZyQ&m=8qsZc_c8QfZOGoITiebvlt5BO9GBK61cAY4xLOCegFU&s=ZGRhkdRCPvSKvbZzx-HAQtWcDZfzce60e2TMvBQyORo&e= master
>>>
>>> commit a9f38e1dec107af70d81338332494bf0a1e76597
>>> Author:     Omar Sandoval <osandov@xxxxxx>
>>> AuthorDate: Mon Oct 15 09:21:34 2018 -0600
>>> Commit:     Jens Axboe <axboe@xxxxxxxxx>
>>> CommitDate: Tue Oct 16 09:50:14 2018 -0600
>>>
>>>     floppy: convert to blk-mq
>>>     
>>>     This driver likes to fetch requests from all over the place, so make
>>>     queue_rq put requests on a list so that the logic stays the same. Tested
>>>     with QEMU.
>>>     
>>>     Signed-off-by: Omar Sandoval <osandov@xxxxxx>
>>>     
>>>     Converted to blk_mq_init_sq_queue() and fixed a few spots where the
>>>     tag_set leaked on cleanup.
>>>     
>>>     Signed-off-by: Jens Axboe <axboe@xxxxxxxxx>
>>>
>>> 6ec3938cff  ataflop: convert to blk-mq
>>> a9f38e1dec  floppy: convert to blk-mq
>>> 8053e5b93e  Merge tag 'trace-v4.20-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
>>> 337734cbca  Add linux-next specific files for 20181106
>>> +---------------------------------------------------------+------------+------------+------------+---------------+
>>> |                                                         | 6ec3938cff | a9f38e1dec | 8053e5b93e | next-20181106 |
>>> +---------------------------------------------------------+------------+------------+------------+---------------+
>>> | boot_successes                                          | 251        | 68         | 69         | 74            |
>>> | boot_failures                                           | 48         | 27         | 25         | 23            |
>>> | Mem-Info                                                | 48         | 12         | 15         | 7             |
>>> | invoked_oom-killer:gfp_mask=0x                          | 6          | 4          | 3          | 2             |
>>> | EIP:iov_iter_fault_in_readable                          | 4          | 1          |            |               |
>>> | Out_of_memory:Kill_process                              | 3          | 2          | 2          |               |
>>> | Out_of_memory_and_no_killable_processes                 | 3          | 2          | 2          |               |
>>> | Kernel_panic-not_syncing:System_is_deadlocked_on_memory | 3          | 2          | 2          |               |
>>> | EIP:__put_user_4                                        | 1          |            |            |               |
>>> | INFO:task_blocked_for_more_than#seconds                 | 0          | 15         | 10         | 16            |
>>> | EIP:lock_is_held_type                                   | 0          | 1          | 0          | 1             |
>>> | EIP:native_safe_halt                                    | 0          | 3          |            |               |
>>> | Kernel_panic-not_syncing:hung_task:blocked_tasks        | 0          | 15         | 10         | 16            |
>>> | EIP:strnlen_user                                        | 0          | 1          |            |               |
>>> | EIP:_local_bh_enable                                    | 0          | 1          |            |               |
>>> | EIP:__lock_acquire                                      | 0          | 1          | 1          | 1             |
>>> | EIP:vprintk_emit                                        | 0          | 1          |            |               |
>>> | EIP:do_softirq_own_stack                                | 0          | 0          | 1          |               |
>>> | EIP:default_idle                                        | 0          | 0          | 2          | 1             |
>>> | EIP:reschedule_interrupt                                | 0          | 0          | 1          |               |
>>> | EIP:delay_tsc                                           | 0          | 0          | 0          | 1             |
>>> | EIP:copy_page_from_iter                                 | 0          | 0          | 0          | 1             |
>>> | EIP:_cond_resched                                       | 0          | 0          | 0          | 1             |
>>> +---------------------------------------------------------+------------+------------+------------+---------------+
>>>
>>> [  244.196551] random: get_random_u32 called from arch_align_stack+0x2d/0x40 with crng_init=1
>>> [  245.254485] _warn_unseeded_randomness: 54 callbacks suppressed
>>> [  245.254491] random: get_random_u32 called from copy_process+0x1c8/0x17b0 with crng_init=1
>>> [  245.257366] random: get_random_u32 called from arch_pick_mmap_layout+0x110/0x140 with crng_init=1
>>> [  245.258675] random: get_random_u32 called from load_elf_binary+0x2b6/0xb48 with crng_init=1
>>> [  245.678853] INFO: task mount:580 blocked for more than 120 seconds.
>>> [  245.679906]       Tainted: G                T 4.19.0-rc6-00172-ga9f38e1 #1
>>> [  245.680959] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>> [  245.682181] mount           D 6372   580      1 0x00000004
>>> [  245.683023] Call Trace:
>>> [  245.683425]  __schedule+0x2df/0x570
>>> [  245.683975]  schedule+0x2d/0x80
>>> [  245.684476]  schedule_timeout+0x19d/0x330
>>> [  245.685090]  ? wait_for_common+0xa5/0x170
>>> [  245.685735]  wait_for_common+0xac/0x170
>>> [  245.686339]  ? do_sched_yield+0x90/0x90
>>> [  245.686935]  wait_for_completion+0x12/0x20
>>> [  245.687571]  __floppy_read_block_0+0xfb/0x150
>>> [  245.688244]  ? floppy_resume+0x40/0x40
>>> [  245.688844]  floppy_revalidate+0x20f/0x240
>>> [  245.689486]  check_disk_change+0x43/0x60
>>> [  245.690087]  floppy_open+0x1ea/0x360
>>> [  245.690653]  __blkdev_get+0xb4/0x4d0
>>> [  245.691212]  ? blkdev_get+0x1db/0x370
>>> [  245.691777]  blkdev_get+0x1f3/0x370
>>> [  245.692351]  ? path_put+0x15/0x20
>>> [  245.692871]  ? lookup_bdev+0x4b/0x90
>>> [  245.693539]  blkdev_get_by_path+0x3d/0x80
>>> [  245.694165]  mount_bdev+0x2a/0x190
>>> [  245.694695]  squashfs_mount+0x10/0x20
>>> [  245.695271]  ? squashfs_alloc_inode+0x30/0x30
>>> [  245.695960]  mount_fs+0xf/0x90
>>> [  245.696451]  vfs_kern_mount+0x43/0x130
>>> [  245.697036]  do_mount+0x187/0xc40
>>> [  245.697563]  ? memdup_user+0x28/0x50
>>> [  245.698124]  ksys_mount+0x60/0xc0
>>> [  245.698639]  sys_mount+0x19/0x20
>>> [  245.699167]  do_int80_syscall_32+0x61/0x130
>>> [  245.699813]  entry_INT80_32+0xc7/0xc7
>>> [  245.700391] EIP: 0x47f46fee
>>> [  245.700829] Code: 11 83 c8 ff eb e2 90 90 90 90 90 90 57 56 53 8b 7c 24 20 8b 74 24 1c 8b 54 24 18 8b 4c 24 14 8b 5c 24 10 b8 15 00 00 00 cd 80 <5b> 5e 5f 3d 01 f0 ff ff 73 01 c3 e8 e8 80 03 00 81 c1 f6 5f 09 00
>>> [  245.703680] EAX: ffffffda EBX: affa4efa ECX: affa4f03 EDX: 080d3630
>>> [  245.704642] ESI: 00008010 EDI: 00000000 EBP: 00000000 ESP: affa45c0
>>> [  245.705637] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b EFLAGS: 00000282
>>
>> There is not a q->queue_lock as blk-legacy to serialize floppy_queue_rq from different contexts.
> 
> Doesn't look immediately racy, the internal queue list is protected by
> the floppy_lock, and the busy start is marked by atomic bit setting.

Oops, I missed the fdc_busy bit set.
I just looked at the patch and found the biggest change was this.
Sorry for the noise.

> Do you see an issue with it, or are you just pontificating?
> 
> FWIW, just ran qemu with two floppy drives and concurrent access,
> didn't see an issue.
> 

Thanks
Jianchao