From user-return-59717-archive-asf-public=cust-asf.ponee.io@cassandra.apache.org Wed Feb 7 15:12:13 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 9C02818065B for ; Wed, 7 Feb 2018 15:12:13 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 8BC9E160C5B; Wed, 7 Feb 2018 14:12:13 +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 0DF31160C3C for ; Wed, 7 Feb 2018 15:12:11 +0100 (CET) Received: (qmail 5591 invoked by uid 500); 7 Feb 2018 14:12:10 -0000 Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user@cassandra.apache.org Delivered-To: mailing list user@cassandra.apache.org Received: (qmail 5581 invoked by uid 99); 7 Feb 2018 14:12:09 -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; Wed, 07 Feb 2018 14:12:09 +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 81ADAC0189 for ; Wed, 7 Feb 2018 14:12:09 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 2.879 X-Spam-Level: ** X-Spam-Status: No, score=2.879 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, FREEMAIL_REPLY=1, HTML_MESSAGE=2, RCVD_IN_DNSWL_NONE=-0.0001, RCVD_IN_MSPIKE_H3=-0.01, RCVD_IN_MSPIKE_WL=-0.01, SPF_PASS=-0.001] autolearn=disabled Authentication-Results: spamd4-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com 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 E6agcurN72kt for ; Wed, 7 Feb 2018 14:12:05 +0000 (UTC) Received: from mail-ot0-f175.google.com (mail-ot0-f175.google.com [74.125.82.175]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTPS id 201145F230 for ; Wed, 7 Feb 2018 14:12:03 +0000 (UTC) Received: by mail-ot0-f175.google.com with SMTP id r23so896701ote.8 for ; Wed, 07 Feb 2018 06:12:03 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:in-reply-to:references:from:date:message-id:subject:to; bh=iHEv2MdFBtXZarkM1LOieLx0dOQiGy025WIlI+S84mk=; b=WrtE5qy+AA5fzOncDTA3/tZavbqWXxzcDbwkGgllDIFMdYYOttw1XpA+4XxqUJJ87J rCiGMglx0dn6HAPpGhI9qYhXJ/0tbCTQg47qnihSOohecAHf6dXLB3Cpbp+esOhj+e5P 5hBn5vlCvXzDRHiT7vCuj9XgobiXw/6PmWItlhmVQSwgCp6kNJcfegY0JnsxX+ZD8K69 XLus40V9WFEEUeyhmIzuPXePJoapxE/4cyX5x30K5hqro4F2SlL0txCaKfnX699P23GQ T7vc0xaxlrw+XOUfctrOa8oJ9WDUU1Y2PY8uU09A/fEwEzJ2dZIZIscl/0HukmfmoY6Z HbUw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to; bh=iHEv2MdFBtXZarkM1LOieLx0dOQiGy025WIlI+S84mk=; b=fO8hlGpzGuS5LAH4u8LP9Hz9gZg5ADnPFJcWSuZ2TXTl/we6YRc18qGqUIe+Dfcwi5 XpJoXKhQKSmQq9hq+3JYuMW5VPCWLMKbr+TxYGXGUTbENK7MIqN2go7s2GeRltlKT/ob 4cgDIphoP/zmaETFUiRYR9QOzu93tJbdzypueRFMyAQ3EgKadmbU2dFhxo1BZKkKp126 boIcYWl/ryjoqHOh3Uepqoci7EsbVPjckkxa94cp/sq3u8zucqaFy8CUDj3y3+spG/7h 4nZ07KUAluHEVQdK8iidf8oMXBzytA96WC15rM7LJXIugtDl/cpaaUAVU7rnYgs34+w/ QLZw== X-Gm-Message-State: APf1xPBxJAm2bUUH/iI4AOS12Z0fM9n50W8k3ppjIRg6SELbMELKmQu2 vmrp3NE3hc2ujTeb0y5wJAcFpinLoYAAT3hAauVawA== X-Google-Smtp-Source: AH8x2279Rby5n1nWKtLpgUWG6nHAdTsAiUWxoiqleT9lmD89jTZs1logBHfTr/8w723aq740p9X3nGKm8jM1dJ4FH50= X-Received: by 10.157.15.37 with SMTP id 34mr4562329ott.358.1518012722157; Wed, 07 Feb 2018 06:12:02 -0800 (PST) MIME-Version: 1.0 Received: by 10.157.67.100 with HTTP; Wed, 7 Feb 2018 06:11:41 -0800 (PST) In-Reply-To: References: From: Nicolas Guyomar Date: Wed, 7 Feb 2018 15:11:41 +0100 Message-ID: Subject: Re: Bootstrapping fails with < 128GB RAM ... To: user@cassandra.apache.org Content-Type: multipart/alternative; boundary="94eb2c037614119eed05649fe176" --94eb2c037614119eed05649fe176 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Ok then, following up on the wild guess : because you have quite a lot of concurrent compactors, maybe it is too much concurrent compactions for the jvm to deal with (taking into account that your load average of 106 seems really high IMHO) 55Gb of data is not that much, you can try to reduce those concurrent compactor to make sure your box is not under too much stress (how many compaction do you have in parallel during boostrap ? ) In the end, it does seem that you're gonna have to share some heap dump for further investigation (sorry I'm not gonna help lot on this matter) On 7 February 2018 at 14:43, J=C3=BCrgen Albersdorfer wrote: > Hi Nicolas, > > Do you know how many sstables is this new node suppose to receive ? > > > If I can find out this via nodetool netstats, then this would be 619 as > following: > > # nodetool netstats > Bootstrap b95371e0-0c0a-11e8-932b-f775227bf21c > /192.168.1.215 - Receiving 71 files, 7744612158 bytes total. Already > received 0 files, 893897583 bytes total > /192.168.1.214 - Receiving 58 files, 5693392001 bytes total. Already > received 0 files, 1078372756 bytes total > /192.168.1.206 - Receiving 52 files, 3389096409 bytes total. Already > received 3 files, 508592758 bytes total > /192.168.1.213 - Receiving 59 files, 6041633329 bytes total. Already > received 0 files, 1038760653 bytes total > /192.168.1.231 - Receiving 79 files, 7579181689 bytes total. Already > received 4 files, 38387859 bytes total > /192.168.1.208 - Receiving 51 files, 3272885123 bytes total. Already > received 3 files, 362450903 bytes total > /192.168.1.207 - Receiving 56 files, 3028344200 bytes total. Already > received 3 files, 57790197 bytes total > /192.168.1.232 - Receiving 79 files, 7268716317 bytes total. Already > received 1 files, 1127174421 bytes total > /192.168.1.209 - Receiving 114 files, 21381846105 bytes total. > Already received 1 files, 961497222 bytes total > > > does disabling compaction_throughput_mb_per_sec or increasing concurrent_ >> compactors has any effect ? > > > I will give it a try: > > # nodetool getcompactionthroughput > Current compaction throughput: 128 MB/s > > # nodetool setcompactionthroughput 0 > > # nodetool getcompactionthroughput > Current compaction throughput: 0 MB/s > > # nodetool getconcurrentcompactors > Current concurrent compactors in the system is: > 16 > > > Which memtable_allocation_type are you using ? > > > # grep memtable_allocation_type /etc/cassandra/conf/cassandra.yaml > memtable_allocation_type: heap_buffers > > > thanks so far, regards > Juergen > > 2018-02-07 14:29 GMT+01:00 Nicolas Guyomar : > >> Hi Jurgen, >> >> It does feel like some OOM during boostrap from previous C* v2, but that >> sould be fixed in your version. >> >> Do you know how many sstables is this new node suppose to receive ? >> >> Juste a wild guess : it may have something to do with compaction not >> keeping up because every other nodes are streaming data to this new one >> (resulting in long lived object in the heap), does disabling >> compaction_throughput_mb_per_sec or increasing concurrent_compactors has >> any effect ? >> >> Which memtable_allocation_type are you using ? >> >> >> On 7 February 2018 at 12:38, J=C3=BCrgen Albersdorfer > > wrote: >> >>> Hi, I always face an issue when bootstrapping a Node having less than >>> 184GB RAM (156GB JVM HEAP) on our 10 Node C* 3.11.1 Cluster. >>> During bootstrap, when I watch the cassandra.log I observe a growth in >>> JVM Heap Old Gen which gets not significantly freed any more. >>> I know that JVM collects on Old Gen only when really needed. I can see >>> collections, but there is always a remainder which >>> seems to grow forever without ever getting freed. >>> After the Node successfully Joined the Cluster, I can remove the extra >>> 128GB of RAM I have given it for bootstrapping without any further effe= ct. >>> >>> It feels like Cassandra will not forget about every single byte streame= d >>> over the Network over time during bootstrapping, - which would be a mem= ory >>> leak and a major problem, too. >>> >>> Or is there something I'm doing wrong? - Any Ideas? >>> >>> Here my observations on a failing Bootstrap - The following Node has >>> 72GB RAM installed, 64GB of it are configured for JVM Heap Space. >>> >>> cassandra.log (truncated): >>> INFO [Service Thread] 2018-02-07 11:12:49,604 GCInspector.java:284 - G= 1 >>> Young Generation GC in 984ms. G1 Eden Space: 14763950080 -> 0; G1 Old = Gen: >>> 36960206856 -> 39661338640; G1 Survivor Space: 2785017856 -> 1476395008= ; >>> INFO [Service Thread] 2018-02-07 11:13:00,108 GCInspector.java:284 - G= 1 >>> Young Generation GC in 784ms. G1 Eden Space: 18387828736 >>> <(838)%20782-8736> -> 0; G1 Old Gen: 39661338640 -> 41053847560; G1 >>> Survivor Space: 1476395008 -> 1845493760; >>> INFO [Service Thread] 2018-02-07 11:13:08,639 GCInspector.java:284 - G= 1 >>> Young Generation GC in 718ms. G1 Eden Space: 16743661568 -> 0; G1 Old = Gen: >>> 41053847560 -> 42832232472; G1 Survivor Space: 1845493760 -> 1375731712= ; >>> INFO [Service Thread] 2018-02-07 11:13:18,271 GCInspector.java:284 - G= 1 >>> Young Generation GC in 546ms. G1 Eden Space: 15535702016 -> 0; G1 Old = Gen: >>> 42831004832 -> 44206736544; G1 Survivor Space: 1375731712 -> 1006632960= ; >>> INFO [Service Thread] 2018-02-07 11:13:35,364 GCInspector.java:284 - G= 1 >>> Young Generation GC in 638ms. G1 Eden Space: 14025752576 >>> <(402)%20575-2576> -> 0; G1 Old Gen: 44206737048 -> 45213369488; G1 >>> Survivor Space: 1778384896 -> 1610612736; >>> INFO [Service Thread] 2018-02-07 11:13:42,898 GCInspector.java:284 - G= 1 >>> Young Generation GC in 614ms. G1 Eden Space: 13388218368 -> 0; G1 Old = Gen: >>> 45213369488 -> 46152893584; G1 Survivor Space: 1610612736 -> 1006632960= ; >>> INFO [Service Thread] 2018-02-07 11:13:58,291 GCInspector.java:284 - G= 1 >>> Young Generation GC in 400ms. G1 Eden Space: 13119782912 -> 0; G1 Old = Gen: >>> 46136116376 -> 47171400848; G1 Survivor Space: 1275068416 -> 771751936; >>> INFO [Service Thread] 2018-02-07 11:14:23,071 GCInspector.java:284 - G= 1 >>> Young Generation GC in 303ms. G1 Eden Space: 11676942336 -> 0; G1 Old = Gen: >>> 47710958232 -> 48239699096; G1 Survivor Space: 1207959552 -> 973078528; >>> INFO [Service Thread] 2018-02-07 11:14:46,157 GCInspector.java:284 - G= 1 >>> Young Generation GC in 305ms. G1 Eden Space: 11005853696 -> 0; G1 Old = Gen: >>> 48903342232 -> 49289001104; G1 Survivor Space: 939524096 -> 973078528; >>> INFO [Service Thread] 2018-02-07 11:14:53,045 GCInspector.java:284 - G= 1 >>> Young Generation GC in 380ms. G1 Eden Space: 10569646080 -> 0; G1 Old = Gen: >>> 49289001104 -> 49586732696; G1 Survivor Space: 973078528 -> 1308622848; >>> INFO [Service Thread] 2018-02-07 11:15:04,692 GCInspector.java:284 - G= 1 >>> Young Generation GC in 360ms. G1 Eden Space: 9294577664 >>> <(929)%20457-7664> -> 0; G1 Old Gen: 50671712912 -> 51269944472; G1 >>> Survivor Space: 905969664 -> 805306368; >>> WARN [Service Thread] 2018-02-07 11:15:07,317 GCInspector.java:282 - G= 1 >>> Young Generation GC in 1102ms. G1 Eden Space: 2617245696 -> 0; G1 Old >>> Gen: 51269944472 -> 47310521496; G1 Survivor Space: 805306368 -> >>> 301989888; >>> .... >>> INFO [Service Thread] 2018-02-07 11:16:36,535 GCInspector.java:284 - G= 1 >>> Young Generation GC in 377ms. G1 Eden Space: 7683964928 -> 0; G1 Old G= en: >>> 51958433432 -> 52658554008; G1 Survivor Space: 1073741824 -> 1040187392= ; >>> INFO [Service Thread] 2018-02-07 11:16:41,756 GCInspector.java:284 - G= 1 >>> Young Generation GC in 340ms. G1 Eden Space: 7046430720 >>> <(704)%20643-0720> -> 0; G1 Old Gen: 52624999576 -> 53299987616; G1 >>> Survivor Space: 1040187392 -> 805306368; >>> WARN [Service Thread] 2018-02-07 11:16:44,087 GCInspector.java:282 - G= 1 >>> Young Generation GC in 1005ms. G1 Eden Space: 2617245696 -> 0; G1 Old >>> Gen: 53299987616 -> 49659331752; G1 Survivor Space: 805306368 -> >>> 436207616; >>> ... >>> INFO [Service Thread] 2018-02-07 11:25:40,902 GCInspector.java:284 - G= 1 >>> Young Generation GC in 254ms. G1 Eden Space: 11475615744 -> 0; G1 Old = Gen: >>> 48904357040 -> 48904357544; G1 Survivor Space: 704643072 -> 805306368; >>> INFO [Service Thread] 2018-02-07 11:26:11,424 GCInspector.java:284 - G= 1 >>> Young Generation GC in 202ms. G1 Eden Space: 11005853696 -> 0; G1 Old = Gen: >>> 48904357544 -> 49321014960; G1 Survivor Space: 939524096 -> 536870912; >>> WARN [Service Thread] 2018-02-07 11:26:44,484 GCInspector.java:282 - G= 1 >>> Young Generation GC in 1295ms. G1 Eden Space: 2617245696 -> 0; G1 Old >>> Gen: 49321014960 -> 46255753384; G1 Survivor Space: 805306368 -> >>> 402653184; >>> ... >>> INFO [Service Thread] 2018-02-07 11:30:37,828 GCInspector.java:284 - G= 1 >>> Young Generation GC in 958ms. G1 Eden Space: 2785017856 -> 0; G1 Old >>> Gen: 51196393000 -> 50629766184; G1 Survivor Space: 637534208 -> >>> 436207616; >>> INFO [Service Thread] 2018-02-07 11:30:45,036 GCInspector.java:284 - G= 1 >>> Young Generation GC in 270ms. G1 Eden Space: 10267656192 -> 0; G1 Old >>> Gen: 50629766184 -> 50626254144; G1 Survivor Space: 436207616 -> >>> 738197504; >>> INFO [Service Thread] 2018-02-07 11:31:48,128 GCInspector.java:284 - G= 1 >>> Young Generation GC in 984ms. G1 Eden Space: 2617245696 -> 0; G1 Old >>> Gen: 51086410272 -> 50443965480; G1 Survivor Space: 805306368 -> >>> 369098752; >>> >>> >>> jvm.options as following (comments removed): >>> ## Use the Hotspot garbage-first collector. >>> -XX:+UseG1GC >>> -XX:MaxGCPauseMillis=3D1000 >>> -XX:InitiatingHeapOccupancyPercent=3D70 >>> -XX:ParallelGCThreads=3D16 >>> -XX:ConcGCThreads=3D16 >>> >>> ### GC logging options -- uncomment to enable >>> -XX:+PrintGCDetails >>> -XX:+PrintGCDateStamps >>> -XX:+PrintHeapAtGC >>> -XX:+PrintTenuringDistribution >>> -XX:+PrintGCApplicationStoppedTime >>> -XX:+PrintPromotionFailure >>> #-XX:PrintFLSStatistics=3D1 >>> #-Xloggc:/var/log/cassandra/gc.log >>> -XX:+UseGCLogFileRotation >>> -XX:NumberOfGCLogFiles=3D10 >>> -XX:GCLogFileSize=3D10M >>> >>> I tried this with ParNewGC and ConcMarkSweepGC, too - and I have the >>> same behavior there, too. >>> >>> From nodetool netstats I see that it wants to Stream about 55,9 GB. >>> After 1,5h of streaming with more than 10MB/s (about 54GB seen with >>> dstat) nodetool netstats displays that only 3,5GB of 55,9 GB already >>> received. >>> >>> uptime >>> 11:30:52 up 1:36, 3 users, load average: 106.01, 87.54, 66.01 >>> >>> nodetool netstats (truncated for better reading) >>> Wed Feb 7 11:19:07 CET 2018 >>> Mode: JOINING >>> Bootstrap 56d204d0-0be9-11e8-ae30-617216855b4a >>> /192.168.1.213 - Receiving 68 files, 6.774.831.556 bytes total. >>> Already received 3 files, 279.238.740 bytes total >>> /192.168.1.215 - Receiving 68 files, 5.721.460.494 bytes total. >>> Already received 4 files, 109.051.913 bytes total >>> /192.168.1.214 - Receiving 68 files, 7.497.726.056 bytes total. >>> Already received 4 files, 870.592.708 bytes total >>> /192.168.1.207 - Receiving 63 files, 4.945.809.501 bytes total. >>> Already received 4 files, 700.599.427 bytes total >>> /192.168.1.232 - Receiving 91 files, 7.344.537.682 bytes total. >>> Already received 3 files, 237.482.005 bytes total >>> /192.168.1.209 - Receiving 102 files, 15.931.849.729 bytes total. >>> Already received 3 files, 1.108.754.920 bytes total >>> /192.168.1.231 - Receiving 92 files, 7.927.882.516 bytes total. >>> Already received 4 files, 269.514.936 bytes total >>> >>> >>> nodetool status: >>> Datacenter: main >>> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D >>> Status=3DUp/Down >>> |/ State=3DNormal/Leaving/Joining/Moving >>> -- Address Load Tokens Owns Host ID >>> Rack >>> UN 192.168.1.232 83,31 GiB 256 ? >>> 510a0068-ee2b-4d1f-9965-9e29602d2f8f rack04 >>> UN 192.168.1.206 51,41 GiB 256 ? >>> a168b632-52e7-408a-ae7f-6ba6b9c55cea rack01 >>> UN 192.168.1.207 57,66 GiB 256 ? >>> 7401ab8f-114d-41b4-801d-53a4b042de52 rack01 >>> UN 192.168.1.208 56,47 GiB 256 ? >>> 767980ef-52f2-4c21-8567-324fc1db274c rack01... >>> UJ 192.168.1.160 68,95 GiB 256 ? >>> a3a5a169-512f-4e1f-8c0b-419c828f23e1 rack02 >>> UN 192.168.1.209 94,27 GiB 256 ? >>> 8757cb4a-183e-4828-8212-7715b5563935 rack02 >>> UN 192.168.1.213 78,26 GiB 256 ? >>> b1e9481c-4ba2-4396-837a-84be35737fe7 rack05 >>> UN 192.168.1.214 80,66 GiB 256 ? >>> 457fc606-7002-49ad-8da5-309b92093acf rack06 >>> UN 192.168.1.231 87,5 GiB 256 ? >>> 2017a9e8-3638-465e-bc4a-5e59e693fb49 rack03 >>> UN 192.168.1.215 86,97 GiB 256 ? >>> 5dfe4c35-8f8a-4305-824a-4610cec9411b rack07 >>> >>> thanks, and kind regards >>> Juergen >>> >> >> > --94eb2c037614119eed05649fe176 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Ok then, following up on the wild guess : because you have= quite a lot of concurrent compactors, maybe it is too much concurrent comp= actions for the jvm to deal with (taking into account that your load averag= e of 106 seems really high IMHO)

55Gb of data is not tha= t much, you can try to reduce those concurrent compactor to make sure your = box is not under too much stress (how many compaction do you have in parall= el during boostrap ? )

In the end, it does seem th= at you're gonna have to share some heap dump for further investigation = (sorry I'm not gonna help lot on this matter)

On 7 February 2018 at 14:43, J= =C3=BCrgen Albersdorfer <jalbersdorfer@gmail.com> wrot= e:
Hi Nicolas,

Do you know how many sstables is this new node supp= ose to receive ?

If I can find out this via nod= etool netstats, then this would be=C2=A0619 as following:

# nodetool netstats
Bootstrap b95371e0-0c0a-11e8-932b= -f775227bf21c
=C2= =A0 =C2=A0 /192.168.1.21= 5 - Receiving 71 files, 7744612158 bytes total. Already received 0 file= s, 893897583 bytes total
=C2=A0 =C2=A0 /192.16= 8.1.214 - Receiving 58 files, 5693392001 bytes total. Already received = 0 files, 1078372756 bytes total
=C2=A0 =C2=A0 /192.168.1.206 - Receiving 52 files, 3389096409 bytes total. Already re= ceived 3 files, 508592758 bytes total
=C2=A0 =C2=A0 /192.168.1.213 - Receiving 59 files, 6041633329 bytes total. Alre= ady received 0 files, 1038760653 bytes total
=C2=A0 =C2=A0 /192.168.1.231 - Receiving 79 files, 7579181689 bytes tota= l. Already received 4 files, 38387859 bytes total
=C2=A0 =C2=A0 /192.168.1.208 - Receiving 51 files, 3272885123 bytes= total. Already received 3 files, 362450903 bytes total
=C2=A0 =C2=A0 /192.168.1.207 - Receiving 56 files, 3028344200= bytes total. Already received 3 files, 57790197 bytes total
=C2=A0 =C2=A0 /192.168.1.232 - Receiving 79 files, 72687= 16317 bytes total. Already received 1 files, 1127174421 bytes total<= /div>
=C2=A0 =C2=A0 /192.168.1.209 - Receiving 114 file= s, 21381846105 bytes total. Already received 1 files, 961497222 bytes total=


does di= sabling compaction_throughput_mb_per_sec or increasing=C2=A0concurrent_compac= tors has any effect ?

I will give it a try:
# nodetool getcompacti= onthroughput
Current c= ompaction throughput: 128 MB/s

# nodeto= ol setcompactionthroughput 0

# nodetool= getcompactionthroughput
Current compaction throughput: 0 MB/s

Current concurrent compactors in the system is:
=
16


Which=C2=A0memtable_allocation_type a= re you using ?
=C2=A0
# grep memtable_allocation_type /etc/c= assandra/conf/cassandra.yaml
memtable_allocation_type: heap_buffers


thanks so far, regards
Juergen
=

2018-02-07 14:29 GMT+01:00 Nicolas Guyomar <nicolas.guyomar@= gmail.com>:
Hi Jurgen,

It does feel like some OOM during boostrap = from previous C* v2, but that sould be fixed in your version.
Do you know how many sstables is this new node suppose to recei= ve ?=C2=A0

Juste a wild guess : it may have someth= ing to do with compaction not keeping up because every other nodes are stre= aming data to this new one (resulting in long lived object in the heap), do= es disabling compaction_throughput_mb_per_sec or increasing=C2=A0concu= rrent_compactors has any effect ?=C2=A0

Which= =C2=A0memtable_allocation_type are you using ?=C2=A0


On 7 F= ebruary 2018 at 12:38, J=C3=BCrgen Albersdorfer <jalbersdorfer@gmail= .com> wrote:
Hi, I always face an issue when bootstrapping a Node having less than 18= 4GB RAM (156GB JVM HEAP) on our 10 Node C* 3.11.1 Cluster.
During = bootstrap, when I watch the cassandra.log I observe a growth in JVM Heap Ol= d Gen which gets not significantly freed any more.
I know that JV= M collects on Old Gen only when really needed. I can see collections, but t= here is always a remainder which
seems to grow forever without ev= er getting freed.
After the Node successfully Joined the Cluster,= I can remove the extra 128GB of RAM I have given it for bootstrapping with= out any further effect.

It feels like Cassandra wi= ll not forget about every single byte streamed over the Network over time d= uring bootstrapping, - which would be a memory leak and a major problem, to= o.

Or is there something I'm doing wrong? - An= y Ideas?

Here my observations on a failing Bootstr= ap - The following Node has 72GB RAM installed, 64GB of it are configured f= or JVM Heap Space.

cassandra.log (truncated):
INFO=C2=A0 [Service T= hread] 2018-02-07 11:12:49,604 GCInspector.java:284 - G1 Young Generation G= C in 984ms.=C2=A0 G1 Eden Space: 14763950080 -> 0; G1 Old Gen: 369602068= 56 -> 39661338640; G1 Survivor Space: 2785017856 -> 1476395008;
INFO=C2=A0 [Servic= e Thread] 2018-02-07 11:13:00,108 GCInspector.java:284 - G1 Young Generatio= n GC in 784ms.=C2=A0 G1 Eden Space: 18387828736 -> 0; G1 Old Gen: 39= 661338640 -> 41053847560; G1 Survivor Space: 1476395008 -> 1845493760= ;
INFO=C2=A0 [Service = Thread] 2018-02-07 11:13:08,639 GCInspector.java:284 - G1 Young Generation = GC in 718ms.=C2=A0 G1 Eden Space: 16743661568 -> 0; G1 Old Gen: 41053847= 560 -> 42832232472; G1 Survivor Space: 1845493760 -> 1375731712;
INFO=C2=A0 [Service Thread= ] 2018-02-07 11:13:18,271 GCInspector.java:284 - G1 Young Generation GC in = 546ms.=C2=A0 G1 Eden Space: 15535702016 -> 0; G1 Old Gen: 42831004832 -&= gt; 44206736544; G1 Survivor Space: 1375731712 -> 1006632960;
INFO=C2=A0 [Service = Thread] 2018-02-07 11:13:35,364 GCInspector.java:284 - G1 Young Generation = GC in 638ms.=C2=A0 G1 Eden Space: 14025752576 -> 0; G1 Old Gen: 44206= 737048 -> 45213369488; G1 Survivor Space: 1778384896 -> 1610612736;
INFO=C2=A0 [Service= Thread] 2018-02-07 11:13:42,898 GCInspector.java:284 - G1 Young Generation= GC in 614ms.=C2=A0 G1 Eden Space: 13388218368 -> 0; G1 Old Gen: 4521336= 9488 -> 46152893584; G1 Survivor Space: 1610612736 -> 1006632960;
INFO=C2=A0 [S= ervice Thread] 2018-02-07 11:13:58,291 GCInspector.java:284 - G1 Young Gene= ration GC in 400ms.=C2=A0 G1 Eden Space: 13119782912 -> 0; G1 Old Gen: 4= 6136116376 -> 47171400848; G1 Survivor Space: 1275068416 -> 771751936= ;
INFO= =C2=A0 [Service Thread] 2018-02-07 11:14:23,071 GCInspector.java:284 - G1 Y= oung Generation GC in 303ms.=C2=A0 G1 Eden Space: 11676942336 -> 0; G1 O= ld Gen: 47710958232 -> 48239699096; G1 Survivor Space: 1207959552 -> = 973078528;
INFO=C2=A0 [Service Thread] 2018-02-07 11:14:46,157 GCInspector.java:2= 84 - G1 Young Generation GC in 305ms.=C2=A0 G1 Eden Space: 11005853696 ->= ; 0; G1 Old Gen: 48903342232 -> 49289001104; G1 Survivor Space: 93952409= 6 -> 973078528;
INFO=C2=A0 [Service Thread] 2018-02-07 11:14:53,045 GCInspector.java:284 -= G1 Young Generation GC in 380ms.=C2=A0 G1 Eden Space: 10569646080 -> 0;= G1 Old Gen: 49289001104 -> 49586732696; G1 Survivor Space: 973078528 -&= gt; 1308622848;
INFO=C2=A0 [Service Thread] 2018-02-07 11:15:04,692 GCInspector.java:= 284 - G1 Young Generation GC in 360ms.=C2=A0 G1 Eden Space: 9294577664 -= > 0; G1 Old Gen: 50671712912 -> 51269944472; G1 Survivor Space: 90596= 9664 -> 805306368;
WARN=C2=A0 [Service Thread] 2018-02-07 11:15:07,317 GCInspector.java:28= 2 - G1 Young Generation GC in 1102ms.=C2=A0 G1 Eden Space: 2617245696 ->= 0; G1 Old Gen: 512699444= 72 -> 47310521496; G1 Survivor Space: 805306368 -> 301989888;<= /font>
....
INFO=C2=A0 [Service Thread] = 2018-02-07 11:16:36,535 GCInspector.java:284 - G1 Young Generation GC in 37= 7ms.=C2=A0 G1 Eden Space: 7683964928 -> 0; G1 Old Gen: 51958433432 ->= 52658554008; G1 Survivor Space: 1073741824 -> 1040187392;
<= div>INFO=C2=A0 [Service Thread] 2018-02= -07 11:16:41,756 GCInspector.java:284 - G1 Young Generation GC in 340ms.=C2= =A0 G1 Eden Space: 7046430720 -> 0; G1 Old Gen: 52624999576 -> 532= 99987616; G1 Survivor Space: 1040187392 -> 805306368;
<= font face=3D"monospace, monospace">WARN=C2=A0 [Service Thread] 2018-02-07 1= 1:16:44,087 GCInspector.java:282 - G1 Young Generation GC in 1005ms.=C2=A0 = G1 Eden Space: 2617245696 -> 0; G1 Old Gen: 53299987616 -> 49659331752; G1 Survivor Spa= ce: 805306368 -> 436207616;
...
INFO= =C2=A0 [Service Thread] 2018-02-07 11:26:11,424 GCInspector.java:284 - G1 Y= oung Generation GC in 202ms.=C2=A0 G1 Eden Space: 11005853696 -> 0; G1 O= ld Gen: 48904357544 -> 49321014960; G1 Survivor Space: 939524096 -> 5= 36870912;
WARN=C2=A0 [= Service Thread] 2018-02-07 11:26:44,484 GCInspector.java:282 - G1 Young Gen= eration GC in 1295ms.=C2=A0 G1 Eden Space: 2617245696 -> 0; G1 Old Gen: 49321014960 -> 462557= 53384; G1 Survivor Space: 805306368 -> 402653184;
...
<= font face=3D"monospace, monospace">INFO=C2=A0 [Service Thread] 2018-02-07 1= 1:30:37,828 GCInspector.java:284 - G1 Young Generation GC in 958ms.=C2=A0 G= 1 Eden Space: 2785017856 -> 0; G1 Old Gen: 51196393000 -> 50629766184; G1 Survivor Spac= e: 637534208 -> 436207616;
INFO=C2=A0 [Service Thread] 2018-02-07 11:30:45,036 GCInspector.jav= a:284 - G1 Young Generation GC in 270ms.=C2=A0 G1 Eden Space: 10267656192 -= > 0; G1 Old Gen: 50629= 766184 -> 50626254144; G1 Survivor Space: 436207616 -> 7381975= 04;
INFO=C2=A0 [Servic= e Thread] 2018-02-07 11:31:48,128 GCInspector.java:284 - G1 Young Generatio= n GC in 984ms.=C2=A0 G1 Eden Space: 2617245696 -> 0; G1 Old Gen: 51086410272 -> 50443965480; G1 Survivor Space: 805306368 -> 369098752;
=

jvm.options as following (comments removed):<= /div>
## Use the Hotspot garba= ge-first collector.
-X= X:+UseG1GC
-XX:Max= GCPauseMillis=3D1000
-XX:InitiatingHeapOccupancyPercent=3D70
-XX:ParallelGCThreads=3D16
-XX:ConcGCThreads=3D16

### GC logging options -- uncomment to enable
-XX:+PrintGCDetails
<= /font>
-XX:+PrintGCDateStamps=
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistri= bution
-XX:+PrintGCApp= licationStoppedTime
-XX:+PrintPromotionFailure
#-XX:PrintFLSStatistics=3D1
#-Xloggc:/var/log/cassandra/gc.log
-XX:+UseGCLogFileRotation
= -XX:NumberOfGCLogFiles=3D10
-XX:GCLogFileSize=3D10M

I tried this with ParNewGC and ConcMarkSweepGC= , too - and I have the same behavior there, too.

F= rom nodetool netstats I see that it wants to Stream about 55,9 GB.=C2=A0
After 1,5h of streaming with more than 10MB/s (about 54GB seen with= dstat) nodetool netstats displays that only 3,5GB of 55,9 GB already recei= ved.

upti= me
=C2=A011:30:52 up= =C2=A0 1:36,=C2=A0 3 users,=C2=A0 load average: 106.01, 87.54, 66.01=

nodetool netstats (truncated for better rea= ding)
Wed Feb=C2=A0 7 11= :19:07 CET 2018
Mode: = JOINING
Bootstrap 56d2= 04d0-0be9-11e8-ae30-617216855b4a
=C2=A0 =C2=A0 /192.168.1.213 - Receiving 68 files, 6.774.831.556 bytes total. A= lready received 3 files, 279.238.740 bytes total
=C2=A0 =C2=A0 /192.168.1.215 - Receiving 68 files, 5.721.460.494 byt= es total. Already received 4 files, 109.051.913 bytes total
=C2=A0 =C2=A0 /192.168.1.214 - Receiving 68 files, 7.497.= 726.056 bytes total. Already received 4 files, 870.592.708 bytes total
=C2=A0 =C2=A0 /192.168.1.207 - Receiving 63 fi= les, 4.945.809.501 bytes total. Already received 4 files, 700.599.427 bytes= total
=C2=A0 =C2=A0 /= 192.168.1.232 - Rece= iving 91 files, 7.344.537.682 bytes total. Already received 3 files, 237.48= 2.005 bytes total
=C2= =A0 =C2=A0 /192.168.1.20= 9 - Receiving 102 files, 15.931.849.729 bytes total. Already received 3= files, 1.108.754.920 bytes total
=C2=A0 =C2=A0 /192.168.1.231 - Receiving 92 files, 7.927.882.516 bytes total. Alrea= dy received 4 files, 269.514.936 bytes total


nodetool status:
Datacenter: main
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
Status=3DUp/Down
|/ State=3DNormal/Leaving/= Joining/Moving
--= =C2=A0 Address=C2=A0 =C2=A0 =C2=A0 =C2=A0 Load=C2=A0 =C2=A0 =C2=A0 =C2=A0To= kens=C2=A0 =C2=A0 =C2=A0 =C2=A0Owns=C2=A0 =C2=A0 Host ID=C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0Rack
UN=C2=A0 192.168.1.232=C2=A0 83,31 GiB=C2=A0 256=C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 ?=C2=A0 =C2=A0 =C2=A0 =C2=A0510a0068-ee2b-4d1f-9965-9e29602= d2f8f=C2=A0 rack04
UN= =C2=A0 192.168.1.206=C2=A0 51,41 GiB=C2=A0 256=C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 ?=C2=A0 =C2=A0 =C2=A0 =C2=A0a168b632-52e7-408a-ae7f-6ba6b9c55ce= a=C2=A0 rack01
UN=C2= =A0 192.168.1.207=C2=A0 57,66 GiB=C2=A0 256=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 ?=C2=A0 =C2=A0 =C2=A0 =C2=A07401ab8f-114d-41b4-801d-53a4b042de52= =C2=A0 rack01
UN=C2=A0= 192.168.1.208=C2=A0 56,47 GiB=C2=A0 256=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = ?=C2=A0 =C2=A0 =C2=A0 =C2=A0767980ef-52f2-4c21-8567-324fc1db274c=C2=A0= rack01...
UJ=C2=A0 19= 2.168.1.160=C2=A0 68,95 GiB=C2=A0 256=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 ?= =C2=A0 =C2=A0 =C2=A0 =C2=A0a3a5a169-512f-4e1f-8c0b-419c828f23e1=C2=A0 = rack02
UN=C2=A0 192.16= 8.1.209=C2=A0 94,27 GiB=C2=A0 256=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 ?=C2=A0= =C2=A0 =C2=A0 =C2=A08757cb4a-183e-4828-8212-7715b5563935=C2=A0 rack02=
UN=C2=A0 192.168.1.21= 3=C2=A0 78,26 GiB=C2=A0 256=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 ?=C2=A0 =C2= =A0 =C2=A0 =C2=A0b1e9481c-4ba2-4396-837a-84be35737fe7=C2=A0 rack05
UN=C2=A0 192.168.1.214=C2= =A0 80,66 GiB=C2=A0 256=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 ?=C2=A0 =C2=A0 = =C2=A0 =C2=A0457fc606-7002-49ad-8da5-309b92093acf=C2=A0 rack06<= /div>
UN=C2=A0 192.168.1.231=C2=A0 = 87,5 GiB=C2=A0 =C2=A0256=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 ?=C2=A0 =C2=A0 = =C2=A0 =C2=A02017a9e8-3638-465e-bc4a-5e59e693fb49=C2=A0 rack03<= /div>
UN=C2=A0 192.168.1.215=C2=A0 = 86,97 GiB=C2=A0 256=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 ?=C2=A0 =C2=A0 =C2=A0= =C2=A05dfe4c35-8f8a-4305-824a-4610cec9411b=C2=A0 rack07
<= /div>

thanks, and kind regards
Juergen



--94eb2c037614119eed05649fe176--