/** * Restores the timeout map with timeout values from the aggregation repository. * <p/> * This is needed in case the aggregator has been stopped and started again (for example a server restart). * Then the existing exchanges from the {@link AggregationRepository} must have their timeout conditions restored. */ protected void restoreTimeoutMapFromAggregationRepository() throws Exception { // grab the timeout value for each partly aggregated exchange Set<String> keys = aggregationRepository.getKeys(); if (keys == null || keys.isEmpty()) { return; } StopWatch watch = new StopWatch(); LOG.trace("Starting restoring CompletionTimeout for {} existing exchanges from the aggregation repository...", keys.size()); for (String key : keys) { Exchange exchange = aggregationRepository.get(camelContext, key); // grab the timeout value long timeout = exchange.hasProperties() ? exchange.getProperty(Exchange.AGGREGATED_TIMEOUT, 0, long.class) : 0; if (timeout > 0) { LOG.trace("Restoring CompletionTimeout for exchangeId: {} with timeout: {} millis.", exchange.getExchangeId(), timeout); addExchangeToTimeoutMap(key, exchange, timeout); } } // log duration of this task so end user can see how long it takes to pre-check this upon starting LOG.info("Restored {} CompletionTimeout conditions in the AggregationTimeoutChecker in {}", timeoutMap.size(), TimeUtils.printDuration(watch.stop())); }
private void doForceCompletionOnStop() { int expected = forceCompletionOfAllGroups(); StopWatch watch = new StopWatch(); while (inProgressCompleteExchanges.size() > 0) { LOG.trace("Waiting for {} inflight exchanges to complete", inProgressCompleteExchanges.size()); try { Thread.sleep(100); } catch (InterruptedException e) { // break out as we got interrupted such as the JVM terminating LOG.warn("Interrupted while waiting for {} inflight exchanges to complete.", inProgressCompleteExchanges.size()); break; } } if (expected > 0) { LOG.info("Forcing completion of all groups with {} exchanges completed in {}", expected, TimeUtils.printDuration(watch.stop())); } }
public Processor wrapProcessorInInterceptors(final CamelContext context, final ProcessorDefinition<?> definition, final Processor target, final Processor nextTarget) throws Exception { return new DelegateAsyncProcessor(target) { @Override public boolean process(final Exchange exchange, final AsyncCallback callback) { debugger.beforeProcess(exchange, target, definition); final StopWatch watch = new StopWatch(); return processor.process(exchange, new AsyncCallback() { public void done(boolean doneSync) { long diff = watch.stop(); debugger.afterProcess(exchange, processor, definition, diff); // must notify original callback callback.done(doneSync); } }); } @Override public String toString() { return "Debug[" + target + "]"; } }; }
@Override public boolean awaitTermination(ExecutorService executorService, long shutdownAwaitTermination) throws InterruptedException { // log progress every 2nd second so end user is aware of we are shutting down StopWatch watch = new StopWatch(); long interval = Math.min(2000, shutdownAwaitTermination); boolean done = false; while (!done && interval > 0) { if (executorService.awaitTermination(interval, TimeUnit.MILLISECONDS)) { done = true; } else { LOG.info("Waited {} for ExecutorService: {} to terminate...", TimeUtils.printDuration(watch.taken()), executorService); // recalculate interval interval = Math.min(2000, shutdownAwaitTermination - watch.taken()); } } return done; }
private DirectVmConsumer awaitConsumer() throws InterruptedException { DirectVmConsumer answer = null; StopWatch watch = new StopWatch(); boolean done = false; while (!done) { // sleep a bit to give chance for the consumer to be ready Thread.sleep(500); if (LOG.isDebugEnabled()) { LOG.debug("Waited {} for consumer to be ready", watch.taken()); } answer = endpoint.getConsumer(); if (answer != null) { return answer; } // we are done if we hit the timeout done = watch.taken() >= endpoint.getTimeout(); } return answer; }
private DirectConsumer awaitConsumer() throws InterruptedException { DirectConsumer answer = null; StopWatch watch = new StopWatch(); boolean done = false; while (!done) { // sleep a bit to give chance for the consumer to be ready Thread.sleep(500); if (LOG.isDebugEnabled()) { LOG.debug("Waited {} for consumer to be ready", watch.taken()); } answer = endpoint.getConsumer(); if (answer != null) { return answer; } // we are done if we hit the timeout done = watch.taken() >= endpoint.getTimeout(); } return answer; }
@Override public void prepareOnStartup(GenericFileOperations<File> operations, GenericFileEndpoint<File> endpoint) { if (deleteOrphanLockFiles) { String dir = endpoint.getConfiguration().getDirectory(); File file = new File(dir); LOG.debug("Prepare on startup by deleting orphaned lock files from: {}", dir); Pattern excludePattern = endpoint.getExclude() != null ? Pattern.compile(endpoint.getExclude()) : null; Pattern includePattern = endpoint.getInclude() != null ? Pattern.compile(endpoint.getInclude()) : null; String endpointPath = endpoint.getConfiguration().getDirectory(); StopWatch watch = new StopWatch(); deleteLockFiles(file, endpoint.isRecursive(), endpointPath, endpoint.getFilter(), endpoint.getAntFilter(), excludePattern, includePattern); // log anything that takes more than a second if (watch.taken() > 1000) { LOG.info("Prepared on startup by deleting orphaned lock files from: {} took {} millis to complete.", dir, watch.taken()); } } }
public void testRedeliveryErrorHandlerNoRedeliveryOnShutdown() throws Exception { getMockEndpoint("mock:foo").expectedMessageCount(1); getMockEndpoint("mock:deadLetter").expectedMessageCount(1); getMockEndpoint("mock:deadLetter").setResultWaitTime(25000); template.sendBody("seda:foo", "Hello World"); getMockEndpoint("mock:foo").assertIsSatisfied(); // should not take long to stop the route StopWatch watch = new StopWatch(); // sleep 3 seconds to do some redeliveries before we stop Thread.sleep(3000); log.info("==== stopping route foo ===="); context.stopRoute("foo"); watch.stop(); getMockEndpoint("mock:deadLetter").assertIsSatisfied(); log.info("OnRedelivery processor counter {}", counter.get()); assertTrue("Should stop route faster, was " + watch.taken(), watch.taken() < 7000); assertTrue("Redelivery counter should be >= 2 and < 12, was: " + counter.get(), counter.get() >= 2 && counter.get() < 12); }
protected void timeSplitRoutes(int numberOfRequests) throws Exception { String[] endpoints = new String[]{"direct:splitSynchronizedAggregation", "direct:splitUnsynchronizedAggregation"}; List<Future<File>> futures = new ArrayList<Future<File>>(); StopWatch stopWatch = new StopWatch(false); for (String endpoint : endpoints) { stopWatch.restart(); for (int requestIndex = 0; requestIndex < numberOfRequests; requestIndex++) { futures.add(template.asyncRequestBody(endpoint, null, File.class)); } for (int i = 0; i < futures.size(); i++) { Future<File> future = futures.get(i); future.get(); } stopWatch.stop(); log.info(String.format("test%d.%s=%d\n", numberOfRequests, endpoint, stopWatch.taken())); } }
public void testRedelivery() throws Exception { StopWatch watch = new StopWatch(); MockEndpoint before = getMockEndpoint("mock:foo"); before.expectedMessageCount(1); template.sendBody("seda:start", "Hello World"); assertMockEndpointsSatisfied(); Thread.sleep(500); context.stopRoute("foo"); // we should reject the task and stop quickly assertTrue("Should stop quickly: " + watch.taken(), watch.taken() < 5000); // should go to DLC Exchange dead = getMockEndpoint("mock:dead").getExchanges().get(0); assertNotNull(dead); Throwable cause = dead.getProperty(Exchange.EXCEPTION_CAUGHT, Throwable.class); assertNotNull(cause); assertIsInstanceOf(RejectedExecutionException.class, cause); assertEquals("Redelivery not allowed while stopping", cause.getMessage()); }
public void testVmInOutChainedTimeout() throws Exception { StopWatch watch = new StopWatch(); try { template2.requestBody("vm:a?timeout=1000", "Hello World"); fail("Should have thrown an exception"); } catch (CamelExecutionException e) { // the chained vm caused the timeout ExchangeTimedOutException cause = assertIsInstanceOf(ExchangeTimedOutException.class, e.getCause()); assertEquals(200, cause.getTimeout()); } long delta = watch.stop(); assertTrue("Should be faster than 1 sec, was: " + delta, delta < 1100); }
@Test public void testJmsRequestReplySharedReplyTo() throws Exception { StopWatch watch = new StopWatch(); // shared is more slower than exclusive, due it need to use a JMS Message Selector // and has a receiveTimeout of 1 sec per default, so it react slower to new messages assertEquals("Hello A", template.requestBody("activemq:queue:foo?replyTo=bar&replyToType=Shared", "A")); assertEquals("Hello B", template.requestBody("activemq:queue:foo?replyTo=bar&replyToType=Shared", "B")); assertEquals("Hello C", template.requestBody("activemq:queue:foo?replyTo=bar&replyToType=Shared", "C")); assertEquals("Hello D", template.requestBody("activemq:queue:foo?replyTo=bar&replyToType=Shared", "D")); assertEquals("Hello E", template.requestBody("activemq:queue:foo?replyTo=bar&replyToType=Shared", "E")); long delta = watch.stop(); assertTrue("Should be slower than about 2 seconds, was: " + delta, delta > 2000); }
@Test public void testAsyncJmsInOut() throws Exception { MockEndpoint mock = getMockEndpoint("mock:result"); mock.expectedMessageCount(100); mock.expectsNoDuplicates(body()); StopWatch watch = new StopWatch(); for (int i = 0; i < 100; i++) { template.sendBody("seda:start", "" + i); } // just in case we run on slow boxes assertMockEndpointsSatisfied(20, TimeUnit.SECONDS); log.info("Took " + watch.stop() + " ms. to process 100 messages request/reply over JMS"); }
@Test public void testConnectionResourceRouter() throws Exception { MockEndpoint mock = getMockEndpoint("mock:result"); mock.expectedMessageCount(100); mock.expectsNoDuplicates(body()); StopWatch watch = new StopWatch(); for (int i = 0; i < 100; i++) { template.sendBody("seda:start", "" + i); } // just in case we run on slow boxes assertMockEndpointsSatisfied(20, TimeUnit.SECONDS); log.info("Took " + watch.stop() + " ms. to process 100 messages request/reply over JMS"); }
@Test public void testSynchronous() throws Exception { MockEndpoint mock = getMockEndpoint("mock:result"); mock.expectedMessageCount(100); mock.expectsNoDuplicates(body()); StopWatch watch = new StopWatch(); for (int i = 0; i < 100; i++) { template.sendBody("seda:start", "" + i); } // just in case we run on slow boxes assertMockEndpointsSatisfied(20, TimeUnit.SECONDS); log.info("Took " + watch.stop() + " ms. to process 100 messages request/reply over JMS"); }
@Test public void testAsynchronous() throws Exception { MockEndpoint mock = getMockEndpoint("mock:result"); mock.expectedMessageCount(100); mock.expectsNoDuplicates(body()); StopWatch watch = new StopWatch(); for (int i = 0; i < 100; i++) { template.sendBody("seda:start", "" + i); } // just in case we run on slow boxes assertMockEndpointsSatisfied(20, TimeUnit.SECONDS); log.info("Took " + watch.stop() + " ms. to process 100 messages request/reply over JMS"); }
@Test public void testJettyAsyncTimeout() throws Exception { getMockEndpoint("mock:result").expectedBodiesReceived("Bye World"); StopWatch watch = new StopWatch(); try { template.requestBody("http://localhost:{{port}}/myservice", null, String.class); fail("Should have thrown an exception"); } catch (CamelExecutionException e) { log.info("Timeout hit and client got reply with failure status code"); long taken = watch.stop(); HttpOperationFailedException cause = assertIsInstanceOf(HttpOperationFailedException.class, e.getCause()); assertEquals(503, cause.getStatusCode()); // should be approx 3-4 sec. assertTrue("Timeout should occur faster than " + taken, taken < 4500); } assertMockEndpointsSatisfied(); }
@Test public void testJettyAsyncTimeout() throws Exception { getMockEndpoint("mock:result").expectedBodiesReceived("Bye World"); StopWatch watch = new StopWatch(); try { template.requestBody("http://localhost:{{port}}/myservice", null, String.class); fail("Should have thrown an exception"); } catch (CamelExecutionException e) { log.info("Timeout hit and client got reply with failure status code"); long taken = watch.stop(); HttpOperationFailedException cause = assertIsInstanceOf(HttpOperationFailedException.class, e.getCause()); assertEquals(503, cause.getStatusCode()); // should be approx 30-34 sec. assertTrue("Timeout should occur faster than " + taken, taken < 34000); } assertMockEndpointsSatisfied(2, TimeUnit.MINUTES); }
public void testDisruptorVmInOutChainedTimeout() throws Exception { StopWatch watch = new StopWatch(); try { template2.requestBody("disruptor-vm:a?timeout=1000", "Hello World"); fail("Should have thrown an exception"); } catch (CamelExecutionException e) { // the chained vm caused the timeout ExchangeTimedOutException cause = assertIsInstanceOf(ExchangeTimedOutException.class, e.getCause()); assertEquals(200, cause.getTimeout()); } long delta = watch.stop(); assertTrue("Should be faster than 1 sec, was: " + delta, delta < 1100); }
@Test public void testDisruptorInOutChainedTimeout() throws Exception { // time timeout after 2 sec should trigger a immediately reply final StopWatch watch = new StopWatch(); try { template.requestBody("disruptor:a?timeout=5000", "Hello World"); fail("Should have thrown an exception"); } catch (CamelExecutionException e) { final ExchangeTimedOutException cause = assertIsInstanceOf(ExchangeTimedOutException.class, e.getCause()); assertEquals(2000, cause.getTimeout()); } final long delta = watch.stop(); assertTrue("Should be faster than 4000 millis, was: " + delta, delta < 4000); }
public void stop() { if (isStopped()) { logger.info(String.format("application %s was already stopped ", name)); return; } StopWatch timingWath = new StopWatch(); try { logStopingInfo(); for (IDrinkWaterService service : services) { service.stop(); } stopExternalServices(); if (isUseServiceManagement()) { stopManagementService(); } stopTokenServiceIfEnabled(); stopDataStores(); stopApplicationContext(); state = ApplicationState.Stopped; timingWath.stop(); } finally { logStoppedInfo(timingWath); } }
private void logStartedInfo(StopWatch stoppedwatch) { Iterator<String> services = getServices().stream() .sorted(Comparator.comparing(s -> s.getConfiguration().getScheme())) .map(Object::toString) .iterator(); logger.info("configured services :"); services.forEachRemaining(s -> logger.info(" > " + s)); logger.info(String.format("----------------------- application %s STARTED in %d ms, have a nice day ------------------------------------", name, stoppedwatch.taken())); }
public static void main(String[] args) { LoanBrokerWS loanBroker = getProxy(url); StopWatch watch = new StopWatch(); String result = loanBroker.getLoanQuote("SSN", 5000.00, 24); System.out.println("Took " + watch.stop() + " milliseconds to call the loan broker service"); System.out.println(result); }
@Override public StopWatch before(Exchange exchange) throws Exception { // only record time if stats is enabled StopWatch answer = counter != null && counter.isStatisticsEnabled() ? new StopWatch() : null; if (answer != null) { beginTime(exchange); } return answer; }
@Override public void after(Exchange exchange, StopWatch watch) throws Exception { // record end time if (watch != null) { recordTime(exchange, watch.stop()); } }
@Override public StopWatch before(Exchange exchange) throws Exception { if (backlogDebugger.isEnabled() && (backlogDebugger.hasBreakpoint(nodeId) || backlogDebugger.isSingleStepMode())) { StopWatch watch = new StopWatch(); backlogDebugger.beforeProcess(exchange, target, definition); return watch; } else { return null; } }
public boolean sleep() throws InterruptedException { // for small delays then just sleep if (delay < 1000) { policy.sleep(delay); return true; } StopWatch watch = new StopWatch(); log.debug("Sleeping for: {} millis until attempting redelivery", delay); while (watch.taken() < delay) { // sleep using 1 sec interval long delta = delay - watch.taken(); long max = Math.min(1000, delta); if (max > 0) { log.trace("Sleeping for: {} millis until waking up for re-check", max); Thread.sleep(max); } // are we preparing for shutdown then only do redelivery if allowed if (preparingShutdown && !policy.isAllowRedeliveryWhileStopping()) { log.debug("Rejected redelivery while stopping"); return false; } } return true; }
@Override public boolean process(final Exchange exchange, final AsyncCallback callback) { // only record time if stats is enabled final StopWatch watch = (counter != null && counter.isStatisticsEnabled()) ? new StopWatch() : null; // mark beginning to process the exchange if (watch != null) { beginTime(exchange); } return processor.process(exchange, new AsyncCallback() { public void done(boolean doneSync) { try { // record end time if (watch != null) { recordTime(exchange, watch.stop()); } } finally { // and let the original callback know we are done as well callback.done(doneSync); } } @Override public String toString() { return InstrumentationProcessor.this.toString(); } }); }
@Override protected void doResume() throws Exception { try { EventHelper.notifyCamelContextResuming(this); log.info("Apache Camel " + getVersion() + " (CamelContext: " + getName() + ") is resuming"); StopWatch watch = new StopWatch(); // start the suspended routes (do not check for route clashes, and indicate) doStartOrResumeRoutes(suspendedRouteServices, false, true, true, false); // mark the route services as resumed (will be marked as started) as well for (RouteService service : suspendedRouteServices.values()) { if (routeSupportsSuspension(service.getId())) { service.resume(); } else { service.start(); } } watch.stop(); if (log.isInfoEnabled()) { log.info("Resumed " + suspendedRouteServices.size() + " routes"); log.info("Apache Camel " + getVersion() + " (CamelContext: " + getName() + ") resumed in " + TimeUtils.printDuration(watch.taken())); } // and clear the list as they have been resumed suspendedRouteServices.clear(); EventHelper.notifyCamelContextResumed(this); } catch (Exception e) { EventHelper.notifyCamelContextResumeFailed(this, e); throw e; } }
public DefaultMessageHistory(String routeId, NamedNode node, Date timestamp) { this.routeId = routeId; this.node = node; this.nodeId = node.getId(); this.timestamp = timestamp; this.stopWatch = new StopWatch(); }
protected void waitForCompleteLatch() throws InterruptedException { if (latch == null) { fail("Should have a latch!"); } StopWatch watch = new StopWatch(); waitForCompleteLatch(resultWaitTime); long delta = watch.stop(); LOG.debug("Took {} millis to complete latch", delta); if (resultMinimumWaitTime > 0 && delta < resultMinimumWaitTime) { fail("Expected minimum " + resultMinimumWaitTime + " millis waiting on the result, but was faster with " + delta + " millis."); } }
public void testPrimitiveTypeConverter() throws Exception { StopWatch watch = new StopWatch(); for (int i = 0; i < 10000; i++) { int num = context.getTypeConverter().convertTo(int.class, "123"); assertEquals(123, num); } log.info("Time taken: " + watch.stop()); }
public void testTimerUsingStopWatch() throws Exception { MockEndpoint mock = getMockEndpoint("mock:result"); mock.expectedMinimumMessageCount(2); StopWatch watch = new StopWatch(); assertMockEndpointsSatisfied(); long interval = watch.stop(); LOG.trace("Should take approx 2000 milliseconds, was: {}", interval); assertTrue("Should take approx 2000 milliseconds, was: " + interval, interval >= 1700); }
public void testPropertyEditorTypeConverter() throws Exception { // test that converters a custom object (MyBean) to a String which causes // PropertyEditorTypeConverter to be used. And this test times how fast // this is. As we want to optimize PropertyEditorTypeConverter to be faster MyBean bean = new MyBean(); bean.setBar("Hello"); StopWatch watch = new StopWatch(); for (int i = 0; i < 500; i++) { String s = context.getTypeConverter().convertTo(String.class, bean); log.debug(s); assertNotNull(s); } log.info("Time taken: " + watch.stop()); }
public void testTypeConverter() throws Exception { // add as type converter Method method = TypeConverterConcurrencyIssueTest.class.getMethod("toMyCamelBean", String.class); assertNotNull(method); context.getTypeConverterRegistry().addTypeConverter(MyCamelBean.class, String.class, new StaticMethodTypeConverter(method)); ExecutorService pool = context.getExecutorServiceManager().newThreadPool(this, "test", 50, 50); final CountDownLatch latch = new CountDownLatch(size); StopWatch watch = new StopWatch(); for (int i = 0; i < size; i++) { pool.submit(new Runnable() { @Override public void run() { try { context.getTypeConverter().mandatoryConvertTo(MyCamelBean.class, "1;MyCamel"); latch.countDown(); } catch (NoTypeConversionAvailableException e) { // ignore, as the latch will not be decremented anymore so that the assert below // will fail after the one minute timeout anyway } } }); } assertTrue("The expected mandatory conversions failed!", latch.await(1, TimeUnit.MINUTES)); log.info("Took " + watch.stop() + " millis to convert " + size + " objects"); }
public void testRedeliveryErrorHandlerNoRedeliveryOnShutdown() throws Exception { getMockEndpoint("mock:foo").expectedMessageCount(1); template.sendBody("seda:foo", "Hello World"); assertMockEndpointsSatisfied(); // should not take long to stop the route StopWatch watch = new StopWatch(); context.stopRoute("foo"); watch.stop(); assertTrue("Should stop route faster, was " + watch.taken(), watch.taken() < 4000); }