[ 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