[lufq.fnst@cn.fujitsu.com: Re: About hung task on generic/041]

[Lu Fengqi <lufq.fnst@cn.fujitsu.com>]

[-- Attachment #1: Type: text/plain, Size: 2682 bytes --]

Hi,

Sorry for the duplicate mail. The previous one seems to be due to the
attachment is too large to be sent to the mailing list.

On Thu, Jul 12, 2018 at 08:33:59PM +0800, Lu Fengqi wrote:
>On Thu, Jul 12, 2018 at 11:40:54AM +0100, Filipe Manana wrote:
>>On Wed, Jul 11, 2018 at 10:02 AM, Lu Fengqi <lufq.fnst@cn.fujitsu.com> wrote:
>>> Hi,
>>>
>>> When I run generic/041 with v4.18-rc3 (turn on kasan and hung task
>>> detection), btrfs-transaction kthread will trigger the hung task timeout
>>> (stall at wait_event in btrfs_commit_transaction). At the same time, you
>>> can see that xfs_io -c fsync will occupy 100% of the CPU. I am not sure
>>> whether this is a problem. Any suggestion?
>>
>>Well, something at 100% cpu and that seems hang forever is definitely
>>a problem, specially a workload as simple as the one in generic/041
>
>To clarify, the hung task will end within 500s. Without KASAN, it will
>end within 80s, so it won't trigger hung task timeout 120s. I'm not sure
>if this is just slow, or have some problem?

Well, I tried to run generic/041 with v4.18-rc4(with KASAN) on the other
machine(with HDD) and it didn't finish all night. The hung task maybe
only end within 500s on SSD.

>
>>(never happened to me, even on vanilla 4.18-rc4).

See the attachment kernel_config. Maybe some config make you can't
replicate the case.

>>Do you have the stack trace for the fsync task? What you pasted below
>
>I will send the stack trace tomorrow.

See the attachment kasan.log.xz.

>From the log it seems that the time is consumed in the
btrfs_log_inode_parent loop call btrfs_log_inode.

I'm very willing to provide a trace(without KASAN) for comparison, but when
I run both systemtap and testcase, I have another problem.

See the attachment btrfs_sync_file.stp and 4.18-rc4.dmesg.

-- 
Thanks,
Lu

>
>-- 
>Thanks,
>Lu
>
>>is only for the transaction kthread and that alone doesn't help.
>>
>>>
>>> [Wed Jul 11 15:50:08 2018] INFO: task btrfs-transacti:1053 blocked for more than 120 seconds.
>>> [Wed Jul 11 15:50:08 2018]       Not tainted 4.18.0-rc3-custom #14
>>> [Wed Jul 11 15:50:08 2018] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>> [Wed Jul 11 15:50:08 2018] btrfs-transacti D    0  1053      2 0x80000000
>>> [Wed Jul 11 15:50:08 2018] Call Trace:
>>>
>>> --
>>> Thanks,
>>> Lu
>>>
>>>
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>
>>
>>
>>-- 
>>Filipe David Manana,
>>
>>“Whether you think you can, or you think you can't — you're right.”
>>
>>



[-- Attachment #2: kernel_config.xz --]
[-- Type: application/x-xz, Size: 27016 bytes --]

[-- Attachment #3: kasan.log.xz --]
[-- Type: application/x-xz, Size: 12284 bytes --]

[-- Attachment #4: btrfs_sync_file.stp --]
[-- Type: text/plain, Size: 481 bytes --]

probe module("btrfs").statement("btrfs_sync_file@fs/btrfs/file.c:*") {
        printf("%ld func %s pp %s\n", gettimeofday_us(), probefunc(), pp());
}

probe module("btrfs").function("btrfs_log_inode") {
	printf("%ld func %s caller %s parms %s\n",
		gettimeofday_us(), probefunc(), symname(caller_addr()), $$parms);
}

probe module("btrfs").statement("btrfs_log_inode_parent@fs/btrfs/tree-log.c:*") {
        printf("%ld func %s pp %s\n",
		gettimeofday_us(), probefunc(), pp());
}

[-- Attachment #5: 4.18-rc4.log.xz --]
[-- Type: application/x-xz, Size: 2188 bytes --]