Bug 93801 - Low read/dirscan performance
Summary: Low read/dirscan performance
Status: NEW
Alias: None
Product: File System
Classification: Unclassified
Component: btrfs (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Josef Bacik
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-02-24 15:35 UTC by Matthias Urlichs
Modified: 2016-03-20 10:17 UTC (History)
1 user (show)

See Also:
Kernel Version: 3.19.0-trunk (Debian)
Tree: Mainline
Regression: No


Attachments

Description Matthias Urlichs 2015-02-24 15:35:36 UTC
This is 3.19, scanning an otherwise-idle filesystem on an otherwise-idle btrfs partition on otherwise-idle disks (LVM), mounted with noatime and nodatasum.

Tracing a dead-slow rsync (read side) on a file system mounted with noatime:
11:41:51.703418 llistxattr("cpool/0/0/5/00556827384267bee22ab9adfb891807", "", 1024) = 0 <0.000018>
11:41:51.703472 lstat("cpool/0/0/5/00524ed0f6edbadd2a92f9366bce00c4", {st_mode=S_IFREG|0640, st_size=1024, ...}) = 0 <0.002519>
11:41:51.706044 getxattr("cpool/0/0/5/00524ed0f6edbadd2a92f9366bce00c4", "system.posix_acl_access", 0x7fff32f63090, 132) = -1 ENODATA (No data available) <0.000028>
11:41:51.706125 stat("cpool/0/0/5/00524ed0f6edbadd2a92f9366bce00c4", {st_mode=S_IFREG|0640, st_size=1024, ...}) = 0 <0.000016>
11:41:51.706170 llistxattr("cpool/0/0/5/00524ed0f6edbadd2a92f9366bce00c4", "", 1024) = 0 <0.000016>

11:41:51.706218 lstat("cpool/0/0/5/0056f3e500258614f19569d7dc014c80", {st_mode=S_IFREG|0640, st_size=351, ...}) = 0 <0.214911>

11:41:51.921209 getxattr("cpool/0/0/5/0056f3e500258614f19569d7dc014c80", "system.posix_acl_access", 0x7fff32f63090, 132) = -1 ENODATA (No data available) <0.000023>
11:41:51.921294 stat("cpool/0/0/5/0056f3e500258614f19569d7dc014c80", {st_mode=S_IFREG|0640, st_size=351, ...}) = 0 <0.000008>
11:41:51.921342 llistxattr("cpool/0/0/5/0056f3e500258614f19569d7dc014c80", "", 1024) = 0 <0.000018>
11:41:51.921397 lstat("cpool/0/0/5/0058f2c720f7567989a0f4d33e5c8eb4", {st_mode=S_IFREG|0640, st_size=65, ...}) = 0 <0.007500>
11:41:51.928959 getxattr("cpool/0/0/5/0058f2c720f7567989a0f4d33e5c8eb4", "system.posix_acl_access", 0x7fff32f63090, 132) = -1 ENODATA (No data available) <0.000027>

0.2sec is not the longest delay I've seen here.

iotop says:
                                                             
 7977 be/4 root      115.70 K/s    0.00 B/s  0.00 % 99.95 % rsync -aPHAX backup/backuppc/. /d/backup/backuppc/
 7259 be/4 root      160.07 K/s  586.40 K/s  0.00 % 99.14 % [btrfs-transacti]

OK. So how can this even happen when there is no writing process here (#7983 writes to the destination disk, formatted with ext4)? And what's the hold-up anyway, given that the partition easily sustains >20 MByte/s write speed? The kernel thread is in 'D' state whenever I run "ps" and causes at most 2% of CPU load.
Comment 1 Matthias Urlichs 2015-02-24 15:40:18 UTC
NB: the comment about #7983 referred to the writing rsync child which I've dropped from iotop output by mistake.

Note You need to log in before you can comment on or make changes to this bug.