XB profiling during the AS start-up

[aloubyansky]

To get an idea of what's taking time in XB during the AS start-up, I added simple time checks for three things:
- creation of unmarshaller instances (parsers)
- unmarshalling (parsing xml + assembling the Java graph)
- schema binding (parsing of JBossXB/JAXB annotations)

I started the default AS configuration 10 times and here are the average time results.

AS start-up: 26385 ms
XB total: 2460 ms or ~9% of AS start-up

unmarshallers (95 instances): 90 ms or ~4% of XB total
unmarshalling (72 files): 1331 ms or ~54% of XB total
binding (17 schemas): 912 ms or ~37% of XB total

First thing I tried was schema binding creation by means of serialization/deserialization of schema bindings instead of re-building them on every start-up from Java annotations (that was a long awaiting feature request). Deserialization of schema bindings (with the standard Java serialization) appears to be around 6.5 times slower then building schema bindings from annotations. Classloading during deserialization takes around 140ms which is ~3% of total derserialization time. So, the idea of serializing/deserializing schema bindings with standard Java serialization is not looking good.

Then I looked into reading annotations (class-, property-, package-level) during schema binding construction. For all the schemas during AS start-up the total average time is 127 ms which is ~14% of the binding time and ~5% of the XB total time. So, this looks good and looking for another source to get this information from doesn't make sense.

What's left for the optimization of schema binding creation is the way the data from annotations is processed. The total average time to process the data from annotations is 785 ms, which is ~86% of total binding time and ~32% of total XB time.

So, at the end the main areas for optimizations in XB during AS start-up are:
- unmarshalling (xml parsing + assembling the Java graph) which takes 1331 ms or ~54% of the XB total time
- processing annotation data during schema binding creation which takes 785 ms or ~32% of the XB total time

But before I proceed with the annotation processing optimization I'm gonna get some more details for the unmarshalling time, i.e. pure XML parsing (which is xerces) vs the rest of the XB unmarshalling code.

[dmlloyd]

I for one would rather see investment in Bill's precompilation idea, at least to see if it's feasible, than having more effort put towards optimizing XB as it is. Pregenerated optimized code should produce the fastest possible unmarshaller (and marshaller for that matter), especially using SAX or StAX from the generated code.

[aloubyansky]

I know that there are definitely things to improve in XB and I'd also like to see whether it'd be worth to spend time on it.
That's why I want to at least have a picture of what's going on with the current impl. I don't think there have been an effort to get it.
You can't avoid pure XML parsing, right? The rest is what can be optimized.

So, it appears that total unmarshalling time (including all the XML files) during AS start-up consists of ~33% of pure XML parsing (xerces) + ~67% of the XB code on top of it.

[aloubyansky]

I've run simple comparison tests for fastjaxb from resteasy and xb based on the "person" test from fastjaxb.
The results don't look that promising for fastjaxb, especially taking into account its binding features at this point are still primitive.

repetitions - number of unmarshallings of Person
total - total time in ms for all the repetitions
avg - average time ms for single repetition

repetitions 1
fast jaxb total=139, avg=139.0
xb total=47, avg=47.0

repetitions 10
fast jaxb total=151, avg=15.1
xb total=106, avg=10.6

repetitions 100
fast jaxb total=249, avg=2.49
xb total=286, avg=2.86

repetitions 1000
fast jaxb total=1057, avg=1.057
xb total=1402, avg=1.402

Here is the test

public class FastJaxbUnitTestCase extends TestCase
{
 public FastJaxbUnitTestCase()
 {
 }

 private long repetitions = 1000;
 public void testFastJaxb() throws Exception
 {
 ParsingCommand c = new FastJaxbParsing(repetitions);
 c.run();
 System.out.println("fast jaxb total=" + c.getTotal() + ", avg=" + c.getAverage());
 }

 public void testXB() throws Exception
 {
 ParsingCommand c = new XBParsing(repetitions);
 c.run();
 System.out.println("xb total=" + c.getTotal() + ", avg=" + c.getAverage());
 }

 private static class XBParsing extends ParsingCommand
 {
 private static final UnmarshallerFactory factory = UnmarshallerFactory.newInstance();
 private SchemaBinding schema;

 protected XBParsing(long repetitions)
 {
 super(repetitions);
 }

 @Override
 protected void setup() throws Exception
 {
 super.setup();
 schema = JBossXBBuilder.build(Person.class);
 }

 @Override
 protected void parse() throws Exception
 {
 Unmarshaller unmarshaller = factory.newUnmarshaller();
 unmarshaller.unmarshal(xmlUri, schema);
 }
 }

 private static class FastJaxbParsing extends ParsingCommand
 {
 private static SAXParserFactory factory = SAXParserFactory.newInstance();
 static
 {
 factory.setNamespaceAware(true);
 }

 private Sax sax;

 protected FastJaxbParsing(long repetitions)
 {
 super(repetitions);
 }

 @Override
 protected void parse() throws Exception
 {
 SAXParser parser = factory.newSAXParser();
 parser.parse(xmlUri, sax);
 }

 @Override
 protected void setup() throws Exception
 {
 super.setup();
 HashMap<String, Handler> map = new HashMap<String, Handler>();
 map.put("urn:person", new Person_Parser());
 sax = new Sax(map);
 }
 }

 private static abstract class ParsingCommand
 {
 protected long repetitions;
 protected long total;
 protected String xmlUri;

 protected ParsingCommand(long repetitions)
 {
 this.repetitions = repetitions;
 }

 public long getTotal()
 {
 return total;
 }

 public double getAverage()
 {
 return ((double)total)/repetitions;
 }

 public long getRepetitions()
 {
 return repetitions;
 }

 protected void setup() throws Exception
 {
 xmlUri = Thread.currentThread().getContextClassLoader().getResource("person.xml").toExternalForm();
 }

 protected abstract void parse() throws Exception;

 public void run() throws Exception
 {
 setup();

 for(int i = 0; i < repetitions; ++i)
 {
 long start = System.currentTimeMillis();
 parse();
 total += System.currentTimeMillis() - start;
 }
 }
 }
}

[aloubyansky]

Just wanted to add I added more addresses to the person.xml to make the file larger. To be more specific 10 address and 12 business-addresses.

[aloubyansky]

The time results for each number of repetitions are consistent in differences, i.e. for each number of repetitions the winner is consistent with more or less the same difference.

[dmlloyd]

I knew he should have used StAX :-)

It should not be possible that a reflective impl is faster than a generated impl. It's just a question of tweaking things I suspect.

[aloubyansky]

XB could have used StAX as well.

[adrian.brock]

The time results for each number of repetitions are consistent in differences, i.e. for each number of repetitions the winner is consistent with more or less the same difference.

I don't think that is true looking at the numbers you post.
fast jaxb is clearly faster at the binding,
but slower at building the model (looking at the numbers for one repetition).

e.g. If you look at the last 900 reps (the 1000 case - 100 case) you get:

fastjaxb = 808 (1057-249) avg 0.89ms
xb=1116ms (1402-286) avg 1.24ms

The slow part of building the model will obviously be the code generation.
I imagine this would get even slower as it becomes more feature rich?

If the code generation was moved to compile time (like xjc), then having
already generated classes will obviously out perform the reflection used by JBossXBBuilder.

I knew he should have used StAX :-)

StAX has nothing to do with the binding. It will probably be faster overall,
but it just replaces the SAX xml parsing, something that has to be done for both cases.
That is 33% of the time versus 67% for binding according the numbers Alex posted above.

If Alex's numbers are typical (never trust a simple benchmark ;-), then
a precompiled fast jaxb implementation might reclaim ~30% (1-808/1116) of that 67%
binding time. i.e. ~20% (.3 * 67%) of the overall time.

Which would mean the overall xml startup would be 2 seconds instead of 2.4 seconds.
Not exactly a huge improvement. :-(

[aloubyansky]

"adrian" wrote:
fast jaxb is clearly faster at the binding

But binding was out of the scope of the test.

"adrian" wrote:
If the code generation was moved to compile time (like xjc), then having
already generated classes will obviously out perform the reflection used by JBossXBBuilder.

Fast jaxb parsers had been generated and compiled before the test run.

[dmlloyd]

Perhaps a more accurate benchmark would involve a single document with, say, 12 to 20 different namespaces in it. This would be more reflective of the concerns that there's a substantial per-namespace cost.

[dmlloyd]

"adrian" wrote:
fast jaxb is clearly faster at the binding

But binding was out of the scope of the test.

I'd say not, since we are doing it at runtime in AS now, and that may be one source of startup time issues.

[dmlloyd]

I knew he should have used StAX :-)

StAX has nothing to do with the binding. It will probably be faster overall,
but it just replaces the SAX xml parsing, something that has to be done for both cases.

I wasn't really serious here, I was just alluding to a separate comment I made to Bill when he started the project. Guess it wasn't that funny anyway...

[aloubyansky]

The time results for each number of repetitions are consistent in differences, i.e. for each number of repetitions the winner is consistent with more or less the same difference.

I don't think that is true looking at the numbers you post.

What I meant was for 1 repetition the results are more or less consistent in difference, for 10 repetitions too, for 100 and 1000 as well.

[adrian.brock]

"adrian" wrote:
fast jaxb is clearly faster at the binding

But binding was out of the scope of the test.

I don't understand that? Surely the unmarshaller.parse() will bind the xml to the
objects in both tests?

"adrian" wrote:
If the code generation was moved to compile time (like xjc), then having
already generated classes will obviously out perform the reflection used by JBossXBBuilder.

Fast jaxb parsers had been generated and compiled before the test run.

Ok, so what is fast jaxb doing that it is 3 times slower on the first iteration
(even though you have already pre-generated classes)?
Is it parsing the xml schema or something? Are you comparing apples to apples?