Return-Path: X-Original-To: apmail-cassandra-commits-archive@www.apache.org Delivered-To: apmail-cassandra-commits-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 46E3418DE6 for ; Fri, 9 Oct 2015 22:50:06 +0000 (UTC) Received: (qmail 22842 invoked by uid 500); 9 Oct 2015 22:50:06 -0000 Delivered-To: apmail-cassandra-commits-archive@cassandra.apache.org Received: (qmail 22808 invoked by uid 500); 9 Oct 2015 22:50:06 -0000 Mailing-List: contact commits-help@cassandra.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cassandra.apache.org Delivered-To: mailing list commits@cassandra.apache.org Received: (qmail 22599 invoked by uid 99); 9 Oct 2015 22:50:05 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 09 Oct 2015 22:50:05 +0000 Date: Fri, 9 Oct 2015 22:50:05 +0000 (UTC) From: "Dodong Juan (JIRA)" To: commits@cassandra.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Comment Edited] (CASSANDRA-10502) Cassandra query degradation with high frequency updated tables MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CASSANDRA-10502?page=3Dcom.atla= ssian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId= =3D14951313#comment-14951313 ]=20 Dodong Juan edited comment on CASSANDRA-10502 at 10/9/15 10:49 PM: ------------------------------------------------------------------- The following traces of the were done on cqlsh . 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 lik= ely).. Just checkout the results. Below is the one that I took when from the client (java application) perspe= ctive it was returning data in about 1100 ms. {noformat} tracing session: 566477c0-6ebc-11e5-9493-9131aba66d63 activity = = | timestamp= | source | source_elapsed ---------------------------------------------------------------------------= ---------------------------------------------------------------------------= ----------------------------------------------------------------+----------= ------------------+---------------+---------------- = = Execute CQL3 query | 2015-10-0= 9 15:31:28.700000 | 172.31.17.129 | 0 Parsing select * from processinfometric_profile where profilecontext=3D'GE= NERIC' and id=3D=E2=80=981' and month=3D'Oct' and day=3D'' and hour=3D'' an= d minute=3D''; [SharedPool-Worker-1] | 2015-10-09 15:31:28.701000 | 172.31.= 17.129 | 101 = = Preparing statement [SharedPool-Worker-1] | 2015-10-0= 9 15:31:28.701000 | 172.31.17.129 | 334 = Executing single-par= tition query on processinfometric_profile [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.701000 | 172.31.17.129 | 692 = = Acquiring sstable references [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.701000 | 172.31.17.129 | 713 = = Merging memtable tombstones [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.701000 | 172.31.17.129 | 726 = = Key cache hit for sstable 209 [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3143 = Se= eking to partition beginning in data file [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3169 = = Key cache hit for sstable 208 [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3691 = Se= eking to partition beginning in data file [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3713 = Skipped 0/2 non-slice-intersecti= ng sstables, included 0 due to tombstones [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3807 = M= erging data from memtables and 2 sstables [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3818 = = Read 462 live and 0 tombstone cells [SharedPool-Worker-3] | 2015-10-0= 9 15:31:29.611000 | 172.31.17.129 | 910723 = = Request complete | 2015-10-0= 9 15:31:29.649251 | 172.31.17.129 | 949251 {noformat} Below when this is around 1400 ms . But the trace data seems to look faster= ..? racing session: 7c591550-6ebf-11e5-9493-9131aba66d63 activity = = | timesta= mp | 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=3D'GE= NERIC' and id=3D=E2=80=981' and month=3D'Oct' and day=3D'' and hour=3D'' an= d minute=3D''; [SharedPool-Worker-133] | 2015-10-09 15:54:00.869000 | 172.3= 1.17.129 | 122 = = Preparing statement [SharedPool-Worker-133] | 2015-10= -09 15:54:00.869000 | 172.31.17.129 | 265 = Executing single-p= artition 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-intersec= ting 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 = = | timesta= mp | 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=3D'GE= NERIC' and id=3D=E2=80=981' and month=3D'Oct' and day=3D'' and hour=3D'' an= d minute=3D''; [SharedPool-Worker-149] | 2015-10-09 16:30:41.552000 | 172.3= 1.17.129 | 99 = = Preparing statement [SharedPool-Worker-149] | 2015-10= -09 16:30:41.552000 | 172.31.17.129 | 215 = Executing single-par= tition 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 = Se= eking 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-intersecti= ng sstables, included 0 due to tombstones [SharedPool-Worker-164] | 2015-10= -09 16:30:41.556000 | 172.31.17.129 | 4050 = M= erging 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-0= 9 16:44:09.342000 | 172.31.17.129 | 0 Parsing select * from processinfometric_profile where profilecontext=3D'GE= NERIC' and id=3D=E2=80=981' and month=3D'Oct' and day=3D'' and hour=3D'' an= d minute=3D''; [SharedPool-Worker-1] | 2015-10-09 16:44:09.342000 | 172.31.= 17.129 | 87 = = Preparing statement [SharedPool-Worker-1] | 2015-10-0= 9 16:44:09.342000 | 172.31.17.129 | 277 = Executing single-par= tition query on processinfometric_profile [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.343000 | 172.31.17.129 | 456 = = Acquiring sstable references [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.343000 | 172.31.17.129 | 473 = = Merging memtable tombstones [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.343000 | 172.31.17.129 | 485 = = Key cache hit for sstable 328 [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.345000 | 172.31.17.129 | 2851 = Se= eking to partition beginning in data file [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.345000 | 172.31.17.129 | 2869 = Skipped 0/1 non-slice-intersecti= ng sstables, included 0 due to tombstones [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.345000 | 172.31.17.129 | 3005 = M= erging data from memtables and 1 sstables [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.345001 | 172.31.17.129 | 3017 = = Read 468 live and 0 tombstone cells [SharedPool-Worker-2] | 2015-10-0= 9 16:44:11.329000 | 172.31.17.129 | 987011 = = Request complete | 2015-10-0= 9 16:44:11.388637 | 172.31.17.129 | 46637 was (Author: dodongjuan): The following traces of the were done on cqlsh . 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 lik= ely).. Just checkout the results. Below is the one that I took when from the client (java application) perspe= ctive 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-0= 9 15:31:28.700000 | 172.31.17.129 | 0 Parsing select * from processinfometric_profile where profilecontext=3D'GE= NERIC' and id=3D=E2=80=981' and month=3D'Oct' and day=3D'' and hour=3D'' an= d minute=3D''; [SharedPool-Worker-1] | 2015-10-09 15:31:28.701000 | 172.31.= 17.129 | 101 = = Preparing statement [SharedPool-Worker-1] | 2015-10-0= 9 15:31:28.701000 | 172.31.17.129 | 334 = Executing single-par= tition query on processinfometric_profile [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.701000 | 172.31.17.129 | 692 = = Acquiring sstable references [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.701000 | 172.31.17.129 | 713 = = Merging memtable tombstones [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.701000 | 172.31.17.129 | 726 = = Key cache hit for sstable 209 [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3143 = Se= eking to partition beginning in data file [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3169 = = Key cache hit for sstable 208 [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3691 = Se= eking to partition beginning in data file [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3713 = Skipped 0/2 non-slice-intersecti= ng sstables, included 0 due to tombstones [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3807 = M= erging data from memtables and 2 sstables [SharedPool-Worker-3] | 2015-10-0= 9 15:31:28.704000 | 172.31.17.129 | 3818 = = Read 462 live and 0 tombstone cells [SharedPool-Worker-3] | 2015-10-0= 9 15:31:29.611000 | 172.31.17.129 | 910723 = = Request complete | 2015-10-0= 9 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 = = | timesta= mp | 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=3D'GE= NERIC' and id=3D=E2=80=981' and month=3D'Oct' and day=3D'' and hour=3D'' an= d minute=3D''; [SharedPool-Worker-133] | 2015-10-09 15:54:00.869000 | 172.3= 1.17.129 | 122 = = Preparing statement [SharedPool-Worker-133] | 2015-10= -09 15:54:00.869000 | 172.31.17.129 | 265 = Executing single-p= artition 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-intersec= ting 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 = = | timesta= mp | 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=3D'GE= NERIC' and id=3D=E2=80=981' and month=3D'Oct' and day=3D'' and hour=3D'' an= d minute=3D''; [SharedPool-Worker-149] | 2015-10-09 16:30:41.552000 | 172.3= 1.17.129 | 99 = = Preparing statement [SharedPool-Worker-149] | 2015-10= -09 16:30:41.552000 | 172.31.17.129 | 215 = Executing single-par= tition 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 = Se= eking 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-intersecti= ng sstables, included 0 due to tombstones [SharedPool-Worker-164] | 2015-10= -09 16:30:41.556000 | 172.31.17.129 | 4050 = M= erging 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-0= 9 16:44:09.342000 | 172.31.17.129 | 0 Parsing select * from processinfometric_profile where profilecontext=3D'GE= NERIC' and id=3D=E2=80=981' and month=3D'Oct' and day=3D'' and hour=3D'' an= d minute=3D''; [SharedPool-Worker-1] | 2015-10-09 16:44:09.342000 | 172.31.= 17.129 | 87 = = Preparing statement [SharedPool-Worker-1] | 2015-10-0= 9 16:44:09.342000 | 172.31.17.129 | 277 = Executing single-par= tition query on processinfometric_profile [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.343000 | 172.31.17.129 | 456 = = Acquiring sstable references [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.343000 | 172.31.17.129 | 473 = = Merging memtable tombstones [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.343000 | 172.31.17.129 | 485 = = Key cache hit for sstable 328 [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.345000 | 172.31.17.129 | 2851 = Se= eking to partition beginning in data file [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.345000 | 172.31.17.129 | 2869 = Skipped 0/1 non-slice-intersecti= ng sstables, included 0 due to tombstones [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.345000 | 172.31.17.129 | 3005 = M= erging data from memtables and 1 sstables [SharedPool-Worker-2] | 2015-10-0= 9 16:44:09.345001 | 172.31.17.129 | 3017 = = Read 468 live and 0 tombstone cells [SharedPool-Worker-2] | 2015-10-0= 9 16:44:11.329000 | 172.31.17.129 | 987011 = = Request complete | 2015-10-0= 9 16:44:11.388637 | 172.31.17.129 | 46637 > Cassandra query degradation with high frequency updated tables > -------------------------------------------------------------- > > Key: CASSANDRA-10502 > URL: https://issues.apache.org/jira/browse/CASSANDRA-1050= 2 > Project: Cassandra > Issue Type: Bug > Components: Core > Reporter: Dodong Juan > > Hi, > So we are developing a system that computes profile of things that it obs= erves. 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 measuremen= t of some kind. Roughly there are about 500 subthings within each thing. We= receive events containing measurements of these 500 subthings every 10 sec= onds or so. > So as we receive events, we read the old profile value, calculate the ne= w profile based on the new value and save it back.=20 > One of the things we observe are the processes running on the server. > We use the following schema to hold the profile.=20 > {noformat} > CREATE TABLE processinfometric_profile ( > profilecontext text, > id text, > month text, > day text, > hour text, > minute text, > command text, > cpu map, > majorfaults map, > minorfaults map, > nice map, > pagefaults map, > pid map, > ppid map, > priority map, > resident map, > rss map, > sharesize map, > size map, > starttime map, > state map, > threads map, > user map, > vsize map, > PRIMARY KEY ((profilecontext, id, month, day, hour, minute), command) > ) WITH CLUSTERING ORDER BY (command ASC) > AND bloom_filter_fp_chance =3D 0.1 > AND caching =3D '{"keys":"ALL", "rows_per_partition":"NONE"}' > AND comment =3D '' > AND compaction =3D {'class': 'org.apache.cassandra.db.compaction.Leve= ledCompactionStrategy'} > AND compression =3D {'sstable_compression': 'org.apache.cassandra.io.= compress.LZ4Compressor'} > AND dclocal_read_repair_chance =3D 0.1 > AND default_time_to_live =3D 0 > AND gc_grace_seconds =3D 864000 > AND max_index_interval =3D 2048 > AND memtable_flush_period_in_ms =3D 0 > AND min_index_interval =3D 128 > AND read_repair_chance =3D 0.0 > AND speculative_retry =3D '99.0PERCENTILE'; > {noformat} > This profile will then be use for certain analytics that can use in the c= ontext of the =E2=80=98thing=E2=80=99 or in the context of specific thing a= nd subthing.=20 > 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. =E2=80=98Oct=E2=80=99) an= d the day and hour will be set to empty =E2=80=98=E2=80=99 string. > The problem that we have observed is that over time (actually in just a m= atter of hours) we will see a huge degradation of query response for the m= onthly 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 j= ust : > {noformat} > select * from myprofile where id=3D=E2=80=981=E2=80=99 and month=3D=E2=80= =98Oct=E2=80=99 and day=3D=E2=80=98=E2=80=99 and hour=3D=E2=80=98' and minu= te=3D'' > {noformat} > This will have only about 500 rows or so. > We were using Cassandra 2.2.1 , but upgraded to 2.2.2 to see if it fixed = the issue to no avail. And since this is a test, we are running on a single= node. -- This message was sent by Atlassian JIRA (v6.3.4#6332)