ConcurrencyPractitioner edited a comment on issue #3983: [Issue#3976] [component/client] Adding config for ReaderImpl URL: https://github.com/apache/pulsar/pull/3983#issuecomment-481514423 Alright, so I ran the test on local and here was a segment of the log for the test I added: ``` Current system time is: 1554866983877 20:29:48.721 [pulsar-load-manager-166-1:org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl@433] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - Writing local data to ZooKeeper because maximum change 34.49612557888031% exceeded threshold 10%; time since last report written is 5.894 seconds 20:29:48.724 [pulsar-load-manager-166-1:org.apache.pulsar.zookeeper.ZooKeeperDataCache@154] INFO org.apache.pulsar.zookeeper.ZooKeeperDataCache - [MockZookeeper] Received ZooKeeper watch event: WatchedEvent state:SyncConnected type:NodeDataChanged path:/loadbalance/brokers/localhost:15077 Seeking to time: 1554866986877 20:29:53.949 [TestNG-method=testReaderAtSelectedTimestamp-1:org.apache.pulsar.client.impl.ReaderBuilderImpl@94] INFO org.apache.pulsar.client.impl.ReaderBuilderImpl - Setting messageId value since timestamp value is 1554866986877 20:29:53.957 [pulsar-web-181-6:org.eclipse.jetty.server.Slf4jRequestLog@60] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [09/Apr/2019:20:29:53 -0700] "GET /admin/v2/persistent/my-property/my-ns/testReaderAtSelectedTimestamp/partitions HTTP/1.1" 200 16 "-" "Pulsar-Java-v2.4.0.0-SNAPSHOT" 5 20:29:53.965 [pulsar-web-181-7:org.eclipse.jetty.server.Slf4jRequestLog@60] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [09/Apr/2019:20:29:53 -0700] "GET /lookup/v2/topic/persistent/my-property/my-ns/testReaderAtSelectedTimestamp HTTP/1.1" 200 132 "-" "Pulsar-Java-v2.4.0.0-SNAPSHOT" 5 20:29:53.967 [pulsar-client-io-187-1:org.apache.pulsar.client.impl.ConsumerImpl@493] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://my-property/my-ns/testReaderAtSelectedTimestamp][reader-876e4801a7] Subscribing to topic on cnx [id: 0x392cc6c5, L:/127.0.0.1:60511 - R:localhost/127.0.0.1:15079] 20:29:53.968 [pulsar-io-174-1:org.apache.pulsar.broker.service.ServerCnx@641] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:60511] Subscribing on topic persistent://my-property/my-ns/testReaderAtSelectedTimestamp / reader-876e4801a7 20:29:53.969 [pulsar-io-174-1:org.apache.pulsar.broker.service.persistent.PersistentTopic@624] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://my-property/my-ns/testReaderAtSelectedTimestamp][reader-876e4801a7] Creating non-durable subscription at msg id -1:-1:-1:-1 20:29:53.969 [pulsar-io-174-1:org.apache.bookkeeper.mledger.impl.NonDurableCursorImpl@54] INFO org.apache.bookkeeper.mledger.impl.NonDurableCursorImpl - [my-property/my-ns/persistent/testReaderAtSelectedTimestamp] Created non-durable cursor read-position=3:0 mark-delete-position=3:-1 20:29:53.970 [pulsar-io-174-1:org.apache.pulsar.broker.service.persistent.PersistentTopic@648] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - Cursor's name is: reader-876e4801a7 20:29:53.971 [pulsar-io-174-1:org.apache.bookkeeper.mledger.impl.ManagedCursorImpl@1789] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [my-property/my-ns/persistent/testReaderAtSelectedTimestamp-reader-876e4801a7] Rewind from 3:0 to 3:0 20:29:53.971 [pulsar-io-174-1:org.apache.pulsar.broker.service.persistent.PersistentTopic@571] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://my-property/my-ns/testReaderAtSelectedTimestamp][reader-876e4801a7] Created new subscription for 0 20:29:53.971 [pulsar-io-174-1:org.apache.pulsar.broker.service.ServerCnx@701] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:60511] Created subscription on topic persistent://my-property/my-ns/testReaderAtSelectedTimestamp / reader-876e4801a7 20:29:53.973 [pulsar-client-io-187-1:org.apache.pulsar.client.impl.ConsumerImpl@588] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://my-property/my-ns/testReaderAtSelectedTimestamp][reader-876e4801a7] Subscribed to topic on localhost/127.0.0.1:15079 -- consumer: 0 20:29:53.975 [TestNG-method=testReaderAtSelectedTimestamp-1:org.apache.pulsar.client.impl.ConsumerImpl@1376] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://my-property/my-ns/testReaderAtSelectedTimestamp][reader-876e4801a7] Seek subscription to publish time 1554866986877 20:29:53.982 [bookkeeper-ml-workers-OrderedExecutor-1-0:org.apache.pulsar.broker.service.persistent.PersistentMessageFinder@69] INFO org.apache.pulsar.broker.service.persistent.PersistentMessageFinder - Message publish time is: 1554866983877 20:29:53.984 [bookkeeper-ml-workers-OrderedExecutor-1-0:org.apache.pulsar.broker.service.persistent.PersistentMessageFinder@69] INFO org.apache.pulsar.broker.service.persistent.PersistentMessageFinder - Message publish time is: 1554866992944 20:29:53.986 [bookkeeper-ml-workers-OrderedExecutor-1-0:org.apache.pulsar.broker.service.persistent.PersistentMessageFinder@69] INFO org.apache.pulsar.broker.service.persistent.PersistentMessageFinder - Message publish time is: 1554866987908 20:29:53.987 [bookkeeper-ml-workers-OrderedExecutor-1-0:org.apache.pulsar.broker.service.persistent.PersistentMessageFinder@69] INFO org.apache.pulsar.broker.service.persistent.PersistentMessageFinder - Message publish time is: 1554866984885 20:29:53.988 [bookkeeper-ml-workers-OrderedExecutor-1-0:org.apache.pulsar.broker.service.persistent.PersistentMessageFinder@69] INFO org.apache.pulsar.broker.service.persistent.PersistentMessageFinder - Message publish time is: 1554866985893 20:29:53.989 [bookkeeper-ml-workers-OrderedExecutor-1-0:org.apache.pulsar.broker.service.persistent.PersistentMessageFinder@69] INFO org.apache.pulsar.broker.service.persistent.PersistentMessageFinder - Message publish time is: 1554866986902 ``` Ok, so I've found some curious behavior here. In this particular segment, we find that we are seeking to a time which is in between the third and fourth messsage published. The last five digits of the message publish times are: ``` 83877 84885 85893 86877 86902 87908 92944 ``` And we are seeking to a time with last five digits of 86877. However, the seek turns out to be ineffective. And when ```Reader#readNext()``` returns a value, it still returns the first value instead. @sijie Do you know what might explain this puzzling behavior?
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services
