From issues-return-69821-archive-asf-public=cust-asf.ponee.io@ignite.apache.org Tue Jul 17 12:00:05 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 94C72180600 for ; Tue, 17 Jul 2018 12:00:04 +0200 (CEST) Received: (qmail 5947 invoked by uid 500); 17 Jul 2018 10:00:03 -0000 Mailing-List: contact issues-help@ignite.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@ignite.apache.org Delivered-To: mailing list issues@ignite.apache.org Received: (qmail 5937 invoked by uid 99); 17 Jul 2018 10:00:03 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 17 Jul 2018 10:00:03 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 3EC3BC0B4A for ; Tue, 17 Jul 2018 10:00:03 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -109.501 X-Spam-Level: X-Spam-Status: No, score=-109.501 tagged_above=-999 required=6.31 tests=[ENV_AND_HDR_SPF_MATCH=-0.5, KAM_ASCII_DIVIDERS=0.8, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, USER_IN_DEF_SPF_WL=-7.5, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id FSqBhdoLZ-pg for ; Tue, 17 Jul 2018 10:00:01 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id E31E85F1E3 for ; Tue, 17 Jul 2018 10:00:00 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 6E162E00C4 for ; Tue, 17 Jul 2018 10:00:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 3041623F96 for ; Tue, 17 Jul 2018 10:00:00 +0000 (UTC) Date: Tue, 17 Jul 2018 10:00:00 +0000 (UTC) From: "Maxim Muzafarov (JIRA)" To: issues@ignite.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Assigned] (IGNITE-7196) Exchange can stuck and wait while new node restoring state from disk and starting caches MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/IGNITE-7196?page=3Dcom.atlassi= an.jira.plugin.system.issuetabpanels:all-tabpanel ] Maxim Muzafarov reassigned IGNITE-7196: --------------------------------------- Assignee: Maxim Muzafarov > Exchange can stuck and wait while new node restoring state from disk and = starting caches > -------------------------------------------------------------------------= --------------- > > Key: IGNITE-7196 > URL: https://issues.apache.org/jira/browse/IGNITE-7196 > Project: Ignite > Issue Type: Bug > Components: cache > Affects Versions: 2.3 > Reporter: Mikhail Cherkasov > Assignee: Maxim Muzafarov > Priority: Critical > Fix For: 2.7 > > > Exchange can stuck and wait while new node restoring state from disk and = starting caches, there's a log snippet from a just joined new node that sho= ws the issue: > [21:36:13,023][INFO][exchange-worker-#62%statement_grid%][time] Started e= xchange init [topVer=3DAffinityTopologyVersion [topVer=3D57, minorTopVer=3D= 0], crd=3Dfalse, evt=3DNODE_JOINED, evtNode=3D3ac1160e-0de4-41bc-a366-59292= c9f03c1, customEvt=3Dnull, allowMerge=3Dtrue] > [21:36:13,023][INFO][exchange-worker-#62%statement_grid%][FilePageStoreMa= nager] Resolved page store work directory: /mnt/store/node00-d1eb270c-d2cc-= 4550-87aa-64f6df2a9463 > [21:36:13,024][INFO][exchange-worker-#62%statement_grid%][FileWriteAheadL= ogManager] Resolved write ahead log work directory: /mnt/wal/WAL/node00-d1e= b270c-d2cc-4550-87aa-64f6df2a9463 > [21:36:13,024][INFO][exchange-worker-#62%statement_grid%][FileWriteAheadL= ogManager] Resolved write ahead log archive directory: /mnt/wal/WAL_archive= /node00-d1eb270c-d2cc-4550-87aa-64f6df2a9463 > [21:36:13,046][INFO][exchange-worker-#62%statement_grid%][FileWriteAheadL= ogManager] Started write-ahead log manager [mode=3DDEFAULT] > [21:36:13,065][INFO][exchange-worker-#62%statement_grid%][PageMemoryImpl]= Started page memory [memoryAllocated=3D100.0 MiB, pages=3D6352, tableSize= =3D373.4 KiB, checkpointBuffer=3D100.0 MiB] > [21:36:13,105][INFO][exchange-worker-#62%statement_grid%][PageMemoryImpl]= Started page memory [memoryAllocated=3D32.0 GiB, pages=3D2083376, tableSiz= e=3D119.6 MiB, checkpointBuffer=3D896.0 MiB] > [21:36:13,428][INFO][exchange-worker-#62%statement_grid%][GridCacheDataba= seSharedManager] Read checkpoint status [startMarker=3D/mnt/store/node00-d1= eb270c-d2cc-4550-87aa-64f6df2a9463/cp/1512930965253-306c0895-1f5f-4237-bebf= -8bf2b49682af-START.bin, endMarker=3D/mnt/store/node00-d1eb270c-d2cc-4550-8= 7aa-64f6df2a9463/cp/1512930869357-1c24b6dc-d64c-4b83-8166-11edf1bfdad3-END.= bin] > [21:36:13,429][INFO][exchange-worker-#62%statement_grid%][GridCacheDataba= seSharedManager] Checking memory state [lastValidPos=3DFileWALPointer [idx= =3D3582, fileOffset=3D59186076, len=3D9229, forceFlush=3Dfalse], lastMarked= =3DFileWALPointer [idx=3D3629, fileOffset=3D50829700, len=3D9229, forceFlus= h=3Dfalse], lastCheckpointId=3D306c0895-1f5f-4237-bebf-8bf2b49682af] > [21:36:13,429][WARNING][exchange-worker-#62%statement_grid%][GridCacheDat= abaseSharedManager] Ignite node stopped in the middle of checkpoint. Will r= estore memory state and finish checkpoint on node start. > [21:36:18,312][INFO][grid-nio-worker-tcp-comm-0-#41%statement_grid%][TcpC= ommunicationSpi] Accepted incoming communication connection [locAddr=3D/172= .31.20.209:48100, rmtAddr=3D/172.31.17.115:57148] > [21:36:21,619][INFO][exchange-worker-#62%statement_grid%][GridCacheDataba= seSharedManager] Found last checkpoint marker [cpId=3D306c0895-1f5f-4237-be= bf-8bf2b49682af, pos=3DFileWALPointer [idx=3D3629, fileOffset=3D50829700, l= en=3D9229, forceFlush=3Dfalse]] > [21:36:21,620][INFO][exchange-worker-#62%statement_grid%][GridCacheDataba= seSharedManager] Finished applying memory changes [changesApplied=3D165103,= time=3D8189ms] > [21:36:22,403][INFO][grid-nio-worker-tcp-comm-1-#42%statement_grid%][TcpC= ommunicationSpi] Accepted incoming communication connection [locAddr=3D/172= .31.20.209:48100, rmtAddr=3D/172.31.28.10:47964] > [21:36:23,414][INFO][grid-nio-worker-tcp-comm-2-#43%statement_grid%][TcpC= ommunicationSpi] Accepted incoming communication connection [locAddr=3D/172= .31.20.209:48100, rmtAddr=3D/172.31.27.101:46000] > [21:36:33,019][WARNING][main][GridCachePartitionExchangeManager] Failed t= o wait for initial partition map exchange. Possible reasons are: > ^-- Transactions in deadlock. > ^-- Long running transactions (ignore if this is the case). > ^-- Unreleased explicit locks. > [21:36:53,021][WARNING][main][GridCachePartitionExchangeManager] Still wa= iting for initial partition map exchange [fut=3DGridDhtPartitionsExchangeFu= ture [firstDiscoEvt=3DDiscoveryEvent [evtNode=3DTcpDiscoveryNode [id=3D3ac1= 160e-0de4-41bc-a366-59292c9f03c1, addrs=3D[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 1= 72.31.20.209], sockAddrs=3D[/0:0:0:0:0:0:0:1%lo:48500, /127.0.0.1:48500, ip= -172-31-20-209.eu-central-1.compute.internal/172.31.20.209:48500], discPort= =3D48500, order=3D57, intOrder=3D36, lastExchangeTime=3D1512931012268, loc= =3Dtrue, ver=3D2.3.1#20171129-sha1:4b1ec0fe, isClient=3Dfalse], topVer=3D57= , nodeId8=3D3ac1160e, msg=3Dnull, type=3DNODE_JOINED, tstamp=3D151293097299= 2], crd=3DTcpDiscoveryNode [id=3D56c97317-26cf-43d2-bf76-0cab59c6fa5f, addr= s=3D[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 172.31.27.101], sockAddrs=3D[/0:0:0:0:0= :0:0:1%lo:48500, /127.0.0.1:48500, ip-172-31-27-101.eu-central-1.compute.in= ternal/172.31.27.101:48500], discPort=3D48500, order=3D1, intOrder=3D1, las= tExchangeTime=3D1512930972830, loc=3Dfalse, ver=3D2.3.1#20171129-sha1:4b1ec= 0fe, isClient=3Dfalse], exchId=3DGridDhtPartitionExchangeId [topVer=3DAffin= ityTopologyVersion [topVer=3D57, minorTopVer=3D0], discoEvt=3DDiscoveryEven= t [evtNode=3DTcpDiscoveryNode [id=3D3ac1160e-0de4-41bc-a366-59292c9f03c1, a= ddrs=3D[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 172.31.20.209], sockAddrs=3D[/0:0:0:= 0:0:0:0:1%lo:48500, /127.0.0.1:48500, ip-172-31-20-209.eu-central-1.compute= .internal/172.31.20.209:48500], discPort=3D48500, order=3D57, intOrder=3D36= , lastExchangeTime=3D1512931012268, loc=3Dtrue, ver=3D2.3.1#20171129-sha1:4= b1ec0fe, isClient=3Dfalse], topVer=3D57, nodeId8=3D3ac1160e, msg=3Dnull, ty= pe=3DNODE_JOINED, tstamp=3D1512930972992], nodeId=3D3ac1160e, evt=3DNODE_JO= INED], added=3Dtrue, initFut=3DGridFutureAdapter [ignoreInterrupts=3Dfalse,= state=3DINIT, res=3Dnull, hash=3D820635914], init=3Dfalse, lastVer=3Dnull,= partReleaseFut=3Dnull, exchActions=3Dnull, affChangeMsg=3Dnull, initTs=3D1= 512930973012, centralizedAff=3Dfalse, changeGlobalStateE=3Dnull, done=3Dfal= se, state=3DSRV, evtLatch=3D0, remaining=3D[eac777d5-281b-4a2e-a743-c585a08= bfc68, ee15ea85-f5f6-4513-871e-7b4b080911cf, 56c97317-26cf-43d2-bf76-0cab59= c6fa5f, f87821f1-e4d9-49b9-9dab-39ee6a620b87, 853066b2-fb70-475e-8a77-b41f1= 80df164, 979e0b69-05db-4652-98f2-a59c8f56acf8, 11c1f792-92cb-44a5-a481-1aa8= cd257aef], super=3DGridFutureAdapter [ignoreInterrupts=3Dfalse, state=3DINI= T, res=3Dnull, hash=3D542833742]]] > [21:37:12,866][INFO][exchange-worker-#62%statement_grid%][GridCacheDataba= seSharedManager] Checkpoint finished [cpId=3D306c0895-1f5f-4237-bebf-8bf2b4= 9682af, pages=3D157778, markPos=3DFileWALPointer [idx=3D3629, fileOffset=3D= 50829700, len=3D9229, forceFlush=3Dfalse], pagesWrite=3D5460ms, fsync=3D457= 81ms, total=3D51241ms] > [21:37:12,878][INFO][exchange-worker-#62%statement_grid%][FileWriteAheadL= ogManager] Resuming logging to WAL segment [file=3D/mnt/wal/WAL/node00-d1eb= 270c-d2cc-4550-87aa-64f6df2a9463/0000000000000009.wal, offset=3D50838929, v= er=3D1] > [21:37:13,028][WARNING][main][GridCachePartitionExchangeManager] Still wa= iting for initial partition map exchange [fut=3DGridDhtPartitionsExchangeFu= ture [firstDiscoEvt=3DDiscoveryEvent [evtNode=3DTcpDiscoveryNode [id=3D3ac1= 160e-0de4-41bc-a366-59292c9f03c1, addrs=3D[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 1= 72.31.20.209], sockAddrs=3D[/0:0:0:0:0:0:0:1%lo:48500, /127.0.0.1:48500, ip= -172-31-20-209.eu-central-1.compute.internal/172.31.20.209:48500], discPort= =3D48500, order=3D57, intOrder=3D36, lastExchangeTime=3D1512931032324, loc= =3Dtrue, ver=3D2.3.1#20171129-sha1:4b1ec0fe, isClient=3Dfalse], topVer=3D57= , nodeId8=3D3ac1160e, msg=3Dnull, type=3DNODE_JOINED, tstamp=3D151293097299= 2], crd=3DTcpDiscoveryNode [id=3D56c97317-26cf-43d2-bf76-0cab59c6fa5f, addr= s=3D[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 172.31.27.101], sockAddrs=3D[/0:0:0:0:0= :0:0:1%lo:48500, /127.0.0.1:48500, ip-172-31-27-101.eu-central-1.compute.in= ternal/172.31.27.101:48500], discPort=3D48500, order=3D1, intOrder=3D1, las= tExchangeTime=3D1512930972830, loc=3Dfalse, ver=3D2.3.1#20171129-sha1:4b1ec= 0fe, isClient=3Dfalse], exchId=3DGridDhtPartitionExchangeId [topVer=3DAffin= ityTopologyVersion [topVer=3D57, minorTopVer=3D0], discoEvt=3DDiscoveryEven= t [evtNode=3DTcpDiscoveryNode [id=3D3ac1160e-0de4-41bc-a366-59292c9f03c1, a= ddrs=3D[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 172.31.20.209], sockAddrs=3D[/0:0:0:= 0:0:0:0:1%lo:48500, /127.0.0.1:48500, ip-172-31-20-209.eu-central-1.compute= .internal/172.31.20.209:48500], discPort=3D48500, order=3D57, intOrder=3D36= , lastExchangeTime=3D1512931032324, loc=3Dtrue, ver=3D2.3.1#20171129-sha1:4= b1ec0fe, isClient=3Dfalse], topVer=3D57, nodeId8=3D3ac1160e, msg=3Dnull, ty= pe=3DNODE_JOINED, tstamp=3D1512930972992], nodeId=3D3ac1160e, evt=3DNODE_JO= INED], added=3Dtrue, initFut=3DGridFutureAdapter [ignoreInterrupts=3Dfalse,= state=3DINIT, res=3Dnull, hash=3D820635914], init=3Dfalse, lastVer=3Dnull,= partReleaseFut=3Dnull, exchActions=3Dnull, affChangeMsg=3Dnull, initTs=3D1= 512930973012, centralizedAff=3Dfalse, changeGlobalStateE=3Dnull, done=3Dfal= se, state=3DSRV, evtLatch=3D0, remaining=3D[eac777d5-281b-4a2e-a743-c585a08= bfc68, ee15ea85-f5f6-4513-871e-7b4b080911cf, 56c97317-26cf-43d2-bf76-0cab59= c6fa5f, f87821f1-e4d9-49b9-9dab-39ee6a620b87, 853066b2-fb70-475e-8a77-b41f1= 80df164, 979e0b69-05db-4652-98f2-a59c8f56acf8, 11c1f792-92cb-44a5-a481-1aa8= cd257aef], super=3DGridFutureAdapter [ignoreInterrupts=3Dfalse, state=3DINI= T, res=3Dnull, hash=3D542833742]]] > [21:37:13,116][INFO][exchange-worker-#62%statement_grid%][GridCacheProces= sor] Started cache [name=3Dignite-sys-cache, memoryPolicyName=3DsysMemPlc, = mode=3DREPLICATED, atomicity=3DTRANSACTIONAL] > [21:37:13,125][INFO][exchange-worker-#62%statement_grid%][GridCacheProces= sor] Started cache [name=3Dstatementp, memoryPolicyName=3DDefault_Region, m= ode=3DPARTITIONED, atomicity=3DTRANSACTIONAL] > [21:37:13,131][INFO][exchange-worker-#62%statement_grid%][GridDhtPartitio= nsExchangeFuture] Finished waiting for partition release future [topVer=3DA= ffinityTopologyVersion [topVer=3D57, minorTopVer=3D0], waitTime=3D0ms, futI= nfo=3DNA] > [21:37:13,133][INFO][exchange-worker-#62%statement_grid%][GridCacheDataba= seSharedManager] Read checkpoint status [startMarker=3D/mnt/store/node00-d1= eb270c-d2cc-4550-87aa-64f6df2a9463/cp/1512930965253-306c0895-1f5f-4237-bebf= -8bf2b49682af-START.bin, endMarker=3D/mnt/store/node00-d1eb270c-d2cc-4550-8= 7aa-64f6df2a9463/cp/1512930965253-306c0895-1f5f-4237-bebf-8bf2b49682af-END.= bin] > [21:37:13,134][INFO][exchange-worker-#62%statement_grid%][GridCacheDataba= seSharedManager] Applying lost cache updates since last checkpoint record [= lastMarked=3DFileWALPointer [idx=3D3629, fileOffset=3D50829700, len=3D9229,= forceFlush=3Dfalse], lastCheckpointId=3D306c0895-1f5f-4237-bebf-8bf2b49682= af] > [21:37:13,738][INFO][exchange-worker-#62%statement_grid%][GridCacheDataba= seSharedManager] Finished applying WAL changes [updatesApplied=3D0, time=3D= 607ms] > [21:37:13,749][INFO][exchange-worker-#62%statement_grid%][time] Finished = exchange init [topVer=3DAffinityTopologyVersion [topVer=3D57, minorTopVer= =3D0], crd=3Dfalse] > [21:37:13,782][INFO][sys-#72%statement_grid%][GridDhtPartitionsExchangeFu= ture] Received full message, will finish exchange [node=3D56c97317-26cf-43d= 2-bf76-0cab59c6fa5f, resVer=3DAffinityTopologyVersion [topVer=3D57, minorTo= pVer=3D0]] > [21:37:13,796][INFO][grid-nio-worker-tcp-comm-4-#45%statement_grid%][TcpC= ommunicationSpi] Accepted incoming communication connection [locAddr=3D/172= .31.20.209:48100, rmtAddr=3D/172.31.24.98:58928] > [21:37:13,796][INFO][grid-nio-worker-tcp-comm-3-#44%statement_grid%][TcpC= ommunicationSpi] Accepted incoming communication connection [locAddr=3D/172= .31.20.209:48100, rmtAddr=3D/172.31.27.95:52532] > [21:37:13,804][INFO][grid-nio-worker-tcp-comm-5-#46%statement_grid%][TcpC= ommunicationSpi] Accepted incoming communication connection [locAddr=3D/172= .31.20.209:48100, rmtAddr=3D/172.31.17.174:54358] > [21:37:13,805][INFO][grid-nio-worker-tcp-comm-6-#47%statement_grid%][TcpC= ommunicationSpi] Accepted incoming communication connection [locAddr=3D/172= .31.20.209:48100, rmtAddr=3D/172.31.23.109:42528] > [21:37:17,569][INFO][sys-#72%statement_grid%][GridDhtPartitionsExchangeFu= ture] Finish exchange future [startVer=3DAffinityTopologyVersion [topVer=3D= 57, minorTopVer=3D0], resVer=3DAffinityTopologyVersion [topVer=3D57, minorT= opVer=3D0], err=3Dnull] -- This message was sent by Atlassian JIRA (v7.6.3#76005)