Package org.mentalog.test

Class Summary
GCTest java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.4.jar:lib/menta-affinity-0.9.7.jar:/usr/share/java/jna.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=true -DmemoryMappedBufferSize=150m -Dasynchronous=true -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -DdetailedBenchmark=true -Ddelay=20 -DprocToBindProducer=2 -DlogProcToBindConsumer=3 -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.GCTest 1000000 09:45:45.364-INFO Log created: ExtendedDefaultLogger=[file=./mentalog_gc_test.log, isSynchronized=false, isMemoryMappedFile=true, isAsynchronous=true, isExtended=true] Wrote 1000000 log lines to a file! Logs that allocated memory: 0 (0.0%) Logs that did not allocate any memory: 1000000 (100.0%) Logs that triggered GC: 0 (0.0%) Memory allocated: 0 bytes Benchmark: Iterations: 1000000 | Avg Time: 336.68 nanos | Min Time: 224 nanos | Max Time: 57275 nanos
MMapFileTest  
PauseSupport  
PerformanceComparator To run: - Regular: (no memory-mapped files, no async logging, no delay, with thread-affinity) java -verbose:gc -cp target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.4.jar:lib/menta-affinity-0.9.7.jar:/usr/share/java/jna.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=false -Dasynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -DdetailedBenchmark=true -Ddelay=-1 -DprocToBindProducer=2 -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog Benchmark: Iterations: 900000 | Avg Time: 5519.54 nanos | Min Time: 4664 nanos | Max Time: 2564909 nanos | 75%: avg=5046 max=5579 | 90%: avg=5155 max=6238 | 99%: avg=5431 max=11877 | 99.9%: avg=5501 max=15905 | 99.99%: avg=5512 max=23269 | 99.999%: avg=5515 max=54925 - Memory-Mapped File: (with memory-mapped files, no async logging, no delay, with thread-affinity) java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.4.jar:lib/menta-affinity-0.9.7.jar:/usr/share/java/jna.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=true -DmemoryMappedBufferSize=150m -Dasynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -DdetailedBenchmark=true -Ddelay=-1 -DprocToBindProducer=2 -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog - Asyn Logging: (no memory-mapped files, with async logging, with delay, with thread-affinity) java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.4.jar:lib/menta-affinity-0.9.7.jar:/usr/share/java/jna.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=false -DmemoryMappedBufferSize=150m -Dasynchronous=true -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -DdetailedBenchmark=true -Ddelay=10 -DprocToBindProducer=2 -DlogProcToBindConsumer=3 -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog - Memory-Mapped File + Async Logging: (with memory-mapped files, with async logging, with delay, with thread-affinity) java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.4.jar:lib/menta-affinity-0.9.7.jar:/usr/share/java/jna.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=true -DmemoryMappedBufferSize=150m -Dasynchronous=true -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -DdetailedBenchmark=true -Ddelay=20 -DprocToBindProducer=2 -DlogProcToBindConsumer=3 -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog Benchmark: Iterations: 900000 | Avg Time: 335.85 nanos | Min Time: 220 nanos | Max Time: 10947 nanos | 75%: avg=312 max=332 | 90%: avg=318 max=380 | 99%: avg=331 max=593 | 99.9%: avg=334 max=1030 | 99.99%: avg=335 max=5371 | 99.999%: avg=335 max=5523 - Log back: (no async with thread affinity) java -verbose:gc -cp target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.4.jar:lib/menta-affinity-0.9.7.jar:/usr/share/java/jna.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=false -Dasynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -DdetailedBenchmark=true -Ddelay=-1 -DprocToBindProducer=2 -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 logback Benchmark: Iterations: 900000 | Avg Time: 3986.98 nanos | Min Time: 3280 nanos | Max Time: 3701513 nanos | 75%: avg=3553 max=3702 | 90%: avg=3618 max=5231 | 99%: avg=3904 max=9200 | 99.9%: avg=3960 max=12028 | 99.99%: avg=3969 max=18548 | 99.999%: avg=3973 max=64366 - Log4J - MentaLog: (no memory-mapped and no async logging) java -verbose:gc -cp target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=false -Dasync=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 5000000 mentalog Iterations: 900000 | Avg Time: 4317.79 nanos | Min Time: 4025 nanos | Max Time: 935349 nanos Iterations: 1800000 | Avg Time: 4148.65 nanos | Min Time: 3806 nanos | Max Time: 2836875 nanos Iterations: 4500000 | Avg Time: 4278.94 nanos | Min Time: 3871 nanos | Max Time: 38635829 nanos ==== Memory allocated: ZERO (not a single byte) ==== - Log4J: java -verbose:gc -cp target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=false -Dasynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 5000000 log4j Iterations: 90000 | Avg Time: 3756.18 nanos | Min Time: 2787 nanos | Max Time: 150017 nanos Iterations: 900000 | Avg Time: 3329.19 nanos | Min Time: 2756 nanos | Max Time: 654025 nanos Iterations: 4500000 | Avg Time: 3280.86 nanos | Min Time: 2859 nanos | Max Time: 6879898 nanos Memory is allocated and GC is triggered - Logback: java -verbose:gc -cp target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=false -Dasynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 5000000 logback Iterations: 900000 | Avg Time: 3750.77 nanos | Min Time: 3158 nanos | Max Time: 648638 nanos Iterations: 1800000 | Avg Time: 3618.32 nanos | Min Time: 3130 nanos | Max Time: 4684685 nanos Iterations: 4500000 | Avg Time: 3701.08 nanos | Min Time: 3200 nanos | Max Time: 55608669 nanos Memory is allocated and GC is triggered - MentaLog: (with memory-mapped file) java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=true -DmemoryMappedBufferSize=150m -Dasynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog Iterations: 900000 | Avg Time: 1294.71 nanos | Min Time: 1204 nanos | Max Time: 101816 nanos Iterations: 1800000 | Avg Time: 1310.23 nanos | Min Time: 1209 nanos | Max Time: 169474 nanos Iterations: 1800000 | Avg Time: 1281.92 nanos | Min Time: 1201 nanos | Max Time: 687653 nanos ==== Memory allocated: ZERO (not a single byte) ==== - MentaLog: (with asynchronous logging) NOTE: Thread pinning might be a good idea here! java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=false -DmemoryMappedBufferSize=150m -Dasynchronous=true -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 5000000 mentalog Iterations: 900000 | Avg Time: 3808.65 nanos | Min Time: 97 nanos | Max Time: 20100420 nanos | 75%: 150 nanos | 90%: 156 nanos | 99%: 164 nanos | 99.9%: 167 nanos | 99.99%: 1890 nanos | 99.999%: 3609 nanos Iterations: 1800000 | Avg Time: 3832.35 nanos | Min Time: 100 nanos | Max Time: 20269036 nanos | 75%: 146 nanos | 90%: 153 nanos | 99%: 160 nanos | 99.9%: 162 nanos | 99.99%: 2128 nanos | 99.999%: 3651 nanos Iterations: 4500000 | Avg Time: 3624.02 nanos | Min Time: 99 nanos | Max Time: 25602060 nanos | 75%: 149 nanos | 90%: 156 nanos | 99%: 163 nanos | 99.9%: 165 nanos | 99.99%: 1734 nanos | 99.999%: 3424 nanos ==== Memory allocated: ZERO (not a single byte) ==== - MentaLog: (with asynchronous logging AND memory-mapped files) NOTE: Thread pinning might make this even better! java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DmemoryMappedFile=true -DmemoryMappedBufferSize=300m -Dasynchronous=true -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 2000000 mentalog Iterations: 4500000 | Avg Time: 969.62 nanos | Min Time: 97 nanos | Max Time: 5229828 nanos | 75%: 178 nanos | 90%: 188 nanos | 99%: 198 nanos | 99.9%: 200 nanos | 99.99%: 500 nanos | 99.999%: 920 nanos Iterations: 1800000 | Avg Time: 973.22 nanos | Min Time: 92 nanos | Max Time: 5024597 nanos | 75%: 164 nanos | 90%: 174 nanos | 99%: 184 nanos | 99.9%: 186 nanos | 99.99%: 519 nanos | 99.999%: 925 nanos Iterations: 900000 | Avg Time: 973.94 nanos | Min Time: 98 nanos | Max Time: 6461357 nanos | 75%: 166 nanos | 90%: 176 nanos | 99%: 187 nanos | 99.9%: 189 nanos | 99.99%: 380 nanos | 99.999%: 911 nanos ==== Memory allocated: ZERO (not a single byte) ==== - MentaLog: (with asynchronous logging and memory-mapped files and consumer and producer thread pinning and busy spinning strategy) java -verbose:gc -cp /usr/share/java/jna.jar:../MentaLogExt/target/classes:../MentaAffinity/target/classes:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:../MentaQueue/target/classes:src/main/java/org/mentalog/test -DlogProcToBindConsumer=3 -DmemoryMappedFile=true -DmemoryMappedBufferSize=150m -Dasynchronous=true -DlogColors=true -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -DdetailedBenchmark=true -Ddelay=1 -DlogLevel=debug -DprocToBindProducer=2 -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog Iterations: 900000 | Avg Time: 323.73 nanos | Min Time: 174 nanos | Max Time: 102708 nanos | 75%: 309 nanos | 90%: 312 nanos | 99%: 318 nanos | 99.9%: 321 nanos | 99.99%: 322 nanos | 99.999%: 323 nanos Iterations: 3600000 | Avg Time: 319.04 nanos | Min Time: 228 nanos | Max Time: 10730 nanos | 75%: 310 nanos | 90%: 312 nanos | 99%: 315 nanos | 99.9%: 317 nanos | 99.99%: 318 nanos | 99.999%: 318 nanos ==== Memory allocated: ZERO (not a single byte) ==== - Log4J: (with asynchronous logging) NOTE: Changet the log4j xml file to use asynchronous logging Iterations: 4500000 | Avg Time: 2566.31 nanos | Min Time: 260 nanos | Max Time: 31647565 nanos | 75%: 273 nanos | 90%: 281 nanos | 99%: 288 nanos | 99.9%: 290 nanos | 99.99%: 292 nanos | 99.999%: 2317 nanos Iterations: 1800000 | Avg Time: 2510.84 nanos | Min Time: 263 nanos | Max Time: 25864561 nanos | 75%: 281 nanos | 90%: 295 nanos | 99%: 307 nanos | 99.9%: 314 nanos | 99.99%: 317 nanos | 99.999%: 2264 nanos Iterations: 900000 | Avg Time: 2747.56 nanos | Min Time: 260 nanos | Max Time: 28432739 nanos | 75%: 276 nanos | 90%: 285 nanos | 99%: 301 nanos | 99.9%: 313 nanos | 99.99%: 316 nanos | 99.999%: 2478 nanos Benchmark: Iterations: 900000 | Avg Time: 3250.74 nanos | Min Time: 282 nanos | Max Time: 33420500 nanos | 75%: avg=298 max=319 | 90%: avg=302 max=326 | 99%: avg=311 max=1439 | 99.9%: avg=322 max=2932 | 99.99%: avg=325 max=8590 | 99.999%: avg=2925 max=32359336 A lot of memory is allocated and GC is triggered
 



Copyright © 2013. All Rights Reserved.