[SOLVED] ceph "sd abort"

R

RobFantini

Famous Member
May 24, 2012
2,041
107
133
Boston,Mass
we have 10 OSD's . all the same model drive Intel SSD DC S3520 .

the OSD's run on pve systems that have no vm's or mons.

the network switch is 10G. the nics on the nodes are 1G.

I've just 2 test kvm's running on ceph.

from vm's out side of ceph we test by running rsync to one and dovecot backup to the other vm.

after approx 30 minutes the systems hang .

from syslog:
Code: 
Mar 30 14:55:45 ceph-test1 kernel: [ 2089.832107] sd 2:0:0:1: [sdb] abort
Mar 30 14:57:01 ceph-test1 kernel: [ 2165.630246] sd 2:0:0:1: [sdb] abort
Mar 30 14:58:55 ceph-test1 kernel: [ 2280.028104] INFO: task jbd2/sdb1-8:725 blocked for more than 120 seconds.
Mar 30 14:58:55 ceph-test1 kernel: [ 2280.028532]       Not tainted 3.16.0-4-amd64 #1
Mar 30 14:58:55 ceph-test1 kernel: [ 2280.028742] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 30 14:58:55 ceph-test1 kernel: [ 2280.029143] jbd2/sdb1-8     D ffff88001a6c3a88     0   725      2 0x00000000
Mar 30 14:58:55 ceph-test1 kernel: [ 2280.029147]  ffff88001a6c3630 0000000000000046 0000000000012f40 ffff88001004bfd8
Mar 30 14:58:55 ceph-test1 kernel: [ 2280.029149]  0000000000012f40 ffff88001a6c3630 ffff88001fc137f0 ffff88001ff9e3f0
Mar 30 14:58:55 ceph-test1 kernel: [ 2280.029150]  0000000000000002 ffffffff8113ee30 ffff88001004bbd0 ffff88001004bcb8


Mar 30 14:55:53 ceph-test2 kernel: [ 2090.856057] sd 2:0:0:1: [sdb] abort
Mar 30 14:59:02 ceph-test2 kernel: [ 2280.028096] INFO: task kworker/u2:0:6 blocked for more than 120 seconds.
Mar 30 14:59:02 ceph-test2 kernel: [ 2280.028799]       Not tainted 3.16.0-4-amd64 #1
Mar 30 14:59:02 ceph-test2 kernel: [ 2280.029147] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 30 14:59:02 ceph-test2 kernel: [ 2280.029828] kworker/u2:0    D ffff88001e5be4a8     0     6      2 0x00000000
Mar 30 14:59:02 ceph-test2 kernel: [ 2280.029852] Workqueue: scsi_tmf_2 scmd_eh_abort_handler [scsi_mod]
Mar 30 14:59:02 ceph-test2 kernel: [ 2280.029855]  ffff88001e5be050 0000000000000046 0000000000012f40 ffff88001e5d7fd8
Mar 30 14:59:02 ceph-test2 kernel: [ 2280.029857]  0000000000012f40 ffff88001e5be050 ffff88001e5d7dc8 ffff88001e5d7d60
Mar 30 14:59:02 ceph-test2 kernel: [ 2280.029860]  ffff88001e5d7dc0 ffff88001e5be050 0000000000002003 0000000000000040
*from system sending data to test2 system:
Code: 
# doveadm backup  -A remote:10.1.3.105
dsync-local(user1): Error: dsync(localhost.localdomain): I/O has stalled, no activity for 600 seconds
dsync-local(user1): Error: Timeout during state=sync_mails (send=mails recv=recv_last_common)
dsync-local(user1): Error: Remote command process isn't dying, killing it


kvm conf:
Code: 
boot: c
bootdisk: scsi0
cores: 1
memory: 512
name: ceph-test1
net0: virtio=1A:64:14:A6:16:3A,bridge=vmbr0,tag=3
numa: 0
ostype: l26
protection: 1
scsi0: ceph-kvm:vm-9001-disk-1,discard=on,size=4G
scsi1: ceph-kvm:vm-9001-disk-2,discard=on,size=200G
scsihw: virtio-scsi-pci
smbios1: uuid=9035f5f9-60e8-42fa-b6ff-5ab38a160365
sockets: 1


boot: c
bootdisk: scsi0
cores: 1
memory: 512
name: ceph-test2
net0: virtio=E2:20:3B:C0:72:F1,bridge=vmbr0,tag=3
numa: 0
ostype: l26
protection: 1
scsi0: ceph-kvm:vm-9002-disk-1,discard=on,size=4G
scsi1: ceph-kvm:vm-9002-disk-2,discard=on,size=50G
scsihw: virtio-scsi-pci
smbios1: uuid=9035f5f9-60e8-42fa-b6ff-5ab38a160365
sockets: 1

ceph: 10.2.6-1~bpo80+1

the systems are 4-drive supermicro X10SLM and X9SCi-LN4F . they have 32GB ecc ram.

Does anyone have some suggestion to solve this issue?
 
Last edited:
and ceph.log on the pve host running the vm's shows no issue that I could see:
Code: 
2017-03-30 14:55:45.276925 mon.0 10.11.12.5:6789/0 53731 : cluster [INF] pgmap v1876724: 768 pgs: 768 active+clean; 67673 MB data, 196 GB used, 4223 GB / 4419 GB avail; 1319 B/s wr, 0 op/s
2017-03-30 14:55:47.614742 mon.0 10.11.12.5:6789/0 53732 : cluster [INF] pgmap v1876725: 768 pgs: 768 active+clean; 67673 MB data, 196 GB used, 4223 GB / 4419 GB avail; 1857 B/s wr, 0 op/s
2017-03-30 14:55:48.640385 mon.0 10.11.12.5:6789/0 53733 : cluster [INF] pgmap v1876726: 768 pgs: 768 active+clean; 67697 MB data, 196 GB used, 4223 GB / 4419 GB avail; 132 kB/s rd, 7186 kB/s wr, 67 op/s
2017-03-30 14:55:49.701338 mon.0 10.11.12.5:6789/0 53734 : cluster [INF] pgmap v1876727: 768 pgs: 768 active+clean; 67718 MB data, 196 GB used, 4222 GB / 4419 GB avail; 404 kB/s rd, 23103 kB/s wr, 243 op/s
2017-03-30 14:55:50.733025 mon.0 10.11.12.5:6789/0 53735 : cluster [INF] pgmap v1876728: 768 pgs: 768 active+clean; 67718 MB data, 196 GB used, 4222 GB / 4419 GB avail; 188 kB/s rd, 12105 kB/s wr, 136 op/s
2017-03-30 14:55:51.832134 mon.0 10.11.12.5:6789/0 53736 : cluster [INF] pgmap v1876729: 768 pgs: 768 active+clean; 67743 MB data, 196 GB used, 4222 GB / 4419 GB avail; 12205 kB/s wr, 72 op/s
2017-03-30 14:55:52.883602 mon.0 10.11.12.5:6789/0 53737 : cluster [INF] pgmap v1876730: 768 pgs: 768 active+clean; 67750 MB data, 196 GB used, 4222 GB / 4419 GB avail; 14666 kB/s wr, 81 op/s
2017-03-30 14:55:53.933899 mon.0 10.11.12.5:6789/0 53738 : cluster [INF] pgmap v1876731: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 16962 kB/s wr, 83 op/s
2017-03-30 14:55:54.981554 mon.0 10.11.12.5:6789/0 53739 : cluster [INF] pgmap v1876732: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 17027 B/s rd, 13690 kB/s wr, 88 op/s
2017-03-30 14:55:56.045237 mon.0 10.11.12.5:6789/0 53740 : cluster [INF] pgmap v1876733: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 17046 B/s rd, 21917 B/s wr, 17 op/s
..
2017-03-30 14:57:09.908893 mon.0 10.11.12.5:6789/0 53774 : cluster [INF] pgmap v1876767: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:57:06.292841 osd.6 10.11.12.20:6800/7052 9 : cluster [INF] 8.b7 scrub starts
2017-03-30 14:57:06.294514 osd.6 10.11.12.20:6800/7052 10 : cluster [INF] 8.b7 scrub ok
2017-03-30 14:57:10.967593 mon.0 10.11.12.5:6789/0 53775 : cluster [INF] pgmap v1876768: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:57:11.994967 mon.0 10.11.12.5:6789/0 53776 : cluster [INF] pgmap v1876769: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 9864 B/s wr, 0 op/s
2017-03-30 14:57:13.038036 mon.0 10.11.12.5:6789/0 53777 : cluster [INF] pgmap v1876770: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 9871 B/s wr, 0 op/s
2017-03-30 14:57:15.084920 mon.0 10.11.12.5:6789/0 53778 : cluster [INF] pgmap v1876771: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 3974 B/s wr, 0 op/s
2017-03-30 14:57:16.143578 mon.0 10.11.12.5:6789/0 53779 : cluster [INF] pgmap v1876772: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 3981 B/s wr, 0 op/s
2017-03-30 14:57:18.200586 mon.0 10.11.12.5:6789/0 53780 : cluster [INF] pgmap v1876773: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:57:20.245732 mon.0 10.11.12.5:6789/0 53781 : cluster [INF] pgmap v1876774: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:58:47.956944 mon.0 10.11.12.5:6789/0 53782 : cluster [INF] pgmap v1876775: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:01.055408 mon.0 10.11.12.5:6789/0 53783 : cluster [INF] pgmap v1876776: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 325 B/s wr, 0 op/s
2017-03-30 14:59:02.105344 mon.0 10.11.12.5:6789/0 53784 : cluster [INF] pgmap v1876777: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 4059 B/s wr, 0 op/s
2017-03-30 14:59:03.123137 mon.0 10.11.12.5:6789/0 53785 : cluster [INF] pgmap v1876778: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 17760 B/s wr, 1 op/s
2017-03-30 14:59:06.045712 mon.0 10.11.12.5:6789/0 53786 : cluster [INF] pgmap v1876779: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 3094 B/s wr, 0 op/s
2017-03-30 14:59:08.096791 mon.0 10.11.12.5:6789/0 53787 : cluster [INF] pgmap v1876780: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 824 B/s rd, 2474 B/s wr, 0 op/s
2017-03-30 14:59:10.170969 mon.0 10.11.12.5:6789/0 53788 : cluster [INF] pgmap v1876781: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 998 B/s rd, 5988 B/s wr, 1 op/s
2017-03-30 14:59:12.635972 mon.0 10.11.12.5:6789/0 53789 : cluster [INF] pgmap v1876782: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 7212 B/s wr, 0 op/s
2017-03-30 14:59:13.689996 mon.0 10.11.12.5:6789/0 53790 : cluster [INF] pgmap v1876783: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 5822 B/s wr, 0 op/s
2017-03-30 14:59:14.728418 mon.0 10.11.12.5:6789/0 53791 : cluster [INF] pgmap v1876784: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:15.775732 mon.0 10.11.12.5:6789/0 53792 : cluster [INF] pgmap v1876785: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:16.852519 mon.0 10.11.12.5:6789/0 53793 : cluster [INF] pgmap v1876786: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:17.910624 mon.0 10.11.12.5:6789/0 53794 : cluster [INF] pgmap v1876787: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:18.947872 mon.0 10.11.12.5:6789/0 53795 : cluster [INF] pgmap v1876788: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:33.184222 mon.0 10.11.12.5:6789/0 53796 : cluster [INF] pgmap v1876789: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:34.238999 mon.0 10.11.12.5:6789/0 53797 : cluster [INF] pgmap v1876790: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 803 B/s wr, 0 op/s
2017-03-30 14:59:35.288863 mon.0 10.11.12.5:6789/0 53798 : cluster [INF] pgmap v1876791: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 17733 B/s wr, 2 op/s
2017-03-30 14:59:37.969251 mon.0 10.11.12.5:6789/0 53799 : cluster [INF] pgmap v1876792: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 7662 B/s wr, 1 op/s
2017-03-30 14:59:40.049690 mon.0 10.11.12.5:6789/0 53800 : cluster [INF] pgmap v1876793: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:41.102283 mon.0 10.11.12.5:6789/0 53801 : cluster [INF] pgmap v1876794: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:42.144042 mon.0 10.11.12.5:6789/0 53802 : cluster [INF] pgmap v1876795: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:43.189721 mon.0 10.11.12.5:6789/0 53803 : cluster [INF] pgmap v1876796: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 21474 B/s wr, 1 op/s
2017-03-30 14:59:44.210799 mon.0 10.11.12.5:6789/0 53804 : cluster [INF] pgmap v1876797: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 21615 B/s wr, 1 op/s
2017-03-30 14:59:45.286081 mon.0 10.11.12.5:6789/0 53805 : cluster [INF] pgmap v1876798: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:46.341524 mon.0 10.11.12.5:6789/0 53806 : cluster [INF] pgmap v1876799: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 5847 B/s wr, 1 op/s
2017-03-30 14:59:47.392903 mon.0 10.11.12.5:6789/0 53807 : cluster [INF] pgmap v1876800: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail; 5850 B/s wr, 1 op/s
2017-03-30 14:59:48.417968 mon.0 10.11.12.5:6789/0 53808 : cluster [INF] pgmap v1876801: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:49.486538 mon.0 10.11.12.5:6789/0 53809 : cluster [INF] pgmap v1876802: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:50.511527 mon.0 10.11.12.5:6789/0 53810 : cluster [INF] pgmap v1876803: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 14:59:51.592561 mon.0 10.11.12.5:6789/0 53811 : cluster [INF] pgmap v1876804: 768 pgs: 768 active+clean; 67778 MB data, 196 GB used, 4222 GB / 4419 GB avail
2017-03-30 15:00:00.000294 mon.0 10.11.12.5:6789/0 53812 : cluster [INF] HEALTH_OK
 
no joy using
Linux debian9 4.9.0-1-amd64 #1 SMP Debian 4.9.2-2 (2017-01-12) x86_64 GNU/Linux
Code: 
[Fri Mar 31 04:04:21 2017] sd 0:0:0:1: [sdb] tag#18 abort
[Fri Mar 31 04:04:43 2017] sd 0:0:0:1: [sdb] tag#5 abort
[Fri Mar 31 04:04:43 2017] sd 0:0:0:1: [sdb] tag#13 abort
[Fri Mar 31 04:04:43 2017] sd 0:0:0:1: [sdb] tag#26 abort
[Fri Mar 31 04:04:43 2017] sd 0:0:0:1: [sdb] tag#11 abort
[Fri Mar 31 04:04:43 2017] sd 0:0:0:1: [sdb] tag#12 abort
[Fri Mar 31 04:04:43 2017] sd 0:0:0:1: [sdb] tag#15 abort
[Fri Mar 31 04:05:41 2017] sd 0:0:0:1: [sdb] tag#7 abort
[Fri Mar 31 04:06:02 2017] sd 0:0:0:1: [sdb] tag#6 abort
[Fri Mar 31 04:06:02 2017] sd 0:0:0:1: [sdb] tag#8 abort
[Fri Mar 31 04:06:02 2017] sd 0:0:0:1: [sdb] tag#4 abort
[Fri Mar 31 04:06:02 2017] sd 0:0:0:1: [sdb] tag#12 abort
[Fri Mar 31 04:06:59 2017] sd 0:0:0:1: [sdb] tag#8 abort
 
I found an issue. one of the nodes had 4 osd's listed when there should have been 3. [ there are only 4 hdd slots. one for opsys, 3 ceph. ] this had something to do with deleting an osd and adding the disk for another purpose [ zfs ] on another system. it somehow did not get cleared. when I put it in a couple of days ago it showed up as an osd . I thought I'd handled that however I did not check the original node that the osd came from. the old osd was put to a zfs only system.

so i rebooted all the osd nodes, and am retesting.
 
issues solved.

edit - next set of testing - issue is back.
Code: 
[Fri Mar 31 10:04:23 2017] sd 2:0:0:0: [sda] abort
[Fri Mar 31 10:07:12 2017] INFO: task kworker/u4:0:6 blocked for more than 120 seconds.
[Fri Mar 31 10:07:12 2017]       Not tainted 3.16.0-4-amd64 #1
[Fri Mar 31 10:07:12 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Fri Mar 31 10:07:12 2017] kworker/u4:0    D ffff88003e2a84a8     0     6      2 0x00000000
[Fri Mar 31 10:07:12 2017] Workqueue: writeback bdi_writeback_workfn (flush-8:0)
[Fri Mar 31 10:07:12 2017]  ffff88003e2a8050 0000000000000046 0000000000012f40 ffff88003e2c3fd8
[Fri Mar 31 10:07:12 2017]  0000000000012f40 ffff88003e2a8050 ffff88003fd137f0 ffff88003ffa57a0
[Fri Mar 31 10:07:12 2017]  0000000000000002 ffffffff811d9e70 ffff88003e2c3670 00000000000000

# othere system:
[Fri Mar 31 10:04:17 2017] sd 2:0:0:1: [sdb] abort
[Fri Mar 31 10:07:15 2017] INFO: task jbd2/sdb1-8:236 blocked for more than 120 seconds.
[Fri Mar 31 10:07:15 2017]       Not tainted 3.16.0-4-amd64 #1
[Fri Mar 31 10:07:15 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Fri Mar 31 10:07:15 2017] jbd2/sdb1-8     D ffff88003728f078     0   236      2 0x00000000
[Fri Mar 31 10:07:15 2017]  ffff88003728ec20 0000000000000046 0000000000012f40 ffff88003cf63fd8
[Fri Mar 31 10:07:15 2017]  0000000000012f40 ffff88003728ec20 ffff88003fc137f0 ffff88003ffafd90
[Fri Mar 31 10:07:15 2017]  0000000000000002 ffffffff811d9e70 ffff88003cf63c80 ffff880036d44b98
 
Last edited:
RobFantini said:
and the two vm's are left in an unstable state. for instance running ' ls ' hangs.

i'll wait 10 minutes to see if they un hang.
Click to expand...
after awhile they unhung.

Note after the 1ST good test I had added 6 more OSD's thinking it was OK some more of the new ones.

Next I restarted all the osd systems, and am retesting.

there are 18 osd.
 
the issue still occurs under heavy load. like doing the two tests and restoring a large lxc backup to ceph storage.

I'll try using 10G network interface cards next.
 
using 10G among other changes fixed our issues.

our original set up was 6 1U nodes with 3 OSD's apiece . they used onboard sata

we are now mostly using more 3 powerful 2U systems with LSI IT mode cards. there a a few more osd's to move.

using gnome disk utility write speeds are 260 MB/s . before they were less the 50 MB/s .
 
You must log in or register to reply here.

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Quick Navigation

Home Get Subscription Wiki Downloads Proxmox Customer Portal About

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!
Community platform by XenForo® © 2010-2024 XenForo Ltd.
Top Bottom