In order to deploy a scalable application, it is necessary to know how the application behaves with varying number of users. I am about to release another web application at work so I have been profiling and load testing it. I wrote a blog entry a year ago on Load and Functional Testing with Selenium and Grinder. Today, I am showing somewhat simpler things that can be done on J2EE application to keep track of its health.
Data Collector
Though, when working for big companies, often we used commercial software such as complex event processor or messaging middleware to keep track of all kind of alerts and events. But here I am showing a simple class that uses LRU based map to keep track of profile data:
1 import java.lang.management.ManagementFactory;
2 import java.util.ArrayList;
3 import java.util.Collections;
4 import java.util.Date;
5 import java.util.List;
6
7 import com.amazon.otb.cache.CacheMap;
8
9 /**
10 * Profile DataCollector used to store profiling data.
11 */
12 public class ProfileDataCollector {
13 private static ProfileDataCollector instance = new ProfileDataCollector();
14 private CacheMap<String, Object> map;
15 private ProfileDataCollector() {
16 map = new CacheMap<String, Object>(1000, 300, null);
17 map.put("ProfileStarted", new Date());
18 }
19
20 public static ProfileDataCollector getInstance() {
21 return instance;
22 }
23
24 public void add(String name, Object value) {
25 map.put(name, value);
26 }
27 public long increment(String name) {
28 Long number = (Long) map.get(name);
29 if (number == null) {
30 number = new Long(1);
31 } else {
32 number = new Long(number.longValue()+1);
33 }
34 add(name, number);
35 return number.longValue();
36 }
37
38 public long decrement(String name) {
39 Long number = (Long) map.get(name);
40 if (number == null) {
41 number = new Long(0);
42 } else {
43 number = new Long(number.longValue()-1);
44 }
45 add(name, number);
46 return number.longValue();
47 }
48
49 public long sum(String name, long total) {
50 Long number = (Long) map.get(name);
51 if (number == null) {
52 number = new Long(total);
53 } else {
54 number = new Long(number.longValue()+total);
55 }
56 add(name, number);
57 return number.longValue();
58 }
59
60
61 public long average(String name, long elapsed) {
62 long number = increment(name + "_times");
63 long sum = sum(name + "_total", elapsed);
64 long average = sum / number;
65 add(name + "_average", average);
66 return average;
67 }
68
69 public void lapse(String name) {
70 add(name, new Long(System.currentTimeMillis()));
71 }
72
73 public long elapsed(String name) {
74 Long started = (Long) map.get(name);
75 if (started != null) {
76 long time = System.currentTimeMillis() - started.longValue();
77 return average(name, time);
78 } else {
79 return -1;
80 }
81 }
82
83 public String[][] getProfileData(String keyPrefix) {
84 List<String> keys = new ArrayList<String>(map.keySet());
85 Collections.sort(keys);
86 String[][] data = new String[keys.size()+5][];
87 Runtime runtime = Runtime.getRuntime();
88 Date started = (Date) map.get("ProfileStarted");
89 long elapsed = (System.currentTimeMillis() - started.getTime()) / 1000;
90 int n = 0;
91 double systemLoad = ManagementFactory.getOperatingSystemMXBean().getSystemLoadAverage();
92 data[n++] = new String[] {keyPrefix + "TotalMemoryInMegs", String.valueOf(runtime.totalMemory()/1024/1024)};
93 data[n++] = new String[] {keyPrefix + "FreeMemoryInMegs", String.valueOf(runtime.freeMemory()/1024/1024)};
94 data[n++] = new String[] {keyPrefix + "ActiveThreads", String.valueOf(Thread.activeCount())};
95 data[n++] = new String[] {keyPrefix + "ServerRunningInSecs", String.valueOf(elapsed)};
96 data[n++] = new String[] {keyPrefix + "SystemLoadAverage", String.valueOf(systemLoad)};
97
98 for (String key : keys) {
99 CacheMap.TimedValue tv = map.getTimedValue(key);
100 data[n++] = new String[] {keyPrefix + key, tv.value + " @" + new Date(tv.time)};
101 }
102 return data;
103 }
104 }
105
106
Where CacheMap is a simple LRU based map, i.e.,
1 import java.util.ArrayList;
2 import java.util.Collection;
3 import java.util.Collections;
4 import java.util.concurrent.Callable;
5 import java.util.concurrent.Executors;
6 import java.util.concurrent.ExecutorService;
7 import java.util.concurrent.locks.ReentrantLock;
8 import java.util.HashMap;
9 import java.util.HashSet;
10 import java.util.Iterator;
11 import java.util.LinkedHashMap;
12 import java.util.List;
13 import java.util.Map;
14 import java.util.Set;
15 import org.apache.log4j.Logger;
16
17
18
19 /**
20 * CacheMap - provides lightweight caching based on LRU size and timeout
21 * and asynchronous reloads.
22 *
23 */
24 public class CacheMap<K, V> implements Map<K, V> {
25 private final static Logger log = Logger.getLogger(CacheMap.class);
26 private final static int MAX_THREADS = 10; // for all cache items across VM
27 private final static int MAX_ITEMS = 1000; // for all cache items across VM
28 private final static ExecutorService executorService = Executors.newFixedThreadPool(MAX_THREADS);
29 private final static boolean lockSync = false;
30
31 public class TimedValue<V> {
32 public final long time;
33 public V value;
34 private boolean updating = false;
35 TimedValue(V value) {
36 this.value = value;
37 this.time = System.currentTimeMillis();
38 }
39 public boolean isExpired(long timeoutInSecs) {
40 long timeDiff = System.currentTimeMillis() - time;
41 return timeDiff > timeoutInSecs * 1000;
42 }
43 public synchronized boolean markUpdating() {
44 if (!this.updating) {
45 this.updating = true;
46 return true;
47 }
48 return false;
49 }
50
51 @Override
52 public String toString() {
53 long timeDiff = System.currentTimeMillis() - time;
54 return "TimedValue(" + value + ") expiring in " + timeDiff;
55 }
56 }
57
58
59 class FixedSizeLruLinkedHashMap<K, V> extends LinkedHashMap<K, V> {
60 private final int maxSize;
61
62 public FixedSizeLruLinkedHashMap(int initialCapacity, float loadFactor, int maxSize) {
63 super(initialCapacity, loadFactor, true);
64 this.maxSize = maxSize;
65 }
66
67 @Override
68 protected boolean removeEldestEntry(Map.Entry<K, V> eldest) {
69 return size() > maxSize;
70 }
71 }
72
73 private final Cacheable classCacheable;
74 private final Map<K, TimedValue<V>> map;
75 private final Map<Object, ReentrantLock> locks;
76 private CacheLoader<K, V> defaultCacheLoader;
77 private final long expireEntriesPeriod;
78 private long lastexpireEntriesTime;
79
80
81 public CacheMap(Cacheable cacheable) {
82 this(cacheable, null, 5);
83 }
84
85 public CacheMap(int timeoutInSecs, CacheLoader<K,V> defaultCacheLoader) {
86 this(0, timeoutInSecs, defaultCacheLoader);
87 }
88
89 public CacheMap(int maxCapacity, int timeoutInSecs, CacheLoader<K,V> defaultCacheLoader) {
90 this(new CacheableImpl(maxCapacity, timeoutInSecs, true, false), defaultCacheLoader, 5);
91 }
92
93 public CacheMap(Cacheable cacheable, CacheLoader<K,V> defaultCacheLoader, long expireEntriesPeriodInSecs) {
94 this.classCacheable = cacheable;
95 this.defaultCacheLoader = defaultCacheLoader;
96 this.expireEntriesPeriod = expireEntriesPeriodInSecs * 1000;
97 int maxCapacity = cacheable != null && cacheable.maxCapacity() > 0 && cacheable.maxCapacity() < MAX_ITEMS ? cacheable.maxCapacity() : MAX_ITEMS;
98 this.map = Collections.synchronizedMap(new FixedSizeLruLinkedHashMap<K, TimedValue<V>>(maxCapacity/ 10, 0.75f, maxCapacity));
99 this.locks = new HashMap<Object, ReentrantLock>();
100 }
101
102 public void setDefaultCacheLoader(CacheLoader<K,V> defaultCacheLoader) {
103 this.defaultCacheLoader = defaultCacheLoader;
104 }
105
106 public int size() {
107 return map.size();
108 }
109
110 public boolean isEmpty() {
111 return map.isEmpty();
112 }
113
114 public boolean containsKey(Object key) {
115 return map.containsKey(key);
116 }
117
118 public boolean containsValue(Object value) {
119 return map.containsValue(value);
120 }
121
122 public V put(K key, V value) {
123 TimedValue<V> old = map.put(key, new TimedValue<V>(value));
124 if (old != null) {
125 return old.value;
126 } else {
127 return null;
128 }
129 }
130
131 public V remove(Object key) {
132 TimedValue<V> old = map.remove(key);
133 if (old != null) {
134 return old.value;
135 } else {
136 return null;
137 }
138 }
139
140
141 public void putAll(Map<? extends K, ? extends V> m) {
142 for (Entry<? extends K, ? extends V> e : m.entrySet()) {
143 put(e.getKey(), e.getValue());
144 }
145 }
146
147
148 public void clear() {
149 map.clear();
150 }
151
152
153 public Set<K> keySet() {
154 return map.keySet();
155 }
156
157
158 public Collection<V> values() {
159 List<V> list = new ArrayList<V>(map.size());
160 for (TimedValue<V> e : map.values()) {
161 list.add(e.value);
162 }
163 return list;
164 }
165
166 public Set<Map.Entry<K,V>> entrySet() {
167 Set<Map.Entry<K,V>> set = new HashSet<Entry<K,V>>();
168 for (final Map.Entry<K, TimedValue<V>> e : map.entrySet()) {
169 set.add(new Map.Entry<K,V>() {
170 public K getKey() {
171 return e.getKey();
172 }
173 public V getValue() {
174 return e.getValue().value;
175 }
176 public V setValue(V value) {
177 TimedValue<V> old = e.getValue();
178 e.getValue().value = value;
179 if (old != null) {
180 return old.value;
181 } else {
182 return null;
183 }
184 }
185 });
186 }
187 return set;
188 }
189
190 public TimedValue<V> getTimedValue(Object key) {
191 return this.map.get(key);
192 }
193
194 public V get(Object key) {
195 V value = null;
196 if (classCacheable != null && defaultCacheLoader != null) {
197 value = get((K)key, classCacheable, defaultCacheLoader, null);
198 } else {
199 TimedValue<V> item = this.map.get(key);
200 if (item == null) {
201 value = null;
202 } else {
203 value = item.value;
204 }
205 }
206 return value;
207 }
208
209 public V get(K key, Cacheable cacheable, CacheLoader<K, V> loader, boolean[] wasCached) {
210 TimedValue<V> item = this.map.get(key);
211 V value = null;
212 ReentrantLock lock = null;
213
214 //expire old entries
215 if (System.currentTimeMillis() - this.lastexpireEntriesTime > this.expireEntriesPeriod) {
216 expireEntries(cacheable);
217 }
218
219
220 try {
221 synchronized(this) {
222 if (lockSync && cacheable.synchronizeAccess()) {
223 lock = lock(key);
224 }
225 }
226 //
227 if (item == null) {
228 // load initial value
229 value = reloadSynchronously(key, loader);
230
231 } else {
232
233 value = item.value;
234
235 boolean cached = true;
236 if (cacheable.timeoutInSecs() > 0 && item.isExpired(cacheable.timeoutInSecs())) {
237
238 if (! cacheable.canReloadAsynchronously()) {
239 // ---> reload it now - don't used cached value
240 cached = false;
241 log.debug("Reloading expired entry synchronously " + key);
242 value = reloadSynchronously(key, loader);
243 } else if (item.markUpdating()) {
244 log.debug("Reloading expired entry asynchronously " + key);
245 reloadAsynchronously(key, loader);
246 }
247 }
248 if (wasCached != null) {
249 wasCached[0] = cached;
250 }
251 }
252 } finally {
253 if (lock != null) {
254 lock.unlock();
255 locks.remove(key);
256 //log.debug("Unlocking " + key);
257 }
258 }
259 return value;
260 }
261
262
263 @Override
264 public String toString() {
265 return super.toString() + "--" + map;
266 }
267
268
269 private ReentrantLock lock(Object key) {
270 ReentrantLock lock = null;
271 synchronized (locks) {
272 lock = locks.get(key);
273 if (lock == null) {
274 lock = new ReentrantLock();
275 locks.put(key, lock);
276 }
277 }
278 //log.debug("Locking " + key);
279 lock.lock();
280 return lock;
281 }
282
283 private V reloadSynchronously(final K key, final CacheLoader<K, V> loader) {
284 try {
285 V value = loader.loadCache(key);
286 put(key, value);
287 //log.info("------reloadSynchronously loaded key " + key + ", cache size: " + this.size() + " -- " + System.identityHashCode(map));
288 return value;
289 } catch (Exception e) {
290 log.error("Failed to load " + key, e);
291 throw new RuntimeException("Failed to load " + key + " for " + classCacheable, e);
292 }
293 }
294
295
296 private void reloadAsynchronously(final K key, final CacheLoader<K,V> loader) {
297 if (log.isDebugEnabled()) {
298 log.debug("requesting reload for "+key.toString()+": "+Thread.currentThread().getName());
299 }
300 executorService.submit(new Callable<V>() {
301 public V call() throws Exception {
302 if (log.isDebugEnabled()) {
303 log.debug("reloading for "+key.toString()+": "+Thread.currentThread().getName());
304 }
305 return reloadSynchronously(key, loader);
306 }
307 });
308 }
309
310 private void expireEntries(final Cacheable cacheable) {
311 Iterator<TimedValue<V>> it = new ArrayList<TimedValue<V>>(this.map.values()).iterator();
312 while (it.hasNext()) {
313 TimedValue<V> value = it.next();
314 if (cacheable.timeoutInSecs() > 0 && value.isExpired(cacheable.timeoutInSecs())) {
315 it.remove();
316 }
317 }
318 this.lastexpireEntriesTime = System.currentTimeMillis();
319 }
320 }
321
322
Session Tracking
I added a listener to keep track of active users/sessions (who accessed the system in last 5 mintutes) as opposed to all sessions which may take 30 minutes or more to expire.
1 public class SessionLogger implements HttpSessionListener, HttpSessionBindingListener {
2 private transient static Log log = LogFactory.getLog(SessionLogger.class);
3 private static int sessionCount;
4 private static final String OBJECTS_IN_SESSION_COUNT = "Objects in Session";
5 private static final long ACTIVE_THRESHOLD = 5 * 60 * 1000; // 5 minutes
6 private static Map<HttpSession, HttpSession> activeSessions = Collections.synchronizedMap(new HashMap<HttpSession, HttpSession>());
7 private static Map<HttpSession, String> allUsers = Collections.synchronizedMap(new HashMap<HttpSession, String>());
8 private static Map<HttpSession, String> activeUsers = Collections.synchronizedMap(new HashMap<HttpSession, String>());
9
10 private static void checkActiveSessions() {
11 long now = System.currentTimeMillis();
12 Iterator<HttpSession> it = activeSessions.keySet().iterator();
13 activeUsers.clear();
14 while (it.hasNext()) {
15 HttpSession session = it.next();
16 if (now-session.getLastAccessedTime() > ACTIVE_THRESHOLD) {
17 it.remove();
18 } else {
19 activeUsers.put(session,(String) session.getAttribute(UserUtil.OTB_REAL_USER));
20 }
21 }
22 ProfileDataCollector.getInstance().add("TotalSessions", String.valueOf(sessionCount));
23 ProfileDataCollector.getInstance().add("ActiveSessions", String.valueOf(activeSessions.size()));
24 ProfileDataCollector.getInstance().add("ActiveUsers", activeUsers.values().toString());
25 ProfileDataCollector.getInstance().add("AllUsers", allUsers.values().toString());
26 }
27
28 public void sessionCreated(HttpSessionEvent se) {
29 HttpSession session = se.getSession();
30 synchronized (this) {
31 sessionCount++;
32 activeSessions.put(session, session);
33 activeSessions.put(session, session);
34 checkActiveSessions();
35 }
36 allUsers.put(session, (String) session.getAttribute(UserUtil.OTB_REAL_USER));
37 }
38
39 public void sessionDestroyed(HttpSessionEvent se) {
40 HttpSession session = se.getSession();
41 allUsers.remove(session);
42 synchronized (this) {
43 sessionCount--;
44 activeSessions.remove(session);
45 checkActiveSessions();
46 }
47 }
48
49 public void valueBound(HttpSessionBindingEvent event) {
50 String username = (String) event.getSession().getAttribute(UserUtil.OTB_REAL_USER);
51 Integer old = (Integer) event.getSession().getAttribute(OBJECTS_IN_SESSION_COUNT);
52 if (old == null) {
53 old = new Integer(0);
54 }
55 Integer count = new Integer(old.intValue()+1);
56 event.getSession().setAttribute(OBJECTS_IN_SESSION_COUNT, count);
57 ProfileDataCollector.getInstance().add("TotalSessionValues", String.valueOf(count));
58 }
59
60 public void valueUnbound(HttpSessionBindingEvent event) {
61 String username = (String) event.getSession().getAttribute(UserUtil.OTB_REAL_USER);
62 Integer old = (Integer) event.getSession().getAttribute(OBJECTS_IN_SESSION_COUNT);
63 if (old == null) {
64 old = new Integer(0);
65 }
66 Integer count = new Integer(old.intValue()-1);
67 event.getSession().setAttribute(OBJECTS_IN_SESSION_COUNT, count);
68 ProfileDataCollector.getInstance().add("TotalSessionValues", String.valueOf(count));
69 }
70 }
71
Publishing profiling data
I then added code that needs to be profiled. Though, I have used AspectJ in past for this kind of work, but for now I am just adding this code where needed, e.g.
1 try {
2 ProfileDataCollector.getInstance().increment("ActiveSearches");
3 ProfileDataCollector.getInstance().lapse("SearchLapse");
4 ...
5
6 } finally {
7 ProfileDataCollector.getInstance()..increment("TotalSearches");
8 ProfileDataCollector.getInstance()..decrement("ActiveSearches");
9 ProfileDataCollector.getInstance()..elapsed("SearchLapse");
10 }
Viewing Profile Data
Finally, I added a servlet to return profiling data with AJAX call, e.g.
1 import java.io.IOException;
2
3 import javax.servlet.ServletException;
4 import javax.servlet.http.HttpServlet;
5 import javax.servlet.http.HttpServletRequest;
6 import javax.servlet.http.HttpServletResponse;
7 public class ProfileServlet extends HttpServlet {
8 protected void doPost(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
9 response.setContentType("text/plain");
10 String format = request.getParameter("format");
11 if ("line".equals(format)) {
12 response.getWriter().println(getProfileLine());
13 } else if ("json".equals(format)) {
14 response.getWriter().println(getProfileJson());
15 } else {
16 response.getWriter().println(getProfileTable());
17 }
18 }
19
20 protected void doGet(HttpServletRequest req, HttpServletResponse rsp) throws ServletException, IOException {
21 doPost(req, rsp);
22 }
23
24
25 public static String[][] getProfileData() {
26 return ProfileDataCollector.getInstance().getProfileData("");
27 }
28
29 public static String getProfileLine() {
30 StringBuilder sb = new StringBuilder();
31 String[][] data = getProfileData();
32 for (String[] param: data) {
33 sb.append(param[0] + "=" + param[1]);
34 }
35 return sb.toString();
36 }
37
38 public static String getProfileTable() {
39 StringBuilder sb = new StringBuilder("<table width='100%' border='2'>");
40 String[][] data = getProfileData();
41 sb.append("<tr>");
42 for (String[] param: data) {
43 sb.append("<th>" + param[0] + "</th>");
44 }
45 sb.append("</tr>");
46 sb.append("<tr>");
47 for (String[] param: data) {
48 sb.append("<td>" + param[1] + "</td>");
49 }
50 sb.append("</tr>");
51 sb.append("</table>");
52 return sb.toString();
53 }
54
55 public static String getProfileJson() {
56 StringBuilder sb = newJsonString();
57 String[][] data = getProfileData();
58 for (String[] param: data) {
59 appendJsonString(sb, param[0], param[1]);
60 }
61 return endJsonString(sb);
62 }
63
64
65 protected static StringBuilder newJsonString() {
66 return new StringBuilder('[');
67 }
68
69 protected static void appendJsonString(StringBuilder sb, String name, String id) {
70 if (sb.length() > 1) {
71 sb.append(',');
72 }
73 sb.append("{ name:'").append(name.replace("'", "\'")).append("', id:'").append(id.replace("'", "\'")).append(
74 "' }");
75 }
76
77 protected static String endJsonString(StringBuilder sb) {
78 sb.append(']');
79 return sb.toString();
80 }
81
82 protected static void addJsonProperty(StringBuilder sb, String name, String value) {
83 sb.append(""" + name + """);
84 sb.append(":");
85 sb.append(""" + value + """);
86 }
87
88 protected static void startJsonObj(StringBuilder sb) {
89 sb.append("{");
90
91 }
92
93 protected static void addNewJsonProperty(StringBuilder sb) {
94 sb.append(",");
95
96 }
97
98 protected static void endJsonObj(StringBuilder sb) {
99 sb.append("}");
100
101 }
102 }
103
And then a JSP to show the results using AJAX calls with Prototype library:
<script src="/otb-static/scriptaculous/prototype.js" type="text/javascript"></script>
<script>
var updater = null;
function initAjax() {
updater = new Ajax.PeriodicalUpdater('profile_div', '/profile?format=table', {
method: 'get',
insertion: Insertion.Top,
frequency: 15,
decay: 2
});
}
function startRequest() {
updater.start();
}
function stopRequest() {
updater.stop();
}
</script>
</head>
<body onLoad="initAjax(), startRequest()">
<ul id="profile_div">
</ul>
Testing
I then wrote a unit test to call various actions of the web application, I am going to use my old pal Grinder to do some real load testing and monitor the health of the server. I am not showing the test here, because it’s very application specific.
