From f370852feddd5554281c3ce60d7fa3dfeb8869a1 Mon Sep 17 00:00:00 2001 From: Jonathan Rajotte Date: Wed, 6 Apr 2022 09:17:38 -0400 Subject: [PATCH] Fix: Revert of 814b4934e2604a419bcb8eec57c0450dbb47e2c3 MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit Observed issue ============== During high throughput event notification generation scenarios the following deadlock happens: Thread 14 (Thread 0x7f74b4ff9700 (LWP 76062)): #0 __lll_lock_wait (futex=futex@entry=0x56408765dde8, private=0) at lowlevellock.c:52 #1 0x00007f74c941a0a3 in __GI___pthread_mutex_lock (mutex=0x56408765dde8) at ../nptl/pthread_mutex_lock.c:80 #2 0x000056408704b207 in run_command_wait (handle=0x56408765ddd0, cmd=0x7f74b4ff7f70) at notification-thread-commands.cpp:31 #3 0x000056408704bcef in notification_thread_command_remove_tracer_event_source (handle=0x56408765ddd0, tracer_event_source_fd=54) at notification-thread-commands.cpp:319 #4 0x000056408708a0c1 in delete_ust_app (app=0x7f749c000bf0) at ust-app.cpp:1059 #5 0x000056408708a511 in delete_ust_app_rcu (head=0x7f749c000ca0) at ust-app.cpp:1122 #6 0x00007f74c988b4a7 in call_rcu_thread (arg=0x7f74b8004a80) at ../src/urcu-call-rcu-impl.h:369 #7 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #8 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 13 (Thread 0x7f74b57fa700 (LWP 76047)): #0 0x00007f74c933a49e in epoll_wait (epfd=48, events=0x7f74a4000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b57f9240, timeout=-1, interruptible=false) at compat/poll.cpp:280 #2 0x00005640870abb65 in thread_agent_management (data=0x56408765f0b0) at agent-thread.cpp:424 #3 0x0000564087062b1a in launch_thread (data=0x56408765f150) at thread.cpp:66 #4 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #5 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 12 (Thread 0x7f74b5ffb700 (LWP 76046)): [630/709] #0 0x00007f74c933a49e in epoll_wait (epfd=47, events=0x7f74a0000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b5ffa170, timeout=-1, interruptible=false) at compat/poll.cpp:280 #2 0x00005640870a4095 in thread_application_notification (data=0x56408765ee40) at notify-apps.cpp:78 #3 0x0000564087062b1a in launch_thread (data=0x56408765eed0) at thread.cpp:66 #4 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #5 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 11 (Thread 0x7f74b67fc700 (LWP 76045)): #0 0x00007f74c933a49e in epoll_wait (epfd=44, events=0x7f74ac000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b67fb170, timeout=-1, interruptible=false) at compat/poll.cpp:280 #2 0x00005640870723db in thread_application_management (data=0x56408765ebd0) at manage-apps.cpp:93 #3 0x0000564087062b1a in launch_thread (data=0x56408765ec60) at thread.cpp:66 #4 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #5 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 10 (Thread 0x7f74b6ffd700 (LWP 76044)): #0 0x00007f74c933a49e in epoll_wait (epfd=39, events=0x7f74a8000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b6ffc130, timeout=-1, interruptible=false) at compat/poll.cpp:280 #2 0x0000564087070a27 in thread_application_registration (data=0x56408765e940) at register.cpp:214 #3 0x0000564087062b1a in launch_thread (data=0x56408765e9f0) at thread.cpp:66 #4 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #5 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 9 (Thread 0x7f74b77fe700 (LWP 76043)): [654/709] #0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38 #1 0x00005640870c8e25 in futex (uaddr=0x5640871e2800 , op=0, val=-1, timeout=0x0, uaddr2=0x0, val3=0) at /home/joraj/lttng/master/install/include/urcu/futex.h:72 #2 0x00005640870c8e6d in futex_async (uaddr=0x5640871e2800 , op=0, val=-1, timeout=0x0, uaddr2=0x0, val3=0) at /home/joraj/lttng/master/install/include/urcu/futex.h:104 #3 0x00005640870c939a in futex_nto1_wait (futex=0x5640871e2800 ) at futex.cpp:77 #4 0x000056408706f2af in thread_dispatch_ust_registration (data=0x56408765e740) at dispatch.cpp:453 #5 0x0000564087062b1a in launch_thread (data=0x56408765e760) at thread.cpp:66 #6 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #7 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 8 (Thread 0x7f74b7fff700 (LWP 76042)): #0 0x00007f74c933a49e in epoll_wait (epfd=33, events=0x7f74b0000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b7ffad40, timeout=-1, interruptible=false) at compat/poll.cpp:280 #2 0x000056408706c424 in thread_manage_clients (data=0x56408765e4f0) at client.cpp:2528 #3 0x0000564087062b1a in launch_thread (data=0x56408765e560) at thread.cpp:66 #4 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #5 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 7 (Thread 0x7f74c4b8f700 (LWP 76041)): [672/709] #0 0x00007f74c933a49e in epoll_wait (epfd=31, events=0x7f74bc000b60, maxevents=3, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00005640870eafa6 in compat_epoll_wait (events=0x7f74c4b8e240, timeout=-1, interruptible=false) at compat/poll.cpp:280 #2 0x000056408705f2b6 in thread_rotation (data=0x56408765e280) at rotation-thread.cpp:804 #3 0x0000564087062b1a in launch_thread (data=0x56408765e310) at thread.cpp:66 #4 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #5 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 6 (Thread 0x7f74c5390700 (LWP 76040)): #0 0x00007f74c925f1d2 in __GI___sigtimedwait (set=0x7f74c538f090, info=0x7f74c538f110, timeout=0x0) at ../sysdeps/unix/sysv/linux/sigtimedwait.c:29 #1 0x000056408706138a in thread_timer (data=0x7ffc1fcbe3f0) at timer.cpp:359 #2 0x0000564087062b1a in launch_thread (data=0x56408765e0a0) at thread.cpp:66 #3 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #4 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 5 (Thread 0x7f74c5b91700 (LWP 76039)): #0 __libc_write (nbytes=8, buf=0x7f74c5b8fc88, fd=24) at ../sysdeps/unix/sysv/linux/write.c:26 #1 __libc_write (fd=24, buf=0x7f74c5b8fc88, nbytes=8) at ../sysdeps/unix/sysv/linux/write.c:24 #2 0x00005640870eeb4f in lttng_write (fd=24, buf=0x7f74c5b8fc88, count=8) at readwrite.cpp:77 #3 0x000056408704b535 in run_command_no_wait (handle=0x56408765ddd0, in_cmd=0x7f74c5b8fdf0) at notification-thread-commands.cpp:92 #4 0x000056408704bf49 in notification_thread_client_communication_update (handle=0x56408765ddd0, id=2, transmission_status=CLIENT_TRANSMISSION_STATUS_QUEUED) at notification-thread-command #5 0x000056408707bc62 in client_handle_transmission_status (client=0x7f74b80050d0, status=CLIENT_TRANSMISSION_STATUS_QUEUED, user_data=0x7f74b8004410) at action-executor.cpp:258 #6 0x0000564087057525 in notification_client_list_send_evaluation (client_list=0x7f74b8004df0, trigger=0x7f74b0001030, evaluation=0x7f74b815d1d0, source_object_creds=0x0, client_report=0x5 #7 0x000056408707bce9 in action_executor_notify_handler (executor=0x7f74b8004410, work_item=0x7f74b815d430, item=0x7f74b80e48e0) at action-executor.cpp:269 #8 0x000056408707dd6d in action_executor_generic_handler (executor=0x7f74b8004410, work_item=0x7f74b815d430, item=0x7f74b80e48e0) at action-executor.cpp:670 #9 0x000056408707df01 in action_work_item_execute (executor=0x7f74b8004410, work_item=0x7f74b815d430) at action-executor.cpp:689 #10 0x000056408707e525 in action_executor_thread (_data=0x7f74b8004410) at action-executor.cpp:771 [698/709] #11 0x0000564087062b1a in launch_thread (data=0x7f74b80044b0) at thread.cpp:66 #12 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #13 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 4 (Thread 0x7f74c6392700 (LWP 76038)): #0 __lll_lock_wait (futex=futex@entry=0x56408765dde8, private=0) at lowlevellock.c:52 #1 0x00007f74c941a0a3 in __GI___pthread_mutex_lock (mutex=0x56408765dde8) at ../nptl/pthread_mutex_lock.c:80 #2 0x0000564087053c89 in handle_notification_thread_command (handle=0x56408765ddd0, state=0x7f74c63911b0) at notification-thread-events.cpp:3142 #3 0x000056408704ac81 in thread_notification (data=0x56408765ddd0) at notification-thread.cpp:715 #4 0x0000564087062b1a in launch_thread (data=0x56408765dec0) at thread.cpp:66 #5 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #run_command_no_wait6 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 3 (Thread 0x7f74c6b93700 (LWP 76037)): #0 0x00007f74c933a49e in epoll_wait (epfd=21, events=0x7f74c0000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00005640870eafa6 in compat_epoll_wait (events=0x7f74c6b92170, timeout=-1, interruptible=false) at compat/poll.cpp:280 #2 0x000056408706400a in thread_manage_health (data=0x56408765db50) at health.cpp:140 #3 0x0000564087062b1a in launch_thread (data=0x56408765dbf0) at thread.cpp:66 #4 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #5 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 2 (Thread 0x7f74c7394700 (LWP 76036)): #0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38 #1 0x00007f74c987d238 in futex (uaddr=0x564087659b10, op=0, val=-1, timeout=0x0, uaddr2=0x0, val3=0) at ../include/urcu/futex.h:72 #2 futex_async (uaddr=0x564087659b10, op=0, val=-1, timeout=0x0, uaddr2=0x0, val3=0) at ../include/urcu/futex.h:104 #3 futex_wait (futex=0x564087659b10) at workqueue.c:136 #4 0x00007f74c987ced2 in workqueue_thread (arg=0x564087659ad0) at workqueue.c:237 #5 0x00007f74c9417609 in start_thread (arg=) at pthread_create.c:477 #6 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 1 (Thread 0x7f74c73cd300 (LWP 76034)): #0 0x00007f74c933a49e in epoll_wait (epfd=50, events=0x564087666880, maxevents=1, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00005640870eafa6 in compat_epoll_wait (events=0x7ffc1fcbe280, timeout=-1, interruptible=false) at compat/poll.cpp:280 #2 0x0000564087062244 in sessiond_wait_for_quit_pipe (timeout_ms=-1) at thread-utils.cpp:83 #3 0x00005640870127dc in main (argc=1, argv=0x7ffc1fcbe668) at main.cpp:1921 Cause ===== The event_pipe used to notify the notification poll loop is full and the lttng_write call blocks with the locks for both the client and the cmd_queue held. Solution ======== Go back to using eventfd but without the use of EFD_SEMAPHORE (linux 2.6.30) to continue supporting kernel between 2.6.27 and 2.6.29. The EFD_SEMAPHORE is emulated with a read, decrement, write as explained by the initial committer of EFD_SEMAPHORE [1]. Known drawbacks ========= This does not solve the actual block+lock problem but simply push it back further. The lttng_write on the eventfd can block when reaching UINT64_MAX. This would represent, at 1 command queued per ns (which is ridiculous), ~584 years of queueing without a dequeue operation. Reference ======= [1] https://lwn.net/Articles/318151/ Signed-off-by: Jonathan Rajotte Signed-off-by: Jérémie Galarneau Change-Id: Ie749c4169708f57463fe3cfab2366f1015bae4e0 --- .../notification-thread-commands.cpp | 4 +- .../notification-thread-events.cpp | 49 ++++++++++++++----- .../lttng-sessiond/notification-thread.cpp | 24 ++++----- .../lttng-sessiond/notification-thread.hpp | 2 +- 4 files changed, 54 insertions(+), 25 deletions(-) diff --git a/src/bin/lttng-sessiond/notification-thread-commands.cpp b/src/bin/lttng-sessiond/notification-thread-commands.cpp index 568580403..1de6ff58b 100644 --- a/src/bin/lttng-sessiond/notification-thread-commands.cpp +++ b/src/bin/lttng-sessiond/notification-thread-commands.cpp @@ -33,7 +33,7 @@ int run_command_wait(struct notification_thread_handle *handle, cds_list_add_tail(&cmd->cmd_list_node, &handle->cmd_queue.list); /* Wake-up thread. */ - ret = lttng_write(lttng_pipe_get_writefd(handle->cmd_queue.event_pipe), + ret = lttng_write(handle->cmd_queue.event_fd, ¬ification_counter, sizeof(notification_counter)); if (ret != sizeof(notification_counter)) { PERROR("write to notification thread's queue event fd"); @@ -89,7 +89,7 @@ int run_command_no_wait(struct notification_thread_handle *handle, cds_list_add_tail(&new_cmd->cmd_list_node, &handle->cmd_queue.list); /* Wake-up thread. */ - ret = lttng_write(lttng_pipe_get_writefd(handle->cmd_queue.event_pipe), + ret = lttng_write(handle->cmd_queue.event_fd, ¬ification_counter, sizeof(notification_counter)); if (ret != sizeof(notification_counter)) { PERROR("write to notification thread's queue event fd"); diff --git a/src/bin/lttng-sessiond/notification-thread-events.cpp b/src/bin/lttng-sessiond/notification-thread-events.cpp index 279bc7c5a..da4f8a4b2 100644 --- a/src/bin/lttng-sessiond/notification-thread-events.cpp +++ b/src/bin/lttng-sessiond/notification-thread-events.cpp @@ -3123,28 +3123,55 @@ end: return 0; } +static +int pop_cmd_queue(struct notification_thread_handle *handle, + struct notification_thread_command **cmd) +{ + int ret; + uint64_t counter; + + pthread_mutex_lock(&handle->cmd_queue.lock); + ret = lttng_read(handle->cmd_queue.event_fd, &counter, sizeof(counter)); + if (ret != sizeof(counter)) { + ret = -1; + goto error_unlock; + } + + /* Simulate behaviour of EFD_SEMAPHORE for older kernels. */ + counter -= 1; + if (counter != 0) { + ret = lttng_write(handle->cmd_queue.event_fd, &counter, + sizeof(counter)); + if (ret != sizeof(counter)) { + PERROR("Failed to write back to event_fd for EFD_SEMAPHORE emulation"); + ret = -1; + goto error_unlock; + } + } + + *cmd = cds_list_first_entry(&handle->cmd_queue.list, + struct notification_thread_command, cmd_list_node); + cds_list_del(&((*cmd)->cmd_list_node)); + ret = 0; + +error_unlock: + pthread_mutex_unlock(&handle->cmd_queue.lock); + return ret; +} + /* Returns 0 on success, 1 on exit requested, negative value on error. */ int handle_notification_thread_command( struct notification_thread_handle *handle, struct notification_thread_state *state) { int ret; - uint64_t counter; struct notification_thread_command *cmd; - /* Read the event pipe to put it back into a quiescent state. */ - ret = lttng_read(lttng_pipe_get_readfd(handle->cmd_queue.event_pipe), &counter, - sizeof(counter)); - if (ret != sizeof(counter)) { + ret = pop_cmd_queue(handle, &cmd); + if (ret) { goto error; } - pthread_mutex_lock(&handle->cmd_queue.lock); - cmd = cds_list_first_entry(&handle->cmd_queue.list, - struct notification_thread_command, cmd_list_node); - cds_list_del(&cmd->cmd_list_node); - pthread_mutex_unlock(&handle->cmd_queue.lock); - DBG("Received `%s` command", notification_command_type_str(cmd->type)); switch (cmd->type) { diff --git a/src/bin/lttng-sessiond/notification-thread.cpp b/src/bin/lttng-sessiond/notification-thread.cpp index cd95e6885..17a995682 100644 --- a/src/bin/lttng-sessiond/notification-thread.cpp +++ b/src/bin/lttng-sessiond/notification-thread.cpp @@ -18,6 +18,7 @@ #include #include #include +#include #include #include @@ -59,8 +60,11 @@ void notification_thread_handle_destroy( pthread_mutex_destroy(&handle->cmd_queue.lock); sem_destroy(&handle->ready); - if (handle->cmd_queue.event_pipe) { - lttng_pipe_destroy(handle->cmd_queue.event_pipe); + if (handle->cmd_queue.event_fd >= 0) { + ret = close(handle->cmd_queue.event_fd); + if (ret < 0) { + PERROR("Failed to close notification command queue event fd"); + } } if (handle->channel_monitoring_pipes.ust32_consumer >= 0) { ret = close(handle->channel_monitoring_pipes.ust32_consumer); @@ -92,7 +96,7 @@ struct notification_thread_handle *notification_thread_handle_create( { int ret; struct notification_thread_handle *handle; - struct lttng_pipe *event_pipe = NULL; + int event_fd = -1; handle = zmalloc(); if (!handle) { @@ -101,14 +105,13 @@ struct notification_thread_handle *notification_thread_handle_create( sem_init(&handle->ready, 0, 0); - event_pipe = lttng_pipe_open(FD_CLOEXEC); - if (!event_pipe) { - ERR("event_pipe creation"); + event_fd = eventfd(0, EFD_CLOEXEC); + if (event_fd < 0) { + PERROR("event_fd creation"); goto error; } - handle->cmd_queue.event_pipe = event_pipe; - event_pipe = NULL; + handle->cmd_queue.event_fd = event_fd; CDS_INIT_LIST_HEAD(&handle->cmd_queue.list); ret = pthread_mutex_init(&handle->cmd_queue.lock, NULL); @@ -150,7 +153,6 @@ struct notification_thread_handle *notification_thread_handle_create( end: return handle; error: - lttng_pipe_destroy(event_pipe); notification_thread_handle_destroy(handle); return NULL; } @@ -296,7 +298,7 @@ int init_poll_set(struct lttng_poll_event *poll_set, ERR("Failed to add notification channel socket to pollset"); goto error; } - ret = lttng_poll_add(poll_set, lttng_pipe_get_readfd(handle->cmd_queue.event_pipe), + ret = lttng_poll_add(poll_set, handle->cmd_queue.event_fd, LPOLLIN | LPOLLERR); if (ret < 0) { ERR("Failed to add notification command queue event fd to pollset"); @@ -711,7 +713,7 @@ void *thread_notification(void *data) ERR("Unexpected poll events %u for notification socket %i", revents, fd); goto error; } - } else if (fd == lttng_pipe_get_readfd(handle->cmd_queue.event_pipe)) { + } else if (fd == handle->cmd_queue.event_fd) { ret = handle_notification_thread_command(handle, &state); if (ret < 0) { diff --git a/src/bin/lttng-sessiond/notification-thread.hpp b/src/bin/lttng-sessiond/notification-thread.hpp index 3444af9c0..2f77189ad 100644 --- a/src/bin/lttng-sessiond/notification-thread.hpp +++ b/src/bin/lttng-sessiond/notification-thread.hpp @@ -63,7 +63,7 @@ struct notification_thread_handle { * has been enqueued. */ struct { - struct lttng_pipe *event_pipe; + int event_fd; struct cds_list_head list; pthread_mutex_t lock; } cmd_queue; -- 2.34.1