[
https://issues.apache.org/jira/browse/IMPALA-12683?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Quanlong Huang updated IMPALA-12683:
------------------------------------
Epic Link: IMPALA-12877
> 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
> Priority: Major
> Fix For: Impala 4.4.0
>
>
> 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: issues-all-unsubscr...@impala.apache.org
For additional commands, e-mail: issues-all-h...@impala.apache.org
