View Javadoc

1   package org.e2etrace.trace;
2   
3   /*
4    * Copyright 2006 Gunther Popp
5    *
6    * Licensed under the Apache License, Version 2.0 (the "License");
7    * you may not use this file except in compliance with the License.
8    * You may obtain a copy of the License at
9    *
10   *      http://www.apache.org/licenses/LICENSE-2.0
11   *
12   * Unless required by applicable law or agreed to in writing, software
13   * distributed under the License is distributed on an "AS IS" BASIS,
14   * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15   * See the License for the specific language governing permissions and
16   * limitations under the License.
17   */
18  
19  import java.io.IOException;
20  import java.io.StringWriter;
21  
22  import org.e2etrace.formatter.ITraceFormatter;
23  import org.e2etrace.formatter.PlainTextTraceFormatter;
24  import org.e2etrace.trace.DefaultTraceSession;
25  import org.e2etrace.trace.DefaultTraceStepFactory;
26  import org.e2etrace.trace.ITraceStep;
27  import org.e2etrace.trace.MethodTraceStepId;
28  import org.e2etrace.trace.SimpleTraceStepId;
29  
30  import junit.framework.TestCase;
31  
32  /**
33   * JUnit testcase for {@link org.e2etrace.trace.DefaultTraceStep}
34   *
35   * The test uses {@link org.e2etrace.trace.MockTimer} instead of real timers.
36   *
37   * @author Gunther Popp
38   *
39   */
40  public class DefaultTraceSessionTest extends TestCase {
41  
42    public static void main(String[] args) {
43      junit.textui.TestRunner.run(DefaultTraceSessionTest.class);
44    }
45  
46    /**
47     * OK: Measure duration between enterStep and leaveStep
48     *
49     * @throws InterruptedException
50     * @throws IOException
51     */
52    public void testMeasureDuration() throws InterruptedException, IOException {
53      DefaultTraceSession ts;
54      ITraceStep step;
55  
56      ts = new DefaultTraceSession("testMeasureDuration", new DefaultTraceStepFactory(
57          new MockTimerFactory(new long[] { 40, 20 })));
58  
59      ts.enterStep("1");
60      ts.enterStep("2");
61      ts.leaveStep("2");
62      ts.leaveStep("1");
63  
64      // Verify that the duration of the Trace Session matches
65      // the simulated
66      // execution times
67      assertEquals(40, ts.getDuration());
68  
69      // The Trace Session serves only as anchor and doesnt measure any
70      // execution time. Hence, the accumulated duration of sts and
71      // it´s root step must be identical
72      step = ts.getRootStep();
73  
74      assertEquals(ts.getDuration(), step.getDuration());
75  
76      // Verify the isolated duration of the Trace Step "1"
77      step = step.getChildren()[0];
78      assertEquals(20, step.getIsolatedDuration());
79  
80    }
81  
82    /**
83     * OK: Omit leaveStep on all children
84     */
85    public void testOmitLeaveStep() {
86      DefaultTraceSession ts;
87      ITraceStep step;
88  
89      ts = new DefaultTraceSession("testOmitLeaveStep", new DefaultTraceStepFactory(
90          new MockTimerFactory(new long[] { 110, 70, 20 })));
91  
92      ts.enterStep("1");
93      ts.enterStep("2");
94      ts.enterStep("3");
95  
96      // Leave only Step 1 (it is expected, that all children of 1 are left
97      // automatically)
98      ts.leaveStep("1");
99  
100     assertEquals(110, ts.getDuration());
101 
102     step = ts.getRootStep().getChildren()[0];
103     assertEquals(40, step.getIsolatedDuration());
104 
105     step = step.getChildren()[0];
106     assertEquals(50, step.getIsolatedDuration());
107 
108     step = step.getChildren()[0];
109     assertEquals(20, step.getIsolatedDuration());
110   }
111 
112   /**
113    * Tests the session using a trace configuration with disabled tracing.
114    * <p>
115    */
116   public void testSwitchOffTracing() {
117     DefaultTraceSession ts;
118     MockTraceConfig tc;
119 
120     tc = new MockTraceConfig();
121     tc.setTraceEnabled(false);
122 
123     ts = new DefaultTraceSession("testUsingConfig", new DefaultTraceStepFactory(
124         new MockTimerFactory(new long[] { 40, 20 })));
125     ts.setConfig(tc);
126 
127     ts.enterStep("1");
128     ts.enterStep("2");
129     ts.leaveStep("2");
130     ts.leaveStep("1");
131 
132     // No trace data has been collected by the sessiono
133     assertEquals(0, ts.getDuration());
134 
135     // Verify, that no children have been added to the session
136     assertEquals(0, ts.getRootStep().getChildren().length);
137 
138   }
139 
140   /**
141    * Tests the session using a trace configuration with disabled tracing for
142    * some trace ids.
143    * <p>
144    */
145   public void testSwitchOffIds() {
146     DefaultTraceSession ts;
147     ITraceStep step;
148     MockTraceConfig tc;
149 
150     // Switch off "upper level" trace step
151     // -----------------------------------------
152     tc = new MockTraceConfig();
153     tc.setTraceEnabledForId(new SimpleTraceStepId("1"), false);
154 
155     ts = new DefaultTraceSession("testUsingConfig", new DefaultTraceStepFactory(
156         new MockTimerFactory(new long[] { 60, 20 })));
157     ts.setConfig(tc);
158 
159     ts.enterStep("1");
160     ts.enterStep("2");
161     ts.enterStep("3");
162     ts.leaveStep("3");
163     ts.leaveStep("2");
164     ts.leaveStep("1");
165 
166     // printTraceTree(ts);
167 
168     // Verify, that only step 2 has been added to the session (this step
169     // will receive the first
170     // execution time specified for the MockTimer).
171     assertEquals(1, ts.getRootStep().getChildren().length);
172     assertEquals(60, ts.getDuration());
173 
174     step = ts.getRootStep().getChildren()[0];
175     assertEquals("2", step.getId().asString());
176     assertEquals(40, step.getIsolatedDuration());
177     assertEquals(ts.getRootStep(), step.getParent());
178 
179     // Switch off "lower level" trace step
180     // -----------------------------------------
181     tc = new MockTraceConfig();
182     tc.setTraceEnabledForId(new SimpleTraceStepId("2"), false);
183 
184     ts = new DefaultTraceSession("testUsingConfig", new DefaultTraceStepFactory(
185         new MockTimerFactory(new long[] { 60, 20 })));
186     ts.setConfig(tc);
187 
188     ts.enterStep("1");
189     ts.enterStep("2");
190     ts.enterStep("3");
191     ts.leaveStep("3");
192     ts.leaveStep("2");
193     ts.leaveStep("1");
194 
195     // printTraceTree(ts);
196 
197     // Verify, that only step 1 has been added to the session (this step
198     // will receive the first
199     // execution time specified for the MockTimer).
200     assertEquals(1, ts.getRootStep().getChildren().length);
201     assertEquals(60, ts.getDuration());
202 
203     step = ts.getRootStep().getChildren()[0];
204     assertEquals("1", step.getId().asString());
205     assertEquals(40, step.getIsolatedDuration());
206     assertEquals(ts.getRootStep(), step.getParent());
207     assertEquals(1, step.getChildren().length);
208 
209   }
210 
211   /**
212    * Test-case: Check getDuration() after children are added manually to a trace
213    * step.
214    * <p>
215    *
216    * This didn´t work initially for the multithreaded test-app, where each of
217    * the parallel threads is added manually to the trace session of the client
218    * application.
219    * <p>
220    */
221   public void testMeasureAfterAddChildren() {
222     DefaultTraceSession ts1, ts2;
223 
224     // OK: Add children to root step ------------------------------
225 
226     ts1 = new DefaultTraceSession("testMeasureAfterAddChildren-1",
227         new DefaultTraceStepFactory(new MockTimerFactory(new long[] { 40, 20 })));
228 
229     ts1.enterStep("1");
230     ts1.enterStep("2");
231     ts1.leaveStep("2");
232     ts1.leaveStep("1");
233 
234     ts2 = new DefaultTraceSession("testMeasureAfterAddChildren-2",
235         new DefaultTraceStepFactory(new MockTimerFactory(new long[] { 40, 20 })));
236 
237     ts2.enterStep("1");
238     ts2.enterStep("2");
239     ts2.leaveStep("2");
240     ts2.leaveStep("1");
241 
242     // Add trace of session 2 to session 1
243     ts1.getRootStep().addChild(ts2.getRootStep());
244 
245     // Verify that the duration of the Trace Session matches
246     // the accumulated duration of BOTH sessions
247     assertEquals(80, ts1.getDuration());
248 
249     // OK: Add children to "normal" step ------------------------------
250 
251     ts2 = new DefaultTraceSession("testMeasureAfterAddChildren-2",
252         new DefaultTraceStepFactory(new MockTimerFactory(new long[] { 40, 20 })));
253 
254     ts2.enterStep("1");
255     ts2.enterStep("2");
256     ts2.leaveStep("2");
257     ts2.leaveStep("1");
258 
259     ts1 = new DefaultTraceSession("testMeasureAfterAddChildren-1",
260         new DefaultTraceStepFactory(new MockTimerFactory(new long[] { 40, 20 })));
261 
262     ts1.enterStep("1");
263     ts1.enterStep("2");
264     ts1.leaveStep("2");
265     ts1.getCurrentStep().addChild(ts2.getRootStep());
266     ts1.leaveStep("1");
267 
268     // printTraceTree(ts1);
269 
270     // In this case the duration of session 2 is not added to session 1
271     assertEquals(40, ts1.getDuration());
272 
273     // For trace step 1 no valid isolated duration can be determined, since
274     // session 2 has been
275     // manually added
276     assertEquals(-1, ts1.getRootStep().getChildren()[0].getIsolatedDuration());
277 
278   }
279 
280   /**
281    * Test case for multiple calls to the same sub-method from within one trace
282    * step.
283    * <p>
284    *
285    */
286   public void testMultipleMethodCalls() {
287     DefaultTraceSession ts;
288 
289     ts = new DefaultTraceSession("testMultipleMethodCalls", new DefaultTraceStepFactory(
290         new MockTimerFactory(new long[] { 100, 20, 20, 20, 20, 20 })));
291 
292     ts.enterStep(new MethodTraceStepId(this.getClass(), "method1"));
293 
294     for (int i = 0; i < 5; i++) {
295       ts.enterStep(new MethodTraceStepId(this.getClass(), "method2"));
296       ts.leaveStep(new MethodTraceStepId(this.getClass(), "method2"));
297     }
298 
299     ts.leaveStep(new MethodTraceStepId(this.getClass(), "method1"));
300 
301     // printTraceTree(ts);
302 
303     // Verify that the duration of the Trace Session matches
304     // the simulated
305     // execution times
306     assertEquals(100, ts.getDuration());
307     assertEquals(5, ts.getRootStep().getChildren()[0].getChildren().length);
308   }
309 
310   /**
311    * Test case for recursive calls to the same sub-method from within one trace
312    * step.
313    * <p>
314    *
315    */
316   public void testRecursiveMethodCalls() {
317     DefaultTraceSession ts;
318     ITraceStep step;
319 
320     ts = new DefaultTraceSession("testMultipleMethodCalls", new DefaultTraceStepFactory(
321         new MockTimerFactory(new long[] { 100, 20, 20, 20, 20, 20 })));
322 
323     ts.enterStep(new MethodTraceStepId(this.getClass(), "method1"));
324 
325     for (int i = 0; i < 5; i++) {
326       ts.enterStep(new MethodTraceStepId(this.getClass(), "method2"));
327     }
328     for (int i = 0; i < 5; i++) {
329       ts.leaveStep(new MethodTraceStepId(this.getClass(), "method2"));
330     }
331 
332     ts.leaveStep(new MethodTraceStepId(this.getClass(), "method1"));
333 
334     // printTraceTree(ts);
335 
336     // Verify that the duration of the Trace Session matches
337     // the simulated
338     // execution times
339     assertEquals(100, ts.getDuration());
340 
341     step = ts.getRootStep().getChildren()[0];
342     for (int i = 0; i < 5; i++) {
343       step = step.getChildren()[0];
344       assertEquals(20, step.getDuration());
345 
346     }
347 
348   }
349 
350   /**
351    * Helper method: Print a tree of trace steps to stdout.
352    * <p>
353    *
354    * @param ts
355    */
356   private void printTraceTree(DefaultTraceSession ts) {
357     ITraceFormatter tf = new PlainTextTraceFormatter();
358     StringWriter testOutput = new StringWriter();
359 
360     try {
361       tf.format(ts, testOutput);
362     } catch (IOException e) {
363       e.printStackTrace();
364     }
365 
366     System.out.println(testOutput.toString());
367 
368   }
369 }