Performance issue in FSTIterator.next

[pavelbazika]

Hi,

I'm using bleve full text search, which uses couchbase as backend. Sometimes I observe high CPU consumption taking several minutes, sometimes even golang garbage collector cannot operate. Tracking the issue down pointed to FSTIterator.next method.

There are around ~400.000 items in the statesStack in my instance. All represents linear sequence of nodes (NumTransitions() == 1 for whole list). There was an optimization made by @steveyen in 462e86d which cuts linear sequence of nodes and spares OUTER loop. But it does not do so when all nodes are in linear sequence. Here is the code:

		// if the top of the stack represents a linear chain of states
		// (i.e., a suffix of nodes linked by single transitions),
		// then optimize by popping the suffix in one shot without
		// going back all the way to the OUTER loop
		var popNum int
		for j := len(i.statesStack) - 1; j > 0; j-- {
			if i.statesStack[j].NumTransitions() != 1 {
				popNum = len(i.statesStack) - 1 - j
				break
			}
		}
		if popNum < 1 { // always pop at least 1 entry from the stacks
			popNum = 1
		}

When all nodes are in linear sequence, popNum remains zero and is set to 1 after the cycle. In my opinion the condition is there for the case the stack top would have more transitions, but when all have 1, it causes looping.

Is it a bug in optimization or is it by intent?

Thanks for reviewing

[mschoch]

Thanks for the report.

I've been reading through the code, and your description, and I'm still trying to load this back into my brain (it has been a while).

Here is my understanding, please correct me wherever I go wrong:

1. You have some key in vellum which is both long and unique (recognizing this key means having some long sequence of states each with just one transition connecting them)
2. An iterator is currently pointing at this key
3. Someone calls Next() on this iterator
4. There is an optimization in place, which should help this case (rather than popping one item off the stack at a time, it looks to see if the previous state also has only one transition, in which case it keep popping them of all at once)
5. The optimization attempts to stop, once it reaches a state with more than one transition.
6. In your case, that condition is never met (because we got all the way back to the root?) And here it seems the optimization does not handle this scenario correctly. Even though it should have popped off many items, it instead behaves as if nothing was popped off (popNum = 0). It then forces popNum to 1.
7. At this point, does it work correctly (just slowly)? Meaning it pops items off one at a time in the outer loop? Or does forcing popNum=1 cause some invalid state and an infinite loop?

That's my rough understanding having read your issue and the code. If you think I'm misunderstanding please let me know.

Also going to ping @steveyen for any thoughts he might have...

My next step will be to try and create a test case that recreates the problem so I can better understand it.

Perhaps it isn't needed to fix this, but I'm curious, can you share anything about your data set that lets to ~400000 items in the stateStack?

[mschoch]

Thought I had some code to reproduce it, but seems my understanding is not correct. Although I see it taking a long time, it isn't in the reported section. So my reproduction must be missing something still.

[mschoch]

OK, I think I have reproduced the issue now.

[mschoch]

I have a fix up for review on Couchbase's gerrit review system. I still hope to discuss it further with @steveyen but that may not be possible.

In particular, my observations on this optimization are:

• the first time the optimization is attempted, it fails (because the start state has 0 transitions), I've concluded this is by design and the optimization is designed to kick-in on the next iteration
• the optimization does kick in on the next iteration, and the fix now identifies the case that all states examined in the for-loop satisfy the condition (j == 1), without this, we never hit an exit condition to set popNum

Open question: why does the loop stop with j > 0? I left that as-is for now, but it means that one more OUTER loop iteration happens, even after the optimization. Doesn't really affect performance, but an open question...

http://review.couchbase.org/c/vellum/+/134677

[pavelbazika]

Hi,

I think you understand the issue correctly. Regarding your first post, I do not know the details of how scorch and vellum operates, so I cannot say what's the purpose of using the FST iterator. But I can share a callstack for reference, it's in scorch merger:

#0  github.com/couchbase/vellum.(*FSTIterator).next (i=0xc0434002a0, lastOffset=-1, ~r1=...) at github.com/couchbase/vellum@v1.0.1/fst_iterator.go:267
#1  0x00000000009c4d24 in github.com/couchbase/vellum.(*FSTIterator).Next (i=0xc0434002a0, ~r0=...) at github.com/couchbase/vellum@v1.0.1/fst_iterator.go:185
#2  0x0000000000a4fc95 in gitlab.icewarp.com/go/zap/v14.(*enumerator).Next (m=0xc009263380, ~r0=...) at gitlab.icewarp.com/go/zap/v14@v14.0.1/enumerator.go:112
#3  0x0000000000a53616 in gitlab.icewarp.com/go/zap/v14.persistMergedRest (segments=..., dropsIn=..., fieldsInv=..., fieldsMap=0xc000f05650, fieldsSame=<optimized out>, 
    newDocNumsIn=..., newSegDocCount=8542, chunkMode=1026, w=0xc000f05620, closeCh=0xc005cbbaa0, ~r10=..., ~r11=<optimized out>, ~r12=...)
    at gitlab.icewarp.com/go/zap/v14@v14.0.1/merge.go:356
#4  0x0000000000a51eef in gitlab.icewarp.com/go/zap/v14.MergeToWriter (segments=..., drops=..., chunkMode=1026, cr=0xc000f05620, closeCh=0xc005cbbaa0, newDocNums=..., 
    numDocs=<optimized out>, storedIndexOffset=<optimized out>, fieldsIndexOffset=<optimized out>, docValueOffset=<optimized out>, dictLocs=..., fieldsInv=..., 
    fieldsMap=<optimized out>, err=...) at gitlab.icewarp.com/go/zap/v14@v14.0.1/merge.go:138
#5  0x0000000000a5172c in gitlab.icewarp.com/go/zap/v14.mergeSegmentBases (segmentBases=..., drops=..., path=..., chunkMode=1026, closeCh=0xc005cbbaa0, s=..., ~r6=..., 
    ~r7=<optimized out>, ~r8=...) at gitlab.icewarp.com/go/zap/v14@v14.0.1/merge.go:79
#6  0x0000000000a5133f in gitlab.icewarp.com/go/zap/v14.(*ZapPlugin).Merge (segments=..., drops=..., path=..., closeCh=0xc005cbbaa0, s=..., ~r5=..., ~r6=<optimized out>, 
    ~r7=...) at gitlab.icewarp.com/go/zap/v14@v14.0.1/merge.go:54
#7  0x0000000000a6f727 in gitlab.icewarp.com/go/bleve/index/scorch.(*Scorch).planMergeAtSnapshot (s=0xc0019ad400, ctx=..., options=0xc003cfe2d0, ourSnapshot=0xc002504180, 
    ~r3=...) at gitlab.icewarp.com/go/bleve@v1.0.11/index/scorch/merge.go:321
#8  0x0000000000a6df67 in gitlab.icewarp.com/go/bleve/index/scorch.(*Scorch).mergerLoop (s=0xc0019ad400) at gitlab.icewarp.com/go/bleve@v1.0.11/index/scorch/merge.go:68
#9  0x0000000000461361 in runtime.goexit () at runtime/asm_amd64.s:1357

(I've forked bleve (and zap, which depends on bleve) to our private repo, but the only change there against upstream v1.0.9 is applied ascii folding fix waiting in blevesearch/bleve#1434, so it is unrelated to this issue).

The index contains ~26000 parsed mails, has ~500MB in size and was created by adding mails in batches of ~200 items per batch + sometimes by adding 1 email when something was received during indexing. If you are interested I can ask my boss if it would be possible to share the index via some private link, but it seems you have already reproduced and fixed the issue.

[mschoch]

I wanted to follow-up here. A fix was merged into vellum, and a new release of bleve (v1.0.10) has been made including this fix.

Separately, I wanted to follow-up again on why you encountered this particular issue in the first place. First, a bit of background, bleve uses vellum to store it's term dictionary. This means that the keys stored in vellum are the terms indexed for a field in bleve. Now, in your case described here, you reported a vellum iterator, who's stack had "~400.000" items in it. On it's own, there is nothing wrong with this, but it is unusual. Essentially each state in the iterator's stack represent one byte in the key, which implies one of the keys in your vellum has length >400000. Coming back to how this can happen in a bleve index, it most likely means that you have a field indexed using the keyword analyzer (which does no transformations on the input), and that one of the source values for that field is very long (>400000 bytes).

Again, without knowing more about how you're using bleve, I cannot say this is wrong. But it's also possible that this is unexpected, and may ultimately lead to some other problems down the road, so I wanted to point it out now. If you have more questions just let me know.

[pavelbazika]

Hi, thanks for the reply.

It's a bit unexpected, but possible. I use standard analyzer with unicode tokenizer, but because I index email messages, there can be some strange or malformed message, like base64 part wrongly marked as text/plain or something like that. Then it can happen a term will be very long.

To know more, I'd need to get the affected email. As I have a core dump, is it somehow possible to retrieve document _id field from local variables available in the callstack shared above?

[mschoch]

It might be possible, but it happened during a merge, so it would likely involve combining several pieces of information.

An easier way would be for you to use the zap cmd-line utility, cmd/zap in the blevesearch/zap repo (be sure to use the correct branch). With this utility you should be able to run zap dict <path to zap file> <field name>. This will list all the terms in that field, and hopefully something will jump out at you as the problem.