incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Desimpel, Ignace" <Ignace.Desim...@nuance.com>
Subject RE: invalid column name length 0
Date Fri, 30 Sep 2011 09:13:40 GMT
Wanted to see if I still would similar exceptions if I lowered the load by reducing the replication
factor.
I saw that in the log files a lot of 'GC parNew' messages and started a complete new run (empty
database) with smaller JVM -Xmn1000M and with replication factor 1 (before it was 3).
Currently running, 10 % user cpu, 3% iowait, 'iostat await' 60 on commitlog device, 'iostat
await 50' on datafiles device, 'iostat svctm 3', 'vmstat si 0', 'vmstat so 0'
I still get the DEAD/UP messages, less 'GC parNew' messages (some parNew take more than 1
sec), but the system recovers and continues.
But the weird thing is that sometimes I still get java.util.concurrent.TimeoutException exceptions
, as well on batch inserts (per 100 rows) and on single row inserts (with just one 64 char
row key and one 4 char column name and 64 char column value). Rpc_timeout is 36000 !

I looked up what the other 3 machines were doing at that time. The 'received record...' and
'Document stored ...' are msgs of our application.
Below a stack trace of exceptions occurring at the 'same time', just 3 seconds time difference,
on machine 1. 
Machine 1 : 08:23:41 : the timeout exception stack trace as listed at end.
Machine 2:  Nothing special
=========
....
2011-09-30 08:23:20.888 Completed flushing /media/datadrive1/capd.cassandra.capd/dbdatafile/KsFullIdx/ForwardShortValues-g-149-Data.db
(131582322 bytes)
2011-09-30 08:23:20.889 Writing Memtable-ForwardLabelValues@260608040(47867232/1983693805
serialized/live bytes, 1150959 ops)
2011-09-30 08:23:23.002 Document stored with count records : 55336 Part DB (ms) : 3666
...
2011-09-30 08:23:33.467 Creating new commitlog segment ../../../../data/capd.cassandra.capd/dbcommitlog/CommitLog-1317363813467.log
2011-09-30 08:23:33.915 Document stored with count records : 9046 Part DB (ms) : 653
....
Machine 3: Is compacting. Also got a timeout exception about 36 seconds before the exception
of machine 1
=========
2011-09-30 08:22:34.458 Compacted to /media/datadrive1/capd.cassandra.capd/dbdatafile/KsFullIdx/ReverseStringValues-tmp-g-622-Data.db.
 966,991,510 to 965,780,805 (~99% of original) bytes for 74,345 keys.  Time: 208,416ms.
2011-09-30 08:22:37.474 Compacting large row KsFullIdx/ForwardStringValues:3237393737 (723544055
bytes) incrementally
2011-09-30 08:22:37.751 Document stored with count records : 13149 Part DB (ms) : 1613
2011-09-30 08:22:37.751 Document stored with count records : 13149 Time elapsed (ms) : 1748
2011-09-30 08:23:14.149 java.util.concurrent.TimeoutException
2011-09-30 08:23:14.149 	at org.apache.cassandra.service.AbstractWriteResponseHandler.get(AbstractWriteResponseHandler.java:69)
2011-09-30 08:23:14.149 	at org.apache.cassandra.service.StorageProxy.mutate(StorageProxy.java:169)
2011-09-30 08:23:14.150 	at be.landc.services.search.server.db.baseserver.indexsearch.store.cassandra.CassandraStore.storeAnnotationsProxy(CassandraStore.java:1290)
2011-09-30 08:23:33.548 Received records to store with total count : 23277
2011-09-30 08:23:34.705 Received records to store with total count : 9816
2011-09-30 08:23:35.152 Received records to store with total count : 8646
2011-09-30 08:23:35.323 Received records to store with total count : 49888
2011-09-30 08:23:35.475 Document stored with count records : 23277 Part DB (ms) : 1926
....
2011-09-30 08:23:39.627 Received records to store with total count : 8443
2011-09-30 08:23:40.081 Document stored with count records : 26862 Part DB (ms) : 3192
2011-09-30 08:23:40.081 Document stored with count records : 26862 Time elapsed (ms) : 3363
...
Machine 4: Nothing special, but also got the timeout exception for a single row insert at
08:22:30
=========
2011-09-30 08:22:12.569 Compacted to /media/datadrive1/capd.cassandra.capd/dbdatafile/KsFullIdx/ForwardIntegerValues-tmp-g-150-Data.db.
 586,039,224 to 586,036,960 (~99% of original) bytes for 36 keys.  Time: 152,823ms.
2011-09-30 08:22:30.713 TimedOutException()
2011-09-30 08:22:30.714 	at org.apache.cassandra.thrift.Cassandra$insert_result.read(Cassandra.java:15214)
2011-09-30 08:22:30.714 	at org.apache.cassandra.thrift.Cassandra$Client.recv_insert(Cassandra.java:858)
2011-09-30 08:22:30.715 	at org.apache.cassandra.thrift.Cassandra$Client.insert(Cassandra.java:830)
....
2011-09-30 08:23:18.902 Document stored with count records : 9186 Time elapsed (ms) : 2705
2011-09-30 08:23:19.240 Received records to store with total count : 8931
2011-09-30 08:23:19.898 flushing high-traffic column family ColumnFamilyStore(table='KsFullIdx',
columnFamily='ForwardStringValues')
2011-09-30 08:23:19.898 Enqueuing flush of Memtable-ForwardStringValues@1365818075(53315582/2559687119
serialized/live bytes, 1158851 ops)
2011-09-30 08:23:19.899 Writing Memtable-ForwardStringValues@1365818075(53315582/2559687119
serialized/live bytes, 1158851 ops)
2011-09-30 08:23:21.725 Document stored with count records : 8931 Part DB (ms) : 2484
....
2011-09-30 08:23:27.158 Document stored with count records : 12923 Time elapsed (ms) : 1126
2011-09-30 08:23:28.319 Completed flushing /media/datadrive1/capd.cassandra.capd/dbdatafile/KsFullIdx/ForwardStringValues-g-517-Data.db
(136428318 bytes)
2011-09-30 08:23:30.719 Received records to store with total count : 41543
...
2011-09-30 08:23:37.734 Received records to store with total count : 13653
2011-09-30 08:23:40.508 Document stored with count records : 13653 Part DB (ms) : 2774
...


Machine 1 : 08:23:41 : the timeout exception as listed below
=========
First one is a StorageProxy.mutate of 100 rows. 
Second one is a single row insert using thrift for a simple and small row/column/value. 
Third is again the same batch of 100 rows. 
Fourth is another single row insert (small row/column/value).

2011-09-30 08:22:59.967 Received records to store with total count : 10224
2011-09-30 08:23:00.231 Document stored with count records : 22179 Part DB (ms) : 1120
2011-09-30 08:23:00.232 Document stored with count records : 22179 Time elapsed (ms) : 1362
2011-09-30 08:23:00.521 Document stored with count records : 10224 Part DB (ms) : 553
2011-09-30 08:23:00.521 Document stored with count records : 10224 Time elapsed (ms) : 604
2011-09-30 08:23:02.291 Received records to store with total count : 8169
2011-09-30 08:23:02.825 Document stored with count records : 8169 Part DB (ms) : 533
2011-09-30 08:23:02.825 Document stored with count records : 8169 Time elapsed (ms) : 604
2011-09-30 08:23:03.762 Received records to store with total count : 15874
2011-09-30 08:23:04.861 Document stored with count records : 15874 Part DB (ms) : 1098
2011-09-30 08:23:04.861 Document stored with count records : 15874 Time elapsed (ms) : 1257
2011-09-30 08:23:04.888 Received records to store with total count : 20536
2011-09-30 08:23:06.082 Received records to store with total count : 18046
2011-09-30 08:23:06.244 Received records to store with total count : 67283
2011-09-30 08:23:06.408 Received records to store with total count : 41107
2011-09-30 08:23:38.592 Compacted to /media/datadrive1/capd.cassandra.capd/dbdatafile/KsFullIdx/ReverseStringValues-tmp-g-622-Data.db.
 958,447,377 to 958,447,377 (~100% of original) bytes for 74,860 keys.  Time: 148,318ms.
2011-09-30 08:23:41.553 java.util.concurrent.TimeoutException
2011-09-30 08:23:41.554 	at org.apache.cassandra.service.AbstractWriteResponseHandler.get(AbstractWriteResponseHandler.java:69)
2011-09-30 08:23:41.554 	at org.apache.cassandra.service.StorageProxy.mutate(StorageProxy.java:169)
2011-09-30 08:23:41.554 	at be.landc.services.search.server.db.baseserver.indexsearch.store.cassandra.CassandraStore.storeAnnotationsProxy(CassandraStore.java:1280)
2011-09-30 08:23:41.554 	at be.landc.services.search.server.db.baseserver.indexsearch.store.cassandra.CassandraStore.storeAnnotations(CassandraStore.java:1018)
2011-09-30 08:23:41.555 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.storeAnnotations(AnnotationStoreDb.java:181)
2011-09-30 08:23:41.555 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.processDocument(AnnotationStoreDb.java:333)
2011-09-30 08:23:41.555 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.processDocument(AnnotationStoreDb.java:290)
2011-09-30 08:23:41.555 	at be.landc.services.search.server.base.SearchServerDelegatingBase.processDocument(SearchServerDelegatingBase.java:93)
2011-09-30 08:23:41.556 	at sun.reflect.GeneratedMethodAccessor133.invoke(Unknown Source)
2011-09-30 08:23:41.556 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-09-30 08:23:41.556 	at java.lang.reflect.Method.invoke(Method.java:597)
2011-09-30 08:23:41.556 	at be.landc.framework.service.server.shared.Server.execute(Server.java:134)
2011-09-30 08:23:41.557 	at be.landc.framework.service.server.rmi.RMIServer.execute(RMIServer.java:80)
2011-09-30 08:23:41.557 	at sun.reflect.GeneratedMethodAccessor108.invoke(Unknown Source)
2011-09-30 08:23:41.557 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-09-30 08:23:41.557 	at java.lang.reflect.Method.invoke(Method.java:597)
2011-09-30 08:23:41.558 	at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
2011-09-30 08:23:41.558 	at sun.rmi.transport.Transport$1.run(Transport.java:159)
2011-09-30 08:23:41.558 	at java.security.AccessController.doPrivileged(Native Method)
2011-09-30 08:23:41.558 	at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
2011-09-30 08:23:41.559 	at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
2011-09-30 08:23:41.559 	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
2011-09-30 08:23:41.559 	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
2011-09-30 08:23:41.559 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
2011-09-30 08:23:41.560 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
2011-09-30 08:23:41.560 	at java.lang.Thread.run(Thread.java:662)
2011-09-30 08:23:42.285 TimedOutException()
2011-09-30 08:23:42.285 	at org.apache.cassandra.thrift.Cassandra$insert_result.read(Cassandra.java:15214)
2011-09-30 08:23:42.286 	at org.apache.cassandra.thrift.Cassandra$Client.recv_insert(Cassandra.java:858)
2011-09-30 08:23:42.286 	at org.apache.cassandra.thrift.Cassandra$Client.insert(Cassandra.java:830)
2011-09-30 08:23:42.286 	at be.landc.services.search.server.db.baseserver.indexsearch.store.cassandra.CassandraStore.storeAnnotationsProxy(CassandraStore.java:1236)
2011-09-30 08:23:42.286 	at be.landc.services.search.server.db.baseserver.indexsearch.store.cassandra.CassandraStore.storeAnnotations(CassandraStore.java:1018)
2011-09-30 08:23:42.286 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.storeAnnotations(AnnotationStoreDb.java:181)
2011-09-30 08:23:42.286 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.processDocument(AnnotationStoreDb.java:333)
2011-09-30 08:23:42.287 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.processDocument(AnnotationStoreDb.java:290)
2011-09-30 08:23:42.287 	at be.landc.services.search.server.base.SearchServerDelegatingBase.processDocument(SearchServerDelegatingBase.java:93)
2011-09-30 08:23:42.287 	at sun.reflect.GeneratedMethodAccessor133.invoke(Unknown Source)
2011-09-30 08:23:42.287 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-09-30 08:23:42.287 	at java.lang.reflect.Method.invoke(Method.java:597)
2011-09-30 08:23:42.287 	at be.landc.framework.service.server.shared.Server.execute(Server.java:134)
2011-09-30 08:23:42.288 	at be.landc.framework.service.server.rmi.RMIServer.execute(RMIServer.java:80)
2011-09-30 08:23:42.288 	at sun.reflect.GeneratedMethodAccessor108.invoke(Unknown Source)
2011-09-30 08:23:42.288 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-09-30 08:23:42.288 	at java.lang.reflect.Method.invoke(Method.java:597)
2011-09-30 08:23:42.288 	at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
2011-09-30 08:23:42.288 	at sun.rmi.transport.Transport$1.run(Transport.java:159)
2011-09-30 08:23:42.289 	at java.security.AccessController.doPrivileged(Native Method)
2011-09-30 08:23:42.289 	at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
2011-09-30 08:23:42.289 	at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
2011-09-30 08:23:42.289 	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
2011-09-30 08:23:42.289 	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
2011-09-30 08:23:42.290 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
2011-09-30 08:23:42.290 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
2011-09-30 08:23:42.290 	at java.lang.Thread.run(Thread.java:662)
2011-09-30 08:23:43.305 java.util.concurrent.TimeoutException
2011-09-30 08:23:43.305 	at org.apache.cassandra.service.AbstractWriteResponseHandler.get(AbstractWriteResponseHandler.java:69)
2011-09-30 08:23:43.306 	at org.apache.cassandra.service.StorageProxy.mutate(StorageProxy.java:169)
2011-09-30 08:23:43.306 	at be.landc.services.search.server.db.baseserver.indexsearch.store.cassandra.CassandraStore.storeAnnotationsProxy(CassandraStore.java:1280)
2011-09-30 08:23:43.306 	at be.landc.services.search.server.db.baseserver.indexsearch.store.cassandra.CassandraStore.storeAnnotations(CassandraStore.java:1018)
2011-09-30 08:23:43.306 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.storeAnnotations(AnnotationStoreDb.java:181)
2011-09-30 08:23:43.306 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.processDocument(AnnotationStoreDb.java:333)
2011-09-30 08:23:43.307 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.processDocument(AnnotationStoreDb.java:290)
2011-09-30 08:23:43.307 	at be.landc.services.search.server.base.SearchServerDelegatingBase.processDocument(SearchServerDelegatingBase.java:93)
2011-09-30 08:23:43.307 	at sun.reflect.GeneratedMethodAccessor133.invoke(Unknown Source)
2011-09-30 08:23:43.307 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-09-30 08:23:43.308 	at java.lang.reflect.Method.invoke(Method.java:597)
2011-09-30 08:23:43.308 	at be.landc.framework.service.server.shared.Server.execute(Server.java:134)
2011-09-30 08:23:43.308 	at be.landc.framework.service.server.rmi.RMIServer.execute(RMIServer.java:80)
2011-09-30 08:23:43.308 	at sun.reflect.GeneratedMethodAccessor108.invoke(Unknown Source)
2011-09-30 08:23:43.309 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-09-30 08:23:43.309 	at java.lang.reflect.Method.invoke(Method.java:597)
2011-09-30 08:23:43.309 	at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
2011-09-30 08:23:43.309 	at sun.rmi.transport.Transport$1.run(Transport.java:159)
2011-09-30 08:23:43.309 	at java.security.AccessController.doPrivileged(Native Method)
2011-09-30 08:23:43.310 	at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
2011-09-30 08:23:43.310 	at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
2011-09-30 08:23:43.310 	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
2011-09-30 08:23:43.310 	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
2011-09-30 08:23:43.310 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
2011-09-30 08:23:43.311 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
2011-09-30 08:23:43.311 	at java.lang.Thread.run(Thread.java:662)
2011-09-30 08:23:44.385 TimedOutException()
2011-09-30 08:23:44.385 	at org.apache.cassandra.thrift.Cassandra$insert_result.read(Cassandra.java:15214)
2011-09-30 08:23:44.386 	at org.apache.cassandra.thrift.Cassandra$Client.recv_insert(Cassandra.java:858)
2011-09-30 08:23:44.386 	at org.apache.cassandra.thrift.Cassandra$Client.insert(Cassandra.java:830)
2011-09-30 08:23:44.386 	at be.landc.services.search.server.db.baseserver.indexsearch.store.cassandra.CassandraStore.storeAnnotationsProxy(CassandraStore.java:1242)
2011-09-30 08:23:44.386 	at be.landc.services.search.server.db.baseserver.indexsearch.store.cassandra.CassandraStore.storeAnnotations(CassandraStore.java:1018)
2011-09-30 08:23:44.387 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.storeAnnotations(AnnotationStoreDb.java:181)
2011-09-30 08:23:44.387 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.processDocument(AnnotationStoreDb.java:333)
2011-09-30 08:23:44.387 	at be.landc.services.search.server.db.baseserver.AnnotationStoreDb.processDocument(AnnotationStoreDb.java:290)
2011-09-30 08:23:44.387 	at be.landc.services.search.server.base.SearchServerDelegatingBase.processDocument(SearchServerDelegatingBase.java:93)
2011-09-30 08:23:44.388 	at sun.reflect.GeneratedMethodAccessor133.invoke(Unknown Source)
2011-09-30 08:23:44.388 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-09-30 08:23:44.388 	at java.lang.reflect.Method.invoke(Method.java:597)
2011-09-30 08:23:44.388 	at be.landc.framework.service.server.shared.Server.execute(Server.java:134)
2011-09-30 08:23:44.389 	at be.landc.framework.service.server.rmi.RMIServer.execute(RMIServer.java:80)
2011-09-30 08:23:44.389 	at sun.reflect.GeneratedMethodAccessor108.invoke(Unknown Source)
2011-09-30 08:23:44.389 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-09-30 08:23:44.389 	at java.lang.reflect.Method.invoke(Method.java:597)
2011-09-30 08:23:44.390 	at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
2011-09-30 08:23:44.390 	at sun.rmi.transport.Transport$1.run(Transport.java:159)
2011-09-30 08:23:44.390 	at java.security.AccessController.doPrivileged(Native Method)
2011-09-30 08:23:44.390 	at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
2011-09-30 08:23:44.391 	at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
2011-09-30 08:23:44.391 	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
2011-09-30 08:23:44.391 	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
2011-09-30 08:23:44.391 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
2011-09-30 08:23:44.392 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
2011-09-30 08:23:44.392 	at java.lang.Thread.run(Thread.java:662)
2011-09-30 08:24:00.970 Received records to store with total count : 27928
2011-09-30 08:24:02.191 Document stored with count records : 27928 Part DB (ms) : 1220
2011-09-30 08:24:02.191 Document stored with count records : 27928 Time elapsed (ms) : 1339
2011-09-30 08:24:07.851 Received records to store with total count : 23548
2011-09-30 08:24:08.241 Received records to store with total count : 27686
2011-09-30 08:24:08.910 Document stored with count records : 23548 Part DB (ms) : 1058
2011-09-30 08:24:08.910 Document stored with count records : 23548 Time elapsed (ms) : 1328
2011-09-30 08:24:09.193 Received records to store with total count : 26117
2011-09-30 08:24:09.507 Document stored with count records : 27686 Part DB (ms) : 1265
2011-09-30 08:24:09.507 Document stored with count records : 27686 Time elapsed (ms) : 1495
2011-09-30 08:24:10.499 Received records to store with total count : 73102
2011-09-30 08:24:10.818 Received records to store with total count : 29409
2011-09-30 08:24:11.972 Document stored with count records : 29409 Part DB (ms) : 1153
2011-09-30 08:24:11.972 Document stored with count records : 29409 Time elapsed (ms) : 1383
2011-09-30 08:24:12.374 Received records to store with total count : 53034
2011-09-30 08:24:13.376 Document stored with count records : 73102 Part DB (ms) : 2876
2011-09-30 08:24:13.376 Document stored with count records : 73102 Time elapsed (ms) : 3303
2011-09-30 08:24:13.515 Received records to store with total count : 70652
2011-09-30 08:24:14.220 Received records to store with total count : 47999
2011-09-30 08:24:14.984 Document stored with count records : 53034 Part DB (ms) : 2609
2011-09-30 08:24:14.984 Document stored with count records : 53034 Time elapsed (ms) : 3133
2011-09-30 08:24:16.806 Creating new commitlog segment ../../../../data/capd.cassandra.capd/dbcommitlog/CommitLog-1317363856806.log
2011-09-30 08:24:17.153 Received records to store with total count : 9021

-----Original Message-----
From: Desimpel, Ignace [mailto:Ignace.Desimpel@nuance.com] 
Sent: dinsdag 27 september 2011 17:51
To: user@cassandra.apache.org
Subject: RE: invalid column name length 0

No, brand new, started from scratch, no data at all.
My setup get into trouble after a couple of hours since it then starts giving the Dead/up
messages. 
I also get messages like '11 MUTATION messages dropped in server lifetime'
Later on I got this type of exception also.

-----Original Message-----
From: Jonathan Ellis [mailto:jbellis@gmail.com]
Sent: dinsdag 27 september 2011 17:41
To: user@cassandra.apache.org
Subject: Re: invalid column name length 0

Is this upgraded from an earlier version?

On Tue, Sep 27, 2011 at 8:51 AM, Desimpel, Ignace <Ignace.Desimpel@nuance.com> wrote:
> Version 0.8.6.
>
> After an extreme load to 4 (embedded) cassandra servers with 
> replication factor 3 ( Ubuntu 10.4, dual six core, 64 bit, no swap, 1
> 15000 rpm commitlog disk, 1 15000 rpm datafile disk, ) I get a fatal 
> exception as listed below.
>
> No more messages were found after that.
>
>
>
> Probably other things are going wrong like the message "410 Could not 
> complete hinted handoff to /xxx.yyy.zzz.60", or the Dead/Up messages 
> (occurring long before this exception).
>
> But maybe this exception can point me in the right direction or even 
> point out some bug in Cassandra.
>
>
>
> Thanks,
>
> Ignace
>
>
>
>
>
> 2011-09-27 06:59:46,383 Compacting large row
> KsFullIdx/ForwardStringValues:3237343034 (178032211 bytes) 
> incrementally
>
> 2011-09-27 07:00:09,738 GC for ParNew: 311 ms for 1 collections,
> 8139389704 used; max is 33344716800
>
> 2011-09-27 07:00:12,818 Compacting large row
> KsFullIdx/ForwardStringValues:31363437 (1281862723 bytes) 
> incrementally
>
> 2011-09-27 07:02:16,025 Compacting large row
> KsFullIdx/ForwardStringValues:31363438 (1623095072 bytes) 
> incrementally
>
> 2011-09-27 07:04:38,332 GC for ParNew: 534 ms for 1 collections,
> 7811259472 used; max is 33344716800
>
> 2011-09-27 07:04:52,803 Compacting large row
> KsFullIdx/ForwardStringValues:3238313433 (1435774436 bytes) 
> incrementally
>
> 2011-09-27 07:06:57,160 Compacted to
> /media/datadrive1/capd.cassandra.capd/dbdatafile/KsFullIdx/ForwardStringValues-tmp-g-542-Data.db.
> 43,244,902,670 to 42,780,624,408 (~98% of original) bytes for 1,260 keys.
> Time: 4,321,960ms.
>
> 2011-09-27 08:01:42,090 Saved KsFullIdx-ForwardStringValues-KeyCache
> (572
> items) in 16 ms
>
> 2011-09-27 08:01:42,182 Saved KsFullIdx-ReverseStringValues-KeyCache
> (25688
> items) in 63 ms
>
> 2011-09-27 08:18:13,078 InetAddress /xxx.yyy.zzz.62 is now dead.
>
> 2011-09-27 08:18:16,467 InetAddress /xxx.yyy.zzz.62 is now UP
>
> 2011-09-27 08:48:56,410 Could not complete hinted handoff to
> /xxx.yyy.zzz.60
>
> 2011-09-27 08:48:56,410 Enqueuing flush of
> Memtable-HintsColumnFamily@2083796703(12097/196566 serialized/live 
> bytes,
> 254 ops)
>
> 2011-09-27 08:48:56,411 Writing
> Memtable-HintsColumnFamily@2083796703(12097/196566 serialized/live 
> bytes,
> 254 ops)
>
> 2011-09-27 08:48:56,411 Nothing to compact in HintsColumnFamily; use 
> forceUserDefinedCompaction if you wish to force compaction of single 
> sstables (e.g. for tombstone collection)
>
> 2011-09-27 08:48:56,411 Finished hinted handoff of 254 rows to 
> endpoint
> /xxx.yyy.zzz.60
>
> 2011-09-27 08:48:56,490 Completed flushing 
> /media/datadrive1/capd.cassandra.capd/dbdatafile/system/HintsColumnFam
> ily-g-10-Data.db
> (25079 bytes)
>
> 2011-09-27 08:49:42,858 Started hinted handoff for endpoint
> /xxx.yyy.zzz.62
>
> 2011-09-27 12:01:42,100 Saved KsFullIdx-ForwardStringValues-KeyCache
> (712
> items) in 27 ms
>
> 2011-09-27 12:01:42,182 Saved KsFullIdx-ReverseStringValues-KeyCache
> (30742
> items) in 55 ms
>
> 2011-09-27 12:10:01,016 InetAddress /xxx.yyy.zzz.59 is now dead.
>
> 2011-09-27 12:10:02,272 InetAddress /xxx.yyy.zzz.59 is now UP
>
> 2011-09-27 12:17:34,596 Fatal exception in thread 
> Thread[HintedHandoff:1,5,RMI Runtime]
>
> java.io.IOError:
> org.apache.cassandra.db.ColumnSerializer$CorruptColumnException: 
> invalid column name length 0
>
>                 at
> org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSort
> edMap.java:265)
>
>                 at
> org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:
> 281)
>
>                 at
> org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:
> 236)
>
>                 at
> java.util.concurrent.ConcurrentSkipListMap.buildFromSorted(ConcurrentS
> kipListMap.java:1493)
>
>                 at
> java.util.concurrent.ConcurrentSkipListMap.<init>(ConcurrentSkipListMa
> p.java:1443)
>
>                 at
> org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.
> java:445)
>
>                 at
> org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.
> java:428)
>
>                 at
> org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.
> java:418)
>
>                 at
> org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.
> java:380)
>
>                 at
> org.apache.cassandra.db.columniterator.IndexedSliceReader$IndexedBlock
> Fetcher.getNextBlock(IndexedSliceReader.java:179)
>
>                 at
> org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(
> IndexedSliceReader.java:121)
>
>                 at
> org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(
> IndexedSliceReader.java:49)
>
>                 at
> com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIt
> erator.java:140)
>
>                 at
> com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.ja
> va:135)
>
>                 at
> org.apache.cassandra.db.columniterator.SSTableSliceIterator.hasNext(SS
> TableSliceIterator.java:108)
>
>                 at
> org.apache.commons.collections.iterators.CollatingIterator.set(Collati
> ngIterator.java:283)
>
>                 at
> org.apache.commons.collections.iterators.CollatingIterator.least(Colla
> tingIterator.java:326)
>
>                 at
> org.apache.commons.collections.iterators.CollatingIterator.next(Collat
> ingIterator.java:230)
>
>                 at
> org.apache.cassandra.utils.ReducingIterator.computeNext(ReducingIterat
> or.java:69)
>
>                 at
> com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIt
> erator.java:140)
>
>                 at
> com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.ja
> va:135)
>
>                 at
> org.apache.cassandra.db.filter.SliceQueryFilter.collectReducedColumns(
> SliceQueryFilter.java:116)
>
>                 at
> org.apache.cassandra.db.filter.QueryFilter.collectCollatedColumns(Quer
> yFilter.java:142)
>
>                 at
> org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFam
> ilyStore.java:1427)
>
>                 at
> org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamily
> Store.java:1304)
>
>                 at
> org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamily
> Store.java:1261)
>
>                 at
> org.apache.cassandra.db.HintedHandOffManager.sendRow(HintedHandOffMana
> ger.java:155)
>
>                 at
> org.apache.cassandra.db.HintedHandOffManager.deliverHintsToEndpoint(Hi
> ntedHandOffManager.java:350)
>
>                 at
> org.apache.cassandra.db.HintedHandOffManager.access$100(HintedHandOffM
> anager.java:89)
>
>                 at
> org.apache.cassandra.db.HintedHandOffManager$2.runMayThrow(HintedHandO
> ffManager.java:397)
>
>                 at
> org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30
> )
>
>                 at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecu
> tor.java:886)
>
>                 at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.
> java:908)
>
>                 at java.lang.Thread.run(Thread.java:662)
>
> Caused by: org.apache.cassandra.db.ColumnSerializer$CorruptColumnException:
> invalid column name length 0
>
>                 at
> org.apache.cassandra.db.ColumnSerializer.deserialize(ColumnSerializer.
> java:89)
>
>                 at
> org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSort
> edMap.java:261)
>
>                 ... 33 more
>
> 2011-09-27 12:17:53,291 Started hinted handoff for endpoint
> /xxx.yyy.zzz.59



--
Jonathan Ellis
Project Chair, Apache Cassandra
co-founder of DataStax, the source for professional Cassandra support http://www.datastax.com

Mime
View raw message