You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by André Cruz <an...@co.sapo.pt> on 2012/11/06 15:43:21 UTC
Strange delay in query
Hello.
I have a SCF that is acting strange. See these 2 query times:
get NamespaceRevision[3cd88d97-ffde-44ca-8ae9-5336caaebc4e] limit 33;
...
Returned 33 results.
Elapsed time: 41 msec(s).
get NamespaceRevision[3cd88d97-ffde-44ca-8ae9-5336caaebc4e] limit 34;
...
Returned 34 results.
Elapsed time: 3569 msec(s).
What can be the cause of this delay? I have a 3 node cluster with a replication factor of 3, so all of the nodes should have a copy of the data.
-> describe cluster;
Cluster Information:
Snitch: org.apache.cassandra.locator.PropertyFileSnitch
Partitioner: org.apache.cassandra.dht.RandomPartitioner
Schema versions:
a354e01a-d342-3755-9821-c550dcd1caba: [zzz, yyy, xxx]
Is there more information that I can provide?
Best regards,
André Cruz
Re: Strange delay in query
Posted by aaron morton <aa...@thelastpickle.com>.
If you have a long lived row with a lot of tombstones or overwrites, it's often more efficient to select a known list of columns. There are short circuits in the read path that can avoid older tombstones filled fragments of the row being read. (Obviously this is hard to do if you don't know the names of the columns).
Cheers
-----------------
Aaron Morton
Freelance Developer
@aaronmorton
http://www.thelastpickle.com
On 11/11/2012, at 10:51 PM, André Cruz <an...@co.sapo.pt> wrote:
> On Nov 11, 2012, at 12:01 AM, Binh Nguyen <bi...@gmail.com> wrote:
>
>> FYI: Repair does not remove tombstones. To remove tombstones you need to run compaction.
>> If you have a lot of data then make sure you run compaction on all nodes before running repair. We had a big trouble with our system regarding tombstone and it took us long time to figure out the reason. It turned out that repair process also transfers TTLed data (compaction is not triggered yet) to the other nodes even that data was removed from the other nodes in the compaction phase before that.
>>
>
> Aren't compactions triggered automatically? At least minor compactions. Also, I read this in http://www.datastax.com/docs/1.1/operations/tuning#tuning-compaction :
>
> "After running a major compaction, automatic minor compactions are no longer triggered, frequently requiring you to manually run major compactions on a routine basis."
> "DataStax does not recommend major compaction."
>
> So I'm unsure whether to start triggering manually these compactions… I guess I'll have to experiment with it.
>
> Thanks!
>
> André
Re: Strange delay in query
Posted by aaron morton <aa...@thelastpickle.com>.
Minor compactions will still be triggered whenever a size tier gets 4+ sstables (for the default compaction strategy). So it does not affect new data.
It just takes longer for the biggest size tier to get to 4 files. So it takes longer to compact the big output from the major compaction.
Assuming your data roughly follows a generational model, where newer data is written to often and older data is mostly read from. This can mean garbage hanging around in the big old file and *potentially* slowing things down.
Cheers
-----------------
Aaron Morton
Freelance Developer
@aaronmorton
http://www.thelastpickle.com
On 14/11/2012, at 12:21 AM, André Cruz <an...@co.sapo.pt> wrote:
> On Nov 13, 2012, at 8:54 AM, aaron morton <aa...@thelastpickle.com> wrote:
>
>>> I don't think that statement is accurate.
>> Which part ?
>
> Probably this part:
> "After running a major compaction, automatic minor compactions are no longer triggered, frequently requiring you to manually run major compactions on a routine basis."
>
> From what I read what happens is that it takes a lot longer for minor compactions to be triggered because 3 more files with the size equal to the compacted one have to be created?
>
> André
Re: Strange delay in query
Posted by "J. D. Jordan" <je...@gmail.com>.
Correct
On Nov 13, 2012, at 5:21 AM, André Cruz <an...@co.sapo.pt> wrote:
> On Nov 13, 2012, at 8:54 AM, aaron morton <aa...@thelastpickle.com> wrote:
>
>>> I don't think that statement is accurate.
>> Which part ?
>
> Probably this part:
> "After running a major compaction, automatic minor compactions are no longer triggered, frequently requiring you to manually run major compactions on a routine basis."
>
> From what I read what happens is that it takes a lot longer for minor compactions to be triggered because 3 more files with the size equal to the compacted one have to be created?
>
> André
Re: Strange delay in query
Posted by André Cruz <an...@co.sapo.pt>.
On Nov 13, 2012, at 8:54 AM, aaron morton <aa...@thelastpickle.com> wrote:
>> I don't think that statement is accurate.
> Which part ?
Probably this part:
"After running a major compaction, automatic minor compactions are no longer triggered, frequently requiring you to manually run major compactions on a routine basis."
From what I read what happens is that it takes a lot longer for minor compactions to be triggered because 3 more files with the size equal to the compacted one have to be created?
André
Re: Strange delay in query
Posted by aaron morton <aa...@thelastpickle.com>.
> I don't think that statement is accurate.
Which part ?
Cheers
-----------------
Aaron Morton
Freelance Developer
@aaronmorton
http://www.thelastpickle.com
On 13/11/2012, at 6:31 AM, Binh Nguyen <bi...@gmail.com> wrote:
> I don't think that statement is accurate. The minor compaction is still triggered for small sstables but for the big sstables it may or may not.
> By default Cassandra will wait until it finds 4 sstables of the same size to trigger the compaction so if the sstables are big then it may take a while to be compacted.
> If you are sure that you have a lot of tombstones and they will be deleted then I think you are safe to go.
>
> -Binh
>
> On Sun, Nov 11, 2012 at 1:51 AM, André Cruz <an...@co.sapo.pt> wrote:
> On Nov 11, 2012, at 12:01 AM, Binh Nguyen <bi...@gmail.com> wrote:
>
>> FYI: Repair does not remove tombstones. To remove tombstones you need to run compaction.
>> If you have a lot of data then make sure you run compaction on all nodes before running repair. We had a big trouble with our system regarding tombstone and it took us long time to figure out the reason. It turned out that repair process also transfers TTLed data (compaction is not triggered yet) to the other nodes even that data was removed from the other nodes in the compaction phase before that.
>>
>
> Aren't compactions triggered automatically? At least minor compactions. Also, I read this in http://www.datastax.com/docs/1.1/operations/tuning#tuning-compaction :
>
> " After running a major compaction, automatic minor compactions are no longer triggered, frequently requiring you to manually run major compactions on a routine basis."
> "DataStax does not recommend major compaction."
>
> So I'm unsure whether to start triggering manually these compactions… I guess I'll have to experiment with it.
>
> Thanks!
>
> André
>
Re: Strange delay in query
Posted by Binh Nguyen <bi...@gmail.com>.
I don't think that statement is accurate. The minor compaction is still
triggered for small sstables but for the big sstables it may or may not.
By default Cassandra will wait until it finds 4 sstables of the same size
to trigger the compaction so if the sstables are big then it may take a
while to be compacted.
If you are sure that you have a lot of tombstones and they will be deleted
then I think you are safe to go.
-Binh
On Sun, Nov 11, 2012 at 1:51 AM, André Cruz <an...@co.sapo.pt> wrote:
> On Nov 11, 2012, at 12:01 AM, Binh Nguyen <bi...@gmail.com> wrote:
>
> FYI: Repair does not remove tombstones. To remove tombstones you need to
> run compaction.
> If you have a lot of data then make sure you run compaction on all nodes
> before running repair. We had a big trouble with our system regarding
> tombstone and it took us long time to figure out the reason. It turned out
> that repair process also transfers TTLed data (compaction is not triggered
> yet) to the other nodes even that data was removed from the other nodes in
> the compaction phase before that.
>
>
> Aren't compactions triggered automatically? At least minor compactions.
> Also, I read this in
> http://www.datastax.com/docs/1.1/operations/tuning#tuning-compaction :
>
> " After running a major compaction, automatic minor compactions are no
> longer triggered, frequently requiring you to manually run major
> compactions on a routine basis."
> "DataStax does *not* recommend major compaction."
>
> So I'm unsure whether to start triggering manually these compactions… I
> guess I'll have to experiment with it.
>
> Thanks!
>
> André
>
Re: Strange delay in query
Posted by André Cruz <an...@co.sapo.pt>.
On Nov 11, 2012, at 12:01 AM, Binh Nguyen <bi...@gmail.com> wrote:
> FYI: Repair does not remove tombstones. To remove tombstones you need to run compaction.
> If you have a lot of data then make sure you run compaction on all nodes before running repair. We had a big trouble with our system regarding tombstone and it took us long time to figure out the reason. It turned out that repair process also transfers TTLed data (compaction is not triggered yet) to the other nodes even that data was removed from the other nodes in the compaction phase before that.
>
Aren't compactions triggered automatically? At least minor compactions. Also, I read this in http://www.datastax.com/docs/1.1/operations/tuning#tuning-compaction :
"After running a major compaction, automatic minor compactions are no longer triggered, frequently requiring you to manually run major compactions on a routine basis."
"DataStax does not recommend major compaction."
So I'm unsure whether to start triggering manually these compactions… I guess I'll have to experiment with it.
Thanks!
André
Re: Strange delay in query
Posted by Binh Nguyen <bi...@gmail.com>.
FYI: Repair does not remove tombstones. To remove tombstones you need to
run compaction.
If you have a lot of data then make sure you run compaction on all nodes
before running repair. We had a big trouble with our system regarding
tombstone and it took us long time to figure out the reason. It turned out
that repair process also transfers TTLed data (compaction is not triggered
yet) to the other nodes even that data was removed from the other nodes in
the compaction phase before that.
-Binh
On Fri, Nov 9, 2012 at 1:34 PM, André Cruz <an...@co.sapo.pt> wrote:
> That must be it. I dumped the sstables to json and there are lots of
> records, including ones that are returned to my application, that have the
> deletedAt attribute. I think this is because the regular repair job was not
> running for some time, surely more than the grace period, and lots of
> tombstones stayed behind even though we are running repair regularly now.
>
> Thanks!
> André
>
> On Nov 8, 2012, at 10:51 PM, Josep Blanquer <bl...@rightscale.com>
> wrote:
>
> Can it be that you have tons and tons of tombstoned columns in the middle
> of these two? I've seen plenty of performance issues with wide
> rows littered with column tombstones (you could check with dumping the
> sstables...)
>
> Just a thought...
>
> Josep M.
>
> On Thu, Nov 8, 2012 at 12:23 PM, André Cruz <an...@co.sapo.pt> wrote:
>
>> These are the two columns in question:
>>
>> => (super_column=13957152-234b-11e2-92bc-e0db550199f4,
>> (column=attributes, value=, timestamp=1351681613263657)
>> (column=blocks,
>> value=A4edo5MhHvojv3Ihx_JkFMsF3ypthtBvAZkoRHsjulw06pez86OHch3K3OpmISnDjHODPoCf69bKcuAZSJj-4Q,
>> timestamp=1351681613263657)
>> (column=hash,
>> value=8_p2QaeRaX_QwJbUWQ07ZqlNHei7ixu0MHxgu9oennfYOGfyH6EsEe_LYO8V8EC_1NPL44Gx8B7UhYV9VSb7Lg,
>> timestamp=1351681613263657)
>> (column=icon, value=image_jpg, timestamp=1351681613263657)
>> (column=is_deleted, value=true, timestamp=1351681613263657)
>> (column=is_dir, value=false, timestamp=1351681613263657)
>> (column=mime_type, value=image/jpeg, timestamp=1351681613263657)
>> (column=mtime, value=1351646803, timestamp=1351681613263657)
>> (column=name, value=/Mobile Photos/Photo 2012-10-28 17_13_50.jpeg,
>> timestamp=1351681613263657)
>> (column=revision, value=13957152-234b-11e2-92bc-e0db550199f4,
>> timestamp=1351681613263657)
>> (column=size, value=1379001, timestamp=1351681613263657)
>> (column=thumb_exists, value=true, timestamp=1351681613263657))
>> => (super_column=40b7ae4e-2449-11e2-8610-e0db550199f4,
>> (column=attributes, value={"posix": 420}, timestamp=1351790781154800)
>> (column=blocks,
>> value=9UCDkHNb8-8LuKr2bv9PjKcWCT0v7FCZa0ebNSflES4-o7QD6eYschVaweCKSbR29Dq2IeGl_Cu7BVnYJYphTQ,
>> timestamp=1351790781154800)
>> (column=hash,
>> value=kao2EV8jw_wN4EBoMkCXZWCwg3qQ0X6m9_X9JIGkEkiGKJE_JeKgkdoTAkAefXgGtyhChuhWPlWMxl_tX7VZUw,
>> timestamp=1351790781154800)
>> (column=icon, value=text_txt, timestamp=1351790781154800)
>> (column=is_dir, value=false, timestamp=1351790781154800)
>> (column=mime_type, value=text/plain, timestamp=1351790781154800)
>> (column=mtime, value=1351378576, timestamp=1351790781154800)
>> (column=name, value=/Documents/VIMDocument.txt,
>> timestamp=1351790781154800)
>> (column=revision, value=40b7ae4e-2449-11e2-8610-e0db550199f4,
>> timestamp=1351790781154800)
>> (column=size, value=13, timestamp=1351790781154800)
>> (column=thumb_exists, value=false, timestamp=1351790781154800))
>>
>>
>> I don't think their size is an issue here.
>>
>> André
>>
>> On Nov 8, 2012, at 6:04 PM, Andrey Ilinykh <ai...@gmail.com> wrote:
>>
>> What is the size of columns? Probably those two are huge.
>>
>>
>> On Thu, Nov 8, 2012 at 4:01 AM, André Cruz <an...@co.sapo.pt> wrote:
>>
>>> On Nov 7, 2012, at 12:15 PM, André Cruz <an...@co.sapo.pt> wrote:
>>>
>>> > This error also happens on my application that uses pycassa, so I
>>> don't think this is the same bug.
>>>
>>> I have narrowed it down to a slice between two consecutive columns.
>>> Observe this behaviour using pycassa:
>>>
>>> >>>
>>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'),
>>> column_count=2,
>>> column_start=uuid.UUID('13957152-234b-11e2-92bc-e0db550199f4')).keys()
>>> DEBUG 2012-11-08 11:55:51,170 pycassa_library.pool:30 6849
>>> 139928791262976 Connection 52905488 (xxx:9160) was checked out from pool
>>> 51715344
>>> DEBUG 2012-11-08 11:55:53,415 pycassa_library.pool:37 6849
>>> 139928791262976 Connection 52905488 (xxx:9160) was checked in to pool
>>> 51715344
>>> [UUID('13957152-234b-11e2-92bc-e0db550199f4'),
>>> UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')]
>>>
>>> A two column slice took more than 2s to return. If I request the next 2
>>> column slice:
>>>
>>> >>>
>>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'),
>>> column_count=2,
>>> column_start=uuid.UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')).keys()
>>> DEBUG 2012-11-08 11:57:32,750 pycassa_library.pool:30 6849
>>> 139928791262976 Connection 52904912 (xxx:9160) was checked out from pool
>>> 51715344
>>> DEBUG 2012-11-08 11:57:32,774 pycassa_library.pool:37 6849
>>> 139928791262976 Connection 52904912 (xxx:9160) was checked in to pool
>>> 51715344
>>> [UUID('40b7ae4e-2449-11e2-8610-e0db550199f4'),
>>> UUID('a364b028-2449-11e2-8882-e0db550199f4')]
>>>
>>> This takes 20msec... Is there a rational explanation for this different
>>> behaviour? Is there some threshold that I'm running into? Is there any way
>>> to obtain more debugging information about this problem?
>>>
>>> Thanks,
>>> André
>>
>>
>>
>>
>
>
Re: Strange delay in query
Posted by André Cruz <an...@co.sapo.pt>.
That must be it. I dumped the sstables to json and there are lots of records, including ones that are returned to my application, that have the deletedAt attribute. I think this is because the regular repair job was not running for some time, surely more than the grace period, and lots of tombstones stayed behind even though we are running repair regularly now.
Thanks!
André
On Nov 8, 2012, at 10:51 PM, Josep Blanquer <bl...@rightscale.com> wrote:
> Can it be that you have tons and tons of tombstoned columns in the middle of these two? I've seen plenty of performance issues with wide rows littered with column tombstones (you could check with dumping the sstables...)
>
> Just a thought...
>
> Josep M.
>
> On Thu, Nov 8, 2012 at 12:23 PM, André Cruz <an...@co.sapo.pt> wrote:
> These are the two columns in question:
>
> => (super_column=13957152-234b-11e2-92bc-e0db550199f4,
> (column=attributes, value=, timestamp=1351681613263657)
> (column=blocks, value=A4edo5MhHvojv3Ihx_JkFMsF3ypthtBvAZkoRHsjulw06pez86OHch3K3OpmISnDjHODPoCf69bKcuAZSJj-4Q, timestamp=1351681613263657)
> (column=hash, value=8_p2QaeRaX_QwJbUWQ07ZqlNHei7ixu0MHxgu9oennfYOGfyH6EsEe_LYO8V8EC_1NPL44Gx8B7UhYV9VSb7Lg, timestamp=1351681613263657)
> (column=icon, value=image_jpg, timestamp=1351681613263657)
> (column=is_deleted, value=true, timestamp=1351681613263657)
> (column=is_dir, value=false, timestamp=1351681613263657)
> (column=mime_type, value=image/jpeg, timestamp=1351681613263657)
> (column=mtime, value=1351646803, timestamp=1351681613263657)
> (column=name, value=/Mobile Photos/Photo 2012-10-28 17_13_50.jpeg, timestamp=1351681613263657)
> (column=revision, value=13957152-234b-11e2-92bc-e0db550199f4, timestamp=1351681613263657)
> (column=size, value=1379001, timestamp=1351681613263657)
> (column=thumb_exists, value=true, timestamp=1351681613263657))
> => (super_column=40b7ae4e-2449-11e2-8610-e0db550199f4,
> (column=attributes, value={"posix": 420}, timestamp=1351790781154800)
> (column=blocks, value=9UCDkHNb8-8LuKr2bv9PjKcWCT0v7FCZa0ebNSflES4-o7QD6eYschVaweCKSbR29Dq2IeGl_Cu7BVnYJYphTQ, timestamp=1351790781154800)
> (column=hash, value=kao2EV8jw_wN4EBoMkCXZWCwg3qQ0X6m9_X9JIGkEkiGKJE_JeKgkdoTAkAefXgGtyhChuhWPlWMxl_tX7VZUw, timestamp=1351790781154800)
> (column=icon, value=text_txt, timestamp=1351790781154800)
> (column=is_dir, value=false, timestamp=1351790781154800)
> (column=mime_type, value=text/plain, timestamp=1351790781154800)
> (column=mtime, value=1351378576, timestamp=1351790781154800)
> (column=name, value=/Documents/VIMDocument.txt, timestamp=1351790781154800)
> (column=revision, value=40b7ae4e-2449-11e2-8610-e0db550199f4, timestamp=1351790781154800)
> (column=size, value=13, timestamp=1351790781154800)
> (column=thumb_exists, value=false, timestamp=1351790781154800))
>
>
> I don't think their size is an issue here.
>
> André
>
> On Nov 8, 2012, at 6:04 PM, Andrey Ilinykh <ai...@gmail.com> wrote:
>
>> What is the size of columns? Probably those two are huge.
>>
>>
>> On Thu, Nov 8, 2012 at 4:01 AM, André Cruz <an...@co.sapo.pt> wrote:
>> On Nov 7, 2012, at 12:15 PM, André Cruz <an...@co.sapo.pt> wrote:
>>
>> > This error also happens on my application that uses pycassa, so I don't think this is the same bug.
>>
>> I have narrowed it down to a slice between two consecutive columns. Observe this behaviour using pycassa:
>>
>> >>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'), column_count=2, column_start=uuid.UUID('13957152-234b-11e2-92bc-e0db550199f4')).keys()
>> DEBUG 2012-11-08 11:55:51,170 pycassa_library.pool:30 6849 139928791262976 Connection 52905488 (xxx:9160) was checked out from pool 51715344
>> DEBUG 2012-11-08 11:55:53,415 pycassa_library.pool:37 6849 139928791262976 Connection 52905488 (xxx:9160) was checked in to pool 51715344
>> [UUID('13957152-234b-11e2-92bc-e0db550199f4'), UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')]
>>
>> A two column slice took more than 2s to return. If I request the next 2 column slice:
>>
>> >>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'), column_count=2, column_start=uuid.UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')).keys()
>> DEBUG 2012-11-08 11:57:32,750 pycassa_library.pool:30 6849 139928791262976 Connection 52904912 (xxx:9160) was checked out from pool 51715344
>> DEBUG 2012-11-08 11:57:32,774 pycassa_library.pool:37 6849 139928791262976 Connection 52904912 (xxx:9160) was checked in to pool 51715344
>> [UUID('40b7ae4e-2449-11e2-8610-e0db550199f4'), UUID('a364b028-2449-11e2-8882-e0db550199f4')]
>>
>> This takes 20msec... Is there a rational explanation for this different behaviour? Is there some threshold that I'm running into? Is there any way to obtain more debugging information about this problem?
>>
>> Thanks,
>> André
>>
>
>
Re: Strange delay in query
Posted by Josep Blanquer <bl...@rightscale.com>.
Can it be that you have tons and tons of tombstoned columns in the middle
of these two? I've seen plenty of performance issues with wide
rows littered with column tombstones (you could check with dumping the
sstables...)
Just a thought...
Josep M.
On Thu, Nov 8, 2012 at 12:23 PM, André Cruz <an...@co.sapo.pt> wrote:
> These are the two columns in question:
>
> => (super_column=13957152-234b-11e2-92bc-e0db550199f4,
> (column=attributes, value=, timestamp=1351681613263657)
> (column=blocks,
> value=A4edo5MhHvojv3Ihx_JkFMsF3ypthtBvAZkoRHsjulw06pez86OHch3K3OpmISnDjHODPoCf69bKcuAZSJj-4Q,
> timestamp=1351681613263657)
> (column=hash,
> value=8_p2QaeRaX_QwJbUWQ07ZqlNHei7ixu0MHxgu9oennfYOGfyH6EsEe_LYO8V8EC_1NPL44Gx8B7UhYV9VSb7Lg,
> timestamp=1351681613263657)
> (column=icon, value=image_jpg, timestamp=1351681613263657)
> (column=is_deleted, value=true, timestamp=1351681613263657)
> (column=is_dir, value=false, timestamp=1351681613263657)
> (column=mime_type, value=image/jpeg, timestamp=1351681613263657)
> (column=mtime, value=1351646803, timestamp=1351681613263657)
> (column=name, value=/Mobile Photos/Photo 2012-10-28 17_13_50.jpeg,
> timestamp=1351681613263657)
> (column=revision, value=13957152-234b-11e2-92bc-e0db550199f4,
> timestamp=1351681613263657)
> (column=size, value=1379001, timestamp=1351681613263657)
> (column=thumb_exists, value=true, timestamp=1351681613263657))
> => (super_column=40b7ae4e-2449-11e2-8610-e0db550199f4,
> (column=attributes, value={"posix": 420}, timestamp=1351790781154800)
> (column=blocks,
> value=9UCDkHNb8-8LuKr2bv9PjKcWCT0v7FCZa0ebNSflES4-o7QD6eYschVaweCKSbR29Dq2IeGl_Cu7BVnYJYphTQ,
> timestamp=1351790781154800)
> (column=hash,
> value=kao2EV8jw_wN4EBoMkCXZWCwg3qQ0X6m9_X9JIGkEkiGKJE_JeKgkdoTAkAefXgGtyhChuhWPlWMxl_tX7VZUw,
> timestamp=1351790781154800)
> (column=icon, value=text_txt, timestamp=1351790781154800)
> (column=is_dir, value=false, timestamp=1351790781154800)
> (column=mime_type, value=text/plain, timestamp=1351790781154800)
> (column=mtime, value=1351378576, timestamp=1351790781154800)
> (column=name, value=/Documents/VIMDocument.txt,
> timestamp=1351790781154800)
> (column=revision, value=40b7ae4e-2449-11e2-8610-e0db550199f4,
> timestamp=1351790781154800)
> (column=size, value=13, timestamp=1351790781154800)
> (column=thumb_exists, value=false, timestamp=1351790781154800))
>
>
> I don't think their size is an issue here.
>
> André
>
> On Nov 8, 2012, at 6:04 PM, Andrey Ilinykh <ai...@gmail.com> wrote:
>
> What is the size of columns? Probably those two are huge.
>
>
> On Thu, Nov 8, 2012 at 4:01 AM, André Cruz <an...@co.sapo.pt> wrote:
>
>> On Nov 7, 2012, at 12:15 PM, André Cruz <an...@co.sapo.pt> wrote:
>>
>> > This error also happens on my application that uses pycassa, so I don't
>> think this is the same bug.
>>
>> I have narrowed it down to a slice between two consecutive columns.
>> Observe this behaviour using pycassa:
>>
>> >>>
>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'),
>> column_count=2,
>> column_start=uuid.UUID('13957152-234b-11e2-92bc-e0db550199f4')).keys()
>> DEBUG 2012-11-08 11:55:51,170 pycassa_library.pool:30 6849
>> 139928791262976 Connection 52905488 (xxx:9160) was checked out from pool
>> 51715344
>> DEBUG 2012-11-08 11:55:53,415 pycassa_library.pool:37 6849
>> 139928791262976 Connection 52905488 (xxx:9160) was checked in to pool
>> 51715344
>> [UUID('13957152-234b-11e2-92bc-e0db550199f4'),
>> UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')]
>>
>> A two column slice took more than 2s to return. If I request the next 2
>> column slice:
>>
>> >>>
>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'),
>> column_count=2,
>> column_start=uuid.UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')).keys()
>> DEBUG 2012-11-08 11:57:32,750 pycassa_library.pool:30 6849
>> 139928791262976 Connection 52904912 (xxx:9160) was checked out from pool
>> 51715344
>> DEBUG 2012-11-08 11:57:32,774 pycassa_library.pool:37 6849
>> 139928791262976 Connection 52904912 (xxx:9160) was checked in to pool
>> 51715344
>> [UUID('40b7ae4e-2449-11e2-8610-e0db550199f4'),
>> UUID('a364b028-2449-11e2-8882-e0db550199f4')]
>>
>> This takes 20msec... Is there a rational explanation for this different
>> behaviour? Is there some threshold that I'm running into? Is there any way
>> to obtain more debugging information about this problem?
>>
>> Thanks,
>> André
>
>
>
>
Re: Strange delay in query
Posted by André Cruz <an...@co.sapo.pt>.
These are the two columns in question:
=> (super_column=13957152-234b-11e2-92bc-e0db550199f4,
(column=attributes, value=, timestamp=1351681613263657)
(column=blocks, value=A4edo5MhHvojv3Ihx_JkFMsF3ypthtBvAZkoRHsjulw06pez86OHch3K3OpmISnDjHODPoCf69bKcuAZSJj-4Q, timestamp=1351681613263657)
(column=hash, value=8_p2QaeRaX_QwJbUWQ07ZqlNHei7ixu0MHxgu9oennfYOGfyH6EsEe_LYO8V8EC_1NPL44Gx8B7UhYV9VSb7Lg, timestamp=1351681613263657)
(column=icon, value=image_jpg, timestamp=1351681613263657)
(column=is_deleted, value=true, timestamp=1351681613263657)
(column=is_dir, value=false, timestamp=1351681613263657)
(column=mime_type, value=image/jpeg, timestamp=1351681613263657)
(column=mtime, value=1351646803, timestamp=1351681613263657)
(column=name, value=/Mobile Photos/Photo 2012-10-28 17_13_50.jpeg, timestamp=1351681613263657)
(column=revision, value=13957152-234b-11e2-92bc-e0db550199f4, timestamp=1351681613263657)
(column=size, value=1379001, timestamp=1351681613263657)
(column=thumb_exists, value=true, timestamp=1351681613263657))
=> (super_column=40b7ae4e-2449-11e2-8610-e0db550199f4,
(column=attributes, value={"posix": 420}, timestamp=1351790781154800)
(column=blocks, value=9UCDkHNb8-8LuKr2bv9PjKcWCT0v7FCZa0ebNSflES4-o7QD6eYschVaweCKSbR29Dq2IeGl_Cu7BVnYJYphTQ, timestamp=1351790781154800)
(column=hash, value=kao2EV8jw_wN4EBoMkCXZWCwg3qQ0X6m9_X9JIGkEkiGKJE_JeKgkdoTAkAefXgGtyhChuhWPlWMxl_tX7VZUw, timestamp=1351790781154800)
(column=icon, value=text_txt, timestamp=1351790781154800)
(column=is_dir, value=false, timestamp=1351790781154800)
(column=mime_type, value=text/plain, timestamp=1351790781154800)
(column=mtime, value=1351378576, timestamp=1351790781154800)
(column=name, value=/Documents/VIMDocument.txt, timestamp=1351790781154800)
(column=revision, value=40b7ae4e-2449-11e2-8610-e0db550199f4, timestamp=1351790781154800)
(column=size, value=13, timestamp=1351790781154800)
(column=thumb_exists, value=false, timestamp=1351790781154800))
I don't think their size is an issue here.
André
On Nov 8, 2012, at 6:04 PM, Andrey Ilinykh <ai...@gmail.com> wrote:
> What is the size of columns? Probably those two are huge.
>
>
> On Thu, Nov 8, 2012 at 4:01 AM, André Cruz <an...@co.sapo.pt> wrote:
> On Nov 7, 2012, at 12:15 PM, André Cruz <an...@co.sapo.pt> wrote:
>
> > This error also happens on my application that uses pycassa, so I don't think this is the same bug.
>
> I have narrowed it down to a slice between two consecutive columns. Observe this behaviour using pycassa:
>
> >>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'), column_count=2, column_start=uuid.UUID('13957152-234b-11e2-92bc-e0db550199f4')).keys()
> DEBUG 2012-11-08 11:55:51,170 pycassa_library.pool:30 6849 139928791262976 Connection 52905488 (xxx:9160) was checked out from pool 51715344
> DEBUG 2012-11-08 11:55:53,415 pycassa_library.pool:37 6849 139928791262976 Connection 52905488 (xxx:9160) was checked in to pool 51715344
> [UUID('13957152-234b-11e2-92bc-e0db550199f4'), UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')]
>
> A two column slice took more than 2s to return. If I request the next 2 column slice:
>
> >>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'), column_count=2, column_start=uuid.UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')).keys()
> DEBUG 2012-11-08 11:57:32,750 pycassa_library.pool:30 6849 139928791262976 Connection 52904912 (xxx:9160) was checked out from pool 51715344
> DEBUG 2012-11-08 11:57:32,774 pycassa_library.pool:37 6849 139928791262976 Connection 52904912 (xxx:9160) was checked in to pool 51715344
> [UUID('40b7ae4e-2449-11e2-8610-e0db550199f4'), UUID('a364b028-2449-11e2-8882-e0db550199f4')]
>
> This takes 20msec... Is there a rational explanation for this different behaviour? Is there some threshold that I'm running into? Is there any way to obtain more debugging information about this problem?
>
> Thanks,
> André
>
Re: Strange delay in query
Posted by Andrey Ilinykh <ai...@gmail.com>.
What is the size of columns? Probably those two are huge.
On Thu, Nov 8, 2012 at 4:01 AM, André Cruz <an...@co.sapo.pt> wrote:
> On Nov 7, 2012, at 12:15 PM, André Cruz <an...@co.sapo.pt> wrote:
>
> > This error also happens on my application that uses pycassa, so I don't
> think this is the same bug.
>
> I have narrowed it down to a slice between two consecutive columns.
> Observe this behaviour using pycassa:
>
> >>>
> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'),
> column_count=2,
> column_start=uuid.UUID('13957152-234b-11e2-92bc-e0db550199f4')).keys()
> DEBUG 2012-11-08 11:55:51,170 pycassa_library.pool:30 6849 139928791262976
> Connection 52905488 (xxx:9160) was checked out from pool 51715344
> DEBUG 2012-11-08 11:55:53,415 pycassa_library.pool:37 6849 139928791262976
> Connection 52905488 (xxx:9160) was checked in to pool 51715344
> [UUID('13957152-234b-11e2-92bc-e0db550199f4'),
> UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')]
>
> A two column slice took more than 2s to return. If I request the next 2
> column slice:
>
> >>>
> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'),
> column_count=2,
> column_start=uuid.UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')).keys()
> DEBUG 2012-11-08 11:57:32,750 pycassa_library.pool:30 6849 139928791262976
> Connection 52904912 (xxx:9160) was checked out from pool 51715344
> DEBUG 2012-11-08 11:57:32,774 pycassa_library.pool:37 6849 139928791262976
> Connection 52904912 (xxx:9160) was checked in to pool 51715344
> [UUID('40b7ae4e-2449-11e2-8610-e0db550199f4'),
> UUID('a364b028-2449-11e2-8882-e0db550199f4')]
>
> This takes 20msec... Is there a rational explanation for this different
> behaviour? Is there some threshold that I'm running into? Is there any way
> to obtain more debugging information about this problem?
>
> Thanks,
> André
Re: Strange delay in query
Posted by André Cruz <an...@co.sapo.pt>.
On Nov 7, 2012, at 12:15 PM, André Cruz <an...@co.sapo.pt> wrote:
> This error also happens on my application that uses pycassa, so I don't think this is the same bug.
I have narrowed it down to a slice between two consecutive columns. Observe this behaviour using pycassa:
>>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'), column_count=2, column_start=uuid.UUID('13957152-234b-11e2-92bc-e0db550199f4')).keys()
DEBUG 2012-11-08 11:55:51,170 pycassa_library.pool:30 6849 139928791262976 Connection 52905488 (xxx:9160) was checked out from pool 51715344
DEBUG 2012-11-08 11:55:53,415 pycassa_library.pool:37 6849 139928791262976 Connection 52905488 (xxx:9160) was checked in to pool 51715344
[UUID('13957152-234b-11e2-92bc-e0db550199f4'), UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')]
A two column slice took more than 2s to return. If I request the next 2 column slice:
>>> DISCO_CASS.col_fam_nsrev.get(uuid.UUID('3cd88d97-ffde-44ca-8ae9-5336caaebc4e'), column_count=2, column_start=uuid.UUID('40b7ae4e-2449-11e2-8610-e0db550199f4')).keys()
DEBUG 2012-11-08 11:57:32,750 pycassa_library.pool:30 6849 139928791262976 Connection 52904912 (xxx:9160) was checked out from pool 51715344
DEBUG 2012-11-08 11:57:32,774 pycassa_library.pool:37 6849 139928791262976 Connection 52904912 (xxx:9160) was checked in to pool 51715344
[UUID('40b7ae4e-2449-11e2-8610-e0db550199f4'), UUID('a364b028-2449-11e2-8882-e0db550199f4')]
This takes 20msec... Is there a rational explanation for this different behaviour? Is there some threshold that I'm running into? Is there any way to obtain more debugging information about this problem?
Thanks,
André
Re: Strange delay in query
Posted by André Cruz <an...@co.sapo.pt>.
On Nov 7, 2012, at 2:12 AM, Chuan-Heng Hsiao <hs...@gmail.com> wrote:
> I assume you are using cassandra-cli and connecting to some specific node.
>
> You can check the following steps:
>
> 1. Can you still reproduce this issue? (not -> maybe the system/node issue)
Yes. I can reproduce this issue on all 3 nodes. Also, I have a replication factor of 3.
> 2. What's the result when query without limit?
This row has 600k columns. I issued a count, and after some 10s:
[disco@Disco] count NamespaceRevision[3cd88d97-ffde-44ca-8ae9-5336caaebc4e];
609054 columns
> 3. What's the result after doing nodetool repair -pr on that
> particular column family and that node?
I already issued a "nodetool repair" on all nodes, nothing changed. Would your command be any different?
> btw, there seems to be some minor bug in the 1.1.5 cassandra-cli (but
> not in 1.1.6).
This error also happens on my application that uses pycassa, so I don't think this is the same bug.
Thanks for the help!
André
Re: Strange delay in query
Posted by Chuan-Heng Hsiao <hs...@gmail.com>.
Hi Andre,
I am just a cassandra user, the following suggestions may not be valid.
I assume you are using cassandra-cli and connecting to some specific node.
You can check the following steps:
1. Can you still reproduce this issue? (not -> maybe the system/node issue)
2. What's the result when query without limit?
3. What's the result after doing nodetool repair -pr on that
particular column family and that node?
btw, there seems to be some minor bug in the 1.1.5 cassandra-cli (but
not in 1.1.6).
I got error msg after creating an empty keyspace and updating the
replication factor as 3 across 3-4 nodes.
but when I showed the schema again, the result was correct (including
replication factor).
Sincerely,
Hsiao
On Wed, Nov 7, 2012 at 8:34 AM, André Cruz <an...@co.sapo.pt> wrote:
> Can anyone shed some light on this matter, please? I don't want to just increase the timeout without understanding why this is happening. Some pointer for me to investigate would be helpful.
>
> I'm running Cassandra 1.1.5 and these are wide rows (lots of small columns). I would think that fetching the first 34 columns would be fast, and just a little bit slower than 33 columns, but this is a big difference.
>
> Thank you and best regards,
> André Cruz
>
> On Nov 6, 2012, at 2:43 PM, André Cruz <an...@co.sapo.pt> wrote:
>
>> Hello.
>>
>> I have a SCF that is acting strange. See these 2 query times:
>>
>>
>> get NamespaceRevision[3cd88d97-ffde-44ca-8ae9-5336caaebc4e] limit 33;
>> ...
>> Returned 33 results.
>> Elapsed time: 41 msec(s).
>>
>> get NamespaceRevision[3cd88d97-ffde-44ca-8ae9-5336caaebc4e] limit 34;
>> ...
>> Returned 34 results.
>> Elapsed time: 3569 msec(s).
>>
>>
>> What can be the cause of this delay? I have a 3 node cluster with a replication factor of 3, so all of the nodes should have a copy of the data.
>>
>> -> describe cluster;
>> Cluster Information:
>> Snitch: org.apache.cassandra.locator.PropertyFileSnitch
>> Partitioner: org.apache.cassandra.dht.RandomPartitioner
>> Schema versions:
>> a354e01a-d342-3755-9821-c550dcd1caba: [zzz, yyy, xxx]
>>
>>
>> Is there more information that I can provide?
>>
>> Best regards,
>> André Cruz
>
Re: Strange delay in query
Posted by André Cruz <an...@co.sapo.pt>.
Can anyone shed some light on this matter, please? I don't want to just increase the timeout without understanding why this is happening. Some pointer for me to investigate would be helpful.
I'm running Cassandra 1.1.5 and these are wide rows (lots of small columns). I would think that fetching the first 34 columns would be fast, and just a little bit slower than 33 columns, but this is a big difference.
Thank you and best regards,
André Cruz
On Nov 6, 2012, at 2:43 PM, André Cruz <an...@co.sapo.pt> wrote:
> Hello.
>
> I have a SCF that is acting strange. See these 2 query times:
>
>
> get NamespaceRevision[3cd88d97-ffde-44ca-8ae9-5336caaebc4e] limit 33;
> ...
> Returned 33 results.
> Elapsed time: 41 msec(s).
>
> get NamespaceRevision[3cd88d97-ffde-44ca-8ae9-5336caaebc4e] limit 34;
> ...
> Returned 34 results.
> Elapsed time: 3569 msec(s).
>
>
> What can be the cause of this delay? I have a 3 node cluster with a replication factor of 3, so all of the nodes should have a copy of the data.
>
> -> describe cluster;
> Cluster Information:
> Snitch: org.apache.cassandra.locator.PropertyFileSnitch
> Partitioner: org.apache.cassandra.dht.RandomPartitioner
> Schema versions:
> a354e01a-d342-3755-9821-c550dcd1caba: [zzz, yyy, xxx]
>
>
> Is there more information that I can provide?
>
> Best regards,
> André Cruz