[lttng-dev] ***UNCHECKED*** Re: urcu workqueue thread uses 99% of cpu while workqueue is empty
Minlan Wang
wangminlan at szsandstone.com
Wed Jun 22 03:45:35 EDT 2022
Hi, Mathieu,
On Tue, Jun 21, 2022 at 09:12:38AM -0400, Mathieu Desnoyers wrote:
> > @@ -0,0 +1,82 @@
> > +#undef LTTNG_UST_TRACEPOINT_PROVIDER
> > +#define LTTNG_UST_TRACEPOINT_PROVIVER workqueue
>
> If you change "PROVIVER" into "PROVIDER" here, does it fix your issue ?
Yes, this did solve the compile problem of the tracepoint patch.
Stupid mistake of mine...
This is the working patch for lttng_ust_tracepoint in workqueue, it is on top
of previous 2 debug patches:
>From 4e25d41b146fa374621582f04f2f9f59163c64a2 Mon Sep 17 00:00:00 2001
From: mlwang <mlwang at szsandstone.com>
Date: Wed, 22 Jun 2022 15:27:41 +0800
Subject: [PATCH] add tracepoint in workqueue.c
---
src/Makefile.am | 4 +-
src/liburcu-cds.pc.in | 2 +-
src/workqueue.c | 29 ++++--------
src/workqueue.h | 1 +
src/workqueue_tp.c | 4 ++
src/workqueue_tp.h | 125 ++++++++++++++++++++++++++++++++++++++++++++++++++
6 files changed, 141 insertions(+), 24 deletions(-)
create mode 100644 src/workqueue_tp.c
create mode 100644 src/workqueue_tp.h
diff --git a/src/Makefile.am b/src/Makefile.am
index 88ccc1f..5a18e31 100644
--- a/src/Makefile.am
+++ b/src/Makefile.am
@@ -2,7 +2,7 @@ AM_CPPFLAGS += -I$(top_srcdir)/include -I$(top_builddir)/include -I$(top_srcdir)
#Add the -version-info directly here since we are only building
# library that use the version-info
-AM_LDFLAGS=-version-info $(URCU_LIBRARY_VERSION)
+AM_LDFLAGS=-version-info $(URCU_LIBRARY_VERSION) -llttng-ust -ldl
if USE_CYGWIN
AM_LDFLAGS+=-no-undefined
endif
@@ -56,7 +56,7 @@ liburcu_bp_la_SOURCES = urcu-bp.c urcu-pointer.c $(COMPAT)
liburcu_bp_la_LIBADD = liburcu-common.la
liburcu_cds_la_SOURCES = rculfqueue.c rculfstack.c lfstack.c \
- workqueue.c workqueue.h $(RCULFHASH) $(COMPAT)
+ workqueue.c workqueue.h workqueue_tp.c workqueue_tp.h $(RCULFHASH) $(COMPAT)
liburcu_cds_la_LIBADD = liburcu-common.la
pkgconfigdir = $(libdir)/pkgconfig
diff --git a/src/liburcu-cds.pc.in b/src/liburcu-cds.pc.in
index e3d13af..f4e5e3e 100644
--- a/src/liburcu-cds.pc.in
+++ b/src/liburcu-cds.pc.in
@@ -7,5 +7,5 @@ Name: Userspace RCU Concurrent Data Structures
Description: Data structures leveraging RCU and atomic operations to provide efficient concurrency-aware storage
Version: @PACKAGE_VERSION@
Requires:
-Libs: -L${libdir} -lurcu-cds
+Libs: -L${libdir} -lurcu-cds -llttng-ust -ldl
Cflags: -I${includedir}
diff --git a/src/workqueue.c b/src/workqueue.c
index 19fc89c..88a0f8f 100644
--- a/src/workqueue.c
+++ b/src/workqueue.c
@@ -137,16 +137,13 @@ static void futex_wait(int32_t *futex)
/* Read condition before read futex */
cmm_smp_mb();
if (uatomic_read(futex) != -1) {
- fprintf(stderr, "%lu: wq %p: %s futex != -1, don't wait\n",
- pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__);
-
+ lttng_ust_tracepoint(workqueue, futex_no_wait, (long)futex, *futex);
return;
}
wait:
while ((ret = futex_async(futex, FUTEX_WAIT, -1, NULL, NULL, 0))) {
err = errno;
- fprintf(stderr, "%lu: wq %p: %s failed, errno %d\n",
- pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__, err);
+ lttng_ust_tracepoint(workqueue, futex_wait_err, (long)futex, *futex, err);
switch (err) {
case EWOULDBLOCK:
/* Value already changed. */
@@ -160,16 +157,14 @@ wait:
}
}
- fprintf(stderr, "%lu: wq %p: %s wait return %d\n",
- pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__, ret);
+ lttng_ust_tracepoint(workqueue, futex_wait_return, (long)futex, *futex, ret);
/*
* Prior queued wakeups can cause futex wait to return even
* though the futex value is still -1. If this happens, wait
* again.
*/
if (uatomic_read(futex) == -1) {
- fprintf(stderr, "%lu: wq %p: %s futex == -1, wait again\n",
- pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__);
+ lttng_ust_tracepoint(workqueue, futex_wait_again, (long)futex, *futex);
goto wait;
}
}
@@ -184,15 +179,9 @@ static void futex_wake_up(int32_t *futex)
if (caa_unlikely(old == -1)) {
old = uatomic_xchg(futex, 0);
if (old == -1) {
- fprintf(stderr, "%lu: wq %p, wakeup succeed: old %d\n",
- pthread_self(),
- caa_container_of(futex, struct urcu_workqueue, futex),
- old);
+ lttng_ust_tracepoint(workqueue, futex_wake_up_success, (long)futex, old);
} else {
- fprintf(stderr, "%lu: wq %p, wakeup failed: old %d\n",
- pthread_self(),
- caa_container_of(futex, struct urcu_workqueue, futex),
- old);
+ lttng_ust_tracepoint(workqueue, futex_wake_up_fail, (long)futex, old);
}
if (futex_async(futex, FUTEX_WAKE, 1,
NULL, NULL, 0) < 0)
@@ -278,11 +267,9 @@ static void *workqueue_thread(void *arg)
futex_wait(&workqueue->futex);
new = uatomic_add_return(&workqueue->futex, -1);
if (new == -1) {
- fprintf(stderr, "%lu: wq %p dec succeed: old %d, new %d\n",
- pthread_self(), workqueue, new + 1, new);
+ lttng_ust_tracepoint(workqueue, futex_dec_success, (long)&workqueue->futex, new+1, new);
} else {
- fprintf(stderr, "%lu: wq %p dec failed: old %d\n",
- pthread_self(), workqueue, new + 1);
+ lttng_ust_tracepoint(workqueue, futex_dec_fail, (long)&workqueue->futex, new+1, new);
}
/*
* Decrement futex before reading
diff --git a/src/workqueue.h b/src/workqueue.h
index 52b6973..63931a4 100644
--- a/src/workqueue.h
+++ b/src/workqueue.h
@@ -28,6 +28,7 @@
#include <pthread.h>
#include <urcu/wfcqueue.h>
+#include "workqueue_tp.h"
#ifdef __cplusplus
extern "C" {
diff --git a/src/workqueue_tp.c b/src/workqueue_tp.c
new file mode 100644
index 0000000..a5f9586
--- /dev/null
+++ b/src/workqueue_tp.c
@@ -0,0 +1,4 @@
+#define LTTNG_UST_TRACEPOINT_CREATE_PROBES
+#define LTTNG_UST_TRACEPOINT_DEFINE
+
+#include "workqueue_tp.h"
diff --git a/src/workqueue_tp.h b/src/workqueue_tp.h
new file mode 100644
index 0000000..b782f61
--- /dev/null
+++ b/src/workqueue_tp.h
@@ -0,0 +1,125 @@
+#undef LTTNG_UST_TRACEPOINT_PROVIDER
+#define LTTNG_UST_TRACEPOINT_PROVIDER workqueue
+
+#undef LTTNG_UST_TRACEPOINT_INCLUDE
+#define LTTNG_UST_TRACEPOINT_INCLUDE "./workqueue_tp.h"
+
+#if !defined(_WORKQUEUE_TP_H) || defined(LTTNG_UST_TRACEPOINT_HEADER_MULTI_READ)
+#define _WORKQUEUE_TP_H
+
+#include <lttng/tracepoint.h>
+
+LTTNG_UST_TRACEPOINT_EVENT(
+ workqueue,
+ futex_no_wait,
+ LTTNG_UST_TP_ARGS(
+ long, futex_p_arg,
+ int, futex_arg
+ ),
+ LTTNG_UST_TP_FIELDS(
+ lttng_ust_field_integer_hex(long, futex, futex_p_arg)
+ lttng_ust_field_integer(int, val, futex_arg)
+ )
+)
+
+LTTNG_UST_TRACEPOINT_EVENT(
+ workqueue,
+ futex_wait_err,
+ LTTNG_UST_TP_ARGS(
+ long, futex_p_arg,
+ int, futex_arg,
+ int, err_arg
+ ),
+ LTTNG_UST_TP_FIELDS(
+ lttng_ust_field_integer_hex(long, futex, futex_p_arg)
+ lttng_ust_field_integer(int, val, futex_arg)
+ lttng_ust_field_integer(int, err, err_arg)
+ )
+)
+
+LTTNG_UST_TRACEPOINT_EVENT(
+ workqueue,
+ futex_wait_return,
+ LTTNG_UST_TP_ARGS(
+ long, futex_p_arg,
+ int, futex_arg,
+ int, ret_arg
+ ),
+ LTTNG_UST_TP_FIELDS(
+ lttng_ust_field_integer_hex(long, futex, futex_p_arg)
+ lttng_ust_field_integer(int, val, futex_arg)
+ lttng_ust_field_integer(int, ret, ret_arg)
+ )
+)
+
+LTTNG_UST_TRACEPOINT_EVENT(
+ workqueue,
+ futex_wait_again,
+ LTTNG_UST_TP_ARGS(
+ long, futex_p_arg,
+ int, futex_arg
+ ),
+ LTTNG_UST_TP_FIELDS(
+ lttng_ust_field_integer_hex(long, futex, futex_p_arg)
+ lttng_ust_field_integer(int, val, futex_arg)
+ )
+)
+
+LTTNG_UST_TRACEPOINT_EVENT(
+ workqueue,
+ futex_wake_up_success,
+ LTTNG_UST_TP_ARGS(
+ long, futex_p_arg,
+ int, futex_arg
+ ),
+ LTTNG_UST_TP_FIELDS(
+ lttng_ust_field_integer_hex(long, futex, futex_p_arg)
+ lttng_ust_field_integer(int, val, futex_arg)
+ )
+)
+
+LTTNG_UST_TRACEPOINT_EVENT(
+ workqueue,
+ futex_wake_up_fail,
+ LTTNG_UST_TP_ARGS(
+ long, futex_p_arg,
+ int, futex_arg
+ ),
+ LTTNG_UST_TP_FIELDS(
+ lttng_ust_field_integer_hex(long, futex, futex_p_arg)
+ lttng_ust_field_integer(int, val, futex_arg)
+ )
+)
+
+LTTNG_UST_TRACEPOINT_EVENT(
+ workqueue,
+ futex_dec_success,
+ LTTNG_UST_TP_ARGS(
+ long, futex_p_arg,
+ int, old_arg,
+ int, new_arg
+ ),
+ LTTNG_UST_TP_FIELDS(
+ lttng_ust_field_integer_hex(long, futex, futex_p_arg)
+ lttng_ust_field_integer(int, old, old_arg)
+ lttng_ust_field_integer(int, new, new_arg)
+ )
+)
+
+LTTNG_UST_TRACEPOINT_EVENT(
+ workqueue,
+ futex_dec_fail,
+ LTTNG_UST_TP_ARGS(
+ long, futex_p_arg,
+ int, old_arg,
+ int, new_arg
+ ),
+ LTTNG_UST_TP_FIELDS(
+ lttng_ust_field_integer_hex(long, futex, futex_p_arg)
+ lttng_ust_field_integer(int, old, old_arg)
+ lttng_ust_field_integer(int, new, new_arg)
+ )
+)
+
+#endif /* _WORKQUEUE_TP_H */
+#include <lttng/tracepoint-event.h>
--
1.8.3.1
And the lttng session is configured to trace these events:
kernel: syscall futex
user: workqueue:'*'
The lttng session is configured in this way:
---
Recording session auto-20220622-150808: [inactive]
Trace output: /root/lttng-traces/auto-20220622-150808
=== Domain: Linux kernel ===
Tracked process attributes
Process IDs: all
Virtual process IDs: 156622
User IDs: all
Virtual user IDs: all
Group IDs: all
Virtual group IDs: all
Channels:
-------------
- channel0: [disabled]
Attributes:
Event-loss mode: discard
Sub-buffer size: 1048576 bytes
Sub-buffer count: 4
Switch timer: inactive
Read timer: 200000 us
Monitor timer: 1000000 us
Blocking timeout: 0 us
Trace file count: 1 per stream
Trace file size: unlimited
Output mode: splice
Statistics:
Discarded events: 0
Recording event rules:
futex (type:syscall) [enabled]
=== Domain: User space ===
Buffering scheme: per-user
Tracked process attributes
Virtual process IDs: 156622
Virtual user IDs: all
Virtual group IDs: all
Channels:
-------------
- channel0: [enabled]
Attributes:
Event-loss mode: discard
Sub-buffer size: 524288 bytes
Sub-buffer count: 4
Switch timer: inactive
Read timer: inactive
Monitor timer: 1000000 us
Blocking timeout: 0 us
Trace file count: 1 per stream
Trace file size: unlimited
Output mode: mmap
Statistics:
Discarded events: 0
Recording event rules:
workqueue:* (type: tracepoint) [enabled]
---
The babletrace output of this session is pretty big, 6 MB in size, i put it in
the attachment trace_0622.tar.bz2.
Let my know if your mailbox can't handle such big attachment.
Thanks,
Minlan
-------------- next part --------------
A non-text attachment was scrubbed...
Name: trace_0622.tar.bz2
Type: application/x-bzip2
Size: 6277601 bytes
Desc: not available
URL: <https://lists.lttng.org/pipermail/lttng-dev/attachments/20220622/36891ce6/attachment-0001.bin>
More information about the lttng-dev
mailing list