I need to collect more numbers to verify that assertion, but, yes, it would seem to do that.
On Wed, Jan 12, 2011 at 8:20 AM, Stack <st...@duboce.net> wrote: > Its interesting that you are running into this issue Ted on a > 'non-hdfs append-enabled substrate'. This would seem to rule out > 'slow hdfs' as culprit. > > St.Ack > > On Tue, Jan 11, 2011 at 2:51 PM, Ted Dunning <tdunn...@maprtech.com> > wrote: > > I am running YCSB to load a modest amount of data (2 M rows) and see > > something similar. > > > > For example: > > > > 10 sec: 135327 operations; 13505.69 current ops/sec; [INSERT > > AverageLatency(ms)=0.84] > > 20 sec: 204440 operations; 6883.08 current ops/sec; [INSERT > > AverageLatency(ms)=3.51] > > 30 sec: 250166 operations; 4572.14 current ops/sec; [INSERT > > AverageLatency(ms)=0.25] > > 40 sec: 348603 operations; 9843.7 current ops/sec; [INSERT > > AverageLatency(ms)=3.02] > > * 50 sec: 348603 operations; 0 current ops/sec; * > > 60 sec: 447040 operations; 9821.11 current ops/sec; [INSERT > > AverageLatency(ms)=3.59] > > 70 sec: 504461 operations; 5741.53 current ops/sec; [INSERT > > AverageLatency(ms)=1.88] > > 80 sec: 598797 operations; 9433.6 current ops/sec; [INSERT > > AverageLatency(ms)=2.53] > > 90 sec: 676724 operations; 7791.92 current ops/sec; [INSERT > > AverageLatency(ms)=1.49] > > 100 sec: 758754 operations; 8202.18 current ops/sec; [INSERT > > AverageLatency(ms)=2.71] > > 110 sec: 779263 operations; 2050.9 current ops/sec; [INSERT > > AverageLatency(ms)=2.26] > > 120 sec: 890004 operations; 11060.83 current ops/sec; [INSERT > > AverageLatency(ms)=2.48] > > 130 sec: 996641 operations; 10662.63 current ops/sec; [INSERT > > AverageLatency(ms)=1.56] > > * 140 sec: 996641 operations; 0 current ops/sec; * > > 150 sec: 1111600 operations; 11494.75 current ops/sec; [INSERT > > AverageLatency(ms)=3.81] > > 160 sec: 1175494 operations; 6371.56 current ops/sec; [INSERT > > AverageLatency(ms)=3.08] > > 170 sec: 1209919 operations; 3442.16 current ops/sec; [INSERT > > AverageLatency(ms)=0.04] > > * 180 sec: 1209919 operations; 0 current ops/sec; * > > 190 sec: 1265127 operations; 5515.84 current ops/sec; [INSERT > > AverageLatency(ms)=10.25] > > 200 sec: 1382184 operations; 11705.7 current ops/sec; [INSERT > > AverageLatency(ms)=0.43] > > 210 sec: 1431400 operations; 4921.11 current ops/sec; [INSERT > > AverageLatency(ms)=2.39] > > * 220 sec: 1431400 operations; 0 current ops/sec; * > > 230 sec: 1490315 operations; 5869.2 current ops/sec; [INSERT > > AverageLatency(ms)=9.58] > > 240 sec: 1513430 operations; 2311.27 current ops/sec; [INSERT > > AverageLatency(ms)=0.29] > > 250 sec: 1599562 operations; 8613.2 current ops/sec; [INSERT > > AverageLatency(ms)=3.86] > > 260 sec: 1725739 operations; 12616.44 current ops/sec; [INSERT > > AverageLatency(ms)=1.35] > > 270 sec: 1823203 operations; 9746.4 current ops/sec; [INSERT > > AverageLatency(ms)=1.39] > > 280 sec: 1911486 operations; 8827.42 current ops/sec; [INSERT > > AverageLatency(ms)=1.25] > > 290 sec: 2000000 operations; 8850.51 current ops/sec; [INSERT > > AverageLatency(ms)=1.41] > > > > > > This is with 0.89 running on 5 region servers on a non-hdfs > append-enabled > > substrate. > > > > I am logging GC's on both master and regions and I don't see a > correlation > > between either. I am still verifying that, so it could be wrong, but I > am > > pretty sure not. What I do see is lots of small compactions that look > > roughly like this: > > > > {Heap before GC invocations=181 (full 23): > > par new generation total 19136K, used 17895K [0x00007f9aa40a0000, > > 0x00007f9aa5560000, 0x00007f9aabda0000) > > eden space 17024K, 99% used [0x00007f9aa40a0000, 0x00007f9aa513b058, > > 0x00007f9aa5140000) > > from space 2112K, 42% used [0x00007f9aa5350000, 0x00007f9aa542ef38, > > 0x00007f9aa5560000) > > to space 2112K, 0% used [0x00007f9aa5140000, 0x00007f9aa5140000, > > 0x00007f9aa5350000) > > concurrent mark-sweep generation total 252700K, used 83769K > > [0x00007f9aabda0000, 0x00007f9abb467000, 0x00007f9ae28a0000) > > concurrent-mark-sweep perm gen total 29120K, used 17377K > > [0x00007f9ae28a0000, 0x00007f9ae4510000, 0x00007f9ae7ca0000) > > 542.472: [GC 542.472: [ParNew > > Desired survivor size 1081344 bytes, new threshold 4 (max 4) > > - age 1: 274408 bytes, 274408 total > > - age 2: 47352 bytes, 321760 total > > - age 3: 10304 bytes, 332064 total > > - age 4: 10472 bytes, 342536 total > > : 17895K->510K(19136K), 0.0586100 secs] 101665K->84784K(271836K) > icms_dc=1 , > > 0.0586740 secs] [Times: user=0.36 sys=0.00, real=0.06 secs] > > Heap after GC invocations=182 (full 23): > > par new generation total 19136K, used 510K [0x00007f9aa40a0000, > > 0x00007f9aa5560000, 0x00007f9aabda0000) > > eden space 17024K, 0% used [0x00007f9aa40a0000, 0x00007f9aa40a0000, > > 0x00007f9aa5140000) > > from space 2112K, 24% used [0x00007f9aa5140000, 0x00007f9aa51bfa98, > > 0x00007f9aa5350000) > > to space 2112K, 0% used [0x00007f9aa5350000, 0x00007f9aa5350000, > > 0x00007f9aa5560000) > > concurrent mark-sweep generation total 252700K, used 84274K > > [0x00007f9aabda0000, 0x00007f9abb467000, 0x00007f9ae28a0000) > > concurrent-mark-sweep perm gen total 29120K, used 17377K > > [0x00007f9ae28a0000, 0x00007f9ae4510000, 0x00007f9ae7ca0000) > > } > > 542.730: [CMS-concurrent-mark: 0.060/2.344 secs] [Times: user=1.48 > sys=0.05, > > real=2.35 secs] > > 542.730: [CMS-concurrent-preclean-start] > > 542.744: [CMS-concurrent-preclean: 0.014/0.014 secs] [Times: user=0.01 > > sys=0.00, real=0.01 secs] > > 542.744: [CMS-concurrent-abortable-preclean-start] > > > > > > It is unusual to see things last 4 generations. There are clearly full > > collections going on, but not a lot of them and the heap is small enough > on > > this system that it should be fast. > > > > I will be gather more information. > > > > On Tue, Jan 11, 2011 at 2:34 PM, Wayne <wav...@gmail.com> wrote: > > > >> We have very frequent cluster wide pauses that stop all reads and > writes > >> for seconds. We are constantly loading data to this cluster of 10 nodes. > >> These pauses can happen as frequently as every minute but sometimes are > not > >> seen for 15+ minutes. Basically watching the Region server list with > >> request > >> counts is the only evidence of what is going on. All reads and writes > >> totally stop and if there is ever any activity it is on the node hosting > >> the > >> .META. table with a request count of region count + 1. This problem > seems > >> to > >> be worse with a larger region size. We tried a 1GB region size and saw > this > >> more than we saw actual activity (and stopped using a larger region size > >> because of it). We went back to the default region size and it was > better, > >> but we had too many regions so now we are up to 512M for a region size > and > >> we are seeing it more again. > >> > >> Does anyone know what this is? We have dug into all of the logs to find > >> some > >> sort of pause but are not able to find anything. Is this an wal hlog > roll? > >> Is this a region split or compaction? Of course our biggest fear is a GC > >> pause on the master but we do not have java logging turned on with the > >> master to tell. What could possibly stop the entire cluster from working > >> for > >> seconds at a time very frequently? > >> > >> Thanks in advance for any ideas of what could be causing this. > >> > > >