160640 - arena performance is intolerable in debug builds

Status: RESOLVED WONTFIX

(NSS :: Libraries, defect, P3)

Description

[Julien Pierre]

I discovered this during my CRL work on partial decoding, while testing the lack
of performance of SEC_ASN1DecodeItem. The decoder was shown to be extremely
intensive in the number of arena alloc and free calls it makes.

It turns out that arena performance degrades greatly as it grows. I think the
two tests below speak for themselves.

1) I did a crlutil -d . -I -i bigcrl.der , where bigcrl.der is a 26 MB CRL.
This calls SEC_ASN1DecodeItem with an arena containing only that one object, and
a SECItem pointing to that large DER . This decoding operation takes about 3
minutes on a Solaris debug build.

2) I did a crlutil -d . -L with a cert7.db containing the aforementioned CRL.
This calls SEC_ASN1DecodeItem with the same object, but a very different arena -
one that has not only the DER but also about 260 MB of data already allocated in
it (see bug # 160635 ). This causes the decoding operation to take over 3
*hours*. Actually I don't exactly know how long it takes, I attached to the
process and saw that it was still doing the decode, and killed it.

3) Just for reference, I did a crlutil -d . -L with the same cert7.db, but with
a version of NSS using my new DER decoder (see # 149816 ) , which barely makes
any arena allocation call, and zero arena deallocation . It took the same time
to decode the CRL with the arena as for the import case with the same decoder,
which is to say about 10 seconds.

Comment 1

[Ian McGreer]

I guess I'm not surprised that performance is bad when dealing with 260MB of
memory.  What is the bug to be fixed with respect to arenas?  Would the heap do
any better?  I have no doubt that there are many places where NSS's use of
arenas is less than optimal, and you seem to have fixed one of them already. 
But I'm not sure there's a problem with arenas themselves.

If there is a problem with the arena implementation, it would be in NSPR (unless
it was a threading issue, but that wouldn't be the case here, as crlutil only
uses one thread).

Comment 2

[Julien Pierre]

Ian,

The bug is the arenas performance was shown to degrade so significantly as to be
useless when it grew to 260 MB. Perhaps this is only in debug builds - there may
be some code that checks the whole arena when deallocating, and since the
existing decoder makes millions of decode and free calls, this could explain
that it takes 3 hours. I will retest the two cases with an optimized build. I
don't know if the performance of the heap would be better at this point - except
that it's hard to imagine how it could be worse than 3 hours.

I'm not sure I entirely agree with you that the arena performance is entirely
NSPR's problem - there is a secport.c which wraps the NSPR arenas. There may be
something in it that slows it down. I didn't look at the code yet. What I do
know is that the code path for SEC_ASN1DecodeItem is not changing and the same
block of DER is passed to it with a different arena in the two cases, therefore
I concluded that the arena size was a significant degrading performance factor
and filed this bug.

As you pointed out, my new DER decoder takes care of the performance problem in
this case - but it does so by avoiding arena calls. This doesn't change the fact
that arenas are still used throughout NSS, so I think it is a useful to know the
performance shortcomings of arenas. We should either improve their performance
or reconsider their use, especially for stan.

Comment 3

[Julien Pierre]

I tested with the optimized build of the unmodified NSS tip, and it only took 40
seconds to decode even with the arena starting at 260 MB - which is the same as
when the arena starts at 26 MB - ie. it was the same time 1) and 2) referenced
at the beginning of this bug.

Since this only affects debug builds, I'm lowering priority to P2 / minor. It
still should be looked at eventually because it makes debugging of applications
with large arenas intolerable - I think 3 hours+ fits that definition.

Comment 4

[Julien Pierre]

I found that the arena passed to the ASN.1 decoder in the lookup case (2) had a
chunk size of 1 byte (!!!). I haven't found yet where that particular arena was
created, as tons of arenas are being created during the object lookup, and there
are three different copies of the arena code - in libnss3.so, libsoftokn3.so and
freebl_hybrid_3.so .

Comment 5

[Julien Pierre]

Never mind, this was just uninitialized data I was seeing, the chunksize is not
1 byte. The arena is being created in crl.c in SEC_LookupCrls, with a default
size of DER_DEFAULT_CHUNKSIZE, which is 2048 bytes.

So the chunk size is the same between cases 1) and 2), the only difference is
the content of the arena is near empty in case 1) and the arena has a lot more
data in case 2).

I increased the arena size from 2 KB to 256 KB, and this brought the 3 hour+
decoding time for the debug build down to 3 minutes.

I also tried case 1 - where the arena is empty - with the larger 256 KB chunk
size. The decoding time for that case with SEC_ASN1DecodeItem went down from 3
minutes to 42 seconds, still for the debug build. In the optimized build,
increasing the arena size only improved brought the time down from 38 seconds to
36 seconds.

My new SEC_QuickDERDecodeItem clocks in at just over 4 seconds for that last
case, and I didn't test it with the larger arena size as it doesn't make any
allocation and wouldn't be affected by it.

Comment 6

[Wan-Teh Chang]

There are two differences between the debug and
optimized arena code in NSS.

The first difference is in NSPR (plarena.{h,c}).
In the debug build, before a release or free, we
memset the memory with the special pattern 0xda.

The second difference is in NSS (secport.c).
In the debug build, the macro THREADMARK is
defined, which causes some code to be
conditonally compiled.

Note: in fact there is a third difference, in
Stan's lib/base/arena.c (NSSArena). There is some
pointer tracking code that *seems* to be
conditionally compiled in the debug build.  However,
I don't think the ASN.1 decoder (secasn1d.c or
quickder.c) uses Stan's arena code.

You can first try deleting the #ifdef DEBUG code
in plarena.{h,c}, and then try undefining
THREADMARK in secport.c, to see which contributes
to the intolerable arena performance in debug
builds.

Comment 7

[Julien Pierre]

I reran my original test case on Solaris. I noticed that when I set
NSS_DISABLE_ARENA_FREE_LIST, the performance problem disappears in the debug build.

Comment 8

[Julien Pierre]

Performance enhancement. Reprioritizing to P3.

Comment 9

[Julien Pierre]

The current development systems I'm using are too fast for this to matter, so
the debug build performance is quite tolerable now. Marking WONTFIX.