001/** 002 * Licensed to the Apache Software Foundation (ASF) under one or more 003 * contributor license agreements. See the NOTICE file distributed with 004 * this work for additional information regarding copyright ownership. 005 * The ASF licenses this file to You under the Apache License, Version 2.0 006 * (the "License"); you may not use this file except in compliance with 007 * the License. You may obtain a copy of the License at 008 * 009 * http://www.apache.org/licenses/LICENSE-2.0 010 * 011 * Unless required by applicable law or agreed to in writing, software 012 * distributed under the License is distributed on an "AS IS" BASIS, 013 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 014 * See the License for the specific language governing permissions and 015 * limitations under the License. 016 */ 017package org.apache.camel.processor; 018 019import java.text.NumberFormat; 020import java.util.concurrent.ScheduledExecutorService; 021import java.util.concurrent.TimeUnit; 022import java.util.concurrent.atomic.AtomicInteger; 023 024import org.apache.camel.AsyncCallback; 025import org.apache.camel.AsyncProcessor; 026import org.apache.camel.CamelContext; 027import org.apache.camel.Exchange; 028import org.apache.camel.spi.IdAware; 029import org.apache.camel.support.ServiceSupport; 030import org.apache.camel.util.AsyncProcessorHelper; 031import org.apache.camel.util.CamelLogger; 032import org.apache.camel.util.ObjectHelper; 033import org.slf4j.Logger; 034import org.slf4j.LoggerFactory; 035 036/** 037 * A logger for logging message throughput. 038 * 039 * @version 040 */ 041public class ThroughputLogger extends ServiceSupport implements AsyncProcessor, IdAware { 042 private static final Logger LOG = LoggerFactory.getLogger(ThroughputLogger.class); 043 044 private String id; 045 private final AtomicInteger receivedCounter = new AtomicInteger(); 046 private NumberFormat numberFormat = NumberFormat.getNumberInstance(); 047 private long groupReceivedCount; 048 private boolean groupActiveOnly; 049 private Integer groupSize; 050 private long groupDelay = 1000; 051 private Long groupInterval; 052 private long startTime; 053 private long groupStartTime; 054 private String action = "Received"; 055 private CamelContext camelContext; 056 private ScheduledExecutorService logSchedulerService; 057 private CamelLogger log; 058 private String lastLogMessage; 059 private double rate; 060 private double average; 061 062 public ThroughputLogger(CamelLogger log) { 063 this.log = log; 064 } 065 066 public ThroughputLogger(CamelLogger log, Integer groupSize) { 067 this(log); 068 setGroupSize(groupSize); 069 } 070 071 public ThroughputLogger(CamelLogger log, CamelContext camelContext, Long groupInterval, Long groupDelay, Boolean groupActiveOnly) { 072 this(log); 073 this.camelContext = camelContext; 074 setGroupInterval(groupInterval); 075 setGroupActiveOnly(groupActiveOnly); 076 if (groupDelay != null) { 077 setGroupDelay(groupDelay); 078 } 079 } 080 081 public String getId() { 082 return id; 083 } 084 085 public void setId(String id) { 086 this.id = id; 087 } 088 089 public void process(Exchange exchange) throws Exception { 090 AsyncProcessorHelper.process(this, exchange); 091 } 092 093 public boolean process(Exchange exchange, AsyncCallback callback) { 094 if (startTime == 0) { 095 startTime = System.currentTimeMillis(); 096 } 097 int receivedCount = receivedCounter.incrementAndGet(); 098 099 //only process if groupSize is set...otherwise we're in groupInterval mode 100 if (groupSize != null) { 101 if (receivedCount % groupSize == 0) { 102 lastLogMessage = createLogMessage(exchange, receivedCount); 103 log.log(lastLogMessage); 104 } 105 } 106 107 callback.done(true); 108 return true; 109 } 110 111 public Integer getGroupSize() { 112 return groupSize; 113 } 114 115 public void setGroupSize(Integer groupSize) { 116 if (groupSize == null || groupSize <= 0) { 117 throw new IllegalArgumentException("groupSize must be positive, was: " + groupSize); 118 } 119 this.groupSize = groupSize; 120 } 121 122 public Long getGroupInterval() { 123 return groupInterval; 124 } 125 126 public void setGroupInterval(Long groupInterval) { 127 if (groupInterval == null || groupInterval <= 0) { 128 throw new IllegalArgumentException("groupInterval must be positive, was: " + groupInterval); 129 } 130 this.groupInterval = groupInterval; 131 } 132 133 public long getGroupDelay() { 134 return groupDelay; 135 } 136 137 public void setGroupDelay(long groupDelay) { 138 this.groupDelay = groupDelay; 139 } 140 141 public boolean getGroupActiveOnly() { 142 return groupActiveOnly; 143 } 144 145 private void setGroupActiveOnly(boolean groupActiveOnly) { 146 this.groupActiveOnly = groupActiveOnly; 147 } 148 149 public NumberFormat getNumberFormat() { 150 return numberFormat; 151 } 152 153 public void setNumberFormat(NumberFormat numberFormat) { 154 this.numberFormat = numberFormat; 155 } 156 157 public String getAction() { 158 return action; 159 } 160 161 public void setAction(String action) { 162 this.action = action; 163 } 164 165 public void reset() { 166 startTime = 0; 167 receivedCounter.set(0); 168 groupStartTime = 0; 169 groupReceivedCount = 0; 170 average = 0.0d; 171 rate = 0.0d; 172 lastLogMessage = null; 173 } 174 175 public double getRate() { 176 return rate; 177 } 178 179 public double getAverage() { 180 return average; 181 } 182 183 public int getReceivedCounter() { 184 return receivedCounter.get(); 185 } 186 187 public String getLastLogMessage() { 188 return lastLogMessage; 189 } 190 191 @Override 192 public void doStart() throws Exception { 193 // if an interval was specified, create a background thread 194 if (groupInterval != null) { 195 ObjectHelper.notNull(camelContext, "CamelContext", this); 196 197 logSchedulerService = camelContext.getExecutorServiceManager().newSingleThreadScheduledExecutor(this, "ThroughputLogger"); 198 Runnable scheduledLogTask = new ScheduledLogTask(); 199 LOG.info("Scheduling throughput log to run every {} millis.", groupInterval); 200 // must use fixed rate to have it trigger at every X interval 201 logSchedulerService.scheduleAtFixedRate(scheduledLogTask, groupDelay, groupInterval, TimeUnit.MILLISECONDS); 202 } 203 } 204 205 @Override 206 public void doStop() throws Exception { 207 if (logSchedulerService != null) { 208 camelContext.getExecutorServiceManager().shutdown(logSchedulerService); 209 logSchedulerService = null; 210 } 211 } 212 213 protected String createLogMessage(Exchange exchange, int receivedCount) { 214 long time = System.currentTimeMillis(); 215 if (groupStartTime == 0) { 216 groupStartTime = startTime; 217 } 218 219 rate = messagesPerSecond(groupSize, groupStartTime, time); 220 average = messagesPerSecond(receivedCount, startTime, time); 221 222 long duration = time - groupStartTime; 223 groupStartTime = time; 224 225 return getAction() + ": " + receivedCount + " messages so far. Last group took: " + duration 226 + " millis which is: " + numberFormat.format(rate) 227 + " messages per second. average: " + numberFormat.format(average); 228 } 229 230 /** 231 * Background task that logs throughput stats. 232 */ 233 private final class ScheduledLogTask implements Runnable { 234 235 public void run() { 236 // only run if CamelContext has been fully started 237 if (!camelContext.getStatus().isStarted()) { 238 LOG.trace("ThroughputLogger cannot start because CamelContext({}) has not been started yet", camelContext.getName()); 239 return; 240 } 241 242 createGroupIntervalLogMessage(); 243 } 244 } 245 246 protected void createGroupIntervalLogMessage() { 247 248 // this indicates that no messages have been received yet...don't log yet 249 if (startTime == 0) { 250 return; 251 } 252 253 int receivedCount = receivedCounter.get(); 254 255 // if configured, hide log messages when no new messages have been received 256 if (groupActiveOnly && receivedCount == groupReceivedCount) { 257 return; 258 } 259 260 long time = System.currentTimeMillis(); 261 if (groupStartTime == 0) { 262 groupStartTime = startTime; 263 } 264 265 long duration = time - groupStartTime; 266 long currentCount = receivedCount - groupReceivedCount; 267 rate = messagesPerSecond(currentCount, groupStartTime, time); 268 average = messagesPerSecond(receivedCount, startTime, time); 269 270 groupStartTime = time; 271 groupReceivedCount = receivedCount; 272 273 lastLogMessage = getAction() + ": " + currentCount + " new messages, with total " + receivedCount + " so far. Last group took: " + duration 274 + " millis which is: " + numberFormat.format(rate) 275 + " messages per second. average: " + numberFormat.format(average); 276 log.log(lastLogMessage); 277 } 278 279 protected double messagesPerSecond(long messageCount, long startTime, long endTime) { 280 // timeOneMessage = elapsed / messageCount 281 // messagePerSend = 1000 / timeOneMessage 282 double rate = messageCount * 1000.0; 283 rate /= endTime - startTime; 284 return rate; 285 } 286 287}