From issues-return-55483-archive-asf-public=cust-asf.ponee.io@ignite.apache.org Thu Jan 18 07:43:05 2018 Return-Path: X-Original-To: archive-asf-public@eu.ponee.io Delivered-To: archive-asf-public@eu.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by mx-eu-01.ponee.io (Postfix) with ESMTP id 9694C180654 for ; Thu, 18 Jan 2018 07:43:05 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 865DC160C48; Thu, 18 Jan 2018 06:43:05 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 7E643160C2B for ; Thu, 18 Jan 2018 07:43:04 +0100 (CET) Received: (qmail 37590 invoked by uid 500); 18 Jan 2018 06:43: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 37581 invoked by uid 99); 18 Jan 2018 06:43:03 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd1-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 18 Jan 2018 06:43:03 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd1-us-west.apache.org (ASF Mail Server at spamd1-us-west.apache.org) with ESMTP id 04150CA975 for ; Thu, 18 Jan 2018 06:43:03 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd1-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -99.911 X-Spam-Level: X-Spam-Status: No, score=-99.911 tagged_above=-999 required=6.31 tests=[KAM_ASCII_DIVIDERS=0.8, RCVD_IN_DNSWL_LOW=-0.7, SPF_PASS=-0.001, T_RP_MATCHES_RCVD=-0.01, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd1-us-west.apache.org [10.40.0.7]) (amavisd-new, port 10024) with ESMTP id FJhEwYDf5UsL for ; Thu, 18 Jan 2018 06:43: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 743205F27E for ; Thu, 18 Jan 2018 06:43:01 +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 F25CEE0161 for ; Thu, 18 Jan 2018 06:43: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 B7DA821305 for ; Thu, 18 Jan 2018 06:43:00 +0000 (UTC) Date: Thu, 18 Jan 2018 06:43:00 +0000 (UTC) From: "Vladimir Ozerov (JIRA)" To: issues@ignite.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (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 Auto-Submitted: auto-generated [ https://issues.apache.org/jira/browse/IGNITE-7196?page=3Dcom.atlassi= an.jira.plugin.system.issuetabpanels:all-tabpanel ] Vladimir Ozerov updated IGNITE-7196: ------------------------------------ Fix Version/s: (was: 2.4) 2.5 > 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: Alexey Goncharuk > Priority: Critical > Fix For: 2.5 > > > 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)