The attached routine demonstrates some strange
behavior in the DLM and it was responsible for the
dmesg text at the end of this note.
This is on a FC2, SMP box running cvs/latest version of
cman and the dlm. Its a 2 CPU box configured with 4 logical
CPUs.
I have a two node cluster and the two machines are identical
as far as I can tell with the exception of which order they are
listed in the cluster config file.
On node #1 (in the config file) when I run the attached test from
two terminals the output looks reasonable. The same as it does if
I run it on Tru64 or VMS (more or less).
8923: over last 10.000 seconds, grant 8922, blkast 0, cancel 0
18730: over last 9.001 seconds, grant 9807, blkast 0, cancel 0
28403: over last 9.001 seconds, grant 9673, blkast 0, cancel 0
If you shut this down and start it up on node #2 (lx4) you start
to get messages that look like:
91280: over last 10.000 seconds, grant 91279, blkast 0, cancel 0
125138: NL Blocking Routine Start ^^^^^^^^^^^^^^^^^^^^^^^^^^
125138: NL Blocking Notification on lockid 0x00010312 (mode 0)
125138: NL Blocking Notification Rountine End ^^^^^^^^^^^^^^^^^^^^
141370: NL Blocking Routine Start ^^^^^^^^^^^^^^^^^^^^^^^^^^
141371: NL Blocking Notification on lockid 0x00010312 (mode 0)
141371: NL Blocking Notification Rountine End ^^^^^^^^^^^^^^^^^^^^
141373: NL Blocking Routine Start ^^^^^^^^^^^^^^^^^^^^^^^^^^
There are two strange things about this:
1) why does node #2 behave differently than node #1. I get the
same results if I reboot both nodes and only node #2
joins the cluster. This seems to imply that the nodes
aren't as identical as I think they are but... They are
running the same kernel build and the same source from
cvs (moved over as a tar file from one to another).
2) Why is a blocking ast routine associated with a NL lock
being triggered. The test code may be a bit hard to follow but
you can look at where this message comes from (nlblkrtn) and
where nlblkrtn is used (DLM_CVT requests to convert to NULL).
This looks like a race condition between queuing a new conversion
request and delivering a blocking AST on the existing lock. I'm
guessing that the conversion to NL is updating the AST pointers
at a time when the blocking AST can still be delivered for the
existing lock.
I tripped over this because do_dlm_dispatch() ends in
/* Call AST */
result.astaddr(result.astparam);
return 0;
and it doesn't check whether result.astaddr() is null or not.
Its not valid to have a NULL completion AST routine but it
is valid to have a NULL blocking AST routine. To go a bit
further, its pretty common to have a null blocking AST routine
on a conversion to NULL because the NULL lock can't block any
other locks.
dmesg output:
------------------------------------------------------------
CMAN: quorum regained, resuming activity
dlm: default: recover event 1 (first)
dlm: default: add nodes
dlm: got connection from 1
dlm: default: total nodes 2
dlm: default: rebuild resource directory
dlm: default: rebuilt 0 resources
dlm: default: recover event 1 done
dlm: default: recover event 1 finished
dlm: default: release lkb with status 3
dlm: lkb
id 102c9
remid 0
flags 4000
status 3
rqmode 5
grmode 3
nodeid 0
lqstate 0
lqflags 44
name "Test Lock" flags 4 nodeid 4294967295 ref 0
grant queue
000102c9 gr 5 rq -1 flg 24000 sts 2 node 0 remid 0 lq 0,44
est Lock"
default cv 5 102c9 "Test Lock"
default cv 3 1018a "Test Lock"
default cv 0 102c9 "Test Lock"
default cv 3 102c9 "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 102c9 "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 102c9 "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 102c9 "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 102c9 "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 102c9 "Test Lock"
default cv 5 1018a "Test Lock"
default un 1018a ref 1 flg 4 nodeid 0/-1 "Test Lock"
DLM: Assertion failed on line 64 of file /usr/src/cvs/cluster_orig/dlm-kernel/src/rsb.c
DLM: assertion: "list_empty(&r->res_grantqueue)"
DLM: time = 948604
name "Test Lock" flags 4 nodeid 4294967295 ref 0
convert queue
000102c9 gr 5 rq 0 flg 4000 sts 3 node 0 remid 0 lq 2,44
est Lock"
default cv 3 1018a "Test Lock"
default cv 0 102c9 "Test Lock"
default cv 3 102c9 "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 102c9 "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 102c9 "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 102c9 "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018adlm: rsb
name "Test Lock"
nodeid -1
flags 4
ref 0
"Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 1018a "Test Lock"
default cv 0 1018a "Test Lock"
default cv 3 102c9 "Test Lock"
default cv 3 1018a "Test Lock"
default cv 5 102c9 "Test Lock"
default cv 5 1018a "Test Lock"
default un 1018a ref 1 flg 4 nodeid 0/-1 "Test Lock"
default cv 0 102c9 "Test Lock"
DLM: Assertion failed on line 661 of file /usr/src/cvs/cluster_orig/dlm-kernel/src/lockqueue.c
DLM: assertion: "target_nodeid && target_nodeid != -1"
DLM: time = 948606
dlm: lkb
id 102c9
remid 0
flags 4000
status 3
rqmode 0
grmode 5
nodeid 0
lqstate 2
lqflags 44
dlm: rsb
name "Test Lock"
nodeid -1
flags 4
ref 0
target_nodeid 0
------------[ cut here ]------------
kernel BUG at /usr/src/cvs/cluster_orig/dlm-kernel/src/lockqueue.c:661!
invalid operand: 0000 [#1]
SMP
Modules linked in: dlm cman parport_pc lp parport autofs4 nfs lockd sunrpc e1000 3c59x floppy sg microcode dm_mod uhci_hcd button battery asus_acpi ac ipv6 ext3 jbd aic7xxx sd_mod scsi_mod
CPU: 2
EIP: 0060:[<f8ac7ae7>] Not tainted
EFLAGS: 00010246 (2.6.7-smp)
EIP is at send_cluster_request+0x577/0x590 [dlm]
eax: 00000001 ebx: f4442810 ecx: f40c5dec edx: 000059ab
esi: 00000000 edi: 00000295 ebp: f8ad6b48 esp: f40c5de8
ds: 007b es: 007b ss: 0068
Process cp (pid: 3565, threadinfo=f40c4000 task=f6cca1b0)
Stack: f8ad5994 00000000 f8ad6b48 f8ad6e54 000e797e f4442810 f7fcca00 f438f934
f4442810 f4442810 00000002 f438f934 f7fcca00 f8ac6510 f4442810 f7fcca80
f4442810 f7fcca80 f8ac58e4 f7fcca00 f8ad5871 00000000 000102c9 f438f9ad
Call Trace:
[<f8ac6510>] remote_stage+0x20/0x50 [dlm]
[<f8ac58e4>] convert_lock+0x1a4/0x1d0 [dlm]
[<f8ac4dc7>] dlm_lock+0x347/0x350 [dlm]
[<f8ac25b0>] ast_routine+0x0/0x150 [dlm]
[<f8ac2590>] bast_routine+0x0/0x20 [dlm]
[<f8ac31a3>] do_user_lock+0x123/0x220 [dlm]
[<f8ac25b0>] ast_routine+0x0/0x150 [dlm]
[<f8ac2590>] bast_routine+0x0/0x20 [dlm]
[<c012eb89>] sigprocmask+0x59/0xe0
[<f8ac33eb>] dlm_write+0xbb/0xe0 [dlm]
[<c015dab1>] vfs_write+0xd1/0x120
[<c015db98>] sys_write+0x38/0x60
[<c0106e3d>] sysenter_past_esp+0x52/0x71
Code: 0f 0b 95 02 48 6b ad f8 e9 09 fc ff ff e8 37 bd ff ff 89 c6
------------[ cut here ]------------
kernel BUG at /usr/src/cvs/cluster_orig/dlm-kernel/src/rsb.c:64!
invalid operand: 0000 [#2]
SMP
Modules linked in: dlm cman parport_pc lp parport autofs4 nfs lockd sunrpc e1000 3c59x floppy sg microcode dm_mod uhci_hcd button battery asus_acpi ac ipv6 ext3 jbd aic7xxx sd_mod scsi_mod
CPU: 3
EIP: 0060:[<f8ad405d>] Not tainted
EFLAGS: 00010246 (2.6.7-smp)
EIP is at _release_rsb+0x29d/0x2b0 [dlm]
eax: 00000001 ebx: f7fcca80 ecx: f6a93f40 edx: 000059af
esi: f438f934 edi: f7fcca00 ebp: 00000000 esp: f6a93f3c
ds: 007b es: 007b ss: 0068
Process dlm_astd (pid: 3404, threadinfo=f6a92000 task=f6af48c0)
Stack: f8ad640e 00000040 f8ad8370 f8ad83ec 000e797c f7fcca80 f4442ec4 f7fcca00
00000005 f8ac1465 f8adfa80 dd2514c0 000f431c f6d1e640 c2031ce0 f438f934
f7b83f58 f8ac2590 f8ac25b0 f8adfa68 f6a92000 f6a93fb4 f6a93fc0 f8ac1f5a
Call Trace:
[<f8ac1465>] process_asts+0xe5/0x1b0 [dlm]
[<f8ac2590>] bast_routine+0x0/0x20 [dlm]
[<f8ac25b0>] ast_routine+0x0/0x150 [dlm]
[<f8ac1f5a>] dlm_astd+0x29a/0x2b0 [dlm]
[<c0120550>] default_wake_function+0x0/0x10
[<c0106da2>] ret_from_fork+0x6/0x14
[<c0120550>] default_wake_function+0x0/0x10
[<f8ac1cc0>] dlm_astd+0x0/0x2b0 [dlm]
[<c01052b5>] kernel_thread_helper+0x5/0x10
Code: 0f 0b 40 00 70 83 ad f8 e9 43 ff ff ff 8d b6 00 00 00 00 31
[root@lx4
Attachment:
conv_play.c
Description: Binary data
