Re: [PATCH 1/3] xfs: pass alloc flags through to xfs_extent_busy_flush()

Wengang Wang
2023-06-16T22:53:55Z

> On Jun 16, 2023, at 3:29 PM, Dave Chinner <david@fromorbit.com> wrote:
>
> On Fri, Jun 16, 2023 at 05:43:42PM +0000, Wengang Wang wrote:
>>> On Jun 16, 2023, at 12:36 AM, Dave Chinner <david@fromorbit.com> wrote:
>>> On Fri, Jun 16, 2023 at 04:27:32AM +0000, Wengang Wang wrote:
>>>>> On Jun 15, 2023, at 5:42 PM, Wengang Wang <wen.gang.wang@oracle.com> wrote:
>>>>>> On Jun 15, 2023, at 5:17 PM, Dave Chinner <david@fromorbit.com> wrote:
>>>>>> Can you please post that debug and analysis, rather than just a
>>>>>> stack trace that is completely lacking in context? Nothing can be
>>>>>> inferred from a stack trace, and what you are saying is occurring
>>>>>> does not match what the code should actually be doing. So I need to
>>>>>> actually look at what is happening in detail to work out where this
>>>>>> mismatch is coming from....
>>>>>
>>>>> The debug patch was based on my previous patch, I will rework the debug patch
>>>>> basing on yours. I will share you the debug patch, output and my analysis later.
>>>>>
>>>>
>>>> My analysis:
>>>> It’s problem of double free. The first free is from xfs_efi_item_recover(), the
>>>> second free is from xfs_extent_free_finish_item().
>>>> Dave’s patch makes it possible that xfs_trans_free_extent() returns -EAGAIN.
>>>> The double free problem begins when the -EAGAIN is returned.
>>>>
>>>> 1. -EAGAIN returned by xfs_trans_free_extent(), see line 5 in the debug output.
>>>> 2. according to -EAGAIN, xfs_free_extent_later() is called to create a deferred
>>>> operation of type XFS_DEFER_OPS_TYPE_AGFL_FREE to current transaction.
>>>> see line 6.
>>>> 3. New EFI (xfs_efi_log_item) is created and attached to current transaction.
>>>> And the deferred options is moved to capture_list. see line 9. The call path is:
>>>> xfs_efi_item_recover()
>>>> xfs_defer_ops_capture_and_commit(tp, capture_list)
>>>> xfs_defer_ops_capture()
>>>> xfs_defer_create_intents()
>>>> xfs_defer_create_intent()
>>>> ops->create_intent() —> xfs_extent_free_create_intent()
>>>> 4. The new EFI is committed with current transaction. see line 10.
>>>> 5. The mount process (log recover) continue to work with other intents. line 11 and line 12.
>>>> 6. The committed new EFI was added to AIL after log flush by a parallel thread. line 20.
>>>> 7. The mount process (log recover) continue work with other intents. line 21 to line 35.
>>>> 8. The mount process (log recover) come to process the new EFI that was added to AIL
>>>> at step 6. I guess the previous log items, which were added to AIL together with the
>>>> EFI, were removed by xfsaild (I didn’t log that) so they didn’t appear in the AIL intents
>>>> iteration in xlog_recover_process_intents(). see line 36.
>>>> 9. The new EFI record (0x25441ca, 0x30) is freed by xfs_efi_item_recover(). \
>>>> That’s the first free. see line 37.
>>>> 10. The AIL intents iteration is done. It begins to process the capture_list.
>>>> 11. it comes to the XFS_DEFER_OPS_TYPE_AGFL_FREE deferred operation which is
>>>> added in step 3. xfs_extent_free_finish_item() is called to free (2nd free) (0x25441ca, 0x30)
>>>> and it failed because (0x25441ca, 0x30) was already freed at step 9. see line 43.
>>>> So, it’s a double free issue.
>>>
>>> Yes, this much I understand.
>>>
>>> As I've been saying all along, there's something else wrong here,
>>> because we should never encounter that new EFI in the recovery loop.
>>> The recovery loop should see some other type of item and abort
>>> before it sees that EFI.
>>
>> Maybe you are right. But here is my concern, its possible that:
>> Even the were other types of items placed in AIL before that new EFI
>> (after your change list_add() -> list_add_tail()), suppose this scenario:
>>
>> # suppose there were many log intents after the Original EFI (which needs retry)
>> to process.
>> 1. Non EFI type log items (say Item A to Item C) were added to AIL.
>> 2. That new EFI log item, Item D was added to AIL.
>> 3. Now the recovery process the remaining log intents. it takes long enough
>> to let step 4 happen.
>> 4. During the time that the mount (log recover) process was processing the
>> remaining intents (suppose that needs long enough time), Item A, Item B
>> and Item C (on AIL) were processed by xfs_aild (iop_push()) and them was
>> removed from AIL later. Possible?
>> 5. In the recovery intents loop, it comes to the first new log item, that is Item D,
>> the new EFI. (Item A to Item C didn’t come before Item D because they were
>> removed in step 4).
>> 6. the records in the new EFI was freed by xfs_efi_item_recover()
>> 7. the same records in the same new EFI was freed by xfs_extent_free_finish_item()
>> again.
>>
>> If above is possible, the problem still exists even you make sure the new log
>> items in original order when they are placed to AIL.
>
> Yes, I *know this can happen*.
>
> What I've been trying to understand is *how the bug occurred in the
> first place*.
>
> Root cause analysis comes first. Second is confirming the analysis
> is correct. Only then do we really start thinking about how to fix
> it properly.
>
> We are at the second step: I need *empirical confirmation* that this
> ordering problem is the root cause of the behaviour that was
> observed.
>
> Stop trying to fix the problem before we understand how it happened!
>
>>> Go back to your trace-cmd shell and ctrl-c it. Wait for it to dump
>>> all the trace events to the trace.dat file. Then run:
>>>
>>> # trace-cmd report > trace.txt
>>>
>>> the trace.txt file should have the entire mount trace in it, all the
>>> xfs events, the trace-printk output and the console output. now you
>>> can filter everything with grep, sed, awk, python, perl, any way you
>>> like.
>>>
>>
>> Good to know. Well, seems it can’t tell us the -EAGAIN thing? We don’t
>> have trace even in every function for every case.
>
> We don't need an explicit trace for that. If we hit that code path
> in recovery, we will see a xfs_bmap_free_deferred trace for an
> extent from recovery, followed by a xfs_alloc_size_busy/xfs_alloc_near_busy
> event followed immediately by a xfs_bmap_free_defer event for the
> extent we were trying to free.
>
> That tells us an EAGAIN was received and the extent free was
> deferred.
>
> All the tracepoints we need to tell us what is happening in this
> path, one just needs to connect the dots correctly.
>
>>> The trace makes it pretty obvious what is happening: there's an
>>> ordering problem in bulk AIL insertion.
>>>
>>> Can you test the patch below on top of the three in this patchset?
>>
>> This maybe work for this specific mounting, but it looks a bit tricky to me.
>> Please see my comment above. I meant the below patch maybe can ‘fix’ the issue
>> occurred to this specific xfs volume(metadump), but will is it sure to fix all cases?
>
> I don't care about "other cases" right now. All I'm trying to do is
> confirm that this is the *root cause* of *this problem*.
>
> I am aware that this is a test patch, and that I wrote it purely to
> confirm my hypothesis. I am aware that it doesn't fix everything and
> I am aware that I am not *trying to fix everything* with it. I need
> confirmation that my root cause analysis is correct before I spend
> any time on working out how to fix the problem completely.
>
> So, can you please just test the patch and see if the problem is
> fixed?

Then OK, I will test it and report back.

thanks,
wengang