You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by myreasoner <my...@gmail.com> on 2011/08/01 04:23:02 UTC
Read latency is over 1 minute on a column family with 400,000 rows
Hi, my read latency is really horrible and I can't figure out what went
wrong. I'm running cassandra 0.8.0 on a 5 machine cluster. The Fingerprint
ColumnFamily has 400,000 rows, each row has about 4,000 Super columns, and
each super column has 1 to 4 columns. One row looks like:
RowKey: 00c26f
=> (super_column=008002c161f008566a4931d6efeab128ef,
(column=183e9d10-b5f0-11e0-b0f4-0025901867fb, value=,
timestamp=1311510352604000))
=> (super_column=008004c34cafa12e22acbf3c2aab9b15ef,
(column=e6371bf6-b72c-11e0-b201-0025901867fb, value=,
timestamp=1311646419206000)
(column=e6371c00-b72c-11e0-b201-0025901867fb, value=,
timestamp=1311646419206000))
=> (super_column=0080097ac5154a96ea8620784ea3b5b56f,
(column=7691b846-b6fc-11e0-a703-003048f330bb, value=,
timestamp=1311625615955000))
...
On cassandra-cli doing *get Fingerprint[rowkey][SuperColumnName]* usually
takes over 60 seconds to return, which almost make the read un-useable. Is
there anything I can tune?
Here are the stats for a column family Fingerprint.
Column Family: Fingerprint
SSTable count: 2056
Space used (live): 164074936666
Space used (total): 164074936666
Memtable Columns Count: 177451
Memtable Data Size: 119948171
Memtable Switch Count: 366
Read Count: 5
*Read Latency: 74487.252 ms.*
Write Count: 30023
Write Latency: 1.602 ms.
Pending Tasks: 0
Key cache capacity: 200000
Key cache size: 8157
Key cache hit rate: 0.01322228263555929
Row cache: disabled
Compacted row minimum size: 104
Compacted row maximum size: 315852
Compacted row mean size: 33709
--
View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639649.html
Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Odp: Read latency is over 1 minute on a column family with 400,000
rows
Posted by Meler Wojciech <WM...@wp-sa.pl>.
Upgrade at least to 0.8.1 as your version has broken compaction...
Reagards
Wojtek Meler
----- Reply message -----
Od: "myreasoner" <my...@gmail.com>
Data: pon., sie 1, 2011 04:23
Temat: Read latency is over 1 minute on a column family with 400,000 rows
Do: "cassandra-user@incubator.apache.org" <ca...@incubator.apache.org>
Hi, my read latency is really horrible and I can't figure out what went
wrong. I'm running cassandra 0.8.0 on a 5 machine cluster. The Fingerprint
ColumnFamily has 400,000 rows, each row has about 4,000 Super columns, and
each super column has 1 to 4 columns. One row looks like:
RowKey: 00c26f
=> (super_column=008002c161f008566a4931d6efeab128ef,
(column=183e9d10-b5f0-11e0-b0f4-0025901867fb, value=,
timestamp=1311510352604000))
=> (super_column=008004c34cafa12e22acbf3c2aab9b15ef,
(column=e6371bf6-b72c-11e0-b201-0025901867fb, value=,
timestamp=1311646419206000)
(column=e6371c00-b72c-11e0-b201-0025901867fb, value=,
timestamp=1311646419206000))
=> (super_column=0080097ac5154a96ea8620784ea3b5b56f,
(column=7691b846-b6fc-11e0-a703-003048f330bb, value=,
timestamp=1311625615955000))
...
On cassandra-cli doing *get Fingerprint[rowkey][SuperColumnName]* usually
takes over 60 seconds to return, which almost make the read un-useable. Is
there anything I can tune?
Here are the stats for a column family Fingerprint.
Column Family: Fingerprint
SSTable count: 2056
Space used (live): 164074936666
Space used (total): 164074936666
Memtable Columns Count: 177451
Memtable Data Size: 119948171
Memtable Switch Count: 366
Read Count: 5
*Read Latency: 74487.252 ms.*
Write Count: 30023
Write Latency: 1.602 ms.
Pending Tasks: 0
Key cache capacity: 200000
Key cache size: 8157
Key cache hit rate: 0.01322228263555929
Row cache: disabled
Compacted row minimum size: 104
Compacted row maximum size: 315852
Compacted row mean size: 33709
--
View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639649.html
Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
"WIRTUALNA POLSKA" Spolka Akcyjna z siedziba w Gdansku przy ul. Traugutta 115 C, wpisana do Krajowego Rejestru Sadowego - Rejestru Przedsiebiorcow prowadzonego przez Sad Rejonowy Gdansk - Polnoc w Gdansku pod numerem KRS 0000068548, o kapitale zakladowym 67.980.024,00 zlotych oplaconym w calosci oraz Numerze Identyfikacji Podatkowej 957-07-51-216.
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by myreasoner <my...@gmail.com>.
Thanks. I will upgrade to 0.8.1 then.
--
View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6642582.html
Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Re: Read latency is over 1 minute on a column family with 400,000 rows
Posted by Jonathan Ellis <jb...@gmail.com>.
You really need to upgrade from 0.8.0 to fix that. Restarting won't
help, much (you'll get exactly one compaction against a given sstable,
before it stops working again).
On Mon, Aug 1, 2011 at 2:34 PM, myreasoner <my...@gmail.com> wrote:
> All compaction related settings in the yaml were untouched. The fingerprint
> column family has been populated three days ago and the cpu/disk usage were
> pretty low. I'd think Cassandra will silently start the compaction thread
> on my behalf and try to preserve the min/max thresholds, rather than waiting
> for a major compaction order from nodetool explicitly.
>
> Anyway, I did a major compaction on all 5 nodes almost at the same time. 4
> of them came back after a few hours, but one of the 5 nodes still has a lot
> of pending ones:
>
> cassandra/bin/nodetool -h localhost compactionstats
> pending tasks: 76
>
> And the uptime is very light.
> 14:31:44 up 30 days, 22:11, 4 users, load average: 0.29, 0.58, 0.58
>
> Some reply suggested this is a broken compaction. I will wait for a few
> hours and restart that node if nothing changes.
>
> --
> View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6642279.html
> Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
>
--
Jonathan Ellis
Project Chair, Apache Cassandra
co-founder of DataStax, the source for professional Cassandra support
http://www.datastax.com
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by myreasoner <my...@gmail.com>.
All compaction related settings in the yaml were untouched. The fingerprint
column family has been populated three days ago and the cpu/disk usage were
pretty low. I'd think Cassandra will silently start the compaction thread
on my behalf and try to preserve the min/max thresholds, rather than waiting
for a major compaction order from nodetool explicitly.
Anyway, I did a major compaction on all 5 nodes almost at the same time. 4
of them came back after a few hours, but one of the 5 nodes still has a lot
of pending ones:
cassandra/bin/nodetool -h localhost compactionstats
pending tasks: 76
And the uptime is very light.
14:31:44 up 30 days, 22:11, 4 users, load average: 0.29, 0.58, 0.58
Some reply suggested this is a broken compaction. I will wait for a few
hours and restart that node if nothing changes.
--
View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6642279.html
Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Re: Read latency is over 1 minute on a column family with 400,000 rows
Posted by Jonathan Ellis <jb...@gmail.com>.
Why do you think it's ignoring it?
In the output you pasted it said "I'm currently busy with a compaction
and I have a backlog of 66 more to get to after that."
On Mon, Aug 1, 2011 at 1:51 PM, myreasoner <my...@gmail.com> wrote:
> It was set the min/4 max/32
>
> Current compaction thresholds for MyKeyspace/Fingerprint:
> min = 4, max = 32
>
> What could possibly cause cassandra to ignore these settings?
>
> --
> View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6642138.html
> Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
>
--
Jonathan Ellis
Project Chair, Apache Cassandra
co-founder of DataStax, the source for professional Cassandra support
http://www.datastax.com
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by myreasoner <my...@gmail.com>.
It was set the min/4 max/32
Current compaction thresholds for MyKeyspace/Fingerprint:
min = 4, max = 32
What could possibly cause cassandra to ignore these settings?
--
View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6642138.html
Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Re: Read latency is over 1 minute on a column family with 400,000 rows
Posted by aaron morton <aa...@thelastpickle.com>.
Having 2056 live SSTables is very odd. Minor compaction should automatically reduce that number. What settings for min_compaction_threshold and max_compaction_threshold did you use when creating the CF ?
You can check them with node tool getcompactionthreshold . The default is min 4 and max 32.
You can also set them using nodetool setcompactionthreshold (Note the value is not persisted across a restart).
To provoke a minor compaction run nodetool flush. Minor compactions are preferred to major as they keep SSTables with the compaction buckets, where as major creates a single large file which will not be compacted again for a long time.
Hope that helps.
-----------------
Aaron Morton
Freelance Cassandra Developer
@aaronmorton
http://www.thelastpickle.com
On 1 Aug 2011, at 17:08, Teijo Holzer wrote:
> Looks like a broken node, just restart Cassandra on that node. Might want to wait for the compaction to finish on the other nodes.
>
> Also, don't forget to JMX gc() manually after the compaction has finished to delete the files on each node.
>
> On 01/08/11 16:29, myreasoner wrote:
>> On the node that the compaction returned almost immediately:
>>
>> *woot@n50:~$ /opt/cassandra/bin/nodetool -h localhost compactionstats
>> pending tasks: 66*
>>
>> However, messages shown on other nodes are:
>> compaction type: Major
>> keyspace: MyKeyspace
>> column family: Fingerprint
>> bytes compacted: 25505066421
>> bytes total: 45573108438
>> compaction progress: 55.97%
>> -----------------
>> pending tasks: 1
>>
>>
>>
>> --
>> View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639836.html
>> Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
>
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by Teijo Holzer <th...@wetafx.co.nz>.
Looks like a broken node, just restart Cassandra on that node. Might want to
wait for the compaction to finish on the other nodes.
Also, don't forget to JMX gc() manually after the compaction has finished to
delete the files on each node.
On 01/08/11 16:29, myreasoner wrote:
> On the node that the compaction returned almost immediately:
>
> *woot@n50:~$ /opt/cassandra/bin/nodetool -h localhost compactionstats
> pending tasks: 66*
>
> However, messages shown on other nodes are:
> compaction type: Major
> keyspace: MyKeyspace
> column family: Fingerprint
> bytes compacted: 25505066421
> bytes total: 45573108438
> compaction progress: 55.97%
> -----------------
> pending tasks: 1
>
>
>
> --
> View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639836.html
> Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by myreasoner <my...@gmail.com>.
On the node that the compaction returned almost immediately:
*woot@n50:~$ /opt/cassandra/bin/nodetool -h localhost compactionstats
pending tasks: 66*
However, messages shown on other nodes are:
compaction type: Major
keyspace: MyKeyspace
column family: Fingerprint
bytes compacted: 25505066421
bytes total: 45573108438
compaction progress: 55.97%
-----------------
pending tasks: 1
--
View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639836.html
Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by Teijo Holzer <th...@wetafx.co.nz>.
Hi,
try
nodetool -h localhost compact
check progress with
nodetool -h localhost compactionstats
and check system.log
Cheers,
T.
On 01/08/11 15:47, myreasoner wrote:
> Thanks.
>
> I did *./nodetool -h localhost compact keyspace columnfamily1 *. But it
> came back really quick and the cfstats doesn't seem change much.
>
> After compaction:
> Column Family: Fingerprint
> SSTable count: 2057
> Space used (live): 164351343468
> Space used (total): 164742957014
> Memtable Columns Count: 33224
> Memtable Data Size: 22410133
> Memtable Switch Count: 378
> Read Count: 7
> Read Latency: NaN ms.
> Write Count: 30972
> Write Latency: 1.579 ms.
> Pending Tasks: 0
> Key cache capacity: 200000
> Key cache size: 8157
> Key cache hit rate: 0.0
> Row cache: disabled
> Compacted row minimum size: 104
> Compacted row maximum size: 315852
> Compacted row mean size: 33846
>
>
> --
> View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639790.html
> Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Re: Read latency is over 1 minute on a column family with 400,000 rows
Posted by Mina Naguib <mi...@bloomdigital.com>.
Did you run that verbatim ? Or you appropriately substituted "keyspace" and "columnfamily1" ?
Also, anything in cassandra's log file (system.log) ? Compacting 150Gb over 2057 SSTables should take a reasonable bit of time...
On 2011-07-31, at 11:47 PM, myreasoner wrote:
> Thanks.
>
> I did *./nodetool -h localhost compact keyspace columnfamily1 *. But it
> came back really quick and the cfstats doesn't seem change much.
>
> After compaction:
> Column Family: Fingerprint
> SSTable count: 2057
> Space used (live): 164351343468
> Space used (total): 164742957014
> Memtable Columns Count: 33224
> Memtable Data Size: 22410133
> Memtable Switch Count: 378
> Read Count: 7
> Read Latency: NaN ms.
> Write Count: 30972
> Write Latency: 1.579 ms.
> Pending Tasks: 0
> Key cache capacity: 200000
> Key cache size: 8157
> Key cache hit rate: 0.0
> Row cache: disabled
> Compacted row minimum size: 104
> Compacted row maximum size: 315852
> Compacted row mean size: 33846
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by myreasoner <my...@gmail.com>.
Thanks.
I did *./nodetool -h localhost compact keyspace columnfamily1 *. But it
came back really quick and the cfstats doesn't seem change much.
After compaction:
Column Family: Fingerprint
SSTable count: 2057
Space used (live): 164351343468
Space used (total): 164742957014
Memtable Columns Count: 33224
Memtable Data Size: 22410133
Memtable Switch Count: 378
Read Count: 7
Read Latency: NaN ms.
Write Count: 30972
Write Latency: 1.579 ms.
Pending Tasks: 0
Key cache capacity: 200000
Key cache size: 8157
Key cache hit rate: 0.0
Row cache: disabled
Compacted row minimum size: 104
Compacted row maximum size: 315852
Compacted row mean size: 33846
--
View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639790.html
Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by Teijo Holzer <th...@wetafx.co.nz>.
Compaction is machine-local, you need to run it on every node. Do it as a
rolling compaction (or in parallel if you can take the performance hit).
Cheers,
T.
On 01/08/11 15:31, myreasoner wrote:
> If I do
>
> ./nodetool -h localhost compact keyspace columnfamily1
>
> it will go out and compact coumnfamily1 on all the nodes not just the
> localhost, correct?
>
> --
> View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639774.html
> Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by myreasoner <my...@gmail.com>.
If I do
./nodetool -h localhost compact keyspace columnfamily1
it will go out and compact coumnfamily1 on all the nodes not just the
localhost, correct?
--
View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639774.html
Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.
Re: Read latency is over 1 minute on a column family with 400,000
rows
Posted by Teijo Holzer <th...@wetafx.co.nz>.
Hi,
try running a major compaction via nodetool on this Column family. The number
of SSTables seems quite large.
Considering the space used, this might take a few hours and might also impact
performance.
Cheers,
T.
On 01/08/11 14:23, myreasoner wrote:
> Hi, my read latency is really horrible and I can't figure out what went
> wrong. I'm running cassandra 0.8.0 on a 5 machine cluster. The Fingerprint
> ColumnFamily has 400,000 rows, each row has about 4,000 Super columns, and
> each super column has 1 to 4 columns. One row looks like:
>
> RowKey: 00c26f
> => (super_column=008002c161f008566a4931d6efeab128ef,
> (column=183e9d10-b5f0-11e0-b0f4-0025901867fb, value=,
> timestamp=1311510352604000))
> => (super_column=008004c34cafa12e22acbf3c2aab9b15ef,
> (column=e6371bf6-b72c-11e0-b201-0025901867fb, value=,
> timestamp=1311646419206000)
> (column=e6371c00-b72c-11e0-b201-0025901867fb, value=,
> timestamp=1311646419206000))
> => (super_column=0080097ac5154a96ea8620784ea3b5b56f,
> (column=7691b846-b6fc-11e0-a703-003048f330bb, value=,
> timestamp=1311625615955000))
> ...
>
>
> On cassandra-cli doing *get Fingerprint[rowkey][SuperColumnName]* usually
> takes over 60 seconds to return, which almost make the read un-useable. Is
> there anything I can tune?
>
> Here are the stats for a column family Fingerprint.
> Column Family: Fingerprint
> SSTable count: 2056
> Space used (live): 164074936666
> Space used (total): 164074936666
> Memtable Columns Count: 177451
> Memtable Data Size: 119948171
> Memtable Switch Count: 366
> Read Count: 5
> *Read Latency: 74487.252 ms.*
> Write Count: 30023
> Write Latency: 1.602 ms.
> Pending Tasks: 0
> Key cache capacity: 200000
> Key cache size: 8157
> Key cache hit rate: 0.01322228263555929
> Row cache: disabled
> Compacted row minimum size: 104
> Compacted row maximum size: 315852
> Compacted row mean size: 33709
>
>
>
> --
> View this message in context: http://cassandra-user-incubator-apache-org.3065146.n2.nabble.com/Read-latency-is-over-1-minute-on-a-column-family-with-400-000-rows-tp6639649p6639649.html
> Sent from the cassandra-user@incubator.apache.org mailing list archive at Nabble.com.