Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Close all HandleTie servants created during import #354

Closed
wants to merge 9 commits into from

Conversation

sbesson
Copy link
Member

@sbesson sbesson commented Mar 20, 2023

This addresses an issue with associated with dangling servants left at the end of a data import. This PR copies over the minimal callback closing changes from the ImportLibrary.importImage and more specifically https://github.com/ome/omero-blitz/blob/49c5d46042487014d0dd6753679cf7f15bee873b/src/main/java/ome/formats/importer/ImportLibrary.java#L704-L709 to ensure that all handle servants are unregistered server-side.

To test these changes, run an import of one or multiple filesets and watch the creation/deletion of HandleTie servants server-side e.g. using tail -F Blitz-0.log | grep HandleTie.

  • without this PR, the import should create N omero.cmd._HandleTie servants, one per fileset, and only close N-1. The last servant should be created (Added servant...) but never deleted (Unregistered servant...)
  • with this PR included, N servants should be created and successfully deleted

This copies the logic from the command-line importer library
to ensure the ImportLibrary Callback can close the handle
@dominikl
Copy link
Member

Could cb.close(true); not be simply done right after its creation cb = library.createCallback(proc, handle, ic); ?

@dominikl
Copy link
Member

Yes, looks like the same lines of code in the (Light)FileImportComponent could be removed then.

@sbesson
Copy link
Member Author

sbesson commented Mar 21, 2023

Based on the comments above, would you consider the issue should be fixed in the ImportComponent classes instead of being in the gateway?
One of the differences between the command-line and the Insight API is that the ImportLibrary.importImage API returns a list of Pixels and handles the callback internally based on the value of minutesToWait. In that scenario, It should always be safe to close the callback handle within the finally block.

In the case of Insight, the API is returning the callback which is used downstream by [Light]FileImportComponent. While most of my testing was performed on single fake files, it is possible that depending on the nature of the imports (HCS) and/or the tasks (thumbnail/pyramid), closing the handle at this stage will cause other issues.
I'll try to perform additional testing with different modalities.

@dominikl
Copy link
Member

I'm fine with the change. Better to do it in the OMEROGateway class than the ImportComponents, I think. I was just wondering, if cb.close(true); could be called straightaway after creating the callback instead of putting it in the finally block, there's nothing coming afterwards which could fail. But I don't mind.

@joshmoore
Copy link
Member

if cb.close(true); could be called straightaway after creating the callback instead of putting it in the finally block, there's nothing coming afterwards which could fail. But I don't mind.

No, since the cb is being returned. The caller is responsible for closing in the non-exceptional case. But with the exception, the cb must be closed internally before throwing.

@imagesc-bot
Copy link

This pull request has been mentioned on Image.sc Forum. There might be relevant details there:

https://forum.image.sc/t/memory-note-clearing-after-data-imports/78815/2

@@ -5861,6 +5863,9 @@ Object importImageFile(SecurityContext ctx, ImportableObject object,
} catch (Exception ex) {}
if (omsc != null && close)
closeImport(ctx, userName);
if (cb != null) {
Copy link
Member

Choose a reason for hiding this comment

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

Realizing (too late!) it's surprising this even works!

Copy link
Member Author

Choose a reason for hiding this comment

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

Thanks for the sanity check. That echoes my concerns expressed in #354 (comment).

Retesting my commit with a local server, I confirm the handle closure in the finally block causes the UI to hang with a spinning wheel. That happens both for fake single image and fake plates with 4 wells. Interestingly, I am also unable to reproduce the original issue of leaking HandleTie servants with OMERO.insight 5.7.2.

Interesting I have a different behavior when connecting to a remote server (same OMERO.server version) and against which I conducted my initial testing for this PR:

  • with OMERO.insight 5.7.2, I can reproduce the unclosed servant issue with both the single fake images and the fake 4-well plate
  • with this change included, the last handle is unregistered in both cases and the import completes successfully
  • with this change included, if importing a 16 wells plate, the servant get unregistered but the import is left spinning forever

I'll mark this PR as draft as more investigation is needed.

Copy link
Member

Choose a reason for hiding this comment

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

Imo it doesn't really matter where cb.close() is called, either directly after creating the callback or in the finally block (later just make is unncessary complicated I think). Anyway, I wonder how it affects Insight's counting of the finished/active imports (pretty sure that's why the spinner doesn't stop).

Copy link
Member

Choose a reason for hiding this comment

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

Imo the cb instance should only be called by the creating thread if there's an exception since when the exception is thrown the cb instance won't be returned and therefore no one will clean up the server-side reference.

@sbesson sbesson marked this pull request as draft March 24, 2023 11:53
@imagesc-bot
Copy link

This pull request has been mentioned on Image.sc Forum. There might be relevant details there:

https://forum.image.sc/t/continously-high-ram-usage-of-omero-server-after-large-import/79555/2

@sbesson
Copy link
Member Author

sbesson commented Aug 15, 2023

Came back to this within the context of the testing of https://forum.image.sc/t/first-release-of-omero-process-container-steward/85067. I confirm that the issue persists using OMERO.insight 5.8.1 against a server including the omero-pc-steward extension cleaning up allocated import memory.

When importing multiple files, the last created HandleTie servant is left registered and is only properly cleaned up when the session is terminated. So a fix against OMERO.insight will also be necessary as well although the impact is undoubtedly lower than ome/omero-blitz#141.

@jburel
Copy link
Member

jburel commented Aug 22, 2023

imported 2 images against a remote server
I do have Added... then unregistered.

@sbesson
Copy link
Member Author

sbesson commented Aug 22, 2023

Retested against OME demo server, imported a test.fake file using OMERO.insight 5.8.1 from my local machine

2023-08-22 13:41:16,962 INFO  [                      omero.cmd.SessionI] (Server-917) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle9e44a242-03e6-4f76-9436-79810bd2709f(omero.cmd._HandleTie@799de717)
2023-08-22 13:41:17,722 INFO  [                      omero.cmd.SessionI] (Server-916) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle9e44a242-03e6-4f76-9436-79810bd2709f(omero.cmd._HandleTie@799de717)
2023-08-22 13:41:25,433 INFO  [                      omero.cmd.SessionI] (Server-915) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle14b31754-9d13-49b9-ab64-74ac8767b5b5(omero.cmd._HandleTie@460176ee)
2023-08-22 13:41:33,827 INFO  [                      omero.cmd.SessionI] (Server-913) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle935f06cd-3677-4044-83f8-e3880c6b9b09(omero.cmd._HandleTie@7cc0ada5)
2023-08-22 13:41:34,551 INFO  [                      omero.cmd.SessionI] (Server-917) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle935f06cd-3677-4044-83f8-e3880c6b9b09(omero.cmd._HandleTie@7cc0ada5)
2023-08-22 13:41:40,604 INFO  [                      omero.cmd.SessionI] (Server-918) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle37e09c81-88c5-4dba-aee0-f0828be96cc8(omero.cmd._HandleTie@3f18e4fe)
2023-08-22 13:41:52,160 INFO  [                      omero.cmd.SessionI] (Server-917) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandleade0d9e0-4767-41d2-9d75-88c386f3f951(omero.cmd._HandleTie@53b8e298)
2023-08-22 13:41:58,674 INFO  [                      omero.cmd.SessionI] (Server-912) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle3effb2f2-d399-4b73-b1cd-9ce709a7daf8(omero.cmd._HandleTie@84cacb89)
2023-08-22 13:41:59,359 INFO  [                      omero.cmd.SessionI] (Server-906) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle3effb2f2-d399-4b73-b1cd-9ce709a7daf8(omero.cmd._HandleTie@84cacb89)
2023-08-22 13:42:04,129 INFO  [                      omero.cmd.SessionI] (Server-913) Added servant to adapter: 0f0350a9-7020-4ff8-8c53-c1e318a81197/IHandle3e0587de-75e6-48bb-a1a3-9ff2b77647e8(omero.cmd._HandleTie@6d86dcdc)
2023-08-22 13:42:04,157 INFO  [                      omero.cmd.SessionI] (Server-914) Unregistered servant:0f0350a9-7020-4ff8-8c53-c1e318a81197/IHandle3e0587de-75e6-48bb-a1a3-9ff2b77647e8(omero.cmd._HandleTie@6d86dcdc)
2023-08-22 13:42:08,039 INFO  [                      omero.cmd.SessionI] (Server-913) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle70bcb998-681e-42c8-bd75-6d37eea949e6(omero.cmd._HandleTie@9daa1e69)
2023-08-22 13:42:08,616 INFO  [                      omero.cmd.SessionI] (Server-913) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle70bcb998-681e-42c8-bd75-6d37eea949e6(omero.cmd._HandleTie@9daa1e69)
2023-08-22 13:42:16,354 INFO  [                      omero.cmd.SessionI] (Server-914) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle0912b7ef-f715-4ece-92f5-a5ffd95a4fd7(omero.cmd._HandleTie@8157718b)
2023-08-22 13:42:23,128 INFO  [                      omero.cmd.SessionI] (Server-912) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle1ba704ba-c7f1-43e1-bfad-218bd3feebb8(omero.cmd._HandleTie@8c7df14b)
2023-08-22 13:42:30,486 INFO  [                      omero.cmd.SessionI] (Server-916) Added servant to adapter: cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle56bbd48e-3bda-425f-85e0-dd4bee94eff9(omero.cmd._HandleTie@682708be)
2023-08-22 13:42:31,071 INFO  [                      omero.cmd.SessionI] (Server-916) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle56bbd48e-3bda-425f-85e0-dd4bee94eff9(omero.cmd._HandleTie@682708be)
2023-08-22 13:42:42,560 INFO  [                      omero.cmd.SessionI] (Server-914) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle14b31754-9d13-49b9-ab64-74ac8767b5b5(omero.cmd._HandleTie@460176ee)
2023-08-22 13:42:42,560 INFO  [                      omero.cmd.SessionI] (Server-914) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle37e09c81-88c5-4dba-aee0-f0828be96cc8(omero.cmd._HandleTie@3f18e4fe)
2023-08-22 13:42:42,561 INFO  [                      omero.cmd.SessionI] (Server-914) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle1ba704ba-c7f1-43e1-bfad-218bd3feebb8(omero.cmd._HandleTie@8c7df14b)
2023-08-22 13:42:42,561 INFO  [                      omero.cmd.SessionI] (Server-914) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandleade0d9e0-4767-41d2-9d75-88c386f3f951(omero.cmd._HandleTie@53b8e298)
2023-08-22 13:42:42,561 INFO  [                      omero.cmd.SessionI] (Server-914) Unregistered servant:cdcd40d0-0454-4514-a014-b2920721b6cd/IHandle0912b7ef-f715-4ece-92f5-a5ffd95a4fd7(omero.cmd._HandleTie@8157718b)

The last 5 servant unregistrations happened after terminating the OMERO.insight connection. So in the example above that's ~50% of the imports where some servants are not cleaned before the session termination

@jburel
Copy link
Member

jburel commented Aug 22, 2023

Did you import with some options off e.g. no thumbnails?

@sbesson
Copy link
Member Author

sbesson commented Aug 22, 2023

Did you import with some options off e.g. no thumbnails?

No options. Regular import of a dummy test.fake file

@jburel
Copy link
Member

jburel commented Aug 22, 2023

this is what I have with the last commit

2023-08-22 15:28:10,348 INFO  [                      omero.cmd.SessionI] (Server-189) Added servant to adapter: c1860f44-1ba6-49c1-a9fa-92351cddfbb8/IHandle59f04684-3ec2-48a5-99ff-a9bd68f90026(omero.cmd._HandleTie@db8e7e8d)
2023-08-22 15:28:10,359 INFO  [                      omero.cmd.SessionI] (Server-188) Unregistered servant:c1860f44-1ba6-49c1-a9fa-92351cddfbb8/IHandle59f04684-3ec2-48a5-99ff-a9bd68f90026(omero.cmd._HandleTie@db8e7e8d)
2023-08-22 15:29:11,140 INFO  [                      omero.cmd.SessionI] (Server-188) Added servant to adapter: c1860f44-1ba6-49c1-a9fa-92351cddfbb8/IHandle7b9567ca-83c5-4d18-93ae-4f472317a431(omero.cmd._HandleTie@ab8cba20)
2023-08-22 15:29:11,149 INFO  [                      omero.cmd.SessionI] (Server-190) Unregistered servant:c1860f44-1ba6-49c1-a9fa-92351cddfbb8/IHandle7b9567ca-83c5-4d18-93ae-4f472317a431(omero.cmd._HandleTie@ab8cba20)
2023-08-22 15:29:12,896 INFO  [                      omero.cmd.SessionI] (Server-189) Added servant to adapter: a5343337-7d58-4772-80a5-df0fa9f20522/IHandle72d8adfe-f692-4c6c-8871-313fac03b7bc(omero.cmd._HandleTie@e142c69d)
2023-08-22 15:29:13,920 INFO  [                      omero.cmd.SessionI] (Server-191) Unregistered servant:a5343337-7d58-4772-80a5-df0fa9f20522/IHandle72d8adfe-f692-4c6c-8871-313fac03b7bc(omero.cmd._HandleTie@e142c69d)
2023-08-22 15:29:26,997 INFO  [                      omero.cmd.SessionI] (Server-190) Added servant to adapter: a5343337-7d58-4772-80a5-df0fa9f20522/IHandle13bb1161-acf2-4d1a-86fc-5c3b55d08565(omero.cmd._HandleTie@c10c3b07)
2023-08-22 15:29:29,901 INFO  [                      omero.cmd.SessionI] (Server-188) Unregistered servant:a5343337-7d58-4772-80a5-df0fa9f20522/IHandle13bb1161-acf2-4d1a-86fc-5c3b55d08565(omero.cmd._HandleTie@c10c3b07)

@sbesson
Copy link
Member Author

sbesson commented Aug 22, 2023

Same outcome for me testing either against the OME demo service hosted at UoD and against a GS testing instance hosted on us-east-1.

Adding some debugging statements, I am getting increasingly convinced the primary problem is that

} else if (result instanceof CmdCallback) {
callback = (CmdCallback) result;
} else {
is not systematically called for every import. In case this line is never accessed, the callback is not registered and there is no logic to close it incl. all associated servants until the termination of the session.

@jburel
Copy link
Member

jburel commented Aug 22, 2023

I think I know what's happening
A property is fired but the code will not always be accessed since the introduction of SwingUtilities.invokeLater(()
cc @dominikl

@dominikl
Copy link
Member

I'm tempted to say, if it works 👍 Insight code just got so complicated (I'm well aware that I've contributed to that...). It definitely makes sense to move that out of the Swing thread to make sure the callback is set.

@sbesson
Copy link
Member Author

sbesson commented Aug 24, 2023

Retested from bafe42a against a remote server with indivual import of fake files. For each file, the HandleTie servant was left uncleaned and only unregistered at session termination

omero@search-test:~$ tail -F OMERO.current/var/log/Blitz-0.log | grep HandleT
2023-08-24 09:55:58,430 INFO  [                      omero.cmd.SessionI] (.Server-68) Added servant to adapter: bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandle14e7c261-2b2e-407a-8447-80bd40d91d50(omero.cmd._HandleTie@31f1a283)
2023-08-24 09:56:11,460 INFO  [                      omero.cmd.SessionI] (.Server-68) Added servant to adapter: bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandle2c907c7e-4653-4acb-a00d-d6c936462a1b(omero.cmd._HandleTie@9915b708)
2023-08-24 09:56:21,278 INFO  [                      omero.cmd.SessionI] (.Server-54) Added servant to adapter: bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandle5ff8565a-5c81-49d5-aa68-92c6e942d173(omero.cmd._HandleTie@a70a6c8a)
2023-08-24 09:56:31,815 INFO  [                      omero.cmd.SessionI] (.Server-69) Added servant to adapter: bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandle70fdce9c-ddef-4150-8474-08287a5a59e5(omero.cmd._HandleTie@3b1e676c)
2023-08-24 09:56:40,804 INFO  [                      omero.cmd.SessionI] (.Server-54) Added servant to adapter: bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandleb34dba75-8328-4719-98c2-6b7efd75505e(omero.cmd._HandleTie@a785f565)
2023-08-24 09:56:50,340 INFO  [                      omero.cmd.SessionI] (.Server-57) Added servant to adapter: bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandlec9a79c3e-eee5-4cd8-85e7-ff4f694e8251(omero.cmd._HandleTie@5f3301bb)
2023-08-24 09:57:01,165 INFO  [                      omero.cmd.SessionI] (.Server-54) Unregistered servant:bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandle5ff8565a-5c81-49d5-aa68-92c6e942d173(omero.cmd._HandleTie@a70a6c8a)
2023-08-24 09:57:01,166 INFO  [                      omero.cmd.SessionI] (.Server-54) Unregistered servant:bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandleb34dba75-8328-4719-98c2-6b7efd75505e(omero.cmd._HandleTie@a785f565)
2023-08-24 09:57:01,166 INFO  [                      omero.cmd.SessionI] (.Server-54) Unregistered servant:bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandle70fdce9c-ddef-4150-8474-08287a5a59e5(omero.cmd._HandleTie@3b1e676c)
2023-08-24 09:57:01,167 INFO  [                      omero.cmd.SessionI] (.Server-54) Unregistered servant:bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandle14e7c261-2b2e-407a-8447-80bd40d91d50(omero.cmd._HandleTie@31f1a283)
2023-08-24 09:57:01,167 INFO  [                      omero.cmd.SessionI] (.Server-54) Unregistered servant:bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandle2c907c7e-4653-4acb-a00d-d6c936462a1b(omero.cmd._HandleTie@9915b708)
2023-08-24 09:57:01,168 INFO  [                      omero.cmd.SessionI] (.Server-54) Unregistered servant:bcbd8f18-58e9-42c7-bc7f-66559eb0faf3/IHandlec9a79c3e-eee5-4cd8-85e7-ff4f694e8251(omero.cmd._HandleTie@5f3301bb)

@jburel
Copy link
Member

jburel commented Aug 24, 2023

thanks

@jburel
Copy link
Member

jburel commented Aug 25, 2023

replaced by #394

@jburel jburel closed this Aug 25, 2023
@sbesson sbesson deleted the handle_servants_removal branch August 25, 2023 11:50
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.

5 participants