тут несколько моментов :
1) Это разные подходы между :
1.
2.
3.
System.out.println("");
System.err.println("");
разное потоки - разное выполнение ...
2) кошерное оформление теста :
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
70.
71.
72.
73.
74.
75.
76.
import java.util.concurrent.TimeUnit;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.LogManager;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Fork;
import org.openjdk.jmh.annotations.Measurement;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Param;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.annotations.Warmup;
import org.openjdk.jmh.infra.Blackhole;
import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;
import ru.stoloto.isalnikov.benchmarkfactorial.Factorial;
@Warmup(iterations = 5)
@Measurement(iterations = 10)
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MILLISECONDS)
@State(Scope.Benchmark)
@Fork(2)
public class Test
{
final static LogManager logMgr = new LogManager();
final static Logger log = logMgr.getLogger(Test.class);
@Param({"10", "100", "1000", "10000", "50000", "100000"})
private int n;
public int logger(int n) {
for (int i = 0; i < n; i++) {
log.trace(Level.TRACE + ": " + i);
log.debug(Level.DEBUG + ": " + i);
log.info(Level.INFO + " : " + i);
log.warn(Level.WARN + " : " + i);
log.error(Level.ERROR + ": " + i);
log.fatal(Level.FATAL + ": " + i);
}
logMgr.shutdown();
return 0;
}
@Benchmark
public void log(Blackhole bh) {
bh.consume(logger(n));
}
public static void main(String[] args) throws RunnerException
{
Options opt = new OptionsBuilder()
.include(Factorial.class.getSimpleName())
.forks(1)
.build();
new Runner(opt).run();
}
}
# Run progress: 83,33% complete, ETA 00:00:15
# Fork: 1 of 1
# Warmup Iteration 1: log4j:WARN No appenders could be found for logger (ru.stoloto.isalnikov.benchmarkfactorial.AATest).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See
http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
91,891 ms/op
# Warmup Iteration 2: 66,285 ms/op
# Warmup Iteration 3: 73,935 ms/op
# Warmup Iteration 4: 62,913 ms/op
# Warmup Iteration 5: 63,678 ms/op
Iteration 1: 61,813 ms/op
Iteration 2: 63,478 ms/op
Iteration 3: 62,874 ms/op
Iteration 4: 63,440 ms/op
Iteration 5: 62,798 ms/op
Iteration 6: 63,161 ms/op
Iteration 7: 63,945 ms/op
Iteration 8: 63,840 ms/op
Iteration 9: 66,408 ms/op
Iteration 10: 63,668 ms/op
Result "log":
63,543 ±(99.9%) 1,791 ms/op [Average]
(min, avg, max) = (61,813, 63,543, 66,408), stdev = 1,185
CI (99.9%): [61,752, 65,333] (assumes normal distribution)
# Run complete. Total time: 00:01:32
Benchmark (n) Mode Cnt Score Error Units
AATest.log 10 avgt 10 0,007 ± 0,002 ms/op
AATest.log 100 avgt 10 0,057 ± 0,002 ms/op
AATest.log 1000 avgt 10 0,591 ± 0,076 ms/op
AATest.log 10000 avgt 10 5,968 ± 0,144 ms/op
AATest.log 50000 avgt 10 31,255 ± 0,839 ms/op
AATest.log 100000 avgt 10 63,543 ± 1,791 ms/op
3) когда вывод в лог пишется как конкатенация - такой код всегда будет выполняться - даже если перед ним будет стоять условие if( тут нужно проверить ) в отличии от форматного кода ... через % - который выполняется в момент вызова -
замените :
на
1.
2.
3.
4.
5.
6.
7.
8.
log.debug("i= %d", i);
или String.format("i= %d", 5) ;
+ добавить для наглядности
if(log.isDebugEnabled()){
}
перепишите заново тесты и будет вам счастье :) + результаты тестов сюда - на обозрение ;)
