[
https://issues.apache.org/jira/browse/CASSANDRA-5068?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13551246#comment-13551246
]
Michael Kjellman commented on CASSANDRA-5068:
---------------------------------------------
{code}
INFO [GossipStage:1] 2013-01-10 23:45:19,580 Gossiper.java (line 772)
InetAddress /10.8.30.103 is now dead.
INFO [GossipStage:1] 2013-01-10 23:45:19,900 Gossiper.java (line 758)
InetAddress /10.8.30.103 is now UP
INFO [HintedHandoff:2] 2013-01-10 23:45:19,901 HintedHandOffManager.java (line
293) Started hinted handoff for host: a6c4d3f6-dcbd-4801-aad3-ef0a26959e51 with
IP: /10.8.30.103
INFO [HintedHandoff:2] 2013-01-10 23:45:19,903 HintedHandOffManager.java (line
408) Finished hinted handoff of 0 rows to endpoint /10.8.30.103
INFO [GossipTasks:1] 2013-01-10 23:45:44,330 Gossiper.java (line 772)
InetAddress /10.8.30.103 is now dead.
INFO [GossipStage:1] 2013-01-10 23:45:47,600 Gossiper.java (line 790) Node
/10.8.30.103 has restarted, now UP
INFO [GossipStage:1] 2013-01-10 23:45:47,601 Gossiper.java (line 758)
InetAddress /10.8.30.103 is now UP
INFO [HintedHandoff:1] 2013-01-10 23:45:47,602 HintedHandOffManager.java (line
293) Started hinted handoff for host: a6c4d3f6-dcbd-4801-aad3-ef0a26959e51 with
IP: /10.8.30.103
INFO [HintedHandoff:1] 2013-01-10 23:45:47,603 HintedHandOffManager.java (line
408) Finished hinted handoff of 0 rows to endpoint /10.8.30.103
INFO [GossipStage:1] 2013-01-10 23:45:57,645 StorageService.java (line 1288)
Node /10.8.30.103 state jump to normal
INFO [GossipStage:1] 2013-01-10 23:45:57,650 ColumnFamilyStore.java (line 647)
Enqueuing flush of Memtable-peers@1717997204(251/5063 serialized/live bytes, 17
ops)
INFO [FlushWriter:1] 2013-01-10 23:45:57,651 Memtable.java (line 424) Writing
Memtable-peers@1717997204(251/5063 serialized/live bytes, 17 ops)
INFO [FlushWriter:1] 2013-01-10 23:45:57,836 Memtable.java (line 458)
Completed flushing /data/cassandra/system/peers/system-peers-ib-564-Data.db
(318 bytes) for commitlog position ReplayPosition(segmentId=1357890248318,
position=464810)
INFO [CompactionExecutor:5] 2013-01-10 23:45:57,839 CompactionTask.java (line
120) Compacting
[SSTableReader(path='/data/cassandra/system/peers/system-peers-ib-564-Data.db'),
SSTableReader(path='/data/cassandra/system/peers/system-peers-ib-561-Data.db'),
SSTableReader(path='/data/cassandra/system/peers/system-peers-ib-563-Data.db'),
SSTableReader(path='/data/cassandra/system/peers/system-peers-ib-562-Data.db')]
INFO [GossipStage:1] 2013-01-10 23:45:57,856 ColumnFamilyStore.java (line 647)
Enqueuing flush of Memtable-local@555590564(70/70 serialized/live bytes, 2 ops)
INFO [FlushWriter:2] 2013-01-10 23:45:57,857 Memtable.java (line 424) Writing
Memtable-local@555590564(70/70 serialized/live bytes, 2 ops)
INFO [FlushWriter:2] 2013-01-10 23:45:58,031 Memtable.java (line 458)
Completed flushing /data2/cassandra/system/local/system-local-ib-621-Data.db
(129 bytes) for commitlog position ReplayPosition(segmentId=1357890248318,
position=465004)
INFO [GossipStage:1] 2013-01-10 23:45:58,033 StorageService.java (line 1288)
Node /10.8.30.103 state jump to normal
INFO [GossipStage:1] 2013-01-10 23:45:58,038 ColumnFamilyStore.java (line 647)
Enqueuing flush of Memtable-peers@1963979017(11/221 serialized/live bytes, 1
ops)
INFO [FlushWriter:1] 2013-01-10 23:45:58,039 Memtable.java (line 424) Writing
Memtable-peers@1963979017(11/221 serialized/live bytes, 1 ops)
INFO [CompactionExecutor:5] 2013-01-10 23:45:58,053 CompactionTask.java (line
267) Compacted 4 sstables to
[/data/cassandra/system/peers/system-peers-ib-565,]. 2,579 bytes to 1,512
(~58% of original) in 213ms = 0.006770MB/s. 20 total rows, 13 unique. Row
merge counts were {1:9, 2:2, 3:1, 4:1, }
INFO [FlushWriter:1] 2013-01-10 23:45:58,265 Memtable.java (line 458)
Completed flushing /data2/cassandra/system/peers/system-peers-ib-566-Data.db
(71 bytes) for commitlog position ReplayPosition(segmentId=1357890248318,
position=465131)
INFO [GossipStage:1] 2013-01-10 23:45:58,285 ColumnFamilyStore.java (line 647)
Enqueuing flush of Memtable-local@232075815(70/70 serialized/live bytes, 2 ops)
INFO [FlushWriter:2] 2013-01-10 23:45:58,286 Memtable.java (line 424) Writing
Memtable-local@232075815(70/70 serialized/live bytes, 2 ops)
INFO [FlushWriter:2] 2013-01-10 23:45:58,472 Memtable.java (line 458)
Completed flushing /data/cassandra/system/local/system-local-ib-622-Data.db
(129 bytes) for commitlog position ReplayPosition(segmentId=1357890248318,
position=465325)
INFO [CompactionExecutor:11] 2013-01-10 23:45:58,475 CompactionTask.java (line
120) Compacting
[SSTableReader(path='/data2/cassandra/system/local/system-local-ib-621-Data.db'),
SSTableReader(path='/data/cassandra/system/local/system-local-ib-622-Data.db'),
SSTableReader(path='/data/cassandra/system/local/system-local-ib-619-Data.db'),
SSTableReader(path='/data/cassandra/system/local/system-local-ib-620-Data.db')]
INFO [GossipStage:1] 2013-01-10 23:45:58,475 Gossiper.java (line 772)
InetAddress /10.8.25.113 is now dead.
INFO [GossipStage:1] 2013-01-10 23:45:58,477 Gossiper.java (line 758)
InetAddress /10.8.25.113 is now UP
INFO [HintedHandoff:2] 2013-01-10 23:45:58,477 HintedHandOffManager.java (line
293) Started hinted handoff for host: 0c11b261-7514-4c98-b94c-baa79c6c4faf with
IP: /10.8.25.113
INFO [HintedHandoff:2] 2013-01-10 23:45:58,478 HintedHandOffManager.java (line
408) Finished hinted handoff of 0 rows to endpoint /10.8.25.113
INFO [CompactionExecutor:11] 2013-01-10 23:45:58,680 CompactionTask.java (line
267) Compacted 4 sstables to
[/data/cassandra/system/local/system-local-ib-623,]. 978 bytes to 591 (~60% of
original) in 204ms = 0.002763MB/s. 4 total rows, 1 unique. Row merge counts
were {1:0, 2:0, 3:0, 4:1, }
INFO [GossipTasks:1] 2013-01-10 23:46:23,389 Gossiper.java (line 772)
InetAddress /10.8.25.113 is now dead.
INFO [GossipStage:1] 2013-01-10 23:46:27,397 Gossiper.java (line 790) Node
/10.8.25.113 has restarted, now UP
INFO [GossipStage:1] 2013-01-10 23:46:27,398 Gossiper.java (line 758)
InetAddress /10.8.25.113 is now UP
INFO [HintedHandoff:1] 2013-01-10 23:46:27,399 HintedHandOffManager.java (line
293) Started hinted handoff for host: 0c11b261-7514-4c98-b94c-baa79c6c4faf with
IP: /10.8.25.113
INFO [HintedHandoff:1] 2013-01-10 23:46:27,400 HintedHandOffManager.java (line
408) Finished hinted handoff of 0 rows to endpoint /10.8.25.113
INFO [GossipStage:1] 2013-01-10 23:46:34,972 StorageService.java (line 1288)
Node /10.8.25.113 state jump to normal
INFO [GossipStage:1] 2013-01-10 23:46:34,976 ColumnFamilyStore.java (line 647)
Enqueuing flush of Memtable-peers@583864609(251/5063 serialized/live bytes, 17
ops)
INFO [FlushWriter:1] 2013-01-10 23:46:34,977 Memtable.java (line 424) Writing
Memtable-peers@583864609(251/5063 serialized/live bytes, 17 ops)
INFO [FlushWriter:1] 2013-01-10 23:46:35,200 Memtable.java (line 458)
Completed flushing /data/cassandra/system/peers/system-peers-ib-567-Data.db
(318 bytes) for commitlog position ReplayPosition(segmentId=1357890248318,
position=473846)
INFO [GossipStage:1] 2013-01-10 23:46:35,215 ColumnFamilyStore.java (line 647)
Enqueuing flush of Memtable-local@2025685109(70/70 serialized/live bytes, 2 ops)
INFO [FlushWriter:2] 2013-01-10 23:46:35,216 Memtable.java (line 424) Writing
Memtable-local@2025685109(70/70 serialized/live bytes, 2 ops)
INFO [FlushWriter:2] 2013-01-10 23:46:35,401 Memtable.java (line 458)
Completed flushing /data/cassandra/system/local/system-local-ib-624-Data.db
(129 bytes) for commitlog position ReplayPosition(segmentId=1357890248318,
position=474040)
INFO [GossipStage:1] 2013-01-10 23:46:38,124 Gossiper.java (line 772)
InetAddress /10.8.25.101 is now dead.
INFO [GossipStage:1] 2013-01-10 23:46:38,268 Gossiper.java (line 758)
InetAddress /10.8.25.101 is now UP
INFO [HintedHandoff:2] 2013-01-10 23:46:38,269 HintedHandOffManager.java (line
293) Started hinted handoff for host: dd3a40e2-fef1-4574-87b8-e2929fd80235 with
IP: /10.8.25.101
INFO [HintedHandoff:2] 2013-01-10 23:46:38,270 HintedHandOffManager.java (line
408) Finished hinted handoff of 0 rows to endpoint /10.8.25.101
INFO [MemoryMeter:1] 2013-01-10 23:46:40,471 Memtable.java (line 207)
CFS(Keyspace='brts', ColumnFamily='evidence_index') liveRatio is
2.471362417743115 (just-counted was 2.471362417743115). calculation took 47ms
for 39 columns
INFO [GossipTasks:1] 2013-01-10 23:47:03,442 Gossiper.java (line 772)
InetAddress /10.8.25.101 is now dead.
INFO [GossipStage:1] 2013-01-10 23:47:04,449 Gossiper.java (line 790) Node
/10.8.25.101 has restarted, now UP
INFO [GossipStage:1] 2013-01-10 23:47:04,449 Gossiper.java (line 758)
InetAddress /10.8.25.101 is now UP
INFO [HintedHandoff:1] 2013-01-10 23:47:04,450 HintedHandOffManager.java (line
293) Started hinted handoff for host: dd3a40e2-fef1-4574-87b8-e2929fd80235 with
IP: /10.8.25.101
INFO [HintedHandoff:1] 2013-01-10 23:47:04,451 HintedHandOffManager.java (line
408) Finished hinted handoff of 0 rows to endpoint /10.8.25.101
INFO [GossipStage:1] 2013-01-10 23:47:12,892 StorageService.java (line 1288)
Node /10.8.25.101 state jump to normal
{code}
> CLONE - Once a host has been hinted to, log messages for it repeat every 10
> mins even if no hints are delivered
> ---------------------------------------------------------------------------------------------------------------
>
> Key: CASSANDRA-5068
> URL: https://issues.apache.org/jira/browse/CASSANDRA-5068
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Affects Versions: 1.1.6, 1.2.0
> Environment: cassandra 1.1.6
> java 1.6.0_30
> Reporter: Peter Haggerty
> Assignee: Brandon Williams
> Priority: Minor
> Labels: hinted, hintedhandoff, phantom
>
> We have "0 row" hinted handoffs every 10 minutes like clockwork. This impacts
> our ability to monitor the cluster by adding persistent noise in the handoff
> metric.
> Previous mentions of this issue are here:
> http://www.mail-archive.com/user@cassandra.apache.org/msg25982.html
> The hinted handoffs can be scrubbed away with
> nodetool -h 127.0.0.1 scrub system HintsColumnFamily
> but they return after anywhere from a few minutes to multiple hours later.
> These started to appear after an upgrade to 1.1.6 and haven't gone away
> despite rolling cleanups, rolling restarts, multiple rounds of scrubbing, etc.
> A few things we've noticed about the handoffs:
> 1. The phantom handoff endpoint changes after a non-zero handoff comes through
> 2. Sometimes a non-zero handoff will be immediately followed by an "off
> schedule" phantom handoff to the endpoint the phantom had been using before
> 3. The sstable2json output seems to include multiple sub-sections for each
> handoff with the same "deletedAt" information.
> The phantom handoff endpoint changes after a non-zero handoff comes through:
> INFO [HintedHandoff:1] 2012-12-11 06:57:35,093 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 0 rows to endpoint /10.10.10.1
> INFO [HintedHandoff:1] 2012-12-11 07:07:35,092 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 0 rows to endpoint /10.10.10.1
> INFO [HintedHandoff:1] 2012-12-11 07:07:37,915 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 1058 rows to endpoint /10.10.10.2
> INFO [HintedHandoff:1] 2012-12-11 07:17:35,093 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 0 rows to endpoint /10.10.10.2
> INFO [HintedHandoff:1] 2012-12-11 07:27:35,093 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 0 rows to endpoint /10.10.10.2
> Sometimes a non-zero handoff will be immediately followed by an "off
> schedule" phantom handoff to the endpoint the phantom had been using before:
> INFO [HintedHandoff:1] 2012-12-12 21:47:39,335 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 0 rows to endpoint /10.10.10.3
> INFO [HintedHandoff:1] 2012-12-12 21:57:39,335 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 0 rows to endpoint /10.10.10.3
> INFO [HintedHandoff:1] 2012-12-12 22:07:43,319 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 1416 rows to endpoint /10.10.10.4
> INFO [HintedHandoff:1] 2012-12-12 22:07:43,320 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 0 rows to endpoint /10.10.10.3
> INFO [HintedHandoff:1] 2012-12-12 22:17:39,357 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 0 rows to endpoint /10.10.10.4
> INFO [HintedHandoff:1] 2012-12-12 22:27:39,337 HintedHandOffManager.java
> (line 392) Finished hinted handoff of 0 rows to endpoint /10.10.10.4
> The first few entries from one of the json files:
> {
> "0aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa": {
> "ccf5dc203a2211e20000e154da71a9bb": {
> "deletedAt": -9223372036854775808,
> "subColumns": []
> },
> "ccf603303a2211e20000e154da71a9bb": {
> "deletedAt": -9223372036854775808,
> "subColumns": []
> },
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
