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

File uploads using the new-style api are getting errors related to search for filename #5729

Closed
Tracked by #5694
wvangeit opened this issue Apr 25, 2024 · 14 comments
Closed
Tracked by #5694
Assignees
Labels
bug buggy, it does not work as expected

Comments

@wvangeit
Copy link
Contributor

wvangeit commented Apr 25, 2024

When uploading files in parallel (5-10 jobs, same file). The file api is starting to return 504 errors. During search operations. As in:

Screenshot 2024-04-24 at 16 51 27

Code: https://github.com/wvangeit/osparc-pyapi-tests/blob/9d9e6b6703d5d6db56292be5ed949beceec3308a/noninter1/run_study.py#L54

@wvangeit wvangeit added the bug buggy, it does not work as expected label Apr 25, 2024
@wvangeit
Copy link
Contributor Author

@pcrespov FYI

@wvangeit
Copy link
Contributor Author

As explained by @bisgaard-itis , this is probably caused by a mechanism that checks, when uploading a file, the same file already exists with the same name/sha256, and avoids uploading it twice. The search might be generating issues.

@wvangeit
Copy link
Contributor Author

This was discovered after switching to the new-style file api, to avoid #5724

@wvangeit wvangeit added this to the Enchanted Odyssey milestone Apr 25, 2024
@wvangeit
Copy link
Contributor Author

@matusdrobuliak66 FYI

@wvangeit
Copy link
Contributor Author

Same issue happens on aws-master

@matusdrobuliak66
Copy link
Contributor

matusdrobuliak66 commented Apr 25, 2024

Test against aws-master.
100 jobs in parallel, all of them failed

image
image

@wvangeit
Copy link
Contributor Author

Statistic from a run of https://github.com/wvangeit/osparc-pyapi-tests/blob/9d9e6b6703d5d6db56292be5ed949beceec3308a/noninter1/Makefile#L15
in the file test log file below, when scaling up the storage service by @matusdrobuliak66

We basically now have ~20-30% error rates. But these errors are caused by 'job start' failures, not uploading files.
1 job failed with #5707

test.202404251047.txt

@bisgaard-itis
Copy link
Contributor

bisgaard-itis commented May 2, 2024

This is what I see when profiling the search endpoint in storage:

   _     ._   __/__   _ _  _  _ _/_   Recorded: 13:19:31  Samples:  2294
 /_//_/// /_\ / //_// / //_'/ //     Duration: 2.344     CPU time: 2.321
/   _/                      v4.6.2

Program: /home/scu/.venv/bin/simcore-service-storage run

2.343 _UnixSelectorEventLoop.run_forever  asyncio/base_events.py:589
├─ 2.342 _UnixSelectorEventLoop._run_once  asyncio/base_events.py:1832
│  ├─ 2.336 Handle._run  asyncio/events.py:78
│  │  ├─ 2.330 RequestHandler._handle_request  aiohttp/web_protocol.py:442
│  │  │  └─ 2.330 Application._handle  aiohttp/web_app.py:509
│  │  │     ├─ 2.328 impl  aiohttp/web_middlewares.py:111
│  │  │     │  └─ 2.328 middleware_handler  servicelib/aiohttp/monitoring.py:145
│  │  │     │     ├─ 2.325 aiozipkin_middleware  aiozipkin/aiohttp_helpers.py:136
│  │  │     │     │  ├─ 2.323 _middleware_handler  servicelib/aiohttp/rest_middlewares.py:67
│  │  │     │     │  │  └─ 2.323 _middleware_handler  servicelib/aiohttp/rest_middlewares.py:153
│  │  │     │     │  │     └─ 2.323 dsm_exception_handler  simcore_service_storage/utils_handlers.py:23
│  │  │     │     │  │        └─ 2.323 profiling_middleware  servicelib/aiohttp/profiler_middleware.py:11
│  │  │     │     │  │           ├─ 2.322 base_long_running_error_handler  servicelib/aiohttp/long_running_tasks/_error_handlers.py:15
│  │  │     │     │  │           │  ├─ 2.297 search_files  simcore_service_storage/handlers_simcore_s3.py:120
│  │  │     │     │  │           │  │  ├─ 2.294 SimcoreS3DataManager.search_read_access_files  simcore_service_storage/simcore_s3_dsm.py:713
│  │  │     │     │  │           │  │  │  ├─ 1.147 SimcoreS3DataManager._search_files  simcore_service_storage/simcore_s3_dsm.py:735
│  │  │     │     │  │           │  │  │  │  ├─ 1.146 list_filter_with_partial_file_id  simcore_service_storage/db_file_meta_data.py:68
│  │  │     │     │  │           │  │  │  │  │  ├─ 1.037 SAConnection._execute  aiopg/sa/connection.py:106
│  │  │     │     │  │           │  │  │  │  │  │  ├─ 1.010 Select.compile  sqlalchemy/sql/elements.py:439
│  │  │     │     │  │           │  │  │  │  │  │  │  └─ 1.010 Select._compiler  sqlalchemy/sql/elements.py:563
│  │  │     │     │  │           │  │  │  │  │  │  │     └─ 1.010 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:722
│  │  │     │     │  │           │  │  │  │  │  │  │        ├─ 1.005 APGCompiler_psycopg2._process_parameters_for_postcompile  sqlalchemy/sql/compiler.py:1159
│  │  │     │     │  │           │  │  │  │  │  │  │        │  ├─ 0.928 BindParameter._with_value  sqlalchemy/sql/elements.py:1581
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  ├─ 0.878 BindParameter._clone  sqlalchemy/sql/elements.py:1649
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  ├─ 0.409 _anonymous_label.safe_construct  sqlalchemy/sql/elements.py:5395
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  ├─ 0.146 _anonymous_label.__new__  sqlalchemy/sql/elements.py:5319
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  ├─ 0.088 _anonymous_label.__new__  sqlalchemy/sql/elements.py:5198
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  │  ├─ 0.054 [self]  sqlalchemy/sql/elements.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  │  ├─ 0.022 str.__new__  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  │  └─ 0.012 isinstance  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  ├─ 0.045 [self]  sqlalchemy/sql/elements.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  └─ 0.013 getattr  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  ├─ 0.140 sub  re.py:202
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  ├─ 0.067 _compile  re.py:288
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  │  ├─ 0.047 [self]  re.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  │  └─ 0.019 isinstance  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  ├─ 0.043 [self]  re.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  └─ 0.030 Pattern.sub  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  ├─ 0.090 [self]  sqlalchemy/sql/elements.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  ├─ 0.017 str.strip  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  └─ 0.016 str.replace  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  ├─ 0.202 BindParameter._clone  sqlalchemy/sql/elements.py:236
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  ├─ 0.096 [self]  sqlalchemy/sql/elements.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  ├─ 0.054 <dictcomp>  sqlalchemy/sql/elements.py:249
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  ├─ 0.018 dict.items  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  ├─ 0.017 dict.copy  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  └─ 0.017 object.__new__  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  ├─ 0.137 memoized_attribute.__get__  sqlalchemy/util/langhelpers.py:1181
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  ├─ 0.077 BindParameter._cloned_set  sqlalchemy/sql/elements.py:294
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  ├─ 0.042 [self]  sqlalchemy/sql/elements.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  │  └─ 0.035 set.add  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  │  └─ 0.060 [self]  sqlalchemy/util/langhelpers.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  ├─ 0.105 [self]  sqlalchemy/sql/elements.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  ├─ 0.013 set.update  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  │  └─ 0.012 id  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  └─ 0.050 [self]  sqlalchemy/sql/elements.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  ├─ 0.038 str._literal_execute_expanding_parameter  sqlalchemy/sql/compiler.py:2174
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  ├─ 0.017 [self]  sqlalchemy/sql/compiler.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  ├─ 0.015 <genexpr>  sqlalchemy/sql/compiler.py:2226
│  │  │     │     │  │           │  │  │  │  │  │  │        │  │  └─ 0.006 <listcomp>  sqlalchemy/sql/compiler.py:2222
│  │  │     │     │  │           │  │  │  │  │  │  │        │  ├─ 0.035 [self]  sqlalchemy/sql/compiler.py
│  │  │     │     │  │           │  │  │  │  │  │  │        │  ├─ 0.002 dict.update  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │        │  ├─ 0.001 <genexpr>  sqlalchemy/sql/compiler.py:1268
│  │  │     │     │  │           │  │  │  │  │  │  │        │  └─ 0.001 <listcomp>  sqlalchemy/sql/compiler.py:1275
│  │  │     │     │  │           │  │  │  │  │  │  │        ├─ 0.003 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:421
│  │  │     │     │  │           │  │  │  │  │  │  │        │  └─ 0.003 APGCompiler_psycopg2.process  sqlalchemy/sql/compiler.py:498
│  │  │     │     │  │           │  │  │  │  │  │  │        │     └─ 0.003 Select._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │  │  │  │  │  │  │        │        └─ 0.003 bool.visit_select  sqlalchemy/sql/compiler.py:3377
│  │  │     │     │  │           │  │  │  │  │  │  │        │           ├─ 0.001 NoneType._compose_select_body  sqlalchemy/sql/compiler.py:3650
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │  └─ 0.001 dict._generate_delimited_and_list  sqlalchemy/sql/compiler.py:1737
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │     └─ 0.001 BooleanClauseList._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │        └─ 0.001 APGCompiler_psycopg2.visit_clauselist  sqlalchemy/sql/compiler.py:1758
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │           └─ 0.001 dict._generate_delimited_list  sqlalchemy/sql/compiler.py:1730
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │              └─ 0.001 <genexpr>  sqlalchemy/sql/compiler.py:1731
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │                 └─ 0.001 <genexpr>  sqlalchemy/sql/compiler.py:1733
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │                    └─ 0.001 BinaryExpression._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │                       └─ 0.001 APGCompiler_psycopg2.visit_binary  sqlalchemy/sql/compiler.py:2232
│  │  │     │     │  │           │  │  │  │  │  │  │        │           ├─ 0.001 CompileState.create_for_statement  sqlalchemy/sql/base.py:486
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │  └─ 0.001 SelectState.create_for_statement  sqlalchemy/sql/base.py:486
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │     └─ 0.001 SelectState.__init__  sqlalchemy/sql/selectable.py:4382
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │        └─ 0.001 Select._generate_columns_plus_names  sqlalchemy/sql/selectable.py:6195
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │           └─ 0.001 memoized_attribute.__get__  sqlalchemy/util/langhelpers.py:1181
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │              └─ 0.001 Select._all_selected_columns  sqlalchemy/sql/selectable.py:6185
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │                 └─ 0.001 SelectState.all_selected_columns  sqlalchemy/sql/selectable.py:4619
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │                    └─ 0.001 <listcomp>  sqlalchemy/sql/selectable.py:4621
│  │  │     │     │  │           │  │  │  │  │  │  │        │           │                       └─ 0.001 ImmutableColumnCollection.__iter__  sqlalchemy/sql/base.py:1208
│  │  │     │     │  │           │  │  │  │  │  │  │        │           └─ 0.001 <listcomp>  sqlalchemy/sql/compiler.py:3485
│  │  │     │     │  │           │  │  │  │  │  │  │        │              └─ 0.001 APGCompiler_psycopg2._label_select_column  sqlalchemy/sql/compiler.py:3157
│  │  │     │     │  │           │  │  │  │  │  │  │        │                 └─ 0.001 Column._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │  │  │  │  │  │  │        │                    └─ 0.001 APGCompiler_psycopg2.visit_column  sqlalchemy/sql/compiler.py:1559
│  │  │     │     │  │           │  │  │  │  │  │  │        │                       └─ 0.001 PGIdentifierPreparer_psycopg2.quote  sqlalchemy/sql/compiler.py:5410
│  │  │     │     │  │           │  │  │  │  │  │  │        └─ 0.002 [self]  sqlalchemy/sql/compiler.py
│  │  │     │     │  │           │  │  │  │  │  │  ├─ 0.016 Cursor.execute  aiopg/connection.py:400
│  │  │     │     │  │           │  │  │  │  │  │  │  ├─ 0.015 cursor.execute  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │  └─ 0.001 Connection._poll  aiopg/connection.py:874
│  │  │     │     │  │           │  │  │  │  │  │  │     └─ 0.001 wait_for  asyncio/tasks.py:392
│  │  │     │     │  │           │  │  │  │  │  │  │        └─ 0.001 [await]  asyncio/tasks.py
│  │  │     │     │  │           │  │  │  │  │  │  ├─ 0.008 APGCompiler_psycopg2.construct_params  aiopg/sa/engine.py:20
│  │  │     │     │  │           │  │  │  │  │  │  │  └─ 0.008 APGCompiler_psycopg2.construct_params  sqlalchemy/sql/compiler.py:964
│  │  │     │     │  │           │  │  │  │  │  │  └─ 0.003 <dictcomp>  aiopg/sa/connection.py:141
│  │  │     │     │  │           │  │  │  │  │  ├─ 0.107 Column.in_  sqlalchemy/sql/operators.py:554
│  │  │     │     │  │           │  │  │  │  │  │  └─ 0.107 Column.operate  sqlalchemy/sql/elements.py:872
│  │  │     │     │  │           │  │  │  │  │  │     └─ 0.107 in_op  sqlalchemy/sql/operators.py:1438
│  │  │     │     │  │           │  │  │  │  │  │        └─ 0.107 Comparator.in_  sqlalchemy/sql/operators.py:554
│  │  │     │     │  │           │  │  │  │  │  │           └─ 0.107 Comparator.operate  sqlalchemy/sql/type_api.py:73
│  │  │     │     │  │           │  │  │  │  │  │              └─ 0.107 _in_impl  sqlalchemy/sql/default_comparator.py:158
│  │  │     │     │  │           │  │  │  │  │  │                 └─ 0.107 expect  sqlalchemy/sql/coercions.py:112
│  │  │     │     │  │           │  │  │  │  │  │                    ├─ 0.105 InElementImpl._literal_coercion  sqlalchemy/sql/coercions.py:568
│  │  │     │     │  │           │  │  │  │  │  │                    │  ├─ 0.060 _is_literal  sqlalchemy/sql/coercions.py:32
│  │  │     │     │  │           │  │  │  │  │  │                    │  │  ├─ 0.037 [self]  sqlalchemy/sql/coercions.py
│  │  │     │     │  │           │  │  │  │  │  │                    │  │  ├─ 0.013 isinstance  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │                    │  │  └─ 0.010 hasattr  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │                    │  ├─ 0.038 [self]  sqlalchemy/sql/coercions.py
│  │  │     │     │  │           │  │  │  │  │  │                    │  └─ 0.007 <genexpr>  simcore_service_storage/db_file_meta_data.py:81
│  │  │     │     │  │           │  │  │  │  │  │                    ├─ 0.001 InElementImpl._post_coercion  sqlalchemy/sql/coercions.py:598
│  │  │     │     │  │           │  │  │  │  │  │                    └─ 0.001 hasattr  <built-in>
│  │  │     │     │  │           │  │  │  │  │  ├─ 0.001 [self]  simcore_service_storage/db_file_meta_data.py
│  │  │     │     │  │           │  │  │  │  │  └─ 0.001 Column.__eq__  sqlalchemy/sql/operators.py:380
│  │  │     │     │  │           │  │  │  │  │     └─ 0.001 Column.operate  sqlalchemy/sql/elements.py:872
│  │  │     │     │  │           │  │  │  │  │        └─ 0.001 Comparator.__eq__  sqlalchemy/sql/operators.py:380
│  │  │     │     │  │           │  │  │  │  │           └─ 0.001 Comparator.operate  sqlalchemy/sql/type_api.py:73
│  │  │     │     │  │           │  │  │  │  │              └─ 0.001 _boolean_compare  sqlalchemy/sql/default_comparator.py:30
│  │  │     │     │  │           │  │  │  │  │                 └─ 0.001 BinaryExpression.__init__  sqlalchemy/sql/elements.py:3909
│  │  │     │     │  │           │  │  │  │  └─ 0.001 _ContextManager.__aexit__  aiopg/utils.py:86
│  │  │     │     │  │           │  │  │  │     └─ 0.001 _close_connection  aiopg/sa/engine.py:115
│  │  │     │     │  │           │  │  │  │        └─ 0.001 SAConnection.close  aiopg/sa/connection.py:384
│  │  │     │     │  │           │  │  │  │           └─ 0.001 shield  asyncio/tasks.py:807
│  │  │     │     │  │           │  │  │  │              └─ 0.001 _ensure_future  asyncio/tasks.py:618
│  │  │     │     │  │           │  │  │  │                 └─ 0.001 _UnixSelectorEventLoop.create_task  asyncio/base_events.py:431
│  │  │     │     │  │           │  │  │  ├─ 1.145 get_readable_project_ids  simcore_service_storage/db_access_layer.py:278
│  │  │     │     │  │           │  │  │  │  ├─ 1.142 list_projects_access_rights  simcore_service_storage/db_access_layer.py:116
│  │  │     │     │  │           │  │  │  │  │  ├─ 0.719 _IterableContextManager.__anext__  aiopg/utils.py:113
│  │  │     │     │  │           │  │  │  │  │  │  ├─ 0.631 ResultProxy.__anext__  aiopg/sa/result.py:355
│  │  │     │     │  │           │  │  │  │  │  │  │  ├─ 0.587 ResultProxy.fetchone  aiopg/sa/result.py:388
│  │  │     │     │  │           │  │  │  │  │  │  │  │  ├─ 0.397 Cursor.fetchone  aiopg/connection.py:505
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  ├─ 0.345 typecast_json  psycopg2/_json.py:159
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  ├─ 0.308 loads  json/__init__.py:299
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  │  ├─ 0.224 JSONDecoder.decode  json/decoder.py:332
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  │  │  ├─ 0.100 [self]  json/decoder.py
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  │  │  ├─ 0.044 Pattern.match  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  │  │  ├─ 0.040 JSONDecoder.raw_decode  json/decoder.py:343
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  │  │  ├─ 0.025 Match.end  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  │  │  └─ 0.015 len  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  │  ├─ 0.056 [self]  json/__init__.py
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  │  ├─ 0.017 str.startswith  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  │  └─ 0.011 isinstance  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  └─ 0.037 [self]  psycopg2/_json.py
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  ├─ 0.040 [self]  aiopg/connection.py
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  └─ 0.012 cursor.fetchone  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │  │  ├─ 0.105 ResultProxy._process_rows  aiopg/sa/result.py:370
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  ├─ 0.058 <listcomp>  aiopg/sa/result.py:375
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  ├─ 0.038 [self]  aiopg/sa/result.py
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  │  └─ 0.020 RowProxy.__init__  aiopg/sa/result.py:20
│  │  │     │     │  │           │  │  │  │  │  │  │  │  │  └─ 0.047 [self]  aiopg/sa/result.py
│  │  │     │     │  │           │  │  │  │  │  │  │  │  ├─ 0.073 [self]  aiopg/sa/result.py
│  │  │     │     │  │           │  │  │  │  │  │  │  │  ├─ 0.010 ResultProxy.cursor  aiopg/sa/result.py:259
│  │  │     │     │  │           │  │  │  │  │  │  │  │  └─ 0.001 ResultProxy.close  aiopg/sa/result.py:325
│  │  │     │     │  │           │  │  │  │  │  │  │  │     └─ 0.001 Cursor.close  aiopg/connection.py:355
│  │  │     │     │  │           │  │  │  │  │  │  │  │        └─ 0.001 cursor.close  <built-in>
│  │  │     │     │  │           │  │  │  │  │  │  │  └─ 0.044 [self]  aiopg/sa/result.py
│  │  │     │     │  │           │  │  │  │  │  │  ├─ 0.047 SAConnection._execute  aiopg/sa/connection.py:106
│  │  │     │     │  │           │  │  │  │  │  │  │  └─ 0.047 Cursor.execute  aiopg/connection.py:400
│  │  │     │     │  │           │  │  │  │  │  │  │     └─ 0.047 Connection._poll  aiopg/connection.py:874
│  │  │     │     │  │           │  │  │  │  │  │  │        └─ 0.047 wait_for  asyncio/tasks.py:392
│  │  │     │     │  │           │  │  │  │  │  │  │           └─ 0.047 [await]  asyncio/tasks.py
│  │  │     │     │  │           │  │  │  │  │  │  └─ 0.041 [self]  aiopg/utils.py
│  │  │     │     │  │           │  │  │  │  │  ├─ 0.180 RowProxy.__getattr__  aiopg/sa/result.py:61
│  │  │     │     │  │           │  │  │  │  │  │  ├─ 0.112 [self]  aiopg/sa/result.py
│  │  │     │     │  │           │  │  │  │  │  │  └─ 0.068 RowProxy.__getitem__  aiopg/sa/result.py:33
│  │  │     │     │  │           │  │  │  │  │  ├─ 0.131 [self]  simcore_service_storage/db_access_layer.py
│  │  │     │     │  │           │  │  │  │  │  ├─ 0.108 _aggregate_access_rights  simcore_service_storage/db_access_layer.py:96
│  │  │     │     │  │           │  │  │  │  │  │  ├─ 0.071 [self]  simcore_service_storage/db_access_layer.py
│  │  │     │     │  │           │  │  │  │  │  │  ├─ 0.027 AccessRights.__init__  <string>:2
│  │  │     │     │  │           │  │  │  │  │  │  └─ 0.010 dict.items  <built-in>
│  │  │     │     │  │           │  │  │  │  │  └─ 0.004 _get_user_groups_ids  simcore_service_storage/db_access_layer.py:89
│  │  │     │     │  │           │  │  │  │  │     ├─ 0.003 SAConnection._execute  aiopg/sa/connection.py:106
│  │  │     │     │  │           │  │  │  │  │     │  ├─ 0.001 Cursor.execute  aiopg/connection.py:400
│  │  │     │     │  │           │  │  │  │  │     │  │  └─ 0.001 cursor.execute  <built-in>
│  │  │     │     │  │           │  │  │  │  │     │  ├─ 0.001 Select.compile  sqlalchemy/sql/elements.py:439
│  │  │     │     │  │           │  │  │  │  │     │  │  └─ 0.001 Select._compiler  sqlalchemy/sql/elements.py:563
│  │  │     │     │  │           │  │  │  │  │     │  │     └─ 0.001 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:722
│  │  │     │     │  │           │  │  │  │  │     │  │        └─ 0.001 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:421
│  │  │     │     │  │           │  │  │  │  │     │  │           └─ 0.001 APGCompiler_psycopg2.process  sqlalchemy/sql/compiler.py:498
│  │  │     │     │  │           │  │  │  │  │     │  │              └─ 0.001 Select._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │  │  │  │  │     │  │                 └─ 0.001 bool.visit_select  sqlalchemy/sql/compiler.py:3377
│  │  │     │     │  │           │  │  │  │  │     │  │                    └─ 0.001 NoneType._compose_select_body  sqlalchemy/sql/compiler.py:3650
│  │  │     │     │  │           │  │  │  │  │     │  └─ 0.001 SAConnection._open_cursor  aiopg/sa/connection.py:95
│  │  │     │     │  │           │  │  │  │  │     │     └─ 0.001 Connection._cursor  aiopg/connection.py:931
│  │  │     │     │  │           │  │  │  │  │     │        └─ 0.001 Cursor.__init__  aiopg/connection.py:309
│  │  │     │     │  │           │  │  │  │  │     └─ 0.001 select  <string>:1
│  │  │     │     │  │           │  │  │  │  │        └─ 0.001 Select._create  sqlalchemy/sql/selectable.py:5256
│  │  │     │     │  │           │  │  │  │  │           └─ 0.001 Select._create_future_select  sqlalchemy/sql/selectable.py:5190
│  │  │     │     │  │           │  │  │  │  │              └─ 0.001 Select.__init__  <string>:1
│  │  │     │     │  │           │  │  │  │  │                 └─ 0.001 warned  sqlalchemy/util/deprecations.py:343
│  │  │     │     │  │           │  │  │  │  └─ 0.002 <listcomp>  simcore_service_storage/db_access_layer.py:283
│  │  │     │     │  │           │  │  │  ├─ 0.001 _ContextManager.__aexit__  aiopg/utils.py:86
│  │  │     │     │  │           │  │  │  │  └─ 0.001 _close_connection  aiopg/sa/engine.py:115
│  │  │     │     │  │           │  │  │  │     └─ 0.001 SAConnection.close  aiopg/sa/connection.py:384
│  │  │     │     │  │           │  │  │  │        └─ 0.001 [await]  aiopg/sa/connection.py
│  │  │     │     │  │           │  │  │  └─ 0.001 _ContextManager.__aenter__  aiopg/utils.py:81
│  │  │     │     │  │           │  │  │     └─ 0.001 Engine._acquire  aiopg/sa/engine.py:205
│  │  │     │     │  │           │  │  │        └─ 0.001 Pool._acquire  aiopg/pool.py:304
│  │  │     │     │  │           │  │  │           └─ 0.001 timeout  async_timeout/__init__.py:32
│  │  │     │     │  │           │  │  │              └─ 0.001 _UnixSelectorEventLoop.time  asyncio/base_events.py:696
│  │  │     │     │  │           │  │  ├─ 0.002 <listcomp>  simcore_service_storage/handlers_simcore_s3.py:154
│  │  │     │     │  │           │  │  │  ├─ 0.001 [self]  simcore_service_storage/handlers_simcore_s3.py
│  │  │     │     │  │           │  │  │  └─ 0.001 jsonable_encoder  models_library/utils/_original_fastapi_encoders.py:34
│  │  │     │     │  │           │  │  │     └─ 0.001 jsonable_encoder  models_library/utils/_original_fastapi_encoders.py:34
│  │  │     │     │  │           │  │  │        └─ 0.001 jsonable_encoder  models_library/utils/_original_fastapi_encoders.py:34
│  │  │     │     │  │           │  │  └─ 0.001 parse_request_query_parameters_as  servicelib/aiohttp/requests_validation.py:145
│  │  │     │     │  │           │  │     └─ 0.001 Request.query  aiohttp/web_request.py:480
│  │  │     │     │  │           │  └─ 0.025 upload_file  simcore_service_storage/handlers_files.py:152
│  │  │     │     │  │           │     └─ 0.025 SimcoreS3DataManager.create_file_upload_links  simcore_service_storage/simcore_s3_dsm.py:241
│  │  │     │     │  │           │        ├─ 0.014 SimcoreS3DataManager._create_fmd_for_upload  simcore_service_storage/simcore_s3_dsm.py:1163
│  │  │     │     │  │           │        │  └─ 0.014 upsert  simcore_service_storage/db_file_meta_data.py:31
│  │  │     │     │  │           │        │     ├─ 0.007 SAConnection._execute  aiopg/sa/connection.py:106
│  │  │     │     │  │           │        │     │  ├─ 0.005 Insert.compile  sqlalchemy/sql/elements.py:439
│  │  │     │     │  │           │        │     │  │  └─ 0.005 Insert._compiler  sqlalchemy/sql/elements.py:563
│  │  │     │     │  │           │        │     │  │     └─ 0.005 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:722
│  │  │     │     │  │           │        │     │  │        └─ 0.005 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:421
│  │  │     │     │  │           │        │     │  │           └─ 0.005 APGCompiler_psycopg2.process  sqlalchemy/sql/compiler.py:498
│  │  │     │     │  │           │        │     │  │              └─ 0.005 Insert._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │        │     │  │                 └─ 0.005 APGCompiler_psycopg2.visit_insert  sqlalchemy/sql/compiler.py:3991
│  │  │     │     │  │           │        │     │  │                    ├─ 0.002 _get_crud_params  sqlalchemy/sql/crud.py:38
│  │  │     │     │  │           │        │     │  │                    │  ├─ 0.001 _scan_cols  sqlalchemy/sql/crud.py:363
│  │  │     │     │  │           │        │     │  │                    │  │  └─ 0.001 _append_param_parameter  sqlalchemy/sql/crud.py:483
│  │  │     │     │  │           │        │     │  │                    │  └─ 0.001 _get_stmt_parameter_tuples_params  sqlalchemy/sql/crud.py:982
│  │  │     │     │  │           │        │     │  │                    │     └─ 0.001 expect_as_key  sqlalchemy/sql/coercions.py:224
│  │  │     │     │  │           │        │     │  │                    ├─ 0.002 APGCompiler_psycopg2.process  sqlalchemy/sql/compiler.py:498
│  │  │     │     │  │           │        │     │  │                    │  └─ 0.002 OnConflictDoUpdate._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │        │     │  │                    │     └─ 0.002 APGCompiler_psycopg2.visit_on_conflict_do_update  sqlalchemy/dialects/postgresql/base.py:2597
│  │  │     │     │  │           │        │     │  │                    │        ├─ 0.001 BindParameter.__init__  sqlalchemy/sql/elements.py:1263
│  │  │     │     │  │           │        │     │  │                    │        │  └─ 0.001 _anonymous_label.safe_construct  sqlalchemy/sql/elements.py:5395
│  │  │     │     │  │           │        │     │  │                    │        │     └─ 0.001 sub  re.py:202
│  │  │     │     │  │           │        │     │  │                    │        └─ 0.001 APGCompiler_psycopg2.process  sqlalchemy/sql/compiler.py:498
│  │  │     │     │  │           │        │     │  │                    │           └─ 0.001 BindParameter._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │        │     │  │                    │              └─ 0.001 APGCompiler_psycopg2.visit_bindparam  sqlalchemy/sql/compiler.py:2467
│  │  │     │     │  │           │        │     │  │                    │                 └─ 0.001 APGCompiler_psycopg2._truncate_bindparam  sqlalchemy/sql/compiler.py:2682
│  │  │     │     │  │           │        │     │  │                    │                    └─ 0.001 APGCompiler_psycopg2._truncated_identifier  sqlalchemy/sql/compiler.py:2695
│  │  │     │     │  │           │        │     │  │                    │                       └─ 0.001 _anonymous_label.apply_map  sqlalchemy/sql/elements.py:5440
│  │  │     │     │  │           │        │     │  │                    │                          └─ 0.001 prefix_anon_map.__missing__  sqlalchemy/sql/base.py:1025
│  │  │     │     │  │           │        │     │  │                    └─ 0.001 PGIdentifierPreparer_psycopg2.format_table  sqlalchemy/sql/compiler.py:5558
│  │  │     │     │  │           │        │     │  │                       └─ 0.001 PGIdentifierPreparer_psycopg2.quote  sqlalchemy/sql/compiler.py:5410
│  │  │     │     │  │           │        │     │  ├─ 0.001 memoized_property.__get__  sqlalchemy/util/langhelpers.py:1110
│  │  │     │     │  │           │        │     │  │  └─ 0.001 APGCompiler_psycopg2._bind_processors  sqlalchemy/sql/compiler.py:934
│  │  │     │     │  │           │        │     │  │     └─ 0.001 <genexpr>  sqlalchemy/sql/compiler.py:937
│  │  │     │     │  │           │        │     │  │        └─ 0.001 <genexpr>  sqlalchemy/sql/compiler.py:942
│  │  │     │     │  │           │        │     │  │           └─ 0.001 String._cached_bind_processor  sqlalchemy/sql/type_api.py:686
│  │  │     │     │  │           │        │     │  └─ 0.001 Cursor.execute  aiopg/connection.py:400
│  │  │     │     │  │           │        │     │     └─ 0.001 Connection._poll  aiopg/connection.py:874
│  │  │     │     │  │           │        │     │        └─ 0.001 wait_for  asyncio/tasks.py:392
│  │  │     │     │  │           │        │     ├─ 0.002 Insert.values  <string>:1
│  │  │     │     │  │           │        │     │  └─ 0.002 _generative  sqlalchemy/sql/base.py:105
│  │  │     │     │  │           │        │     │     └─ 0.002 Insert.values  <string>:1
│  │  │     │     │  │           │        │     │        └─ 0.002 check  sqlalchemy/sql/base.py:129
│  │  │     │     │  │           │        │     │           └─ 0.002 Insert.values  sqlalchemy/sql/dml.py:623
│  │  │     │     │  │           │        │     │              └─ 0.002 InsertDMLState._get_crud_kv_pairs  sqlalchemy/sql/dml.py:70
│  │  │     │     │  │           │        │     │                 └─ 0.002 <listcomp>  sqlalchemy/sql/dml.py:72
│  │  │     │     │  │           │        │     │                    └─ 0.002 expect  sqlalchemy/sql/coercions.py:112
│  │  │     │     │  │           │        │     │                       ├─ 0.001 [self]  sqlalchemy/sql/coercions.py
│  │  │     │     │  │           │        │     │                       └─ 0.001 ExpressionElementImpl._literal_coercion  sqlalchemy/sql/coercions.py:487
│  │  │     │     │  │           │        │     ├─ 0.002 jsonable_encoder  models_library/utils/_original_fastapi_encoders.py:34
│  │  │     │     │  │           │        │     │  └─ 0.002 jsonable_encoder  models_library/utils/_original_fastapi_encoders.py:34
│  │  │     │     │  │           │        │     │     └─ 0.002 jsonable_encoder  models_library/utils/_original_fastapi_encoders.py:34
│  │  │     │     │  │           │        │     │        ├─ 0.001 isinstance  <built-in>
│  │  │     │     │  │           │        │     │        └─ 0.001 is_dataclass  dataclasses.py:1210
│  │  │     │     │  │           │        │     ├─ 0.001 SAConnection.execute  aiopg/sa/connection.py:55
│  │  │     │     │  │           │        │     ├─ 0.001 [self]  simcore_service_storage/db_file_meta_data.py
│  │  │     │     │  │           │        │     └─ 0.001 match  re.py:187
│  │  │     │     │  │           │        │        └─ 0.001 _compile  re.py:288
│  │  │     │     │  │           │        ├─ 0.004 SimcoreS3DataManager.delete_file  simcore_service_storage/simcore_s3_dsm.py:494
│  │  │     │     │  │           │        │  └─ 0.004 get  simcore_service_storage/db_file_meta_data.py:59
│  │  │     │     │  │           │        │     └─ 0.004 SAConnection._execute  aiopg/sa/connection.py:106
│  │  │     │     │  │           │        │        ├─ 0.002 Select.compile  sqlalchemy/sql/elements.py:439
│  │  │     │     │  │           │        │        │  └─ 0.002 Select._compiler  sqlalchemy/sql/elements.py:563
│  │  │     │     │  │           │        │        │     └─ 0.002 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:722
│  │  │     │     │  │           │        │        │        ├─ 0.001 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:421
│  │  │     │     │  │           │        │        │        │  └─ 0.001 APGCompiler_psycopg2.process  sqlalchemy/sql/compiler.py:498
│  │  │     │     │  │           │        │        │        │     └─ 0.001 Select._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │        │        │        │        └─ 0.001 bool.visit_select  sqlalchemy/sql/compiler.py:3377
│  │  │     │     │  │           │        │        │        │           └─ 0.001 <listcomp>  sqlalchemy/sql/compiler.py:3485
│  │  │     │     │  │           │        │        │        │              └─ 0.001 APGCompiler_psycopg2._label_select_column  sqlalchemy/sql/compiler.py:3157
│  │  │     │     │  │           │        │        │        │                 └─ 0.001 Column._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │        │        │        │                    └─ 0.001 APGCompiler_psycopg2.visit_column  sqlalchemy/sql/compiler.py:1559
│  │  │     │     │  │           │        │        │        └─ 0.001 [self]  sqlalchemy/sql/compiler.py
│  │  │     │     │  │           │        │        ├─ 0.001 Cursor.execute  aiopg/connection.py:400
│  │  │     │     │  │           │        │        │  └─ 0.001 Connection._poll  aiopg/connection.py:874
│  │  │     │     │  │           │        │        │     └─ 0.001 wait_for  asyncio/tasks.py:392
│  │  │     │     │  │           │        │        │        └─ 0.001 _UnixSelectorEventLoop.call_later  asyncio/base_events.py:705
│  │  │     │     │  │           │        │        └─ 0.001 ResultProxy.__init__  aiopg/sa/result.py:244
│  │  │     │     │  │           │        │           └─ 0.001 ResultProxy._init_metadata  aiopg/sa/result.py:301
│  │  │     │     │  │           │        │              └─ 0.001 ResultMetaData.__init__  aiopg/sa/result.py:94
│  │  │     │     │  │           │        │                 └─ 0.001 ResultProxy.dialect  aiopg/sa/result.py:254
│  │  │     │     │  │           │        ├─ 0.003 SimcoreS3DataManager._clean_pending_upload  simcore_service_storage/simcore_s3_dsm.py:815
│  │  │     │     │  │           │        │  └─ 0.003 get  simcore_service_storage/db_file_meta_data.py:59
│  │  │     │     │  │           │        │     └─ 0.003 SAConnection._execute  aiopg/sa/connection.py:106
│  │  │     │     │  │           │        │        ├─ 0.002 Select.compile  sqlalchemy/sql/elements.py:439
│  │  │     │     │  │           │        │        │  └─ 0.002 Select._compiler  sqlalchemy/sql/elements.py:563
│  │  │     │     │  │           │        │        │     └─ 0.002 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:722
│  │  │     │     │  │           │        │        │        └─ 0.002 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:421
│  │  │     │     │  │           │        │        │           └─ 0.002 APGCompiler_psycopg2.process  sqlalchemy/sql/compiler.py:498
│  │  │     │     │  │           │        │        │              └─ 0.002 Select._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │        │        │                 └─ 0.002 bool.visit_select  sqlalchemy/sql/compiler.py:3377
│  │  │     │     │  │           │        │        │                    └─ 0.002 <listcomp>  sqlalchemy/sql/compiler.py:3485
│  │  │     │     │  │           │        │        │                       └─ 0.002 APGCompiler_psycopg2._label_select_column  sqlalchemy/sql/compiler.py:3157
│  │  │     │     │  │           │        │        │                          ├─ 0.001 Column._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │        │        │                          └─ 0.001 String.dialect_impl  sqlalchemy/sql/type_api.py:649
│  │  │     │     │  │           │        │        └─ 0.001 ResultProxy.__init__  aiopg/sa/result.py:244
│  │  │     │     │  │           │        │           └─ 0.001 ResultProxy._init_metadata  aiopg/sa/result.py:301
│  │  │     │     │  │           │        │              └─ 0.001 ResultMetaData.__init__  aiopg/sa/result.py:94
│  │  │     │     │  │           │        ├─ 0.002 get_file_access_rights  simcore_service_storage/db_access_layer.py:199
│  │  │     │     │  │           │        │  ├─ 0.001 SAConnection._execute  aiopg/sa/connection.py:106
│  │  │     │     │  │           │        │  │  └─ 0.001 Select.compile  sqlalchemy/sql/elements.py:439
│  │  │     │     │  │           │        │  │     └─ 0.001 Select._compiler  sqlalchemy/sql/elements.py:563
│  │  │     │     │  │           │        │  │        └─ 0.001 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:722
│  │  │     │     │  │           │        │  │           └─ 0.001 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:421
│  │  │     │     │  │           │        │  │              └─ 0.001 APGCompiler_psycopg2.process  sqlalchemy/sql/compiler.py:498
│  │  │     │     │  │           │        │  │                 └─ 0.001 Select._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│  │  │     │     │  │           │        │  │                    └─ 0.001 bool.visit_select  sqlalchemy/sql/compiler.py:3377
│  │  │     │     │  │           │        │  │                       └─ 0.001 <listcomp>  sqlalchemy/sql/compiler.py:3485
│  │  │     │     │  │           │        │  │                          └─ 0.001 APGCompiler_psycopg2._label_select_column  sqlalchemy/sql/compiler.py:3157
│  │  │     │     │  │           │        │  │                             └─ 0.001 String.dialect_impl  sqlalchemy/sql/type_api.py:649
│  │  │     │     │  │           │        │  │                                └─ 0.001 WeakKeyDictionary.__getitem__  weakref.py:415
│  │  │     │     │  │           │        │  └─ 0.001 get_project_access_rights  simcore_service_storage/db_access_layer.py:158
│  │  │     │     │  │           │        │     └─ 0.001 _get_user_groups_ids  simcore_service_storage/db_access_layer.py:89
│  │  │     │     │  │           │        │        └─ 0.001 SAConnection._execute  aiopg/sa/connection.py:106
│  │  │     │     │  │           │        │           └─ 0.001 SAConnection._open_cursor  aiopg/sa/connection.py:95
│  │  │     │     │  │           │        │              └─ 0.001 WeakSet.add  _weakrefset.py:86
│  │  │     │     │  │           │        │                 └─ 0.001 set.add  <built-in>
│  │  │     │     │  │           │        ├─ 0.001 match  re.py:187
│  │  │     │     │  │           │        │  └─ 0.001 _compile  re.py:288
│  │  │     │     │  │           │        └─ 0.001 _ContextManager.__aenter__  aiopg/utils.py:81
│  │  │     │     │  │           │           └─ 0.001 Engine._acquire  aiopg/sa/engine.py:205
│  │  │     │     │  │           │              └─ 0.001 Pool._acquire  aiopg/pool.py:304
│  │  │     │     │  │           │                 └─ 0.001 Timeout.__aenter__  async_timeout/__init__.py:131
│  │  │     │     │  │           │                    └─ 0.001 Timeout._do_enter  async_timeout/__init__.py:216
│  │  │     │     │  │           │                       └─ 0.001 Timeout._reschedule  async_timeout/__init__.py:200
│  │  │     │     │  │           │                          └─ 0.001 current_task  asyncio/tasks.py:35
│  │  │     │     │  │           │                             └─ 0.001 dict.get  <built-in>
│  │  │     │     │  │           └─ 0.001 StreamResponse.content_type  aiohttp/web_response.py:290
│  │  │     │     │  │              └─ 0.001 StreamResponse.content_type  aiohttp/web_response.py:285
│  │  │     │     │  │                 └─ 0.001 StreamResponse.content_type  aiohttp/helpers.py:781
│  │  │     │     │  │                    └─ 0.001 StreamResponse._parse_content_type  aiohttp/helpers.py:769
│  │  │     │     │  │                       └─ 0.001 HeaderParser.parsestr  email/parser.py:75
│  │  │     │     │  │                          └─ 0.001 HeaderParser.parsestr  email/parser.py:59
│  │  │     │     │  │                             └─ 0.001 HeaderParser.parse  email/parser.py:72
│  │  │     │     │  │                                └─ 0.001 HeaderParser.parse  email/parser.py:41
│  │  │     │     │  │                                   └─ 0.001 FeedParser.close  email/feedparser.py:184
│  │  │     │     │  │                                      └─ 0.001 FeedParser._call_parse  email/feedparser.py:178
│  │  │     │     │  │                                         └─ 0.001 FeedParser._parsegen  email/feedparser.py:218
│  │  │     │     │  │                                            └─ 0.001 FeedParser._parse_headers  email/feedparser.py:471
│  │  │     │     │  │                                               └─ 0.001 Compat32.header_source_parse  email/_policybase.py:293
│  │  │     │     │  └─ 0.002 _get_span  aiozipkin/aiohttp_helpers.py:80
│  │  │     │     │     ├─ 0.001 Tracer.new_trace  aiozipkin/tracer.py:50
│  │  │     │     │     │  └─ 0.001 Tracer.to_span  aiozipkin/tracer.py:69
│  │  │     │     │     │     └─ 0.001 Record.__init__  aiozipkin/record.py:20
│  │  │     │     │     │        └─ 0.001 _endpoint_asdict  aiozipkin/record.py:12
│  │  │     │     │     └─ 0.001 [self]  aiozipkin/aiohttp_helpers.py
│  │  │     │     ├─ 0.002 HTTPInternalServerError.__init__  aiohttp/web_exceptions.py:90
│  │  │     │     │  └─ 0.002 HTTPInternalServerError.text  aiohttp/web_response.py:686
│  │  │     │     │     └─ 0.002 HTTPInternalServerError.charset  aiohttp/web_response.py:296
│  │  │     │     │        └─ 0.002 HTTPInternalServerError.charset  aiohttp/helpers.py:789
│  │  │     │     │           └─ 0.002 HTTPInternalServerError._parse_content_type  aiohttp/helpers.py:769
│  │  │     │     │              ├─ 0.001 Message.get_content_type  email/message.py:564
│  │  │     │     │              │  └─ 0.001 _splitparam  email/message.py:29
│  │  │     │     │              └─ 0.001 Message.get_params  email/message.py:645
│  │  │     │     └─ 0.001 [self]  servicelib/aiohttp/monitoring.py
│  │  │     └─ 0.002 UrlDispatcher.resolve  aiohttp/web_urldispatcher.py:1017
│  │  │        ├─ 0.001 DynamicResource.resolve  aiohttp/web_urldispatcher.py:368
│  │  │        │  └─ 0.001 DynamicResource._match  aiohttp/web_urldispatcher.py:488
│  │  │        │     └─ 0.001 Pattern.fullmatch  <built-in>
│  │  │        └─ 0.001 [self]  aiohttp/web_urldispatcher.py
│  │  ├─ 0.002 [self]  asyncio/events.py
│  │  ├─ 0.001 Context.run  <built-in>
│  │  ├─ 0.001 _SelectorSocketTransport._read_ready  asyncio/selector_events.py:818
│  │  │  └─ 0.001 _SelectorSocketTransport._read_ready__data_received  asyncio/selector_events.py:858
│  │  │     └─ 0.001 RequestHandler.data_received  aiohttp/web_protocol.py:342
│  │  ├─ 0.001 _ready  aiopg/connection.py:779
│  │  │  └─ 0.001 decode  encodings/utf_8.py:15
│  │  └─ 0.001 _release_waiter  asyncio/tasks.py:387
│  │     └─ 0.001 Future.set_result  <built-in>
│  ├─ 0.005 EpollSelector.select  selectors.py:452
│  │  └─ 0.005 epoll.poll  <built-in>
│  └─ 0.001 [self]  asyncio/base_events.py
└─ 0.001 [self]  asyncio/base_events.py

As can be seen, the overhead is split more or less equally between SimcoreS3DataManager._search_files simcore_service_storage/simcore_s3_dsm.py:735 and get_readable_project_ids simcore_service_storage/db_access_layer.py:278

On the other hand, I can see that simply getting a file from its file_id is a very cheap operation. Hence, we should have an endpoint in storage which gets a file from its checksum (perhaps together with its filename), see #5770

@bisgaard-itis
Copy link
Contributor

bisgaard-itis commented May 2, 2024

Clearly the overhead in the above profile is due to the way we handle search for files with read access rights. The profile above is done searching for files with read access (deafult). When I do the same search but for files with write access I get

  _     ._   __/__   _ _  _  _ _/_   Recorded: 19:45:24  Samples:  11
 /_//_/// /_\ / //_// / //_'/ //     Duration: 0.013     CPU time: 0.012
/   _/                      v4.6.2

Program: /home/scu/.venv/bin/simcore-service-storage run

0.013 Handle._run  asyncio/events.py:78
├─ 0.012 RequestHandler._handle_request  aiohttp/web_protocol.py:442
│  └─ 0.012 Application._handle  aiohttp/web_app.py:509
│     └─ 0.012 impl  aiohttp/web_middlewares.py:111
│        └─ 0.012 middleware_handler  servicelib/aiohttp/monitoring.py:145
│           └─ 0.012 aiozipkin_middleware  aiozipkin/aiohttp_helpers.py:136
│              └─ 0.012 _middleware_handler  servicelib/aiohttp/rest_middlewares.py:67
│                 └─ 0.012 _middleware_handler  servicelib/aiohttp/rest_middlewares.py:153
│                    └─ 0.012 dsm_exception_handler  simcore_service_storage/utils_handlers.py:23
│                       └─ 0.012 profiling_middleware  servicelib/aiohttp/profiler_middleware.py:11
│                          ├─ 0.011 base_long_running_error_handler  servicelib/aiohttp/long_running_tasks/_error_handlers.py:15
│                          │  └─ 0.011 search_files  simcore_service_storage/handlers_simcore_s3.py:120
│                          │     ├─ 0.010 SimcoreS3DataManager.search_owned_files  simcore_service_storage/simcore_s3_dsm.py:725
│                          │     │  └─ 0.010 SimcoreS3DataManager._search_files  simcore_service_storage/simcore_s3_dsm.py:735
│                          │     │     ├─ 0.009 list_filter_with_partial_file_id  simcore_service_storage/db_file_meta_data.py:68
│                          │     │     │  ├─ 0.007 SAConnection._execute  aiopg/sa/connection.py:106
│                          │     │     │  │  ├─ 0.003 Select.compile  sqlalchemy/sql/elements.py:439
│                          │     │     │  │  │  └─ 0.003 Select._compiler  sqlalchemy/sql/elements.py:563
│                          │     │     │  │  │     └─ 0.003 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:722
│                          │     │     │  │  │        ├─ 0.002 APGCompiler_psycopg2.__init__  sqlalchemy/sql/compiler.py:421
│                          │     │     │  │  │        │  └─ 0.002 APGCompiler_psycopg2.process  sqlalchemy/sql/compiler.py:498
│                          │     │     │  │  │        │     └─ 0.002 Select._compiler_dispatch  sqlalchemy/sql/visitors.py:71
│                          │     │     │  │  │        │        └─ 0.002 bool.visit_select  sqlalchemy/sql/compiler.py:3377
│                          │     │     │  │  │        │           ├─ 0.001 CompileState.create_for_statement  sqlalchemy/sql/base.py:486
│                          │     │     │  │  │        │           │  └─ 0.001 SelectState.create_for_statement  sqlalchemy/sql/base.py:486
│                          │     │     │  │  │        │           │     └─ 0.001 SelectState.__init__  sqlalchemy/sql/selectable.py:4382
│                          │     │     │  │  │        │           │        └─ 0.001 Select._generate_columns_plus_names  sqlalchemy/sql/selectable.py:6195
│                          │     │     │  │  │        │           └─ 0.001 <listcomp>  sqlalchemy/sql/compiler.py:3485
│                          │     │     │  │  │        └─ 0.001 APGCompiler_psycopg2._process_parameters_for_postcompile  sqlalchemy/sql/compiler.py:1159
│                          │     │     │  │  ├─ 0.003 Cursor.execute  aiopg/connection.py:400
│                          │     │     │  │  │  └─ 0.003 Connection._poll  aiopg/connection.py:874
│                          │     │     │  │  │     └─ 0.003 wait_for  asyncio/tasks.py:392
│                          │     │     │  │  │        └─ 0.003 [await]  asyncio/tasks.py
│                          │     │     │  │  └─ 0.001 ResultProxy.__init__  aiopg/sa/result.py:244
│                          │     │     │  │     └─ 0.001 ResultProxy._init_metadata  aiopg/sa/result.py:301
│                          │     │     │  │        └─ 0.001 ResultMetaData.__init__  aiopg/sa/result.py:94
│                          │     │     │  ├─ 0.001 Column.__eq__  sqlalchemy/sql/operators.py:380
│                          │     │     │  │  └─ 0.001 Column.operate  sqlalchemy/sql/elements.py:872
│                          │     │     │  │     └─ 0.001 Comparator.__eq__  sqlalchemy/sql/operators.py:380
│                          │     │     │  │        └─ 0.001 Comparator.operate  sqlalchemy/sql/type_api.py:73
│                          │     │     │  │           └─ 0.001 _boolean_compare  sqlalchemy/sql/default_comparator.py:30
│                          │     │     │  │              └─ 0.001 BinaryExpression.__init__  sqlalchemy/sql/elements.py:3909
│                          │     │     │  │                 └─ 0.001 Column.self_group  sqlalchemy/sql/elements.py:817
│                          │     │     │  └─ 0.001 BooleanClauseList.__and__  sqlalchemy/sql/operators.py:59
│                          │     │     │     └─ 0.001 BooleanClauseList.operate  sqlalchemy/sql/elements.py:872
│                          │     │     │        └─ 0.001 Comparator.__and__  sqlalchemy/sql/operators.py:59
│                          │     │     │           └─ 0.001 Comparator.operate  sqlalchemy/sql/type_api.py:73
│                          │     │     │              └─ 0.001 _conjunction_operate  sqlalchemy/sql/default_comparator.py:145
│                          │     │     │                 └─ 0.001 BooleanClauseList.and_  sqlalchemy/sql/elements.py:2579
│                          │     │     │                    └─ 0.001 BooleanClauseList._construct  sqlalchemy/sql/elements.py:2504
│                          │     │     │                       └─ 0.001 BooleanClauseList._process_clauses_for_boolean  sqlalchemy/sql/elements.py:2465
│                          │     │     │                          └─ 0.001 <listcomp>  sqlalchemy/sql/elements.py:2502
│                          │     │     │                             └─ 0.001 BooleanClauseList.self_group  sqlalchemy/sql/elements.py:2699
│                          │     │     └─ 0.001 convert_db_to_model  simcore_service_storage/utils.py:17
│                          │     └─ 0.001 <listcomp>  simcore_service_storage/handlers_simcore_s3.py:154
│                          │        └─ 0.001 jsonable_encoder  models_library/utils/_original_fastapi_encoders.py:34
│                          │           └─ 0.001 jsonable_encoder  models_library/utils/_original_fastapi_encoders.py:34
│                          └─ 0.001 StreamResponse.content_type  aiohttp/web_response.py:290
│                             └─ 0.001 StreamResponse.content_type  aiohttp/web_response.py:285
│                                └─ 0.001 StreamResponse.content_type  aiohttp/helpers.py:781
│                                   └─ 0.001 StreamResponse._parse_content_type  aiohttp/helpers.py:769
│                                      └─ 0.001 HeaderParser.parsestr  email/parser.py:75
│                                         └─ 0.001 HeaderParser.parsestr  email/parser.py:59
│                                            └─ 0.001 HeaderParser.parse  email/parser.py:72
│                                               └─ 0.001 HeaderParser.parse  email/parser.py:41
│                                                  └─ 0.001 FeedParser.close  email/feedparser.py:184
└─ 0.001 [self]  asyncio/events.py

Hence, searching read-access files is approximately 180x slower than searching write-access files (note that the result of the search in this example is the same: the single file with a given sha256 checksum).The reason is that, in the case of read-access, we first fetch project ids for which the user has read access from the db into the python code and then to a second request to the db to get the searched files. Probably doing these two calls as a single join would do the job

@bisgaard-itis
Copy link
Contributor

bisgaard-itis commented May 2, 2024

Another interesting question (recently raised by @sanderegg ) is the performance difference between looking up a file via its id and searching for it via its sha256_checksum. Here's a little experiment where I did that:

(base) jovyan@31755d329263:~/mads$ time curl -N -X POST 'master_storage:8080/v0/simcore-s3/files/metadata:search?user_id=61349&sha256_checksum=581a042d8757c9bbd7b4679b89411c7dd66ff82cd84f1f1e6626f019bee285d5&access_right=write'
{"data":[{"file_uuid":"api/2094b0f6-1cad-3264-9502-60b52764a56f/input.data","location_id":0,"project_name":null,"node_name":null,"file_name":"input.data","file_id":"api/2094b0f6-1cad-3264-9502-60b52764a56f/input.data","created_at":"2024-04-30T08:47:37.625676","last_modified":"2024-04-30T08:47:37+00:00","file_size":33,"entity_tag":"9fa72c121e6c11244cc3b1c63b6efe57","is_soft_link":false,"is_directory":false,"sha256_checksum":"581a042d8757c9bbd7b4679b89411c7dd66ff82cd84f1f1e6626f019bee285d5"}]}
real    0m0.017s
user    0m0.010s
sys     0m0.000s
(base) jovyan@31755d329263:~/mads$ time curl -N -X GET 'master_storage:8080/v0/locations/0/files/api%2F2094b0f6-1cad-3264-9502-60b52764a56f%2Finput.data/metadata?user_id=61349'
{"data":{"file_uuid":"api/2094b0f6-1cad-3264-9502-60b52764a56f/input.data","location_id":0,"project_name":null,"node_name":null,"file_name":"input.data","file_id":"api/2094b0f6-1cad-3264-9502-60b52764a56f/input.data","created_at":"2024-04-30T08:47:37.625676","last_modified":"2024-04-30T08:47:37+00:00","file_size":33,"entity_tag":"9fa72c121e6c11244cc3b1c63b6efe57","is_soft_link":false,"is_directory":false,"sha256_checksum":"581a042d8757c9bbd7b4679b89411c7dd66ff82cd84f1f1e6626f019bee285d5"},"error":null}
real    0m0.031s
user    0m0.007s
sys     0m0.003s

As can be seen searching files with write-access does not carry a large overhead (as opposed to searching read-access files).

@sanderegg
Copy link
Member

@bisgaard-itis can you maybe explain how you ran the test? which deployment? also you said the read access rights takes longer to find as the write access rights. this is a very interesting fact. I think I would try to check why that is the case. The whole access rights being a JSON column, I think there must be something weird in how storage retrieve that. Or else also check my comment about moving the projects_access_rights to its own table.

@bisgaard-itis
Copy link
Contributor

bisgaard-itis commented May 3, 2024

@bisgaard-itis can you maybe explain how you ran the test? which deployment? also you said the read access rights takes longer to find as the write access rights. this is a very interesting fact. I think I would try to check why that is the case. The whole access rights being a JSON column, I think there must be something weird in how storage retrieve that. Or else also check my comment about moving the projects_access_rights to its own table.

Sure, I think I have a quite clear picture of why searching with read-access files takes a lot longer than the case of write-access. But I am not sure I can write it well here, so probably it is more efficient if I just explain it to you in person. We should sit down and have a look at it.

Here's how I ran the above experiment. I entered the admin panel on dalco master deployment and ran

curl -N -X POST -H 'x-profile: true' 'master_storage:8080/v0/simcore-s3/files/metadata:search?user_id=61349&sha256_checksum=581a042d8757c9bbd7b4679b89411c7dd66ff82cd84f1f1e6626f019bee285d5' | jq -r .profile

to get the profile in the case or read-access and

curl -N -X POST -H 'x-profile: true' 'master_storage:8080/v0/simcore-s3/files/metadata:search?user_id=61349&sha256_checksum=581a042d8757c9bbd7b4679b89411c7dd66ff82cd84f1f1e6626f019bee285d5&access_right=write' | jq -r .profile

to get the profile in the case of write access. Note these are searching for the same file via its checksum. Of course this benchmark depends heavily on the fact that I am using my user_id. If there is not much data in the db then performance should not be much different between the two searches.

@bisgaard-itis
Copy link
Contributor

bisgaard-itis commented May 5, 2024

After merging #5772 I close this issue.

Here's why I consider this issue closed: When running make master-parallel in https://github.com/wvangeit/osparc-pyapi-tests/tree/master/noninter1 and returning right after uploading the files, the 100 jobs run through without any exceptions. From the Grafana dashboards I can see the approximate avg time it takes to do the lookup (hitting the /v0/simcore-s3/files/metadata:search endpoint in storage) takes a bit less than 8e-3 seconds, which I consider acceptable. I don't see any way to do this faster as it is a single query to the db.

When not returning right after the uploading the files, most jobs still fail when running make master-parallel in https://github.com/wvangeit/osparc-pyapi-tests/tree/master/noninter1. Also many of them fail when doing the file lookup. But from looking at the Grafana dashboards (and considering the above mentioned result) it is quite clear that it is the fact that other endpoints, whose overhead is very large, are getting hit at the same time and blocking the lookup endpoint. Here's what I see in the Grafana dashboard for storage:

image

From this it is clear that a next target should be to reduce the overhead of

  • GET /v0/locations/{location_id}/files/{file_id}/metadata
  • GET /v0/locations/{location_id}/datasets

As a sidenote, I remark that this is qhat the CPU/RAM usage of the storage container looks the same timeframe as the above screenshot:

image

So clearly storage is under a lot of pressure 😓

@bisgaard-itis
Copy link
Contributor

bisgaard-itis commented May 5, 2024

After merging #5772 I close this issue.

Here's why I consider this issue closed: When running make master-parallel in https://github.com/wvangeit/osparc-pyapi-tests/tree/master/noninter1 and returning right after uploading the files, the 100 jobs run through without any exceptions. From the Grafana dashboards I can see the approximate avg time it takes to do the lookup (hitting the /v0/simcore-s3/files/metadata:search endpoint in storage) takes a bit less than 8e-3 seconds, which I consider acceptable. I don't see any way to do this faster as it is a single query to the db.

When not returning right after the uploading the files, most jobs still fail when running make master-parallel in https://github.com/wvangeit/osparc-pyapi-tests/tree/master/noninter1. Also many of them fail when doing the file lookup. But from looking at the Grafana dashboards (and considering the above mentioned result) it is quite clear that it is the fact that other endpoints, whose overhead is very large, are getting hit at the same time and blocking the lookup endpoint. Here's what I see in the Grafana dashboard for storage:

image

From this it is clear that a next target should be to reduce the overhead of

* `GET /v0/locations/{location_id}/files/{file_id}/metadata`

* `GET /v0/locations/{location_id}/datasets`

As a sidenote, I remark that this is qhat the CPU/RAM usage of the storage container looks the same timeframe as the above screenshot:

image

So clearly storage is under a lot of pressure 😓

These two endpoints are not hit directly by the api-server. Hence, probably the crook here is the create_project endpoint in the webserver. Next step I will take is to either profile that guy and see if I can improve performance or directly profile the create_study_job endpoint in the api-server to get a sense of the timings

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug buggy, it does not work as expected
Projects
None yet
Development

No branches or pull requests

4 participants