Quanlong Huang created IMPALA-12683:
---------------------------------------
Summary: Incorrect last synced event time in
testDisableEventSyncFlag
Key: IMPALA-12683
URL: https://issues.apache.org/jira/browse/IMPALA-12683
Project: IMPALA
Issue Type: Bug
Reporter: Quanlong Huang
Assignee: Quanlong Huang
In https://jenkins.impala.io/job/ubuntu-20.04-from-scratch/1346 ,
MetastoreEventsProcessorTest.testDisableEventSyncFlag failed with
{noformat}
java.lang.AssertionError: Incorrect last synced event time for event 32759
expected:<1704337032> but was:<1704337031>
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:834)
at org.junit.Assert.assertEquals(Assert.java:645)
at
org.apache.impala.catalog.events.SynchronousHMSEventProcessorForTests.verifyEventSyncedMetrics(SynchronousHMSEventProcessorForTests.java:65)
at
org.apache.impala.catalog.events.SynchronousHMSEventProcessorForTests.processEvents(SynchronousHMSEventProcessorForTests.java:51)
at
org.apache.impala.catalog.events.MetastoreEventsProcessorTest.testDDLOpUsingEvent(MetastoreEventsProcessorTest.java:2250)
at
org.apache.impala.catalog.events.MetastoreEventsProcessorTest.runDDLTestsWithFlags(MetastoreEventsProcessorTest.java:2102)
at
org.apache.impala.catalog.events.MetastoreEventsProcessorTest.testDisableEventSyncFlag(MetastoreEventsProcessorTest.java:2056)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at
org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:316)
at
org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:240)
at
org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:214)
at
org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:155)
at
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:385)
at
org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
at
org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:507)
at
org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495){noformat}
I can find suspecious logs of FeSupport:
{noformat}
I0104 02:57:12.006399 1487414 MetastoreEventsProcessor.java:903] Received 3
events. Start event id : 32756
I0104 02:57:12.007038 1487414 MetastoreEvents.java:289] Total number of events
received: 3 Total number of events filtered out: 0
I0104 02:57:12.007139 1487414 MetastoreEvents.java:634] EventId: 32759
EventType: ALTER_PARTITIONS Created a batch event for 3 events from 32757 to
32759
I0104 02:57:12.007193 1487414 MetastoreEvents.java:634] EventId: 32759
EventType: ALTER_PARTITIONS Found table level flag impala.disableHmsSync is set
to true for table events_test_db.runddltestswithflags
I0104 02:57:12.007223 1487414 MetastoreEvents.java:634] EventId: 32759
EventType: ALTER_PARTITIONS Skipping this event because of flag evaluation
I0104 02:57:12.007287 1487414 MetastoreEventsProcessor.java:1180] Time elapsed
in processing event batch: 822.814us
I0104 02:57:12.007939 1487414 MetastoreEventsProcessor.java:1017] Latest event
in HMS: id=32759, time=1704337032. Last synced event: id=32759, time=1704337031.
W0104 02:57:12.007990 1487414 MetastoreEventsProcessor.java:1020] Lag: 1s. 0
events pending to be processed.{noformat}
The last second line shows the same event id with different event time. So the
last line shows a lag of 1s. The last processed event is a batch event of 3
ALTER_PARTITION events. The bug is that we use the first event time to update
last-synced-event-time. Instead, we should use the last one, just like how we
get the event id:
{code:java}
@Override
public long getEventId() {
Preconditions.checkState(!batchedEvents_.isEmpty());
return batchedEvents_.get(batchedEvents_.size()-1).getEventId();
}{code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
