    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}