use of org.apache.stanbol.enhancer.servicesapi.helper.execution.Execution in project stanbol by apache.
the class EnhancementJobHandler method logExecutionTimes.
/**
* Helper method that logs the execution time for the Chain and all the
* Enhancement Engines on DEBUG level
* @param logger The logger used for logging
* @param job the job to log. This expects that
* <code>{@link EnhancementJob#isFinished()} == true</code>
*/
protected static void logExecutionTimes(Logger logger, EnhancementJob job) {
if (logger.isInfoEnabled()) {
try {
ExecutionMetadata em = ExecutionMetadata.parseFrom(job.getExecutionMetadata(), job.getContentItem().getUri());
ChainExecution ce = em.getChainExecution();
long cd = ce.getDuration();
StringBuilder message = new StringBuilder("> processed ContentItem ").append(job.getContentItem().getUri()).append(" with Chain '").append(ce.getChainName()).append("' in ").append(ce.getDuration()).append("ms | ");
List<Execution> ees = new ArrayList<Execution>(em.getEngineExecutions().values());
//sort by start date (execution order)
Collections.sort(ees, new Comparator<Execution>() {
@Override
public int compare(Execution e1, Execution e2) {
return e1.getStarted().compareTo(e2.getStarted());
}
});
message.append("chain:[");
long eds = 0;
boolean first = true;
for (Execution ee : ees) {
if (first) {
first = false;
} else {
message.append(", ");
}
long ed = ee.getDuration();
eds = eds + ed;
int edp = Math.round(ed * 100 / (float) cd);
message.append(ee.getExecutionNode().getEngineName()).append(": ").append(ed).append("ms (").append(edp).append("%)");
}
float cf = eds / cd;
int cfp = Math.round((cf - 1) * 100);
message.append("], concurrency: ").append(cf).append(" (").append(cfp).append("%)");
logger.info(message.toString());
} catch (RuntimeException e) {
log.warn("Exception while logging ExecutionTimes for Chain: '" + job.getChainName() + " and ContentItem " + job.getContentItem().getUri() + " to Logger " + logger.getName(), e);
}
}
}
use of org.apache.stanbol.enhancer.servicesapi.helper.execution.Execution in project stanbol by apache.
the class EventJobManagerImpl method enhanceContent.
@Override
public void enhanceContent(ContentItem ci, Chain chain) throws EnhancementException {
if (ci == null) {
throw new IllegalArgumentException("The parsed contentItem MUST NOT be NULL!");
}
if (chain == null) {
throw new IllegalArgumentException("Unable to enhance ContentItem '" + ci.getUri() + "' because NULL was passed as enhancement chain");
}
long start = System.currentTimeMillis();
enhancementJobManagerLog.debug(">> enhance {} with chain {}", ci.getUri(), chain.getName());
boolean isDefaultChain = chain.equals(chainManager.getDefault());
EnhancementJob job = new EnhancementJob(ci, chain.getName(), chain.getExecutionPlan(), isDefaultChain);
//start the execution
//wait for the results
EnhancementJobObserver observer = jobHandler.register(job);
//now wait for the execution to finish for the configured maximum time
boolean completed = observer.waitForCompletion(maxEnhancementJobWaitTime);
if (!completed) {
//throw timeout exception
StringBuilder sb = new StringBuilder("Status:\n");
ExecutionMetadata em = ExecutionMetadata.parseFrom(job.getExecutionMetadata(), ci.getUri());
for (Entry<String, Execution> ex : em.getEngineExecutions().entrySet()) {
sb.append(" -").append(ex.getKey()).append(": ").append(ex.getValue().getStatus()).append('\n');
}
throw new ChainException("Execution timeout after " + ((System.currentTimeMillis() - start) / 1000f) + "sec (timeout:" + (maxEnhancementJobWaitTime / 1000) + "sec) for ContentItem " + ci.getUri() + "\n" + sb.toString() + " \n To change the timeout change value of property '" + MAX_ENHANCEMENT_JOB_WAIT_TIME + "' for the service " + getClass());
}
log.info("Execution of Chain {} {} after {}ms for ContentItem {}", new Object[] { chain.getName(), job.isFailed() ? "failed" : "finished", System.currentTimeMillis() - start, job.getContentItem().getUri() });
//ci.getMetadata().addAll(job.getExecutionMetadata());
if (job.isFailed()) {
Exception e = job.getError();
EnhancementJobHandler.logJobInfo(log, job, null, true);
logExecutionMetadata(enhancementJobManagerLog, job, true);
log.warn("ExecutionMetadata: ");
for (Iterator<Triple> it = job.getExecutionMetadata().iterator(); it.hasNext(); log.warn(it.next().toString())) ;
if (e instanceof SecurityException) {
throw (SecurityException) e;
} else if (e instanceof EnhancementException) {
throw (EnhancementException) e;
} else {
throw new ChainException(job.getErrorMessage(), e);
}
}
if (!job.isFinished()) {
log.warn("Execution finished, but Job is not finished!");
EnhancementJobHandler.logJobInfo(log, job, null, true);
logExecutionMetadata(log, job, true);
throw new ChainException("EnhancementJobManager was deactivated while" + " enhancing the passed ContentItem " + job.getContentItem() + " (EnhancementJobManager type: " + getClass() + ")");
} else {
//log infos about the execution times to the enhancementJobManager
EnhancementJobHandler.logExecutionTimes(enhancementJobManagerLog, job);
logExecutionMetadata(enhancementJobManagerLog, job, false);
}
}
Aggregations