Details
-
Test
-
Status: In Progress
-
Major
-
Resolution: Unresolved
-
1.16.0
-
None
Description
This issue holds files related to thread locking analysis tracked in [https://github.com/apache/qpid-dispatch/pull/1261|PR-1261]. As the PR progresses analysis results will be posted here.
Attachments
Attachments
- DISPATCH-2183_3f2bd_router-mesh_three-router-test_routerb.txt
- 104 kB
- Charles E. Rolke
- DISPATCH-2183_80c84_PYTHON-locking-during-get-schema.txt
- 317 kB
- Charles E. Rolke
- DISPATCH-2183_85f805_topology-disposition-routerA.txt
- 282 kB
- Charles E. Rolke
- DISPATCH-2183_pr1261_at_80c84.txt
- 31 kB
- Charles E. Rolke
Activity
Commit 2b7a4 adds
- printouts of the router server start/stop times
- deadlock analysis
Two recurring deadlocks happen in multiple routers:
CONNECTOR - ENTITY_CACHE
This lock inversion occurs after startup and before shutdown and should be mitigated.
371179227080 Server begin time: 2021-07-06 14:22:59.698457, ticks: 371179227080 371179227358 TID: 0x513580 LOCK CONNECTOR ALLOC_INIT ENTITY_CACHE ==> [ LOCK acquire_uS 0 ] 371179227407 TID: 0x513580 UNLOCK CONNECTOR ALLOC_INIT ENTITY_CACHE <== [0x17bb488 UNLOCK acquire_uS 0 use 49 total 49 ] 371228850930 TID: 0x513580 LOCK PYTHON ROUTER ENTITY_CACHE CONNECTOR ==> [ LOCK acquire_uS 0 ] 371228850938 TID: 0x513580 UNLOCK PYTHON ROUTER ENTITY_CACHE CONNECTOR <== [0x1b1c848 UNLOCK acquire_uS 0 use 8 total 8 ] 371229387480 Server end time: 2021-07-06 14:23:49.858857, ticks: 371229387480
LOG - ENTITY_CACHE
This inversion appears less problematic as code holding the LOG lock and taking the ENTITY_CACHE lock happens only at startup.
At runtime code holding the ENTITY_CACHE lock routinely takes the LOG lock.
371179125586 TID: 0x513580 LOCK LOG ENTITY_CACHE ==> [ LOCK acquire_uS 0 ] 371179125591 TID: 0x513580 UNLOCK LOG ENTITY_CACHE <== [0x17bb488 UNLOCK acquire_uS 0 use 5 total 5 ] 371179220368 TID: 0x513580 LOCK PYTHON LOG ENTITY_CACHE ==> [ LOCK acquire_uS 0 ] 371179220372 TID: 0x513580 UNLOCK PYTHON LOG ENTITY_CACHE <== [0x17bb488 UNLOCK acquire_uS 0 use 4 total 4 ] 371179227080 Server begin time: 2021-07-06 14:22:59.698457, ticks: 371179227080 371228849932 TID: 0x513580 LOCK PYTHON ROUTER ENTITY_CACHE LOG ==> [ LOCK acquire_uS 1 ] 371229387480 Server end time: 2021-07-06 14:23:49.858857, ticks: 371229387480
PYTHON - SERVER
Grepping all the self-test logs and out files reveals a third inversion pattern. This pattern is not a problem as it happens only during startup.
After adding program stack backtrace to the lock analysis setup then the code causing the lock inversions are identified.
connector-before-entity_cache when connector creates a new connection
462473116894 TID: 0x513580 LOCK connector ALLOC_INIT ENTITY_CACHE ==> [ LOCK acquire_uS 0 stack_0: qdrouterd(_dump_locks_lock+0x15e) [0x46bbf9], stack_1: qdrouterd(sys_mutex_lock+0x13b) [0x46c283], stack_2: qdrouterd() [0x45230d], stack_3: qdrouterd(qd_entity_cache_add+0x25) [0x452439], stack_4: qdrouterd() [0x443f2e], stack_5: qdrouterd(qd_alloc+0x2a) [0x443f6a], stack_6: qdrouterd(new_qd_connection_t+0x20) [0x4b5420], stack_7: qdrouterd(qd_server_connection+0x15) [0x4b6e3c], stack_8: qdrouterd(try_open_lh+0x27) [0x4b90ce], stack_9: qdrouterd(try_open_cb+0x50) [0x4b9933], ] 462473117172 TID: 0x513580 UNLOCK connector ALLOC_INIT ENTITY_CACHE <== [0x1c7c488 UNLOCK acquire_uS 0 use 278 total 278 stack_0: qdrouterd(_dump_locks_unlock+0x1dd) [0x46be90], stack_1: qdrouterd(sys_mutex_unlock+0x102) [0x46c388], stack_2: qdrouterd() [0x45240f], stack_3: qdrouterd(qd_entity_cache_add+0x25) [0x452439], stack_4: qdrouterd() [0x443f2e], stack_5: qdrouterd(qd_alloc+0x2a) [0x443f6a], stack_6: qdrouterd(new_qd_connection_t+0x20) [0x4b5420], stack_7: qdrouterd(qd_server_connection+0x15) [0x4b6e3c], stack_8: qdrouterd(try_open_lh+0x27) [0x4b90ce], stack_9: qdrouterd(try_open_cb+0x50) [0x4b9933], ]
entity_cache-before-connector during routine management refresh cycle
462480493625 TID: 0x1df81c0 LOCK PYTHON ROUTER ENTITY_CACHE connector ==> [ LOCK acquire_uS 0 stack_0: qdrouterd(_dump_locks_lock+0x15e) [0x46bbf9], stack_1: qdrouterd(sys_mutex_lock+0x13b) [0x46c283], stack_2: qdrouterd(qd_entity_refresh_connector+0x46) [0x44b6ef], stack_3: /lib64/libffi.so.6(ffi_call_unix64+0x4c) [0x7f3cae2f2b10], stack_4: /lib64/libffi.so.6(ffi_call+0x1c3) [0x7f3cae2f20a3], stack_5: /usr/lib64/python3.9/lib-dynload/_ctypes.cpython-39-x86_64-linux-gnu.so(+0x12b94) [0x7f3cadf83b94], stack_6: /usr/lib64/python3.9/lib-dynload/_ctypes.cpython-39-x86_64-linux-gnu.so(+0x121a0) [0x7f3cadf831a0], stack_7: /lib64/libpython3.9.so.1.0(_PyObject_MakeTpCall+0x83) [0x7f3cbc77aee3], stack_8: /lib64/libpython3.9.so.1.0(_PyEval_EvalFrameDefault+0x599b) [0x7f3cbc777b3b], stack_9: /lib64/libpython3.9.so.1.0(+0x118b1b) [0x7f3cbc77fb1b], ] 462480493773 TID: 0x1df81c0 UNLOCK PYTHON ROUTER ENTITY_CACHE connector <== [0x1ff66c8 UNLOCK acquire_uS 0 use 148 total 148 stack_0: qdrouterd(_dump_locks_unlock+0x1dd) [0x46be90], stack_1: qdrouterd(sys_mutex_unlock+0x102) [0x46c388], stack_2: qdrouterd(qd_entity_refresh_connector+0x2c0) [0x44b969], stack_3: /lib64/libffi.so.6(ffi_call_unix64+0x4c) [0x7f3cae2f2b10], stack_4: /lib64/libffi.so.6(ffi_call+0x1c3) [0x7f3cae2f20a3], stack_5: /usr/lib64/python3.9/lib-dynload/_ctypes.cpython-39-x86_64-linux-gnu.so(+0x12b94) [0x7f3cadf83b94], stack_6: /usr/lib64/python3.9/lib-dynload/_ctypes.cpython-39-x86_64-linux-gnu.so(+0x121a0) [0x7f3cadf831a0], stack_7: /lib64/libpython3.9.so.1.0(_PyObject_MakeTpCall+0x83) [0x7f3cbc77aee3], stack_8: /lib64/libpython3.9.so.1.0(_PyEval_EvalFrameDefault+0x599b) [0x7f3cbc777b3b], stack_9: /lib64/libpython3.9.so.1.0(+0x118b1b) [0x7f3cbc77fb1b], ]
The following lock stacks are observed while running the full suite of self tests
Lock stacks =========== Found 139 lock stacks In each line the first held lock is on the left ALLOC_INIT,ENTITY_CACHE CONNECTOR,ALLOC_INIT CONNECTOR,ALLOC_INIT,ENTITY_CACHE CONNECTOR,LOG CONNECTOR,LOG,qd_log_entry_t CONNECTOR,SERVER CONNECTOR,qd_connection_t CONNECTOR,qd_log_entry_t CONN_ACTIVATION,LOG CONN_ACTIVATION,LOG,qd_log_entry_t CONN_ACTIVATION,SERVER CONN_ACTIVATION,qd_connection_t CONN_ACTIVATION,qd_log_entry_t CONN_WORK,ALLOC_INIT CONN_WORK,ALLOC_INIT,ENTITY_CACHE CONN_WORK,CORE_ACTION CONN_WORK,LOG CONN_WORK,LOG,qd_log_entry_t CONN_WORK,qd_buffer_t CONN_WORK,qd_iterator_t CONN_WORK,qd_log_entry_t CONN_WORK,qdr_action_t CONN_WORK,qdr_delivery_cleanup_t CONN_WORK,qdr_delivery_ref_t CONN_WORK,qdr_delivery_t CONN_WORK,qdr_error_t CONN_WORK,qdr_field_t CONN_WORK,qdr_link_ref_t CONN_WORK,qdr_link_work_t CORE_ACTION,qdr_action_t HTTP1_ADAPTOR,CORE_ACTION HTTP1_ADAPTOR,SERVER HTTP1_ADAPTOR,qdr_action_t LOG,ENTITY_CACHE LOG,qd_log_entry_t MSG_CONTENT,ALLOC_INIT MSG_CONTENT,ALLOC_INIT,ENTITY_CACHE MSG_CONTENT,qd_buffer_t MSG_CONTENT,qd_message_stream_data_t PYTHON,ALLOC_INIT PYTHON,ALLOC_INIT,ENTITY_CACHE PYTHON,CONNECTOR PYTHON,CONNECTOR,ALLOC_INIT PYTHON,CONNECTOR,ALLOC_INIT,ENTITY_CACHE PYTHON,CONNECTOR,CONN_ACTIVATION PYTHON,CONNECTOR,CONN_DEFERRED_CALL PYTHON,CONNECTOR,SERVER PYTHON,CONNECTOR,qd_deferred_call_t PYTHON,CONTAINER PYTHON,CONTAINER,ALLOC_INIT PYTHON,CONTAINER,ALLOC_INIT,ENTITY_CACHE PYTHON,CONTAINER,qd_hash_item_t PYTHON,CORE_ACTION PYTHON,CORE_ID PYTHON,HTTP1_ADAPTOR PYTHON,HTTP1_ADAPTOR,CORE_ACTION PYTHON,HTTP1_ADAPTOR,SERVER PYTHON,HTTP1_ADAPTOR,qdr_action_t PYTHON,HTTP2_ADAPTOR PYTHON,LOG PYTHON,LOG,ENTITY_CACHE PYTHON,LOG,qd_log_entry_t PYTHON,LWS_WORK_QUEUE PYTHON,MSG_CONTENT PYTHON,POLICY_TREE PYTHON,POLICY_TREE,LOG PYTHON,POLICY_TREE,qd_hash_handle_t PYTHON,POLICY_TREE,qd_hash_item_t PYTHON,POLICY_TREE,qd_log_entry_t PYTHON,POLICY_TREE,qd_parse_node_t PYTHON,ROUTER PYTHON,ROUTER,ENTITY_CACHE PYTHON,ROUTER,ENTITY_CACHE,CONNECTOR PYTHON,ROUTER,ENTITY_CACHE,LOG PYTHON,ROUTER,ENTITY_CACHE,LOG,qd_log_entry_t PYTHON,ROUTER,ENTITY_CACHE,POLICY_STATS PYTHON,ROUTER,ENTITY_CACHE,bridge_stats_lock PYTHON,ROUTER,ENTITY_CACHE,qd_log_entry_t PYTHON,SERVER PYTHON,SERVER,qd_timer_t PYTHON,TRACE_MASK PYTHON,TRACE_MASK,ALLOC_INIT PYTHON,TRACE_MASK,ALLOC_INIT,ENTITY_CACHE PYTHON,TRACE_MASK,qd_hash_handle_t PYTHON,TRACE_MASK,qd_hash_item_t PYTHON,TRACE_MASK,qdtm_router_t PYTHON,bridge_stats_lock PYTHON,qd_bitmask_t PYTHON,qd_buffer_t PYTHON,qd_composed_field_t PYTHON,qd_composite_t PYTHON,qd_connector_t PYTHON,qd_hash_handle_t PYTHON,qd_hash_item_t PYTHON,qd_http_connector_t PYTHON,qd_http_listener_t PYTHON,qd_iterator_t PYTHON,qd_listener_t PYTHON,qd_log_entry_t PYTHON,qd_message_content_t PYTHON,qd_message_t PYTHON,qd_node_t PYTHON,qd_parse_node_t PYTHON,qd_parse_tree_t PYTHON,qd_parsed_field_t PYTHON,qd_tcp_bridge_t PYTHON,qd_tcp_connector_t PYTHON,qd_tcp_listener_t PYTHON,qd_timer_t PYTHON,qdr_action_t PYTHON,qdr_address_t PYTHON,qdr_connection_info_t PYTHON,qdr_connection_t PYTHON,qdr_core_timer_t PYTHON,qdr_field_t PYTHON,qdr_http1_connection_t PYTHON,qdr_http2_connection_t PYTHON,qdr_http2_session_data_t PYTHON,qdr_http2_stream_data_t PYTHON,qdr_link_t PYTHON,qdr_query_t PYTHON,qdr_tcp_connection_t PYTHON,qdr_terminus_t SERVER,LOG SERVER,LOG,qd_log_entry_t SERVER,POLICY_STATS SERVER,PYTHON SERVER,qd_log_entry_t SERVER,qd_timer_t TCP_ACTIVATION,LOG TCP_ACTIVATION,LOG,qd_log_entry_t TCP_ACTIVATION,qd_log_entry_t TRACE_MASK,qd_hash_handle_t TRACE_MASK,qd_hash_item_t TRACE_MASK,qdtm_router_t delivery-433,qd_delivery_state_t delivery-437,qd_delivery_state_t delivery-439,qd_delivery_state_t delivery-459,qd_delivery_state_t
While investigating the SERVER-PYTHON inversion this table emerged. The test program counts the lines of UNLOCK output as they are processed and further counts how many times each individual lock stack is encountered. Locks stacks with only one lock (i.e. lock is taken and released without taking any other lock) are not processed other than counting the 54+ million of them.
This is generated by the full self test suite.
Lock stacks =========== Found 69785766 lines total Found 69785766 UNLOCK lines Found 135 lock stacks len >= 2 to process Found 54202664 lock stacks len == 1 to ignore ALLOC_INIT,ENTITY_CACHE : n= 6661 : CONN_ACTIVATION,LOG : n= 154 : CONN_ACTIVATION,LOG,qd_log_entry_t : n= 126 : CONN_ACTIVATION,SERVER : n= 1 : CONN_ACTIVATION,qd_connection_t : n= 3536 : CONN_ACTIVATION,qd_log_entry_t : n= 156 : CONN_WORK,ALLOC_INIT : n= 256 : CONN_WORK,ALLOC_INIT,ENTITY_CACHE : n= 256 : CONN_WORK,CORE_ACTION : n= 38 : CONN_WORK,LOG : n= 757792 : CONN_WORK,LOG,qd_log_entry_t : n= 746164 : CONN_WORK,qd_buffer_t : n= 810 : CONN_WORK,qd_iterator_t : n= 810 : CONN_WORK,qd_log_entry_t : n= 758580 : CONN_WORK,qdr_action_t : n= 40 : CONN_WORK,qdr_delivery_cleanup_t : n= 330 : CONN_WORK,qdr_delivery_ref_t : n= 165289 : CONN_WORK,qdr_delivery_t : n= 330 : CONN_WORK,qdr_error_t : n= 487 : CONN_WORK,qdr_field_t : n= 810 : CONN_WORK,qdr_link_ref_t : n= 353081 : CONN_WORK,qdr_link_work_t : n= 179491 : CORE_ACTION,qdr_action_t : n= 76257 : HTTP1_ADAPTOR,CORE_ACTION : n= 8 : HTTP1_ADAPTOR,SERVER : n= 503 : HTTP1_ADAPTOR,qdr_action_t : n= 8 : LOG,ENTITY_CACHE : n= 1760 : LOG,qd_log_entry_t : n= 6887152 : MSG_CONTENT,ALLOC_INIT : n= 20 : MSG_CONTENT,ALLOC_INIT,ENTITY_CACHE : n= 20 : MSG_CONTENT,qd_buffer_t : n= 4211906 : MSG_CONTENT,qd_message_stream_data_t : n= 12361 : PYTHON,ALLOC_INIT : n= 5452 : PYTHON,ALLOC_INIT,ENTITY_CACHE : n= 5452 : PYTHON,CONTAINER : n= 336 : PYTHON,CONTAINER,ALLOC_INIT : n= 336 : PYTHON,CONTAINER,ALLOC_INIT,ENTITY_CACHE : n= 336 : PYTHON,CONTAINER,qd_hash_item_t : n= 1008 : PYTHON,CORE_ACTION : n= 11763 : PYTHON,CORE_ID : n= 14 : PYTHON,HTTP1_ADAPTOR : n= 20 : PYTHON,HTTP1_ADAPTOR,CORE_ACTION : n= 1 : PYTHON,HTTP1_ADAPTOR,SERVER : n= 9 : PYTHON,HTTP1_ADAPTOR,qdr_action_t : n= 1 : PYTHON,HTTP2_ADAPTOR : n= 1 : PYTHON,LOG : n= 62096 : PYTHON,LOG,ENTITY_CACHE : n= 5392 : PYTHON,LOG,qd_log_entry_t : n= 14941 : PYTHON,LWS_WORK_QUEUE : n= 24 : PYTHON,MSG_CONTENT : n= 7696 : PYTHON,POLICY_TREE : n= 7 : PYTHON,POLICY_TREE,LOG : n= 10 : PYTHON,POLICY_TREE,qd_hash_handle_t : n= 8 : PYTHON,POLICY_TREE,qd_hash_item_t : n= 4 : PYTHON,POLICY_TREE,qd_log_entry_t : n= 8 : PYTHON,POLICY_TREE,qd_parse_node_t : n= 6 : PYTHON,ROUTER : n= 1314 : PYTHON,ROUTER,ENTITY_CACHE : n= 1314 : PYTHON,ROUTER,ENTITY_CACHE,LOG : n= 15731 : PYTHON,ROUTER,ENTITY_CACHE,LOG,qd_log_entry_t : n= 863 : PYTHON,ROUTER,ENTITY_CACHE,POLICY_STATS : n= 978 : PYTHON,ROUTER,ENTITY_CACHE,bridge_stats_lock : n= 145 : PYTHON,ROUTER,ENTITY_CACHE,connector : n= 402 : PYTHON,ROUTER,ENTITY_CACHE,qd_log_entry_t : n= 16624 : PYTHON,SERVER : n= 371 : PYTHON,SERVER,qd_timer_t : n= 11 : PYTHON,TRACE_MASK : n= 640 : PYTHON,TRACE_MASK,ALLOC_INIT : n= 128 : PYTHON,TRACE_MASK,ALLOC_INIT,ENTITY_CACHE : n= 128 : PYTHON,TRACE_MASK,qd_hash_handle_t : n= 387 : PYTHON,TRACE_MASK,qd_hash_item_t : n= 387 : PYTHON,TRACE_MASK,qdtm_router_t : n= 463 : PYTHON,bridge_stats_lock : n= 121 : PYTHON,connector : n= 369 : PYTHON,connector,CONN_ACTIVATION : n= 7 : PYTHON,connector,CONN_DEFERRED_CALL : n= 7 : PYTHON,connector,SERVER : n= 181 : PYTHON,qd_bitmask_t : n= 2286 : PYTHON,qd_buffer_t : n= 74510 : PYTHON,qd_composed_field_t : n= 47848 : PYTHON,qd_composite_t : n= 125918 : PYTHON,qd_connector_t : n= 495 : PYTHON,qd_deferred_call_t : n= 19 : PYTHON,qd_hash_handle_t : n= 1825 : PYTHON,qd_hash_item_t : n= 1397 : PYTHON,qd_http_connector_t : n= 25 : PYTHON,qd_http_listener_t : n= 25 : PYTHON,qd_iterator_t : n= 599462 : PYTHON,qd_listener_t : n= 1228 : PYTHON,qd_log_entry_t : n= 49078 : PYTHON,qd_message_content_t : n= 9062 : PYTHON,qd_message_t : n= 23200 : PYTHON,qd_node_t : n= 1008 : PYTHON,qd_parse_node_t : n= 2201 : PYTHON,qd_parse_tree_t : n= 2056 : PYTHON,qd_parsed_field_t : n= 265820 : PYTHON,qd_tcp_bridge_t : n= 130 : PYTHON,qd_tcp_connector_t : n= 37 : PYTHON,qd_tcp_listener_t : n= 119 : PYTHON,qd_timer_t : n= 1903 : PYTHON,qdr_action_t : n= 12648 : PYTHON,qdr_address_t : n= 1700 : PYTHON,qdr_connection_info_t : n= 59 : PYTHON,qdr_connection_t : n= 59 : PYTHON,qdr_core_timer_t : n= 1511 : PYTHON,qdr_field_t : n= 11172 : PYTHON,qdr_http1_connection_t : n= 21 : PYTHON,qdr_http2_connection_t : n= 3 : PYTHON,qdr_http2_session_data_t : n= 3 : PYTHON,qdr_http2_stream_data_t : n= 3 : PYTHON,qdr_link_t : n= 38 : PYTHON,qdr_query_t : n= 935 : PYTHON,qdr_tcp_connection_t : n= 35 : PYTHON,qdr_terminus_t : n= 52 : SERVER,LOG : n= 3985 : SERVER,LOG,qd_log_entry_t : n= 2424 : SERVER,POLICY_STATS : n= 6793 : SERVER,PYTHON : n= 462 : SERVER,qd_log_entry_t : n= 4197 : SERVER,qd_timer_t : n= 1180 : TCP_ACTIVATION,LOG : n= 1281 : TCP_ACTIVATION,LOG,qd_log_entry_t : n= 1161 : TCP_ACTIVATION,qd_log_entry_t : n= 1287 : TRACE_MASK,qd_hash_handle_t : n= 187 : TRACE_MASK,qd_hash_item_t : n= 187 : TRACE_MASK,qdtm_router_t : n= 275 : connector,LOG : n= 255 : connector,LOG,qd_log_entry_t : n= 31 : connector,SERVER : n= 376 : connector,qd_log_entry_t : n= 431 : delivery-405,qd_delivery_state_t : n= 2 : delivery-407,qd_delivery_state_t : n= 2 : delivery-409,qd_delivery_state_t : n= 3 : delivery-411,qd_delivery_state_t : n= 6 : delivery-431,qd_delivery_state_t : n= 1 : Possible deadlocks ================== Inversion PYTHON and SERVER Inversion ENTITY_CACHE and LOG Inversion LOG and ENTITY_CACHE Inversion SERVER and PYTHON SERVER,PYTHON : n= 462 : ./tests/system_test.dir/system_tests_authz_service_plugin/AuthServicePluginAuthzTest/setUpClass/router-3.out:619102552328 TID: 0x1180190 UNLOCK SERVER PYTHON <== [0xe73a08 UNLOCK acquire_uS 0 use 227 total 227 stack_0: qdrouterd(_dump_locks_unlock+0x1dd) [0x46bebc], stack_1: qdrouterd(sys_mutex_unlock+0x102) [0x46c3b4], stack_2: qdrouterd(qd_python_unlock+0x21) [0x46f4b0], stack_3: qdrouterd(qd_policy_socket_close+0x15c) [0x465428], stack_4: qdrouterd(qd_connection_free+0x201) [0x4b86b4], stack_5: qdrouterd(thread_run+0x119) [0x4b9053], stack_6: qdrouterd() [0x46cf6c], stack_7: /lib64/libpthread.so.0(+0x93f9) [0x7f795e6ed3f9], stack_8: /lib64/libc.so.6(clone+0x43) [0x7f795e2004c3], ] PYTHON,SERVER : n= 371 : ./tests/system_test.dir/system_tests_qdmanage/QdmanageTest/setUpClass/test_router_1-2.out:618541611189 TID: 0x514580 UNLOCK PYTHON SERVER <== [0x1a64548 UNLOCK acquire_uS 0 use 156 total 156 stack_0: qdrouterd(_dump_locks_unlock+0x1dd) [0x46bebc], stack_1: qdrouterd(sys_mutex_unlock+0x102) [0x46c3b4], stack_2: qdrouterd(qd_timer_schedule+0x3ee) [0x4bbd19], stack_3: qdrouterd(qd_router_setup_late+0xfa) [0x4b3e58], stack_4: /lib64/libffi.so.6(ffi_call_unix64+0x4c) [0x7f19c31ecb10], stack_5: /lib64/libffi.so.6(ffi_call+0x1c3) [0x7f19c31ec0a3], stack_6: /usr/lib64/python3.9/lib-dynload/_ctypes.cpython-39-x86_64-linux-gnu.so(+0x12b94) [0x7f19c2e7db94], stack_7: /usr/lib64/python3.9/lib-dynload/_ctypes.cpython-39-x86_64-linux-gnu.so(+0x121a0) [0x7f19c2e7d1a0], stack_8: /lib64/libpython3.9.so.1.0(_PyObject_MakeTpCall+0x83) [0x7f19d1674ee3], stack_9: /lib64/libpython3.9.so.1.0(_PyEval_EvalFrameDefault+0x599b) [0x7f19d1671b3b], ] PYTHON,SERVER,qd_timer_t : n= 11 : ./tests/system_test.dir/system_tests_qdmanage/QdmanageTest/setUpClass/test_router_1-2.out:618608318235 TID: 0x514580 UNLOCK PYTHON SERVER qd_timer_t <== [0x1c7f708 UNLOCK acquire_uS 1 use 210 total 211 stack_0: qdrouterd(_dump_locks_unlock+0x1dd) [0x46bebc], stack_1: qdrouterd(sys_mutex_unlock+0x102) [0x46c3b4], stack_2: qdrouterd(qd_dealloc+0x23a) [0x4448c7], stack_3: qdrouterd(free_qd_timer_t+0x30) [0x4bb38f], stack_4: qdrouterd() [0x4bb6ac], stack_5: qdrouterd(qd_timer_free+0xee) [0x4bb87b], stack_6: qdrouterd(qd_connection_manager_delete_connector+0xf8) [0x44c6e8], stack_7: /lib64/libffi.so.6(ffi_call_unix64+0x4c) [0x7f19c31ecb10], stack_8: /lib64/libffi.so.6(ffi_call+0x1c3) [0x7f19c31ec0a3], stack_9: /usr/lib64/python3.9/lib-dynload/_ctypes.cpython-39-x86_64-linux-gnu.so(+0x12b94) [0x7f19c2e7db94], ]
Commit 3f2bd adds a few improvements the biggest of which is untangling the held_lock in the core thread condition wait. This commit also trims the system tests router logging to info level to get the log locks out of the picture (at the expense of having a bunch of tests that rely on logging fail).