Hmm, it seems off to me that the merge step is taking 1 to 2 seconds, especially when there are only ~500 cells from one sstable and the memtables. Can you open a ticket ( https://issues.apache.org/jira/browse/CASSANDRA) with your schema, details on your data layout, and these traces?
On Fri, Oct 9, 2015 at 3:47 PM, Nazario Parsacala <dodongj...@gmail.com> wrote: > > > So the trace is varying a lot. And does not seem to correlate with the > data return from the client ? Maybe datastax java driver related. ..? (not > likely).. Just checkout the results. > > > Below is the one that I took when from the client (java application) > perspective it was returning data in about 1100 ms. > > > > *racing session: *566477c0-6ebc-11e5-9493-9131aba66d63 > > *activity* > > | > *timestamp* | *source* | *source_elapsed* > > ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+---------------+---------------- > > > *Execute CQL3 query* | *2015-10-09 > 15:31:28.700000* | *172.31.17.129* | *0* > *Parsing select * from processinfometric_profile where > profilecontext='GENERIC' and id=‘1' and month='Oct' and day='' and hour='' > and minute=''; [SharedPool-Worker-1]* | *2015-10-09 15:31:28.701000* | > *172.31.17.129* | *101* > > > *Preparing statement [SharedPool-Worker-1]* | > *2015-10-09 > 15:31:28.701000* | *172.31.17.129* | *334* > > *Executing > single-partition query on processinfometric_profile [SharedPool-Worker-3]* > | *2015-10-09 15:31:28.701000* | *172.31.17.129* | *692* > > > *Acquiring sstable references [SharedPool-Worker-3]* | *2015-10-09 > 15:31:28.701000* | *172.31.17.129* | *713* > > > *Merging memtable tombstones [SharedPool-Worker-3]* | > *2015-10-09 > 15:31:28.701000* | *172.31.17.129* | *726* > > > *Key cache hit for sstable 209 [SharedPool-Worker-3]* | > *2015-10-09 > 15:31:28.704000* | *172.31.17.129* | *3143* > > > *Seeking > to partition beginning in data file [SharedPool-Worker-3]* | *2015-10-09 > 15:31:28.704000* | *172.31.17.129* | *3169* > > > *Key cache hit for sstable 208 [SharedPool-Worker-3]* | > *2015-10-09 > 15:31:28.704000* | *172.31.17.129* | *3691* > > > *Seeking > to partition beginning in data file [SharedPool-Worker-3]* | *2015-10-09 > 15:31:28.704000* | *172.31.17.129* | *3713* > > *Skipped 0/2 > non-slice-intersecting sstables, included 0 due to tombstones > [SharedPool-Worker-3]* | *2015-10-09 15:31:28.704000* | *172.31.17.129* | > *3807* > > > *Merging > data from memtables and 2 sstables [SharedPool-Worker-3]* | *2015-10-09 > 15:31:28.704000* | *172.31.17.129* | *3818* > > > *Read 462 live and 0 tombstone cells [SharedPool-Worker-3]* | > *2015-10-09 > 15:31:29.611000* | *172.31.17.129* | *910723* > > > *Request complete* | *2015-10-09 > 15:31:29.649251* | *172.31.17.129* | *949251* > > > > > Below when this is around 1400 ms . But the trace data seems to look > faster ..? > > > > *racing session: *7c591550-6ebf-11e5-9493-9131aba66d63 > > *activity* > > | > *timestamp* | *source* | *source_elapsed* > > ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+---------------+---------------- > > > *Execute CQL3 query* | > *2015-10-09 > 15:54:00.869000* | *172.31.17.129* | *0* > *Parsing select * from processinfometric_profile where > profilecontext='GENERIC' and id=‘1' and month='Oct' and day='' and hour='' > and minute=''; [SharedPool-Worker-133]* | *2015-10-09 15:54:00.869000* | > *172.31.17.129* | *122* > > > *Preparing statement [SharedPool-Worker-133]* | > *2015-10-09 > 15:54:00.869000* | *172.31.17.129* | *265* > > *Executing > single-partition query on processinfometric_profile [SharedPool-Worker-9]* > | *2015-10-09 15:54:00.870000* | *172.31.17.129* | *673* > > > *Acquiring sstable references [SharedPool-Worker-9]* | > *2015-10-09 > 15:54:00.870000* | *172.31.17.129* | *695* > > > *Merging memtable tombstones [SharedPool-Worker-9]* | > *2015-10-09 > 15:54:00.870000* | *172.31.17.129* | *709* > > > *Key cache hit for sstable 242 [SharedPool-Worker-9]* | > *2015-10-09 > 15:54:00.872000* | *172.31.17.129* | *3134* > > > *Seeking > to partition beginning in data file [SharedPool-Worker-9]* | *2015-10-09 > 15:54:00.872000* | *172.31.17.129* | *3155* > > *Skipped 0/1 > non-slice-intersecting sstables, included 0 due to tombstones > [SharedPool-Worker-9]* | *2015-10-09 15:54:00.872000* | *172.31.17.129* | > *3259* > > > *Merging > data from memtables and 1 sstables [SharedPool-Worker-9]* | *2015-10-09 > 15:54:00.872000* | *172.31.17.129* | *3270* > > > *Read 462 live and 0 tombstone cells [SharedPool-Worker-9]* | > *2015-10-09 > 15:54:02.070000* | *172.31.17.129* | *201640* > > > *Request complete* | > *2015-10-09 > 15:54:02.111294* | *172.31.17.129* | *242294* > > > > > This is when it was 1600 ms. > > *Tracing session: *9c0ea900-6ec4-11e5-9493-9131aba66d63 > > *activity* > > | > *timestamp* | *source* | *source_elapsed* > > ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+---------------+---------------- > > > *Execute CQL3 query* | > *2015-10-09 > 16:30:41.552000* | *172.31.17.129* | *0* > *Parsing select * from processinfometric_profile where > profilecontext='GENERIC' and id=‘1' and month='Oct' and day='' and hour='' > and minute=''; [SharedPool-Worker-149]* | *2015-10-09 16:30:41.552000* | > *172.31.17.129* | *99* > > > *Preparing statement [SharedPool-Worker-149]* | > *2015-10-09 > 16:30:41.552000* | *172.31.17.129* | *215* > > *Executing > single-partition query on processinfometric_profile [SharedPool-Worker-164]* > | *2015-10-09 16:30:41.552000* | *172.31.17.129* | *507* > > > *Acquiring sstable references [SharedPool-Worker-164]* | > *2015-10-09 > 16:30:41.552000* | *172.31.17.129* | *533* > > > *Merging memtable tombstones [SharedPool-Worker-164]* | > *2015-10-09 > 16:30:41.552000* | *172.31.17.129* | *551* > > > *Key cache hit for sstable 302 [SharedPool-Worker-164]* | > *2015-10-09 > 16:30:41.556000* | *172.31.17.129* | *3875* > > > *Seeking > to partition beginning in data file [SharedPool-Worker-164]* | *2015-10-09 > 16:30:41.556000* | *172.31.17.129* | *3902* > > *Skipped 0/1 > non-slice-intersecting sstables, included 0 due to tombstones > [SharedPool-Worker-164]* | *2015-10-09 16:30:41.556000* | *172.31.17.129* > | *4050* > > > *Merging > data from memtables and 1 sstables [SharedPool-Worker-164]* | *2015-10-09 > 16:30:41.556000* | *172.31.17.129* | *4068* > > > *Read 468 live and 0 tombstone cells [SharedPool-Worker-164]* | > *2015-10-09 > 16:30:43.269000* | *172.31.17.129* | *717277* > > > *Request complete* | > *2015-10-09 > 16:30:43.307559* | *172.31.17.129* | *755559* > > > > > The last one is now at 2300 ms. > > > *racing session: *7d89a1e0-6ec6-11e5-9493-9131aba66d63 > > *activity* > > | > *timestamp* | *source* | *source_elapsed* > > ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+---------------+---------------- > > > *Execute CQL3 query* | *2015-10-09 > 16:44:09.342000* | *172.31.17.129* | *0* > *Parsing select * from processinfometric_profile where > profilecontext='GENERIC' and id=‘1' and month='Oct' and day='' and hour='' > and minute=''; [SharedPool-Worker-1]* | *2015-10-09 16:44:09.342000* | > *172.31.17.129* | *87* > > > *Preparing statement [SharedPool-Worker-1]* | > *2015-10-09 > 16:44:09.342000* | *172.31.17.129* | *277* > > *Executing > single-partition query on processinfometric_profile [SharedPool-Worker-2]* > | *2015-10-09 16:44:09.343000* | *172.31.17.129* | *456* > > > *Acquiring sstable references [SharedPool-Worker-2]* | *2015-10-09 > 16:44:09.343000* | *172.31.17.129* | *473* > > > *Merging memtable tombstones [SharedPool-Worker-2]* | > *2015-10-09 > 16:44:09.343000* | *172.31.17.129* | *485* > > > *Key cache hit for sstable 328 [SharedPool-Worker-2]* | > *2015-10-09 > 16:44:09.345000* | *172.31.17.129* | *2851* > > > *Seeking > to partition beginning in data file [SharedPool-Worker-2]* | *2015-10-09 > 16:44:09.345000* | *172.31.17.129* | *2869* > > *Skipped 0/1 > non-slice-intersecting sstables, included 0 due to tombstones > [SharedPool-Worker-2]* | *2015-10-09 16:44:09.345000* | *172.31.17.129* | > *3005* > > > *Merging > data from memtables and 1 sstables [SharedPool-Worker-2]* | *2015-10-09 > 16:44:09.345001* | *172.31.17.129* | *3017* > > > *Read 468 live and 0 tombstone cells [SharedPool-Worker-2]* | > *2015-10-09 > 16:44:11.329000* | *172.31.17.129* | *987011* > > > *Request complete* | *2015-10-09 > 16:44:11.388637* | *172.31.17.129* | *46637* > > > > > On Oct 9, 2015, at 2:48 PM, Nazario Parsacala <dodongj...@gmail.com> > wrote: > > Compaction did not help too. > > > > On Oct 9, 2015, at 1:01 PM, Nazario Parsacala <dodongj...@gmail.com> > wrote: > > So I upgraded to 2.2.2 and change the compaction strategy from > DateTieredCompactionStrategy > to LeveledCompactionStrategy. But the problem still exists. > At the start we were getting responses around 80 to a couple of hundred of > ms. But after 1.5 hours of running, it is now hitting 1447 ms. I think this > will degrade some more as time progresses. I will let this run a couple of > hours more and will also try to force compaction. > > BTW, with 2.2.2 I am getting the following exceptions. Not sure if there > is already a bug report on this. > > Caused by: java.io.IOException: Seek position 182054 is not within mmap > segment (seg offs: 0, length: 182054) > at > org.apache.cassandra.io.util.ByteBufferDataInput.seek(ByteBufferDataInput.java:47) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.io.util.AbstractDataInput.skipBytes(AbstractDataInput.java:33) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.io.util.FileUtils.skipBytesFully(FileUtils.java:405) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.RowIndexEntry$Serializer.skipPromotedIndex(RowIndexEntry.java:164) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.RowIndexEntry$Serializer.skip(RowIndexEntry.java:155) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.io.sstable.format.big.BigTableReader.getPosition(BigTableReader.java:244) > ~[apache-cassandra-2.2.2.jar:2.2.2] > ... 17 common frames omitted > WARN [SharedPool-Worker-42] 2015-10-09 12:54:57,221 > AbstractTracingAwareExecutorService.java:169 - Uncaught exception on thread > Thread[SharedPool-Worker-42,5,main]: {} > java.lang.RuntimeException: > org.apache.cassandra.io.sstable.CorruptSSTableException: > java.io.IOException: Seek position 182054 is not within mmap segment (seg > offs: 0, length: 182054) > at > org.apache.cassandra.service.StorageProxy$DroppableRunnable.run(StorageProxy.java:2187) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) > ~[na:1.8.0_60] > at > org.apache.cassandra.concurrent.AbstractTracingAwareExecutorService$FutureTask.run(AbstractTracingAwareExecutorService.java:164) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at org.apache.cassandra.concurrent.SEPWorker.run(SEPWorker.java:105) > [apache-cassandra-2.2.2.jar:2.2.2] > at java.lang.Thread.run(Thread.java:745) [na:1.8.0_60] > Caused by: org.apache.cassandra.io.sstable.CorruptSSTableException: > java.io.IOException: Seek position 182054 is not within mmap segment (seg > offs: 0, length: 182054) > at > org.apache.cassandra.io.sstable.format.big.BigTableReader.getPosition(BigTableReader.java:250) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.io.sstable.format.SSTableReader.getPosition(SSTableReader.java:1558) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.io.sstable.format.big.SSTableSliceIterator.<init>(SSTableSliceIterator.java:42) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.io.sstable.format.big.BigTableReader.iterator(BigTableReader.java:75) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.filter.SliceQueryFilter.getSSTableColumnIterator(SliceQueryFilter.java:246) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.filter.QueryFilter.getSSTableColumnIterator(QueryFilter.java:62) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.CollationController.collectAllData(CollationController.java:270) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.CollationController.getTopLevelColumns(CollationController.java:64) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:2004) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1808) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at org.apache.cassandra.db.Keyspace.getRow(Keyspace.java:360) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.SliceFromReadCommand.getRow(SliceFromReadCommand.java:85) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.service.StorageProxy$LocalReadRunnable.runMayThrow(StorageProxy.java:1537) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.service.StorageProxy$DroppableRunnable.run(StorageProxy.java:2183) > ~[apache-cassandra-2.2.2.jar:2.2.2] > ... 4 common frames omitted > Caused by: java.io.IOException: Seek position 182054 is not within mmap > segment (seg offs: 0, length: 182054) > at > org.apache.cassandra.io.util.ByteBufferDataInput.seek(ByteBufferDataInput.java:47) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.io.util.AbstractDataInput.skipBytes(AbstractDataInput.java:33) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.io.util.FileUtils.skipBytesFully(FileUtils.java:405) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.RowIndexEntry$Serializer.skipPromotedIndex(RowIndexEntry.java:164) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.db.RowIndexEntry$Serializer.skip(RowIndexEntry.java:155) > ~[apache-cassandra-2.2.2.jar:2.2.2] > at > org.apache.cassandra.io.sstable.format.big.BigTableReader.getPosition(BigTableReader.java:244) > ~[apache-cassandra-2.2.2.jar:2.2.2] > > > > > On Oct 9, 2015, at 9:26 AM, Carlos Alonso <i...@mrcalonso.com> wrote: > > Yeah, I was about to suggest the compaction strategy too. Leveled > compaction sounds like a better fit when records are being updated > > Carlos Alonso | Software Engineer | @calonso <https://twitter.com/calonso> > > On 8 October 2015 at 22:35, Tyler Hobbs <ty...@datastax.com> wrote: > >> Upgrade to 2.2.2. Your sstables are probably not compacting due to >> CASSANDRA-10270 <https://issues.apache.org/jira/browse/CASSANDRA-10270>, >> which was fixed in 2.2.2. >> >> Additionally, you may want to look into using leveled compaction ( >> http://www.datastax.com/dev/blog/when-to-use-leveled-compaction). >> >> On Thu, Oct 8, 2015 at 4:27 PM, Nazario Parsacala <dodongj...@gmail.com> >> wrote: >> >>> >>> Hi, >>> >>> so we are developing a system that computes profile of things that it >>> observes. The observation comes in form of events. Each thing that it >>> observe has an id and each thing has a set of subthings in it which has >>> measurement of some kind. Roughly there are about 500 subthings within each >>> thing. We receive events containing measurements of these 500 subthings >>> every 10 seconds or so. >>> >>> So as we receive events, we read the old profile value, calculate the >>> new profile based on the new value and save it back. We use the following >>> schema to hold the profile. >>> >>> CREATE TABLE myprofile ( >>> id text, >>> month text, >>> day text, >>> hour text, >>> subthings text, >>> lastvalue double, >>> count int, >>> stddev double, >>> PRIMARY KEY ((id, month, day, hour), subthings) >>> ) WITH CLUSTERING ORDER BY (subthings ASC) ); >>> >>> >>> This profile will then be use for certain analytics that can use in the >>> context of the ‘thing’ or in the context of specific thing and subthing. >>> >>> A profile can be defined as monthly, daily, hourly. So in case of >>> monthly the month will be set to the current month (i.e. ‘Oct’) and the day >>> and hour will be set to empty ‘’ string. >>> >>> >>> The problem that we have observed is that over time (actually in just a >>> matter of hours) we will see a huge degradation of query response for the >>> monthly profile. At the start it will be respinding in 10-100 ms and after >>> a couple of hours it will go to 2000-3000 ms . If you leave it for a couple >>> of days you will start experiencing readtimeouts . The query is basically >>> just : >>> >>> select * from myprofile where id=‘1’ and month=‘Oct’ and day=‘’ and >>> hour=‘' >>> >>> This will have only about 500 rows or so. >>> >>> >>> I believe that this is cause by the fact there are multiple updates done >>> to this specific partition. So what do we think can be done to resolve this >>> ? >>> >>> BTW, I am using Cassandra 2.2.1 . And since this is a test , this is >>> just running on a single node. >>> >>> >>> >>> >>> >> >> >> -- >> Tyler Hobbs >> DataStax <http://datastax.com/> >> > > > > > -- Tyler Hobbs DataStax <http://datastax.com/>