Sparsemapcontent insertion performance degrades with 1000+ nodes

[Chris Tweney]

Nakamurians, and Ian--

Please see [1] for some depressing test results. I ran some jmeter tests
that POST a lot of nodes with a single string property about 60K in
size. All the nodes go into a single path with random names
(/~admin/test/kern-2196/nodeXYZ).

As long as you start with an empty server and only POST about 1000 nodes
everything seems fine; throughput is about 18/s. Past 1000 nodes,
performance starts dropping dramatically, until on a server with about
2500 nodes on it the throughput was down to 1.5/s. Restarting the server
did not help.

Obviously we need to look at this and decide what to do.

[1]
https://jira.sakaiproject.org/browse/KERN-2196?focusedCommentId=137632&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-137632

--
Chris Tweney, Senior Software Developer
Educational Technology Services
University of California, Berkeley
ch...@media.berkeley.edu

[Chris Tweney]

For those of a more visual bent, a graph of the performance dropoff is
at [2]. JMeter's graph tool wraps at the 2000th sample, so the top blue
line is avg time of samples 2000-2406. Note that the slope of the avg
time line increases at sample ~2200.

Node size doesn't seem to make a difference. I ran some tests with
600-byte and 6000-byte nodes, and the response time curves were similar.

[2]
https://jira.sakaiproject.org/secure/attachment/28044/60000-byte-graph.png

-chris

[Nicolaas Matthijs]

Hi everyone,

I wanted to bump this thread up again because I wouldn't want it to
get lost. It sounds
like this could be an issue, and it would be great if we could get
some other back-end
eyes on this and some assessment as to what this means for a v1 release and
pilot deployments.

Thanks,
Nicolaas

> --
> You received this message because you are subscribed to the Google Groups
> "Sakai Nakamura" group.
> To post to this group, send email to sakai-...@googlegroups.com.
> To unsubscribe from this group, send email to
> sakai-kernel...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/sakai-kernel?hl=en.
>
>

[John Norman]

In terms of importance/priority, how much of a problem is this? Loading 200,000 users at 1 every 10s would take 2,000,000 = 23 days

Loading 20,000 users at 1 per second would take 5 and a half hours (would complete overnight).

I'm not saying it is not a problem, but unless it is symptomatic of problems in other areas it might not be critical right now. We might also be interested in user creation time for synchonisation and/or create account on demand scenarios, but a big one-off batch task that is subsequently manageable may not be so bad.

Just a thought.

John

John Norman
Director - CARET
University of Cambridge
jo...@caret.cam.ac.uk
+44-1223-765367

[Clay Fenlason]

I may be misunderstanding the test, but I'd thought sparsemapcontent
handled not only users but also content in general.

~Clay

[Carl Hall]

Sparse does handle users and content. Chris's testing has been focusing on the newly implemented feature to store data that is over 64k in size. Chris tested yesterday with MySQL with like results. No tests against a nosql db have been conducted but I have high interest in knowing how Cassandra or Mongo would fare in these tests.

We still need to dig down into this to see where the slowdown is occurring. I don't know if reads would be affected in the same way writes were in these tests. While these tests do show an bottleneck in the system, they may represent a scenario that institutions may not reach for a while. More testing and profiling will help us see how this unfolds.

If it helps anyone, NYU is in production with a good amount of information and have not experienced any slowdowns.

[Nicolaas Matthijs]

Yes, that's right. Sparsemapcontent deals with all user generated content.
If this is only an issue with insertion performance dropping, I would agree with
John in that it's probably not critical at this point and end users
wouldn't probably
really be hit by this slowdown. Performance degradation in retrieving this data
would probably be a critical issue though. Do we have any data on this?

Thanks,
Nicolaas

[Ray Davis]

Remember, however, that SparseMapContent also deals with all Activity
records, and Activity logging is *extremely* write-intensive, easily
stacking up hundreds or thousands of insertions for a single piece of
"real" content over time, few of which will ever be read more than once.
Moreover, the last time I checked Activity records were being stored in
the same table as "real" content.

If that's still the case, it might be good to add a JIRA task to break
Activity logging out into a separate storage area, since its tuning and
maintenance requirements tend to conflict with the requirements typical
for other sorts of data.

Best,
Ray

[Chris Tweney]

Ian's been notified and a sparsemapcontent bug filed at [1]. He's
investigating further to see where the bottleneck is, although given his
moving schedule I'm not sure how soon we can expect any action.

Nico, I'll do a test to see what happens to reads once the insertion
slowdown point is reached. Expect results later today.

[1] https://github.com/ieb/sparsemapcontent/issues/85

-chris

On 9/2/11 7:52 AM, Nicolaas Matthijs wrote:

[John Norman]

But doesn't activity logging use a messaging infrastructure (JMS?) that decouples timing and allows load smoothing? IIUC it also allows logs to be routed anywhere, so perhaps having them in with other content was only ever intended to be temporary...

Separately, I thought we were likely to come back round to number of requests per user action at some point because this /might/ be an issue that limits performance in a cluster. It occurs to me that such a change might reduce log volume too, but that presumably depends on whether logging is at the request level or at the level of complete user transaction.

Perhaps the question should be to the server leads: should we be alarmed by this analysis? If storage of over 64K is new, then how much of the overall system behaviour is affected?

J

[Chris Tweney]

John--

Just to be maximally clear: Storage of over 64K is not the issue. That was just the initial route to my discovery.

The performance dropoff happens with a defaultly configured derby-backed Nakamura handling nodes of any size. Most of my tests use 60000-byte nodes, but the dropoff is also observable with 600-byte nodes.

-chris

[Carl Hall]

All events generated by the system are sent out using JMS as a means for integration but activity logging is written to the content store to allow for activity feeds in the system. This could be offloaded using JMS to put activity in some other storage container but that's a can of worms we haven't opened yet. We can also investigate creating another namespace to split the storage of activities away from regular content. It's not a simple task but not impossible.

IIRC activity logging is a caused manually and not connected to request level access logging.

I am concerned by the results from the testing but I don't have a good connection to how it relates to real world usage so I am not yet alarmed.

[Chris Tweney]

To answer Nico's question: Lookup performance does *not* appear to
suffer when the insertion degradation has manifested. Discussion at [1].
Pretty graph at [2].

Bottom line: Get performance takes about 1000 requests to ramp up, then
levels off at a constant plateau. It was about the same before the big
insert run as after it.

During the big insertion run, the bottleneck is definitely in sparse,
[3], specifically in WideColumnIndexer.internalHasNext, which takes
57.5% of the cpu time in the run.

[1]
https://jira.sakaiproject.org/browse/KERN-2196?focusedCommentId=137815&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-137815

[2]
https://jira.sakaiproject.org/secure/attachment/28105/600-byte-gets-after-insertion-jprofiling-graph.png

[3]
https://jira.sakaiproject.org/secure/attachment/28108/jprofiler-hotspots-during-600byte-insert-run.png

-chris

[Zach Thomas]

I agree with Ray that storing an audit trail of activities is
different in character from the rest of the content we store.

I'm in favor of getting the activities into a storage medium that is a
happier fit for it, like MongoDB[1] or Redis[2].

This would simultaneously improve our auditing / analytics capability
and take a considerable strain off Oracle, MySQL, or whatever.

[1] http://blog.mongodb.org/post/172254834/mongodb-is-fantastic-for-logging
[2] http://blog.grayproductions.net/articles/where_redis_is_a_good_fit

On Sep 2, 12:12 pm, Chris Tweney <ch...@media.berkeley.edu> wrote:
> To answer Nico's question: Lookup performance does *not* appear to
> suffer when the insertion degradation has manifested. Discussion at [1].
> Pretty graph at [2].
>
> Bottom line: Get performance takes about 1000 requests to ramp up, then
> levels off at a constant plateau. It was about the same before the big
> insert run as after it.
>
> During the big insertion run, the bottleneck is definitely in sparse,
> [3], specifically in WideColumnIndexer.internalHasNext, which takes
> 57.5% of the cpu time in the run.
>

> [1]https://jira.sakaiproject.org/browse/KERN-2196?focusedCommentId=13781...
>
> [2]https://jira.sakaiproject.org/secure/attachment/28105/600-byte-gets-a...
>
> [3]https://jira.sakaiproject.org/secure/attachment/28108/jprofiler-hotsp...

>
> -chris
>
> On 9/2/11 8:39 AM, Chris Tweney wrote:
>
>
>
>
>
>
>
> > Ian's been notified and a sparsemapcontent bug filed at [1]. He's
> > investigating further to see where the bottleneck is, although given
> > his moving schedule I'm not sure how soon we can expect any action.
>
> > Nico, I'll do a test to see what happens to reads once the insertion
> > slowdown point is reached. Expect results later today.
>
> > [1]https://github.com/ieb/sparsemapcontent/issues/85
>
> > -chris
>
> > On 9/2/11 7:52 AM, Nicolaas Matthijs wrote:
> >> Yes, that's right. Sparsemapcontent deals with all user generated
> >> content.
> >> If this is only an issue with insertion performance dropping, I would
> >> agree with
> >> John in that it's probably not critical at this point and end users
> >> wouldn't probably
> >> really be hit by this slowdown. Performance degradation in retrieving
> >> this data
> >> would probably be a critical issue though. Do we have any data on this?
>
> >> Thanks,
> >> Nicolaas
>
> >> On Fri, Sep 2, 2011 at 3:42 PM, Clay Fenlason

> >> <clay.fenla...@et.gatech.edu>  wrote:

> >>> I may be misunderstanding the test, but I'd thought sparsemapcontent
> >>> handled not only users but also content in general.
>
> >>> ~Clay
>

> >>> On Fri, Sep 2, 2011 at 10:00 AM, John Norman<j...@caret.cam.ac.uk>  

> >>>>https://jira.sakaiproject.org/secure/attachment/28044/60000-byte-grap...

>
> >>>> -chris
>
> >>>> On 8/30/11 4:51 PM, Chris Tweney wrote:
>
> >>>> Nakamurians, and Ian--
>
> >>>> Please see [1] for some depressing test results. I ran some jmeter
> >>>> tests
>
> >>>> that POST a lot of nodes with a single string property about 60K in
> >>>> size.
>
> >>>> All the nodes go into a single path with random names
>
> >>>> (/~admin/test/kern-2196/nodeXYZ).
>
> >>>> As long as you start with an empty server and only POST about 1000
> >>>> nodes
>
> >>>> everything seems fine; throughput is about 18/s. Past 1000 nodes,
>
> >>>> performance starts dropping dramatically, until on a server with
> >>>> about 2500
>
> >>>> nodes on it the throughput was down to 1.5/s. Restarting the server
> >>>> did not
>
> >>>> help.
>
> >>>> Obviously we need to look at this and decide what to do.
>
> >>>> [1]
>

> >>>>https://jira.sakaiproject.org/browse/KERN-2196?focusedCommentId=13763...

[Chris Tweney]

Here's the state of play on the insertion performance issue:

Ian found some issues with indexing in both Derby and MySQL that are
fixed (partly fixed in MySQL's case; a full fix would require porting
MySQL to the wide column used by Derby). These fixes flattened the
insertion-time graph, but did not make it perfectly flat (constant time
insertion).

I investigated [2] and found that Sling *even when not using the JCR*
uses StorageClient.listChildren() in a way that will make insertion time
increase linearly with the number of children under a node. JCR is known
not to support big flat content trees [3] but it seems that Sling
contains some of the same bad assumptions and is thus similarly afflicted.

Ironically, JCR's poor performance with big flat content trees was a
principal reason for the switch to sparse.

I am considering whether to report this to the Sling project as a Sling
bug.

[1] https://github.com/ieb/sparsemapcontent/issues/85

[2]
https://jira.sakaiproject.org/browse/KERN-2196?focusedCommentId=138039&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-138039

[3] https://issues.apache.org/jira/browse/JCR-642

-chris