A hang bug of dm on s390x

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi guys,

I encountered  a hang issue on a s390x system.  The tested kernel is
not preemptible and booting with "nr_cpus=1"

The test steps:
      umount /home
      lvremove /dev/rhel_s390x-kvm-011/home
      ## uncomment "snapshot_autoextend_threshold = 70" and
      "snapshot_autoextend_percent = 20" in /etc/lvm/lvm.conf

      systemctl enable lvm2-monitor.service
      systemctl start lvm2-monitor.service

      lvremove -y rhel_s390x-kvm-011/thinp
      lvcreate -L 10M -T rhel_s390x-kvm-011/thinp
      lvcreate -V 400M -T rhel_s390x-kvm-011/thinp -n src
      mkfs.ext4 /dev/rhel_s390x-kvm-011/src
      mount /dev/rhel_s390x-kvm-011/src /mnt
      for((i=0;i<4;i++)); do dd if=/dev/zero of=/mnt/test$i.img
bs=100M count=1; done

And the system hangs with the console log [1]

The related kernel config

    CONFIG_PREEMPT_NONE_BUILD=y
    CONFIG_PREEMPT_NONE=y
    CONFIG_PREEMPT_COUNT=y
    CONFIG_SCHED_CORE=y

It turns out that when hanging, the kernel is stuck in the dead-loop
in the function dm_wq_work()
        while (!test_bit(DMF_BLOCK_IO_FOR_SUSPEND, &md->flags)) {
                spin_lock_irq(&md->deferred_lock);
                bio = bio_list_pop(&md->deferred);
                spin_unlock_irq(&md->deferred_lock);

                if (!bio)
                        break;
                thread_cpu = smp_processor_id();
                submit_bio_noacct(bio);
        }
where dm_wq_work()->__submit_bio_noacct()->...->dm_handle_requeue()
keeps generating new bio, and the condition "if (!bio)" can not be
meet.


After applying the following patch, the issue is gone.

diff --git a/drivers/md/dm.c b/drivers/md/dm.c
index e1ea3a7bd9d9..95c9cb07a42f 100644
--- a/drivers/md/dm.c
+++ b/drivers/md/dm.c
@@ -2567,6 +2567,7 @@ static void dm_wq_work(struct work_struct *work)
                        break;

                submit_bio_noacct(bio);
+               cond_resched();
        }
 }

But I think it is not a proper solution. And without this patch, if
removing nr_cpus=1 (the system has two cpus), the issue can not be
triggered. That says when more than one cpu, the above loop can exit
by the condition "if (!bio)"

Any ideas?

Thanks,

Pingfan

[1]: the console log when hanging

 [ 2062.321473] device-mapper: thin: 253:4: reached low water mark for
data device: sending event.
 [ 2062.353217] dm-3: detected capacity change from 122880 to 147456
 [-- MARK -- Wed Dec 14 08:45:00 2022]
[ 2062.376690] device-mapper: thin: 253:4: switching pool to
out-of-data-space (queue IO) mode
 [ 2122.393998] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
 [ 2122.394011] (detected by 0, t=6002 jiffies, g=36205, q=624 ncpus=1)
 [ 2122.394014] rcu: All QSes seen, last rcu_sched kthread activity
6002 (4295149593-4295143591), jiffies_till_next_fqs=1, root ->qsmask
0x0
 [ 2122.394017] rcu: rcu_sched kthread starved for 6002 jiffies!
g36205 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=0
 [ 2122.394019] rcu: Unless rcu_sched kthread gets sufficient CPU
time, OOM is now expected behavior.
 [ 2122.394020] rcu: RCU grace-period kthread stack dump:
 [ 2122.394022] task:rcu_sched       state:R  running task     stack:
  0 pid:   15 ppid:     2 flags:0x00000000
 [ 2122.394027] Call Trace:
 [ 2122.394030]  [<00000001001fd5b0>] __schedule+0x300/0x6c0
 [ 2122.394040]  [<00000001001fd9d2>] schedule+0x62/0xf0
 [ 2122.394042]  [<000000010020360c>] schedule_timeout+0x8c/0x170
 [ 2122.394045]  [<00000000ff9e219e>] rcu_gp_fqs_loop+0x30e/0x3d0
 [ 2122.394053]  [<00000000ff9e3ee2>] rcu_gp_kthread+0x132/0x1b0
 [ 2122.394054]  [<00000000ff980578>] kthread+0x108/0x110
 [ 2122.394058]  [<00000000ff9035cc>] __ret_from_fork+0x3c/0x60
 [ 2122.394061]  [<000000010020455a>] ret_from_fork+0xa/0x30
 [ 2122.394064] rcu: Stack dump where RCU GP kthread last ran:
 [ 2122.394064] Task dump for CPU 0:
 [ 2122.394066] task:kworker/0:2     state:R  running task     stack:
  0 pid:16943 ppid:     2 flags:0x00000004
 [ 2122.394070] Workqueue: kdmflush/253:6 dm_wq_work [dm_mod]
 [ 2122.394100] Call Trace:
 [ 2122.394100]  [<00000000ff98bb98>] sched_show_task.part.0+0xf8/0x130
 [ 2122.394106]  [<00000001001efc9a>]
rcu_check_gp_kthread_starvation+0x172/0x190
 [ 2122.394111]  [<00000000ff9e5afe>] print_other_cpu_stall+0x2de/0x370
 [ 2122.394113]  [<00000000ff9e5d60>] check_cpu_stall+0x1d0/0x270
 [ 2122.394114]  [<00000000ff9e6152>] rcu_sched_clock_irq+0x82/0x230
 [ 2122.394117]  [<00000000ff9f808a>] update_process_times+0xba/0xf0
 [ 2122.394121]  [<00000000ffa0adfa>] tick_sched_handle+0x4a/0x70
 [ 2122.394124]  [<00000000ffa0b2fe>] tick_sched_timer+0x5e/0xc0
 [ 2122.394126]  [<00000000ff9f8cb6>] __hrtimer_run_queues+0x136/0x290
 [ 2122.394128]  [<00000000ff9f9f80>] hrtimer_interrupt+0x150/0x2d0
 [ 2122.394130]  [<00000000ff90ce36>] do_IRQ+0x56/0x70
 [ 2122.394133]  [<00000000ff90d216>] do_irq_async+0x56/0xb0
 [ 2122.394135]  [<00000001001f6786>] do_ext_irq+0x96/0x160
 [ 2122.394138]  [<00000001002047bc>] ext_int_handler+0xdc/0x110
 [ 2122.394140]  [<000003ff8005cf48>]
dm_split_and_process_bio+0x28/0x4d0 [dm_mod]
 [ 2122.394152] ([<000003ff8005d2ec>]
dm_split_and_process_bio+0x3cc/0x4d0 [dm_mod])
 [ 2122.394162]  [<000003ff8005dca8>] dm_submit_bio+0x68/0x110 [dm_mod]
 [ 2122.394173]  [<00000000ffda0698>] __submit_bio+0x78/0x190
 [ 2122.394178]  [<00000000ffda081c>] __submit_bio_noacct+0x6c/0x1e0
 [ 2122.394180]  [<000003ff8005c2ac>] dm_wq_work+0x5c/0xc0 [dm_mod]
 [ 2122.394190]  [<00000000ff9771e6>] process_one_work+0x216/0x4a0
 [ 2122.394196]  [<00000000ff9779a4>] worker_thread+0x64/0x4a0
 [ 2122.394198]  [<00000000ff980578>] kthread+0x108/0x110
 [ 2122.394199]  [<00000000ff9035cc>] __ret_from_fork+0x3c/0x60
 [ 2122.394201]  [<000000010020455a>] ret_from_fork+0xa/0x30
 [ 2302.444001] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
 [ 2302.444015] (detected by 0, t=24007 jiffies, g=36205, q=624 ncpus=1)
 [ 2302.444018] rcu: All QSes seen, last rcu_sched kthread activity
24007 (4295167598-4295143591), jiffies_till_next_fqs=1, root ->qsmask
0x0
 [ 2302.444021] rcu: rcu_sched kthread starved for 24007 jiffies!
g36205 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=0
 [ 2302.444024] rcu: Unless rcu_sched kthread gets sufficient CPU
time, OOM is now expected behavior.
 [ 2302.444025] rcu: RCU grace-period kthread stack dump:
 [ 2302.444027] task:rcu_sched       state:R  running task     stack:
  0 pid:   15 ppid:     2 flag[-- MARK -- Wed Dec 14 08:50:00 2022]
s:0x00000000
 [ 2302.444204] Call Trace:
 [ 2302.444207]  [<00000001001fd5b0>] __schedule+0x300/0x6c0
 [ 2302.444216]  [<00000001001fd9d2>] schedule+0x62/0xf0
 [ 2302.444218]  [<000000010020360c>] schedule_timeout+0x8c/0x170
 [ 2302.444221]  [<00000000ff9e219e>] rcu_gp_fqs_loop+0x30e/0x3d0
 [ 2302.444227]  [<00000000ff9e3ee2>] rcu_gp_kthread+0x132/0x1b0
 [ 2302.444229]  [<00000000ff980578>] kthread+0x108/0x110
 [ 2302.444232]  [<00000000ff9035cc>] __ret_from_fork+0x3c/0x60
 [ 2302.444235]  [<000000010020455a>] ret_from_fork+0xa/0x30
 [ 2302.444237] rcu: Stack dump where RCU GP kthread last ran:
 [ 2302.444238] Task dump for CPU 0:
 [ 2302.444239] task:kworker/0:2     state:R  running task     stack:
  0 pid:16943 ppid:     2 flags:0x00000004
 [ 2302.444244] Workqueue: kdmflush/253:6 dm_wq_work [dm_mod]
 [ 2302.444270] Call Trace:
 [ 2302.444270]  [<00000000ff98bb98>] sched_show_task.part.0+0xf8/0x130
 [ 2302.444275]  [<00000001001efc9a>]
rcu_check_gp_kthread_starvation+0x172/0x190
 [ 2302.444280]  [<00000000ff9e5afe>] print_other_cpu_stall+0x2de/0x370
 [ 2302.444282]  [<00000000ff9e5d60>] check_cpu_stall+0x1d0/0x270
 [ 2302.444284]  [<00000000ff9e6152>] rcu_sched_clock_irq+0x82/0x230
 [ 2302.444286]  [<00000000ff9f808a>] update_process_times+0xba/0xf0
 [ 2302.444290]  [<00000000ffa0adfa>] tick_sched_handle+0x4a/0x70
 [ 2302.444292]  [<00000000ffa0b2fe>] tick_sched_timer+0x5e/0xc0
 [ 2302.444294]  [<00000000ff9f8cb6>] __hrtimer_run_queues+0x136/0x290
 [ 2302.444296]  [<00000000ff9f9f80>] hrtimer_interrupt+0x150/0x2d0
 [ 2302.444298]  [<00000000ff90ce36>] do_IRQ+0x56/0x70
 [ 2302.444301]  [<00000000ff90d216>] do_irq_async+0x56/0xb0
 [ 2302.444303]  [<00000001001f6786>] do_ext_irq+0x96/0x160
 [ 2302.444306]  [<00000001002047bc>] ext_int_handler+0xdc/0x110
 [ 2302.444308]  [<00000000ffbe2a1e>] kmem_cache_alloc+0x15e/0x530
 [ 2302.444316]  [<00000000ffb3e780>] mempool_alloc+0x60/0x210
 [ 2302.444319]  [<00000000ffd9ac4e>] bio_alloc_bioset+0x1ae/0x410
 [ 2302.444324]  [<00000000ffd9af8c>] bio_alloc_clone+0x3c/0x90
 [ 2302.444326]  [<000003ff8005cf9a>]
dm_split_and_process_bio+0x7a/0x4d0 [dm_mod]
 [ 2302.444337]  [<000003ff8005dca8>] dm_submit_bio+0x68/0x110 [dm_mod]
 [ 2302.444347]  [<00000000ffda0698>] __submit_bio+0x78/0x190
 [ 2302.444350]  [<00000000ffda081c>] __submit_bio_noacct+0x6c/0x1e0
 [ 2302.444353]  [<000003ff8005c2ac>] dm_wq_work+0x5c/0xc0 [dm_mod]
 [ 2302.444363]  [<00000000ff9771e6>] process_one_work+0x216/0x4a0
 [ 2302.444367]  [<00000000ff9779a4>] worker_thread+0x64/0x4a0
 [ 2302.444369]  [<00000000ff980578>] kthread+0x108/0x110
 [ 2302.444371]  [<00000000ff9035cc>] __ret_from_fork+0x3c/0x60
 [ 2302.444373]  [<000000010020455a>] ret_from_fork+0xa/0x30

--
dm-devel mailing list
dm-devel@xxxxxxxxxx
https://listman.redhat.com/mailman/listinfo/dm-devel




[Index of Archives]     [DM Crypt]     [Fedora Desktop]     [ATA RAID]     [Fedora Marketing]     [Fedora Packaging]     [Fedora SELinux]     [Yosemite Discussion]     [KDE Users]     [Fedora Docs]

  Powered by Linux