Note: "permalinks" may not be as permanent as we would like,
direct links of old sources may well be a few messages off.
On Fri, Dec 12, 2008 at 01:41:07PM -0800, Nolan wrote:
> On Fri, 2008-12-12 at 11:30 +0100, Lars Ellenberg wrote:
> > On Thu, Dec 11, 2008 at 05:56:36PM -0800, Nolan wrote:
> > > I've got two nodes running Ubuntu 8.10/64bit using the included DRBD:
> > > version: 8.2.6 (api:88/proto:86-88)
> > > GIT-hash: 3e69822d3bb4920a8c1bfdf7d647169eba7d2eb4 build by
> > > phil at fat-tyre, 2008-05-30 12:59:17
> > >
> > > Each node has 4 drives, which are striped together using LVM, and then
> > > cut into 24 logical volumes. One DRBD is attached to each of the 24
> > > lvs. The two nodes speak over 2x bonded e1000s. All was running well
> > > for 40+ days with 24 KVM VMs running.
> > >
> > > I decided to try out the online verify functionality, and after adding
> > > "verify-alg crc32c;" to my config on both hosts, and running adjust, I
> > > ran:
> > > drbdadm verify VM24
> > >
> > > All was well, and I watched "/proc/drbd" as the verify progressed. But
> > > then it stopped at 14%:
> > > 24: cs:VerifyS st:Primary/Secondary ds:UpToDate/UpToDate C r---
> > > ns:2035752 nr:160958366 dw:162994118 dr:23997736 al:186 bm:10021
> > > lo:0 pe:4624 ua:0 ap:16 oos:0
> > > 14% 5847476/39734074
> > >
> > > The VM using that storage is hung hard. Stracing it shows it blocked in
> > > a rather uninformative spot:
> > > root at node1:~# strace -p 9878
> > > Process 9878 attached - interrupt to quit
> > > futex(0xb531a0, 0x80 /* FUTEX_??? */, 2
> > >
> > > Dmesg on the secondary node has nothing interesting, but dmesg on the
> > > primary node has:
> > > [3628294.472338] drbd24: state = { cs:Connected st:Primary/Secondary
> > > ds:UpToDate/UpToDate r--- }
> > > [3628294.481196] drbd24: wanted = { cs:VerifyS st:Primary/Secondary
> > > ds:UpToDate/UpToDate r--- }
> > > [3628524.571022] drbd24: conn( Connected -> VerifyS )
> > > [3628919.655921] drbd24: qemu-system-x86[10223] Concurrent local write
> > > detected! [DISCARD L] new: 952311s +3584; pending: 952311s +3584
> > > [3628919.668048] drbd24: qemu-system-x86[10223] Concurrent local write
> > > detected! [DISCARD L] new: 952318s +512; pending: 952318s +512
> > > [3628919.680433] drbd24: qemu-system-x86[10223] Concurrent local write
> > > detected! [DISCARD L] new: 799599s +3584; pending: 799599s +3584
> > > [3628919.692566] drbd24: qemu-system-x86[10223] Concurrent local write
> > > detected! [DISCARD L] new: 799606s +512; pending: 799606s +512
> > > [3629004.628073] drbd24: qemu-system-x86[10224] Concurrent local write
> > > detected! [DISCARD L] new: 952311s +3584; pending: 952311s +3584
> > > [3629004.640192] drbd24: qemu-system-x86[10224] Concurrent local write
> > > detected! [DISCARD L] new: 952318s +512; pending: 952318s +512
> > > [3629004.652675] drbd24: qemu-system-x86[10224] Concurrent local write
> > > detected! [DISCARD L] new: 799599s +3584; pending: 799599s +3584
> > > [3629004.664787] drbd24: qemu-system-x86[10224] Concurrent local write
> > > detected! [DISCARD L] new: 799606s +512; pending: 799606s +512
> > >
> > > Any ideas what could be causing this?
> > >
> > > Google on the "concurrent local write" error only turned up the check-in
> > > that added that code to DRBD.
> >
> > that means something is locally submitting writes to some block where we
> > still have pending writes to. that is unexpected behaviour, and would
> > lead to non-deterministic results on disk. drbd does not allow that.
>
> When you say locally, do you mean the underlying /dev/mapper/whatever
> device that the DRBD device is layered on top of?
no. DRBD won't notice that.
the "concurrent write" detecting logic was introduced to support
dual primary setups, where it is obvious that concurrent simultaneous
writes from both nodes to the same area are bad.
but this same logic also catches concurrent simultaneous writes to the
same area when issues only "locally", on one node only.
appart from running many processes doing direct io to the same
block, there is not much I can think of that may produce these
concurrent writes.
maybe some disk image accidentally mounted on the host,
while simultaneously being used from within a virtual machine guest?
or some "optimization" taking place on the virtual disk driver?
> > > I can leave the system as it is for a few days, if there is more
> > > information I should collect.
> >
> > great.
> >
> > please do
> > echo 2 > /sys/module/drbd/parameters/proc_details
> > and provide the output of
> > cat /proc/drbd
>
> version: 8.2.6 (api:88/proto:86-88)
> GIT-hash: 3e69822d3bb4920a8c1bfdf7d647169eba7d2eb4 build by
> phil at fat-tyre, 2008-05-30 12:59:17
0 not existent,
1 to 23 not interessting.
ok.
> 24: cs:VerifyS st:Primary/Secondary ds:UpToDate/UpToDate C r---
> ns:2035752 nr:160958366 dw:162994118 dr:23997736 al:186 bm:10021 lo:0 pe:4624 ua:0 ap:16 oos:0
> 14% 5847476/39734074
> resync: used:2/61 hits:85309102 misses:11130 starving:0 dirty:0 changed:11130
> act_log: used:3/127 hits:717422 misses:186 starving:0 dirty:0 changed:186
> nn: lc_number refcnt rs_left
> 0: 1399 0 0 --------- ------
> 1: 1400 0 0 --------- ------
> 2: 1401 0 0 --------- ------
> 3: 1402 0 0 --------- ------
> 4: 1397 0 0 --------- ------
> 5: 1391 0 0 --------- ------
> 6: 1398 0 0 --------- ------
> 7: 1396 0 0 --------- ------
> 8: 1394 0 0 --------- ------
> 9: 1395 0 0 --------- ------
> 10: 1393 0 0 --------- ------
> 11: 1390 0 0 --------- ------
> 12: 1389 0 0 --------- ------
> 13: 1387 0 0 --------- ------
> 14: 1392 0 0 --------- ------
> 15: 1386 0 0 --------- ------
> 16: 1385 0 0 --------- ------
> 17: 1384 0 0 --------- ------
> 18: 1388 0 0 --------- ------
> 19: 1380 0 0 --------- ------
> 20: 1383 0 0 --------- ------
> 21: 1375 0 0 --------- ------
> 22: 1382 0 0 --------- ------
> 23: 1378 0 0 --------- ------
> 24: 1371 0 0 --------- ------
> 25: 1381 0 0 --------- ------
> 26: 1379 0 0 --------- ------
> 27: 1368 0 0 --------- ------
> 28: 1377 0 0 --------- ------
> 29: 1370 0 0 --------- ------
> 30: 1374 0 0 --------- ------
> 31: 1372 0 0 --------- ------
> 32: 1373 0 0 --------- ------
> 33: 1428 2996 0 --------- LOCKED
> 34: 1376 0 0 --------- ------
> 35: 1427 1612 0 --------- LOCKED
> 36: 1426 0 0 --------- ------
> 37: 1369 0 0 --------- ------
> 38: 1425 0 0 --------- ------
> 39: 1424 0 0 --------- ------
> 40: 1422 0 0 --------- ------
> 41: 1420 0 0 --------- ------
> 42: 1421 0 0 --------- ------
> 43: 1423 0 0 --------- ------
> 44: 1417 0 0 --------- ------
> 45: 1413 0 0 --------- ------
> 46: 1415 0 0 --------- ------
> 47: 1419 0 0 --------- ------
> 48: 1418 0 0 --------- ------
> 49: 1416 0 0 --------- ------
> 50: 1411 0 0 --------- ------
> 51: 1410 0 0 --------- ------
> 52: 1408 0 0 --------- ------
> 53: 1414 0 0 --------- ------
> 54: 1406 0 0 --------- ------
> 55: 1407 0 0 --------- ------
> 56: 1404 0 0 --------- ------
> 57: 1412 0 0 --------- ------
> 58: 1403 0 0 --------- ------
> 59: 1405 0 0 --------- ------
> 60: 1409 0 0 --------- ------
>
> > ps -eo pid,state,wchan:30,cmd | grep -e drbd -e D
>
> PID S WCHAN CMD
...
> 6771 S down_interruptible [drbd24_worker]
> 6781 S sk_wait_data [drbd24_receiver]
> 6913 S sk_wait_data [drbd24_asender]
> 9878 S futex_wait /usr/local/bin/qemu-system-x86_64
> -m 512 -drive file=/dev/drbd24,if=scsi,cache=off,boot=on -drive
> if=ide,index=2,media=cdrom,boot=off -usbdevice tablet -name root_vm_1
> -net nic,macaddr=00:0c:29:12:47:21,model=rtl8139 -net tap -monitor
> unix:/tmp/VM_root_vm_1,server,nowait -tdf -daemonize -vnc :0,password
hm.
and neither /proc/mounts, /proc/partitions nor dmsetup table
triggered anything in my brain either.
I'll have to think about that some more.
can you do the ps -eo | grep magic on the other node as well please?
--
: Lars Ellenberg
: LINBIT | Your Way to High Availability
: DRBD/HA support and consulting http://www.linbit.com
DRBD® and LINBIT® are registered trademarks of LINBIT, Austria.
__
please don't Cc me, but send to list -- I'm subscribed