[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]

[Linux-cluster] Strange behavior(s) of DLM



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


[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]