Project

Profile

Help

Download (21.7 KB)

Support #6547 ยป Re_ [Saxon - Support #6547] Schema loading performance regressions - 2024-09-23T16_12_11Z.eml

Johan Walters, 2024-09-23 18:12

 
X-He-Spam-Score: -3.1
Return-Path: <johan.walters@visma.com>
Delivered-To: dropbox@plan.io
Received: from m.launch.gmbh ([127.0.0.1])
by m.launch.gmbh with LMTP
id EGarAUmT8WaAQggAJzdhvw
(envelope-from <johan.walters@visma.com>)
for <dropbox@plan.io>; Mon, 23 Sep 2024 18:11:53 +0200
X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on m.launch.gmbh
X-Spam-Level:
X-Spam-Status: No, score=-3.1 required=5.0 tests=BAYES_00,DKIM_SIGNED,
DKIM_VALID,DKIM_VALID_AU,DMARC_PASS,HTML_MESSAGE,RCVD_IN_DNSWL_NONE,
RCVD_IN_MSPIKE_H2,RCVD_IN_VALIDITY_CERTIFIED_BLOCKED,
RCVD_IN_VALIDITY_RPBL_BLOCKED,SPF_HELO_NONE,SPF_PASS autolearn=ham
autolearn_force=no version=3.4.6
X-Spam-Report:
* -1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1%
* [score: 0.0000]
* -0.1 SPF_PASS SPF check passed
* -0.1 DMARC_PASS DMARC check passed
* -0.0 RCVD_IN_DNSWL_NONE RBL: Sender listed at
* https://www.dnswl.org/, no trust
* [209.85.208.175 listed in list.dnswl.org]
* 0.0 SPF_HELO_NONE SPF: HELO does not publish an SPF Record
* -0.9 RCVD_IN_MSPIKE_H2 RBL: Average reputation (+2)
* [209.85.208.175 listed in wl.mailspike.net]
* 0.0 RCVD_IN_VALIDITY_RPBL_BLOCKED RBL: ADMINISTRATOR NOTICE: The
* query to Validity was blocked. See
* https://knowledge.validity.com/hc/en-us/articles/20961730681243
* for more information.
* [209.85.208.175 listed in bl.score.senderscore.com]
* 0.0 RCVD_IN_VALIDITY_CERTIFIED_BLOCKED RBL: ADMINISTRATOR NOTICE:
* The query to Validity was blocked. See
* https://knowledge.validity.com/hc/en-us/articles/20961730681243
* for more information.
* [209.85.208.175 listed in sa-trusted.bondedsender.org]
* 0.0 HTML_MESSAGE BODY: HTML included in message
* -0.1 DKIM_VALID_AU Message has a valid DKIM or DK signature from
* author's domain
* -0.1 DKIM_VALID Message has at least one valid DKIM or DK signature
* 0.1 DKIM_SIGNED Message has a DKIM or DK signature, not necessarily
* valid
X-Spam-Score: -3.1
Authentication-Results: m.launch.gmbh; dmarc=pass (p=none dis=none) header.from=visma.com
Authentication-Results: m.launch.gmbh; spf=pass smtp.mailfrom=visma.com
Authentication-Results: m.launch.gmbh;
dkim=pass (1024-bit key; secure) header.d=visma.com header.i=@visma.com header.a=rsa-sha256 header.s=google header.b=OhBOqMXa;
dkim-atps=neutral
Envelope-to: inbox+saxonica+f38e+saxon@plan.io
Received: from mail-lj1-f175.google.com (mail-lj1-f175.google.com [209.85.208.175])
(using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits)
key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256)
(No client certificate requested)
by m.launch.gmbh (Postfix) with ESMTPS id CECC116678F
for <inbox+saxonica+f38e+saxon@plan.io>; Mon, 23 Sep 2024 18:11:52 +0200 (CEST)
Received: by mail-lj1-f175.google.com with SMTP id 38308e7fff4ca-2f75c6ed428so45131101fa.0
for <inbox+saxonica+f38e+saxon@plan.io>; Mon, 23 Sep 2024 09:11:52 -0700 (PDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
d=visma.com; s=google; t=1727107912; x=1727712712; darn=plan.io;
h=to:subject:message-id:date:from:in-reply-to:references:mime-version
:from:to:cc:subject:date:message-id:reply-to;
bh=i+YyTqotx2D4xl996TNH76nEj5eKj7T1uoeJoPypIN8=;
b=OhBOqMXagH84xNK+10NKh5E34fleAmPsxQmJAXFQ5J+HH+ZXMxprXanJPbK05RaLbf
dFQLqplywCi2lQGzRwbDUVsAcpJtZ1K4O5lnnM9N6hhwpr5W0Z8a/kLPGUZszaXRcWJP
uSBYGfflXOD9cFTpRmTye1aVzeYBH0ic64iYw=
X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
d=1e100.net; s=20230601; t=1727107912; x=1727712712;
h=to:subject:message-id:date:from:in-reply-to:references:mime-version
:x-gm-message-state:from:to:cc:subject:date:message-id:reply-to;
bh=i+YyTqotx2D4xl996TNH76nEj5eKj7T1uoeJoPypIN8=;
b=md6Ojt2YTkM60ilNKQ03CbOkR9c1xm5gwHKCODpGa10NFovzCge0gQP//yzo2WRN3s
tO/88gyCmexp8DS4S8c+e+AxlhPAsOdwyPRoDHT77kmT0GpWVJqGGy1ajuH7flDREkud
ZK4UCZjqP7XQfu0cNcNzMk7uF3zkV6n3A+nhoQYrrVOG3oKI36XkyxIIZiedhc2NDDw5
BPgRg6Rg5iu7rvg+Mfpfm9tnSqW6sOySrIzGw5vDAf+UlseerUDT0YavN/oSFSx/4OgT
61KrLKa4oIm9D+hZFJ4sIZE8kzdJkfIHctjX2H99Aqps8NJOZ/fhN+n/ltPBaJbslKiW
xVgg==
X-Gm-Message-State: AOJu0YycjWF/gKqSXhzm2JoDwr5ms6pdA98XAqhPHkF2itjeFgeI9UHK
+lcSUoSq0X7beNQVBvoJpdD3iKrZVg9GM9rBLgQAfsfhWORGlaydK75b+kb5hrggEQ7FVAevL8N
kcsL8UDpUPmJBdf/sbMOuWarBYkZzmChOilXDFTKi3aa8rvpWGaM=
X-Google-Smtp-Source: AGHT+IHEYtCPeiB1rDlnCXkbr2Fghu8K/fWOUbR1iGcO5G5YBI2h1gDhVN4ynQh1C4X3fSpvBMkTiYwmH652DP7LayU=
X-Received: by 2002:a05:651c:508:b0:2f7:7216:d7ca with SMTP id
38308e7fff4ca-2f7cc213768mr62866961fa.13.1727107911647; Mon, 23 Sep 2024
09:11:51 -0700 (PDT)
MIME-Version: 1.0
References: <redmine.issue-6547.20240923122500.866@plan.io> <redmine.journal-26824.20240923143350.866@plan.io>
In-Reply-To: <redmine.journal-26824.20240923143350.866@plan.io>
From: Johan Walters <johan.walters@visma.com>
Date: Mon, 23 Sep 2024 18:11:40 +0200
Message-ID: <CAHNy0maKSM=xrax7-tkhXZLcEQyVvXVSiv+7kn5E1SGOJuHBRw@mail.gmail.com>
Subject: Re: [Saxon - Support #6547] Schema loading performance regressions
To: Saxonica Developer Community <inbox+saxonica+f38e+saxon@plan.io>
Content-Type: multipart/alternative; boundary="0000000000009069980622cba5fe"

--0000000000009069980622cba5fe
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

I will attach the set of schema files tomorrow.
I did test exporting the schema component files (scm), and using those
instead. I was surprised that all time spent in lookForCycles is still
there (I would have expected this to be bypassed). Also
AutomatonState.addSpecificTransition takes a noticeable time (replacing
getSpecificTransition?). Third up, ElementParticle.getElementParticleType
is noticeable (which it wasn't before).
Thanks for looking into this!

On Mon, 23 Sept 2024 at 16:33, Saxonica Developer Community <
notifications@plan.io> wrote:

> --- In your reply, please do not write below this line ---
> Issue #6547 <https://saxonica.plan.io/issues/6547?pn=3D1#change-26824> ha=
s
> been updated by Michael Kay.
> ------------------------------
>
>
> Are you able to share the schema set that you used for these measurements=
?
> I haven't come across any schema that's taking as long as this to process=
,
> and I strongly suspect that it is something specific to this particular
> schema. With performance, the devil is very often in the detail.
>
> As regards deferring the building of the finite state automaton until all
> schema documents are loaded, this is something we have been looking at fo=
r
> Saxon 13. The reason it's difficult is that the FSA is used not only when
> validating instance documents, but also to verify the subsumption rules.
> ------------------------------
> Support #6547: Schema loading performance regressions
> <https://saxonica.plan.io/issues/6547?pn=3D1#change-26824> open
>
> - *Author: *Johan Walters
> - *Status: *New
> - *Priority: *Low
> - *Category: *Schema-Aware processing
> - *Start date: *2024-09-23
> - *Applies to branch: *12
> - *Platforms: *Java
>
> Loading schemas in Saxon consumes a lot of time, which only seems to
> regress across versions. (Currently migrating from 9.9 to 12.1). I did so=
me
> performance measurements on 12.1 of which I would like to share my findin=
gs.
>
> The folowing method consumes a *lot* of CPU time:
> *com.saxonica.ee.schema.ElementDecl.addSubstitutionGroupMember* which is
> specifically caused by the following:
>
> this.substitutionGroupMembers.add(member);
> if (this.substitutionGroupMembers.size() > 10) {
> this.substitutionGroupMembers =3D new HashSet(this.substi=
tutionGroupMembers);
> }
>
> I fail to see the reason why the HashSet must be replaced by a new hashse=
t
> every time an item is added and the set size is over 10. HashSet#iterate,
> HashSet#putVal and ElementDecl#hashCode are quite costly. Is there any
> particular reason for this copying? I would be very happy if this behavio=
ur
> could be changed.
>
> Other performance hotspots:
>
> *EnterpriseConfiguration.getNamepsaceStatus* (also called from
> ElementDecl.addSubstitutionGroupMember via config.isSealedNamespace) Here=
,
> I suspect that hashCode() on NamespaceUri is not particularly performant.
> Perhaps implementing this explicitly on that class, e.g. forwarding to th=
e
> underlying String could help.
>
> *net.sf.saxon.tree.util.Navigator.getPath* (via SchemaReader.read ->
> SchemaElement.processAllAttributes -> XSDElement.prepareAttributes)
> Specifically, XSDElement.prepareAttributes tends to call Navigator.getPat=
h
> three times: by calling new ElementDecl, by calling new TypedReference an=
d
> directly as argument for this.element.setGeneratedId. It would be nice if
> this expensive path for 'this' (being used as locator) would be reused, a=
nd
> not recomputed inside the constructors of ElemDecl and TypedReference (vi=
a
> an overloaded constructor maybe?)
>
> *AutomationState.getSpecificTransition* of which 62% of the time is spent
> in Edge.getTerm(), which is strange, as it is just a simple getter.
>
> Some numbers, given a program where 490.000ms are spent in
> SchemaCompiler.readSchema: 281.000ms spent in ElementDecl.lookForCycles (=
of
> which 93.000ms spent in EnterpriseConfiguration.getNamspaceStatus and
> 140.000ms copying HashSets) 195.000ms spent in
> XSDElement.processAllAttributes (roughly 3x 63.000ms for each repeated
> Navigator.getPath) All of which I believe should be easily achievable und=
er
> 100s, given some optimizations.
>
> =C5=83ote that this is not a synthetic test: this involves reading 30 sch=
emas,
> each consisting of dozens of schema files, all of which are used in
> production.
>
> Also note that I applied a 'hack' to disable calling
> SchemaCompiler.makeAllAutomata() after each and every file (by subclassin=
g
> SchemaCompiler and overriding that method to a no-op). Without this, the
> whole processing time of loading all schema files becomes extreme (the li=
st
> of scheduledForAutomaton seems to only ever grow, never being reset) Stil=
l,
> calling makeAllAutomata() once for each schema (after reading all separat=
e
> schema files individually) takes another 224.000ms due to
> getSpecificTransition (on top of the aforementioned 490.000ms).
>
> It does not help to use SchemaCompiler.readMultipleSchemas for two reason=
s:
>
> - it forwards to SchemaReader.getSources, which expects
> targetNamespace not to be null. I pass a null as there is no particula=
r
> expected namspace. readSchema() handles this null properly.
> - it assumes all schemas contribute to the same targetNamespace, which
> is not the case, so things break
>
> In the past we used setDefferedValidationMode, which helped a lot, until
> it got deprecated and eventually removed. For this reason we stuck to 9.9
> for a long time.
>
> Are any of these issues fixed in versions after 12.1? Is there a chance
> (some of) these issues could be addressed in a next release? Are there
> other workarounds I could try to speed up processing?
>
> Kind regards,
>
> Johan Walters
> ------------------------------
>
> You have received this notification because you have either subscribed to
> or are involved in a project on Saxonica Developer Community site. To
> change your notification preferences, please click here:
> https://saxonica.plan.io/my/account?tour=3Dmail_preferences
>
> This notification was cheerfully delivered by <https://plan.io/>
> [image: Planio] <https://plan.io/>
>

--0000000000009069980622cba5fe
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div>I will attach the set of schema files tomorrow.</div>=
<div>I did=20
test exporting the schema component files (scm), and using those=20
instead. I was surprised that all time spent in lookForCycles is still=20
there (I would have expected this to be bypassed). Also AutomatonState.addS=
pecificTransition takes a noticeable time (replacing getSpecificTransition?=
). Third up, ElementParticle.getElementParticleType is noticeable (which it=
wasn&#39;t before).</div><div>Thanks for looking into this!</div></div><br=
><div class=3D"gmail_quote"><div dir=3D"ltr" class=3D"gmail_attr">On Mon, 2=
3 Sept 2024 at 16:33, Saxonica Developer Community &lt;<a href=3D"mailto:no=
tifications@plan.io">notifications@plan.io</a>&gt; wrote:<br></div><blockqu=
ote class=3D"gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;border-left:1px=
solid rgb(204,204,204);padding-left:1ex"><div class=3D"msg-138560601189562=
5115"><u></u>







<div style=3D"font-family:&quot;ProximaNova-Regular&quot;,Helvetica,Arial,s=
ans-serif;font-size:14px;line-height:1.4em;color:rgb(51,52,52)">
<table width=3D"100%" cellspacing=3D"0" cellpadding=3D"0" style=3D"border-c=
ollapse:collapse;border-spacing:0px;margin-bottom:0px;width:100%;border:med=
ium;padding:0px">
<tbody><tr><td style=3D"text-align:center;width:100%;font-family:MarketWeb,=
Helvetica,Arial,sans-serif;font-size:0.8em;color:rgb(215,215,215);border:me=
dium;padding:0px"><p>--- In your reply, please do not write below this line=
---</p></td></tr>
<tr><td style=3D"border:medium;padding:0px">Issue <a href=3D"https://saxoni=
ca.plan.io/issues/6547?pn=3D1#change-26824" style=3D"color:rgb(0,136,183)" =
target=3D"_blank">#6547</a> has been updated by Michael Kay.
<hr style=3D"width:100%;height:1px;background:rgb(204,204,204);border:0px;m=
argin:1.2em 0px">

<ul style=3D"color:rgb(149,149,149);margin-bottom:1.5em">
</ul>

<p>Are you able to share the schema set that you used for these measurement=
s? I haven&#39;t come across any schema that&#39;s taking as long as this t=
o process, and I strongly suspect that it is something specific to this par=
ticular schema. With performance, the devil is very often in the detail.</p=
>
<p>As regards deferring the building of the finite state automaton until al=
l schema documents are loaded, this is something we have been looking at fo=
r Saxon 13. The reason it&#39;s difficult is that the FSA is used not only =
when validating instance documents, but also to verify the subsumption rule=
s.</p>
<hr style=3D"width:100%;height:1px;background:rgb(204,204,204);border:0px;m=
argin:1.2em 0px">
<h1 style=3D"font-family:&quot;ProximaNova-Bold&quot;,Helvetica,Arial,sans-=
serif;font-weight:normal;margin:0px;font-size:1.3em;line-height:1.4em">
<a href=3D"https://saxonica.plan.io/issues/6547?pn=3D1#change-26824" styl=
e=3D"color:rgb(0,136,183);text-decoration:none" target=3D"_blank">Support #=
6547: Schema loading performance regressions</a>
<span style=3D"font-weight:bold;font-size:10px;padding:1px 3px;margin-rig=
ht:2px;margin-left:2px;border-radius:2px;text-transform:uppercase;text-deco=
ration:none;color:rgb(32,93,134);border:1px solid rgb(32,93,134)">open</spa=
n>
</h1>

<ul style=3D"color:rgb(149,149,149);margin-bottom:1.5em"><li><strong>Author=
: </strong>Johan Walters</li>
<li><strong>Status: </strong>New</li>
<li><strong>Priority: </strong>Low</li>
<li><strong>Category: </strong>Schema-Aware processing</li>
<li><strong>Start date: </strong>2024-09-23</li>
<li><strong>Applies to branch: </strong>12</li>
<li><strong>Platforms: </strong>Java</li></ul>

<p>Loading schemas in Saxon consumes a lot of time, which only seems to reg=
ress across versions. (Currently migrating from 9.9 to 12.1). I did some pe=
rformance measurements on 12.1 of which I would like to share my findings.<=
/p>
<p>The folowing method consumes a <em>lot</em> of CPU time:
<strong>com.saxonica.ee.schema.ElementDecl.addSubstitutionGroupMember</stro=
ng>
which is specifically caused by the following:</p>
<pre style=3D"font-family:Hack,Consolas,Menlo,&quot;Liberation Mono&quot;,C=
ourier,monospace;font-size:85%;background-color:rgb(236,236,236);margin:1em=
0px;padding:8px;border:medium;border-radius:3px;width:auto;overflow:auto h=
idden"><code style=3D"font-family:Hack,Consolas,Menlo,&quot;Liberation Mono=
&quot;,Courier,monospace;font-size:85%;background-color:rgb(236,236,236);bo=
rder-radius:3px;margin:0px;padding:0px"> <span>this</span><span>=
.</span><span>substitutionGroupMembers</span><span>.</span><span>add</span>=
<span>(</span><span>member</span><span>);</span>
<span>if</span> <span>(</span><span>this</span><span>.</span><s=
pan>substitutionGroupMembers</span><span>.</span><span>size</span><span>()<=
/span> <span>&gt;</span> <span>10</span><span>)</span> <span>{</span>
<span>this</span><span>.</span><span>substitutionGroupMembe=
rs</span> <span>=3D</span> <span>new</span> <span>HashSet</span><span>(</sp=
an><span>this</span><span>.</span><span>substitutionGroupMembers</span><spa=
n>);</span>
<span>}</span>
</code></pre>
<p>I fail to see the reason why the HashSet must be replaced by a new hashs=
et every time an item is added and the set size is over 10. HashSet#iterate=
, HashSet#putVal and ElementDecl#hashCode are quite costly. Is there any pa=
rticular reason for this copying? I would be very happy if this behaviour c=
ould be changed.</p>
<p>Other performance hotspots:</p>
<p><strong>EnterpriseConfiguration.getNamepsaceStatus</strong> (also called=
from ElementDecl.addSubstitutionGroupMember via config.isSealedNamespace)
Here, I suspect that hashCode() on NamespaceUri is not particularly perform=
ant. Perhaps implementing this explicitly on that class, e.g. forwarding to=
the underlying String could help.</p>
<p><strong>net.sf.saxon.tree.util.Navigator.getPath</strong>
(via SchemaReader.read -&gt; SchemaElement.processAllAttributes -&gt; XSDEl=
ement.prepareAttributes)
Specifically, XSDElement.prepareAttributes tends to call Navigator.getPath =
three times:
by calling new ElementDecl, by calling new TypedReference and directly as a=
rgument for this.element.setGeneratedId.
It would be nice if this expensive path for &#39;this&#39; (being used as l=
ocator) would be reused, and not recomputed inside the constructors of Elem=
Decl and TypedReference (via an overloaded constructor maybe?)</p>
<p><strong>AutomationState.getSpecificTransition</strong>
of which 62% of the time is spent in Edge.getTerm(), which is strange, as i=
t is just a simple getter.</p>
<p>Some numbers, given a program where 490.000ms are spent in SchemaCompile=
r.readSchema:
281.000ms spent in ElementDecl.lookForCycles
(of which 93.000ms spent in EnterpriseConfiguration.getNamspaceStatus and 1=
40.000ms copying HashSets)
195.000ms spent in XSDElement.processAllAttributes (roughly 3x 63.000ms for=
each repeated Navigator.getPath)
All of which I believe should be easily achievable under 100s, given some o=
ptimizations.</p>
<p>=C5=83ote that this is not a synthetic test: this involves reading 30 sc=
hemas, each consisting of dozens of schema files, all of which are used in =
production.</p>
<p>Also note that I applied a &#39;hack&#39; to disable calling SchemaCompi=
ler.makeAllAutomata() after each and every file (by subclassing SchemaCompi=
ler and overriding that method to a no-op). Without this, the whole process=
ing time of loading all schema files becomes extreme (the list of scheduled=
ForAutomaton seems to only ever grow, never being reset)
Still, calling makeAllAutomata() once for each schema (after reading all se=
parate schema files individually) takes another 224.000ms due to getSpecifi=
cTransition (on top of the aforementioned 490.000ms).</p>
<p>It does not help to use SchemaCompiler.readMultipleSchemas for two reaso=
ns:</p>
<ul>
<li>it forwards to SchemaReader.getSources, which expects targetNamespace n=
ot to be null. I pass a null as there is no particular expected namspace. r=
eadSchema() handles this null properly.</li>
<li>it assumes all schemas contribute to the same targetNamespace, which is=
not the case, so things break</li>
</ul>
<p>In the past we used setDefferedValidationMode, which helped a lot, until=
it got deprecated and eventually removed. For this reason we stuck to 9.9 =
for a long time.</p>
<p>Are any of these issues fixed in versions after 12.1? Is there a chance =
(some of) these issues could be addressed in a next release? Are there othe=
r workarounds I could try to speed up processing?</p>
<p>Kind regards,</p>
<p>Johan Walters</p>


<div><div></div></div>

</td></tr>
<tr><td style=3D"font-size:0.8em;width:100%;border:medium;padding:0px"><hr =
style=3D"width:100%;height:1px;background:rgb(204,204,204);border:0px;margi=
n:1.2em 0px"><p>You have received this notification because you have either=
subscribed to or are involved in a project on Saxonica Developer Community=
site.
To change your notification preferences, please click here: <a href=3D"http=
s://saxonica.plan.io/my/account?tour=3Dmail_preferences" style=3D"color:rgb=
(0,136,183)" target=3D"_blank">https://saxonica.plan.io/my/account?tour=3Dm=
ail_preferences</a></p></td></tr>
<tr><td style=3D"text-align:center;width:100%;font-family:MarketWeb,Helveti=
ca,Arial,sans-serif;font-size:1.2em;color:rgb(215,215,215);border:medium;pa=
dding:0px"><br><div><a href=3D"https://plan.io/" style=3D"color:rgb(215,215=
,215);text-decoration:none" target=3D"_blank">This notification was cheerfu=
lly delivered by</a></div></td></tr>
<tr><td style=3D"text-align:center;width:100%;border:medium;padding:0px"><a=
href=3D"https://plan.io/" title=3D"Planio" style=3D"color:rgb(0,136,183)" =
target=3D"_blank"><img src=3D"https://assets.plan.io/images/planio_logo_gra=
y_204x50.png" height=3D"25" width=3D"102" border=3D"0" alt=3D"Planio" style=
=3D"vertical-align: middle; border: medium;"></a></td></tr>
</tbody></table>
</div>

</div></blockquote></div>

--0000000000009069980622cba5fe--
    (1-1/1)