Re: + shmem-fix-faulting-into-a-hole-while-its-punched-take-2.patch added to -mm tree

[Sasha Levin <sasha.levin@oracle.com>]

[-- Attachment #1: Type: text/plain, Size: 8281 bytes --]

On 07/09/2014 08:47 AM, Sasha Levin wrote:
>> > So it would again help to see stacks of other tasks, to see who holds the i_mutex and where it's stuck...
> The stacks print got garbled due to having large amount of tasks and too low of a
> console buffer. I've fixed that and will update when (if) the problem reproduces.

Okay, so the issue reproduces on today's -next as well, and here's my analysis.

Hung task timer was triggered for trinity-c37:

[  483.991095] INFO: task trinity-c37:8968 blocked for more than 120 seconds.
[  483.995898]       Not tainted 3.16.0-rc4-next-20140709-sasha-00024-gd22103d-dirty #775
[  484.000405] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  484.004961] trinity-c37     D 00000000ffffffff 13160  8968   8558 0x10000000
[  484.009035]  ffff8800c0457ce8 0000000000000006 ffffffff9ac1d920 0000000000000001
[  484.012654]  ffff8800c0457fd8 00000000001e2740 00000000001e2740 00000000001e2740
[  484.015716]  ffff880201610000 ffff8800c0bc3000 ffff8800c0457cd8 ffff880223115bb0
[  484.050723] Call Trace:
[  484.051831] schedule (kernel/sched/core.c:2841)
[  484.053683] schedule_preempt_disabled (kernel/sched/core.c:2868)
[  484.055979] mutex_lock_nested (kernel/locking/mutex.c:532 kernel/locking/mutex.c:584)
[  484.058175] ? shmem_fallocate (mm/shmem.c:1760)
[  484.060441] ? get_parent_ip (kernel/sched/core.c:2555)
[  484.063899] ? shmem_fallocate (mm/shmem.c:1760)
[  484.067485] shmem_fallocate (mm/shmem.c:1760)
[  484.071113] ? put_lock_stats.isra.12 (./arch/x86/include/asm/preempt.h:98 kernel/locking/lockdep.c:254)
[  484.075128] do_fallocate (include/linux/fs.h:1281 fs/open.c:299)
[  484.078566] SyS_madvise (mm/madvise.c:332 mm/madvise.c:381 mm/madvise.c:531 mm/madvise.c:462)
[  484.082074] tracesys (arch/x86/kernel/entry_64.S:542)
[  484.150284] 2 locks held by trinity-c37/8968:
[  484.152995] #0: (sb_writers#16){.+.+.+}, at: do_fallocate (fs/open.c:298)
[  484.158692] #1: (&sb->s_type->i_mutex_key#18){+.+.+.}, at: shmem_fallocate (mm/shmem.c:1760)

It has acquired sb_writers lock ("sb_start_write(inode->i_sb);") in do_fallocate and
is blocking on an attempt to acquire i_mutex in shmem_fallocate():

        if (mode & ~(FALLOC_FL_KEEP_SIZE | FALLOC_FL_PUNCH_HOLE))
                return -EOPNOTSUPP;

        mutex_lock(&inode->i_mutex); <=== HERE

        if (mode & FALLOC_FL_PUNCH_HOLE) {

Now, looking into what actually holds i_mutex rather than waiting on it we see trinity-c507:

[  488.014804] trinity-c507    D 0000000000000002 13112  9445   8558 0x10000002
[  488.014860]  ffff88010391fab8 0000000000000002 ffffffff9abff6b0 0000000000000002
[  488.014894]  ffff88010391ffd8 00000000001e2740 00000000001e2740 00000000001e2740
[  488.014912]  ffff8800be3f8000 ffff88010389b000 ffff88010391faa8 ffff880223115d58
[  488.014942] Call Trace:
[  488.014948] schedule (kernel/sched/core.c:2841)
[  488.014960] schedule_preempt_disabled (kernel/sched/core.c:2868)
[  488.014970] mutex_lock_nested (kernel/locking/mutex.c:532 kernel/locking/mutex.c:584)
[  488.014983] ? unmap_mapping_range (mm/memory.c:2392)
[  488.014992] ? unmap_mapping_range (mm/memory.c:2392)
[  488.015005] unmap_mapping_range (mm/memory.c:2392)
[  488.015021] truncate_inode_page (mm/truncate.c:136 mm/truncate.c:180)
[  488.015041] shmem_undo_range (mm/shmem.c:441)
[  488.015059] shmem_truncate_range (mm/shmem.c:537)
[  488.015069] shmem_fallocate (mm/shmem.c:1771)
[  488.015079] ? put_lock_stats.isra.12 (./arch/x86/include/asm/preempt.h:98 kernel/locking/lockdep.c:254)
[  488.015098] do_fallocate (include/linux/fs.h:1281 fs/open.c:299)
[  488.015110] SyS_madvise (mm/madvise.c:332 mm/madvise.c:381 mm/madvise.c:531 mm/madvise.c:462)
[  488.015131] tracesys (arch/x86/kernel/entry_64.S:542)

It has acquired i_mutex lock in shmem_fallocate() and is now blocking on i_mmap_mutex
in unmap_mapping_range():

        details.check_mapping = even_cows? NULL: mapping;
        details.nonlinear_vma = NULL;
        details.first_index = hba;
        details.last_index = hba + hlen - 1;
        if (details.last_index < details.first_index)
                details.last_index = ULONG_MAX;


        mutex_lock(&mapping->i_mmap_mutex); <==== HERE
        if (unlikely(!RB_EMPTY_ROOT(&mapping->i_mmap)))
                unmap_mapping_range_tree(&mapping->i_mmap, &details);

The only process that actually holds a i_mmap_mutex (instead of just spinning on it)
is trinity-c402:

[  487.925991] trinity-c402    R  running task    13160  9339   8558 0x10000000
[  487.926007]  ffff8800b7eb7b88 0000000000000002 ffff88006efe3290 0000000000000282
[  487.926013]  ffff8800b7eb7fd8 00000000001e2740 00000000001e2740 00000000001e2740
[  487.926022]  ffff8800362b3000 ffff8800b7eb8000 ffff8800b7eb7b88 ffff8800b7eb7fd8
[  487.926028] Call Trace:
[  487.926030] preempt_schedule (./arch/x86/include/asm/preempt.h:80 kernel/sched/core.c:2889)
[  487.926034] ___preempt_schedule (arch/x86/kernel/preempt.S:11)
[  487.926039] ? zap_pte_range (mm/memory.c:1218)
[  487.926042] ? _raw_spin_unlock (./arch/x86/include/asm/preempt.h:98 include/linux/spinlock_api_smp.h:152 kernel/locking/spinlock.c:183)
[  487.926045] ? _raw_spin_unlock (include/linux/spinlock_api_smp.h:152 kernel/locking/spinlock.c:183)
[  487.926049] zap_pte_range (mm/memory.c:1218)
[  487.926056] unmap_single_vma (mm/memory.c:1256 mm/memory.c:1277 mm/memory.c:1301 mm/memory.c:1346)
[  487.926060] unmap_vmas (mm/memory.c:1375 (discriminator 1))
[  487.926066] exit_mmap (mm/mmap.c:2802)
[  487.926069] ? preempt_count_sub (kernel/sched/core.c:2611)
[  487.926075] mmput (kernel/fork.c:638)
[  487.926079] do_exit (kernel/exit.c:744)
[  487.926086] do_group_exit (kernel/exit.c:884)
[  487.926091] SyS_exit_group (kernel/exit.c:895)
[  487.926095] tracesys (arch/x86/kernel/entry_64.S:542)

We can see that it's not blocked since it's in the middle of a spinlock unlock
call, and we can guess it's been in that function for a while because of the hung
task timer, and other processes waiting on that i_mmap_mutex:


[  487.857145] trinity-c338    D 0000000000000008 12904  9274   8558 0x10000004
[  487.857179]  ffff8800b9bcbaa8 0000000000000002 ffffffff9abff6b0 0000000000000000
[  487.857193]  ffff8800b9bcbfd8 00000000001e2740 00000000001e2740 00000000001e2740
[  487.857202]  ffff880107198000 ffff8800b9bc0000 ffff8800b9bcba98 ffff8801ec17f090
[  487.857209] Call Trace:
[  487.857210] schedule (kernel/sched/core.c:2841)
[  487.857222] schedule_preempt_disabled (kernel/sched/core.c:2868)
[  487.857228] mutex_lock_nested (kernel/locking/mutex.c:532 kernel/locking/mutex.c:584)
[  487.857237] ? unlink_file_vma (mm/mmap.c:245)
[  487.857241] ? unlink_file_vma (mm/mmap.c:245)
[  487.857251] unlink_file_vma (mm/mmap.c:245)
[  487.857261] free_pgtables (mm/memory.c:540)
[  487.857275] exit_mmap (mm/mmap.c:2803)
[  487.857284] ? preempt_count_sub (kernel/sched/core.c:2611)
[  487.857291] mmput (kernel/fork.c:638)
[  487.857305] do_exit (kernel/exit.c:744)
[  487.857317] ? get_signal_to_deliver (kernel/signal.c:2333)
[  487.857327] ? debug_smp_processor_id (lib/smp_processor_id.c:57)
[  487.857339] ? put_lock_stats.isra.12 (./arch/x86/include/asm/preempt.h:98 kernel/locking/lockdep.c:254)
[  487.857351] ? _raw_spin_unlock_irq (./arch/x86/include/asm/paravirt.h:819 include/linux/spinlock_api_smp.h:168 kernel/locking/spinlock.c:199)
[  487.857362] do_group_exit (kernel/exit.c:884)
[  487.857376] get_signal_to_deliver (kernel/signal.c:2351)
[  487.857392] do_signal (arch/x86/kernel/signal.c:698)
[  487.857399] ? put_lock_stats.isra.12 (./arch/x86/include/asm/preempt.h:98 kernel/locking/lockdep.c:254)
[  487.857411] ? vtime_account_user (kernel/sched/cputime.c:687)
[  487.857418] ? preempt_count_sub (kernel/sched/core.c:2611)
[  487.857431] ? context_tracking_user_exit (./arch/x86/include/asm/paravirt.h:809 (discriminator 2) kernel/context_tracking.c:184 (discriminator 2))
[  487.857441] ? __this_cpu_preempt_check (lib/smp_processor_id.c:63)
[  487.857451] ? trace_hardirqs_on_caller (kernel/locking/lockdep.c:2557 kernel/locking/lockdep.c:2599)
[  487.857464] do_notify_resume (arch/x86/kernel/signal.c:751)
[  487.857479] int_signal (arch/x86/kernel/entry_64.S:600)

Hope that helps. Full log attached for reference.


Thanks,
Sasha


[-- Attachment #2: log.gz --]
[-- Type: application/gzip, Size: 1419339 bytes --]