[
https://issues.apache.org/jira/browse/PHOENIX-2478?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15109348#comment-15109348
]
James Taylor commented on PHOENIX-2478:
---------------------------------------
[~poornachandra] - we're testing use the read/write fence and we're seeing the
following exception (see below for a snippet of the tx manager log while index
creation is happening). Any insights? When/why does the connection get reset?
{code}
java.sql.SQLException: ERROR 1077 (44A08): Transaction Failure Exception from
canCommit for transaction 1453319824534000000.
at
org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:419)
at
org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:145)
at
org.apache.phoenix.util.TransactionUtil.getTransactionFailureException(TransactionUtil.java:55)
at
org.apache.phoenix.execute.MutationState.commit(MutationState.java:1151)
at
org.apache.phoenix.jdbc.PhoenixConnection$3.call(PhoenixConnection.java:517)
at
org.apache.phoenix.jdbc.PhoenixConnection$3.call(PhoenixConnection.java:514)
at org.apache.phoenix.call.CallRunner.run(CallRunner.java:53)
at
org.apache.phoenix.jdbc.PhoenixConnection.commit(PhoenixConnection.java:514)
at
org.apache.phoenix.query.ConnectionQueryServicesImpl.updateData(ConnectionQueryServicesImpl.java:2612)
at
org.apache.phoenix.schema.MetaDataClient.buildIndex(MetaDataClient.java:1103)
at
org.apache.phoenix.schema.MetaDataClient.createIndex(MetaDataClient.java:1397)
at
org.apache.phoenix.compile.CreateIndexCompiler$1.execute(CreateIndexCompiler.java:85)
at
org.apache.phoenix.jdbc.PhoenixStatement$2.call(PhoenixStatement.java:336)
at
org.apache.phoenix.jdbc.PhoenixStatement$2.call(PhoenixStatement.java:323)
at org.apache.phoenix.call.CallRunner.run(CallRunner.java:53)
at
org.apache.phoenix.jdbc.PhoenixStatement.executeMutation(PhoenixStatement.java:321)
at
org.apache.phoenix.jdbc.PhoenixStatement.execute(PhoenixStatement.java:242)
at
org.apache.phoenix.jdbc.PhoenixPreparedStatement.execute(PhoenixPreparedStatement.java:172)
at
org.apache.phoenix.jdbc.PhoenixPreparedStatement.execute(PhoenixPreparedStatement.java:177)
at
org.apache.phoenix.jdbc.PhoenixConnection.executeStatements(PhoenixConnection.java:351)
at
org.apache.phoenix.util.PhoenixRuntime.executeStatements(PhoenixRuntime.java:293)
at org.apache.phoenix.util.PhoenixRuntime.main(PhoenixRuntime.java:238)
Caused by: co.cask.tephra.TransactionFailureException: Exception from canCommit
for transaction 1453319824534000000.
at
co.cask.tephra.TransactionContext.checkForConflicts(TransactionContext.java:249)
at co.cask.tephra.TransactionContext.finish(TransactionContext.java:114)
at
org.apache.phoenix.execute.MutationState.commit(MutationState.java:1144)
... 18 more
Caused by: java.lang.RuntimeException: java.lang.Exception: Thrift error for
co.cask.tephra.distributed.TransactionServiceClient$4@4e628b52:
java.net.SocketException: Connection reset
at com.google.common.base.Throwables.propagate(Throwables.java:160)
at
co.cask.tephra.distributed.TransactionServiceClient.canCommit(TransactionServiceClient.java:305)
at
co.cask.tephra.TransactionContext.checkForConflicts(TransactionContext.java:240)
... 20 more
Caused by: java.lang.Exception: Thrift error for
co.cask.tephra.distributed.TransactionServiceClient$4@4e628b52:
java.net.SocketException: Connection reset
{code}
Here's the txn manager log while index is created:
{code}
2016-01-20 20:24:30,870 ERROR [Thread-10] server.TThreadedSelectorServerWithFix
- Read a frame size of 101362407, which is bigger than the maximum allowable
buffer size for ALL connections.
2016-01-20 20:24:31,714 ERROR [Thread-11] server.TThreadedSelectorServerWithFix
- Read a frame size of 101362407, which is bigger than the maximum allowable
buffer size for ALL connections.
2016-01-20 20:24:33,008 ERROR [Thread-10] server.TThreadedSelectorServerWithFix
- Read a frame size of 101362407, which is bigger than the maximum allowable
buffer size for ALL connections.
2016-01-20 20:24:35,339 ERROR [Thread-11] server.TThreadedSelectorServerWithFix
- Read a frame size of 101362407, which is bigger than the maximum allowable
buffer size for ALL connections.
2016-01-20 20:24:43,583 ERROR [Thread-10] server.TThreadedSelectorServerWithFix
- Read a frame size of 101362407, which is bigger than the maximum allowable
buffer size for ALL connections.
2016-01-20 20:24:52,668 INFO [-reporter-1-thread-1] tephra-metrics -
type=GAUGE, name=committed.size, value=1
2016-01-20 20:24:52,668 INFO [-reporter-1-thread-1] tephra-metrics -
type=GAUGE, name=committing.size, value=0
2016-01-20 20:24:52,668 INFO [-reporter-1-thread-1] tephra-metrics -
type=GAUGE, name=inprogress.size, value=2
2016-01-20 20:24:52,668 INFO [-reporter-1-thread-1] tephra-metrics -
type=GAUGE, name=invalid.size, value=0
2016-01-20 20:24:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=abort.latency, count=2, min=0, max=146, mean=73.0,
stddev=73.0, median=146.0, p75=146.0, p95=146.0, p98=146.0, p99=146.0,
p999=146.0
2016-01-20 20:24:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=canCommit.latency, count=1, min=0, max=0, mean=0.0,
stddev=0.0, median=0.0, p75=0.0, p95=0.0, p98=0.0, p99=0.0, p999=0.0
2016-01-20 20:24:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=commit.latency, count=1, min=1, max=1, mean=1.0,
stddev=0.0, median=1.0, p75=1.0, p95=1.0, p98=1.0, p99=1.0, p999=1.0
2016-01-20 20:24:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=start.short.latency, count=5, min=0, max=114,
mean=22.45086090321082, stddev=44.57980095686536, median=1.0, p75=1.0,
p95=114.0, p98=114.0, p99=114.0, p999=114.0
2016-01-20 20:24:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=wal.append.latency, count=9, min=0, max=146,
mean=27.432997340464226, stddev=52.813699432629704, median=0.0, p75=1.0,
p95=146.0, p98=146.0, p99=146.0, p999=146.0
2016-01-20 20:24:52,671 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=wal.sync.size, count=8, min=1, max=1, mean=1.0,
stddev=0.0, median=1.0, p75=1.0, p95=1.0, p98=1.0, p99=1.0, p999=1.0
2016-01-20 20:24:52,671 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=abort, count=2, mean_rate=0.05466640491254933,
m1=0.24261226388505344, m5=0.3619349672143838, m15=0.3868864401928024,
rate_unit=events/second
2016-01-20 20:24:52,671 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=canCommit, count=1, mean_rate=0.03180977230916161,
m1=0.1318481260400888, m5=0.18400888292586465, m15=0.1945208954232697,
rate_unit=events/second
2016-01-20 20:24:52,671 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=commit, count=1, mean_rate=0.031820426582075304,
m1=0.1318481260400888, m5=0.18400888292586465, m15=0.1945208954232697,
rate_unit=events/second
2016-01-20 20:24:52,671 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=start.short, count=5, mean_rate=0.13612291283274078,
m1=0.3850023840227043, m5=0.5489852494589212, m15=0.5824850109429405,
rate_unit=events/second
2016-01-20 20:24:52,671 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=wal.append.count, count=9, mean_rate=0.24578134589517642,
m1=0.6486986361028818, m5=0.9170030153106505, m15=0.9715268017894798,
rate_unit=events/second
2016-01-20 20:25:12,456 ERROR [Thread-11] server.TThreadedSelectorServerWithFix
- Read a frame size of 101362407, which is bigger than the maximum allowable
buffer size for ALL connections.
2016-01-20 20:25:52,668 INFO [-reporter-1-thread-1] tephra-metrics -
type=GAUGE, name=committed.size, value=1
2016-01-20 20:25:52,668 INFO [-reporter-1-thread-1] tephra-metrics -
type=GAUGE, name=committing.size, value=0
2016-01-20 20:25:52,668 INFO [-reporter-1-thread-1] tephra-metrics -
type=GAUGE, name=inprogress.size, value=1
2016-01-20 20:25:52,668 INFO [-reporter-1-thread-1] tephra-metrics -
type=GAUGE, name=invalid.size, value=0
2016-01-20 20:25:52,668 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=abort.latency, count=3, min=0, max=146,
mean=29.86244283644055, stddev=58.148748179949145, median=1.0, p75=1.0,
p95=146.0, p98=146.0, p99=146.0, p999=146.0
2016-01-20 20:25:52,669 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=canCommit.latency, count=1, min=0, max=0, mean=0.0,
stddev=0.0, median=0.0, p75=0.0, p95=0.0, p98=0.0, p99=0.0, p999=0.0
2016-01-20 20:25:52,669 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=commit.latency, count=1, min=1, max=1, mean=1.0,
stddev=0.0, median=1.0, p75=1.0, p95=1.0, p98=1.0, p99=1.0, p999=1.0
2016-01-20 20:25:52,669 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=start.short.latency, count=5, min=0, max=114,
mean=22.45086090321082, stddev=44.57980095686536, median=1.0, p75=1.0,
p95=114.0, p98=114.0, p99=114.0, p999=114.0
2016-01-20 20:25:52,669 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=wal.append.latency, count=10, min=0, max=146,
mean=21.041676728076403, stddev=47.359781121547904, median=1.0, p75=1.0,
p95=146.0, p98=146.0, p99=146.0, p999=146.0
2016-01-20 20:25:52,669 INFO [-reporter-1-thread-1] tephra-metrics -
type=HISTOGRAM, name=wal.sync.size, count=9, min=1, max=1,
mean=0.9999999999999999, stddev=1.1102230246251564E-16, median=1.0, p75=1.0,
p95=1.0, p98=1.0, p99=1.0, p999=1.0
2016-01-20 20:25:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=abort, count=3, mean_rate=0.031060934789005137,
m1=0.1007102001340411, m5=0.299419802353146, m15=0.3630186462880341,
rate_unit=events/second
2016-01-20 20:25:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=canCommit, count=1, mean_rate=0.010936656895649016,
m1=0.04850421492712977, m5=0.15065373129093135, m15=0.1819756564030736,
rate_unit=events/second
2016-01-20 20:25:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=commit, count=1, mean_rate=0.010937914614283327,
m1=0.04850421492712977, m5=0.15065373129093135, m15=0.1819756564030736,
rate_unit=events/second
2016-01-20 20:25:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=start.short, count=5, mean_rate=0.051690125215490865,
m1=0.14163446188394554, m5=0.4494711067182062, m15=0.544918796413339,
rate_unit=events/second
2016-01-20 20:25:52,670 INFO [-reporter-1-thread-1] tephra-metrics -
type=METER, name=wal.append.count, count=10, mean_rate=0.10350177487128351,
m1=0.25010102781287424, m5=0.7538710833805282, m15=0.9099537882931363,
rate_unit=events/second
{code}
> Rows committed in transaction overlapping index creation are not populated
> --------------------------------------------------------------------------
>
> Key: PHOENIX-2478
> URL: https://issues.apache.org/jira/browse/PHOENIX-2478
> Project: Phoenix
> Issue Type: Sub-task
> Reporter: James Taylor
> Assignee: James Taylor
> Fix For: 4.7.0
>
> Attachments: PHOENIX-2478.patch, PHOENIX-2478_addendum.patch,
> PHOENIX-2478_addendum2.patch, PHOENIX-2478_addendum3.patch,
> PHOENIX-2478_addendum4.patch, PHOENIX-2478_v2.patch, PHOENIX-2478_v3.patch,
> PHOENIX-2478_v4.patch
>
>
> For a reproducible case, see IndexIT.testCreateIndexAfterUpsertStarted() and
> the associated FIXME comments for PHOENIX-2446.
> The case that is failing is when a commit starts before an index exists, but
> commits after the index build is completed. For transactional data, this is
> problematic because the index gets a timestamp after the commit of the data
> table mutation and thus these mutations won't be seen during the commit.
> Also, when the index is being built, the data hasn't yet been committed and
> thus won't be part of the initial index build.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
