You are viewing a plain text version of this content. The canonical link for it is here.
Posted to kerby@directory.apache.org by "Zheng, Kai" <ka...@intel.com> on 2015/07/20 05:58:05 UTC
Kerby benchmark issue related to ApacheDS
Hi Emmanuel or all,
I'm working on Kerby benchmark and just converted existing benchmark tests to use JMH micro benchmark framework. A test related to ApacheDS failed as below and I'm wondering if there're some concurrency issue in the codes. Would you take a look at it if you're convenient? Thanks.
How to repeat:
cd benchmark/
mvn integration-test
Kind regards,
Kai
[INFO]
[INFO] --- exec-maven-plugin:1.4.0:exec (run-benchmarks) @ benchmark ---
# JMH 1.10.3 (released 3 days ago)
# VM version: JDK 1.7.0_60, VM 24.60-b09
Picked up _JAVA_OPTIONS: -Djava.net.preferIPv4Stack=true
# VM invoker: c:\work\jdk\jre\bin\java.exe
# VM options: -Djava.net.preferIPv4Stack=true
# Warmup: 2 iterations, 1 s each
# Measurement: 5 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: org.apache.kerby.benchmark.KrbCodecBenchmark.decodeWithApacheDS
# Run progress: 0.00% complete, ETA 00:00:28
# Fork: 1 of 2
# Warmup Iteration 1: SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
<failure>
org.apache.directory.api.asn1.DecoderException: ERR_00001_BAD_TRANSITION_FROM_STATE Bad transition from state START_STATE, tag 0x6E
at org.apache.directory.api.asn1.ber.grammar.AbstractGrammar.executeAction(AbstractGrammar.java:125)
at org.apache.directory.api.asn1.ber.Asn1Decoder.treatTLVDoneState(Asn1Decoder.java:600)
at org.apache.directory.api.asn1.ber.Asn1Decoder.decode(Asn1Decoder.java:736)
at org.apache.directory.shared.kerberos.codec.apReq.actions.StoreTicket.action(StoreTicket.java:83)
at org.apache.directory.shared.kerberos.codec.apReq.actions.StoreTicket.action(StoreTicket.java:41)
at org.apache.directory.api.asn1.ber.grammar.AbstractGrammar.executeAction(AbstractGrammar.java:136)
at org.apache.directory.api.asn1.ber.Asn1Decoder.treatTLVDoneState(Asn1Decoder.java:600)
at org.apache.directory.api.asn1.ber.Asn1Decoder.decode(Asn1Decoder.java:736)
at org.apache.kerby.benchmark.KrbCodecBenchmark.decodeWithApacheDS(KrbCodecBenchmark.java:68)
at org.apache.kerby.benchmark.generated.KrbCodecBenchmark_decodeWithApacheDS.decodeWithApacheDS_avgt_jmhStub(KrbCodecBenchmark_decodeWithApacheDS.java
at org.apache.kerby.benchmark.generated.KrbCodecBenchmark_decodeWithApacheDS.decodeWithApacheDS_AverageTime(KrbCodecBenchmark_decodeWithApacheDS.java:
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.openjdk.jmh.runner.BenchmarkHandler$BenchmarkTask.call(BenchmarkHandler.java:430)
at org.openjdk.jmh.runner.BenchmarkHandler$BenchmarkTask.call(BenchmarkHandler.java:412)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Picked up _JAVA_OPTIONS: -Djava.net.preferIPv4Stack=true
# Run progress: 25.00% complete, ETA 00:00:04
# Fork: 2 of 2
# Warmup Iteration 1: SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
<failure>
org.apache.directory.api.asn1.DecoderException: ERR_00001_BAD_TRANSITION_FROM_STATE Bad transition from state START_STATE, tag 0x6E
at org.apache.directory.api.asn1.ber.grammar.AbstractGrammar.executeAction(AbstractGrammar.java:125)
at org.apache.directory.api.asn1.ber.Asn1Decoder.treatTLVDoneState(Asn1Decoder.java:600)
at org.apache.directory.api.asn1.ber.Asn1Decoder.decode(Asn1Decoder.java:736)
at org.apache.directory.shared.kerberos.codec.apReq.actions.StoreTicket.action(StoreTicket.java:83)
at org.apache.directory.shared.kerberos.codec.apReq.actions.StoreTicket.action(StoreTicket.java:41)
at org.apache.directory.api.asn1.ber.grammar.AbstractGrammar.executeAction(AbstractGrammar.java:136)
at org.apache.directory.api.asn1.ber.Asn1Decoder.treatTLVDoneState(Asn1Decoder.java:600)
at org.apache.directory.api.asn1.ber.Asn1Decoder.decode(Asn1Decoder.java:736)
at org.apache.kerby.benchmark.KrbCodecBenchmark.decodeWithApacheDS(KrbCodecBenchmark.java:68)
at org.apache.kerby.benchmark.generated.KrbCodecBenchmark_decodeWithApacheDS.decodeWithApacheDS_avgt_jmhStub(KrbCodecBenchmark_decodeWithApacheDS.java
at org.apache.kerby.benchmark.generated.KrbCodecBenchmark_decodeWithApacheDS.decodeWithApacheDS_AverageTime(KrbCodecBenchmark_decodeWithApacheDS.java:
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.openjdk.jmh.runner.BenchmarkHandler$BenchmarkTask.call(BenchmarkHandler.java:430)
at org.openjdk.jmh.runner.BenchmarkHandler$BenchmarkTask.call(BenchmarkHandler.java:412)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Picked up _JAVA_OPTIONS: -Djava.net.preferIPv4Stack=true
# JMH 1.10.3 (released 3 days ago)
# VM version: JDK 1.7.0_60, VM 24.60-b09
Picked up _JAVA_OPTIONS: -Djava.net.preferIPv4Stack=true
# VM invoker: c:\work\jdk\jre\bin\java.exe
# VM options: -Djava.net.preferIPv4Stack=true
# Warmup: 2 iterations, 1 s each
# Measurement: 5 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: org.apache.kerby.benchmark.KrbCodecBenchmark.decodeWithKerby
# Run progress: 50.00% complete, ETA 00:00:02
# Fork: 1 of 2
# Warmup Iteration 1: 25545.827 ns/op
# Warmup Iteration 2: 7670.003 ns/op
Iteration 1: 7228.367 ns/op
Iteration 2: 6854.991 ns/op
Iteration 3: 6827.826 ns/op
Iteration 4: 6873.941 ns/op
Iteration 5: 6968.195 ns/op
Picked up _JAVA_OPTIONS: -Djava.net.preferIPv4Stack=true
# Run progress: 75.00% complete, ETA 00:00:03
# Fork: 2 of 2
# Warmup Iteration 1: 23219.519 ns/op
# Warmup Iteration 2: 7588.838 ns/op
Iteration 1: 7017.634 ns/op
Iteration 2: 7084.992 ns/op
Iteration 3: 6890.524 ns/op
Iteration 4: 7293.447 ns/op
Iteration 5: 6964.228 ns/op
Picked up _JAVA_OPTIONS: -Djava.net.preferIPv4Stack=true
Result "decodeWithKerby":
7000.414 ±(99.9%) 239.912 ns/op [Average]
(min, avg, max) = (6827.826, 7000.414, 7293.447), stdev = 158.687
CI (99.9%): [6760.502, 7240.326] (assumes normal distribution)
# Run complete. Total time: 00:00:18
Benchmark Mode Cnt Score Error Units
KrbCodecBenchmark.decodeWithKerby avgt 10 7000.414 ± 239.912 ns/op
Picked up _JAVA_OPTIONS: -Djava.net.preferIPv4Stack=true
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 32.830s
[INFO] Finished at: Mon Jul 20 11:53:21 CST 2015
[INFO] Final Memory: 21M/365M
[INFO] ------------------------------------------------------------------------
kaizhen@KAIZHEN-MOBL1 /c/work/projects/kerby/benchmark (master)
Re: Kerby benchmark issue related to ApacheDS
Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 20/07/15 08:22, Zheng, Kai a écrit :
> I got it, thanks for the detailed explanation. I had already corrected the codes and it works fine now. I guess the performance overhead may be incurred by the fragment handling.
>
> # Run complete. Total time: 00:00:29
>
> Benchmark Mode Cnt Score Error Units
> KrbCodecBenchmark.decodeWithApacheDS avgt 10 10702.118 ± 1475.804 ns/op
> KrbCodecBenchmark.decodeWithKerby avgt 10 5833.663 ± 168.466 ns/op
>
> By the way, in the following I will work out benchmarks for back ends and the KDC server, using the JMH framework like above.
Good !
As expected, and as proven months ago, the Kerby codec is faster than
the ApacheDS's one. This is a great result !
RE: Kerby benchmark issue related to ApacheDS
Posted by "Zheng, Kai" <ka...@intel.com>.
I got it, thanks for the detailed explanation. I had already corrected the codes and it works fine now. I guess the performance overhead may be incurred by the fragment handling.
# Run complete. Total time: 00:00:29
Benchmark Mode Cnt Score Error Units
KrbCodecBenchmark.decodeWithApacheDS avgt 10 10702.118 ± 1475.804 ns/op
KrbCodecBenchmark.decodeWithKerby avgt 10 5833.663 ± 168.466 ns/op
By the way, in the following I will work out benchmarks for back ends and the KDC server, using the JMH framework like above.
Regards,
Kai
-----Original Message-----
From: Emmanuel Lécharny [mailto:elecharny@gmail.com]
Sent: Monday, July 20, 2015 2:06 PM
To: kerby@directory.apache.org
Subject: Re: Kerby benchmark issue related to ApacheDS
Le 20/07/15 07:11, Zheng, Kai a écrit :
> Ah, right. I didn't notice the token to be decoded should be passed TWO times (though not very natural to me).
We don't pass the toke twice. What you do is really a corner case : you decode a full buffer in one pass.
The decoder takes two arguments :
- a buffer containing bytes
- a container that holds the on going decoding PDU
As we may have fragmented PDU, we need to be able to keep going with the decoding everytime we receive some bytes, and thsi is why we pass teh first parameter ove rand over, untl we have deocded the full PDU As we may have to decode inner PDU (as a Ticket inside an ApReqRequest, for instance), we must accumulate the bytes in a buffer instead the container
In your case, the PDU is complete, so we simply store it fully in the container. When the Ticket has been full read (it's a Single TLV), then we will be able to call the Ticket decoder methods using the same Buffer, but starting at position 25, to decode the Ticket.
Re: Kerby benchmark issue related to ApacheDS
Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 20/07/15 07:11, Zheng, Kai a écrit :
> Ah, right. I didn't notice the token to be decoded should be passed TWO times (though not very natural to me).
We don't pass the toke twice. What you do is really a corner case : you
decode a full buffer in one pass.
The decoder takes two arguments :
- a buffer containing bytes
- a container that holds the on going decoding PDU
As we may have fragmented PDU, we need to be able to keep going with the
decoding everytime we receive some bytes, and thsi is why we pass teh
first parameter ove rand over, untl we have deocded the full PDU
As we may have to decode inner PDU (as a Ticket inside an ApReqRequest,
for instance), we must accumulate the bytes in a buffer instead the
container
In your case, the PDU is complete, so we simply store it fully in the
container. When the Ticket has been full read (it's a Single TLV), then
we will be able to call the Ticket decoder methods using the same
Buffer, but starting at position 25, to decode the Ticket.
RE: Kerby benchmark issue related to ApacheDS
Posted by "Zheng, Kai" <ka...@intel.com>.
Ah, right. I didn't notice the token to be decoded should be passed TWO times (though not very natural to me). Thanks Emmanule!
ApReqContainer apreqContainer = new ApReqContainer(apreqToken.duplicate());
krbDecoder.decode(apreqToken, apreqContainer);
Regards,
Kai
-----Original Message-----
From: Emmanuel Lécharny [mailto:elecharny@gmail.com]
Sent: Monday, July 20, 2015 1:02 PM
To: kerby@directory.apache.org
Subject: Re: Kerby benchmark issue related to ApacheDS
Le 20/07/15 05:58, Zheng, Kai a écrit :
> Hi Emmanuel or all,
>
> I'm working on Kerby benchmark and just converted existing benchmark tests to use JMH micro benchmark framework. A test related to ApacheDS failed as below and I'm wondering if there're some concurrency issue in the codes. Would you take a look at it if you're convenient? Thanks.
There is a mistake in your test.
When you do :
ApReqContainer apreqContainer = new ApReqContainer(apreqToken.duplicate());
you inject a different stream in the container than teh one you will decode. When the codec will try to decode the inner ticket, it will use this duplicated stream, which will start at position 0, as the stream is duplicated, when it's expected to be at position 25, as the original stream has already been partially decoded.
What you should do is :
ApReqContainer apreqContainer = new ApReqContainer(apreqToken);
Now, be sure to do a apreqToken.flip(); at the end of your test, otherwise you won't be able to run it more than once
Re: Kerby benchmark issue related to ApacheDS
Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 20/07/15 05:58, Zheng, Kai a écrit :
> Hi Emmanuel or all,
>
> I'm working on Kerby benchmark and just converted existing benchmark tests to use JMH micro benchmark framework. A test related to ApacheDS failed as below and I'm wondering if there're some concurrency issue in the codes. Would you take a look at it if you're convenient? Thanks.
There is a mistake in your test.
When you do :
ApReqContainer apreqContainer = new
ApReqContainer(apreqToken.duplicate());
you inject a different stream in the container than teh one you will
decode. When the codec will try to decode the inner ticket, it will use
this duplicated stream, which will start at position 0, as the stream is
duplicated, when it's expected to be at position 25, as the original
stream has already been partially decoded.
What you should do is :
ApReqContainer apreqContainer = new ApReqContainer(apreqToken);
Now, be sure to do a apreqToken.flip(); at the end of your test,
otherwise you won't be able to run it more than once