[
https://issues.apache.org/jira/browse/PHOENIX-909?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jeffrey Zhong updated PHOENIX-909:
----------------------------------
Description:
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}
was:
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.
Therefore, I think we should not use time range bound Get or Scan otherwise it
will be problematic when we have a time clock skew within the cluster. Let me
know what's your thoughts. Thanks.
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}
> 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
> Reporter: Jeffrey Zhong
> Assignee: Jeffrey Zhong
>
> 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)
