001/**
002 * Copyright (c) 2004-2011 QOS.ch
003 * All rights reserved.
004 *
005 * Permission is hereby granted, free  of charge, to any person obtaining
006 * a  copy  of this  software  and  associated  documentation files  (the
007 * "Software"), to  deal in  the Software without  restriction, including
008 * without limitation  the rights to  use, copy, modify,  merge, publish,
009 * distribute,  sublicense, and/or sell  copies of  the Software,  and to
010 * permit persons to whom the Software  is furnished to do so, subject to
011 * the following conditions:
012 *
013 * The  above  copyright  notice  and  this permission  notice  shall  be
014 * included in all copies or substantial portions of the Software.
015 *
016 * THE  SOFTWARE IS  PROVIDED  "AS  IS", WITHOUT  WARRANTY  OF ANY  KIND,
017 * EXPRESS OR  IMPLIED, INCLUDING  BUT NOT LIMITED  TO THE  WARRANTIES OF
018 * MERCHANTABILITY,    FITNESS    FOR    A   PARTICULAR    PURPOSE    AND
019 * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
020 * LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
021 * OF CONTRACT, TORT OR OTHERWISE,  ARISING FROM, OUT OF OR IN CONNECTION
022 * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
023 *
024 */
025package org.slf4j.profiler;
026
027import static org.junit.Assert.assertEquals;
028import static org.junit.Assert.assertNotNull;
029import static org.junit.Assert.assertNull;
030
031import org.junit.Test;
032import org.slf4j.Logger;
033import org.slf4j.LoggerFactory;
034
035public class ProfilerTest {
036
037    Logger logger = LoggerFactory.getLogger(ProfilerTest.class);
038
039    @Test
040    public void testSmoke() {
041        Profiler profiler = new Profiler("SMOKE");
042        profiler.stop();
043        StopWatch gSW = profiler.globalStopWatch;
044
045        // verify
046        profiler.sanityCheck();
047        assertEquals(TimeInstrumentStatus.STOPPED, gSW.status);
048        assertEquals(0, profiler.childTimeInstrumentList.size());
049        assertNull(profiler.getLastTimeInstrument());
050    }
051
052    @Test
053    public void testBasicProfiling() {
054        Profiler profiler = new Profiler("BAS");
055
056        profiler.start("doX");
057        doX(1);
058
059        profiler.start("doY");
060        doY(10);
061
062        profiler.start("doZ");
063        doZ(2);
064        profiler.stop();
065
066        // verify
067        profiler.sanityCheck();
068        StopWatch gSW = profiler.globalStopWatch;
069        assertEquals(TimeInstrumentStatus.STOPPED, gSW.status);
070        assertEquals(3, profiler.childTimeInstrumentList.size());
071        assertNotNull(profiler.getLastTimeInstrument());
072        assertEquals("doZ", profiler.getLastTimeInstrument().getName());
073    }
074
075    // + Profiler [BAS]
076    // |-- elapsed time [doX] 1.272 milliseconds.
077    // |-- elapsed time [doYYYYY] 25.398 milliseconds.
078    // |--+ Profiler [subtask]
079    // |-- elapsed time [n1] 1.434 milliseconds.
080    // |-- elapsed time [n2] 5.855 milliseconds.
081    // |-- Total elapsed time [subtask] 7.321 milliseconds.
082    // |-- elapsed time [doZ] 3.211 milliseconds.
083    // |-- Total elapsed time [BAS] 30.317 milliseconds.
084    @Test
085    public void testNestedProfiling() {
086
087        Profiler profiler = new Profiler("BAS");
088        profiler.setLogger(logger);
089        profiler.start("doX");
090        doX(1);
091
092        profiler.start("doYYYYY");
093        for (int i = 0; i < 5; i++) {
094            doY(i);
095        }
096        Profiler nested = profiler.startNested("subtask");
097        doSubtask(nested);
098        profiler.start("doZ");
099        doZ(2);
100        profiler.stop();
101
102        // verify
103        profiler.sanityCheck();
104        StopWatch gSW = profiler.globalStopWatch;
105        assertEquals(TimeInstrumentStatus.STOPPED, gSW.status);
106        // assertEquals(3, profiler.stopwatchList.size());
107        assertEquals(4, profiler.childTimeInstrumentList.size());
108        assertNotNull(profiler.getLastTimeInstrument());
109        assertEquals("doZ", profiler.getLastTimeInstrument().getName());
110
111    }
112
113    private void doX(int millis) {
114        delay(millis);
115    }
116
117    private void doY(int millis) {
118        delay(millis);
119    }
120
121    private void doZ(int millis) {
122        delay(millis);
123    }
124
125    public void doSubtask(Profiler nested) {
126        nested.start("n1");
127        doX(1);
128
129        nested.start("n2");
130        doX(5);
131        nested.stop();
132    }
133
134    void delay(int millis) {
135        try {
136            Thread.sleep(millis);
137        } catch (InterruptedException e) {
138        }
139    }
140}