Re: [RFC] xfs: Flush iclog containing XLOG_COMMIT_TRANS before waiting for log space

[Chandan Rajendra <chandan@linux.ibm.com>]

On Saturday, August 31, 2019 10:29 AM Chandan Rajendra wrote: 
> On Friday, August 30, 2019 10:17 PM Brian Foster wrote: 
> > On Fri, Aug 30, 2019 at 09:08:17AM +1000, Dave Chinner wrote:
> > > On Thu, Aug 29, 2019 at 10:51:59AM +0530, Chandan Rajendra wrote:
> > > > On Monday, August 26, 2019 6:02 AM Dave Chinner wrote: 
> > > > > On Sun, Aug 25, 2019 at 08:35:17PM +0530, Chandan Rajendra wrote:
> > > > > > On Friday, August 23, 2019 7:08 PM Chandan Rajendra wrote:
> > > > > > 
> > > > > > Dave, With the above changes made in xfs_trans_reserve(), mount task is
> > > > > > deadlocking due to the following,
> > > > > > 1. With synchronous transactions, __xfs_trans_commit() now causes iclogs to be
> > > > > > flushed to the disk and hence log items to be ultimately moved to AIL.
> > > > > > 2. xfsaild task is woken up, which acts in items on AIL.
> > > > > > 3. After some time, we stop issuing synchronous transactions because AIL has
> > > > > >    log items in its list and hence !xfs_ail_min(tp->t_mountp->m_ail) evaluates to
> > > > > >    false. In xfsaild_push(), "XFS_LSN_CMP(lip->li_lsn, target) <= 0"
> > > > > >    evaluates to false on the first iteration of the while loop. This means we
> > > > > >    have a log item whose LSN is larger than xfs_ail->ail_target at the
> > > > > >    beginning of the AIL.
> > > > > 
> > > > > The push target for xlog_grant_push_ail() is to free 25% of the log
> > > > > space. So if all the items in the AIL are not within 25% of the tail
> > > > > end of the log, there's nothing for the AIL to push. This indicates
> > > > > that there is at least 25% of physical log space free.
> > > > 
> > > > Sorry for the late response. I was trying to understand the code flow.
> > > > 
> > > > Here is a snippet of perf trace explaining what is going on,
> > > > 
> > > > 	 760881:           mount  8654 [002]   216.813041:                         probe:xlog_grant_push_ail: (c000000000765864) comm="xfsaild/loop1" threshold_cycle_s32=3 threshold_block_s32=3970 need_bytes_s32=389328 last_sync_cycle_u32=2 last_sync_block_u32=19330 free_threshold_s32=5120 free_bytes_s32=383756 free_blocks_s32=749 l_logsize=10485760 reserve_cycle_s32=3 reserve_block_s32=9513204(~18580 blocks) tail_cycle_s32=2 tail_block_s32=19330
> > > 
> > > So this looks like last_sync_lsn is 2/19330, and the transaction
> > > reservation is ~380kB, or close on 3% of the log. The reserve grant
> > > head is at 3/18580, so we're ~700 * 512 = ~350kB of reservation
> > > remaining. Yup, so we are definitely in the "go to sleep and wait"
> > > situation here.
> > > 
> > > > 	 786576: kworker/4:1H-kb  1825 [004]   217.041079:                       xfs:xfs_log_assign_tail_lsn: dev 7:1 new tail lsn 2/19333, old lsn 2/19330, last sync 3/18501
> > > 
> > > 200ms later the tail has moved, and last_sync_lsn is now 3/18501.
> > > i.e. the iclog writes have made it to disk, and the items have been
> > > moved into the AIL. I don't know where that came from, but I'm
> > > assuming it's an IO completion based on it being run from a
> > > kworker context that doesn't have an "xfs-" name prefix(*).
> > > 
> > > As the tail has moved, this should have woken the anything sleeping
> > > on the log tail in xlog_grant_head_wait() via a call to
> > > xfs_log_space_wake(). The first waiter should wake, see that there
> > > still isn't room in the log (only 3 sectors were freed in the log,
> > > we need at least 60). That woken process should then run
> > > xlog_grant_push_ail() again and go back to sleep.
> > > 
> > > (*) I have a patch that shortens "s/kworker/kw/" so that you can
> > > actually see the name of the kworker in the 16 byte field we have
> > > for the task name. We really should just increase current->comm to
> > > 32 bytes.
> > > 
> > > > 	 786577: kworker/4:1H-kb  1825 [004]   217.041087:                       xfs:xfs_log_assign_tail_lsn: dev 7:1 new tail lsn 2/19333, old lsn 2/19330, last sync 3/18501
> > > > 	 793653:   xfsaild/loop1  8661 [004]   265.407708:                probe:xfsaild_push_last_pushed_lsn: (c000000000784644) comm="xfsaild/loop1" cycle_lsn_u32=0 block_lsn_u32=0 target_cycle_lsn_u32=2 target_block_lsn_u32=19330
> > > > 	 793654:   xfsaild/loop1  8661 [004]   265.407717:              probe:xfsaild_push_min_lsn_less_than: (c0000000007846a0) comm="xfsaild/loop1" less_than_s32=0 cycle_lsn_u32=2 block_lsn_u32=19333 lip_x64=0xc000000303fb4a48
> > > 
> > > Ans some 40s later the xfsaild is woken by something, sees there's
> > > nothing to do, and goes back to sleep. I don't see the process
> > > sleeping on the grant head being ever being woken and calling
> > > xlog_grant_push_ail(), which would see the new last_sync_lsn and
> > > move the push target....
> > > 
> > > From this trace, it looks like the problem here is a missing or
> > > incorrectly processed wakeup when the log tail moves.
> > > 
> > > Unfortunately, you haven't used the built in trace points for
> > > debugging log space hangs so I can't tell anything more than this.
> > > i.e the trace we need contains these build in tracepoints:
> > > 
> > > # trace-cmd record -e xfs_log\* -e xfs_ail\* sleep 120 &
> > > # <run workload that hangs within 120s>
> > > 
> > > <wait for trace-cmd to exit>
> > > # trace-cmd report | gzip > trace.txt.gz
> > > 
> > > as that will record all transaction reservations, grant head
> > > manipulations, changes to the tail lsn, when processes sleep on the
> > > grant head and are worken, AIL insert/move/delete, etc.
> > > 
> > > This will generate a -lot- of data. I often generate and analyse
> > > traces in the order of tens of GBs of events to track down issues
> > > like this, because the problem is often only seen in a single trace
> > > event in amongst the millions that are recorded....
> > > 
> > > And if we need more info, then we add the appropriate tracepoints
> > > into xlog_grant_push_ail, xfsaild_push, etc under those tracepoint
> > > namespaces, so next time we have a problem we don't ahve to write
> > > custom tracepoints.....
> > > 
> > > > i.e the log size was 2560 * 4096 = 10485760 bytes.
> > > 
> > > The default minimum size.
> > > 
> > > > > I suspect that this means the CIL is overruning it's background push
> > > > > target by more than expected probably because the log is so small. That leads
> > > > > to the outstanding CIL pending commit size (the current CIL context
> > > > > and the previous CIL commit that is held off by the uncommited
> > > > > iclog) is greater than the AIL push target, and so nothing will free
> > > > > up more log space and wake up the transaction waiting for grant
> > > > > space.
> > > > > 
> > > > > e.g. the previous CIL context commit might take 15% of the log
> > > > > space, and the current CIL has reserved 11% of the log space.
> > > > > Now new transactions reservations have run out of grant space and we
> > > > > push on the ail, but it's lowest item is at 26%, and so the AIL push
> > > > > does nothing and we're stuck because the CIL has pinned 26% of the
> > > > > log space.
> > > > > 
> > > > > As a test, can you run the test with larger log sizes? I think
> > > > > the default used was about ~3600 blocks, so it you step that up by
> > > > > 500 blocks at a time we should get an idea of the size of the
> > > > > overrun by the size of the log where the hang goes away. A
> > > > > trace of the transaction reservations and AIL pushing would also be
> > > > > insightful.
> > > > 
> > > > After increasing the log size to 4193 blocks (i.e. 4193 * 4k = 17174528
> > > > bytes) and also the patch applied, I don't see the dead lock happening.
> > > 
> > > Likely because now the 380k transaction reservation is only 2% of the
> > > log instead of close to 4% of the log, and so the overrun isn't
> > > large enough to trigger whatever wakeup issue we have....
> > > 
> > > > Meanwhile, I am planning to read more code to map the explaination
> > > > provided below.
> > > 
> > > Can you get a complete trace (as per above) of a hang? we're going
> > > to need that trace to validate any analysis you do yourself,
> > > anyway...
> > > 
> > 
> > FWIW, I finally managed to reproduce this (trace dump attached for
> > reference). I ultimately moved to another system, starting using loop
> > devices and bumped up the fstests LOAD_FACTOR. What I see is essentially
> > what looks like the lack of a wake up problem described above. More
> > specifically:
> > 
> > - Workload begins, background CIL push occurs for ~1.25MB context.
> > - While the first checkpoint is being written out, another background
> >   push is requested. By the time we can execute the next CIL push, the
> >   second context accrues to ~8MB in size, basically consuming the rest of
> >   the log.
> > 
> > So that essentially describes the delay. It's just a matter of timing
> > due to the amount of time it takes to complete the first checkpoint and
> > start the second vs. the log reservation consumption workload.
> > 
> > - The next CIL push executes, but all transaction waiters block before
> >   the iclog with the commit record for the first checkpoint hits the
> >   log.
> > 
> > So the AIL doesn't actually remain empty indefinitely here. Shortly
> > after the second CIL push starts doing I/O, the items from the first
> > checkpoint make it into the AIL. The problem is just that the AIL stays
> > empty long enough to absorb all of the AIL pushes that occur due to
> > log reservation pressure before everything stops.
> > 
> > I think the two extra AIL push patches Dave has posted are enough to
> > keep things moving. So far I haven't been able to reproduce with those
> > applied (though I applied a modified variant of the second)...
> > 
> 
> I am able to recreate the bug without the "synchronous transaction" patch. I
> am attaching the trace file with this mail.

I think it essentially boils down to the fact that without "synchronous
transactions" during log recovery, the last iclog containing the commit record
wouldn't be submitted for I/O since in the case of this bug we have more than
"2*sizeof(xlog_op_header_t)" space left in it.

Without the "synchronous transaction" change, the patch which initiates the
AIL push from the iclog endio function would be ineffective.

-- 
chandan