[
https://issues.apache.org/jira/browse/KUDU-1753?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15710881#comment-15710881
]
Alexey Serbin edited comment on KUDU-1753 at 12/1/16 4:55 AM:
--------------------------------------------------------------
I suspect that the issue appears due to deletion of a tablet while scan
operation is in progress. Below is what I found:
In the Kudu Tablet Server Web UI:
{noformat}
impala::tpch_100_kudu.customer_original 8df8e2e331eb4a16baef8655fdae37e5
hash buckets: (30) TABLET_DATA_TOMBSTONED Tablet
initializing...
{noformat}
At the machine where Kudu tablet server runs from
kudu-tserver.ve1121.halxg.cloudera.com.invalid-user.log.INFO.20161130-120838.16284:
{noformat}
I1130 12:14:20.467965 128171 raft_consensus.cc:409] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Starting pre-election (no leader contacted us within the election
timeout)
I1130 12:14:20.468698 128171 raft_consensus.cc:2156] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Snoozing failure detection for election timeout plus an additional
13.620s
I1130 12:14:20.468785 128171 raft_consensus.cc:433] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Starting pre-election with config: opid_index: 102 OBSOLETE_local:
false peers { permanent_uuid: "e577a0b26d89456fb94a33283429b53d" member_type:
VOTER last_known_addr { host: "ve1124.halxg.cloudera.com" port: 7050 } } peers
{ permanent_uuid: "520ffc6d07ad42b
aaf49e59f7129b080" member_type: VOTER last_known_addr { host:
"ve1121.halxg.cloudera.com" port: 7050 } } peers { permanent_uuid:
"c101883d3e82496989a5f9f667c30e38" member_type: VOTER last_known_addr { host:
"ve1122.halxg.cloudera.com" port:
7050 } }I1130 12:14:20.468909 128171 leader_election.cc:215] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080
[CANDIDATE]: Term 83 pre-election: Re
questing pre-vote from peer e577a0b26d89456fb94a33283429b53dI1130
12:14:20.468925 128171 leader_election.cc:215] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080
[CANDIDATE]: Term 83 pre-election: Re
questing pre-vote from peer c101883d3e82496989a5f9f667c30e38I1130
12:14:26.961638 16318 leader_election.cc:361] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080
[CANDIDATE]: Term 83 pre-election: Vote denied by peer
e577a0b26d89456fb94a33283429b53d. Message: Invalid argument: T
8df8e2e331eb4a16baef8655fdae37e5 P e577a0b26d89456fb94a33283429b53d [term 82
FOLLOWER]: Leader pre-election vote request: Denying vote to candidate
520ffc6d07ad42baaf49e59f7129b080 for term 83 because replica is either leader
or believes a valid leader to be alive.
W1130 12:14:34.100399 16317 leader_election.cc:271] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080
[CANDIDATE]: Term 83 pre-election: RPC error from VoteRequest() call to peer
c101883d3e82496989a5f9f667c30e38: Timed out: RequestConsensusVote RPC to
10.17.246.32:7050 timed out after 13.620s
I1130 12:14:34.101230 16317 leader_election.cc:242] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080
[CANDIDATE]: Term 83 pre-election: Election decided. Result: candidate lost.
I1130 12:14:34.102461 82913 raft_consensus.cc:2156] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Snoozing failure detection for election timeout plus an additional
14.886s
I1130 12:14:34.104115 82913 raft_consensus.cc:1904] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Leader pre-election lost for term 83. Reason: could not achieve
majority
I1130 12:14:34.611028 16364 tablet_service.cc:660] Processing DeleteTablet for
tablet 8df8e2e331eb4a16baef8655fdae37e5 with delete_type TABLET_DATA_TOMBSTONED
(TS 520ffc6d07ad42baaf49e59f7129b080 not found in new config with opid_index
123) from {real_user=kudu} at 10.17.246.26:56270
I1130 12:14:34.616175 16364 tablet_peer.cc:216] Initiating TabletPeer shutdown
for tablet: 8df8e2e331eb4a16baef8655fdae37e5
I1130 12:14:34.616677 16364 maintenance_manager.cc:190] Unregistered op
CompactRowSetsOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.624974 16364 maintenance_manager.cc:190] Unregistered op
MinorDeltaCompactionOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.624991 16364 maintenance_manager.cc:190] Unregistered op
MajorDeltaCompactionOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.625010 16364 maintenance_manager.cc:190] Unregistered op
FlushMRSOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.625022 16364 maintenance_manager.cc:190] Unregistered op
FlushDeltaMemStoresOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.625032 16364 maintenance_manager.cc:190] Unregistered op
LogGCOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.625043 16364 raft_consensus.cc:1560] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Raft consensus shutting down.
I1130 12:14:34.625054 16364 raft_consensus.cc:1576] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Raft consensus is shut down!
I1130 12:14:34.627727 16364 ts_tablet_manager.cc:924] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080: Deleting
tablet data with delete state TABLET_DATA_TOMBSTONED
I1130 12:14:34.740515 16364 ts_tablet_manager.cc:935] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080: Tablet
deleted. Last logged OpId: 81.122
I1130 12:14:34.741192 16364 log.cc:848] T 8df8e2e331eb4a16baef8655fdae37e5
Deleting WAL directory
{noformat}
At Impala machine where one of the coordinator runs from
impalad.ve1121.halxg.cloudera.com.impala.log.WARNING.20161130-114346.122511:
{noformat}
W1130 12:14:38.245721 10974 client.cc:1304] Scan at tablet server
520ffc6d07ad42baaf49e59f7129b080 (ve1121.halxg.cloudera.com:7050) of tablet
impala::tpch_100_kudu.customer_original: failed: Illegal state: Tablet is not
running
{noformat}
was (Author: aserbin):
I suspect that the issue appears due to deletion of a tablet while scan
operation is in progress. Below is what I found:
In the Kudu Tablet Server Web UI:
{noformat}
impala::tpch_100_kudu.customer_original 8df8e2e331eb4a16baef8655fdae37e5
hash buckets: (30) TABLET_DATA_TOMBSTONED Tablet
initializing...
{noformat}
At the machine where Kudu tablet server runs from
kudu-tserver.ve1121.halxg.cloudera.com.invalid-user.log.INFO.20161130-120838.16284:
{noformat}
I1130 12:14:20.467965 128171 raft_consensus.cc:409] T 8df8e2e331eb4a16baef8655fd
ae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82 FOLLOWER]: Starting pre-elect
ion (no leader contacted us within the election timeout)
I1130 12:14:20.468698 128171 raft_consensus.cc:2156] T 8df8e2e331eb4a16baef8655f
dae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82 FOLLOWER]: Snoozing failure
detection for election timeout plus an additional 13.620s
I1130 12:14:20.468785 128171 raft_consensus.cc:433] T 8df8e2e331eb4a16baef8655fd
ae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82 FOLLOWER]: Starting pre-elect
ion with config: opid_index: 102 OBSOLETE_local: false peers { permanent_uuid: "
e577a0b26d89456fb94a33283429b53d" member_type: VOTER last_known_addr { host: "ve
1124.halxg.cloudera.com" port: 7050 } } peers { permanent_uuid: "520ffc6d07ad42b
aaf49e59f7129b080" member_type: VOTER last_known_addr { host: "ve1121.halxg.clou
dera.com" port: 7050 } } peers { permanent_uuid: "c101883d3e82496989a5f9f667c30e
38" member_type: VOTER last_known_addr { host: "ve1122.halxg.cloudera.com" port:
7050 } }
I1130 12:14:20.468909 128171 leader_election.cc:215] T 8df8e2e331eb4a16baef8655f
dae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [CANDIDATE]: Term 83 pre-election: Re
questing pre-vote from peer e577a0b26d89456fb94a33283429b53d
I1130 12:14:20.468925 128171 leader_election.cc:215] T 8df8e2e331eb4a16baef8655f
dae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [CANDIDATE]: Term 83 pre-election: Re
questing pre-vote from peer c101883d3e82496989a5f9f667c30e38
I1130 12:14:26.961638 16318 leader_election.cc:361] T 8df8e2e331eb4a16baef8655fd
ae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [CANDIDATE]: Term 83 pre-election: Vot
e denied by peer e577a0b26d89456fb94a33283429b53d. Message: Invalid argument: T
8df8e2e331eb4a16baef8655fdae37e5 P e577a0b26d89456fb94a33283429b53d [term 82 FOL
LOWER]: Leader pre-election vote request: Denying vote to candidate 520ffc6d07ad
42baaf49e59f7129b080 for term 83 because replica is either leader or believes a
valid leader to be alive.
W1130 12:14:34.100399 16317 leader_election.cc:271] T 8df8e2e331eb4a16baef8655fd
ae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [CANDIDATE]: Term 83 pre-election: RPC
error from VoteRequest() call to peer c101883d3e82496989a5f9f667c30e38: Timed o
ut: RequestConsensusVote RPC to 10.17.246.32:7050 timed out after 13.620s
I1130 12:14:34.101230 16317 leader_election.cc:242] T 8df8e2e331eb4a16baef8655fd
ae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [CANDIDATE]: Term 83 pre-election: Ele
ction decided. Result: candidate lost.
I1130 12:14:34.102461 82913 raft_consensus.cc:2156] T 8df8e2e331eb4a16baef8655fd
ae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82 FOLLOWER]: Snoozing failure d
etection for election timeout plus an additional 14.886s
I1130 12:14:34.104115 82913 raft_consensus.cc:1904] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Leader pre-election lost for term 83. Reason: could not achieve
majority
I1130 12:14:34.611028 16364 tablet_service.cc:660] Processing DeleteTablet for
tablet 8df8e2e331eb4a16baef8655fdae37e5 with delete_type TABLET_DATA_TOMBSTONED
(TS 520ffc6d07ad42baaf49e59f7129b080 not found in new config with opid_index
123) from {real_user=kudu} at 10.17.246.26:56270
I1130 12:14:34.616175 16364 tablet_peer.cc:216] Initiating TabletPeer shutdown
for tablet: 8df8e2e331eb4a16baef8655fdae37e5
I1130 12:14:34.616677 16364 maintenance_manager.cc:190] Unregistered op
CompactRowSetsOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.624974 16364 maintenance_manager.cc:190] Unregistered op
MinorDeltaCompactionOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.624991 16364 maintenance_manager.cc:190] Unregistered op
MajorDeltaCompactionOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.625010 16364 maintenance_manager.cc:190] Unregistered op
FlushMRSOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.625022 16364 maintenance_manager.cc:190] Unregistered op
FlushDeltaMemStoresOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.625032 16364 maintenance_manager.cc:190] Unregistered op
LogGCOp(8df8e2e331eb4a16baef8655fdae37e5)
I1130 12:14:34.625043 16364 raft_consensus.cc:1560] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Raft consensus shutting down.
I1130 12:14:34.625054 16364 raft_consensus.cc:1576] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080 [term 82
FOLLOWER]: Raft consensus is shut down!
I1130 12:14:34.627727 16364 ts_tablet_manager.cc:924] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080: Deleting
tablet data with delete state TABLET_DATA_TOMBSTONED
I1130 12:14:34.740515 16364 ts_tablet_manager.cc:935] T
8df8e2e331eb4a16baef8655fdae37e5 P 520ffc6d07ad42baaf49e59f7129b080: Tablet
deleted. Last logged OpId: 81.122
I1130 12:14:34.741192 16364 log.cc:848] T 8df8e2e331eb4a16baef8655fdae37e5
Deleting WAL directory
{noformat}
At Impala where one of the coordinator runs from
impalad.ve1121.halxg.cloudera.com.impala.log.WARNING.20161130-114346.122511:
{noformat}
W1130 12:14:38.245721 10974 client.cc:1304] Scan at tablet server
520ffc6d07ad42baaf49e59f7129b080 (ve1121.halxg.cloudera.com:7050) of tablet
impala::tpch_100_kudu.customer_original: failed: Illegal state: Tablet is not
running
{noformat}
> Impala query fails: Unable to advance iterator: Illegal state: Tablet is not
> running
> ------------------------------------------------------------------------------------
>
> Key: KUDU-1753
> URL: https://issues.apache.org/jira/browse/KUDU-1753
> Project: Kudu
> Issue Type: Bug
> Components: client, impala
> Reporter: Taras Bobrovytsky
> Assignee: Alexey Serbin
> Priority: Critical
> Attachments: impalad.INFO, kudu-tserver.INFO
>
>
> We were running queries (with mem limits set in Impala) like the following
> one after another (only one query was executing at the same time at any
> point).
> {code}
> upsert into table lineitem select * from lineitem_original where l_orderkey %
> 11 = 0
> {code}
> and
> {code}
> delete from lineitem where l_orderkey % 11 = 0
> {code}
> One of the queries failed with the following error:
> {code}
> Unable to advance iterator: Illegal state: Tablet is not running
> {code}
> from kudu-tserver.INFO:
> {code}
> I1122 17:54:10.659071 7021 tablet.cc:1160] T
> 5e7e168f1919488ba902f87b32be6065 Flush: entering phase 2 (starting to
> duplicate updates in new rowsets)
> I1122 17:54:10.740268 16858 log.cc:513] Max segment size reached. Starting
> new segment allocation.
> I1122 17:54:10.772285 7086 raft_consensus.cc:1192] Rejecting consensus
> request: Soft memory limit exceeded (at 82.22% of capacity) [suppressed
> 5 similar messages]
> I1122 17:54:11.809483 7094 raft_consensus.cc:1192] Rejecting consensus
> request: Soft memory limit exceeded (at 84.45% of capacity) [suppressed
> 5 similar messages]
> I1122 17:54:12.095155 16858 log.cc:398] Rolled over to a new segment:
> /data1/kudu/tserver/ wals/5e7e168f1919488ba902f87b32be6065/wal-000000082
> I1122 17:54:13.143566 7088 raft_consensus.cc:1192] Rejecting consensus
> request: Soft memory limit exceeded (at 82.84% of capacity) [suppressed
> 6 similar messages]
> I1122 17:54:13.633990 7021 tablet.cc:1215] T
> 5e7e168f1919488ba902f87b32be6065 Flush Phase 2: carrying over any updates
> which arrived during Phase 1
> I1122 17:54:13.634016 7021 tablet.cc:1217] T
> 5e7e168f1919488ba902f87b32be6065 Phase 2 snapshot:
> MvccSnapshot[committed={T|T < 1298537 or (T in {1298538,1298537})}]
> I1122 17:54:14.154855 7094 raft_consensus.cc:1192] Rejecting consensus
> request: Soft memory limit exceeded (at 83.44% of capacity) [suppressed
> 5 similar messages]
> I1122 17:54:15.068207 7095 tablet_copy_client.cc:273] T
> 44cf60f4c34841899e3a32852365b112 P 8e6f4cf16c544ef3b7913f6cda1bfe54: Tablet
> Copy client: Tablet Copy complete. Replacing tablet superblock.
> I1122 17:54:15.071156 9784 ts_tablet_manager.cc:633] T
> 44cf60f4c34841899e3a32852365b112 P 8e6f4cf16c544ef3b7913f6cda1bfe54:
> Bootstrapping tablet
> I1122 17:54:15.071321 9784 tablet_bootstrap.cc:380] T
> 44cf60f4c34841899e3a32852365b112 P 8e6f4cf16c544ef3b7913f6cda1bfe54:
> Bootstrap starting.
> I1122 17:54:15.081435 9784 tablet_bootstrap.cc:542] T
> 44cf60f4c34841899e3a32852365b112 P 8e6f4cf16c544ef3b7913f6cda1bfe54: Time
> spent opening tablet: real 0.010s user 0.006s sys 0.004s
> .....
> .....
> I1122 17:54:15.086483 9784 tablet_bootstrap.cc:606] T
> 44cf60f4c34841899e3a32852365b112 P 8e6f4cf16c544ef3b7913f6cda1bfe54: Moving
> log directory /data1/kudu/tserver/wals/
> 44cf60f4c34841899e3a32852365b112 to recovery directory
> /data1/kudu/tserver/wals/ 44cf60f4c34841899e3a32852365b112.recovery
> in preparation for log replay
> I1122 17:54:15.087378 9784 log_util.cc:312] Log segment
> /data1/kudu/tserver/wals/
> 44cf60f4c34841899e3a32852365b112.recovery/wal-000000087 has no footer. This
> segment was likely being written when the server previously shut down.
> I1122 17:54:15.087385 9784 log_reader.cc:151] Log segment
> /data1/kudu/tserver/wals/
> 44cf60f4c34841899e3a32852365b112.recovery/wal-000000087 was likely left
> in-progress after a previous crash. Will try to rebuild footer by scanning
> data.
> W1122 17:54:15.119765 7095 rpcz_store.cc:234] Call
> kudu.consensus.ConsensusService. StartTabletCopy from
> 172.28.195.11:33598 (request call id 247782) took 56098ms (client timeout
> 1000).
> W1122 17:54:15.119963 7095 rpcz_store.cc:238] Trace:
>
> 1122 17:53:19.020889 (+ 0us) service_pool.cc:143] Inserting onto call
> queue
> 1122 17:53:19.020911 (+ 22us) service_pool.cc:202] Handling call
>
> 1122 17:53:19.022175 (+ 1264us) ts_tablet_manager.cc:418] T
> 44cf60f4c34841899e3a32852365b112 P
> 8e6f4cf16c544ef3b7913f6cda1bfe54: Initiating tablet copy from Peer
> bb2ce221ba374ff4bff7ff5c56946f45 (kudu-stress-8.vpc.cloudera.com:7050)
> 1122 17:53:19.064954 (+ 42779us) tablet_metadata.cc:461] Metadata flushed
>
> 1122 17:53:19.065703 (+ 749us) tablet_metadata.cc:461] Metadata flushed
>
> 1122 17:54:15.071167 (+56005464us) ts_tablet_manager.cc:634] Bootstrapping
> tablet
> 1122 17:54:15.119736 (+ 48569us) inbound_call.cc:130] Queueing success
> response
> Metrics:
> {"fdatasync":967,"fdatasync_us":32775470,"spinlock_wait_cycles":4352,"tablet-
>
> bootstrap.queue_time_us":248,"tcmalloc_contention_cycles":527821056,"thread_start_us":229,
> "threads_started":1}
> W1122 17:54:15.251955 7021 tablet_peer.cc:656] Time spent Committing
> in-flights took a long time.: real 1.530s user 0.000s sys 0.000s
> {code}
> from impalad.INFO:
> {code}
> 8e6f4cf16c544ef3b7913f6cda1bfe54 (kudu-stress-6.vpc.cloudera.com:7050) of
> tablet impala:: tpch_10_kudu.lineitem: failed: Illegal state: Tablet is not
> running
> I1122 17:53:23.382364 9488 status.cc:114] Unable to advance iterator:
> Illegal state: Tablet is not running
>
> @ 0x11c14e3 impala::Status::Status()
>
> @ 0x17eace2 impala::KuduScanner::GetNextScannerBatch()
>
> @ 0x17e93fa impala::KuduScanner::GetNext()
>
> @ 0x1785893 impala::KuduScanNode::ProcessScanToken()
>
> @ 0x1785bb2 impala::KuduScanNode::RunScannerThread()
>
> @ 0x1787ad2 boost::_mfi::mf2<>::operator()()
>
> @ 0x1787998 boost::_bi::list3<>::operator()<>()
>
> @ 0x1787519 boost::_bi::bind_t<>::operator()()
>
> @ 0x178734f
> boost::detail::function::void_function_obj_invoker0<>::invoke()
> @ 0x133ce98 boost::function0<>::operator()()
>
> @ 0x15e8921 impala::Thread::SuperviseThread()
>
> @ 0x15ef8fa boost::_bi::list4<>::operator()<>()
>
> @ 0x15ef83d boost::_bi::bind_t<>::operator()()
>
> @ 0x15ef798 boost::detail::thread_data<>::run()
>
> @ 0x1a3c34a thread_proxy
>
> @ 0x38382079d1 (unknown)
>
> @ 0x3837ee88fd (unknown)
>
> I1122 17:53:23.392840 9459 runtime-state.cc:208] Error from query
> 6e47c2d5c47683e8: 5c1a097d00000000: Unable to advance iterator: Illegal
> state: Tablet is not running
> I1122 17:53:23.451575 9459 fragment-mgr.cc:99] PlanFragment completed.
> instance_id=6e47c2d5c47683e8:5c1a097d00000000
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
