[
https://issues.apache.org/jira/browse/PHOENIX-909?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13969147#comment-13969147
]
Hudson commented on PHOENIX-909:
--------------------------------
SUCCESS: Integrated in Phoenix-3.0 #69 (See
[https://builds.apache.org/job/Phoenix-3.0/69/])
PHOENIX-909: Handle scan time range for low time resolution OS (jzhong: rev
be09f3651a725d85c35ed032c252ac94273d3f37)
*
phoenix-core/src/main/java/org/apache/phoenix/coprocessor/MetaDataRegionObserver.java
* phoenix-core/src/main/java/org/apache/phoenix/execute/BasicQueryPlan.java
* phoenix-core/src/main/java/org/apache/phoenix/query/QueryServicesOptions.java
*
phoenix-core/src/main/java/org/apache/phoenix/coprocessor/SequenceRegionObserver.java
> 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
> Fix For: 5.0.0, 3.1, 4.1
>
> 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)
