Skip to content

Commit 46c842c

Browse files
merlimatmerlimat
authored
BP-69: Convert http, tools, benchmark and metadata-drivers to slog (phase 4+6) (#4758)
* BP-69 base: add slog dependency and LICENSE entries Minimal scaffolding commit for the BP-69 slog migration series: - Add `io.github.merlimat.slog:slog:0.9.7` to the root pom.xml dependencyManagement and to the global compile classpath alongside the existing SLF4J API (which stays as the rendering backend). - Add lombok.config at the repo root so `@CustomLog` generates a slog `Logger` instead of an SLF4J one. - Register the slog jar in LICENSE-all.bin.txt, LICENSE-server.bin.txt and LICENSE-bkctl.bin.txt so the CI check-binary-license script finds it accounted for in the bundled-jars list. No actual Java file is converted in this commit. Individual module migrations stack on top of this one. * BP-69: Convert http, tools, benchmark and metadata-drivers modules to slog * Bump slog dependency to 0.9.8 Pulls in the MDC propagation fix from merlimat/slog#6, which makes log4j2 ThreadContext entries visible on slog events emitted via the Log4j2Logger backend (so %X{key} layouts and appenders that read event.getContextData().getValue(key) see the caller's MDC).
1 parent 51abbc2 commit 46c842c

45 files changed

Lines changed: 546 additions & 425 deletions

File tree

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

‎bookkeeper-benchmark/src/main/java/org/apache/bookkeeper/benchmark/BenchBookie.java‎

Lines changed: 16 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@
2929
import java.io.IOException;
3030
import java.util.concurrent.Executors;
3131
import java.util.concurrent.ScheduledExecutorService;
32+
import lombok.CustomLog;
3233
import org.apache.bookkeeper.client.BKException;
3334
import org.apache.bookkeeper.client.BookKeeper;
3435
import org.apache.bookkeeper.client.LedgerHandle;
@@ -51,22 +52,20 @@
5152
import org.apache.commons.cli.PosixParser;
5253
import org.apache.commons.lang3.SystemUtils;
5354
import org.apache.zookeeper.KeeperException;
54-
import org.slf4j.Logger;
55-
import org.slf4j.LoggerFactory;
5655

5756
/**
5857
* A utility class used for benchmarking the performance of bookies.
5958
*/
59+
@CustomLog
6060
public class BenchBookie {
61-
static final Logger LOG = LoggerFactory.getLogger(BenchBookie.class);
6261

6362
static class LatencyCallback implements WriteCallback {
6463
boolean complete;
6564
@Override
6665
public synchronized void writeComplete(int rc, long ledgerId, long entryId,
6766
BookieId addr, Object ctx) {
6867
if (rc != 0) {
69-
LOG.error("Got error " + rc);
68+
log.error().attr("rc", rc).log("Got error");
7069
}
7170
complete = true;
7271
notifyAll();
@@ -88,7 +87,7 @@ static class ThroughputCallback implements WriteCallback {
8887
public synchronized void writeComplete(int rc, long ledgerId, long entryId,
8988
BookieId addr, Object ctx) {
9089
if (rc != 0) {
91-
LOG.error("Got error " + rc);
90+
log.error().attr("rc", rc).log("Got error");
9291
}
9392
count++;
9493
if (count >= waitingCount) {
@@ -163,7 +162,9 @@ public static void main(String[] args)
163162
try {
164163
eventLoop = new EpollEventLoopGroup();
165164
} catch (Throwable t) {
166-
LOG.warn("Could not use Netty Epoll event loop for benchmark {}", t.getMessage());
165+
log.warn()
166+
.attr("exceptionMessage", t.getMessage())
167+
.log("Could not use Netty Epoll event loop for benchmark");
167168
eventLoop = new NioEventLoopGroup();
168169
}
169170
} else {
@@ -196,11 +197,11 @@ public static void main(String[] args)
196197
entry, ByteBufList.get(toSend), tc, null, BookieProtocol.FLAG_NONE,
197198
false, WriteFlag.NONE);
198199
}
199-
LOG.info("Waiting for warmup");
200+
log.info("Waiting for warmup");
200201
tc.waitFor(warmUpCount);
201202

202203
ledger = getValidLedgerId(servers);
203-
LOG.info("Benchmarking latency");
204+
log.info("Benchmarking latency");
204205
long startTime = System.nanoTime();
205206
for (long entry = 0; entry < latencyCount; entry++) {
206207
ByteBuf toSend = Unpooled.buffer(size);
@@ -216,10 +217,12 @@ public static void main(String[] args)
216217
lc.waitForComplete();
217218
}
218219
long endTime = System.nanoTime();
219-
LOG.info("Latency: " + (((double) (endTime - startTime)) / ((double) latencyCount)) / 1000000.0);
220+
log.info()
221+
.attr("latencyMs", (((double) (endTime - startTime)) / ((double) latencyCount)) / 1000000.0)
222+
.log("Latency");
220223

221224
ledger = getValidLedgerId(servers);
222-
LOG.info("Benchmarking throughput");
225+
log.info("Benchmarking throughput");
223226
startTime = System.currentTimeMillis();
224227
tc = new ThroughputCallback();
225228
for (long entry = 0; entry < throughputCount; entry++) {
@@ -235,7 +238,9 @@ public static void main(String[] args)
235238
}
236239
tc.waitFor(throughputCount);
237240
endTime = System.currentTimeMillis();
238-
LOG.info("Throughput: " + ((long) throughputCount) * 1000 / (endTime - startTime));
241+
log.info()
242+
.attr("throughput", ((long) throughputCount) * 1000 / (endTime - startTime))
243+
.log("Throughput");
239244

240245
bc.close();
241246
scheduler.shutdown();

‎bookkeeper-benchmark/src/main/java/org/apache/bookkeeper/benchmark/BenchReadThroughputLatency.java‎

Lines changed: 25 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@
3232
import java.util.concurrent.atomic.AtomicInteger;
3333
import java.util.regex.Matcher;
3434
import java.util.regex.Pattern;
35+
import lombok.CustomLog;
3536
import org.apache.bookkeeper.client.BookKeeper;
3637
import org.apache.bookkeeper.client.LedgerEntry;
3738
import org.apache.bookkeeper.client.LedgerHandle;
@@ -45,14 +46,12 @@
4546
import org.apache.commons.cli.PosixParser;
4647
import org.apache.zookeeper.WatchedEvent;
4748
import org.apache.zookeeper.Watcher;
48-
import org.slf4j.Logger;
49-
import org.slf4j.LoggerFactory;
5049

5150
/**
5251
* A benchmark that benchmarks the read throughput and latency.
5352
*/
53+
@CustomLog
5454
public class BenchReadThroughputLatency {
55-
static final Logger LOG = LoggerFactory.getLogger(BenchReadThroughputLatency.class);
5655

5756
private static final Pattern LEDGER_PATTERN = Pattern.compile("L([0-9]+)$");
5857

@@ -75,7 +74,7 @@ public int compare(String o1, String o2) {
7574
};
7675

7776
private static void readLedger(ClientConfiguration conf, long ledgerId, byte[] passwd, int batchEntries) {
78-
LOG.info("Reading ledger {}", ledgerId);
77+
log.info().attr("ledgerId", ledgerId).log("Reading ledger");
7978
BookKeeper bk = null;
8079
long time = 0;
8180
long entriesRead = 0;
@@ -117,7 +116,10 @@ private static void readLedger(ClientConfiguration conf, long ledgerId, byte[] p
117116
entriesRead++;
118117
lastRead = e.getEntryId();
119118
if ((entriesRead % 10000) == 0) {
120-
LOG.info("{} entries read from ledger {}", entriesRead, ledgerId);
119+
log.info()
120+
.attr("entriesRead", entriesRead)
121+
.attr("ledgerId", ledgerId)
122+
.log("entries read from ledger");
121123
}
122124
e.getEntryBuffer().release();
123125
}
@@ -132,9 +134,12 @@ private static void readLedger(ClientConfiguration conf, long ledgerId, byte[] p
132134
} catch (InterruptedException ie) {
133135
Thread.currentThread().interrupt();
134136
} catch (Exception e) {
135-
LOG.error("Exception in reader", e);
137+
log.error().exception(e).log("Exception in reader");
136138
} finally {
137-
LOG.info("Read {} in {}ms", entriesRead, time / 1000 / 1000);
139+
log.info()
140+
.attr("entriesRead", entriesRead)
141+
.attr("timeMs", time / 1000 / 1000)
142+
.log("Read complete");
138143

139144
try {
140145
if (lh != null) {
@@ -144,7 +149,7 @@ private static void readLedger(ClientConfiguration conf, long ledgerId, byte[] p
144149
bk.close();
145150
}
146151
} catch (Exception e) {
147-
LOG.error("Exception closing stuff", e);
152+
log.error().exception(e).log("Exception closing stuff");
148153
}
149154
}
150155
}
@@ -185,7 +190,7 @@ public static void main(String[] args) throws Exception {
185190
final int sockTimeout = Integer.parseInt(cmd.getOptionValue("sockettimeout", "5"));
186191
final int batchentries = Integer.parseInt(cmd.getOptionValue("batchentries", "1000"));
187192
if (cmd.hasOption("ledger") && cmd.hasOption("listen")) {
188-
LOG.error("Cannot used -ledger and -listen together");
193+
log.error("Cannot used -ledger and -listen together");
189194
usage(options);
190195
System.exit(-1);
191196
}
@@ -197,7 +202,7 @@ public static void main(String[] args) throws Exception {
197202
} else if (cmd.hasOption("listen")) {
198203
numLedgers.set(Integer.parseInt(cmd.getOptionValue("listen")));
199204
} else {
200-
LOG.error("You must use -ledger or -listen");
205+
log.error("You must use -ledger or -listen");
201206
usage(options);
202207
System.exit(-1);
203208
}
@@ -215,7 +220,9 @@ public static void main(String[] args) throws Exception {
215220
} else if ("longHierarchical".equals(ledgerManagerType)) {
216221
nodepath = String.format("/ledgers%s", StringUtils.getLongHierarchicalLedgerPath(ledger.get()));
217222
} else {
218-
LOG.warn("Unknown ledger manager type: {}, use flat as the value", ledgerManagerType);
223+
log.warn()
224+
.attr("ledgerManagerType", ledgerManagerType)
225+
.log("Unknown ledger manager type, use flat as the value");
219226
nodepath = String.format("/ledgers/L%010d", ledger.get());
220227
}
221228

@@ -271,15 +278,17 @@ public void run() {
271278
shutdownLatch.countDown();
272279
}
273280
} else {
274-
LOG.error("Cant file ledger id in {}", ledger);
281+
log.error()
282+
.attr("ledger", ledger)
283+
.log("Cant file ledger id");
275284
}
276285
}
277286
}
278287
} else {
279-
LOG.warn("Unknown event {}", event);
288+
log.warn().attr("event", event).log("Unknown event");
280289
}
281290
} catch (Exception e) {
282-
LOG.error("Exception in watcher", e);
291+
log.error().exception(e).log("Exception in watcher");
283292
}
284293
}
285294
});
@@ -289,13 +298,13 @@ public void run() {
289298
readLedger(conf, ledger.get(), passwd, batchentries);
290299
shutdownLatch.countDown();
291300
} else {
292-
LOG.info("Watching for creation of" + nodepath);
301+
log.info().attr("nodepath", nodepath).log("Watching for creation of znode");
293302
}
294303
} else {
295304
zk.getChildren("/ledgers", true);
296305
}
297306
shutdownLatch.await();
298-
LOG.info("Shutting down");
307+
log.info("Shutting down");
299308
}
300309
}
301310
}

0 commit comments

Comments
 (0)