You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@tika.apache.org by ta...@apache.org on 2021/08/04 14:35:21 UTC
[tika] 02/02: TIKA-3512 -- add trace logging to tika-core pipes
components
This is an automated email from the ASF dual-hosted git repository.
tallison pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/tika.git
commit 1972c6ed014a0c1f91842119761781358e4a629d
Author: tallison <ta...@apache.org>
AuthorDate: Wed Aug 4 10:35:03 2021 -0400
TIKA-3512 -- add trace logging to tika-core pipes components
---
.../java/org/apache/tika/pipes/PipesClient.java | 60 ++++++++++----
.../org/apache/tika/pipes/PipesConfigBase.java | 8 +-
.../java/org/apache/tika/pipes/PipesServer.java | 95 +++++++++++++++++-----
.../org/apache/tika/pipes/async/AsyncEmitter.java | 3 +-
.../apache/tika/pipes/async/AsyncProcessor.java | 50 ++++++++++--
5 files changed, 169 insertions(+), 47 deletions(-)
diff --git a/tika-core/src/main/java/org/apache/tika/pipes/PipesClient.java b/tika-core/src/main/java/org/apache/tika/pipes/PipesClient.java
index 525a423..273ed12 100644
--- a/tika-core/src/main/java/org/apache/tika/pipes/PipesClient.java
+++ b/tika-core/src/main/java/org/apache/tika/pipes/PipesClient.java
@@ -111,17 +111,26 @@ public class PipesClient implements Closeable {
private PipesResult actuallyProcess(FetchEmitTuple t) {
long start = System.currentTimeMillis();
FutureTask<PipesResult> futureTask = new FutureTask<>(() -> {
+
ByteArrayOutputStream bos = new ByteArrayOutputStream();
try (ObjectOutputStream objectOutputStream = new ObjectOutputStream(bos)) {
objectOutputStream.writeObject(t);
}
+
byte[] bytes = bos.toByteArray();
output.write(CALL.getByte());
output.writeInt(bytes.length);
output.write(bytes);
output.flush();
-
- return readResults(t, start);
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- write tuple: {} ms", System.currentTimeMillis() - start);
+ }
+ long readStart = System.currentTimeMillis();
+ PipesResult result = readResults(t, start);
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- read result: {} ms", System.currentTimeMillis() - readStart);
+ }
+ return result;
});
try {
@@ -131,18 +140,23 @@ public class PipesClient implements Closeable {
process.destroyForcibly();
return PipesResult.INTERRUPTED_EXCEPTION;
} catch (ExecutionException e) {
+ LOG.error("pipesClientId=" + pipesClientId + " execution exception", e);
long elapsed = System.currentTimeMillis() - start;
destroyWithPause();
if (!process.isAlive() && TIMEOUT_EXIT_CODE == process.exitValue()) {
- LOG.warn("server timeout: {} in {} ms", t.getId(), elapsed);
+ LOG.warn("pipesClientId={} server timeout: {} in {} ms", pipesClientId, t.getId(),
+ elapsed);
return PipesResult.TIMEOUT;
}
try {
process.waitFor(500, TimeUnit.MILLISECONDS);
if (process.isAlive()) {
- LOG.warn("crash: {} in {} ms with no exit code available", t.getId(), elapsed);
+ LOG.warn("pipesClientId={} crash: {} in {} ms with no exit code available",
+ pipesClientId, t.getId(), elapsed);
} else {
- LOG.warn("crash: {} in {} ms with exit code {}", t.getId(), elapsed, process.exitValue());
+ LOG.warn("pipesClientId={} crash: {} in {} ms with exit code {}",
+ pipesClientId, t.getId(),
+ elapsed, process.exitValue());
}
} catch (InterruptedException interruptedException) {
//swallow
@@ -151,7 +165,8 @@ public class PipesClient implements Closeable {
} catch (TimeoutException e) {
long elapsed = System.currentTimeMillis() - start;
process.destroyForcibly();
- LOG.warn("client timeout: {} in {} ms", t.getId(), elapsed);
+ LOG.warn("pipesClientId={} client timeout: {} in {} ms",
+ pipesClientId, t.getId(), elapsed);
return PipesResult.TIMEOUT;
} finally {
futureTask.cancel(true);
@@ -182,33 +197,35 @@ public class PipesClient implements Closeable {
}
switch (status) {
case OOM:
- LOG.warn("oom: {} in {} ms", t.getId(), millis);
+ LOG.warn("pipesClientId={} oom: {} in {} ms", pipesClientId, t.getId(), millis);
return PipesResult.OOM;
case TIMEOUT:
- LOG.warn("server response timeout: {} in {} ms", t.getId(), millis);
+ LOG.warn("pipesClientId={} server response timeout: {} in {} ms", pipesClientId, t.getId(),
+ millis);
return PipesResult.TIMEOUT;
case EMIT_EXCEPTION:
- LOG.warn("emit exception: {} in {} ms", t.getId(), millis);
+ LOG.warn("pipesClientId={} emit exception: {} in {} ms", pipesClientId, t.getId(), millis);
return readMessage(PipesResult.STATUS.EMIT_EXCEPTION);
case EMITTER_NOT_FOUND:
- LOG.warn("emitter not found: {} in {} ms", t.getId(), millis);
+ LOG.warn("pipesClientId={} emitter not found: {} in {} ms", pipesClientId, t.getId(), millis);
return readMessage(PipesResult.STATUS.NO_EMITTER_FOUND);
case FETCHER_NOT_FOUND:
- LOG.warn("fetcher not found: {} in {} ms", t.getId(), millis);
+ LOG.warn("pipesClientId={} fetcher not found: {} in {} ms", pipesClientId, t.getId(), millis);
return readMessage(PipesResult.STATUS.NO_FETCHER_FOUND);
case FETCHER_INITIALIZATION_EXCEPTION:
- LOG.warn("fetcher initialization exception: {} in {} ms", t.getId(), millis);
+ LOG.warn("pipesClientId={} fetcher initialization exception: {} in {} ms", pipesClientId,
+ t.getId(), millis);
return readMessage(PipesResult.STATUS.FETCHER_INITIALIZATION_EXCEPTION);
case FETCH_EXCEPTION:
- LOG.warn("fetch exception: {} in {} ms", t.getId(), millis);
+ LOG.warn("pipesClientId={} fetch exception: {} in {} ms", pipesClientId, t.getId(), millis);
return readMessage(PipesResult.STATUS.FETCH_EXCEPTION);
case PARSE_SUCCESS:
- LOG.info("parse success: {} in {} ms", t.getId(), millis);
+ LOG.info("pipesClientId={} parse success: {} in {} ms", pipesClientId, t.getId(), millis);
return deserializeEmitData();
case PARSE_EXCEPTION_NO_EMIT:
return readMessage(PipesResult.STATUS.PARSE_EXCEPTION_NO_EMIT);
case EMIT_SUCCESS:
- LOG.info("emit success: {} in {} ms", t.getId(), millis);
+ LOG.info("pipesClientId={} emit success: {} in {} ms", pipesClientId, t.getId(), millis);
return PipesResult.EMIT_SUCCESS;
case EMIT_SUCCESS_PARSE_EXCEPTION:
return readMessage(PipesResult.STATUS.EMIT_SUCCESS_PARSE_EXCEPTION);
@@ -314,6 +331,8 @@ public class PipesClient implements Closeable {
boolean hasHeadless = false;
boolean hasExitOnOOM = false;
boolean hasLog4j = false;
+ String origGCString = null;
+ String newGCLogString = null;
for (String arg : configArgs) {
if (arg.startsWith("-Djava.awt.headless")) {
hasHeadless = true;
@@ -328,6 +347,15 @@ public class PipesClient implements Closeable {
if (arg.startsWith("-Dlog4j.configuration")) {
hasLog4j = true;
}
+ if (arg.startsWith("-Xloggc:")) {
+ origGCString = arg;
+ newGCLogString = arg.replace("${pipesClientId}", "id-" + pipesClientId);
+ }
+ }
+
+ if (origGCString != null && newGCLogString != null) {
+ configArgs.remove(origGCString);
+ configArgs.add(newGCLogString);
}
List<String> commandLine = new ArrayList<>();
@@ -357,7 +385,7 @@ public class PipesClient implements Closeable {
commandLine.add(Long.toString(pipesConfig.getMaxForEmitBatchBytes()));
commandLine.add(Long.toString(pipesConfig.getTimeoutMillis()));
commandLine.add(Long.toString(pipesConfig.getShutdownClientAfterMillis()));
- LOG.debug("commandline: " + commandLine);
+ LOG.debug("commandline: {}", commandLine);
return commandLine.toArray(new String[0]);
}
}
diff --git a/tika-core/src/main/java/org/apache/tika/pipes/PipesConfigBase.java b/tika-core/src/main/java/org/apache/tika/pipes/PipesConfigBase.java
index f48e7fd..a02654f 100644
--- a/tika-core/src/main/java/org/apache/tika/pipes/PipesConfigBase.java
+++ b/tika-core/src/main/java/org/apache/tika/pipes/PipesConfigBase.java
@@ -19,6 +19,7 @@ package org.apache.tika.pipes;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.ArrayList;
+import java.util.Collections;
import java.util.List;
import org.apache.tika.config.ConfigBase;
@@ -92,11 +93,14 @@ public class PipesConfigBase extends ConfigBase {
}
public List<String> getForkedJvmArgs() {
- return forkedJvmArgs;
+ //defensive copy
+ List<String> ret = new ArrayList<>();
+ ret.addAll(forkedJvmArgs);
+ return ret;
}
public void setForkedJvmArgs(List<String> jvmArgs) {
- this.forkedJvmArgs = jvmArgs;
+ this.forkedJvmArgs = Collections.unmodifiableList(jvmArgs);
}
/**
diff --git a/tika-core/src/main/java/org/apache/tika/pipes/PipesServer.java b/tika-core/src/main/java/org/apache/tika/pipes/PipesServer.java
index 74ae1a3..8f3ff09 100644
--- a/tika-core/src/main/java/org/apache/tika/pipes/PipesServer.java
+++ b/tika-core/src/main/java/org/apache/tika/pipes/PipesServer.java
@@ -113,6 +113,7 @@ public class PipesServer implements Runnable {
}
private final Object[] lock = new Object[0];
+ private long checkForTimeoutMs = 1000;
private final Path tikaConfigPath;
private final DataInputStream input;
private final DataOutputStream output;
@@ -147,22 +148,25 @@ public class PipesServer implements Runnable {
public static void main(String[] args) throws Exception {
- Path tikaConfig = Paths.get(args[0]);
- long maxForEmitBatchBytes = Long.parseLong(args[1]);
- long serverParseTimeoutMillis = Long.parseLong(args[2]);
- long serverWaitTimeoutMillis = Long.parseLong(args[3]);
-
- PipesServer server =
- new PipesServer(tikaConfig, System.in, System.out,
- maxForEmitBatchBytes, serverParseTimeoutMillis,
- serverWaitTimeoutMillis);
- System.setIn(new ByteArrayInputStream(new byte[0]));
- System.setOut(System.err);
- Thread watchdog = new Thread(server, "Tika Watchdog");
- watchdog.setDaemon(true);
- watchdog.start();
-
- server.processRequests();
+ try {
+ Path tikaConfig = Paths.get(args[0]);
+ long maxForEmitBatchBytes = Long.parseLong(args[1]);
+ long serverParseTimeoutMillis = Long.parseLong(args[2]);
+ long serverWaitTimeoutMillis = Long.parseLong(args[3]);
+
+ PipesServer server =
+ new PipesServer(tikaConfig, System.in, System.out, maxForEmitBatchBytes,
+ serverParseTimeoutMillis, serverWaitTimeoutMillis);
+ System.setIn(new ByteArrayInputStream(new byte[0]));
+ System.setOut(System.err);
+ Thread watchdog = new Thread(server, "Tika Watchdog");
+ watchdog.setDaemon(true);
+ watchdog.start();
+
+ server.processRequests();
+ } finally {
+ LOG.info("server shutting down");
+ }
}
public void run() {
@@ -175,11 +179,11 @@ public class PipesServer implements Runnable {
exit(TIMEOUT_EXIT_CODE);
} else if (!parsing && serverWaitTimeoutMillis > 0 &&
elapsed > serverWaitTimeoutMillis) {
- LOG.debug("closing down from inactivity");
+ LOG.info("closing down from inactivity");
exit(0);
}
}
- Thread.sleep(100);
+ Thread.sleep(checkForTimeoutMs);
}
} catch (InterruptedException e) {
//swallow
@@ -189,7 +193,11 @@ public class PipesServer implements Runnable {
public void processRequests() {
//initialize
try {
+ long start = System.currentTimeMillis();
initializeParser();
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- initialize parser: {} ms", System.currentTimeMillis() - start);
+ }
} catch (Throwable t) {
t.printStackTrace();
LOG.error("couldn't initialize parser", t);
@@ -204,14 +212,23 @@ public class PipesServer implements Runnable {
//main loop
try {
write(STATUS.READY);
+ long start = System.currentTimeMillis();
while (true) {
int request = input.read();
if (request == -1) {
exit(1);
} else if (request == STATUS.PING.getByte()) {
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- ping: {} ms", System.currentTimeMillis() - start);
+ }
write(STATUS.PING);
+ start = System.currentTimeMillis();
} else if (request == STATUS.CALL.getByte()) {
parseOne();
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- parse one: {} ms", System.currentTimeMillis() - start);
+ }
+ start = System.currentTimeMillis();
} else {
throw new IllegalStateException("Unexpected request");
}
@@ -280,8 +297,16 @@ public class PipesServer implements Runnable {
}
FetchEmitTuple t = null;
try {
+ long start = System.currentTimeMillis();
t = readFetchEmitTuple();
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- read fetchEmitTuple: {} ms", System.currentTimeMillis() - start);
+ }
+ start = System.currentTimeMillis();
actuallyParse(t);
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- actually parsed: {} ms", System.currentTimeMillis() - start);
+ }
} catch (OutOfMemoryError e) {
handleOOM(t.getId(), e);
} finally {
@@ -294,7 +319,7 @@ public class PipesServer implements Runnable {
private void actuallyParse(FetchEmitTuple t) {
List<Metadata> metadataList = null;
-
+ long start = System.currentTimeMillis();
Fetcher fetcher = null;
try {
fetcher = fetcherManager.getFetcher(t.getFetchKey().getFetcherName());
@@ -310,7 +335,11 @@ public class PipesServer implements Runnable {
ExceptionUtils.getStackTrace(e));
return;
}
-
+ if (LOG.isTraceEnabled()) {
+ long elapsed = System.currentTimeMillis() - start;
+ LOG.trace("timer -- got fetcher: {}ms", elapsed);
+ }
+ start = System.currentTimeMillis();
Metadata metadata = new Metadata();
try (InputStream stream = fetcher.fetch(t.getFetchKey().getFetchKey(), metadata)) {
metadataList = parse(t, stream, metadata);
@@ -321,11 +350,14 @@ public class PipesServer implements Runnable {
LOG.warn("fetch exception " + t.getId(), e);
write(STATUS.FETCH_EXCEPTION, ExceptionUtils.getStackTrace(e));
}
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- to parse: {} ms", System.currentTimeMillis() - start);
+ }
if (metadataIsEmpty(metadataList)) {
write(STATUS.EMPTY_OUTPUT);
return;
}
-
+ start = System.currentTimeMillis();
String stack = getContainerStacktrace(t, metadataList);
if (StringUtils.isBlank(stack) || t.getOnParseException() == FetchEmitTuple.ON_PARSE_EXCEPTION.EMIT) {
injectUserMetadata(t.getMetadata(), metadataList);
@@ -337,9 +369,15 @@ public class PipesServer implements Runnable {
EmitData emitData = new EmitData(t.getEmitKey(), metadataList);
if (maxForEmitBatchBytes >= 0 && emitData.getEstimatedSizeBytes() >= maxForEmitBatchBytes) {
emit(t.getId(), emitData, stack);
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- emitted: {} ms", System.currentTimeMillis() - start);
+ }
} else {
//ignore the stack, it is stored in the emit data
write(emitData);
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- to write data: {} ms", System.currentTimeMillis() - start);
+ }
}
} else {
write(STATUS.PARSE_EXCEPTION_NO_EMIT, stack);
@@ -414,6 +452,7 @@ public class PipesServer implements Runnable {
});
String containerException = null;
+ long start = System.currentTimeMillis();
try {
autoDetectParser.parse(stream, handler, metadata, parseContext);
} catch (SAXException e) {
@@ -438,6 +477,9 @@ public class PipesServer implements Runnable {
} catch (TikaException e) {
LOG.warn("exception mapping metadata", e);
}
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- parse only time: {} ms", System.currentTimeMillis() - start);
+ }
}
return Collections.singletonList(metadata);
}
@@ -449,6 +491,7 @@ public class PipesServer implements Runnable {
new BasicContentHandlerFactory(handlerConfig.getType(), handlerConfig.getWriteLimit()),
handlerConfig.getMaxEmbeddedResources(), tikaConfig.getMetadataFilter());
ParseContext parseContext = new ParseContext();
+ long start = System.currentTimeMillis();
try {
rMetaParser.parse(stream, handler, metadata, parseContext);
} catch (SAXException e) {
@@ -460,6 +503,10 @@ public class PipesServer implements Runnable {
throw e;
} catch (Exception e) {
LOG.warn("exception: " + fetchEmitTuple.getId(), e);
+ } finally {
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- parse only time: {} ms", System.currentTimeMillis() - start);
+ }
}
return handler.getMetadataList();
}
@@ -475,7 +522,11 @@ public class PipesServer implements Runnable {
}
private void exit(int exitCode) {
- LOG.error("exiting: {}", exitCode);
+ if (exitCode != 0) {
+ LOG.error("exiting: {}", exitCode);
+ } else {
+ LOG.info("exiting: {}", exitCode);
+ }
System.exit(exitCode);
}
diff --git a/tika-core/src/main/java/org/apache/tika/pipes/async/AsyncEmitter.java b/tika-core/src/main/java/org/apache/tika/pipes/async/AsyncEmitter.java
index 67a4de7..fce65c5 100644
--- a/tika-core/src/main/java/org/apache/tika/pipes/async/AsyncEmitter.java
+++ b/tika-core/src/main/java/org/apache/tika/pipes/async/AsyncEmitter.java
@@ -76,7 +76,8 @@ public class AsyncEmitter implements Callable<Integer> {
} else {
LOG.trace("Nothing on the async queue");
}
- LOG.debug("cache size: ({}) bytes and count: {}", cache.estimatedSize, cache.size);
+ LOG.debug("cache size: ({}) bytes and extract count: {}", cache.estimatedSize,
+ cache.size);
long elapsed = ChronoUnit.MILLIS.between(lastEmitted, Instant.now());
if (elapsed > asyncConfig.getEmitWithinMillis()) {
LOG.debug("{} elapsed > {}, going to emitAll", elapsed, asyncConfig.getEmitWithinMillis());
diff --git a/tika-core/src/main/java/org/apache/tika/pipes/async/AsyncProcessor.java b/tika-core/src/main/java/org/apache/tika/pipes/async/AsyncProcessor.java
index 62cc2d3..2b3e80b 100644
--- a/tika-core/src/main/java/org/apache/tika/pipes/async/AsyncProcessor.java
+++ b/tika-core/src/main/java/org/apache/tika/pipes/async/AsyncProcessor.java
@@ -30,6 +30,9 @@ import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
import org.apache.tika.exception.TikaException;
import org.apache.tika.pipes.FetchEmitTuple;
import org.apache.tika.pipes.PipesClient;
@@ -48,6 +51,7 @@ public class AsyncProcessor implements Closeable {
static final int PARSER_FUTURE_CODE = 1;
+ private static final Logger LOG = LoggerFactory.getLogger(AsyncProcessor.class);
private final ArrayBlockingQueue<FetchEmitTuple> fetchEmitTuples;
private final ArrayBlockingQueue<EmitData> emitData;
@@ -55,6 +59,7 @@ public class AsyncProcessor implements Closeable {
private final ExecutorService executorService;
private final AsyncConfig asyncConfig;
private final AtomicLong totalProcessed = new AtomicLong(0);
+ private static long MAX_OFFER_WAIT_MS = 120000;
private int numParserThreadsFinished = 0;
private boolean addedEmitterSemaphores = false;
private int finished = 0;
@@ -129,8 +134,12 @@ public class AsyncProcessor implements Closeable {
public void finished() throws InterruptedException {
for (int i = 0; i < asyncConfig.getNumClients(); i++) {
- //can hang forever
- fetchEmitTuples.offer(PipesIterator.COMPLETED_SEMAPHORE);
+ boolean offered = fetchEmitTuples.offer(PipesIterator.COMPLETED_SEMAPHORE,
+ MAX_OFFER_WAIT_MS, TimeUnit.MILLISECONDS);
+ if (! offered) {
+ throw new RuntimeException("Couldn't offer completed semaphore within " +
+ MAX_OFFER_WAIT_MS + " ms");
+ }
}
}
@@ -151,8 +160,17 @@ public class AsyncProcessor implements Closeable {
}
if (numParserThreadsFinished == asyncConfig.getNumClients() && ! addedEmitterSemaphores) {
for (int i = 0; i < asyncConfig.getNumEmitters(); i++) {
- //can hang forever
- emitData.offer(AsyncEmitter.EMIT_DATA_STOP_SEMAPHORE);
+ try {
+ boolean offered = emitData.offer(AsyncEmitter.EMIT_DATA_STOP_SEMAPHORE,
+ MAX_OFFER_WAIT_MS,
+ TimeUnit.MILLISECONDS);
+ if (! offered) {
+ throw new RuntimeException("Couldn't offer emit data stop semaphore " +
+ "within " + MAX_OFFER_WAIT_MS + " ms");
+ }
+ } catch (InterruptedException e) {
+ throw new RuntimeException(e);
+ }
}
addedEmitterSemaphores = true;
}
@@ -190,7 +208,13 @@ public class AsyncProcessor implements Closeable {
FetchEmitTuple t = fetchEmitTuples.poll(1, TimeUnit.SECONDS);
if (t == null) {
//skip
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("null fetch emit tuple");
+ }
} else if (t == PipesIterator.COMPLETED_SEMAPHORE) {
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("hit completed semaphore");
+ }
return PARSER_FUTURE_CODE;
} else {
PipesResult result = null;
@@ -200,9 +224,23 @@ public class AsyncProcessor implements Closeable {
} catch (IOException e) {
result = PipesResult.UNSPECIFIED_CRASH;
}
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- pipes client process: {} ms",
+ System.currentTimeMillis() - start);
+ }
+ long offerStart = System.currentTimeMillis();
if (result.getStatus() == PipesResult.STATUS.PARSE_SUCCESS) {
- //TODO -- add timeout, this currently hangs forever
- emitDataQueue.offer(result.getEmitData());
+ boolean offered = emitDataQueue.offer(result.getEmitData(),
+ MAX_OFFER_WAIT_MS,
+ TimeUnit.MILLISECONDS);
+ if (! offered) {
+ throw new RuntimeException("Couldn't offer emit data to queue " +
+ "within " + MAX_OFFER_WAIT_MS + " ms");
+ }
+ }
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("timer -- offered: {} ms",
+ System.currentTimeMillis() - offerStart);
}
long elapsed = System.currentTimeMillis() - start;
asyncConfig.getPipesReporter().report(t, result, elapsed);