Hang when trying to access fs

Hello,

When trying to rsync to btrfs, the process just hangs. dmesg output alternates between:

Jan 28 09:42:49 vostro kernel: [  360.460076] INFO: task rsync:3484 blo=
cked for more than 120 seconds.
Jan 28 09:42:49 vostro kernel: [  360.460079] "echo 0 > /proc/sys/kerne=
l/hung_task_timeout_secs" disables this message.
Jan 28 09:42:49 vostro kernel: [  360.460081] rsync           D ffff880=
09d8d7850     0  3484      1 0x00000004
Jan 28 09:42:49 vostro kernel: [  360.460085]  ffff88009d8d7850 0000000=
000000082 0000000000000000 ffff88009b4d1810
Jan 28 09:42:49 vostro kernel: [  360.460089]  0000000000012f40 ffff880=
092361fd8 ffff880092361fd8 ffff88009d8d7850
Jan 28 09:42:49 vostro kernel: [  360.460092]  0000000000000246 fffffff=
f8132de1c ffff88009b5342f0 ffff880094051e80
Jan 28 09:42:49 vostro kernel: [  360.460096] Call Trace:
Jan 28 09:42:49 vostro kernel: [  360.460102]  [<ffffffff8132de1c>] ? _=
raw_spin_lock_irqsave+0x9/0x25
Jan 28 09:42:49 vostro kernel: [  360.460118]  [<ffffffffa05afd19>] ? w=
ait_current_trans.isra.22+0xae/0xdd [btrfs]
Jan 28 09:42:49 vostro kernel: [  360.460122]  [<ffffffff8105ec6b>] ? a=
dd_wait_queue+0x3c/0x3c
Jan 28 09:42:49 vostro kernel: [  360.460132]  [<ffffffffa05b0f82>] ? s=
tart_transaction+0x231/0x246 [btrfs]
Jan 28 09:42:49 vostro kernel: [  360.460144]  [<ffffffffa05b9772>] ? b=
trfs_dirty_inode+0x23/0x11d [btrfs]
Jan 28 09:42:49 vostro kernel: [  360.460148]  [<ffffffff8111001c>] ? _=
_mark_inode_dirty+0x22/0x17a
Jan 28 09:42:49 vostro kernel: [  360.460159]  [<ffffffffa05b891e>] ? b=
trfs_setattr+0x6d/0x92 [btrfs]
Jan 28 09:42:49 vostro kernel: [  360.460162]  [<ffffffff81107642>] ? n=
otify_change+0x18e/0x256
Jan 28 09:42:49 vostro kernel: [  360.460165]  [<ffffffff810353a7>] ? s=
hould_resched+0x5/0x23
Jan 28 09:42:49 vostro kernel: [  360.460168]  [<ffffffff81114930>] ? u=
times_common+0x10c/0x135
Jan 28 09:42:49 vostro kernel: [  360.460170]  [<ffffffff81114a14>] ? d=
o_utimes+0xbb/0xd6
Jan 28 09:42:49 vostro kernel: [  360.460173]  [<ffffffff810f779c>] ? s=
ys_newlstat+0x23/0x2b
Jan 28 09:42:49 vostro kernel: [  360.460175]  [<ffffffff810353a7>] ? s=
hould_resched+0x5/0x23
Jan 28 09:42:49 vostro kernel: [  360.460178]  [<ffffffff81114b1a>] ? s=
ys_utimensat+0x6e/0x77
Jan 28 09:42:49 vostro kernel: [  360.460181]  [<ffffffff81332e12>] ? s=

ystem_call_fastpath+0x16/0x1b

and

Jan 28 09:42:49 vostro kernel: [  360.460184] INFO: task rsync:3495 blo=
cked for more than 120 seconds.
Jan 28 09:42:49 vostro kernel: [  360.460185] "echo 0 > /proc/sys/kerne=
l/hung_task_timeout_secs" disables this message.
Jan 28 09:42:49 vostro kernel: [  360.460186] rsync           D ffff880=
0bfc92f40     0  3495      1 0x00000004
Jan 28 09:42:49 vostro kernel: [  360.460189]  ffff88009b4c47f0 0000000=
000000086 ffff880000000000 ffff8800bbf080c0
Jan 28 09:42:49 vostro kernel: [  360.460192]  0000000000012f40 ffff880=
091ff1fd8 ffff880091ff1fd8 ffff88009b4c47f0
Jan 28 09:42:49 vostro kernel: [  360.460196]  0000000000000000 0000000=
1bff5b700 ffffffff8102f71b ffff880094060a20
Jan 28 09:42:49 vostro kernel: [  360.460199] Call Trace:
Jan 28 09:42:49 vostro kernel: [  360.460202]  [<ffffffff8102f71b>] ? p=
te_alloc_one+0x2f/0x39
Jan 28 09:42:49 vostro kernel: [  360.460205]  [<ffffffff8132d437>] ? _=
_mutex_lock_common.isra.6+0xff/0x164
Jan 28 09:42:49 vostro kernel: [  360.460209]  [<ffffffff810cada2>] ? c=
opy_pte_range+0x34d/0x391
Jan 28 09:42:49 vostro kernel: [  360.460211]  [<ffffffff8132d325>] ? m=
utex_lock+0x1a/0x2d
Jan 28 09:42:49 vostro kernel: [  360.460214]  [<ffffffff810fcb6d>] ? w=
alk_component+0x1f4/0x406
Jan 28 09:42:49 vostro kernel: [  360.460217]  [<ffffffff8102f999>] ? p=
tep_set_access_flags+0x39/0x45
Jan 28 09:42:49 vostro kernel: [  360.460219]  [<ffffffff810fd9c1>] ? p=
ath_lookupat+0x7c/0x29e
Jan 28 09:42:49 vostro kernel: [  360.460222]  [<ffffffff810353a7>] ? s=
hould_resched+0x5/0x23
Jan 28 09:42:49 vostro kernel: [  360.460224]  [<ffffffff8132cb37>] ? _=
cond_resched+0x7/0x1c
Jan 28 09:42:49 vostro kernel: [  360.460227]  [<ffffffff810fdbff>] ? d=
o_path_lookup+0x1c/0x87
Jan 28 09:42:49 vostro kernel: [  360.460229]  [<ffffffff810ff47a>] ? u=
ser_path_at_empty+0x47/0x7b
Jan 28 09:42:49 vostro kernel: [  360.460232]  [<ffffffff81330dea>] ? d=
o_page_fault+0x2fc/0x337
Jan 28 09:42:49 vostro kernel: [  360.460234]  [<ffffffff810f7636>] ? v=
fs_fstatat+0x32/0x60
Jan 28 09:42:49 vostro kernel: [  360.460236]  [<ffffffff810f778b>] ? s=
ys_newlstat+0x12/0x2b
Jan 28 09:42:49 vostro kernel: [  360.460239]  [<ffffffff810353a7>] ? s=
hould_resched+0x5/0x23
Jan 28 09:42:49 vostro kernel: [  360.460241]  [<ffffffff8132e435>] ? p=
age_fault+0x25/0x30
Jan 28 09:42:49 vostro kernel: [  360.460244]  [<ffffffff81332e12>] ? s=

ystem_call_fastpath+0x16/0x1b

Kernel is 3.1.0. I'm writing to a 500 GB external USB disk.

Known bug? If not, anything I can do to help?

Best,

-Nikolaus

--=20
=C2=BBTime flies like an arrow, fruit flies like a Banana.=C2=AB

PGP fingerprint: 5B93 61F8 4EA2 E279 ABF6 02CF A9AD B7F8 AE4E 425C
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" = in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

[...]

I guess I should also mention that this is reproducible, and I don't even need to run rsync. Simply mounting the file system produces a similar warning soon afterwards:

[  678.316046] usb 1-4: new high speed USB device number 7 using ehci_h=
cd
[  678.448928] usb 1-4: New USB device found, idVendor=3D152d, idProduc=
t=3D2509
[  678.448931] usb 1-4: New USB device strings: Mfr=3D10, Product=3D11,=
 SerialNumber=3D3
[  678.448933] usb 1-4: Product: Usb production
[  678.448934] usb 1-4: Manufacturer: Jmicron Corp.
[  678.448936] usb 1-4: SerialNumber: 00A123456789
[  678.450429] scsi7 : usb-storage 1-4:1.0
[  681.372710] scsi 7:0:0:0: Direct-Access     WDC WD50 01AALS-00L3B2  =
  0000 PQ: 0 ANSI: 2 CCS
[  681.658185] sd 7:0:0:0: [sdg] 976773168 512-byte logical blocks: (50=
0 GB/465 GiB)
[  681.658925] sd 7:0:0:0: [sdg] Write Protect is off
[  681.658929] sd 7:0:0:0: [sdg] Mode Sense: 28 00 00 00
[  681.659675] sd 7:0:0:0: [sdg] No Caching mode page present
[  681.659679] sd 7:0:0:0: [sdg] Assuming drive cache: write through
[  681.662049] sd 7:0:0:0: [sdg] No Caching mode page present
[  681.662052] sd 7:0:0:0: [sdg] Assuming drive cache: write through
[  681.670316]  sdg: sdg1
[  681.673554] sd 7:0:0:0: [sdg] No Caching mode page present
[  681.673558] sd 7:0:0:0: [sdg] Assuming drive cache: write through
[  681.673562] sd 7:0:0:0: [sdg] Attached SCSI disk
[  791.512475] Btrfs loaded
[  791.513625] device label Videos devid 1 transid 142 /dev/mapper/udis=
ks-luks-uuid-7adf0c16-c741-485e-86dd-8a209fe4ce85-uid1000
[  791.567843] btrfs: disk space caching is enabled
[  960.456073] INFO: task sync:4930 blocked for more than 120 seconds.
[  960.456077] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disab=
les this message.
[  960.456080] sync            D ffff8800bfc92f40     0  4930      1 0x=
00000000
[  960.456085]  ffff88009f4d5790 0000000000000082 0000000000000000 ffff=
8800bbf080c0
[  960.456089]  0000000000012f40 ffff88009f4d7fd8 ffff88009f4d7fd8 ffff=
88009f4d5790
[  960.456094]  0000000000000246 000000018132de1c ffff880091d342f0 ffff=
88008686ae80
[  960.456098] Call Trace:
[  960.456117]  [<ffffffffa05aed19>] ? wait_current_trans.isra.22+0xae/=
0xdd [btrfs]
[  960.456123]  [<ffffffff8105ec6b>] ? add_wait_queue+0x3c/0x3c
[  960.456137]  [<ffffffffa05aff82>] ? start_transaction+0x231/0x246 [b=
trfs]
[  960.456141]  [<ffffffff81114543>] ? __sync_filesystem+0x6e/0x6e
[  960.456150]  [<ffffffffa0594357>] ? btrfs_sync_fs+0x79/0x95 [btrfs]
[  960.456153]  [<ffffffff8111452b>] ? __sync_filesystem+0x56/0x6e
[  960.456157]  [<ffffffff810f6578>] ? iterate_supers+0x5e/0xab
[  960.456160]  [<ffffffff811145cd>] ? sys_sync+0x3d/0x52
[  960.456164]  [<ffffffff81332e12>] ? system_call_fastpath+0x16/0x1b

Best,

-Nikolaus

--=20
=C2=BBTime flies like an arrow, fruit flies like a Banana.=C2=AB

PGP fingerprint: 5B93 61F8 4EA2 E279 ABF6 02CF A9AD B7F8 AE4E 425C
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" = in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Nikolaus Rath posted on Sat, 28 Jan 2012 10:23:53 -0500 as excerpted:

ehci_hcd

Two points, based on the wiki at: https://btrfs.wiki.kernel.org/

1) In the first post you mention kernel 3.1. Here's what the wiki has to say about kernel versions right at the top of the "Getting started" page:

btrfs is a fast-moving target. There are typically a great many bug fixes and enhancements between one kernel release and the next. Therefore:

** If you have btrfs filesystems, run the latest kernel.

If you are running a kernel two or more versions behind the latest one available from kernel.org, the first thing you will be asked to when you report a problem is to upgrade to the latest kernel.
<<<<<

It goes on to mention the userspace tools as well. Note that the last btrfs-tools release version, (0.19 IIRC), is from (IIRC) 2010. You REALLY want to be running a recently rebuilt live-git btrfs-tools build.

Elsewhere (I don't see the reference ATM) I believe I saw a recommendation to run the rc kernels as well (tho you might wish to wait until rc 3 or 4 just to be sure, I personally run git kernels but don't normally update during the merge window, so not until after rc1), for much the same reason -- they'll have fixes before a stable kernel will.

Given that we're past 3.3-rc1 at this point and there's been a couple 3.2- stable updates, you really should be running at LEAST 3.2 stable, if not 3.3-rc1+. 3.1 is really a bit old, given that btrfs really /is/ still in heavy development.

2) I saw that /dev/mapper/udisks-luks-* message in the log and it reminded me of the following from the wiki gotchas page. I don't run encryption here and thus haven't sorted out all the various encryption setups and don't know if luks is dm-crypt or something else, but it may apply regardless. If you've had a power outage or unplugged without umounting, you're likely corrupted, and that's what's triggering your issue, since there's no indication that write-caching is turned off in the log you posted (tho it may not register in the log, I'll grant).

btrfs volumes on top of dm-crypt block devices (and possibly LVM) require write-caching to be turned off on the underlying HDD. Failing to do so, in the event of a power failure, may result in corruption not yet handled by btrfs code. (2.6.33)
<<<<<

Despite the above warning, it may be that the first procedure listed at the top of the problem FAQ, zeroing out the log, may help, altho it's not clear from your post whether it actually mounted, or not. You can try it. There's also a note about the zero-log procedure in the (main) FAQ, under "Is btrfs stable", "Pragmantic, personal and anecdotal answer", which states (as of 2011-08-21):

In the last few months, the vast majority of the problems with broken and unmountable filesystems I've seen on IRC and the mailing list have been caused by power outages in the middle of a write to the FS, and have been fixable by use of the btrfs-zero-log tool.
<<<<<

But I'm not sure if that overrides the caveat on dm-crypt or if that has been fixed by now, since the dm-crypt note is from ~2010 since it mentions 2.6.33.

You can also try mounting read-only, which I found mentioned as a hint somewhere, as well, and there's a newer tool (that I don't see covered on the wiki, I read about it elsewhere) that will often let you at least copy the data out of a bad btrfs partition, if it's necessary. That might allow you to get the data off, at least, if you don't have proper backups, which you DEFINITELY should have, given that btrfs is still experimental and under rapid development.

Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman

s.

[...]

t=20

d on=20

=20

er=20

There's no important data on the drive, and I have no personal interest in getting this to work or debugging it further. I just wanted to repor= t
this in case someone else would like to figure out what might be going on here (in which case I'd be willing to assist).

Sorry if my mail gave the wrong impression. I meant to offer help if that's an unknown bug, I didn't mean to ask for help :-).

Best,

-Nikolaus

--=20
=C2=BBTime flies like an arrow, fruit flies like a Banana.=C2=AB

PGP fingerprint: 5B93 61F8 4EA2 E279 ABF6 02CF A9AD B7F8 AE4E 425C
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" = in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Nikolaus Rath posted on Sat, 28 Jan 2012 23:07:20 -0500 as excerpted:

NP! I'm just so used to interpreting posts as requests for help on the other lists I'm on, that in the absence of explicit wording to the contrary, I tend to do that here (where I know rather less about the topic, at least at this point, I'm learning) as well.

It's all good! =:^)

Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman