DataStax Support Forums » Topic: Unbalanced ring on Cassandra side of Brisk cluster

DataStax Support Forums » Topic: Unbalanced ring on Cassandra side of Brisk cluster http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster Software, Support, and Training for Apache Cassandra en-US Wed, 22 May 2013 20:08:09 +0000 http://bbpress.org/?v=1.0.3 <![CDATA[Search]]> q http://www.datastax.com/support-forums/search.php joaquin on "Unbalanced ring on Cassandra side of Brisk cluster" http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster#post-393 Thu, 28 Jul 2011 20:55:10 +0000 joaquin 393@http://www.datastax.com/support-forums/ After investigating this further, this is a common side affect of not having your memory overcommitted for Brisk. Since Brisk has many components bundled under the same JVM, this is a requirement. Could you run: echo 1 | sudo tee /proc/sys/vm/overcommit_memory and let us know if this problem returns? After making this change, do your nodetool operations now complete successfully? Thanks, Joaquin joaquin on "Unbalanced ring on Cassandra side of Brisk cluster" http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster#post-391 Thu, 28 Jul 2011 20:36:33 +0000 joaquin 391@http://www.datastax.com/support-forums/ Could you add the line: JVM_OPTS="$JVM_OPTS -XX:ErrorFile=/path/to/file" at some point in cassandra-env.sh. You should find this under /etc/brisk/cassandra/cassandra-env.sh if you installed it via the packages or $BRISK_HOME/resources/cassandra/conf/cassandra-env.sh. This way we will be able to easily find your log. If this is not set, then typically the log will be in the folder that you called the process from. I'm having others look into this and will let you know what we find. Thanks, joaquin blueplastic on "Unbalanced ring on Cassandra side of Brisk cluster" http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster#post-386 Thu, 28 Jul 2011 19:00:38 +0000 blueplastic 386@http://www.datastax.com/support-forums/ You're right Joaquin. That EOFException error was not critical. It actually happened during the Cassandra start, not during the crash. Jonathan Ellis also said it was harmless on the Cassandra mailing list. However, we have tried running Repair and compaction on the node unbalanced node with no luck. Both Repair and Compaction seem to be crashing the Cassandra java process on the node. I eventually got repair to successfully complete on the node. Then yesterday, while running compaction, I got the following error in OpsCenter in the evening: 7/27/2011 11:30pm Alert Node reported as being down 10.2.206.x However, the system.log file for that node shows nothing but informational messages at that time: INFO [ScheduledTasks:1] 2011-07-28 06:29:21,429 GCInspector.java (line 128) GC for ParNew: 213 ms, 147241608 reclaimed leaving 2152005360 used; max is 4030726144 INFO [ScheduledTasks:1] 2011-07-28 06:29:28,622 GCInspector.java (line 128) GC for ParNew: 219 ms, 147301832 reclaimed leaving 2188187360 used; max is 4030726144 INFO [ScheduledTasks:1] 2011-07-28 06:29:39,666 GCInspector.java (line 128) GC for ParNew: 240 ms, 148102840 reclaimed leaving 2222749344 used; max is 4030726144 After that in the log, there is a long gap till I restart Cassandra this morning. Note that the time stamp in the log is different than what OpsCenter reports maybe because of EC2 or OpsCenter time zone stuff, but they are the same time. There was definitely something quirky with the Cassandra process on the node this morning. I couldn't run nodetool ring on it: Caused by: java.net.ConnectException: Connection refused at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351) I restarted the Cassandra process this morning and now OpsCenter has it marked as up, but I think Compaction is incomplete now. This shows me restarting the Cassandra process this morning: INFO [ScheduledTasks:1] 2011-07-28 06:29:21,429 GCInspector.java (line 128) GC for ParNew: 213 ms, 147241608 reclaimed leaving 2152005360 used; max is 4030726144 INFO [ScheduledTasks:1] 2011-07-28 06:29:28,622 GCInspector.java (line 128) GC for ParNew: 219 ms, 147301832 reclaimed leaving 2188187360 used; max is 4030726144 INFO [ScheduledTasks:1] 2011-07-28 06:29:39,666 GCInspector.java (line 128) GC for ParNew: 240 ms, 148102840 reclaimed leaving 2222749344 used; max is 4030726144 INFO [main] 2011-07-28 17:48:28,584 AbstractCassandraDaemon.java (line 78) Logging initialized INFO [main] 2011-07-28 17:48:28,617 AbstractCassandraDaemon.java (line 96) Heap size: 3894411264/3894411264 INFO [main] 2011-07-28 17:48:34,199 CLibrary.java (line 106) JNA mlockall successful I also checked the Linux syslog around that time (July 28 6:29am) and it looks like the OS dumped the java process? Jul 28 06:25:01 ip-10-2-206-127 CRON[15405]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1) Jul 28 06:25:01 ip-10-2-206-127 CRON[15406]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )) Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627014] apt-get invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627020] apt-get cpuset=/ mems_allowed=0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627025] Pid: 15420, comm: apt-get Not tainted 2.6.35-30-virtual #54-Ubuntu Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627027] Call Trace: Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627041] [<ffffffff810aefbd>] ? cpuset_print_task_mems_allowed+0x9d/0xb0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627048] [<ffffffff81104451>] dump_header+0x81/0xc0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627052] [<ffffffff81104511>] oom_kill_process+0x81/0x180 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627056] [<ffffffff81104a48>] __out_of_memory+0x58/0xd0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627059] [<ffffffff81104b46>] out_of_memory+0x86/0x1c0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627063] [<ffffffff811085ae>] __alloc_pages_slowpath+0x58e/0x5a0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627068] [<ffffffff8110872c>] __alloc_pages_nodemask+0x16c/0x1d0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627074] [<ffffffff8113aaaa>] alloc_pages_current+0x9a/0x100 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627078] [<ffffffff81101b57>] __page_cache_alloc+0x87/0x90 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627081] [<ffffffff8110168e>] ? find_get_page+0x1e/0x90 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627085] [<ffffffff81103113>] filemap_fault+0x1b3/0x450 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627091] [<ffffffff8111e3d4>] __do_fault+0x54/0x560 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627095] [<ffffffff81121379>] handle_mm_fault+0x1b9/0x440 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627101] [<ffffffff810072f2>] ? check_events+0x12/0x20 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627107] [<ffffffff815aaa35>] do_page_fault+0x125/0x350 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627111] [<ffffffff815a75b5>] page_fault+0x25/0x30 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627114] Mem-Info: Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627116] Node 0 DMA per-cpu: Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627119] CPU 0: hi: 0, btch: 1 usd: 0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627122] CPU 1: hi: 0, btch: 1 usd: 0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627124] Node 0 DMA32 per-cpu: Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627127] CPU 0: hi: 186, btch: 31 usd: 41 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627129] CPU 1: hi: 186, btch: 31 usd: 172 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627131] Node 0 Normal per-cpu: Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627134] CPU 0: hi: 186, btch: 31 usd: 0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627136] CPU 1: hi: 186, btch: 31 usd: 30 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627141] active_anon:665806 inactive_anon:133214 isolated_anon:0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627142] active_file:259 inactive_file:1039 isolated_file:0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627143] unevictable:1039172 dirty:0 writeback:259 unstable:0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627144] free:8797 slab_reclaimable:1978 slab_unreclaimable:3119 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627146] mapped:4552 shmem:49 pagetables:18095 bounce:0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627148] Node 0 DMA free:7808kB min:20kB low:24kB high:28kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15712kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627159] lowmem_reserve[]: 0 4024 7559 7559 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627165] Node 0 DMA32 free:22208kB min:5916kB low:7392kB high:8872kB active_anon:2135320kB inactive_anon:427136kB active_file:888kB inactive_file:3612kB unevictable:1425952kB isolated(anon):0kB isolated(file):0kB present:4120800kB mlocked:1425952kB dirty:0kB writeback:1036kB mapped:2532kB shmem:4kB slab_reclaimable:756kB slab_unreclaimable:4656kB kernel_stack:1240kB pagetables:50796kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:6976 all_unreclaimable? no Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627176] lowmem_reserve[]: 0 0 3535 3535 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627182] Node 0 Normal free:5172kB min:5196kB low:6492kB high:7792kB active_anon:527904kB inactive_anon:105720kB active_file:148kB inactive_file:544kB unevictable:2730736kB isolated(anon):0kB isolated(file):0kB present:3619840kB mlocked:2730736kB dirty:16kB writeback:0kB mapped:15676kB shmem:192kB slab_reclaimable:7156kB slab_unreclaimable:7820kB kernel_stack:2208kB pagetables:21584kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1088 all_unreclaimable? yes Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627192] lowmem_reserve[]: 0 0 0 0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627197] Node 0 DMA: 2*4kB 1*8kB 1*16kB 1*32kB 1*64kB 2*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB 1*4096kB = 7808kB Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627212] Node 0 DMA32: 672*4kB 662*8kB 501*16kB 4*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 1*4096kB = 22208kB Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627226] Node 0 Normal: 221*4kB 28*8kB 0*16kB 1*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 5172kB Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627257] 5640 total pagecache pages Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627260] 0 pages in swap cache Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627263] Swap cache stats: add 0, delete 0, find 0/0 Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627264] Free swap = 0kB Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.627266] Total swap = 0kB Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.652382] 1966064 pages RAM Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.652387] 54111 pages reserved Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.652388] 14176 pages shared Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.652390] 1897463 pages non-shared Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.652394] Out of memory: kill process 2126 (java) score 20305 or a child Jul 28 06:29:44 ip-10-2-206-127 kernel: [576488.652414] Killed process 2126 (java) vsz:951250956kB, anon-rss:4554448kB, file-rss:15276kB I don't see a JVM crashlog ( hs_err_pid[pid].log) in ~/brisk/resources/cassandra/bin or /tmp. So, I guess my question is: Why did the OS kill Java/Cassandra during compaction? Any more thoughts on why the ring would be so unbalanced? Also, I'm starting to suspect a bug in the random partitioner in 0.8.1? Has anyone loaded a large amount of data into 0.8.1? joaquin on "Unbalanced ring on Cassandra side of Brisk cluster" http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster#post-352 Tue, 26 Jul 2011 17:56:26 +0000 joaquin 352@http://www.datastax.com/support-forums/ That above error just means that a message either came in corrupt, got cut off, or another application pinged the Cassandra port. If you could use OpsCenter, MBeans, or nodetool netstats to watch the repair that would be great. Also if there are any other errors, that's something to look into, but this one is benign. Thanks, Joaquin blueplastic on "Unbalanced ring on Cassandra side of Brisk cluster" http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster#post-319 Thu, 21 Jul 2011 18:32:09 +0000 blueplastic 319@http://www.datastax.com/support-forums/ Looks like the Repair failed with this error on the 1st node (with 900+GB of data): ERROR [Thread-23] 2011-07-21 15:48:43,868 AbstractCassandraDaemon.java (line 113) Fatal exception in thread Thread[Thread-23,5,main] java.io.IOError: java.io.EOFException at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:78) Caused by: java.io.EOFException at java.io.DataInputStream.readInt(DataInputStream.java:375) at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:66) There's just a bunch of informational messages about Gossip before this. Any ideas about what could have caused this? joaquin on "Unbalanced ring on Cassandra side of Brisk cluster" http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster#post-318 Wed, 20 Jul 2011 18:38:54 +0000 joaquin 318@http://www.datastax.com/support-forums/ Were you running at QUORUM or ANY writes? This can also affect it, probably not as much as your seeing, but if the writes never made it across to the other two nodes there would be log errors on machines dropping messages to those two nodes. Let us know when the repairs are done! tamalex on "Unbalanced ring on Cassandra side of Brisk cluster" http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster#post-317 Tue, 19 Jul 2011 22:59:29 +0000 tamalex 317@http://www.datastax.com/support-forums/ Thanks, Joaquin. I'll let you know how it turns out. I also want to let you know that I saw this load imbalance during the writing process. We had very very few deletes, and no nodes down during the writing process, so I'm not sure why we should even have to be running repair. joaquin on "Unbalanced ring on Cassandra side of Brisk cluster" http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster#post-316 Tue, 19 Jul 2011 22:42:55 +0000 joaquin 316@http://www.datastax.com/support-forums/ Hello, Yes, Node 0 will create more data than it needs when doing repairs, but once it's done, it should shrink down appropriately. However, 900 GB does seem a bit high, but hopefully it will shrink back down momentarily. Do keep us posted on the size of this node. As for the nodes with just 128 GB of data, could you run repair on those nodes? Repair is IO intensive so running staggered repairs are definitely advised. Once these operations are complete, then let us know if you still see the same issue. That will give us better ground to determine where the problem would lie. Thanks, Joaquin tamalex on "Unbalanced ring on Cassandra side of Brisk cluster" http://www.datastax.com/support-forums/topic/unbalanced-ring-on-cassandra-side-of-brisk-cluster#post-315 Tue, 19 Jul 2011 21:05:28 +0000 tamalex 315@http://www.datastax.com/support-forums/ My team is running brisk v1 beta2 on 12 nodes – 8 cassandra in DC1 and 4 brisk in DC 2 in EC2. Wrote a few TBs of data to the cluster via Hector as we have done in the past, and unfortunately the load is very unbalanced. Every key is the same size and we are using RandomPartitioner. There are two replicas of data in DC1 and one replica in DC2. The load amount in DC2 makes sense (about 250GB per node). DC1 should also have about 250GB per node (since there is twice the data and twice the number of nodes), but as can be seen below two nodes have an inordinate amount of data and the other 6 have only about 128GB: Address DC Rack Status State Load Owns Token 148873535527910577765226390751398592512 10.2.206.x DC1 RAC1 Up Normal 901.6 GB 12.50% 0 10.116.230.x DC2 RAC1 Up Normal 258.23 GB 6.25% 10633823966279326983230456482242756608 10.110.6.x DC1 RAC1 Up Normal 129.08 GB 6.25% 21267647932558653966460912964485513216 10.2.38.x DC1 RAC1 Up Normal 128.51 GB 12.50% 42535295865117307932921825928971026432 10.114.39.x DC2 RAC1 Up Normal 257.32 GB 6.25% 53169119831396634916152282411213783040 10.210.27.x DC1 RAC1 Up Normal 128.67 GB 6.25% 63802943797675961899382738893456539648 10.207.39.x DC1 RAC2 Up Normal 643.14 GB 12.50% 85070591730234615865843651857942052864 10.85.157.x DC2 RAC1 Up Normal 256.78 GB 6.25% 95704415696513942849074108340184809472 10.2.209.x DC1 RAC2 Up Normal 128.96 GB 6.25% 106338239662793269832304564822427566080 10.96.74.x DC1 RAC2 Up Normal 128.3 GB 12.50% 127605887595351923798765477786913079296 10.194.205.x DC2 RAC1 Up Normal 257.15 GB 6.25% 138239711561631250781995934269155835904 10.201.194.x DC1 RAC2 Up Normal 129.46 GB 6.25% 148873535527910577765226390751398592512 I should also node that the first node used to have 640GB of load until the instance went down and we needed to run repair on a new instance in its place. Repair still hasn't finished running on it, and we're hoping it will get back down to 640GB when it does. Any ideas why this may have happened? Here is Sameer's note on this as well: FYI - This manual reordering of the DCs and RACs might make it easier to see how the tokens are arranged. Pretty sure that the token ranges are picked correctly. Ignore the Owns column, b/c it is not multi-datacenter aware (so it thinks all of the nodes are in one ring as opposed to two (DC1 & DC2)). Here is what the nodetool ring output looked like before we replaced the 1st node (643 GB) with new hardware. After running repair on it, for some reason, to our dismay, it re-spawned as a 900+ GB node. Address DC Rack Status State Load Owns Token 148873535527910577765226390751398592512 10.192.143.x DC1 RAC1 Up Normal 643.42 GB 12.50% 0 10.192.171.x DC1 RAC1 Up Normal 128.96 GB 6.25% 21267647932558653966460912964485513216 10.210.95.x DC1 RAC1 Up Normal 128.34 GB 12.50% 42535295865117307932921825928971026432 10.211.19.x DC1 RAC1 Up Normal 128.55 GB 6.25% 63802943797675961899382738893456539648 10.68.58.x DC1 RAC2 Up Normal 643.05 GB 12.50% 85070591730234615865843651857942052864 10.110.31.x DC1 RAC2 Up Normal 128.84 GB 6.25% 106338239662793269832304564822427566080 10.96.58.x DC1 RAC2 Up Normal 128.11 GB 12.50% 127605887595351923798765477786913079296 10.210.195.x DC1 RAC2 Up Normal 129.33 GB 6.25% 148873535527910577765226390751398592512 10.114.138.x DC2 RAC1 Up Normal 258.04 GB 6.25% 10633823966279326983230456482242756608 10.203.79.x DC2 RAC1 Up Normal 257.14 GB 6.25% 53169119831396634916152282411213783040 10.242.209.x DC2 RAC1 Up Normal 256.58 GB 6.25% 95704415696513942849074108340184809472 10.38.25.x DC2 RAC1 Up Normal 257.08 GB 6.25% 138239711561631250781995934269155835904