write(2) taking 4s. (Was: Memory leak?)

[Stephane Chazelas <stephane_chazelas@yahoo.fr>]

[-- Attachment #1: Type: text/plain, Size: 4283 bytes --]

Still on my btrfs-based backup system. I still see one BUG()
reached in btrfs-fixup per boot time, no memory exhaustion
anymore. There is now however something new: write performance
is down to a few bytes per second.

I've got a few processes (rsync, patched ntfsclone, shells
mostly) writing to files at the same time on this server.

disk stats per second:

--dsk/sda-----dsk/sdb-----dsk/sdc--
 read  writ: read  writ: read  writ
 264k   44k: 193k   44k: 225k   42k
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
   0    60k:   0     0 :   0     0
   0    12k:   0  1176k:   0  1164k
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
   0    40k:   0     0 :8192B    0
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :4096B    0
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
 324k    0 : 248k    0 : 548k    0
   0  4096B:   0     0 :   0     0
 352k    0 :   0     0 :   0     0
   0     0 :   0     0 :   0     0
   0     0 :   0     0 :4096B    0
   0     0 :   0     0 :   0     0
   0    80k:   0     0 :   0     0

rsync:

# strace -Ts0 -p 5015
Process 5015 attached - interrupt to quit
write(3, ""..., 1024)                   = 1024 <0.007700>
write(3, ""..., 1024)                   = 1024 <0.015822>
write(3, ""..., 1024)                   = 1024 <0.031853>
write(3, ""..., 1024)                   = 1024 <0.015881>
write(3, ""..., 1024)                   = 1024 <0.015911>
write(3, ""..., 1024)                   = 1024 <0.015796>
write(3, ""..., 1024)                   = 1024 <0.031946>
write(3, ""..., 1024)                   = 1024 <4.083854>
write(3, ""..., 1024)                   = 1024 <0.007925>
write(3, ""..., 1024)                   = 1024 <0.003776>
write(3, ""..., 1024)                   = 1024 <0.031862>
write(3, ""..., 1024)                   = 1024 <0.011807>
write(3, ""..., 1024)                   = 1024 <0.019742>
write(3, ""..., 1024)                   = 1024 <0.015857>
write(3, ""..., 1024)                   = 1024 <0.031833>
write(3, ""..., 1024)                   = 1024 <0.015789>
write(3, ""..., 1024)                   = 1024 <0.015926>
write(3, ""..., 1024)                   = 1024 <4.095967>
write(3, ""..., 1024)                   = 1024 <0.019798>
write(3, ""..., 1024)                   = 1024 <4.083682>
write(3, ""..., 1024)                   = 1024 <0.015398>
write(3, ""..., 1024)                   = 1024 <0.015951>
write(3, ""..., 1024)                   = 1024 <0.035837>
write(3, ""..., 1024)                   = 1024 <0.015962>
write(3, ""..., 1024)                   = 1024 <0.015909>
write(3, ""..., 1024)                   = 1024 <0.015967>
write(3, ""..., 48)                     = 48 <0.003782>
write(3, ""..., 1024)                   = 1024 <0.031802>
write(3, ""..., 1024)                   = 1024 <0.015811>
write(3, ""..., 1024)                   = 1024 <0.015944>
write(3, ""..., 1024)                   = 1024 <0.019810>
write(3, ""..., 1024)                   = 1024 <0.031948>

ntfsclone (patched to only write modified clusters):

# strace -Te write -p 4717
Process 4717 attached - interrupt to quit
write(1, " 65.16 percent completed\r", 25) = 25 <0.008996>
write(1, " 65.16 percent completed\r", 25) = 25 <0.743358>
write(1, " 65.16 percent completed\r", 25) = 25 <0.306582>
write(1, " 65.17 percent completed\r", 25) = 25 <4.082723>
write(1, " 65.17 percent completed\r", 25) = 25 <0.006402>
write(1, " 65.17 percent completed\r", 25) = 25 <0.012582>
write(1, " 65.17 percent completed\r", 25) = 25 <4.052504>
write(1, " 65.17 percent completed\r", 25) = 25 <0.012111>
write(1, " 65.17 percent completed\r", 25) = 25 <0.016001>
write(1, " 65.17 percent completed\r", 25) = 25 <4.028017>
write(1, " 65.18 percent completed\r", 25) = 25 <0.013365>
write(1, " 65.18 percent completed\r", 25) = 25 <0.003963>
(that's writing to a log file)

See how many write(2)s take 4 seconds.

No issue when writing to an ext4 FS.

SMART status on all drives OK.

What else could I look at?

Attached is a sysrq-t output.

-- 
Stephane

[-- Attachment #2: sysrq-t.txt.xz --]
[-- Type: application/octet-stream, Size: 14324 bytes --]