Re: Rough (re)start with btrfs

Re: Rough (re)start with btrfs

[Qu Wenruo]

[-- Attachment #1.1: Type: text/plain, Size: 2800 bytes --]



On 2019/5/3 上午3:02, Hendrik Friedel wrote:
> Hello,
> 
> thanks for your replies. I appreciate it!
>>>  I am using btrfs-progs v4.20.2 and debian stretch with
>>>  4.19.0-0.bpo.2-amd64 (I think, this is the latest Kernel available in
>>>  stretch. Please correct if I am wrong.
>>
>> What scheduler is being used for the drive?
>>
>> # cat /sys/block/<dev>/queue/scheduler
> [mq-deadline] none
> 
>> If it's none, then kernel version and scheduler aren't likely related
>> to what you're seeing.
>>
>> It's not immediately urgent, but I would still look for something
>> newer, just because the 4.19 series already has 37 upstream updates
>> released, each with dozens of fixes, easily there are over 1000 fixes
>> available in total. I'm not a Debian user but I think there's
>> stretch-backports that has newer kernels?
>> http://jensd.be/818/linux/install-a-newer-kernel-in-debian-9-stretch-stable
>>
> 
> Unfortunately, backports provides 4.19 as the latest.
> I am now manually compiling 5.0. Last time I did that, I was less half
> my current age :-)
> 
>> We need the entire dmesg so we can see if there are any earlier
>> complaints by the drive or the link. Can you attach the entire dmesg
>> as a file?
> Done (also the two smartctl outputs).
> 
>>Have you tried stop the workload, and see if the timeout disappears?
> 
> Unfortunately not. I had the impression that the system did not react
> anymore. I CTRL-Ced and rebooted.
> I was copying all the stuff from my old drive to the new one. I should
> say, that the workload was high, but not exceptional. Just one or two
> copy jobs.

Then it's some deadlock, not regular high load timeout.

> Also, the btrfs drive was in advantage:
> 1) it had btrfs ;-) (the other ext4)
> 2) it did not need to search
> 3) it was connected via SATA (and not USB3 as the source)
> 
> The drive does not seem to be an SMR drive (WD80EZAZ).
> 
>> If it just disappear after some time, then it's the disk too slow and
>> too heavy load, combined with btrfs' low concurrency design leading to
>> the problem.
> 
> I was tempted to ask, whether this should be fixed. On the other hand, I
> am not even sure anything bad happened (except, well, the system -at
> least the copy- seemed to hang).

Definitely needs to be fixed.

With full dmesg, it's now clear that is a real dead lock.
Something wrong with the free space cache, blocking the whole fs to be
committed.

If you still want to try btrfs, you could try "nosapce_cache" mount option.
Free space cache of btrfs is just an optimization, you can completely
ignore that with minor performance drop.

Thanks,
Qu

> 
> By the way: I ran a scrub and a smartctl -t long. Both without errors.
> 
> Greetings,
> Hendrik


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re[2]: Rough (re)start with btrfs

[Hendrik Friedel]

Hello,

-by the way: I think my mail did not appear in the list, but only 
reached Chris and Qu directly. I just tried to re-send it. Could this be 
caused by
1) me not a subscriber of the list
2) combined with me sending attachments
I did *not* get any error message by the server.

>>  I was tempted to ask, whether this should be fixed. On the other hand, I
>>  am not even sure anything bad happened (except, well, the system -at
>>  least the copy- seemed to hang).
>
>Definitely needs to be fixed.
>
>With full dmesg, it's now clear that is a real dead lock.
>Something wrong with the free space cache, blocking the whole fs to be
>committed.
>
So, what's the next step? Shall I open a bug report somewhere, or is it 
already on some list?

>If you still want to try btrfs, you could try "nosapce_cache" mount option.
>Free space cache of btrfs is just an optimization, you can completely
>ignore that with minor performance drop.
>
I will try that, yes.
Can you confirm, that it is unlikely, that I lost any data / damaged the 
Filesystem?

Regards,
Hendrik

Re: Re[2]: Rough (re)start with btrfs

[Chris Murphy]

On Thu, May 2, 2019 at 11:41 PM Hendrik Friedel <hendrik@friedels.name> wrote:
>
> Hello,
>
> -by the way: I think my mail did not appear in the list, but only
> reached Chris and Qu directly. I just tried to re-send it. Could this be
> caused by
> 1) me not a subscriber of the list
> 2) combined with me sending attachments
> I did *not* get any error message by the server.
>
> >>  I was tempted to ask, whether this should be fixed. On the other hand, I
> >>  am not even sure anything bad happened (except, well, the system -at
> >>  least the copy- seemed to hang).
> >
> >Definitely needs to be fixed.
> >
> >With full dmesg, it's now clear that is a real dead lock.
> >Something wrong with the free space cache, blocking the whole fs to be
> >committed.
> >
> So, what's the next step? Shall I open a bug report somewhere, or is it
> already on some list?
>
> >If you still want to try btrfs, you could try "nosapce_cache" mount option.
> >Free space cache of btrfs is just an optimization, you can completely
> >ignore that with minor performance drop.
> >
> I will try that, yes.
> Can you confirm, that it is unlikely, that I lost any data / damaged the
> Filesystem?

Not likely. You can do a scrub to check for metadata and data
corruption. And you can do an offline (unmounted) 'btrfs check
--readonly' to check the validity of the metadata. The Btrfs call
traces during the blocked task are INFO, not warnings or errors, so
the file system and data is likely fine. There's no read, write,
corruption, or generation errors in the dmesg; but you can also check
'btfs dev stats <mountpoint>' which is a persistent counter for this
particular device.

-- 
Chris Murphy

Re[4]: Rough (re)start with btrfs

[Hendrik Friedel]

Hello,

this:
 >Some prefer bug report in mail list directly like me, some prefer 
kernel
 >bugzilla.

and this:
 >Not sure if other is looking into this.
 >Btrfs bug tracking is somewhat tricky.

may be related...


 >Not likely. You can do a scrub to check for metadata and data
 >corruption.

Did that. All good.

 >And you can do an offline (unmounted) 'btrfs check
 >--readonly' to check the validity of the metadata.

Will do that.

 > The Btrfs call
 >traces during the blocked task are INFO, not warnings or errors, so
 >the file system and data is likely fine. There's no read, write,
 >corruption, or generation errors in the dmesg; but you can also check
 >'btfs dev stats <mountpoint>' which is a persistent counter for this
 >particular device.
[/dev/sdh1].write_io_errs 0
[/dev/sdh1].read_io_errs 0
[/dev/sdh1].flush_io_errs 0
[/dev/sdh1].corruption_errs 0
[/dev/sdh1].generation_errs 0


 >I should have read this before replying earlier.
 >
 >You can also do a one time clean mount with '-o
 >clear_cache,space_cache=v2' which will remove the v1 (default) space
 >cache, and create a v2 cache. Subsequent mount will see the flag for
 >this feature and always use the v2 cache. It's a totally differently
 >implementation and shouldn't have this problem.

So, you have a suspicion already about what caused the problem? Why is 
v2 then not default? Is it worth chasing the Bug in v1?
For me, the question now is, whether we should chase this Bug or not. I 
encountered it three times while filling a 8TB drive with 7TB. Now, I 
have 1TB left and I am not sure I can reproduce, but I can try.

 >Qu would know better but usually developers ask for sysrq+w when
 >there's blocked tasks.

I am wondering, whether there is a -long term- a better way than this. 
Ideally, btrfs would automatically create a 
btrfs-bug-DD-MM-YY-hh-mm-ss.tar.gz with all the info you need and inform 
the User about it and where to issue the bug. I am aware that this is 
tricky. But in order to further mature btrfs, I assume you need more 
real life data with good quality (that is, the right logs) without too 
much work (asking for logs). What's your view on this?

 >You know what? Try changing the scheduler from mq-deadline to none.
 >Change nothing else. Now try to reproduce. Let's see if it still
 >happens.

Wouldn't it make sense first to try to reproduce without changing 
anything?

 >Also, what are the mount options?
rw,noatime,nospace_cache,subvolid=5,subvol=/
But noatime and nospace_cache I added just today.

Greetings,
Hendrik

Re: Re[4]: Rough (re)start with btrfs

[Chris Murphy]

On Sat, May 4, 2019 at 3:31 AM Hendrik Friedel <hendrik@friedels.name> wrote:
>
>  >I should have read this before replying earlier.
>  >
>  >You can also do a one time clean mount with '-o
>  >clear_cache,space_cache=v2' which will remove the v1 (default) space
>  >cache, and create a v2 cache. Subsequent mount will see the flag for
>  >this feature and always use the v2 cache. It's a totally differently
>  >implementation and shouldn't have this problem.
>
> So, you have a suspicion already about what caused the problem? Why is
> v2 then not default? Is it worth chasing the Bug in v1?

v2 is expected to become the default soon

There's known contention for certain workloads when using v1 because
the cache information is stored as if it were a hidden data file,
whereas v2 uses its own btree. But from the sound of it Qu has enough
information to maybe track down the v1 problem and fix it, and
probably should be fixed as v1 is the default and is still supported
and will be forever. But the time frame for a fix may be a while, I'm
not sure.


> For me, the question now is, whether we should chase this Bug or not. I
> encountered it three times while filling a 8TB drive with 7TB. Now, I
> have 1TB left and I am not sure I can reproduce, but I can try.

I don't think it's necessary unless Qu specifically asks.


>
>  >Qu would know better but usually developers ask for sysrq+w when
>  >there's blocked tasks.
>
> I am wondering, whether there is a -long term- a better way than this.
> Ideally, btrfs would automatically create a
> btrfs-bug-DD-MM-YY-hh-mm-ss.tar.gz with all the info you need and inform
> the User about it and where to issue the bug.

No Linux file system has such a thing. And to create such a package
would happen in user space, not the kernel code. Most of Btrfs is
kernel code, same as ext4 and XFS and other file systems. What is
usually the case, if the file system gets confused, it should dump
information into the kernel messages, and the file system developers
do control what kinds of info, error, and warning kernel messages get
dumped into dmesg. Normally that's enough. But since Btrfs is in the
kernel, it depends on other things that happen in the kernel and it's
sometimes necessary to get more information on demand. There really
isn't a way to automate sysrq - you wouldn't want to constantly dump
that amount of information into kernel message buffer and then burden
the system logger with quite a lot of extraneous information.



>
>  >You know what? Try changing the scheduler from mq-deadline to none.
>  >Change nothing else. Now try to reproduce. Let's see if it still
>  >happens.
>
> Wouldn't it make sense first to try to reproduce without changing
> anything?

I assumed it was a persistent problem rather than a transient one. So
yes you should first discover the reproduce steps. That's ideal too
for the developers because often they need to reproduce to see on
their own system what's going on, and often times they have Btrfs
debug option set in their kernels which most distros do not enable. So
they can see more things than we do.

Once you have a reproducer, then you can change the scheduler and see
if your reproduce steps still reproduce the problem.



>
>  >Also, what are the mount options?
> rw,noatime,nospace_cache,subvolid=5,subvol=/
> But noatime and nospace_cache I added just today.

OK that all looks good.


-- 
Chris Murphy

Re[6]: Rough (re)start with btrfs

[Hendrik Friedel]

Hello,

>v2 is expected to become the default soon
That is good to hear.

>But from the sound of it Qu has enough
>information to maybe track down the v1 problem and fix it, and
>probably should be fixed as v1 is the default and is still supported
>and will be forever.
That's good to hear.

>>
>>  For me, the question now is, whether we should chase this Bug or not. I
>>  encountered it three times while filling a 8TB drive with 7TB. Now, I
>>  have 1TB left and I am not sure I can reproduce, but I can try.
>
>I don't think it's necessary unless Qu specifically asks.
Let me know Qu.

>>you wouldn't want to constantly dump
>that amount of information into kernel message buffer and then burden
>the system logger with quite a lot of extraneous information.
I understand. Still, a a pitty.

>Once you have a reproducer, then you can change the scheduler and see
>if your reproduce steps still reproduce the problem.
I will try and let you know. It's not persistent.

Greetings,
Hendrik


>

Re: Rough (re)start with btrfs

[Qu Wenruo]

[-- Attachment #1.1: Type: text/plain, Size: 1506 bytes --]



On 2019/5/3 下午1:41, Hendrik Friedel wrote:
> Hello,
> 
> -by the way: I think my mail did not appear in the list, but only
> reached Chris and Qu directly. I just tried to re-send it. Could this be
> caused by
> 1) me not a subscriber of the list
> 2) combined with me sending attachments
> I did *not* get any error message by the server.
> 
>>>  I was tempted to ask, whether this should be fixed. On the other
>>> hand, I
>>>  am not even sure anything bad happened (except, well, the system -at
>>>  least the copy- seemed to hang).
>>
>> Definitely needs to be fixed.
>>
>> With full dmesg, it's now clear that is a real dead lock.
>> Something wrong with the free space cache, blocking the whole fs to be
>> committed.
>>
> So, what's the next step? Shall I open a bug report somewhere, or is it
> already on some list?

Not sure if other is looking into this.

Btrfs bug tracking is somewhat tricky.
Some prefer bug report in mail list directly like me, some prefer kernel
bugzilla.

> 
>> If you still want to try btrfs, you could try "nosapce_cache" mount
>> option.
>> Free space cache of btrfs is just an optimization, you can completely
>> ignore that with minor performance drop.
>>
> I will try that, yes.
> Can you confirm, that it is unlikely, that I lost any data / damaged the
> Filesystem?

You lost nothing except the new data which is going be committed in the
blocked transaction.

Thanks,
Qu

> 
> Regards,
> Hendrik
> 


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: Rough (re)start with btrfs

[Chris Murphy]

On Thu, May 2, 2019 at 5:40 PM Qu Wenruo <quwenruo.btrfs@gmx.com> wrote:
>
>
>
> On 2019/5/3 上午3:02, Hendrik Friedel wrote:
> > Hello,
> >
> > thanks for your replies. I appreciate it!
> >>>  I am using btrfs-progs v4.20.2 and debian stretch with
> >>>  4.19.0-0.bpo.2-amd64 (I think, this is the latest Kernel available in
> >>>  stretch. Please correct if I am wrong.
> >>
> >> What scheduler is being used for the drive?
> >>
> >> # cat /sys/block/<dev>/queue/scheduler
> > [mq-deadline] none
> >
> >> If it's none, then kernel version and scheduler aren't likely related
> >> to what you're seeing.
> >>
> >> It's not immediately urgent, but I would still look for something
> >> newer, just because the 4.19 series already has 37 upstream updates
> >> released, each with dozens of fixes, easily there are over 1000 fixes
> >> available in total. I'm not a Debian user but I think there's
> >> stretch-backports that has newer kernels?
> >> http://jensd.be/818/linux/install-a-newer-kernel-in-debian-9-stretch-stable
> >>
> >
> > Unfortunately, backports provides 4.19 as the latest.
> > I am now manually compiling 5.0. Last time I did that, I was less half
> > my current age :-)
> >
> >> We need the entire dmesg so we can see if there are any earlier
> >> complaints by the drive or the link. Can you attach the entire dmesg
> >> as a file?
> > Done (also the two smartctl outputs).
> >
> >>Have you tried stop the workload, and see if the timeout disappears?
> >
> > Unfortunately not. I had the impression that the system did not react
> > anymore. I CTRL-Ced and rebooted.
> > I was copying all the stuff from my old drive to the new one. I should
> > say, that the workload was high, but not exceptional. Just one or two
> > copy jobs.
>
> Then it's some deadlock, not regular high load timeout.
>
> > Also, the btrfs drive was in advantage:
> > 1) it had btrfs ;-) (the other ext4)
> > 2) it did not need to search
> > 3) it was connected via SATA (and not USB3 as the source)
> >
> > The drive does not seem to be an SMR drive (WD80EZAZ).
> >
> >> If it just disappear after some time, then it's the disk too slow and
> >> too heavy load, combined with btrfs' low concurrency design leading to
> >> the problem.
> >
> > I was tempted to ask, whether this should be fixed. On the other hand, I
> > am not even sure anything bad happened (except, well, the system -at
> > least the copy- seemed to hang).
>
> Definitely needs to be fixed.
>
> With full dmesg, it's now clear that is a real dead lock.
> Something wrong with the free space cache, blocking the whole fs to be
> committed.
>
> If you still want to try btrfs, you could try "nosapce_cache" mount option.
> Free space cache of btrfs is just an optimization, you can completely
> ignore that with minor performance drop.


I should have read this before replying earlier.

You can also do a one time clean mount with '-o
clear_cache,space_cache=v2' which will remove the v1 (default) space
cache, and create a v2 cache. Subsequent mount will see the flag for
this feature and always use the v2 cache. It's a totally differently
implementation and shouldn't have this problem.


-- 
Chris Murphy

Re: Re[2]: Rough (re)start with btrfs

[Chris Murphy]

On Thu, May 2, 2019 at 1:02 PM Hendrik Friedel <hendrik@friedels.name> wrote:
>
> >What scheduler is being used for the drive?
> >
> ># cat /sys/block/<dev>/queue/scheduler
> [mq-deadline] none

At first I thought you might be running into this bug
https://lwn.net/Articles/774440/

However:

[Mo Apr 29 20:44:47 2019]       Not tainted 4.19.0-0.bpo.2-amd64 #1
Debian 4.19.16-1~bpo9+1

This is actually based on 4.19.16 which has the fix for that.


[Mo Apr 29 06:44:32 2019] systemd[1]: apt-daily-upgrade.timer: Adding
36min 35.299087s random time.
[Mo Apr 29 20:44:47 2019] INFO: task btrfs-transacti:10227 blocked for
more than 120 seconds.

Literally nothing for hours before the blocking. And I don't see
anything off during device discovery.

Qu would know better but usually developers ask for sysrq+w when
there's blocked tasks.
https://www.kernel.org/doc/html/v4.11/admin-guide/sysrq.html

Basically as root issue
# echo 1 >/proc/sys/kernel/sysrq
# echo w > /proc/sysrq-trigger

What I do is run the first command and type out the second command but
do not press return; in another shell reproduce the hang, and then go
back to the first shell and hit return. That way it doesn't take a
minute or two to type out during the hang. The result appears in
dmesg, so stop the operation causing the hang if possible and then
'dmesg>dmesg.txt' and attach it. Also, you'll want to reboot with
'log_bug_len=1M' because the sysrq+w that gets dumped to dmesg will
fill up the kernel message buffer.

> Done (also the two smartctl outputs).

I don't see anything weird there either. The errors are a little weird
but predate the Btrfs error by a lot.


> I was tempted to ask, whether this should be fixed. On the other hand, I am not even sure anything bad happened (except, well, the system -at least the copy- seemed to hang).

It could be a bug somewhere, but question is where. The workload is
only copy? Seems trivial and not prone to lock contention.

You know what? Try changing the scheduler from mq-deadline to none.
Change nothing else. Now try to reproduce. Let's see if it still
happens.

Also, what are the mount options?

-- 
Chris Murphy

Rough (re)start with btrfs

[Hendrik Friedel]

Hello,

as discussed in the other thread, I am migrating to BTRFS (again).
Unfortunately, I had a bit of a rough start
[Mo Apr 29 20:44:47 2019] INFO: task btrfs-transacti:10227 blocked for 
more than 120 seconds.
[...]
This repeated several times while moving data over. Full log of one 
instance below.

I am using btrfs-progs v4.20.2 and debian stretch with 
4.19.0-0.bpo.2-amd64 (I think, this is the latest Kernel available in 
stretch. Please correct if I am wrong.

I understand that this was a 'timeout'. Is this caused by hardware?

In the SMART logs indeed, I see that errors happened (Full log below)
84 51 20 df 27 81 40  Error: ICRC, ABRT 32 sectors at LBA = 0x008127df = 
8464351
But this happened after 44h. I am now at 82h, so that was long before 
the error -infact during my 'burn-in test'.

Is this a case for an RMA of the drive?

Greetings,
Hendrik












[Mo Apr 29 20:44:47 2019] INFO: task btrfs-transacti:10227 blocked for 
more than 120 seconds.
[Mo Apr 29 20:44:47 2019]       Not tainted 4.19.0-0.bpo.2-amd64 #1 
Debian 4.19.16-1~bpo9+1
[Mo Apr 29 20:44:47 2019] "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Mo Apr 29 20:44:47 2019] btrfs-transacti D    0 10227      2 0x80000000
[Mo Apr 29 20:44:47 2019] Call Trace:
[Mo Apr 29 20:44:47 2019]  ? __schedule+0x3f5/0x880
[Mo Apr 29 20:44:47 2019]  schedule+0x32/0x80
[Mo Apr 29 20:44:47 2019]  wait_for_commit+0x41/0x80 [btrfs]
[Mo Apr 29 20:44:47 2019]  ? remove_wait_queue+0x60/0x60
[Mo Apr 29 20:44:47 2019]  btrfs_commit_transaction+0x10b/0x8a0 [btrfs]
[Mo Apr 29 20:44:47 2019]  ? start_transaction+0x8f/0x3e0 [btrfs]
[Mo Apr 29 20:44:47 2019]  transaction_kthread+0x157/0x180 [btrfs]
[Mo Apr 29 20:44:47 2019]  kthread+0xf8/0x130
[Mo Apr 29 20:44:47 2019]  ? btrfs_cleanup_transaction+0x500/0x500 
[btrfs]
[Mo Apr 29 20:44:47 2019]  ? kthread_create_worker_on_cpu+0x70/0x70
[Mo Apr 29 20:44:47 2019]  ret_from_fork+0x35/0x40
[Mo Apr 29 20:44:47 2019] INFO: task kworker/u4:8:10576 blocked for more 
than 120 seconds.
[Mo Apr 29 20:44:47 2019]       Not tainted 4.19.0-0.bpo.2-amd64 #1 
Debian 4.19.16-1~bpo9+1
[Mo Apr 29 20:44:47 2019] "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Mo Apr 29 20:44:47 2019] kworker/u4:8    D    0 10576      2 0x80000000
[Mo Apr 29 20:44:47 2019] Workqueue: events_unbound 
btrfs_async_reclaim_metadata_space [btrfs]
[Mo Apr 29 20:44:47 2019] Call Trace:
[Mo Apr 29 20:44:47 2019]  ? __schedule+0x3f5/0x880
[Mo Apr 29 20:44:47 2019]  schedule+0x32/0x80
[Mo Apr 29 20:44:47 2019]  wait_current_trans+0xb9/0xf0 [btrfs]
[Mo Apr 29 20:44:47 2019]  ? remove_wait_queue+0x60/0x60
[Mo Apr 29 20:44:47 2019]  start_transaction+0x201/0x3e0 [btrfs]
[Mo Apr 29 20:44:47 2019]  flush_space+0x14d/0x5e0 [btrfs]
[Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
[Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
[Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
[Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
[Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
[Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
[Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
[Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
[Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
[Mo Apr 29 20:44:47 2019]  ? get_alloc_profile+0x72/0x180 [btrfs]
[Mo Apr 29 20:44:47 2019]  ? can_overcommit.part.63+0x55/0xe0 [btrfs]
[Mo Apr 29 20:44:47 2019]  btrfs_async_reclaim_metadata_space+0xfb/0x4c0 
[btrfs]
[Mo Apr 29 20:44:47 2019]  process_one_work+0x191/0x370
[Mo Apr 29 20:44:47 2019]  worker_thread+0x4f/0x3b0
[Mo Apr 29 20:44:47 2019]  kthread+0xf8/0x130
[Mo Apr 29 20:44:47 2019]  ? rescuer_thread+0x340/0x340
[Mo Apr 29 20:44:47 2019]  ? kthread_create_worker_on_cpu+0x70/0x70
[Mo Apr 29 20:44:47 2019]  ret_from_fork+0x35/0x40





SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      
UPDATED  WHEN_FAILED RAW_VALUE
   1 Raw_Read_Error_Rate     0x000b   100   100   016    Pre-fail  Always 
       -       0
   2 Throughput_Performance  0x0004   128   128   054    Old_age   
Offline      -       116
   3 Spin_Up_Time            0x0007   198   198   024    Pre-fail  Always 
       -       349 (Average 317)
   4 Start_Stop_Count        0x0012   100   100   000    Old_age   Always 
       -       26
   5 Reallocated_Sector_Ct   0x0033   100   100   005    Pre-fail  Always 
       -       0
   7 Seek_Error_Rate         0x000a   100   100   067    Old_age   Always 
       -       0
   8 Seek_Time_Performance   0x0004   128   128   020    Old_age   
Offline      -       18
   9 Power_On_Hours          0x0012   100   100   000    Old_age   Always 
       -       82
  10 Spin_Retry_Count        0x0012   100   100   060    Old_age   Always 
       -       0
  12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always 
       -       26
  22 Helium_Level            0x0023   100   100   025    Pre-fail  Always 
       -       100
192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age   Always 
       -       27
193 Load_Cycle_Count        0x0012   100   100   000    Old_age   Always 
       -       27
194 Temperature_Celsius     0x0002   250   250   000    Old_age   Always 
       -       26 (Min/Max 24/55)
196 Reallocated_Event_Count 0x0032   100   100   000    Old_age   Always 
       -       0
197 Current_Pending_Sector  0x0022   100   100   000    Old_age   Always 
       -       0
198 Offline_Uncorrectable   0x0008   100   100   000    Old_age   
Offline      -       0
199 UDMA_CRC_Error_Count    0x000a   200   200   000    Old_age   Always 
       -       2

SMART Error Log Version: 1
ATA Error Count: 2
         CR = Command Register [HEX]
         FR = Features Register [HEX]
         SC = Sector Count Register [HEX]
         SN = Sector Number Register [HEX]
         CL = Cylinder Low Register [HEX]
         CH = Cylinder High Register [HEX]
         DH = Device/Head Register [HEX]
         DC = Device Command Register [HEX]
         ER = Error register [HEX]
         ST = Status register [HEX]
Powered_Up_Time is measured from power on, and printed as
DDd+hh:mm:SS.sss where DD=days, hh=hours, mm=minutes,
SS=sec, and sss=millisec. It "wraps" after 49.710 days.

Error 2 occurred at disk power-on lifetime: 44 hours (1 days + 20 hours)
   When the command that caused the error occurred, the device was doing 
SMART Offline or Self-test.

   After command completion occurred, registers were:
   ER ST SC SN CL CH DH
   -- -- -- -- -- -- --
   84 51 20 df 27 81 40  Error: ICRC, ABRT 32 sectors at LBA = 0x008127df 
= 8464351

   Commands leading to the command that caused the error were:
   CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
   -- -- -- -- -- -- -- --  ----------------  --------------------
   35 03 20 df 27 81 40 00      00:00:54.041  WRITE DMA EXT
   35 03 01 ff 27 81 40 00      00:00:54.040  WRITE DMA EXT
   25 03 20 02 00 00 40 00      00:00:54.040  READ DMA EXT
   25 03 20 02 00 00 40 00      00:00:54.040  READ DMA EXT
   25 03 01 af 2a 81 40 00      00:00:54.011  READ DMA EXT

Error 1 occurred at disk power-on lifetime: 44 hours (1 days + 20 hours)
   When the command that caused the error occurred, the device was doing 
SMART Offline or Self-test.

   After command completion occurred, registers were:
   ER ST SC SN CL CH DH
   -- -- -- -- -- -- --
   84 51 00 00 00 00 00

   Commands leading to the command that caused the error were:
   CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
   -- -- -- -- -- -- -- --  ----------------  --------------------
   47 00 01 00 00 00 a0 08      00:00:37.434  READ LOG DMA EXT
   47 00 01 13 00 00 a0 08      00:00:37.433  READ LOG DMA EXT
   47 00 01 00 00 00 a0 08      00:00:37.432  READ LOG DMA EXT
   ef 10 02 00 00 00 a0 08      00:00:37.430  SET FEATURES [Enable SATA 
feature]
   27 00 00 00 00 00 e0 08      00:00:37.427  READ NATIVE MAX ADDRESS EXT 
[OBS-ACS-3]

SMART Self-test log structure revision number 1
No self-tests have been logged.  [To run self-tests, use: smartctl -t]

SMART Selective self-test log data structure revision number 1
  SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
     1        0        0  Not_testing
     2        0        0  Not_testing
     3        0        0  Not_testing
     4        0        0  Not_testing
     5        0        0  Not_testing
Selective self-test flags (0x0):
   After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute 
delay.

Re: Rough (re)start with btrfs

[Chris Murphy]

On Wed, May 1, 2019 at 7:54 AM Hendrik Friedel <hendrik@friedels.name> wrote:
>
> Hello,
>
> as discussed in the other thread, I am migrating to BTRFS (again).
> Unfortunately, I had a bit of a rough start
> [Mo Apr 29 20:44:47 2019] INFO: task btrfs-transacti:10227 blocked for
> more than 120 seconds.
> [...]
> This repeated several times while moving data over. Full log of one
> instance below.
>
> I am using btrfs-progs v4.20.2 and debian stretch with
> 4.19.0-0.bpo.2-amd64 (I think, this is the latest Kernel available in
> stretch. Please correct if I am wrong.

What scheduler is being used for the drive?

# cat /sys/block/<dev>/queue/scheduler

If it's none, then kernel version and scheduler aren't likely related
to what you're seeing.

It's not immediately urgent, but I would still look for something
newer, just because the 4.19 series already has 37 upstream updates
released, each with dozens of fixes, easily there are over 1000 fixes
available in total. I'm not a Debian user but I think there's
stretch-backports that has newer kernels?
http://jensd.be/818/linux/install-a-newer-kernel-in-debian-9-stretch-stable



> [Mo Apr 29 20:44:47 2019] INFO: task btrfs-transacti:10227 blocked for
> more than 120 seconds.
> [Mo Apr 29 20:44:47 2019]       Not tainted 4.19.0-0.bpo.2-amd64 #1
> Debian 4.19.16-1~bpo9+1
> [Mo Apr 29 20:44:47 2019] "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mo Apr 29 20:44:47 2019] btrfs-transacti D    0 10227      2 0x80000000
> [Mo Apr 29 20:44:47 2019] Call Trace:
> [Mo Apr 29 20:44:47 2019]  ? __schedule+0x3f5/0x880
> [Mo Apr 29 20:44:47 2019]  schedule+0x32/0x80
> [Mo Apr 29 20:44:47 2019]  wait_for_commit+0x41/0x80 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? remove_wait_queue+0x60/0x60
> [Mo Apr 29 20:44:47 2019]  btrfs_commit_transaction+0x10b/0x8a0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? start_transaction+0x8f/0x3e0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  transaction_kthread+0x157/0x180 [btrfs]
> [Mo Apr 29 20:44:47 2019]  kthread+0xf8/0x130
> [Mo Apr 29 20:44:47 2019]  ? btrfs_cleanup_transaction+0x500/0x500
> [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? kthread_create_worker_on_cpu+0x70/0x70
> [Mo Apr 29 20:44:47 2019]  ret_from_fork+0x35/0x40
> [Mo Apr 29 20:44:47 2019] INFO: task kworker/u4:8:10576 blocked for more
> than 120 seconds.
> [Mo Apr 29 20:44:47 2019]       Not tainted 4.19.0-0.bpo.2-amd64 #1
> Debian 4.19.16-1~bpo9+1
> [Mo Apr 29 20:44:47 2019] "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mo Apr 29 20:44:47 2019] kworker/u4:8    D    0 10576      2 0x80000000
> [Mo Apr 29 20:44:47 2019] Workqueue: events_unbound
> btrfs_async_reclaim_metadata_space [btrfs]
> [Mo Apr 29 20:44:47 2019] Call Trace:
> [Mo Apr 29 20:44:47 2019]  ? __schedule+0x3f5/0x880
> [Mo Apr 29 20:44:47 2019]  schedule+0x32/0x80
> [Mo Apr 29 20:44:47 2019]  wait_current_trans+0xb9/0xf0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? remove_wait_queue+0x60/0x60
> [Mo Apr 29 20:44:47 2019]  start_transaction+0x201/0x3e0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  flush_space+0x14d/0x5e0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
> [Mo Apr 29 20:44:47 2019]  ? get_alloc_profile+0x72/0x180 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? can_overcommit.part.63+0x55/0xe0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  btrfs_async_reclaim_metadata_space+0xfb/0x4c0
> [btrfs]
> [Mo Apr 29 20:44:47 2019]  process_one_work+0x191/0x370
> [Mo Apr 29 20:44:47 2019]  worker_thread+0x4f/0x3b0
> [Mo Apr 29 20:44:47 2019]  kthread+0xf8/0x130
> [Mo Apr 29 20:44:47 2019]  ? rescuer_thread+0x340/0x340
> [Mo Apr 29 20:44:47 2019]  ? kthread_create_worker_on_cpu+0x70/0x70
> [Mo Apr 29 20:44:47 2019]  ret_from_fork+0x35/0x40

We need the entire dmesg so we can see if there are any earlier
complaints by the drive or the link. Can you attach the entire dmesg
as a file?

Also the output from

# smartctl -l gplog,0x13 /dev/sdX

If there's an error or it outputs nothing useful, then
# smarctl -x /dev/sdX

Also attach that as a file.

It's better if these things are file attachments, they're easier to
read, most MUAs do terrible line wraps.

-- 
Chris Murphy

Re: Rough (re)start with btrfs

[Qu Wenruo]

[-- Attachment #1.1: Type: text/plain, Size: 10406 bytes --]



On 2019/5/1 下午9:54, Hendrik Friedel wrote:
> Hello,
> 
> as discussed in the other thread, I am migrating to BTRFS (again).
> Unfortunately, I had a bit of a rough start
> [Mo Apr 29 20:44:47 2019] INFO: task btrfs-transacti:10227 blocked for
> more than 120 seconds.
> [...]
> This repeated several times while moving data over. Full log of one
> instance below.
> 
> I am using btrfs-progs v4.20.2 and debian stretch with
> 4.19.0-0.bpo.2-amd64 (I think, this is the latest Kernel available in
> stretch. Please correct if I am wrong.
> 
> I understand that this was a 'timeout'. Is this caused by hardware?

Transaction get blocked for 2 minutes, depends on the load, it can be
either normal or a dead lock.

Have you tried stop the workload, and see if the timeout disappears?

If it just disappear after some time, then it's the disk too slow and
too heavy load, combined with btrfs' low concurrency design leading to
the problem.

Thanks,
Qu

> 
> In the SMART logs indeed, I see that errors happened (Full log below)
> 84 51 20 df 27 81 40  Error: ICRC, ABRT 32 sectors at LBA = 0x008127df =
> 8464351
> But this happened after 44h. I am now at 82h, so that was long before
> the error -infact during my 'burn-in test'.
> 
> Is this a case for an RMA of the drive?
> 
> Greetings,
> Hendrik
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> [Mo Apr 29 20:44:47 2019] INFO: task btrfs-transacti:10227 blocked for
> more than 120 seconds.
> [Mo Apr 29 20:44:47 2019]       Not tainted 4.19.0-0.bpo.2-amd64 #1
> Debian 4.19.16-1~bpo9+1
> [Mo Apr 29 20:44:47 2019] "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mo Apr 29 20:44:47 2019] btrfs-transacti D    0 10227      2 0x80000000
> [Mo Apr 29 20:44:47 2019] Call Trace:
> [Mo Apr 29 20:44:47 2019]  ? __schedule+0x3f5/0x880
> [Mo Apr 29 20:44:47 2019]  schedule+0x32/0x80
> [Mo Apr 29 20:44:47 2019]  wait_for_commit+0x41/0x80 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? remove_wait_queue+0x60/0x60
> [Mo Apr 29 20:44:47 2019]  btrfs_commit_transaction+0x10b/0x8a0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? start_transaction+0x8f/0x3e0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  transaction_kthread+0x157/0x180 [btrfs]
> [Mo Apr 29 20:44:47 2019]  kthread+0xf8/0x130
> [Mo Apr 29 20:44:47 2019]  ? btrfs_cleanup_transaction+0x500/0x500 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? kthread_create_worker_on_cpu+0x70/0x70
> [Mo Apr 29 20:44:47 2019]  ret_from_fork+0x35/0x40
> [Mo Apr 29 20:44:47 2019] INFO: task kworker/u4:8:10576 blocked for more
> than 120 seconds.
> [Mo Apr 29 20:44:47 2019]       Not tainted 4.19.0-0.bpo.2-amd64 #1
> Debian 4.19.16-1~bpo9+1
> [Mo Apr 29 20:44:47 2019] "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [Mo Apr 29 20:44:47 2019] kworker/u4:8    D    0 10576      2 0x80000000
> [Mo Apr 29 20:44:47 2019] Workqueue: events_unbound
> btrfs_async_reclaim_metadata_space [btrfs]
> [Mo Apr 29 20:44:47 2019] Call Trace:
> [Mo Apr 29 20:44:47 2019]  ? __schedule+0x3f5/0x880
> [Mo Apr 29 20:44:47 2019]  schedule+0x32/0x80
> [Mo Apr 29 20:44:47 2019]  wait_current_trans+0xb9/0xf0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? remove_wait_queue+0x60/0x60
> [Mo Apr 29 20:44:47 2019]  start_transaction+0x201/0x3e0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  flush_space+0x14d/0x5e0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x34/0x70
> [Mo Apr 29 20:44:47 2019]  ? __switch_to_asm+0x40/0x70
> [Mo Apr 29 20:44:47 2019]  ? get_alloc_profile+0x72/0x180 [btrfs]
> [Mo Apr 29 20:44:47 2019]  ? can_overcommit.part.63+0x55/0xe0 [btrfs]
> [Mo Apr 29 20:44:47 2019]  btrfs_async_reclaim_metadata_space+0xfb/0x4c0
> [btrfs]
> [Mo Apr 29 20:44:47 2019]  process_one_work+0x191/0x370
> [Mo Apr 29 20:44:47 2019]  worker_thread+0x4f/0x3b0
> [Mo Apr 29 20:44:47 2019]  kthread+0xf8/0x130
> [Mo Apr 29 20:44:47 2019]  ? rescuer_thread+0x340/0x340
> [Mo Apr 29 20:44:47 2019]  ? kthread_create_worker_on_cpu+0x70/0x70
> [Mo Apr 29 20:44:47 2019]  ret_from_fork+0x35/0x40
> 
> 
> 
> 
> 
> SMART Attributes Data Structure revision number: 16
> Vendor Specific SMART Attributes with Thresholds:
> ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE     
> UPDATED  WHEN_FAILED RAW_VALUE
>   1 Raw_Read_Error_Rate     0x000b   100   100   016    Pre-fail  Always
>       -       0
>   2 Throughput_Performance  0x0004   128   128   054    Old_age  
> Offline      -       116
>   3 Spin_Up_Time            0x0007   198   198   024    Pre-fail  Always
>       -       349 (Average 317)
>   4 Start_Stop_Count        0x0012   100   100   000    Old_age   Always
>       -       26
>   5 Reallocated_Sector_Ct   0x0033   100   100   005    Pre-fail  Always
>       -       0
>   7 Seek_Error_Rate         0x000a   100   100   067    Old_age   Always
>       -       0
>   8 Seek_Time_Performance   0x0004   128   128   020    Old_age  
> Offline      -       18
>   9 Power_On_Hours          0x0012   100   100   000    Old_age   Always
>       -       82
>  10 Spin_Retry_Count        0x0012   100   100   060    Old_age   Always
>       -       0
>  12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always
>       -       26
>  22 Helium_Level            0x0023   100   100   025    Pre-fail  Always
>       -       100
> 192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age   Always
>       -       27
> 193 Load_Cycle_Count        0x0012   100   100   000    Old_age   Always
>       -       27
> 194 Temperature_Celsius     0x0002   250   250   000    Old_age   Always
>       -       26 (Min/Max 24/55)
> 196 Reallocated_Event_Count 0x0032   100   100   000    Old_age   Always
>       -       0
> 197 Current_Pending_Sector  0x0022   100   100   000    Old_age   Always
>       -       0
> 198 Offline_Uncorrectable   0x0008   100   100   000    Old_age  
> Offline      -       0
> 199 UDMA_CRC_Error_Count    0x000a   200   200   000    Old_age   Always
>       -       2
> 
> SMART Error Log Version: 1
> ATA Error Count: 2
>         CR = Command Register [HEX]
>         FR = Features Register [HEX]
>         SC = Sector Count Register [HEX]
>         SN = Sector Number Register [HEX]
>         CL = Cylinder Low Register [HEX]
>         CH = Cylinder High Register [HEX]
>         DH = Device/Head Register [HEX]
>         DC = Device Command Register [HEX]
>         ER = Error register [HEX]
>         ST = Status register [HEX]
> Powered_Up_Time is measured from power on, and printed as
> DDd+hh:mm:SS.sss where DD=days, hh=hours, mm=minutes,
> SS=sec, and sss=millisec. It "wraps" after 49.710 days.
> 
> Error 2 occurred at disk power-on lifetime: 44 hours (1 days + 20 hours)
>   When the command that caused the error occurred, the device was doing
> SMART Offline or Self-test.
> 
>   After command completion occurred, registers were:
>   ER ST SC SN CL CH DH
>   -- -- -- -- -- -- --
>   84 51 20 df 27 81 40  Error: ICRC, ABRT 32 sectors at LBA = 0x008127df
> = 8464351
> 
>   Commands leading to the command that caused the error were:
>   CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
>   -- -- -- -- -- -- -- --  ----------------  --------------------
>   35 03 20 df 27 81 40 00      00:00:54.041  WRITE DMA EXT
>   35 03 01 ff 27 81 40 00      00:00:54.040  WRITE DMA EXT
>   25 03 20 02 00 00 40 00      00:00:54.040  READ DMA EXT
>   25 03 20 02 00 00 40 00      00:00:54.040  READ DMA EXT
>   25 03 01 af 2a 81 40 00      00:00:54.011  READ DMA EXT
> 
> Error 1 occurred at disk power-on lifetime: 44 hours (1 days + 20 hours)
>   When the command that caused the error occurred, the device was doing
> SMART Offline or Self-test.
> 
>   After command completion occurred, registers were:
>   ER ST SC SN CL CH DH
>   -- -- -- -- -- -- --
>   84 51 00 00 00 00 00
> 
>   Commands leading to the command that caused the error were:
>   CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
>   -- -- -- -- -- -- -- --  ----------------  --------------------
>   47 00 01 00 00 00 a0 08      00:00:37.434  READ LOG DMA EXT
>   47 00 01 13 00 00 a0 08      00:00:37.433  READ LOG DMA EXT
>   47 00 01 00 00 00 a0 08      00:00:37.432  READ LOG DMA EXT
>   ef 10 02 00 00 00 a0 08      00:00:37.430  SET FEATURES [Enable SATA
> feature]
>   27 00 00 00 00 00 e0 08      00:00:37.427  READ NATIVE MAX ADDRESS EXT
> [OBS-ACS-3]
> 
> SMART Self-test log structure revision number 1
> No self-tests have been logged.  [To run self-tests, use: smartctl -t]
> 
> SMART Selective self-test log data structure revision number 1
>  SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
>     1        0        0  Not_testing
>     2        0        0  Not_testing
>     3        0        0  Not_testing
>     4        0        0  Not_testing
>     5        0        0  Not_testing
> Selective self-test flags (0x0):
>   After scanning selected spans, do NOT read-scan remainder of disk.
> If Selective self-test is pending on power-up, resume after 0 minute delay.
> 


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]