Error calling the central lock handler

[former_member211576]

Hi experts,

Symptom 1: I found a lot of error messages in screenshot 1

Symptom 2: I can't run ensmon like screenshot 2

Symptom 3: enqueue statistic is ok in SAPMMC

Questions: Is enqueue server alive or not? How do I eliminate the error messages: Error calling the central lock handler.

By the way, I have checked the note: 79084 and it is not useful. My kernel is 721_EXT and patch level is 324

---------------------------------------------------

trc file: "dev_ensmon", trc level: 3, release: "721"

---------------------------------------------------

Sun Oct 19 17:37:34 2014

EncCliInit: enque/con_timeout = 5000, enque/con_retries 60, slots: 3

EnsaCliRegisterCom: new connection layer EncCli registered in slot 0

EncCliCon: get slot for con to tccprd1/sapdp00

EnsaCliICreateHandle: inserted new slot 0 (default connection/tccprd1/sapdp00) with layer 0 (EncCli)

EncCliBuf: allocate 79 bytes for con 0

EnsaCliGetBuffer: got 19(19) bytes for handle 0(0) from layer 0(EncCli) at 0000000003505FE4

EncCliReq: connected to host tccprd1, service sapdp00

EncCliReq: sent request (47 bytes) on connection 0

EncCliReq: received 1 fragments (27 bytes) (message complete)

EncCliDisconnect: freed buffer 0000000003505FB0

EncCliDisconnect: closed connection 0000000003593940

EncCliDisconnect: deallocated client 0

EnsaCliCloseConnection: closed connection 0 (default connection/tccprd1/sapdp00) in layer 0/EncCli)

simple request)

EnsMonMenu:registerGlobalOpcode: try to register action Reload Enqueue Server ACL file (simple request) for opcode 4

EnsMonMenu:addAction: added action 5: get Enqueue Server ACL status

EnsMonMenu:registerGlobalOpcode: try to register action get Enqueue Server ACL status for opcode 5

EnsMonMenu:addAction: added action 6: dump Enqueue Server ACL

EnsMonMenu:registerGlobalOpcode: try to register action dump Enqueue Server ACL for opcode 6

EnsMonMenu:addAction: added action 7: Get information about all enqueue server threads

EnsMonMenu:registerGlobalOpcode: try to register action Get information about all enqueue server threads for opcode 7

EnsMonMenu:addAction: added action 8: Get information about enqueue memory

EnsMonMenu:registerGlobalOpcode: try to register action Get information about enqueue memory for opcode 8

EnsMonMenu:addAction: added action 9: dump Enqueue Parameter

EnsMonMenu:registerGlobalOpcode: try to register action dump Enqueue Parameter for opcode 9

EnsMonInitialize: server hostname tccprd1 specified

EnsMonInitialize: server instance 00 specified

EnsMonInitialize: opcode = 1 (1)

EnsMonInitialize: 1 parameters to opcode:

     0: 1

NiIInit: allocated nitab (2048 at 000000000350CBD0)

NiIHSBufInit: initialize hostname buffer (IPv4)

NiHLInit: alloc host buf (100 entries)

NiSrvLInit: alloc serv bufs (100 entries)

addrinfo of 'tccprd1':

0: 10.243.23.244:0 'tccprd1' <unknown socket type 0> (0-2-0-0-16)

NiHLGetNodeAddr: got hostname 'tccprd1' from operating system

NiIGetNodeAddr: hostname 'tccprd1' = addr 10.243.23.244

addrinfo of 'sapdp00':

0: ::1.3200 STREAM (0-23-1-0-28)

1: 127.0.0.1:3200 STREAM (0-2-1-0-16)

NiSrvLGetServNo: got service name 'sapdp00' from operating system

NiIGetServNo: servicename 'sapdp00' = port 3200

EncCliSetParameter: set con-retries for handle 0 to 1

EnsMonMenu:executeOpcode: execute opcode 1 ==> action Dummy request

  1 parameters:

   <1>

NiICreateHandle: hdl 1 state NI_INITIAL_CON

NiIInitSocket: set default settings for new hdl 1/sock 320 (I4; ST)

NiIBlockMode: set blockmode for hdl 1 FALSE

NiITraceByteOrder: CPU byte order: little endian, reverse network, low val .. high val

NiIConnectSocket: hdl 1 is connecting to 10.243.23.244:3200 (timeout=5000)

SiPeekPendConn: connection of sock 320 established

NiICheckPendConnection: connection of hdl 1 to 10.243.23.244:3200 established

NiIConnect: hdl 1 took local address 10.243.23.16:49474

NiIConnect: state of hdl 1 NI_CONNECTED

NiBufIHdlInit: init for hdl 1

NiMyHostName: hostname = 'dl980-3'

EncDefaultName: set EncLocalName to dl980-3_14168_1

EncPack: UcsToUtf8s (dl980-3_14168_1) written 16 bytes

LOCAL UNICODE = 1

SND: <I=0, M=0xABCDE123, D=CONNECTION_ADM, T=SYNC_REQUEST, MF=NO, len=88/88>

Adresse   Offset  EncMsgTrc

------------------------------------------------------------------------

000000000293F4F0  000000  00000000 00000000 88130000 00000000 |................|

000000000293F500  000016  00000000 00000006 00000000 00040000 |................|

000000000293F510  000032  00000001 00040000 00000003 646c3938 |............dl98|

000000000293F520  000048  302d335f 31343136 385f3100 00000002 |0-3_14168_1.....|

000000000293F530  000064  0000003b 00000005 00000003 00000006 |...;............|

000000000293F540  000080  00000004 00000001                   |........        |

------------------------------------------------------------------------

NiBufIWrite starting

NiIWrite: hdl 1 sent data (wrt=88,pac=1,MESG_IO)

NiIRead: hdl 1 recv would block (errno=EAGAIN)

NiIPeek: peek successful for hdl 1 (r)

NiBufIAlloc: malloc NIBUF-IN, to 93 bytes

NiIRead: hdl 1 received data (rcd=93,pac=1,MESG_IO)

NiBufIIn: NIBUF len=93

NiBufIIn: packet complete for hdl 1

NiBufReceive starting

EncFragRecv: using copy mode for connection 0000000003593940

RCV: <I=0, M=0xABCDE123, D=CONNECTION_ADM, T=RESPONSE, MF=NO, len=93/93>

Adresse   Offset  EncMsgTrc

------------------------------------------------------------------------

000000000293F4E0  000000  abcde123 00000000 0000005d 0000005d |...#.......]...]|

000000000293F4F0  000016  06020002 00000006 00000000 00040000 |................|

000000000293F500  000032  00000001 00040000 00000003 646c3938 |............dl98|

000000000293F510  000048  302d335f 494f5468 72656164 5f305f31 |0-3_IOThread_0_1|

000000000293F520  000064  00000000 02000000 3b000000 05000000 |........;.......|

000000000293F530  000080  03000000 06000000 04000000 01       |.............   |

------------------------------------------------------------------------

EncFragRecv: handle opcode ENC Parameter Response

EncOAMParamParse: posistion 12, rest 61, param ENCPARAM_RECV_LEN

EncOAMParamParse: posistion 20, rest 53, param ENCPARAM_SEND_LEN

EncUnpack: Utf8sToUcs (dl980-3_IOThread_0_1) read 21 bytes (count = 21)

EncOAMParamParse: posistion 45, rest 28, param ENCPARAM_SET_NAME

EncOAMParamParse: posistion 53, rest 20, param ENCPARAM_MSG_TYPE

EncOAMParamParse: posistion 61, rest 12, param ENCPARAM_SET_VERSION

EncOAMParamParse: posistion 73, rest 0, param ENCPARAM_SET_UCSUPPORT

EncIDoOAMReq: read parameter max_recv_frag 262144

EncIDoOAMReq: read parameter max_send_frag 262144

EncIDoOAMReq: read parameter remote name dl980-3_IOThread_0_1

EncIDoOAMReq: read parameter remote msg types 59

EncIDoOAMReq: read parameter remote version 3

EncIDoOAMReq: read parameter remote unicode support YES

EncRecvParams: negotiation successful: recv_frag 262144, send_frag 262144

SND: <I=1, M=0xABCDE123, D=SERVER_ADMIN, T=SYNC_REQUEST, MF=NO, len=47/47>

Adresse   Offset  EncMsgTrc

------------------------------------------------------------------------

0000000003505FD0  000000  f000d502 00000000 f000d502 00000000 |................|

0000000003505FE0  000016  60004c03 454e4300 01010003 23454141 |`.L.ENC.....#EAA|

0000000003505FF0  000032  01000000 13010000 00000023 454145   |...........#EAE |

------------------------------------------------------------------------

NiBufIWrite starting

NiIWrite: hdl 1 sent data (wrt=47,pac=1,MESG_IO)

NiIRead: hdl 1 recv would block (errno=EAGAIN)

NiIPeek: peek successful for hdl 1 (r)

NiBufIAlloc: malloc NIBUF-IN, to 47 bytes

NiIRead: hdl 1 received data (rcd=47,pac=1,MESG_IO)

NiBufIIn: NIBUF len=47

NiBufIIn: packet complete for hdl 1

NiBufReceive starting

EncFragRecv: using copy mode for connection 0000000003593940

RCV: <I=1, M=0xABCDE123, D=SYNC_ENQUE, T=SYNC_REQUEST, MF=NO, len=47/47>

Adresse   Offset  EncMsgTrc

------------------------------------------------------------------------

0000000003505FD0  000000  abcde123 00000001 0000002f 0000002f |...#......./.../|

0000000003505FE0  000016  01000000 454e4300 01010003 23454141 |....ENC.....#EAA|

0000000003505FF0  000032  01000000 13012000 00000023 454145   |...... ....#EAE |

------------------------------------------------------------------------

rc of EnsMonMenu:executeOpcode: 0

NiICloseHandle: shutdown and close hdl 1/sock 320

NiBufIClose: clear extension for hdl 1

[alwina_enns · Accepted solution]

Hello Dennis,

try to execute

SM12 --> Extras --> Diagnosis

and

SM12 --> Extras --> Diagnosis in Update

Does it return errors?

Regards,
Alwina

[former_member211576 · Accepted solution]

Hi Alwina,

  No errors found.

By the way, the last time I solved this issue is to update kernel, especially enserver.exe.

---

MMC SnapIn:

C:\Windows\system32\sapmmc.dll: 720, patch 415, changelist 1393508, optU (EXT), NTAMD64, 2013 02 13 03:39:20

C:\Windows\system32\sapmmcada.dll: 720, patch 415, changelist 1393508, optU (EXT), NTAMD64, 2013 02 13 03:39:22

C:\Windows\system32\sapmmcdb6.dll: 720, patch 415, changelist 1393508, optU (EXT), NTAMD64, 2013 02 13 03:39:36

C:\Windows\system32\sapmmcms.dll: 720, patch 415, changelist 1393508, optU (EXT), NTAMD64, 2013 02 13 03:39:22

TCP <hostname> 0:

S:\usr\sap\TCP\ASCS00\exe\sapstartsrv.exe: 721, patch 324, changelist 1522267, optU (EXT), NTAMD64, 2014 09 06 15:56:13

S:\usr\sap\TCP\ASCS00\exe\disp+work.exe: 721, patch 324, changelist 1522267, optU (EXT), NTAMD64, 2014 09 06 15:56:07

S:\usr\sap\TCP\ASCS00\exe\gwrd.exe: 721, patch 324, changelist 1522267, optU (EXT), NTAMD64, 2014 09 06 15:56:09

S:\usr\sap\TCP\ASCS00\exe\msg_server.exe: 721, patch 324, changelist 1522267, optU (EXT), NTAMD64, 2014 09 06 15:56:12

S:\usr\sap\TCP\ASCS00\exe\dboraslib.dll: 721, patch 300, changelist 1498740, optU (EXT), NTAMD64, 2014 05 26 10:11:10

S:\usr\sap\TCP\ASCS00\exe\dbmssslib.dll: 721, patch 316, changelist 1510772, optU (EXT), NTAMD64, 2014 07 17 03:23:41

S:\usr\sap\TCP\ASCS00\exe\dbdb2slib.dll: 721, patch 300, changelist 1498740, optU (EXT), NTAMD64, 2014 05 26 10:11:07

S:\usr\sap\TCP\ASCS00\exe\dbdb4slib.dll: 721, patch 300, changelist 1498740, optU (EXT), NTAMD64, 2014 05 26 10:11:08

S:\usr\sap\TCP\ASCS00\exe\dbdb6slib.dll: 721, patch 300, changelist 1498740, optU (EXT), NTAMD64, 2014 05 26 10:11:09

S:\usr\sap\TCP\ASCS00\exe\dbsybslib.dll: 721, patch 300, changelist 1498740, optU (EXT), NTAMD64, 2014 05 26 10:11:11

S:\usr\sap\TCP\ASCS00\exe\enserver.exe: 721, patch 323, changelist 1520995, optU (EXT), NTAMD64, 2014 09 01 02:39:52

S:\usr\sap\TCP\ASCS00\exe\icman.exe: 721, patch 324, changelist 1522267, optU (EXT), NTAMD64, 2014 09 06 15:56:09

S:\usr\sap\TCP\ASCS00\exe\sapwebdisp.exe: 721, patch 324, changelist 1522267, optU (EXT), NTAMD64, 2014 09 06 15:56:14

S:\usr\sap\TCP\ASCS00\exe\jcontrol.exe: 721, patch 324, changelist 1522267, optU (EXT), NTAMD64, 2014 09 06 15:56:10

S:\usr\sap\TCP\ASCS00\exe\jlaunch.exe: 721, patch 324, changelist 1522267, optU (EXT), NTAMD64, 2014 09 06 15:56:11

S:\usr\sap\TCP\ASCS00\exe\jstart.exe: 721, patch 324, changelist 1522267, optU (EXT), NTAMD64, 2014 09 06 15:56:12

[alwina_enns · Accepted solution]

Hello Dennis,

please check also dispatcher trace dev_disp and message server trace dev_ms for any connection errors at the time, when you have got the errors. The communication to the enqueue service would be:

work process --> dispatcher --> message server --> enqueue

Do you see any connection errors in the traces of all communication partners (dev_w*, dev_disp, dev_ms, dev_enq)?

Regards,
Alwina

[former_member211576 · Accepted solution]

Hi Alwina,

  Nothing particular in dev_ensmon, dev_disp, disp_ms but I found an error message in dev_w15. Does this mean a network issue? So niping to monitor?

---

M 

M Wed Oct 29 09:53:00 2014

M  ***LOG Q0I=> NiIRead: P=10.243.23.244:3200; L=10.243.23.118:60750: recv (10054: WSAECONNRESET: Connection reset by peer) [nixxi.cpp 5082]

M  *** ERROR => NiIRead: SiRecv failed for hdl 22/sock 300

    (SI_ECONN_BROKEN/10054; I4; ST; P=10.243.23.244:3200; L=10.243.23.118:60750) [nixxi.cpp    5082]

M  {root-id=E41F131898CE1EE497E1437FA8F7AC64}_{conn-id=00000000000000000000000000000000}_0

E  *** ERROR => EncCliIConnect: failed to connect to enqueue server at tccprd1/sapdp00 through layer EncCli (rc=-3) [enccli.c     1085]

E  {root-id=E41F131898CE1EE497E1437FA8F7AC64}_{conn-id=00000000000000000000000000000000}_0

E  *** ERROR => EncCliReq: failed to connect to server [enccli.c     507]

E  {root-id=E41F131898CE1EE497E1437FA8F7AC64}_{conn-id=00000000000000000000000000000000}_0

E  *** ERROR => EnsaCliDoRequest: DoRequest failed (rc=107): 412 bytes on con. 0 in layer 0 (EncCli) (1/1) [ensacli.c    406]

E  {root-id=E41F131898CE1EE497E1437FA8F7AC64}_{conn-id=00000000000000000000000000000000}_0

E  *** ERROR => ENSA_DoRequest(): Error 7 returned from EncCliReq() [ensaclnt.c   1761]

E  {root-id=E41F131898CE1EE497E1437FA8F7AC64}_{conn-id=00000000000000000000000000000000}_0

E  *** ERROR => Enqueue: ENSA_DoRequest() errror 8 [enxxhead.c   3239]

E  {root-id=E41F131898CE1EE497E1437FA8F7AC64}_{conn-id=00000000000000000000000000000000}_0

M  ***LOG GI0=>  [enctrl.c     2395]

M  ***LOG GI4=>   [enctrl.c     2395]

E  *** ERROR => DequeAll() failed. Returncode = 8 [enctrl.c     2397]

E  {root-id=E41F131898CE1EE497E1437FA8F7AC64}_{conn-id=00000000000000000000000000000000}_0

E  *** ERROR => Owner = 20141029092257932000031545tccap45........................., ReturnCode = 8 [enctrl.c     2399]

E  {root-id=E41F131898CE1EE497E1437FA8F7AC64}_{conn-id=00000000000000000000000000000000}_0

[alwina_enns · Accepted solution]

Hello Dennis,

could you please check also all traces in the working directory of the enqueue server (dev_enqsrv for example), do you see some more information at the same time like in dev_w15 " Wed Oct 29 09:53:00 2014", if it was a problem with the enqueue server, or if you see also messages like "connection reset by peer"? It could be many reasons for this issue (settings for the enqueue server, a bug, settings on OS level), network is one of them, probably you can find in the traces of the enqueue server a hint. The work process has noticed only, that the connection is closed suddenly.

Regards,
Alwina

[former_member211576 · Accepted solution]

Hi Alwina,

   I found there are a lot of "WARNING => NiICreateHandle: no more free handles" in dev_enqlisten but I have increase RFC connection in the profile like below.

---------------------------------------------------

trc file: "dev_enqlisten", trc level: 1, release: "721"

---------------------------------------------------

sysno      00

sid        TCP

systemid   562 (PC with Windows NT)

relno      7210

patchlevel 0

patchno    317

intno      20020600

make       multithreaded, Unicode, 64 bit, optimized

pid        14116

[Thr 14248] Wed Oct 29 09:52:58 2014

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] Wed Oct 29 09:52:59 2014

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] Wed Oct 29 09:53:00 2014

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] Wed Oct 29 09:53:02 2014

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] Wed Oct 29 09:53:03 2014

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

[Thr 14248] *** WARNING => NiICreateHandle: no more free handles (1011) [nixxi.cpp    466]

-------------

# Gateway Parameters

gw/max_conn = 2000

gw/max_overflow_size = 25000000

gw/max_sys = 2000

gw/acl_mode = 1

rdisp/appc_ca_blk_no = 2000

rdisp/bufrefmode = sendon,exeauto

rdisp/max_arq = 2000

rdisp/max_comm_entries = 2000

rdisp/plugin_auto_logout = 1800

rdisp/tm_max_no = 2000

rdisp/wp_ca_blk_no = 2000

rdisp/rfc_min_wait_dia_wp = 10

rdisp/rfc_check = 3

[alwina_enns · Accepted solution]

Hello Dennis,

yes, most likely this warning is the cause. Could you please check the value for parameter enque/server/max_client?

Regards,
Alwina

[former_member211576 · Accepted solution]

Hi Alwina,

enque/server/max_clients = 1000(default).

[alwina_enns · Accepted solution]

Hello Dennis,

I think this parameter has limited connections to the enqueue server. In the warning you see:

no more free handles (1011)

1011 - number of used handles

You need to increase the value for enque/server/max_clients. How many work processes has the affected system? As per note "2013043 - Performance Problems with Enqueue Work Process" this value should be at least the same as total number of the work processes in the system. You may need to check also other enqueue server parameters as described in this note.

Regards,
Alwina

[former_member211576 · Accepted solution]

Hi Alwina,

  1) 17 * 59 = 1003 work processes.

  2) I have increased enque/server/max_clients = 1500

  3) I restarted <SID>_ERS_10 on both nodes at 10/28 13:54 and the problem disappears all of a            sudden. That's weird. enrepserver.exe and enserver.exe are two different processes, aren't they?

  4)By the way, SAP recommends to set (note 1903553)

    enque/snapshot_pck_size = 50000

    enque/snapshot_pck_ids = 10000

[alwina_enns · Accepted solution]

Hello Dennis,

I'm glad to hear that the issue is resolved 🙂

Yes, enrepserver.exe and enserver.exe are 2 different ptocesses, enrepserver.exe is the enqueue replication server, enserver.exe is the enqueue server.

Regards,
Alwina

[Former Member]

Hi Mate,

Check your network connection during that time, in our case 70% time it was the network when for few secs the connection was getting timed out and the apps were not able to access the enqueue server resulting this locks.

You can try monitoring the using niping(sap's own ping tool) and try to find if there is any network issues.

In our case we had this issue when the infra team had implemented so VM stuff which created temp load on VM side and due to that the server was not responding for that fraction of secs,.