# Concerned about new BTRFS 3.12-dirty Kernel Messages

## splurben

Running Gentoo AMD64 on a Testing System

These are appearing three or four times a day, and I have analysed them over and over and I can’t figure out which device or filesystem is generating them.

I recently lost a device on the RAID10 labelled thialfi2, I’m waiting for a replacement spare. But “btrfs --repair” and “btrfs filesystem scrub” return no errors on all filesystems. The filesystem labelled mounted at “/mnt/archive” is on a USB external drive.

It’s possible these are just verbose debugging info that don’t matter, but I’d like to make sure.

```
# btrfs version

Btrfs v3.12-dirty
```

```
Linux thialfi2 3.13.9-gentoo #1 SMP Fri Apr 4 20:36:40 WST 2014 x86_64 Intel(R) Core(TM) i7 CPU 950 @ 3.07GHz GenuineIntel GNU/Linux
```

```
# eselect profile list

…

  [1]   default/linux/amd64/13.0 *

…
```

```
# grep -i btrfs /etc/fstab

UUID="ce967be5-dc72-473f-b7c5-2c8a0bad895f"     /               btrfs   defaults,noatime,discard,ssd,compress=lzo   0 1

LABEL="thialfi2"                                /mnt/THIALFI2   btrfs   defaults,nodiratime,noatime,compress=lzo    1 2

UUID="123e3aad-a9cd-48c0-858b-c13c5c57aba1"     /mnt/archive    btrfs   defaults,nodiratime,noatime,compress=lzo    1 2
```

```
# blkid | grep -i btrfs

/dev/sda4: UUID="ce967be5-dc72-473f-b7c5-2c8a0bad895f" UUID_SUB="352cabd5-cc50-4f25-9854-bb906d64f559" TYPE="btrfs" PARTLABEL="ssdThialfi2Root" PARTUUID="dfb522a7-754d-47ba-a311-cc4c117853c2" 

/dev/sdc: LABEL="thialfi2" UUID="320ccc9e-1e84-4765-acfb-3a88d6aa8de8" UUID_SUB="1b82c8ab-1774-4fc4-bbf4-7627332bbae4" TYPE="btrfs" 

/dev/sdd: LABEL="thialfi2" UUID="320ccc9e-1e84-4765-acfb-3a88d6aa8de8" UUID_SUB="c4acc57f-b069-400f-837a-16b945a2f600" TYPE="btrfs" 

/dev/sde: LABEL="thialfi2" UUID="320ccc9e-1e84-4765-acfb-3a88d6aa8de8" UUID_SUB="f99caaf0-c5f0-4d2c-b976-f8da6ef0f0c1" TYPE="btrfs" 

/dev/sdf: LABEL="thialfi2" UUID="320ccc9e-1e84-4765-acfb-3a88d6aa8de8" UUID_SUB="33f13c09-a2c7-40a6-982e-288b1ecad7ce" TYPE="btrfs" 

/dev/sdg: UUID="123e3aad-a9cd-48c0-858b-c13c5c57aba1" UUID_SUB="f0564dcc-c30e-4449-a2bf-70ee448095b5" TYPE="btrfs"
```

```
# btrfs filesystem show

Label: none  uuid: ce967be5-dc72-473f-b7c5-2c8a0bad895f

   Total devices 1 FS bytes used 38.91GiB

   devid    1 size 102.04GiB used 102.04GiB path /dev/sda4

Label: thialfi2  uuid: 320ccc9e-1e84-4765-acfb-3a88d6aa8de8

   Total devices 4 FS bytes used 2.26TiB

   devid    1 size 1.36TiB used 1.13TiB path /dev/sdc

   devid    2 size 1.36TiB used 1.13TiB path /dev/sdd

   devid    4 size 1.36TiB used 1.13TiB path /dev/sdf

   devid    5 size 1.82TiB used 1.13TiB path /dev/sde

Label: none  uuid: 123e3aad-a9cd-48c0-858b-c13c5c57aba1

   Total devices 1 FS bytes used 959.39GiB

   devid    1 size 1.82TiB used 1.81TiB path /dev/sdg
```

emerge --info http://pastebin.com/b32gRzPn

Output from DMESG:

```
[38225.642922] INFO: task cnid_dbd:5358 blocked for more than 120 seconds.

[38225.642925]       Tainted: P          IO 3.13.9-gentoo #1

[38225.642927] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[38225.642928] cnid_dbd        D 0000000000000002     0  5358   3223 0x00000000

[38225.642933]  ffff880139f519f8 0000000000000082 ffff880139f51fd8 ffff880390d5f120

[38225.642936]  0000000000011900 ffff880390d5f120 ffff880418e9fe30 0000000000000003

[38225.642939]  0000000000000000 0000000000000000 0000000000000001 ffff880139f51960

[38225.642943] Call Trace:

[38225.642950]  [<ffffffff81082b31>] ? default_wake_function+0xd/0xf

[38225.642955]  [<ffffffff8108e02b>] ? autoremove_wake_function+0xd/0x2f

[38225.642958]  [<ffffffff8108daa8>] ? __wake_up_common+0x51/0x7e

[38225.642963]  [<ffffffff814c8472>] schedule+0x6a/0x6c

[38225.642967]  [<ffffffff81208370>] wait_for_commit.isra.18+0x4e/0x65

[38225.642970]  [<ffffffff8108e01e>] ? __wake_up_sync+0xd/0xd

[38225.642973]  [<ffffffff81208ec9>] btrfs_commit_transaction+0x133/0x7f9

[38225.642975]  [<ffffffff812098cd>] ? start_transaction+0x33e/0x45c

[38225.642980]  [<ffffffff811f6a40>] reserve_metadata_bytes+0x61f/0x6fd

[38225.642983]  [<ffffffff814ca1f1>] ? mutex_unlock+0x9/0xb

[38225.642986]  [<ffffffff811f6e8e>] btrfs_block_rsv_add+0x1b/0x3b

[38225.642988]  [<ffffffff812096e4>] start_transaction+0x155/0x45c

[38225.642991]  [<ffffffff81209a01>] btrfs_start_transaction+0x16/0x18

[38225.642995]  [<ffffffff8120dd16>] btrfs_dirty_inode+0x60/0xa4

[38225.642997]  [<ffffffff8120dde6>] btrfs_update_time+0x8c/0x9a

[38225.643002]  [<ffffffff8112a9d7>] update_time+0x1e/0xa2

[38225.643005]  [<ffffffff8112abff>] file_update_time+0x8f/0xad

[38225.643008]  [<ffffffff81214b68>] btrfs_page_mkwrite+0x68/0x2cc

[38225.643011]  [<ffffffff810eab30>] do_wp_page+0x1da/0x74b

[38225.643016]  [<ffffffff814691a1>] ? inet_recvmsg+0x6b/0x7a

[38225.643019]  [<ffffffff810ed93e>] handle_mm_fault+0x91c/0xb35

[38225.643023]  [<ffffffff81059d39>] __do_page_fault+0x2b9/0x41a

[38225.643027]  [<ffffffff814069a7>] ? SyS_recvfrom+0xe4/0x144

[38225.643032]  [<ffffffff8106e586>] ? __set_current_blocked+0x31/0x4c

[38225.643034]  [<ffffffff8106e6c1>] ? sigprocmask+0x5b/0x5f

[38225.643038]  [<ffffffff811265d8>] ? SyS_pselect6+0x18c/0x1a7

[38225.643043]  [<ffffffff81059ec2>] do_page_fault+0x9/0xb

[38225.643045]  [<ffffffff814cbb48>] page_fault+0x28/0x30

[38225.643049] INFO: task nmbd:16302 blocked for more than 120 seconds.

[38225.643049]       Tainted: P          IO 3.13.9-gentoo #1

[38225.643050] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[38225.643051] nmbd            D 0000000000000004     0 16302   3501 0x00000000

[38225.643052]  ffff880044b5bc68 0000000000000082 ffff880044b5bfd8 ffff880120540690

[38225.643054]  0000000000011900 ffff880120540690 0000000000000003 ffff88042ffcbb00

[38225.643055]  0000000000000002 0000000000000000 ffff880044b5bcd0 ffffffff810d56c3

[38225.643057] Call Trace:

[38225.643059]  [<ffffffff810d56c3>] ? __alloc_pages_nodemask+0x147/0x7fd

[38225.643061]  [<ffffffff814c8472>] schedule+0x6a/0x6c

[38225.643062]  [<ffffffff814c8731>] schedule_preempt_disabled+0x9/0xb

[38225.643064]  [<ffffffff814ca3d0>] __mutex_lock_slowpath+0x167/0x2a7

[38225.643065]  [<ffffffff814ca51d>] mutex_lock+0xd/0x1d

[38225.643066]  [<ffffffff81121827>] do_last+0x195/0xb54

[38225.643068]  [<ffffffff81122432>] path_openat+0x24c/0x5c1

[38225.643069]  [<ffffffff810ed93e>] ? handle_mm_fault+0x91c/0xb35

[38225.643070]  [<ffffffff81123490>] do_filp_open+0x35/0x7a

[38225.643072]  [<ffffffff8112cdc7>] ? __alloc_fd+0x59/0xe0

[38225.643075]  [<ffffffff811160c4>] do_sys_open+0x148/0x1d7

[38225.643076]  [<ffffffff8111616c>] SyS_open+0x19/0x1b

[38225.643078]  [<ffffffff814cc079>] system_call_fastpath+0x16/0x1b

[38225.643079] INFO: task nmbd:16309 blocked for more than 120 seconds.

[38225.643080]       Tainted: P          IO 3.13.9-gentoo #1

[38225.643080] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[38225.643081] nmbd            D 0000000000000004     0 16309   3501 0x00000000

[38225.643082]  ffff880398bcbc68 0000000000000086 ffff880398bcbfd8 ffff8800269163d0

[38225.643084]  0000000000011900 ffff8800269163d0 0000000000000003 ffff88042ffcbb00

[38225.643085]  0000000000000002 0000000000000000 ffff880398bcbcd0 ffffffff810d56c3

[38225.643087] Call Trace:

[38225.643089]  [<ffffffff810d56c3>] ? __alloc_pages_nodemask+0x147/0x7fd

[38225.643090]  [<ffffffff814c8472>] schedule+0x6a/0x6c

[38225.643092]  [<ffffffff814c8731>] schedule_preempt_disabled+0x9/0xb

[38225.643093]  [<ffffffff814ca3d0>] __mutex_lock_slowpath+0x167/0x2a7

[38225.643094]  [<ffffffff814ca51d>] mutex_lock+0xd/0x1d

[38225.643095]  [<ffffffff81121827>] do_last+0x195/0xb54

[38225.643097]  [<ffffffff81122432>] path_openat+0x24c/0x5c1

[38225.643098]  [<ffffffff810ed93e>] ? handle_mm_fault+0x91c/0xb35

[38225.643099]  [<ffffffff81123490>] do_filp_open+0x35/0x7a

[38225.643101]  [<ffffffff8112cdc7>] ? __alloc_fd+0x59/0xe0

[38225.643102]  [<ffffffff811160c4>] do_sys_open+0x148/0x1d7

[38225.643104]  [<ffffffff8111616c>] SyS_open+0x19/0x1b

[38225.643105]  [<ffffffff814cc079>] system_call_fastpath+0x16/0x1b

[38225.643107] INFO: task nmbd:16310 blocked for more than 120 seconds.

[38225.643107]       Tainted: P          IO 3.13.9-gentoo #1

[38225.643108] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[38225.643108] nmbd            D 0000000000000004     0 16310   3501 0x00000000

[38225.643110]  ffff8801bd79bc68 0000000000000082 ffff8801bd79bfd8 ffff8802e4f3cde0

[38225.643111]  0000000000011900 ffff8802e4f3cde0 00000002ffffffff 0000000000000000

[38225.643113]  0000000000000001 ffff88042ffcbb00 ffff88042ffcbb08 0000000000000000

[38225.643114] Call Trace:

[38225.643116]  [<ffffffff814c8472>] schedule+0x6a/0x6c

[38225.643118]  [<ffffffff814c8731>] schedule_preempt_disabled+0x9/0xb

[38225.643119]  [<ffffffff814ca3d0>] __mutex_lock_slowpath+0x167/0x2a7

[38225.643120]  [<ffffffff814ca51d>] mutex_lock+0xd/0x1d

[38225.643121]  [<ffffffff81121827>] do_last+0x195/0xb54

[38225.643123]  [<ffffffff81122432>] path_openat+0x24c/0x5c1

[38225.643124]  [<ffffffff810ed3fe>] ? handle_mm_fault+0x3dc/0xb35

[38225.643125]  [<ffffffff81123490>] do_filp_open+0x35/0x7a

[38225.643127]  [<ffffffff8112cdc7>] ? __alloc_fd+0x59/0xe0

[38225.643128]  [<ffffffff811160c4>] do_sys_open+0x148/0x1d7

[38225.643130]  [<ffffffff8111616c>] SyS_open+0x19/0x1b

[38225.643131]  [<ffffffff814cc079>] system_call_fastpath+0x16/0x1b

[38225.643133] INFO: task sendmail:16335 blocked for more than 120 seconds.

[38225.643134]       Tainted: P          IO 3.13.9-gentoo #1

[38225.643134] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[38225.643135] sendmail        D 0000000000000000     0 16335  16331 0x00000000

[38225.643136]  ffff8801c0395e28 0000000000000082 ffff8801c0395fd8 ffff8803c920b360

[38225.643138]  0000000000011900 ffff8803c920b360 00007fbd00459000 ffff8801ae747378

[38225.643139]  00007fbd00458000 ffff88022153def8 ffff8801c0395dd8 ffffffff810f138c

[38225.643141] Call Trace:

[38225.643143]  [<ffffffff810f138c>] ? vma_merge+0x1a6/0x2a1

[38225.643144]  [<ffffffff810f0842>] ? __vm_enough_memory+0x24/0x13c

[38225.643146]  [<ffffffff810f2827>] ? mmap_region+0x2f6/0x44a

[38225.643148]  [<ffffffff814c8472>] schedule+0x6a/0x6c

[38225.643149]  [<ffffffff814c8731>] schedule_preempt_disabled+0x9/0xb

[38225.643150]  [<ffffffff814ca3d0>] __mutex_lock_slowpath+0x167/0x2a7

[38225.643151]  [<ffffffff814ca51d>] mutex_lock+0xd/0x1d

[38225.643153]  [<ffffffff81215f36>] btrfs_file_llseek+0x3b/0x200

[38225.643155]  [<ffffffff8111a915>] ? SyS_newfstat+0x25/0x2e

[38225.643157]  [<ffffffff8111622c>] vfs_llseek+0x29/0x2b

[38225.643158]  [<ffffffff811165eb>] SyS_lseek+0x44/0x6b

[38225.643160]  [<ffffffff814cc079>] system_call_fastpath+0x16/0x1b
```

----------

## drescherjm

I see these from time to time when BTRFS takes several minutes to mount when it rebuilds the space cache.

----------

