[DRBD-user] drbd FIXME bitmap locked messages

[Jeremy Faith]

Hi,

I have been working with a 4 node cluster and have noticed some FIXME messages in the logs.
Maybe the same as https://lists.linbit.com/pipermail/drbd-user/2019-June/025078.html

drbd90 kernel module version:9.0.22-2(later updated to 9.0.25-1)
drbd90-utils:9.12.2-1
kernel:3.10.0-1127.18.2.el7.x86_64
pacemaker:1.1.21-4
corosync-2.4.5-4
system is centos:7.6
host is VMware ESXi

FIXME messages seem to happen during initial sync/resync.

Example from system log:

Sep 21 17:02:17 cdc0 kernel: drbd r0 dh-cdc0-n3: Handshake to peer 3 successful: Agreed network protocol version 116
Sep 21 17:02:17 cdc0 kernel: drbd r0 dh-cdc0-n3: Feature flags enabled on protocol level: 0xf TRIM THIN_RESYNC WRITE_SAME WRITE_ZEROES.
Sep 21 17:02:17 cdc0 kernel: drbd r0 dh-cdc0-n3: Starting ack_recv thread (from drbd_r_r0 [16881])
Sep 21 17:02:18 cdc0 kernel: drbd r0: Preparing cluster-wide state change 1184555410 (1->3 499/145)
Sep 21 17:02:18 cdc0 kernel: drbd r0: State change 1184555410: primary_nodes=2, weak_nodes=FFFFFFFFFFFFFFF1
Sep 21 17:02:18 cdc0 kernel: drbd r0: Committing cluster-wide state change 1184555410 (1365ms)
Sep 21 17:02:18 cdc0 kernel: drbd r0 dh-cdc0-n3: conn( Connecting -> Connected ) peer( Unknown -> Secondary )
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: WRITE_SAME disabled by config
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: drbd_sync_handshake:
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: self 52067E32B742047A:FCB41408CC57E195:0000000000000000:0000000000000000 bits:994 flags:20
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: peer 0000000000000004:0000000000000000:0000000000000000:0000000000000000 bits:0 flags:24
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: uuid_compare()=source-set-bitmap by rule 30
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: Writing the whole bitmap, full sync required after drbd_sync_handshake.
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[18134] op clear, bitmap locked for 'set_n_write from sync_handshake' by drbd_r_r0[16881]
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: pdsk( DUnknown -> Inconsistent ) repl( Off -> WFBitMapS )
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: send bitmap stats [Bytes(packets)]: plain 0(0), RLE 21(1), total 21; compression: 100.0%
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: receive bitmap stats [Bytes(packets)]: plain 0(0), RLE 21(1), total 21; compression: 100.0%
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: helper command: /sbin/drbdadm before-resync-source
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: helper command: /sbin/drbdadm before-resync-source exit code 0
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: repl( WFBitMapS -> SyncSource )
Sep 21 17:02:18 cdc0 kernel: drbd r0/0 drbd0 dh-cdc0-n3: Began resync as SyncSource (will sync 5144576 KB [1286144 bits set]).
Sep 21 17:02:19 cdc0 kernel: drbd r0 dh-cdc0-n2: Preparing remote state change 3124969320
Sep 21 17:02:19 cdc0 kernel: drbd r0 dh-cdc0-n2: Committing remote state change 3124969320 (primary_nodes=2)


I uninstalled the 9.0.22 kernel module rpm and compiled and installed the 9.0.25-1 version on all 4 nodes and resynced the partition(using 'drbdadm invalidate all' on the 3 secondary nodes) but I still see the FIXME messages:

Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0 dh-cdc0-n3: Preparing remote state change 3729689878
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0 dh-cdc0-n3: Committing remote state change 3729689878 (primary_nodes=2)
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n3: pdsk( UpToDate -> Consistent ) repl( Established -> StartingSyncS )
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n3: pdsk( Consistent -> Outdated )
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[27396] op clear, bitmap locked for 'set_n_write from StartingSync' by drbd_w_r0[24628]
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[27396] op clear, bitmap locked for 'set_n_write from StartingSync' by drbd_w_r0[24628]
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[27396] op clear, bitmap locked for 'set_n_write from StartingSync' by drbd_w_r0[24628]
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[27396] op clear, bitmap locked for 'set_n_write from StartingSync' by drbd_w_r0[24628]
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[27396] op clear, bitmap locked for 'set_n_write from StartingSync' by drbd_w_r0[24628]
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[27396] op clear, bitmap locked for 'set_n_write from StartingSync' by drbd_w_r0[24628]
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[27396] op clear, bitmap locked for 'set_n_write from StartingSync' by drbd_w_r0[24628]
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[27396] op clear, bitmap locked for 'set_n_write from StartingSync' by drbd_w_r0[24628]
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n3: helper command: /sbin/drbdadm before-resync-source
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n3: helper command: /sbin/drbdadm before-resync-source exit code 0
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n3: pdsk( Outdated -> Inconsistent ) repl( StartingSyncS -> SyncSource )
Oct  6 12:02:19 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n3: Began resync as SyncSource (will sync 5144576 KB [1286144 bits set]).
Oct  6 12:02:21 dh-cdc0-n1 kernel: drbd r0/0 drbd0: new current UUID: 76D23070780C9DB1 weak: FFFFFFFFFFFFFFE1
Oct  6 12:02:23 dh-cdc0-n1 crmd[24427]:  notice: State transition S_IDLE -> S_POLICY_ENGINE
Oct  6 12:02:23 dh-cdc0-n1 pengine[24426]:  notice: Calculated transition 3, saving inputs in /var/lib/pacemaker/pengine/pe-input-53.bz2
Oct  6 12:02:23 dh-cdc0-n1 crmd[24427]:  notice: Transition 3 (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-53.bz2): Complete
Oct  6 12:02:23 dh-cdc0-n1 crmd[24427]:  notice: State transition S_TRANSITION_ENGINE -> S_IDLE
Oct  6 12:02:24 dh-cdc0-n1 crmd[24427]:  notice: State transition S_IDLE -> S_POLICY_ENGINE
Oct  6 12:02:24 dh-cdc0-n1 pengine[24426]:  notice: Calculated transition 4, saving inputs in /var/lib/pacemaker/pengine/pe-input-54.bz2
Oct  6 12:02:24 dh-cdc0-n1 crmd[24427]:  notice: Transition 4 (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-54.bz2): Complete
Oct  6 12:02:24 dh-cdc0-n1 crmd[24427]:  notice: State transition S_TRANSITION_ENGINE -> S_IDLE
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0 dh-cdc0-n4: Preparing remote state change 1158604591
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0 dh-cdc0-n4: Committing remote state change 1158604591 (primary_nodes=2)
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n4: pdsk( UpToDate -> Consistent ) repl( Established -> StartingSyncS )
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n4: pdsk( Consistent -> Outdated )
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0/0 drbd0: FIXME drbd_a_r0[28404] op clear, bitmap locked for 'set_n_write from StartingSync' by drbd_w_r0[24628]
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0/0 drbd0: bitmap page idx 11 changed during IO!
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n4: helper command: /sbin/drbdadm before-resync-source
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n4: pdsk( Outdated -> Inconsistent )
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n4: helper command: /sbin/drbdadm before-resync-source exit code 0
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n4: repl( StartingSyncS -> SyncSource )
Oct  6 12:02:30 dh-cdc0-n1 kernel: drbd r0/0 drbd0 dh-cdc0-n4: Began resync as SyncSource (will sync 5144576 KB [1286144 bits set]).
Oct  6 12:02:36 dh-cdc0-n1 crmd[24427]:  notice: Current ping state: S_IDLE
Oct  6 12:02:40 dh-cdc0-n1 crmd[24427]:  notice: State transition S_IDLE -> S_POLICY_ENGINE
Oct  6 12:02:40 dh-cdc0-n1 pengine[24426]:  notice: Calculated transition 5, saving inputs in /var/lib/pacemaker/pengine/pe-input-55.bz2
Oct  6 12:02:40 dh-cdc0-n1 crmd[24427]:  notice: Transition 5 (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-55.bz2): Complete
Oct  6 12:02:40 dh-cdc0-n1 crmd[24427]:  notice: State transition S_TRANSITION_ENGINE -> S_IDLE
Oct  6 12:02:41 dh-cdc0-n1 kernel: drbd r0/0 drbd0: new current UUID: 6BB40F1CCF845C01 weak: FFFFFFFFFFFFFFE1

Are these messages a problem or just noise?

Regards,
Jeremy
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linbit.com/pipermail/drbd-user/attachments/20201007/808a5753/attachment-0001.htm>