Skip to content

Right panel perf#604

Open
will-moore wants to merge 3 commits into
ome:masterfrom
will-moore:right_panel_perf
Open

Right panel perf#604
will-moore wants to merge 3 commits into
ome:masterfrom
will-moore:right_panel_perf

Conversation

@will-moore
Copy link
Copy Markdown
Member

@will-moore will-moore commented Jan 17, 2025

Improves performance of loading right panel for single Objects (Project, Dataset, Image, Screen, Plate, Well, PlateAcquisition)

I looked into the timing for getObject() with group: -1 and found that is slower when the user is logged-in to a large group (even if that group is private).

E.g. about 1 second in the code below.

It's actually faster to:

  • perform a preliminary queryService.get() to get the object, get it's group ID...
  • and then use that group ID for getObject()
  • These 2 queries take about 0.02 seconds in the code below.
import argparse
import sys
from datetime import datetime

from omero.cli import cli_login
from omero.gateway import BlitzGateway

def main(argv):
    parser = argparse.ArgumentParser()
    parser.add_argument('dataset', type=int, help='Dataset ID')
    args = parser.parse_args(argv)

    with cli_login() as cli:
        conn = BlitzGateway(client_obj=cli._client)
        dataset_id = args.dataset
        for test in range(10):
            start = datetime.now()
            if test % 2 == 0:
                # Use group: -1 via get(), then set group for conn.getObject()
                group_id = conn.getQueryService().get("Dataset", dataset_id, {'group': '-1'}).details.group.id.val
            else:
                group_id = -1
            conn.SERVICE_OPTS.setOmeroGroup(group_id,)
            dataset = conn.getObject("Dataset", dataset_id)
            print(datetime.now() - start, "group_id", group_id)

if __name__ == '__main__':
    main(sys.argv[1:])

prints:

0:00:00.031096 group_id 2
0:00:01.097150 group_id -1
0:00:00.028419 group_id 2
0:00:00.999497 group_id -1
0:00:00.019667 group_id 2
0:00:01.045434 group_id -1
0:00:00.021599 group_id 2
0:00:01.070055 group_id -1
0:00:00.023816 group_id 2
0:00:00.942411 group_id -1

@joshmoore
Copy link
Copy Markdown
Member

joshmoore commented Mar 15, 2025

Just tested this on the TiM server with about 200 users in the main workshop group. Unfortunately, @Tom-TBT and I are still seeing a number of calls (projections, findAllByQueries, etc.) taking on the order of 300ms to a postgresql on the same host when loading the right-hand panel:

web perf4j log
2025-03-15 21:15:57,206 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069756886] time[319] tag[omero.call.success.ome.logic.QueryImpl.projection]
2025-03-15 21:15:57,218 INFO  [                 org.perf4j.TimingLogger] (-thread-43) start[1742069757212] time[5] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2025-03-15 21:15:57,218 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069757210] time[8] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2025-03-15 21:15:57,492 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069757489] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:15:57,576 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069757243] time[333] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2025-03-15 21:15:57,819 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069757494] time[325] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2025-03-15 21:15:58,199 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069757822] time[377] tag[omero.call.success.ome.logic.QueryImpl.projection]
2025-03-15 21:15:58,266 INFO  [                 org.perf4j.TimingLogger] (-thread-43) start[1742069758261] time[4] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2025-03-15 21:15:58,266 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069758259] time[7] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2025-03-15 21:15:58,663 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069758308] time[355] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2025-03-15 21:16:02,469 INFO  [                 org.perf4j.TimingLogger] (-thread-43) start[1742069762464] time[5] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2025-03-15 21:16:02,470 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069762461] time[9] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2025-03-15 21:16:02,473 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069762471] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:16:02,474 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069762472] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:16:02,484 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069762475] time[9] tag[omero.call.success.ome.logic.QueryImpl.projection]
2025-03-15 21:16:02,800 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069762476] time[324] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2025-03-15 21:16:03,081 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069763079] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:16:03,119 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069762803] time[316] tag[omero.call.success.ome.logic.QueryImpl.projection]
2025-03-15 21:16:03,129 INFO  [                 org.perf4j.TimingLogger] (-thread-43) start[1742069763124] time[4] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2025-03-15 21:16:03,129 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069763122] time[7] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2025-03-15 21:16:03,408 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069763083] time[325] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2025-03-15 21:16:03,440 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069763134] time[306] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2025-03-15 21:16:03,737 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069763410] time[326] tag[omero.call.success.ome.logic.QueryImpl.projection]
2025-03-15 21:16:03,748 INFO  [                 org.perf4j.TimingLogger] (-thread-43) start[1742069763743] time[4] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2025-03-15 21:16:03,748 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069763741] time[7] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2025-03-15 21:16:04,100 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069763793] time[307] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2025-03-15 21:16:05,520 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069765518] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:16:05,850 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069765522] time[328] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2025-03-15 21:16:06,229 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069765853] time[376] tag[omero.call.success.ome.logic.QueryImpl.projection]
2025-03-15 21:16:06,242 INFO  [                 org.perf4j.TimingLogger] (-thread-43) start[1742069766237] time[4] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2025-03-15 21:16:06,243 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069766235] time[8] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2025-03-15 21:16:06,578 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069766247] time[330] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2025-03-15 21:16:09,738 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069769734] time[3] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]

Loading the same projects, datasets and images details only take sub-20ms (though mostly sub-10ms):

insight perf4j log
2025-03-15 21:17:43,707 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069863703] time[3] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:43,722 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069863710] time[11] tag[omero.call.success.ome.logic.MetadataImpl.loadAnnotations]
2025-03-15 21:17:43,729 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069863727] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:43,742 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069863735] time[6] tag[omero.call.success.ome.logic.QueryImpl.findAllByQuery]
2025-03-15 21:17:43,805 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069863803] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:43,831 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069863813] time[18] tag[omero.call.success.ome.logic.MetadataImpl.loadAnnotations]
2025-03-15 21:17:43,841 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069863839] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:43,853 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069863845] time[8] tag[omero.call.success.ome.logic.QueryImpl.findAllByQuery]
2025-03-15 21:17:44,483 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069864481] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:44,500 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069864488] time[12] tag[omero.call.success.ome.logic.MetadataImpl.loadAnnotations]
2025-03-15 21:17:44,508 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069864504] time[3] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:44,519 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069864511] time[7] tag[omero.call.success.ome.logic.QueryImpl.findAllByQuery]
2025-03-15 21:17:45,196 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069865193] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:45,213 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069865200] time[12] tag[omero.call.success.ome.logic.MetadataImpl.loadAnnotations]
2025-03-15 21:17:45,219 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069865216] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:45,229 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069865222] time[6] tag[omero.call.success.ome.logic.QueryImpl.findAllByQuery]
2025-03-15 21:17:46,228 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069866225] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:46,245 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069866232] time[12] tag[omero.call.success.ome.logic.MetadataImpl.loadAnnotations]
2025-03-15 21:17:46,252 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069866249] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:46,261 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069866257] time[4] tag[omero.call.success.ome.logic.QueryImpl.findAllByQuery]
2025-03-15 21:17:46,797 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1742069866794] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:46,819 INFO  [                 org.perf4j.TimingLogger] (.Server-21) start[1742069866802] time[16] tag[omero.call.success.ome.logic.MetadataImpl.loadAnnotations]
2025-03-15 21:17:46,829 INFO  [                 org.perf4j.TimingLogger] (.Server-25) start[1742069866826] time[2] tag[omero.call.success.ome.services.blitz.impl.ServiceFactoryI$3.doWork]
2025-03-15 21:17:46,840 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1742069866833] time[7] tag[omero.call.success.ome.logic.QueryImpl.findAllByQuery]

The result of the difference is that we're seeing right-hand panel loading times of upwards of 4 seconds.

@will-moore
Copy link
Copy Markdown
Member Author

@joshmoore. Do you know if this PR caused any improvement in the right panel loading times?

@joshmoore
Copy link
Copy Markdown
Member

The numbers with and without the PR were similar, with the 10ish calls of 300ms or so.

@joshmoore
Copy link
Copy Markdown
Member

By the way, the workaround we finally settled on was to move all pre-created conference users into a different, backup LDAP group and then on login have them moved back to the main conference group automatically.

cc: @pwalczysko

@will-moore
Copy link
Copy Markdown
Member Author

@pwalczysko "this is still a problem" - Need to find a server like learning where we can test this..

@pwalczysko
Copy link
Copy Markdown
Member

The testing setup:

Connect an OMERO.web running on testing VM (...train3...) to learning server.
Open images in Histology, with the Inspector of the RHP open. Harvest the image_metadata (or dataset_metadata) values from the "HTML" tab of the "Network" tab of the inspector as you click on thumbnails in central pane (all in FF on Mac).

With this PR, Images RHP values [ms]: 2687, 2836, 2736, 2752, 2675, dataset: 1008
Without this PR (5.29.3 release) [ms]: 3118, 3082, 3183, 3126, 3079, dataset: 1320.

This, as per calculation, is an improvement of 12%.
I would say that if there is any doubt with this PR otherwise, this improvement will not be outweighing the drawbacks.
But if this PR has no side-effects, then it could be merged imho.

@pwalczysko
Copy link
Copy Markdown
Member

backup LDAP group and then on login have them moved back to the main conference group automatically.

Yes, this is an approach which we are also adopting, thanks for explaining @joshmoore - we have adapted a script which is "cleaning up" the users. But this script has to be run once-a-year manually. On another server (SLS ns), such approach is not an option even (the default group "My Data" is getting quite full).

@pwalczysko
Copy link
Copy Markdown
Member

Sorry to bring up another topic (but quite important imho in this context): The biggest problem performance-wise in the "many users in the group" setup is actually less the RHP (although it would help to improve this dramatically). The main problem on the user-experience front is rather the slowness of opening images in full viewer (iviewer in our case).

@joshmoore
Copy link
Copy Markdown
Member

this is an approach which we are also adopting

Perhaps but let me be a bit more clear. We de-LDAP'd everyone to speed things up, in that sense it's similar. But we relied on the fact that with sync_on_login people would be moved back to the correct group if and only if they logged back in. (But you're right, this won't help for true large groups.)

@pwalczysko
Copy link
Copy Markdown
Member

But we relied on the fact that with sync_on_login people would be moved back to the correct group if and only if they logged back in.

Thanks for clarification.
We do the same, the difference might be between moved back to the correct group -> recreated the user into the correct group. The script in use is renaming the users when moving them into the alumni group in step 1. The reliance on the correct behaviour when they log back in is the same between the two cases (but we tested it thoroughly).
(@joshmoore the script is called inactivate_users.py and is in mngmt tools in learning folder).

@pwalczysko
Copy link
Copy Markdown
Member

@will-moore @joshmoore I have just ran the script mentioned in #604 (comment). This removed (out of some 600 users inside the original group which needed to be speeded up) some 530 users.

The effect of this removal:

The waiting time of RHP is now after the click on a thumb down to 827 ms, 951 ms etc. (just giving two numbers for 2 clicks on thumbs)

This means, compared with the times mentioned in #604 (comment) (around 3000 ms, improved by this PR to around 2700 ms, i.e. some 12%) we have an improvement of 66% (from 3 sec to 1 sec).
I know that it is "unfair" to compare those two improvements, but still, this is my "wished for" behaviour here :)

@pwalczysko pwalczysko closed this May 22, 2026
@pwalczysko pwalczysko reopened this May 22, 2026
Copy link
Copy Markdown
Member

@pwalczysko pwalczysko left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry, was too fast with the approval. Lets wait till the GHA finishes before merging.

Copy link
Copy Markdown
Member

@pwalczysko pwalczysko left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Now lgtm

{% if manager.share.isExpired %}
This {{ manager.share.getShareType|lower }} has expired and you no longer can make any comments.
{% else %}
<form id="add_share_comment_form" action="{% url 'annotate_comment' %}" method="post">{% csrf_token %}
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What is the relationship between these changes and the proposed performance improvements?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There was a lot of code for loading the objects for form_comment = CommentAnnotationForm(initial=initial) when that add_share_comment_form is not supported any more.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants