devinbost commented on issue #6054:
URL: https://github.com/apache/pulsar/issues/6054#issuecomment-843541155
I dropped some timestamps into
`ManagedLedgerImpl.updateLedgersIdsComplete(..)`, and I'm not seeing anything
glaring yet. Adding logs like this:
```
public synchronized void updateLedgersIdsComplete(Stat stat) {
STATE_UPDATER.set(this, State.LedgerOpened);
lastLedgerCreatedTimestamp = clock.millis();
if (log.isDebugEnabled()) {
log.debug("[{}] Resending {} pending messages", name,
pendingAddEntries.size());
}
// Avoid use same OpAddEntry between different ledger handle
long priorNano = System.nanoTime();
int pendingSize = pendingAddEntries.size();
OpAddEntry existsOp;
do {
log.debug("updateLedgersIdsComplete 1. Nanoseconds is: {}",
System.nanoTime() - priorNano);
priorNano = System.nanoTime();
existsOp = pendingAddEntries.poll();
//log.debug("In ManagedLedgerImpl.updateLedgersIdsComplete(..),
we're processing OpAddEntry {}",
// existsOp != null ? existsOp.toString() : null);
if (existsOp != null) {
// If op is used by another ledger handle, we need to close
it and create a new one
if (existsOp.ledger != null) {
log.debug("updateLedgersIdsComplete 2. Nanoseconds is:
{}", System.nanoTime() - priorNano);
priorNano = System.nanoTime();
existsOp.close();
log.debug("updateLedgersIdsComplete 3. Nanoseconds is:
{}", System.nanoTime() - priorNano);
priorNano = System.nanoTime();
existsOp = OpAddEntry.create(existsOp.ml, existsOp.data,
existsOp.getNumberOfMessages(), existsOp.callback, existsOp.ctx);
log.debug("updateLedgersIdsComplete 4. Nanoseconds is:
{}", System.nanoTime() - priorNano);
priorNano = System.nanoTime();
}
existsOp.setLedger(currentLedger);
log.debug("updateLedgersIdsComplete 5. Nanoseconds is: {}",
System.nanoTime() - priorNano);
priorNano = System.nanoTime();
if (beforeAddEntry(existsOp)) {
log.debug("updateLedgersIdsComplete 6. Nanoseconds is:
{}", System.nanoTime() - priorNano);
priorNano = System.nanoTime();
pendingAddEntries.add(existsOp);
log.debug("updateLedgersIdsComplete 7. Nanoseconds is:
{}", System.nanoTime() - priorNano);
priorNano = System.nanoTime();
}
}
} while (existsOp != null && --pendingSize > 0);
// Process all the pending addEntry requests
for (OpAddEntry op : pendingAddEntries) {
//log.debug("In ManagedLedgerImpl.updateLedgersIdsComplete(..),
processing list of pendingAddEntries, starting"
// + " with OpAddEntry {}",
// op != null ? op.toString() : null);
log.debug("updateLedgersIdsComplete 8. Nanoseconds is: {}",
System.nanoTime() - priorNano);
priorNano = System.nanoTime();
++currentLedgerEntries;
currentLedgerSize += op.data.readableBytes();
if (log.isDebugEnabled()) {
log.debug("[{}] Sending {}", name, op);
}
if (currentLedgerIsFull()) {
log.debug("updateLedgersIdsComplete 9. Nanoseconds is: {}",
System.nanoTime() - priorNano);
priorNano = System.nanoTime();
STATE_UPDATER.set(this, State.ClosingLedger);
op.setCloseWhenDone(true);
log.debug("updateLedgersIdsComplete 10. Nanoseconds is: {}",
System.nanoTime() - priorNano);
priorNano = System.nanoTime();
op.initiate();
log.debug("updateLedgersIdsComplete 11. Nanoseconds is: {}",
System.nanoTime() - priorNano);
if (log.isDebugEnabled()) {
log.debug("[{}] Stop writing into ledger {} queue={}",
name, currentLedger.getId(),
pendingAddEntries.size());
}
break;
} else {
op.initiate();
log.debug("updateLedgersIdsComplete 12. Nanoseconds is: {}",
System.nanoTime() - priorNano);
}
}
}
```
gave this output (plus many thousand more similar lines):
```
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 2. Nanoseconds is: 246
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 3. Nanoseconds is: 35
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 4. Nanoseconds is: 335
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 5. Nanoseconds is: 31
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 6. Nanoseconds is: 29
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 7. Nanoseconds is: 64
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 1. Nanoseconds is: 24
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 2. Nanoseconds is: 292
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 3. Nanoseconds is: 34
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 4. Nanoseconds is: 401
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 5. Nanoseconds is: 31
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 6. Nanoseconds is: 29
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 7. Nanoseconds is: 82
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 1. Nanoseconds is: 23
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 2. Nanoseconds is: 234
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 3. Nanoseconds is: 101
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 4. Nanoseconds is: 447
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 5. Nanoseconds is: 31
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 6. Nanoseconds is: 29
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 7. Nanoseconds is: 60
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 1. Nanoseconds is: 24
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 2. Nanoseconds is: 176
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 3. Nanoseconds is: 123
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 4. Nanoseconds is: 362
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 5. Nanoseconds is: 31
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 6. Nanoseconds is: 32
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 7. Nanoseconds is: 88
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 1. Nanoseconds is: 25
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 2. Nanoseconds is: 236
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 3. Nanoseconds is: 123
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 4. Nanoseconds is: 353
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 5. Nanoseconds is: 32
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 6. Nanoseconds is: 29
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 7. Nanoseconds is: 58
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 1. Nanoseconds is: 25
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 2. Nanoseconds is: 233
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 3. Nanoseconds is: 36
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 4. Nanoseconds is: 739
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 5. Nanoseconds is: 29
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 6. Nanoseconds is: 29
DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
updateLedgersIdsComplete 7. Nanoseconds is: 90
```
--
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]
