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... Cheers, Dave. -- Dave Chinner david@xxxxxxxxxxxxx
