Performance when using recommender

[senier]

I noticed a significant performance impact on annotating when using a recommender (in this case I'm using the built-in Multi-Token Sequence Classifier (OpenNLP NER)).

When the recommender is active, annotation becomes more sluggish after a while. Single-clicking a label may then take 0.5-1 second, which significant hampers the workflow. At some point, the UI may not accept any inputs for a while (i.e. the single clicked labels don't get accepted for a while or at all). Reloading the page rectifies the situation, at least for a while.

I noticed those pop up messages appearing frequently (but unsure whether this is related):

Is that expected? Is there anything wrong with my setup? It's a single-user setup running locally. The system has 32GiB of RAM of with only 50% is being used. The JVM (openjdk 17.0.6) runs with the default limit of 8GiB. The CPU is a fairly recent Intel Core i7. I'm running Linux and tried Chrome and Firefox with the same result.

I'm using 27.2.

Thanks!

[reckart]

It sounds like there might be some kind of leak on the browser side. Do you use any sidebars while annotating, and if so which one(s)? You could try starting INCEpTION with -Dwebsocket.enabled=false and check if that has a positive effect. However, note that the annotation sidebar won't be working in this mode.

[senier]

Thanks for the quick response!

Disabling web sockets made no difference. The problem happens when I don't use the annotations sidebar. When I do use the "Annotations" sidebar, I see similar issues with the Accept/Reject and Select/Delete buttons. They feel increasingly sluggish up to the point when they become unresponsive.

[reckart]

What is "a while" for you?

[senier]

Just checked: In one instance it hung after as little as 45 seconds, in another it was after ~5 minutes. Even before that, the lag made it hardly usable (like, you need to click labels multiple times to get them accepted).

[reckart]

Hm.... are you familiar with the developer tools in your browser?

You could start INCEpTION with -Ddebug.sendServerSideTimings=true.

Then open the annotation editor in Chrome. Open the Chrome developer
console and go to the network panel. Make sure it is activated.

Then perform an action which you feel takes too long. There should be one or more items added to the network panel by that action. Click on the one that took longest and look for the Timings panel. There should be a breakdown there what took how long. Can you please provide that information? That might help figuring out if the problem is on the browser side or on the server side.

[senier]

As everything felt too slow with debugging on, I labeled until the tool got stuck. When I clock (or it may actually be the hover event) on a suggestion, the following request is sent:

http://localhost:8080/p/foo/annotate?2-1.0-centerArea-editor

The timing is as follows:

Other UI elements (changing pages, changing labels from the right sidebar) work, but clicking on the suggested labels doesn't seem to have any effect (except for sending the above request).

Here is a particularly slow request to /annotate?2-2.0-centerArea-editor (after reloading the page, when it didn't get stuck, yet):

[reckart]

500ms is slow but not unbearably slow, right? The server-side timing stats in the second screenshot account for about 50% of the "waiting for server" time - but the "Server-side total" line does not seem to be visible here. It would be nice to see if there is a difference between the "server-side total" in the lower part and the "waiting for server" in the upper part.

How many rows do you display at a time in the brat view? Still 1?

[senier]

Frankly, it feels slower than 500ms to me. There is no more information than that in the "Timing" tab. I've never seen "Server-side total". Any idea how to get those?

I tried 1 row as well as 8 rows. More rows feel slower, but that may be totally subjective.

[reckart]

The "Server side total" is generated on the server side by INCEpTION - it is specific to INCEpTION. It captures the time between the earliest easily accessible point the request is received to the latest easily accessible point where the response is sent.

The entire transaction consists of a browser part (usually slowest is rendering), a network part (usually slowest is latency), and a server-side part (bottlenecks may vary).

We looked mainly at the network and server side part so far. If you want to get an idea of the client-side of the transaction, you can go to the Performance tab in Chrome, start recording, then perform a single action (e.g. create an annoatation), and then stop recording. Try avoiding passing over/hovering over other annotations or such during the processing.

[duesentrieb-net]

Hello!

We have absolutely the same problem.
When using the Accept / Reject / Delete buttons, it now takes a very long time.
The console shows response times of about 1,800ms.

If you create a new project, it is still very fast, but it gets slower and slower with each document that you processed. The 1.800ms come from a project with 150 documents at the moment. One document has on average 30 lines.
If you have a solution to the problem, we would be very grateful. If we should have processed several hundred documents, it will move in the direction of 10 seconds.

Best regards
Johannes

[reckart]

Can you also provide a breakdown of the server-side timings by setting -Ddebug.sendServerSideTimings=true (cf. #3916 (comment)). Also, when you open the recommender sidebar and click on the "log" button, how many recommendations does it tell you are being generated/inherited?

[duesentrieb-net]

Hello reckart,

we have found out that the whole problem is user-dependent. On the one hand, within a project: as soon as a user has annotated more than 100 documents, it becomes much slower. But also across all projects: a user who has annotated more than 1,000 documents in total over different projects becomes much slower within a project.

A workaround would therefore be to create a new user every 100 documents.

Best regards
Johannes

[reckart]

I believe this PR should remove the problem: #3938

[duesentrieb-net]

Depending on the project, the predictions are between 40 and 130, whereby the documents from projects with 40 to 50 are not faster than those with 110 to 130.

Here is a screenshot with the server-side timings:

[reckart]

Please try the latest INCEpTION 27.5. That includes #3938 which should (hopefully) resolve the performance issue with the recommenders.

[duesentrieb-net]

Actually a good idea, but the projects contain a lot of personal data of third parties, which we are unfortunately not allowed to give out.

Is there anything we can investigate for you?

[reckart]

Are you familiar with VisualVM?

[duesentrieb-net]

Unfortunately not.
Unless you describe to us what we should do, how and where.
We are also not Java developers (more in the field of web development and Python).
We just use Inception :-)

[reckart]

Write me an email - we'll see what we can do.

[reckart]

@duesentrieb-net This PR introduced a write-through cache for the learning records (and does a ton of refactoring...). I wouldn't be surprised it the refactoring had introduced some bugs though...

I also noticed that the learning records are not part of the project export/import - thus moving a project that is slow due to learning records from a prod-server to a test-server will speed the project up simply by discarding the learning records.... including this data in the export has a separate issue now.

[senier]

Thanks for working on that issue! I'm on a business trip and cannot test whether the new release fixes my problem right now. When I'm back next week, I'll test it. If the issue persists, I'll be able to share example data privately with you.

[reckart]

I don't see anything unusual at the moment here either.

You say that certain parts of the UI are still reacting if the application stalls. Could it be that maybe just the central editor part of the browser-side crashes? Can you open the JavaScript developer console and check if you see errors being logged there?

[senier]

Thinking about it, that makes a lot of sense as reloading the page rectifies the issue. And indeed, an exception gets thrown:

Uncaught TypeError: this.arcDragOriginGroup is undefined
    startArcDrag AnnotatorUI.ts:231
    onMouseMove AnnotatorUI.ts:285
    post Dispatcher.ts:110
    registerHandlers Visualizer.ts:3832
    jQuery 2
        dispatch
        handle
AnnotatorUI.ts:231:4

The very same exception keeps happening when I continue to interact with the app after that.

Earlier I can see another exception in the logs. That's before the app stops responding:

Uncaught TypeError: t.highlightPos is undefined
    renderHighlightBox Visualizer.ts:3628
    renderHighlightBoxes Visualizer.ts:3623
    onMouseOverSpan Visualizer.ts:3567
    onMouseOver Visualizer.ts:3724
    post Dispatcher.ts:110
    registerHandlers Visualizer.ts:3832
    jQuery 2
        dispatch
        handle
Visualizer.ts:3628:25

[reckart]

Thanks! I'll check if looking at the code at these respective locations make me any wiser - if not, I may come back to ask for sample data :)

[reckart]

@senier I have tried to make this code a bit more robust in v27.8 - please try. My assumption is that it may be an input action timing issue since you seem to be having the problem in irregular intervals and probably not always at the same place/under the same condition. If you still run into the problem, it would be helpful if you could privately provide me with a project that allows reproducing the issue with a deterministic sequence of actions.

[senier]

I accepted a significant amount of recommendations with v27.8 and the issue did not occur! No exceptions in the JS console or from the Java process either. Looks like that's fixed. Thanks, @reckart!

[reckart]

That's great! Thanks for letting us know :)