Groups > linux.kernel > #1290983 > unrolled thread

Re: corruption causing crash in __queue_work

Started by	Nikolay Borisov <kernel@kyup.com>
First post	2015-12-14 09:50 +0100
Last post	2015-12-21 22:50 +0100
Articles	11 — 3 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

  Re: corruption causing crash in __queue_work Nikolay Borisov <kernel@kyup.com> - 2015-12-14 09:50 +0100
    Re: corruption causing crash in __queue_work Mike Snitzer <snitzer@redhat.com> - 2015-12-14 16:40 +0100
      Re: corruption causing crash in __queue_work Nikolay Borisov <kernel@kyup.com> - 2015-12-14 21:20 +0100
        Re: corruption causing crash in __queue_work Mike Snitzer <snitzer@redhat.com> - 2015-12-14 21:40 +0100
          Re: corruption causing crash in __queue_work Nikolay Borisov <kernel@kyup.com> - 2015-12-17 11:50 +0100
            Re: corruption causing crash in __queue_work Tejun Heo <tj@kernel.org> - 2015-12-17 16:40 +0100
              Re: corruption causing crash in __queue_work Nikolay Borisov <kernel@kyup.com> - 2015-12-17 16:50 +0100
                Re: corruption causing crash in __queue_work Tejun Heo <tj@kernel.org> - 2015-12-17 17:00 +0100
                  Re: corruption causing crash in __queue_work Mike Snitzer <snitzer@redhat.com> - 2015-12-17 18:20 +0100
                    Re: corruption causing crash in __queue_work Tejun Heo <tj@kernel.org> - 2015-12-21 22:50 +0100
                      Re: corruption causing crash in __queue_work Tejun Heo <tj@kernel.org> - 2015-12-21 22:50 +0100

#1290983 — Re: corruption causing crash in __queue_work

From	Nikolay Borisov <kernel@kyup.com>
Date	2015-12-14 09:50 +0100
Subject	Re: corruption causing crash in __queue_work
Message-ID	<qFwZu-3HK-41@gated-at.bofh.it>


On 12/11/2015 07:08 PM, Tejun Heo wrote:
> Hello, Nikolay.
> 
> On Fri, Dec 11, 2015 at 05:57:22PM +0200, Nikolay Borisov wrote:
>> So I had a server with the patch just crash on me:
>>
>> Here is how the queue looks like:
>>  crash> struct workqueue_struct 0xffff8802420a4a00
>> struct workqueue_struct {
>>   pwqs = {
>>     next = 0xffff8802420a4c00,
>>     prev = 0xffff8802420a4a00
> 
> Hmmm... pwq list is already corrupt.  ->prev is terminated but ->next
> isn't.
> 
>>   },
>>   list = {
>>     next = 0xffff880351f9b210,
>>     prev = 0xdead000000200200
> 
> Followed by by 0xdead000000200200 which is likely from
> CONFIG_ILLEGAL_POINTER_VALUE.
> 
> ...
>>   name =
>> "dm-thin\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000",
>>   rcu = {
>>     next = 0xffff8802531c4c20,
>>     func = 0xffffffff810692e0 <rcu_free_wq>
> 
> and call_rcu_sched() already called.  The workqueue has already been
> destroyed.
> 
>>   },
>>   flags = 131082,
>>   cpu_pwqs = 0x0,
>>   numa_pwq_tbl = 0xffff8802420a4b10
>> }
>>
>> crash> rd 0xffff8802420a4b10 2 (the machine has 2 NUMA nodes hence the
>> '2' argument)
>> ffff8802420a4b10:  0000000000000000 0000000000000000   ................
>>
>> At the same time searching for 0xffff8802420a4a00 in the debug output
>> shows nothing IOW it seems that the numa_pwq_tbl is never installed for
>> this workqueue apparently:
>>
>> [root@smallvault8 ~]# grep 0xffff8802420a4a00 /var/log/messages
>>
>> Also dumping all the logs from the dmesg contained in the vmcore image I
>> find nothing and when I do the following correlation:
>> [root@smallvault8 ~]# grep \(null\) wq.log | wc -l
>> 1940
>> [root@smallvault8 ~]# wc -l wq.log
>> 1940 wq.log
>>
>> It seems what's happening is really just changing the numa_pwq_tbl on
>> workqueue creation i.e. it is never re-assigned. So at this point I
>> think it seems that there is a situation where the wqattr are not being
>> applied at all.
> 
> Hmmm... No idea why it didn't show up in the debug log but the only
> way a workqueue could be in the above state is either it got
> explicitly destroyed or somehow pwq refcnting is messed up, in both
> cases it should have shown up in the log.

Had another poke at the backtrace that is produced and here what the
delayed_work looks like:

crash> struct delayed_work ffff88036772c8c0
struct delayed_work {
  work = {
    data = {
      counter = 1537
    },
    entry = {
      next = 0xffff88036772c8c8,
      prev = 0xffff88036772c8c8
    },
    func = 0xffffffffa0211a30 <do_waker>
  },
  timer = {
    entry = {
      next = 0x0,
      prev = 0xdead000000200200
    },
    expires = 4349463655,
    base = 0xffff88047fd2d602,
    function = 0xffffffff8106da40 <delayed_work_timer_fn>,
    data = 18446612146934696128,
    slack = -1,
    start_pid = -1,
    start_site = 0x0,
    start_comm =
"\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
  },
  wq = 0xffff88030cf65400,
  cpu = 21
}

From this it seems that the timer is also cancelled/expired judging by
the values in timer -> entry. But then again in dm-thin the pool is
first suspended, which implies the following functions were called:

cancel_delayed_work(&pool->waker);
cancel_delayed_work(&pool->no_space_timeout);
flush_workqueue(pool->wq);

so at that point dm-thin's workqueue should be empty and it shouldn't be
possible to queue any more delayed work. But the crashdump clearly shows
that the opposite is happening. So far all of this points to a race
condition and inserting some sleeps after umount and after vgchange -Kan
(command to disable volume group and suspend, so the cancel_delayed_work
is invoked) seems to reduce the frequency of crashes, though it doesn't
eliminate them.

> 
> cc'ing dm people.  Is there any chance dm-think could be using
> workqueue after destroying it?
> 
> Thanks.
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [next] | [standalone]

#1291283

From	Mike Snitzer <snitzer@redhat.com>
Date	2015-12-14 16:40 +0100
Message-ID	<qFDod-7ZC-1@gated-at.bofh.it>
In reply to	#1290983

On Mon, Dec 14 2015 at  3:41P -0500,
Nikolay Borisov <kernel@kyup.com> wrote:
 
> Had another poke at the backtrace that is produced and here what the
> delayed_work looks like:
> 
> crash> struct delayed_work ffff88036772c8c0
> struct delayed_work {
>   work = {
>     data = {
>       counter = 1537
>     },
>     entry = {
>       next = 0xffff88036772c8c8,
>       prev = 0xffff88036772c8c8
>     },
>     func = 0xffffffffa0211a30 <do_waker>
>   },
>   timer = {
>     entry = {
>       next = 0x0,
>       prev = 0xdead000000200200
>     },
>     expires = 4349463655,
>     base = 0xffff88047fd2d602,
>     function = 0xffffffff8106da40 <delayed_work_timer_fn>,
>     data = 18446612146934696128,
>     slack = -1,
>     start_pid = -1,
>     start_site = 0x0,
>     start_comm =
> "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
>   },
>   wq = 0xffff88030cf65400,
>   cpu = 21
> }
> 
> From this it seems that the timer is also cancelled/expired judging by
> the values in timer -> entry. But then again in dm-thin the pool is
> first suspended, which implies the following functions were called:
> 
> cancel_delayed_work(&pool->waker);
> cancel_delayed_work(&pool->no_space_timeout);
> flush_workqueue(pool->wq);
> 
> so at that point dm-thin's workqueue should be empty and it shouldn't be
> possible to queue any more delayed work. But the crashdump clearly shows
> that the opposite is happening. So far all of this points to a race
> condition and inserting some sleeps after umount and after vgchange -Kan
> (command to disable volume group and suspend, so the cancel_delayed_work
> is invoked) seems to reduce the frequency of crashes, though it doesn't
> eliminate them.

'vgchange -Kan' doesn't suspend the pool before it destroys the device.
So the cancel_delayed_work()s you referenced aren't applicable.

Can you try this patch?

diff --git a/drivers/md/dm-thin.c b/drivers/md/dm-thin.c
index 63903a5..b201d887 100644
--- a/drivers/md/dm-thin.c
+++ b/drivers/md/dm-thin.c
@@ -2750,8 +2750,11 @@ static void __pool_destroy(struct pool *pool)
 	dm_bio_prison_destroy(pool->prison);
 	dm_kcopyd_client_destroy(pool->copier);
 
-	if (pool->wq)
+	if (pool->wq) {
+		cancel_delayed_work(&pool->waker);
+		cancel_delayed_work(&pool->no_space_timeout);
 		destroy_workqueue(pool->wq);
+	}
 
 	if (pool->next_mapping)
 		mempool_free(pool->next_mapping, pool->mapping_pool);
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1291528

From	Nikolay Borisov <kernel@kyup.com>
Date	2015-12-14 21:20 +0100
Message-ID	<qFHLb-2w9-13@gated-at.bofh.it>
In reply to	#1291283

On Mon, Dec 14, 2015 at 5:31 PM, Mike Snitzer <snitzer@redhat.com> wrote:
> On Mon, Dec 14 2015 at  3:41P -0500,
> Nikolay Borisov <kernel@kyup.com> wrote:
>
>> Had another poke at the backtrace that is produced and here what the
>> delayed_work looks like:
>>
>> crash> struct delayed_work ffff88036772c8c0
>> struct delayed_work {
>>   work = {
>>     data = {
>>       counter = 1537
>>     },
>>     entry = {
>>       next = 0xffff88036772c8c8,
>>       prev = 0xffff88036772c8c8
>>     },
>>     func = 0xffffffffa0211a30 <do_waker>
>>   },
>>   timer = {
>>     entry = {
>>       next = 0x0,
>>       prev = 0xdead000000200200
>>     },
>>     expires = 4349463655,
>>     base = 0xffff88047fd2d602,
>>     function = 0xffffffff8106da40 <delayed_work_timer_fn>,
>>     data = 18446612146934696128,
>>     slack = -1,
>>     start_pid = -1,
>>     start_site = 0x0,
>>     start_comm =
>> "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
>>   },
>>   wq = 0xffff88030cf65400,
>>   cpu = 21
>> }
>>
>> From this it seems that the timer is also cancelled/expired judging by
>> the values in timer -> entry. But then again in dm-thin the pool is
>> first suspended, which implies the following functions were called:
>>
>> cancel_delayed_work(&pool->waker);
>> cancel_delayed_work(&pool->no_space_timeout);
>> flush_workqueue(pool->wq);
>>
>> so at that point dm-thin's workqueue should be empty and it shouldn't be
>> possible to queue any more delayed work. But the crashdump clearly shows
>> that the opposite is happening. So far all of this points to a race
>> condition and inserting some sleeps after umount and after vgchange -Kan
>> (command to disable volume group and suspend, so the cancel_delayed_work
>> is invoked) seems to reduce the frequency of crashes, though it doesn't
>> eliminate them.
>
> 'vgchange -Kan' doesn't suspend the pool before it destroys the device.
> So the cancel_delayed_work()s you referenced aren't applicable.

Hm, but does it not in fact destroy it. Using the following simple
stap script proves so:


probe module("dm_thin_pool").function("__pool_destroy") {
    print("=========__pool_destroy======");
    print_backtrace();

}

probe module("dm_thin_pool").function("pool_postsuspend") {

    printf("==== POOL_POSTSUSPEND =====\n");
    print_backtrace();

}

Produces the following backtraces:

==== POOL_POSTSUSPEND =====
 0xffffffffa033ad40 : pool_postsuspend+0x0/0x50 [dm_thin_pool]
 0xffffffff8148a5bf : suspend_targets+0x3f/0x90 [kernel]
 0xffffffff8148a668 : dm_table_postsuspend_targets+0x18/0x20 [kernel]
 0xffffffff814886dc : __dm_destroy+0x17c/0x190 [kernel]
 0xffffffff81488723 : dm_destroy+0x13/0x20 [kernel]
 0xffffffff8148f55a : dev_remove+0xfa/0x130 [kernel]
 0xffffffff8148fe94 : ctl_ioctl+0x1d4/0x2e0 [kernel]
 0xffffffff8148ffb3 : dm_ctl_ioctl+0x13/0x20 [kernel]
 0xffffffff811af3f3 : do_vfs_ioctl+0x73/0x380 [kernel]
 0xffffffff811af792 : sys_ioctl+0x92/0xa0 [kernel]
 0xffffffff8159ae2e : entry_SYSCALL_64_fastpath+0x12/0x71 [kernel]
=========__pool_destroy====== 0xffffffffa033ae20 :
__pool_destroy+0x0/0x110 [dm_thin_pool]
 0xffffffffa033af61 : __pool_dec+0x31/0x50 [dm_thin_pool]
 0xffffffffa033afae : pool_dtr+0x2e/0x70 [dm_thin_pool]
 0xffffffff8148c085 : dm_table_destroy+0x65/0x120 [kernel]
 0xffffffff8148868a : __dm_destroy+0x12a/0x190 [kernel]
 0xffffffff81488723 : dm_destroy+0x13/0x20 [kernel]
 0xffffffff8148f55a : dev_remove+0xfa/0x130 [kernel]
 0xffffffff8148fe94 : ctl_ioctl+0x1d4/0x2e0 [kernel]
 0xffffffff8148ffb3 : dm_ctl_ioctl+0x13/0x20 [kernel]
 0xffffffff811af3f3 : do_vfs_ioctl+0x73/0x380 [kernel]
 0xffffffff811af792 : sys_ioctl+0x92/0xa0 [kernel]
 0xffffffff8159ae2e : entry_SYSCALL_64_fastpath+0x12/0x71 [kernel]

When I run vgchange -Kan on a volume group. So in __dm_destroy before
dm_table_destroy (which calls pool_dtr)
the device is checked to see if it is suspended, and if not not dm
core would invoke the pre/post suspend hooks, and
this should cause the workqueue to be flushed and in quiescent state. No?

What am I missing?

>
> Can you try this patch?

I've scheduled some machines to go online with this patch and
will report back if it changes the situation. Thanks a lot!

>
> diff --git a/drivers/md/dm-thin.c b/drivers/md/dm-thin.c
> index 63903a5..b201d887 100644
> --- a/drivers/md/dm-thin.c
> +++ b/drivers/md/dm-thin.c
> @@ -2750,8 +2750,11 @@ static void __pool_destroy(struct pool *pool)
>         dm_bio_prison_destroy(pool->prison);
>         dm_kcopyd_client_destroy(pool->copier);
>
> -       if (pool->wq)
> +       if (pool->wq) {
> +               cancel_delayed_work(&pool->waker);
> +               cancel_delayed_work(&pool->no_space_timeout);
>                 destroy_workqueue(pool->wq);
> +       }
>
>         if (pool->next_mapping)
>                 mempool_free(pool->next_mapping, pool->mapping_pool);
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1291535

From	Mike Snitzer <snitzer@redhat.com>
Date	2015-12-14 21:40 +0100
Message-ID	<qFI4x-2Ex-1@gated-at.bofh.it>
In reply to	#1291528

On Mon, Dec 14 2015 at  3:11pm -0500,
Nikolay Borisov <kernel@kyup.com> wrote:

> On Mon, Dec 14, 2015 at 5:31 PM, Mike Snitzer <snitzer@redhat.com> wrote:
> > On Mon, Dec 14 2015 at  3:41P -0500,
> > Nikolay Borisov <kernel@kyup.com> wrote:
> >
> >> Had another poke at the backtrace that is produced and here what the
> >> delayed_work looks like:
> >>
> >> crash> struct delayed_work ffff88036772c8c0
> >> struct delayed_work {
> >>   work = {
> >>     data = {
> >>       counter = 1537
> >>     },
> >>     entry = {
> >>       next = 0xffff88036772c8c8,
> >>       prev = 0xffff88036772c8c8
> >>     },
> >>     func = 0xffffffffa0211a30 <do_waker>
> >>   },
> >>   timer = {
> >>     entry = {
> >>       next = 0x0,
> >>       prev = 0xdead000000200200
> >>     },
> >>     expires = 4349463655,
> >>     base = 0xffff88047fd2d602,
> >>     function = 0xffffffff8106da40 <delayed_work_timer_fn>,
> >>     data = 18446612146934696128,
> >>     slack = -1,
> >>     start_pid = -1,
> >>     start_site = 0x0,
> >>     start_comm =
> >> "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
> >>   },
> >>   wq = 0xffff88030cf65400,
> >>   cpu = 21
> >> }
> >>
> >> From this it seems that the timer is also cancelled/expired judging by
> >> the values in timer -> entry. But then again in dm-thin the pool is
> >> first suspended, which implies the following functions were called:
> >>
> >> cancel_delayed_work(&pool->waker);
> >> cancel_delayed_work(&pool->no_space_timeout);
> >> flush_workqueue(pool->wq);
> >>
> >> so at that point dm-thin's workqueue should be empty and it shouldn't be
> >> possible to queue any more delayed work. But the crashdump clearly shows
> >> that the opposite is happening. So far all of this points to a race
> >> condition and inserting some sleeps after umount and after vgchange -Kan
> >> (command to disable volume group and suspend, so the cancel_delayed_work
> >> is invoked) seems to reduce the frequency of crashes, though it doesn't
> >> eliminate them.
> >
> > 'vgchange -Kan' doesn't suspend the pool before it destroys the device.
> > So the cancel_delayed_work()s you referenced aren't applicable.
> 
> Hm, but does it not in fact destroy it. Using the following simple
> stap script proves so:
> 
> 
> probe module("dm_thin_pool").function("__pool_destroy") {
>     print("=========__pool_destroy======");
>     print_backtrace();
> 
> }
> 
> probe module("dm_thin_pool").function("pool_postsuspend") {
> 
>     printf("==== POOL_POSTSUSPEND =====\n");
>     print_backtrace();
> 
> }
> 
> Produces the following backtraces:
> 
> ==== POOL_POSTSUSPEND =====
>  0xffffffffa033ad40 : pool_postsuspend+0x0/0x50 [dm_thin_pool]
>  0xffffffff8148a5bf : suspend_targets+0x3f/0x90 [kernel]
>  0xffffffff8148a668 : dm_table_postsuspend_targets+0x18/0x20 [kernel]
>  0xffffffff814886dc : __dm_destroy+0x17c/0x190 [kernel]
>  0xffffffff81488723 : dm_destroy+0x13/0x20 [kernel]
>  0xffffffff8148f55a : dev_remove+0xfa/0x130 [kernel]
>  0xffffffff8148fe94 : ctl_ioctl+0x1d4/0x2e0 [kernel]
>  0xffffffff8148ffb3 : dm_ctl_ioctl+0x13/0x20 [kernel]
>  0xffffffff811af3f3 : do_vfs_ioctl+0x73/0x380 [kernel]
>  0xffffffff811af792 : sys_ioctl+0x92/0xa0 [kernel]
>  0xffffffff8159ae2e : entry_SYSCALL_64_fastpath+0x12/0x71 [kernel]
> =========__pool_destroy====== 0xffffffffa033ae20 :
> __pool_destroy+0x0/0x110 [dm_thin_pool]
>  0xffffffffa033af61 : __pool_dec+0x31/0x50 [dm_thin_pool]
>  0xffffffffa033afae : pool_dtr+0x2e/0x70 [dm_thin_pool]
>  0xffffffff8148c085 : dm_table_destroy+0x65/0x120 [kernel]
>  0xffffffff8148868a : __dm_destroy+0x12a/0x190 [kernel]
>  0xffffffff81488723 : dm_destroy+0x13/0x20 [kernel]
>  0xffffffff8148f55a : dev_remove+0xfa/0x130 [kernel]
>  0xffffffff8148fe94 : ctl_ioctl+0x1d4/0x2e0 [kernel]
>  0xffffffff8148ffb3 : dm_ctl_ioctl+0x13/0x20 [kernel]
>  0xffffffff811af3f3 : do_vfs_ioctl+0x73/0x380 [kernel]
>  0xffffffff811af792 : sys_ioctl+0x92/0xa0 [kernel]
>  0xffffffff8159ae2e : entry_SYSCALL_64_fastpath+0x12/0x71 [kernel]
> 
> When I run vgchange -Kan on a volume group. So in __dm_destroy before
> dm_table_destroy (which calls pool_dtr)
> the device is checked to see if it is suspended, and if not not dm
> core would invoke the pre/post suspend hooks, and
> this should cause the workqueue to be flushed and in quiescent state. No?
> 
> What am I missing?

Nothing, clearly you're right!
 
> >
> > Can you try this patch?
> 
> I've scheduled some machines to go online with this patch and
> will report back if it changes the situation. Thanks a lot!

Shouldn't make any difference given the above.

But in that the suspend hooks are used during destroy (if not already
suspended): makes this report all the more bizarre.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1293750

From	Nikolay Borisov <kernel@kyup.com>
Date	2015-12-17 11:50 +0100
Message-ID	<qGEid-6Cx-15@gated-at.bofh.it>
In reply to	#1291535


On 12/14/2015 10:31 PM, Mike Snitzer wrote:
> On Mon, Dec 14 2015 at  3:11pm -0500,
> Nikolay Borisov <kernel@kyup.com> wrote:
> 
>> On Mon, Dec 14, 2015 at 5:31 PM, Mike Snitzer <snitzer@redhat.com> wrote:
>>> On Mon, Dec 14 2015 at  3:41P -0500,
>>> Nikolay Borisov <kernel@kyup.com> wrote:
>>>
>>>> Had another poke at the backtrace that is produced and here what the
>>>> delayed_work looks like:
>>>>
>>>> crash> struct delayed_work ffff88036772c8c0
>>>> struct delayed_work {
>>>>   work = {
>>>>     data = {
>>>>       counter = 1537
>>>>     },
>>>>     entry = {
>>>>       next = 0xffff88036772c8c8,
>>>>       prev = 0xffff88036772c8c8
>>>>     },
>>>>     func = 0xffffffffa0211a30 <do_waker>
>>>>   },
>>>>   timer = {
>>>>     entry = {
>>>>       next = 0x0,
>>>>       prev = 0xdead000000200200
>>>>     },
>>>>     expires = 4349463655,
>>>>     base = 0xffff88047fd2d602,
>>>>     function = 0xffffffff8106da40 <delayed_work_timer_fn>,
>>>>     data = 18446612146934696128,
>>>>     slack = -1,
>>>>     start_pid = -1,
>>>>     start_site = 0x0,
>>>>     start_comm =
>>>> "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
>>>>   },
>>>>   wq = 0xffff88030cf65400,
>>>>   cpu = 21
>>>> }
>>>>
>>>> From this it seems that the timer is also cancelled/expired judging by
>>>> the values in timer -> entry. But then again in dm-thin the pool is
>>>> first suspended, which implies the following functions were called:
>>>>
>>>> cancel_delayed_work(&pool->waker);
>>>> cancel_delayed_work(&pool->no_space_timeout);
>>>> flush_workqueue(pool->wq);
>>>>
>>>> so at that point dm-thin's workqueue should be empty and it shouldn't be
>>>> possible to queue any more delayed work. But the crashdump clearly shows
>>>> that the opposite is happening. So far all of this points to a race
>>>> condition and inserting some sleeps after umount and after vgchange -Kan
>>>> (command to disable volume group and suspend, so the cancel_delayed_work
>>>> is invoked) seems to reduce the frequency of crashes, though it doesn't
>>>> eliminate them.
>>>
>>> 'vgchange -Kan' doesn't suspend the pool before it destroys the device.
>>> So the cancel_delayed_work()s you referenced aren't applicable.
>>
>> Hm, but does it not in fact destroy it. Using the following simple
>> stap script proves so:
>>
>>
>> probe module("dm_thin_pool").function("__pool_destroy") {
>>     print("=========__pool_destroy======");
>>     print_backtrace();
>>
>> }
>>
>> probe module("dm_thin_pool").function("pool_postsuspend") {
>>
>>     printf("==== POOL_POSTSUSPEND =====\n");
>>     print_backtrace();
>>
>> }
>>
>> Produces the following backtraces:
>>
>> ==== POOL_POSTSUSPEND =====
>>  0xffffffffa033ad40 : pool_postsuspend+0x0/0x50 [dm_thin_pool]
>>  0xffffffff8148a5bf : suspend_targets+0x3f/0x90 [kernel]
>>  0xffffffff8148a668 : dm_table_postsuspend_targets+0x18/0x20 [kernel]
>>  0xffffffff814886dc : __dm_destroy+0x17c/0x190 [kernel]
>>  0xffffffff81488723 : dm_destroy+0x13/0x20 [kernel]
>>  0xffffffff8148f55a : dev_remove+0xfa/0x130 [kernel]
>>  0xffffffff8148fe94 : ctl_ioctl+0x1d4/0x2e0 [kernel]
>>  0xffffffff8148ffb3 : dm_ctl_ioctl+0x13/0x20 [kernel]
>>  0xffffffff811af3f3 : do_vfs_ioctl+0x73/0x380 [kernel]
>>  0xffffffff811af792 : sys_ioctl+0x92/0xa0 [kernel]
>>  0xffffffff8159ae2e : entry_SYSCALL_64_fastpath+0x12/0x71 [kernel]
>> =========__pool_destroy====== 0xffffffffa033ae20 :
>> __pool_destroy+0x0/0x110 [dm_thin_pool]
>>  0xffffffffa033af61 : __pool_dec+0x31/0x50 [dm_thin_pool]
>>  0xffffffffa033afae : pool_dtr+0x2e/0x70 [dm_thin_pool]
>>  0xffffffff8148c085 : dm_table_destroy+0x65/0x120 [kernel]
>>  0xffffffff8148868a : __dm_destroy+0x12a/0x190 [kernel]
>>  0xffffffff81488723 : dm_destroy+0x13/0x20 [kernel]
>>  0xffffffff8148f55a : dev_remove+0xfa/0x130 [kernel]
>>  0xffffffff8148fe94 : ctl_ioctl+0x1d4/0x2e0 [kernel]
>>  0xffffffff8148ffb3 : dm_ctl_ioctl+0x13/0x20 [kernel]
>>  0xffffffff811af3f3 : do_vfs_ioctl+0x73/0x380 [kernel]
>>  0xffffffff811af792 : sys_ioctl+0x92/0xa0 [kernel]
>>  0xffffffff8159ae2e : entry_SYSCALL_64_fastpath+0x12/0x71 [kernel]
>>
>> When I run vgchange -Kan on a volume group. So in __dm_destroy before
>> dm_table_destroy (which calls pool_dtr)
>> the device is checked to see if it is suspended, and if not not dm
>> core would invoke the pre/post suspend hooks, and
>> this should cause the workqueue to be flushed and in quiescent state. No?
>>
>> What am I missing?
> 
> Nothing, clearly you're right!
>  
>>>
>>> Can you try this patch?
>>
>> I've scheduled some machines to go online with this patch and
>> will report back if it changes the situation. Thanks a lot!
> 
> Shouldn't make any difference given the above.
> 
> But in that the suspend hooks are used during destroy (if not already
> suspended): makes this report all the more bizarre.

I applied the following patch:

diff --git a/drivers/md/dm-thin.c b/drivers/md/dm-thin.c
index 493c38e08bd2..ccbbf7823cf3 100644
--- a/drivers/md/dm-thin.c
+++ b/drivers/md/dm-thin.c
@@ -3506,8 +3506,8 @@ static void pool_postsuspend(struct dm_target *ti)
        struct pool_c *pt = ti->private;
        struct pool *pool = pt->pool;

-       cancel_delayed_work(&pool->waker);
-       cancel_delayed_work(&pool->no_space_timeout);
+       cancel_delayed_work_sync(&pool->waker);
+       cancel_delayed_work_sync(&pool->no_space_timeout);
        flush_workqueue(pool->wq);
        (void) commit(pool);
 }

And this seems to have resolved the crashes. For the past 24 hours I
haven't seen a single server crash whereas before at least 3-5 servers
would crash.

Given that, it seems like a race condition between destroying the
workqueue from dm-thin and cancelling all the delayed work.

Tejun, I've looked at cancel_delayed_work/cancel_delayed_work_sync and
they both call try_to_grab_pending and then their function diverges. Is
it possible that there is a latent race condition between canceling the
delayed work and the subsequent re-scheduling of the work item?

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1293979

From	Tejun Heo <tj@kernel.org>
Date	2015-12-17 16:40 +0100
Message-ID	<qGIOR-1gS-11@gated-at.bofh.it>
In reply to	#1293750

Hello, Nikolay.

On Thu, Dec 17, 2015 at 12:46:10PM +0200, Nikolay Borisov wrote:
> diff --git a/drivers/md/dm-thin.c b/drivers/md/dm-thin.c
> index 493c38e08bd2..ccbbf7823cf3 100644
> --- a/drivers/md/dm-thin.c
> +++ b/drivers/md/dm-thin.c
> @@ -3506,8 +3506,8 @@ static void pool_postsuspend(struct dm_target *ti)
>         struct pool_c *pt = ti->private;
>         struct pool *pool = pt->pool;
> 
> -       cancel_delayed_work(&pool->waker);
> -       cancel_delayed_work(&pool->no_space_timeout);
> +       cancel_delayed_work_sync(&pool->waker);
> +       cancel_delayed_work_sync(&pool->no_space_timeout);
>         flush_workqueue(pool->wq);
>         (void) commit(pool);
>  }
> 
> And this seems to have resolved the crashes. For the past 24 hours I
> haven't seen a single server crash whereas before at least 3-5 servers
> would crash.

So, that's an obvious bug on dm-thin side.

> Given that, it seems like a race condition between destroying the
> workqueue from dm-thin and cancelling all the delayed work.
> 
> Tejun, I've looked at cancel_delayed_work/cancel_delayed_work_sync and
> they both call try_to_grab_pending and then their function diverges. Is
> it possible that there is a latent race condition between canceling the
> delayed work and the subsequent re-scheduling of the work item?

It's just the wrong variant being used.  cancel_delayed_work() doesn't
guarantee that the work item isn't running on return.  If the work
item was running and the workqueue is destroyed afterwards, it may end
up trying to requeue itself on a destroyed workqueue.

Thanks.

-- 
tejun
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1293985

From	Nikolay Borisov <kernel@kyup.com>
Date	2015-12-17 16:50 +0100
Message-ID	<qGIYy-1kc-11@gated-at.bofh.it>
In reply to	#1293979


On 12/17/2015 05:33 PM, Tejun Heo wrote:
> Hello, Nikolay.
> 
> On Thu, Dec 17, 2015 at 12:46:10PM +0200, Nikolay Borisov wrote:
>> diff --git a/drivers/md/dm-thin.c b/drivers/md/dm-thin.c
>> index 493c38e08bd2..ccbbf7823cf3 100644
>> --- a/drivers/md/dm-thin.c
>> +++ b/drivers/md/dm-thin.c
>> @@ -3506,8 +3506,8 @@ static void pool_postsuspend(struct dm_target *ti)
>>         struct pool_c *pt = ti->private;
>>         struct pool *pool = pt->pool;
>>
>> -       cancel_delayed_work(&pool->waker);
>> -       cancel_delayed_work(&pool->no_space_timeout);
>> +       cancel_delayed_work_sync(&pool->waker);
>> +       cancel_delayed_work_sync(&pool->no_space_timeout);
>>         flush_workqueue(pool->wq);
>>         (void) commit(pool);
>>  }
>>
>> And this seems to have resolved the crashes. For the past 24 hours I
>> haven't seen a single server crash whereas before at least 3-5 servers
>> would crash.
> 
> So, that's an obvious bug on dm-thin side.


Mike if you are ok with this I will submit a proper patch ?
> 
>> Given that, it seems like a race condition between destroying the
>> workqueue from dm-thin and cancelling all the delayed work.
>>
>> Tejun, I've looked at cancel_delayed_work/cancel_delayed_work_sync and
>> they both call try_to_grab_pending and then their function diverges. Is
>> it possible that there is a latent race condition between canceling the
>> delayed work and the subsequent re-scheduling of the work item?
> 
> It's just the wrong variant being used.  cancel_delayed_work() doesn't
> guarantee that the work item isn't running on return.  If the work
> item was running and the workqueue is destroyed afterwards, it may end
> up trying to requeue itself on a destroyed workqueue.

Right, but my initial understanding was that when canceling the delayed
work and then issuing flush_workqueue would act the same way as if
cancel_delayed_work_sync is called wrt to this particular delayed item, no?



> 
> Thanks.
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1294000

From	Tejun Heo <tj@kernel.org>
Date	2015-12-17 17:00 +0100
Message-ID	<qGJ8e-1nC-21@gated-at.bofh.it>
In reply to	#1293985

Hello, Nikolay.

On Thu, Dec 17, 2015 at 05:43:12PM +0200, Nikolay Borisov wrote:
> Right, but my initial understanding was that when canceling the delayed
> work and then issuing flush_workqueue would act the same way as if
> cancel_delayed_work_sync is called wrt to this particular delayed item, no?

Not necessarily.  cancel_delayed_work() cancels whatever is currently
pending.  flush_workqueue() flushes whatever is pending and in flight
at the time of invocation.  Imagine the following scenario.

1. Work item is running but hasn't requeued itself yet.

2. cancel_delayed_work_sync() doesn't do anything as it's not pending.

3. flush_workqueue() starts and waits for the running instance.

4. The running instance requeues itself but this isn't included in the
   scope of the above flush_workqueue().

5. flush_workqueue() returns when the work item is finished (but it's
   still queued).

Thanks.

-- 
tejun
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1294062

From	Mike Snitzer <snitzer@redhat.com>
Date	2015-12-17 18:20 +0100
Message-ID	<qGKnD-2nS-1@gated-at.bofh.it>
In reply to	#1294000

On Thu, Dec 17 2015 at 10:50am -0500,
Tejun Heo <tj@kernel.org> wrote:

> Hello, Nikolay.
> 
> On Thu, Dec 17, 2015 at 05:43:12PM +0200, Nikolay Borisov wrote:
> > Right, but my initial understanding was that when canceling the delayed
> > work and then issuing flush_workqueue would act the same way as if
> > cancel_delayed_work_sync is called wrt to this particular delayed item, no?
> 
> Not necessarily.  cancel_delayed_work() cancels whatever is currently
> pending.  flush_workqueue() flushes whatever is pending and in flight
> at the time of invocation.  Imagine the following scenario.
> 
> 1. Work item is running but hasn't requeued itself yet.
> 
> 2. cancel_delayed_work_sync() doesn't do anything as it's not pending.

Did you mean cancel_delayed_work()?

> 3. flush_workqueue() starts and waits for the running instance.
> 
> 4. The running instance requeues itself but this isn't included in the
>    scope of the above flush_workqueue().
> 
> 5. flush_workqueue() returns when the work item is finished (but it's
>    still queued).

Hmm, the comment above cancel_delayed_work() is pretty misleading then:

 * Note:
 * The work callback function may still be running on return, unless
 * it returns %true and the work doesn't re-arm itself.  Explicitly flush or
 * use cancel_delayed_work_sync() to wait on it.

Given dm-thin.c:pool_postsuspend() does:

        cancel_delayed_work(&pool->waker);
        cancel_delayed_work(&pool->no_space_timeout);
        flush_workqueue(pool->wq);

I wouldn't have thought cancel_delayed_work_sync() was needed.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1296229

From	Tejun Heo <tj@kernel.org>
Date	2015-12-21 22:50 +0100
Message-ID	<qIgv8-3rX-3@gated-at.bofh.it>
In reply to	#1294062

On Sat, Dec 19, 2015 at 03:34:45PM +0200, Nikolay Borisov wrote:
> Ping as Tejun might have missed this email. I'm also interested in knowing
> the logic behind the comment.

Didn't I already reply to that?

http://thread.gmane.org/gmane.linux.kernel/2104051

-- 
tejun
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]

#1296233

From	Tejun Heo <tj@kernel.org>
Date	2015-12-21 22:50 +0100
Message-ID	<qIgv8-3rX-17@gated-at.bofh.it>
In reply to	#1296229

On Mon, Dec 21, 2015 at 4:44 PM, Tejun Heo <tj@kernel.org> wrote:
> On Sat, Dec 19, 2015 at 03:34:45PM +0200, Nikolay Borisov wrote:
>> Ping as Tejun might have missed this email. I'm also interested in knowing
>> the logic behind the comment.
>
> Didn't I already reply to that?
>
> http://thread.gmane.org/gmane.linux.kernel/2104051

Oops, wrong link.

http://thread.gmane.org/gmane.linux.kernel/2104051/focus=2110844

-- 
tejun
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [standalone]

csiph-web

Re: corruption causing crash in __queue_work

Contents

#1290983 — Re: corruption causing crash in __queue_work

#1291283

#1291528

#1291535

#1293750

#1293979

#1293985

#1294000

#1294062

#1296229

#1296233