* Rough (re)start with btrfs
@ 2019-05-01 13:54 Hendrik Friedel
2019-05-02 0:12 ` Chris Murphy
2019-05-02 3:01 ` Qu Wenruo
0 siblings, 2 replies; 6+ messages in thread
From: Hendrik Friedel @ 2019-05-01 13:54 UTC (permalink / raw)
To: linux-btrfs
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.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Rough (re)start with btrfs
2019-05-01 13:54 Rough (re)start with btrfs Hendrik Friedel
@ 2019-05-02 0:12 ` Chris Murphy
2019-05-02 3:01 ` Qu Wenruo
1 sibling, 0 replies; 6+ messages in thread
From: Chris Murphy @ 2019-05-02 0:12 UTC (permalink / raw)
To: Hendrik Friedel, Btrfs BTRFS
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
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Rough (re)start with btrfs
2019-05-01 13:54 Rough (re)start with btrfs Hendrik Friedel
2019-05-02 0:12 ` Chris Murphy
@ 2019-05-02 3:01 ` Qu Wenruo
1 sibling, 0 replies; 6+ messages in thread
From: Qu Wenruo @ 2019-05-02 3:01 UTC (permalink / raw)
To: Hendrik Friedel, linux-btrfs
[-- 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 --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Rough (re)start with btrfs
2019-05-03 5:41 ` Re[2]: " Hendrik Friedel
@ 2019-05-03 7:34 ` Qu Wenruo
0 siblings, 0 replies; 6+ messages in thread
From: Qu Wenruo @ 2019-05-03 7:34 UTC (permalink / raw)
To: Hendrik Friedel, Chris Murphy, Btrfs BTRFS
[-- 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 --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Rough (re)start with btrfs
2019-05-02 23:40 ` Qu Wenruo
2019-05-03 5:41 ` Re[2]: " Hendrik Friedel
@ 2019-05-03 5:58 ` Chris Murphy
1 sibling, 0 replies; 6+ messages in thread
From: Chris Murphy @ 2019-05-03 5:58 UTC (permalink / raw)
To: Qu Wenruo; +Cc: Hendrik Friedel, Chris Murphy, Btrfs BTRFS
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
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Rough (re)start with btrfs
[not found] <em9eba60a7-2c0d-4399-8712-c134f0f50d4d@ryzen>
@ 2019-05-02 23:40 ` Qu Wenruo
2019-05-03 5:41 ` Re[2]: " Hendrik Friedel
2019-05-03 5:58 ` Chris Murphy
0 siblings, 2 replies; 6+ messages in thread
From: Qu Wenruo @ 2019-05-02 23:40 UTC (permalink / raw)
To: Hendrik Friedel, Chris Murphy, Btrfs BTRFS
[-- 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 --]
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2019-05-03 7:34 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-05-01 13:54 Rough (re)start with btrfs Hendrik Friedel
2019-05-02 0:12 ` Chris Murphy
2019-05-02 3:01 ` Qu Wenruo
[not found] <em9eba60a7-2c0d-4399-8712-c134f0f50d4d@ryzen>
2019-05-02 23:40 ` Qu Wenruo
2019-05-03 5:41 ` Re[2]: " Hendrik Friedel
2019-05-03 7:34 ` Qu Wenruo
2019-05-03 5:58 ` Chris Murphy
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.