You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@phoenix.apache.org by "James Taylor (JIRA)" <ji...@apache.org> on 2014/04/02 03:12:15 UTC
[jira] [Commented] (PHOENIX-909) Handle scan time range for low
time resolution OS
[ https://issues.apache.org/jira/browse/PHOENIX-909?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13957220#comment-13957220 ]
James Taylor commented on PHOENIX-909:
--------------------------------------
+1
> Handle scan time range for low time resolution OS
> -------------------------------------------------
>
> Key: PHOENIX-909
> URL: https://issues.apache.org/jira/browse/PHOENIX-909
> Project: Phoenix
> Issue Type: Bug
> Affects Versions: 3.0.0, 4.0.0
> Reporter: Jeffrey Zhong
> Assignee: Jeffrey Zhong
> Attachments: phoenix-909.patch
>
>
> When running end2end tests against a live windows multi-node cluster, there are always some intermittent failures. Below is one example:
> {code}
> When running end2end tests against a windows cluster(3 region servers and 1 master), we always has 20-30 failures.(Running against a single node windows cluster always pass). When rerun those failed ones, they will pass in most retries but not always.
> Below is one of example. As you will see, the test code did create the sequence(by Mutate call) while later still throw error SEQUENCE_UNDEFINED in the following incrementSequence(Multi call). The root cause is that we create sequence using data table creation time stamp while when we query the sequence in SequenceRegionObserver#preIncrement, we have following code which is very problematic.
> if (maxTimestamp == HConstants.LATEST_TIMESTAMP) {
> maxTimestamp = EnvironmentEdgeManager.currentTimeMillis();
> tr = new TimeRange(tr.getMin(), maxTimestamp);
> }
> Because EnvironmentEdgeManager.currentTimeMillis() is server time stamp while the timestamp used by sequence creation maybe from another server. If we have time clock skew, the following time range Get may not see the just created sequence. The issue is magnified in windows system because the minimum time resolution on windows is 50-100 milliseconds. In other words, within 50-100 milliseconds, the EnvironmentEdgeManager.currentTimeMillis() returns a same value. Therefore, timestamp on different boxes are likely see a gap or same if the difference are within 50-100 milliseconds. The similar issue happens when Upsert a value and immediately select those values. Sometimes select returns nothing.
> Test Error Stack Trace:
> testNonSaltedUpdatableViewWithIndex(org.apache.phoenix.end2end.ViewIT)
> org.apache.phoenix.schema.SequenceNotFoundException: ERROR 1201 (42Z01): Sequence undefined. tableName=_SEQ_T.
> at org.apache.phoenix.exception.SQLExceptionCode$12.newException(SQLExceptionCode.java:225)
> at org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:133)
> at org.apache.phoenix.schema.Sequence.incrementValue(Sequence.java:207)
> at org.apache.phoenix.query.ConnectionQueryServicesImpl.incrementSequenceValues(ConnectionQueryServicesImpl.java:1707)
> at org.apache.phoenix.query.ConnectionQueryServicesImpl.incrementSequences(ConnectionQueryServicesImpl.java:1643)
> at org.apache.phoenix.schema.MetaDataClient.createIndex(MetaDataClient.java:643)
> at org.apache.phoenix.compile.CreateIndexCompiler$1.execute(CreateIndexCompiler.java:76)
> at org.apache.phoenix.jdbc.PhoenixStatement.executeMutation(PhoenixStatement.java:226)
> at org.apache.phoenix.jdbc.PhoenixStatement.execute(PhoenixStatement.java:919)
> at org.apache.phoenix.end2end.BaseViewIT.testUpdatableViewIndex(BaseViewIT.java:102)
> at org.apache.phoenix.end2end.BaseViewIT.testUpdatableViewWithIndex(BaseViewIT.java:50)
> at org.apache.phoenix.end2end.ViewIT.testNonSaltedUpdatableViewWithIndex(ViewIT.java:96)
> Trace from Phoenix client side:
> 14/03/28 22:52:54 DEBUG ipc.RpcClient: IPC Client (1665919290) connection to hhuang-qecls154/10.215.20.25:60020 from Ad
> ministrator: wrote request header call_id: 223 method_name: "Mutate" request_param: true
> 14/03/28 22:52:54 DEBUG ipc.RpcClient: IPC Client (1665919290) connection to hhuang-qecls154/10.215.20.25:60020 from Ad
> ministrator: got response header call_id: 223 cell_block_meta { length: 39 }, totalSize: 54 bytes
> 14/03/28 22:52:54 INFO ipc.RpcClient: Got response back value=result {
> associated_cell_count: 1
> stale: false
> }
> …
> 14/03/28 22:52:54 DEBUG ipc.RpcClient: IPC Client (1665919290) connection to hhuang-qecls154/10.215.20.25:60020 from Ad
> ministrator: wrote request header call_id: 224 method_name: "Multi" request_param: true
> 14/03/28 22:52:54 DEBUG ipc.RpcClient: IPC Client (1665919290) connection to hhuang-qecls154/10.215.20.25:60020 from Ad
> ministrator: got response header call_id: 224 cell_block_meta { length: 39 }, totalSize: 60 bytes
> 14/03/28 22:52:54 INFO ipc.RpcClient: Got response back value=regionActionResult {
> resultOrException {
> index: 0
> result {
> associated_cell_count: 1
> stale: false
> }
> }
> }
> Trace from Region Server:
> 2014-03-28 22:52:54,653 TRACE org.apache.hadoop.ipc.RpcServer: callId: 223 service: ClientService methodName: Mutate size: 335 connection: 10.215.24.5:62150 param: region= SYSTEM.SEQUENCE,,1396047167673.d1266e39810c34ebca00df5ef1bee895., row=\x00_SEQ_T\x00 connection: 10.215.24.5:62150, response result { associated_cell_count: 1 stale: false } queueTime: 0 processingTime: 47
> 2014-03-28 22:52:54,653 DEBUG org.apache.hadoop.ipc.RpcServer: RpcServer.responder: callId: 223 wrote 58 bytes.
> 2014-03-28 22:52:54,653 TRACE org.apache.hadoop.ipc.RpcServer: RequestHeader call_id: 224 method_name: "Multi" request_param: true totalRequestSize: 225 bytes
> 2014-03-28 22:52:54,653 DEBUG org.apache.hadoop.ipc.RpcServer: callId: 224 service: ClientService methodName: Multi size: 225 connection: 10.215.24.5:62150 executing as Administrator
> 2014-03-28 22:52:54,684 TRACE org.apache.hadoop.ipc.RpcServer: callId: 224 service: ClientService methodName: Multi size: 225 connection: 10.215.24.5:62150 param: region= SYSTEM.SEQUENCE,,1396047167673.d1266e39810c34ebca00df5ef1bee895., for 1 actions and 1st row key=\x00_SEQ_T\x00 connection: 10.215.24.5:62150, response regionActionResult { resultOrException { index: 0 result { associated_cell_count: 1 stale: false } } } queueTime: 0 processingTime: 31
> The Trace from Phoenix side when test run fine:
> 14/03/28 22:55:29 DEBUG ipc.RpcClient: IPC Client (1871254963) connection to hhuang-qecls153/10.59.208.69:60020 from Ad
> ministrator: wrote request header call_id: 84 method_name: "Mutate" request_param: true
> 14/03/28 22:55:29 DEBUG ipc.RpcClient: IPC Client (1871254963) connection to hhuang-qecls153/10.59.208.69:60020 from Ad
> ministrator: got response header call_id: 84 cell_block_meta { length: 39 }, totalSize: 53 bytes
> 14/03/28 22:55:29 INFO ipc.RpcClient: Got response back value=result {
> associated_cell_count: 1
> stale: false
> }
> …
> 14/03/28 22:55:29 TRACE ipc.RpcClient: cellBlock=org.apache.hadoop.hbase.codec.KeyValueCodec$KeyValueDecoder@92c3688
> 14/03/28 22:55:29 DEBUG ipc.RpcClient: IPC Client (1871254963) connection to hhuang-qecls153/10.59.208.69:60020 from Ad
> ministrator: wrote request header call_id: 85 method_name: "Multi" request_param: true
> 14/03/28 22:55:29 DEBUG ipc.RpcClient: IPC Client (1871254963) connection to hhuang-qecls153/10.59.208.69:60020 from Ad
> ministrator: got response header call_id: 85 cell_block_meta { length: 158 }, totalSize: 179 bytes
> 14/03/28 22:55:29 INFO ipc.RpcClient: Got response back value=regionActionResult {
> resultOrException {
> index: 0
> result {
> associated_cell_count: 3
> stale: false
> }
> }
> }
> The Trace from Region Server side when test run fine:
> 2014-03-28 22:55:50,655 TRACE org.apache.hadoop.ipc.RpcServer: callId: 223 service: ClientService methodName: Mutate size: 336 connection: 10.215.24.5:62800 param: region= SYSTEM.SEQUENCE,,1396047346119.29a2f3fb4c183705c2b336ba317b020d., row=\x00_SEQ_T\x00 connection: 10.215.24.5:62800, response result { associated_cell_count: 1 stale: false } queueTime: 1 processingTime: 3
> 2014-03-28 22:55:50,655 DEBUG org.apache.hadoop.ipc.RpcServer: RpcServer.responder: callId: 223 wrote 58 bytes.
> 2014-03-28 22:55:50,660 TRACE org.apache.hadoop.ipc.RpcServer: RequestHeader call_id: 224 method_name: "Multi" request_param: true totalRequestSize: 225 bytes
> 2014-03-28 22:55:50,660 DEBUG org.apache.hadoop.ipc.RpcServer: callId: 224 service: ClientService methodName: Multi size: 225 connection: 10.215.24.5:62800 executing as Administrator
> 2014-03-28 22:55:50,676 TRACE org.apache.hadoop.ipc.RpcServer: callId: 224 service: ClientService methodName: Multi size: 225 connection: 10.215.24.5:62800 param: region= SYSTEM.SEQUENCE,,1396047346119.29a2f3fb4c183705c2b336ba317b020d., for 1 actions and 1st row key=\x00_SEQ_T\x00 connection: 10.215.24.5:62800, response regionActionResult { resultOrException { index: 0 result { associated_cell_count: 3 stale: false } } } queueTime: 0 processingTime: 16
> {code}
--
This message was sent by Atlassian JIRA
(v6.2#6252)