Hi Jon,
should I register to the JIRA and open an Issue or will you do so?
I'm currently trying to bootstrap another node - with 100GB RAM, this time,
and I'm recording Java Heap Memory over time via Jconsole, Top Threads and
do monitoring the debug.log.
There, in the debug.log, I can see, that the other nodes seem to
immediatelly start hinting to the joining node, indicated by the following
logs, which I have hundrets per second in my debug.log:
DEBUG [MutationStage-27] 2018-02-09 12:06:03,241 HintVerbHandler.java:95 -
Failed to apply hint
java.util.concurrent.CompletionException:
org.apache.cassandra.exceptions.WriteTimeoutException: Operation timed out
- received only 0 responses.
at
java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292)
~[na:1.8.0_151]
at
java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308)
~[na:1.8.0_151]
at
java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:647)
~[na:1.8.0_151]
at
java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:632)
~[na:1.8.0_151]
at
java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
~[na:1.8.0_151]
at
java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
~[na:1.8.0_151]
at
org.apache.cassandra.db.Keyspace.applyInternal(Keyspace.java:523)
~[apache-cassandra-3.11.1.jar:3.11.1]
at
org.apache.cassandra.db.Keyspace.lambda$applyInternal$0(Keyspace.java:538)
~[apache-cassandra-3.11.1.jar:3.11.1]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
~[na:1.8.0_151]
at
org.apache.cassandra.concurrent.AbstractLocalAwareExecutorService$FutureTask.run(AbstractLocalAwareExecutorService.java:162)
~[apache-cassandra-3.11.1.jar:3.11.1]
at
org.apache.cassandra.concurrent.SEPWorker.run(SEPWorker.java:109)
~[apache-cassandra-3.11.1.jar:3.11.1]
at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_151]
Caused by: org.apache.cassandra.exceptions.WriteTimeoutException: Operation
timed out - received only 0 responses.
... 6 common frames omitted
Could this be connected? Maybe causing the extensive RAM requirement?
Thanks so far, regards
Juergen
2018-02-07 19:49 GMT+01:00 Jon Haddad <j...@jonhaddad.com>:
> It would be extremely helpful to get some info about your heap. At a bare
> minimum, a histogram of the heap dump would be useful, but ideally a full
> heap dump would be best.
>
> jmap -dump:live,format=b,file=heap.bin PID
>
> Taking a look at that in YourKit should give some pretty quick insight
> into what kinds of objects are allocated then we can get to the bottom of
> the issue. This should be moved to a JIRA (https://issues.apache.org/
> jira/secure/Dashboard.jspa) in order to track and fix it, if you could
> attach that heap dump it would be very helpful.
>
> Jon
>
>
> On Feb 7, 2018, at 6:11 AM, Nicolas Guyomar <nicolas.guyo...@gmail.com>
> wrote:
>
> 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ürgen Albersdorfer <jalbersdor...@gmail.com>
> 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 <(774)%20461-2158>
>> 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 <(757)%20918-1689>
>> 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 <(302)%20834-4200>
>> bytes total. Already received 3 files, 57790197 bytes total
>> /192.168.1.232 - Receiving 79 files, 7268716317 <(726)%20871-6317>
>> 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 <nicolas.guyo...@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 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ürgen Albersdorfer <
>>> jalbersdor...@gmail.com> 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 effect.
>>>>
>>>> It feels like Cassandra will not forget about every single byte
>>>> streamed over the Network over time during bootstrapping, - which would be
>>>> a memory 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 Young Generation GC in 377ms. G1 Eden Space: 7683964928 -> 0; G1 Old
>>>> Gen: 51958433432 -> 52658554008; G1 Survivor Space: 1073741824 ->
>>>> 1040187392;
>>>> INFO [Service Thread] 2018-02-07 11:16:41,756 GCInspector.java:284 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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 -
>>>> G1 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=1000
>>>> -XX:InitiatingHeapOccupancyPercent=70
>>>> -XX:ParallelGCThreads=16
>>>> -XX:ConcGCThreads=16
>>>>
>>>> ### GC logging options -- uncomment to enable
>>>> -XX:+PrintGCDetails
>>>> -XX:+PrintGCDateStamps
>>>> -XX:+PrintHeapAtGC
>>>> -XX:+PrintTenuringDistribution
>>>> -XX:+PrintGCApplicationStoppedTime
>>>> -XX:+PrintPromotionFailure
>>>> #-XX:PrintFLSStatistics=1
>>>> #-Xloggc:/var/log/cassandra/gc.log
>>>> -XX:+UseGCLogFileRotation
>>>> -XX:NumberOfGCLogFiles=10
>>>> -XX:GCLogFileSize=10M
>>>>
>>>> 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
>>>> ================
>>>> Status=Up/Down
>>>> |/ State=Normal/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
>>>>
>>>
>>>
>>
>
>
