pulsar-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From GitBox <...@apache.org>
Subject [GitHub] [pulsar] ConcurrencyPractitioner edited a comment on issue #3983: [Issue#3976] [component/client] Adding config for ReaderImpl
Date Wed, 10 Apr 2019 03:41:23 GMT
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? 
   
   BTW, the test result is the following:
   ```
   [ERROR] testReaderAtSelectedTimestamp(org.apache.pulsar.client.api.TopicReaderTest)  Time
elapsed: 10.171 s  <<< FAILURE!
   java.lang.AssertionError: Received message my-message-0 did not match the expected message
my-message-3 expected [my-message-3] but found [my-message-0]
   	at org.testng.Assert.fail(Assert.java:96)
   	at org.testng.Assert.failNotEquals(Assert.java:776)
   	at org.testng.Assert.assertEqualsImpl(Assert.java:137)
   ```
   

----------------------------------------------------------------
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:
users@infra.apache.org


With regards,
Apache Git Services

Mime
View raw message