[logback-dev] svn commit: r1855 - logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic
Ralph Goers
ralph.goers at dslextreme.com
Tue Oct 21 04:45:05 CEST 2008
I increased referencePerf from 500 to 2500 and got the test to pass.
I'm not really sure how the appropriate number was determined.
Ralph Goers wrote:
> I'm having trouble getting the new version of LoggerPerfTest to pass.
> I've attached the output of the test.
>
> Ralph
>
> noreply.ceki at qos.ch wrote:
>> Author: ceki
>> Date: Mon Oct 20 21:57:39 2008
>> New Revision: 1855
>>
>> Modified:
>>
>> logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java
>>
>>
>> Log:
>> Related to LBCORE-58
>>
>> SleepAppender can derive from UnsynchronizedAppenderBase
>>
>>
>> Modified:
>> logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java
>>
>> ==============================================================================
>>
>> ---
>> logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java
>> (original)
>> +++
>> logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java
>> Mon Oct 20 21:57:39 2008
>> @@ -9,89 +9,111 @@
>> */
>> package ch.qos.logback.classic;
>>
>> +import static org.junit.Assert.assertTrue;
>>
>> -import java.net.InetAddress;
>> -
>> -import junit.framework.TestCase;
>> -
>> +import org.junit.Before;
>> +import org.junit.Test;
>> import org.slf4j.helpers.BogoPerf;
>>
>> import ch.qos.logback.classic.spi.LoggingEvent;
>> import ch.qos.logback.classic.turbo.NOPTurboFilter;
>> +import ch.qos.logback.core.UnsynchronizedAppenderBase;
>> import ch.qos.logback.core.appender.NOPAppender;
>>
>> -public class LoggerPerfTest extends TestCase {
>> -
>> - final static String KAL = "kal";
>> - String localhostName = null;
>> - static long NORMAL_RUN_LENGTH = 1000*1000;
>> +public class LoggerPerfTest {
>>
>> + long NANOS_IN_ONE_SEC = 1000*1000*1000L;
>> + static long NORMAL_RUN_LENGTH = 1000 * 1000;
>> + static long SHORTENED_RUN_LENGTH = 500 * 1000;
>> static long REFERENCE_BIPS = 9324;
>> - +
>> + @Before
>> public void setUp() throws Exception {
>> - localhostName = InetAddress.getLocalHost().getCanonicalHostName();
>> }
>> - public void testBasic() {
>> - basicDurationInNanos(NORMAL_RUN_LENGTH);
>> - double avg = basicDurationInNanos(NORMAL_RUN_LENGTH); - +
>> + @Test
>> + public void testDurationOfDisabledLogWithStraightStringParameter() {
>> +
>> computeDurationOfDisabledLogWithStraightStringParameter(NORMAL_RUN_LENGTH);
>>
>> + double avg =
>> computeDurationOfDisabledLogWithStraightStringParameter(NORMAL_RUN_LENGTH);
>>
>> +
>> long referencePerf = 17;
>> BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS);
>> - //System.out.println("Average log time for disabled statements:
>> "+avg+" nanos.");
>> - }
>> - - public void testParameterized() {
>> - loopParameterized(NORMAL_RUN_LENGTH);
>> - double avgDuration = loopParameterized(NORMAL_RUN_LENGTH); -
>> long referencePerf = 36;
>> - BogoPerf.assertDuration(avgDuration, referencePerf,
>> REFERENCE_BIPS);
>> - //System.out.println("Average log time for disabled
>> (parameterized) statements: "+avg+" nanos.");
>> }
>> - - - public void testNOPFilter() {
>> - loopNopFilter(NORMAL_RUN_LENGTH);
>> - double avg = loopNopFilter(NORMAL_RUN_LENGTH);
>> - //System.out.println("Average log time for disabled (NOPFilter)
>> statements: "+avg+" nanos.");
>> - long referencePerf = 48;
>> - BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS);
>> - }
>> - - double basicDurationInNanos(long len) {
>> +
>> + double
>> computeDurationOfDisabledLogWithStraightStringParameter(long len) {
>> LoggerContext lc = new LoggerContext();
>> - NOPAppender<LoggingEvent> mopAppender = new
>> NOPAppender<LoggingEvent>();
>> - mopAppender.start();
>> Logger logger = lc.getLogger(this.getClass());
>> logger.setLevel(Level.OFF);
>> - for(long i = 0; i < len; i++) {
>> + for (long i = 0; i < len; i++) {
>> logger.debug("Toto");
>> }
>> long start = System.nanoTime();
>> - for(long i = 0; i < len; i++) {
>> + for (long i = 0; i < len; i++) {
>> logger.debug("Toto");
>> }
>> long end = System.nanoTime();
>> - return (end-start)/len;
>> + return (end - start) / len;
>> }
>>
>> - double loopParameterized(long len) {
>> + @Test
>> + public void testDurationOfDisabledLogWithParameters() {
>> + computeDurationOfDisabledLogWithParameters(NORMAL_RUN_LENGTH);
>> + double avgDuration =
>> computeDurationOfDisabledLogWithParameters(NORMAL_RUN_LENGTH);
>> + long referencePerf = 36;
>> + BogoPerf.assertDuration(avgDuration, referencePerf,
>> REFERENCE_BIPS);
>> + }
>> + + double computeDurationOfDisabledLogWithParameters(long len) {
>> LoggerContext lc = new LoggerContext();
>> - NOPAppender<LoggingEvent> mopAppender = new
>> NOPAppender<LoggingEvent>();
>> - mopAppender.start();
>> Logger logger = lc.getLogger(this.getClass());
>> logger.setLevel(Level.OFF);
>> - for(long i = 0; i < len; i++) {
>> + for (long i = 0; i < len; i++) {
>> logger.debug("Toto {}", i);
>> }
>> long start = System.nanoTime();
>> - for(long i = 0; i < len; i++) {
>> + for (long i = 0; i < len; i++) {
>> logger.debug("Toto {}", i);
>> }
>> long end = System.nanoTime();
>> - return (end-start)/len;
>> + return (end - start) / len;
>> + }
>> +
>> + @Test
>> + public void testDurationOfEnabledWithStraightStringParameter() {
>> +
>> computeDurationOfEnabledLogWithStraightStringParameter(SHORTENED_RUN_LENGTH);
>>
>> + double avgDuration =
>> computeDurationOfEnabledLogWithStraightStringParameter(SHORTENED_RUN_LENGTH);
>>
>> + long referencePerf = 500;
>> + BogoPerf.assertDuration(avgDuration, referencePerf,
>> REFERENCE_BIPS);
>> + System.out.println("avgDuration="+avgDuration);
>> }
>> - double loopNopFilter(long len) {
>> + double computeDurationOfEnabledLogWithStraightStringParameter(long
>> len) {
>> + LoggerContext lc = new LoggerContext();
>> + Logger logger = lc.getLogger(this.getClass());
>> + logger.setLevel(Level.ALL);
>> + NOPAppender<LoggingEvent> nopAppender = new
>> NOPAppender<LoggingEvent>();
>> + nopAppender.start();
>> + logger.addAppender(nopAppender);
>> + for (long i = 0; i < len; i++) {
>> + logger.debug("Toto", i);
>> + }
>> + long start = System.nanoTime();
>> + for (long i = 0; i < len; i++) {
>> + logger.debug("Toto");
>> + }
>> + long end = System.nanoTime();
>> + return (end - start) / len;
>> + }
>> +
>> + @Test
>> + public void testComputeDurationOfDisabledLogsWithNOPFilter() {
>> + computeDurationOfDisabledLogsWithNOPFilter(NORMAL_RUN_LENGTH);
>> + double avg =
>> computeDurationOfDisabledLogsWithNOPFilter(NORMAL_RUN_LENGTH);
>> + long referencePerf = 48;
>> + BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS);
>> + }
>> +
>> + double computeDurationOfDisabledLogsWithNOPFilter(long len) {
>> LoggerContext lc = new LoggerContext();
>> NOPAppender<LoggingEvent> mopAppender = new
>> NOPAppender<LoggingEvent>();
>> NOPTurboFilter nopFilter = new NOPTurboFilter();
>> @@ -100,15 +122,92 @@
>> lc.addTurboFilter(nopFilter);
>> Logger logger = lc.getLogger(this.getClass());
>> logger.setLevel(Level.OFF);
>> - for(long i = 0; i < len; i++) {
>> + for (long i = 0; i < len; i++) {
>> logger.debug("Toto");
>> }
>> long start = System.nanoTime();
>> - for(long i = 0; i < len; i++) {
>> + for (long i = 0; i < len; i++) {
>> logger.debug("Toto");
>> }
>> long end = System.nanoTime();
>> - return (end-start)/len;
>> + return (end - start) / len;
>> }
>> - +
>> + @Test
>> + public void testThreadedLogging() throws InterruptedException {
>> + LoggerContext lc = new LoggerContext();
>> + SleepAppender<LoggingEvent> appender = new
>> SleepAppender<LoggingEvent>();
>> + + int MILLIS_PER_CALL = 250;
>> + int NANOS_PER_CALL = 250*1000*1000;;
>> + appender.setDuration(MILLIS_PER_CALL);
>> + appender.start();
>> + Logger logger = lc.getLogger(this.getClass());
>> + logger.addAppender(appender);
>> + logger.setLevel(Level.DEBUG);
>> + long start;
>> + long end;
>> + int threadCount = 10;
>> + int iterCount = 5;
>> + TestRunner[] threads = new TestRunner[threadCount];
>> + for (int i = 0; i < threads.length; ++i) {
>> + threads[i] = new TestRunner(logger, iterCount);
>> + }
>> + start = System.nanoTime();
>> + for (Thread thread : threads) {
>> + thread.start();
>> + }
>> + for (TestRunner thread : threads) {
>> + thread.join();
>> + }
>> + end = System.nanoTime();
>> + double tolerance = threadCount * .125; // Very little thread
>> contention
>> + // should occur in this test.
>> + double max = ((((double) NANOS_PER_CALL) / NANOS_IN_ONE_SEC) *
>> iterCount) * tolerance;
>> + double serialized = (((double) NANOS_PER_CALL) /
>> NANOS_IN_ONE_SEC) * iterCount
>> + * threadCount;
>> + double actual = ((double) (end - start)) / NANOS_IN_ONE_SEC;
>> + System.out
>> + .printf(
>> + "Sleep duration: %,.4f seconds. Max expected: %,.4f
>> seconds, Serialized: %,.4f\n",
>> + actual, max, serialized);
>> + assertTrue("Exceeded maximum expected time.", actual < max);
>> + }
>> +
>> + // ============================================================
>> + private static class TestRunner extends Thread {
>> + private Logger logger;
>> + private long len;
>> +
>> + public TestRunner(Logger logger, long len) {
>> + this.logger = logger;
>> + this.len = len;
>> + }
>> +
>> + public void run() {
>> + Thread.yield();
>> + for (long i = 0; i < len; i++) {
>> + logger.debug("Toto");
>> + }
>> + }
>> + }
>> +
>> + // ============================================================
>> + public static class SleepAppender<E> extends
>> UnsynchronizedAppenderBase<E> {
>> + private static long duration = 500;
>> +
>> + public void setDuration(long millis) {
>> + duration = millis;
>> + }
>> +
>> + @Override
>> + protected void append(E eventObject) {
>> + try {
>> + Thread.sleep(duration);
>> + } catch (InterruptedException ie) {
>> + // Ignore
>> + }
>> + }
>> + }
>> + // ============================================================
>> }
>> _______________________________________________
>> logback-dev mailing list
>> logback-dev at qos.ch
>> http://qos.ch/mailman/listinfo/logback-dev
>>
More information about the logback-dev
mailing list