001: // $Id: LogTest.java 1932 2006-08-01 02:46:10Z twall $
002: // Copyright (c) Oculus Technologies Corporation, all rights reserved
003: // ----------------------------------------------------------------------------
004: package abbot;
005:
006: import java.io.ByteArrayOutputStream;
007: import java.io.PrintStream;
008: import junit.extensions.abbot.*;
009: import junit.framework.TestCase;
010:
011: /** Testing for the Log class.
012:
013: @author twall@users.sf.net
014: */
015:
016: public class LogTest extends TestCase {
017:
018: private String stackNest(int nest, int lines) {
019: if (nest <= 0)
020: return Log.getStack(lines);
021: return stackNest(nest - 1, lines);
022: }
023:
024: private String className() {
025: return getClass().getName();
026: }
027:
028: private ByteArrayOutputStream logContents;
029: private PrintStream original;
030:
031: protected void setUp() {
032: logContents = new ByteArrayOutputStream();
033: original = Log.getLog();
034: Log.setEchoToConsole(false);
035: Log.flush();
036: Log.setDestination(new PrintStream(logContents));
037: }
038:
039: protected void tearDown() {
040: logContents = null;
041: Log.flush();
042: Log.setDestination(original);
043: Log.setEchoToConsole(true);
044: }
045:
046: /** Verify that the stack dump is accurate. */
047: public void testStackLines() throws Exception {
048: String dump = stackNest(3, Log.FULL_STACK);
049: String atLine = "\\s*at " + className() + ".stackNest\\(.*\\)$";
050: assertTrue("Full stack trace mismatch: '" + dump + "'", dump
051: .matches("(?sm)\\s*" + className()
052: + ".stackNest\\(.*\\)$" + atLine + atLine
053: + atLine + "\\s*at " + className()
054: + ".testStackLines\\(.*\\)$.*"));
055: dump = stackNest(3, 1);
056: assertTrue("Stack trace mismatch, 1 line: '" + dump + "'", dump
057: .matches("^\\s*" + className() + ".stackNest.*$"));
058: dump = stackNest(3, 2);
059: assertTrue("Stack trace mismatch, 2 lines: '" + dump + "'",
060: dump.matches("(?sm)\\s*" + className()
061: + ".stackNest.*$" + atLine + ".*"));
062: dump = stackNest(3, 3);
063: assertTrue("Stack trace mismatch, 3 lines: '" + dump + "'",
064: dump.matches("(?sm)\\s*" + className()
065: + ".stackNest.*$" + atLine + atLine + ".*"));
066: }
067:
068: /** Verify we get a proper stack trace. */
069: public void testStackTrace() throws Exception {
070: String dump = stackNest(4, Log.FULL_STACK);
071: String atLine = "\\s*at " + className() + ".stackNest\\(.*\\)$";
072: // We need to check multiple lines...
073: assertTrue("Level 4 stack trace mismatch: '" + dump + "'", dump
074: .matches("(?sm)\\s*" + className()
075: + ".stackNest\\(.*\\)$" + atLine + atLine
076: + atLine + atLine + "\\s*at " + className()
077: + ".testStackTrace\\(.*\\)$.*"));
078: dump = stackNest(3, Log.FULL_STACK);
079: assertTrue("Level 3 stack trace mismatch: '" + dump + "'", dump
080: .matches("(?sm)\\s*" + className()
081: + ".stackNest\\(.*\\)$" + atLine + atLine
082: + atLine + "\\s*at " + className()
083: + ".testStackTrace\\(.*\\)$.*"));
084: dump = stackNest(2, Log.FULL_STACK);
085: assertTrue("Level 2 stack trace mismatch: '" + dump + "'", dump
086: .matches("(?sm)\\s*" + className()
087: + ".stackNest\\(.*\\)$" + atLine + atLine
088: + "\\s*at " + className()
089: + ".testStackTrace\\(.*\\)$.*"));
090: dump = stackNest(1, Log.FULL_STACK);
091: assertTrue("Level 1 stack trace mismatch: '" + dump + "'", dump
092: .matches("(?sm)\\s*" + className()
093: + ".stackNest\\(.*\\)$" + atLine + "\\s*at "
094: + className() + ".testStackTrace\\(.*\\)$.*"));
095: dump = stackNest(0, Log.FULL_STACK);
096: assertTrue("Level 0 stack trace mismatch: '" + dump + "'", dump
097: .matches("(?sm)\\s*" + className()
098: + ".stackNest\\(.*\\)$" + "\\s*at "
099: + className() + ".testStackTrace\\(.*\\)$.*"));
100: }
101:
102: /** Test class-from-string generation. */
103: public void testDebugEnabling() {
104: try {
105: try {
106: Class c = Class.forName(className());
107: assertEquals("Wrong class found by forName for "
108: + className(), LogTest.class, c);
109: Log.addDebugClass(LogTest.class);
110: assertTrue(
111: "Log class debugging not enabled after explicit enable",
112: Log.isClassDebugEnabled(LogTest.class));
113:
114: Log.removeDebugClass(LogTest.class.getName());
115: assertFalse(
116: "Log class debugging enabled after explicit disable",
117: Log.isClassDebugEnabled(LogTest.class));
118:
119: Log.addDebugClass(LogTest.class.getName(),
120: Log.FULL_STACK);
121: assertTrue("Log class debugging should be enabled", Log
122: .isClassDebugEnabled(LogTest.class));
123: assertEquals("Wrong log stack depth", Log.FULL_STACK,
124: Log.getClassStackDepth(LogTest.class.getName()));
125: } catch (ClassNotFoundException exc) {
126: fail("Can't derive class from " + className() + ": "
127: + exc);
128: }
129: } finally {
130: Log.removeDebugClass(LogTest.class);
131: }
132: }
133:
134: public void testSuppressUnenabledDebugOutput() {
135: Log.debug("A message");
136: Log.flush();
137: assertEquals("Expect no debug output", "", logContents
138: .toString());
139: }
140:
141: public void testEnableDebugOutput() {
142: String EXPECTED = "A message";
143: Log.addDebugClass(LogTest.class);
144: Log.debug(EXPECTED);
145: Log.flush();
146: try {
147: assertFalse("Missing debug output", "".equals(logContents
148: .toString()));
149: assertTrue("Incorrect debug output", logContents.toString()
150: .indexOf(EXPECTED) != -1);
151: } finally {
152: Log.removeDebugClass(LogTest.class);
153: }
154: }
155:
156: public void testSetDebugOutputDepth() {
157: Log.addDebugClass(LogTest.class.getName() + ":" + 2);
158: Log.debug("anything");
159: Log.flush();
160: try {
161: assertEquals("Expect two lines of stack trace: "
162: + logContents.toString(), 2, logContents.toString()
163: .split("\tat ").length);
164: } finally {
165: Log.removeDebugClass(LogTest.class);
166: }
167: }
168:
169: public void testWarnThrowable() {
170: try {
171: throw new RuntimeException("rte");
172: } catch (RuntimeException e) {
173: Log.warn(e);
174: Log.flush();
175: String output = logContents.toString();
176: assertFalse("No log output", "".equals(output));
177: assertTrue("Missng exception stack trace: " + output,
178: output.indexOf("Exception thrown at") != -1);
179: assertTrue("Missing 'caught at': " + output, output
180: .indexOf("caught at") != -1);
181: assertTrue("Missing default message: " + output, output
182: .indexOf(e.toString()) != -1);
183: }
184: }
185:
186: public void testLogThrowable() {
187: try {
188: throw new RuntimeException("logged exception");
189: } catch (RuntimeException e) {
190: Log.log("Exception thrown", e);
191: Log.flush();
192: String output = logContents.toString();
193: assertFalse("No log output", "".equals(output));
194: assertTrue("Missng exception stack trace: " + output,
195: output.indexOf("Exception thrown at") != -1);
196: assertTrue("Missing 'caught at': " + output, output
197: .indexOf("caught at") != -1);
198: assertTrue("Missing default message: " + output, output
199: .indexOf(e.toString()) != -1);
200: }
201: }
202:
203: public void testDebugThrowable() {
204: Log.addDebugClass(LogTest.class);
205: try {
206: throw new RuntimeException("rte");
207: } catch (RuntimeException e) {
208: Log.debug("debug message", e);
209: Log.flush();
210: String output = logContents.toString();
211: assertFalse("No log output", "".equals(output));
212: assertTrue("Missng exception stack trace: " + output,
213: output.indexOf("Exception thrown at") != -1);
214: assertTrue("Missing 'caught at': " + output, output
215: .indexOf("caught at") != -1);
216: assertTrue("Missing default message: " + output, output
217: .indexOf(e.toString()) != -1);
218: } finally {
219: Log.removeDebugClass(LogTest.class);
220: }
221: }
222:
223: public void testLogRepeatedMessages() {
224: final String MESSAGE = "message";
225: Log.warn(MESSAGE);
226: Log.warn(MESSAGE);
227: Log.warn(MESSAGE);
228: Log.warn("something else");
229: Log.flush();
230: String output = logContents.toString();
231: assertTrue("Should indicate a message repeat count: " + output,
232: output.indexOf("repeated") != -1);
233: }
234:
235: // 39 ms for 1000 invocations
236: public void testDebugSpeedWithNoDebugEnabled() {
237: final int REPEAT = 1000;
238: Timer timer = new Timer();
239: for (int i = 0; i < REPEAT; i++) {
240: }
241: long base = timer.elapsed() + 1;
242:
243: timer.reset();
244: for (int i = 0; i < REPEAT; i++) {
245: Log.debug("i=" + i);
246: }
247: long debugged = timer.elapsed();
248: long delta = debugged - base;
249: int MAX_US_PER_DEBUG = 500;
250: assertTrue("Expected debug overhead exceeded: " + delta * 1000
251: / REPEAT + "us >= " + MAX_US_PER_DEBUG + "us", delta
252: * 1000 / REPEAT < MAX_US_PER_DEBUG);
253: }
254:
255: public void testLogSpeed() {
256: final int REPEAT = 1000;
257: Timer timer = new Timer();
258: for (int i = 0; i < REPEAT; i++) {
259: }
260: long base = timer.elapsed() + 1;
261:
262: timer.reset();
263: for (int i = 0; i < REPEAT; i++) {
264: Log.log("i=" + i);
265: }
266: long debugged = timer.elapsed();
267: long delta = debugged - base;
268: final int MAX_US_PER_DEBUG = 500;
269: assertTrue("Expected log overhead exceeded: " + delta * 1000
270: / REPEAT + " >= " + MAX_US_PER_DEBUG + "us", delta
271: * 1000 / REPEAT < MAX_US_PER_DEBUG);
272:
273: timer.reset();
274: Log.flush();
275: long elapsed = timer.elapsed();
276:
277: final int MAX_US_PER_MSG = 500;
278: assertTrue("Too long flushing " + REPEAT + " log messages: "
279: + elapsed + "ms",
280: elapsed * 1000 / REPEAT < MAX_US_PER_MSG);
281: }
282:
283: // flush: ~500ms for 1000 messages
284: public void testDebugMemoryUse() {
285: final int REPEAT = 1000;
286: long delta = 0;
287: long flush = 0;
288: {
289: Log.addDebugClass(LogTest.class);
290: long before = SizeOf.getMemoryUse();
291: for (int i = 0; i < REPEAT; i++) {
292: Log.debug("i=" + i);
293: }
294: Timer timer = new Timer();
295: Log.flush();
296: flush = timer.elapsed();
297: delta = SizeOf.getMemoryUse() - before;
298: Log.removeDebugClass(LogTest.class);
299: }
300: System.out.println("Memory increase: " + delta / 1024 + "Kb");
301: System.out.println("Flush time: " + flush + "ms for " + REPEAT
302: + " msgs");
303: }
304:
305: /**
306: * Run the main suite of this test case.
307: */
308: public static void main(String[] args) {
309: TestHelper.runTests(args, LogTest.class);
310: }
311: }
|