Skip to content

[improve] [Follow-PR#3596] Optimize logger debug enable to reduce allocating objects #3763

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wenbingshen wants to merge 1 commit into from
Closed

[improve] [Follow-PR#3596] Optimize logger debug enable to reduce allocating objects #3763

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 8 additions & 4 deletions bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PacketProcessorBase.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -121,7 +121,7 @@ protected void sendResponse(int rc, Object response, OpStatsLogger statsLogger)

if (channel.isActive()) {
ChannelPromise promise = channel.newPromise().addListener(future -> {
if (!future.isSuccess()) {
if (!future.isSuccess() && logger.isDebugEnabled()) {
logger.debug("Netty channel write exception. ", future.cause());
}
});
Expand All @@ -130,8 +130,10 @@ protected void sendResponse(int rc, Object response, OpStatsLogger statsLogger)
if (response instanceof BookieProtocol.Response) {
((BookieProtocol.Response) response).release();
}
logger.debug("Netty channel {} is inactive, "
+ "hence bypassing netty channel writeAndFlush during sendResponse", channel);
if (logger.isDebugEnabled()) {
logger.debug("Netty channel {} is inactive, "
+ "hence bypassing netty channel writeAndFlush during sendResponse", channel);
}
}
if (BookieProtocol.EOK == rc) {
statsLogger.registerSuccessfulEvent(MathUtils.elapsedNanos(enqueueNanos), TimeUnit.NANOSECONDS);
Expand All @@ -154,7 +156,9 @@ protected void sendResponseAndWait(int rc, Object response, OpStatsLogger statsL
future.get();
}
} catch (ExecutionException | InterruptedException e) {
logger.debug("Netty channel write exception. ", e);
if (logger.isDebugEnabled()) {
logger.debug("Netty channel write exception. ", e);
}
return;
}
if (BookieProtocol.EOK == rc) {
Expand Down
12 changes: 9 additions & 3 deletions bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/ReadLacProcessorV3.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -61,7 +61,9 @@ private ReadLacResponse getReadLacResponse() {
return readLacResponse.build();
}

logger.debug("Received ReadLac request: {}", request);
if (logger.isDebugEnabled()) {
logger.debug("Received ReadLac request: {}", request);
}
StatusCode status = StatusCode.EOK;
ByteBuf lastEntry = null;
ByteBuf lac = null;
Expand All @@ -72,7 +74,9 @@ private ReadLacResponse getReadLacResponse() {
}
} catch (Bookie.NoLedgerException e) {
status = StatusCode.ENOLEDGER;
logger.debug("No ledger found while performing readLac from ledger: {}", ledgerId, e);
if (logger.isDebugEnabled()) {
logger.debug("No ledger found while performing readLac from ledger: {}", ledgerId, e);
}
} catch (BookieException.DataUnknownException e) {
status = StatusCode.EUNKNOWNLEDGERSTATE;
logger.error("Ledger {} in unknown state and cannot serve reacLac requests", ledgerId, e);
Expand All @@ -90,7 +94,9 @@ private ReadLacResponse getReadLacResponse() {
}
} catch (Bookie.NoLedgerException e) {
status = StatusCode.ENOLEDGER;
logger.debug("No ledger found while trying to read last entry: {}", ledgerId, e);
if (logger.isDebugEnabled()) {
logger.debug("No ledger found while trying to read last entry: {}", ledgerId, e);
}
} catch (BookieException.DataUnknownException e) {
status = StatusCode.EUNKNOWNLEDGERSTATE;
logger.error("Ledger in an unknown state while trying to read last entry: {}", ledgerId, e);
Expand Down
8 changes: 6 additions & 2 deletions bookkeeper-server/src/main/java/org/apache/bookkeeper/zookeeper/ZooWorker.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -133,7 +133,9 @@ public static<T> T syncCallWithRetries(ZooKeeperClient client,
if (null != client) {
client.waitForConnection();
}
logger.debug("Execute {} at {} retry attempt.", proc, attempts);
if (logger.isDebugEnabled()) {
logger.debug("Execute {} at {} retry attempt.", proc, attempts);
}
if (null != rateLimiter) {
rateLimiter.acquire();
}
Expand All @@ -150,7 +152,9 @@ public static<T> T syncCallWithRetries(ZooKeeperClient client,
}
if (rethrow) {
statsLogger.registerFailedEvent(MathUtils.elapsedMicroSec(startTimeNanos), TimeUnit.MICROSECONDS);
logger.debug("Stopped executing {} after {} attempts.", proc, attempts);
if (logger.isDebugEnabled()) {
logger.debug("Stopped executing {} after {} attempts.", proc, attempts);
}
throw e;
}
TimeUnit.MILLISECONDS.sleep(retryPolicy.nextRetryWaitTime(attempts, elapsedTime));
Expand Down
4 changes: 3 additions & 1 deletion bookkeeper-server/src/test/java/org/apache/bookkeeper/client/TestAddEntryQuorumTimeout.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -94,7 +94,9 @@ public void testBasicTimeout() throws Exception {
private void waitForSyncObj(SyncObj syncObj) throws Exception {
synchronized (syncObj) {
while (syncObj.counter < 1) {
logger.debug("Entries counter = " + syncObj.counter);
if (logger.isDebugEnabled()) {
logger.debug("Entries counter = " + syncObj.counter);
}
syncObj.wait();
}
}
Expand Down
20 changes: 14 additions & 6 deletions stream/distributedlog/core/src/main/java/org/apache/distributedlog/ReadAheadEntryReader.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -406,8 +406,10 @@ private void orderedSubmit(Runnable runnable) {
try {
scheduler.executeOrdered(streamName, runnable);
} catch (RejectedExecutionException ree) {
logger.debug("Failed to submit and execute an operation for readhead entry reader of {}",
streamName, ree);
if (logger.isDebugEnabled()) {
logger.debug("Failed to submit and execute an operation for readhead entry reader of {}",
streamName, ree);
}
}
}

Expand Down Expand Up @@ -524,7 +526,7 @@ private void notifyStateChangeOnFailure(Throwable cause) {
}

void setLastException(IOException cause) {
if (!lastException.compareAndSet(null, cause)) {
if (!lastException.compareAndSet(null, cause) && logger.isDebugEnabled()) {
logger.debug("last exception has already been set to ", lastException.get());
}
// the exception is set and notify the state change
Expand Down Expand Up @@ -924,13 +926,17 @@ private void unsafeMoveToNextLogSegment() {
FutureUtils.ensure(
currentSegmentReader.close(),
removeClosedSegmentReadersFunc);
logger.debug("close current segment reader {}", currentSegmentReader.getSegment());
if (logger.isDebugEnabled()) {
logger.debug("close current segment reader {}", currentSegmentReader.getSegment());
}
currentSegmentReader = null;
}
boolean hasSegmentToRead = false;
if (null != nextSegmentReader) {
currentSegmentReader = nextSegmentReader;
logger.debug("move to read segment {}", currentSegmentReader.getSegment());
if (logger.isDebugEnabled()) {
logger.debug("move to read segment {}", currentSegmentReader.getSegment());
}
currentSegmentSequenceNumber = currentSegmentReader.getSegment().getLogSegmentSequenceNumber();
nextSegmentReader = null;
// start reading
Expand All @@ -940,7 +946,9 @@ private void unsafeMoveToNextLogSegment() {
unsafePrefetchNextSegment(false);
if (null != nextSegmentReader) {
currentSegmentReader = nextSegmentReader;
logger.debug("move to read segment {}", currentSegmentReader.getSegment());
if (logger.isDebugEnabled()) {
logger.debug("move to read segment {}", currentSegmentReader.getSegment());
}
currentSegmentSequenceNumber = currentSegmentReader.getSegment().getLogSegmentSequenceNumber();
nextSegmentReader = null;
unsafePrefetchNextSegment(true);
Expand Down
8 changes: 5 additions & 3 deletions ...butedlog/core/src/main/java/org/apache/distributedlog/impl/ZKLogSegmentMetadataStore.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -115,7 +115,7 @@ public void onFailure(Throwable cause) {
public void run() {
if (null != store.listeners.get(logSegmentsPath)) {
store.zkGetLogSegmentNames(logSegmentsPath, store).whenComplete(this);
} else {
} else if (logger.isDebugEnabled()) {
logger.debug("Log segments listener for {} has been removed.", logSegmentsPath);
}
}
Expand Down Expand Up @@ -411,8 +411,10 @@ public CompletableFuture<Versioned<List<String>>> getLogSegmentNames(String logS
listenerSet.put(listener, new VersionedLogSegmentNamesListener(listener));
if (!listeners.containsKey(logSegmentsPath)) {
// listener set has been removed, add it back
if (null != listeners.putIfAbsent(logSegmentsPath, listenerSet)) {
logger.debug("Listener set is already found for log segments path {}", logSegmentsPath);
if (null != listeners.putIfAbsent(logSegmentsPath, listenerSet)
&& logger.isDebugEnabled()) {
logger.debug("Listener set is already found for log segments path {}",
logSegmentsPath);
}
}
}
Expand Down
7 changes: 5 additions & 2 deletions ...core/src/main/java/org/apache/distributedlog/impl/logsegment/BKLogSegmentEntryReader.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -455,8 +455,11 @@ public void openComplete(int rc, LedgerHandle lh, Object ctx) {
lh.asyncClose(new AsyncCallback.CloseCallback() {
@Override
public void closeComplete(int rc, LedgerHandle lh, Object ctx) {
logger.debug("Close the open ledger {} since the log segment reader is already closed",
lh.getId());
if (logger.isDebugEnabled()) {
logger.debug("Close the open ledger {} "
+ "since the log segment reader is already closed",
lh.getId());
}
}
}, null);
return;
Expand Down
8 changes: 6 additions & 2 deletions ...e/src/main/java/org/apache/distributedlog/impl/subscription/ZKSubscriptionStateStore.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -72,11 +72,15 @@ public CompletableFuture<DLSN> getLastCommitPosition() {
CompletableFuture<DLSN> getLastCommitPositionFromZK() {
final CompletableFuture<DLSN> result = new CompletableFuture<DLSN>();
try {
logger.debug("Reading last commit position from path {}", zkPath);
if (logger.isDebugEnabled()) {
logger.debug("Reading last commit position from path {}", zkPath);
}
zooKeeperClient.get().getData(zkPath, false, new AsyncCallback.DataCallback() {
@Override
public void processResult(int rc, String path, Object ctx, byte[] data, Stat stat) {
logger.debug("Read last commit position from path {}: rc = {}", zkPath, rc);
if (logger.isDebugEnabled()) {
logger.debug("Read last commit position from path {}: rc = {}", zkPath, rc);
}
if (KeeperException.Code.NONODE.intValue() == rc) {
result.complete(DLSN.NonInclusiveLowerBound);
} else if (KeeperException.Code.OK.intValue() != rc) {
Expand Down
4 changes: 3 additions & 1 deletion stream/distributedlog/core/src/main/java/org/apache/distributedlog/lock/LockWaiter.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -89,7 +89,9 @@ public boolean waitForAcquireQuietly() {
} catch (DLInterruptedException ie) {
Thread.currentThread().interrupt();
} catch (LockTimeoutException lte) {
logger.debug("Timeout on lock acquiring", lte);
if (logger.isDebugEnabled()) {
logger.debug("Timeout on lock acquiring", lte);
}
} catch (IOException e) {
logger.error("Caught exception waiting for lock acquired", e);
}
Expand Down
2 changes: 1 addition & 1 deletion ...tedlog/core/src/main/java/org/apache/distributedlog/namespace/NamespaceDriverManager.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -125,7 +125,7 @@ public static void registerDriver(String backend, Class<? extends NamespaceDrive
}
NamespaceDriverInfo newDriverInfo = new NamespaceDriverInfo(driver);
oldDriverInfo = drivers.putIfAbsent(scheme, newDriverInfo);
if (null != oldDriverInfo) {
if (null != oldDriverInfo && logger.isDebugEnabled()) {
logger.debug("Driver for {} is already there.", scheme);
}
}
Expand Down
4 changes: 3 additions & 1 deletion stream/distributedlog/core/src/test/java/org/apache/distributedlog/ZooKeeperClientUtils.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,9 @@ public static void expireSession(ZooKeeperClient zkc, String zkServers, int time
oldZk.exists("/", new Watcher() {
@Override
public void process(WatchedEvent event) {
logger.debug("Receive event : {}", event);
if (logger.isDebugEnabled()) {
logger.debug("Receive event : {}", event);
}
if (event.getType() == Event.EventType.None
&& event.getState() == Event.KeeperState.Expired) {
expireLatch.countDown();
Expand Down
4 changes: 3 additions & 1 deletion ...e/src/test/java/org/apache/distributedlog/impl/metadata/TestZKLogStreamMetadataStore.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -202,7 +202,9 @@ public void setup() throws Exception {
ZooDefs.Ids.OPEN_ACL_UNSAFE,
CreateMode.PERSISTENT);
} catch (KeeperException.NodeExistsException nee) {
logger.debug("The namespace uri already exists.");
if (logger.isDebugEnabled()) {
logger.debug("The namespace uri already exists.");
}
}
scheduler = OrderedScheduler.newSchedulerBuilder()
.name("test-scheduler")
Expand Down