[lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

Hi, Mathieu,
	We are running a CentOS 8.2 os on Intel(R) Xeon(R) CPU E5-2630 v4,
and using the workqueue interfaces in src/workqueue.h in
userspace-rcu-latest-0.12.tar.bz2. 
	Recently, we found the workqueue thread rushes cpu into 99% usage.
After some debuging, we found that the futex in struct urcu_workqueue got
into very big negative value, e.g, -12484; while the qlen, cbs_tail, and
cbs_head suggest that the workqueue is empty.
We add a watchpoint of workqueue->futex in workqueue_thread(), and got this
log when workqueue->futex first get into -2:
...
Old value = -1
New value = 0
0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at workqueue.c:160
160     in workqueue.c
#0  0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at
workqueue.c:160
#1  0x00007ffff37c2737 in wake_worker_thread (workqueue=0x55555f74aa00) at
workqueue.c:324
#2  0x00007ffff37c29fb in urcu_workqueue_queue_work (workqueue=0x55555f74aa00,
work=0x555566e05e00, func=0x7ffff7523c90 <write_dirty_finish>) at
workqueue.c:3
67
#3  0x00007ffff752c520 in aio_complete_cb (ctx=<optimized out>,
iocb=<optimized out>, res=<optimized out>, res2=<optimized out>) at
bio/aio_bio_adapter.c:152
#4  0x00007ffff752c696 in poll_io_complete (arg=0x555562e4f4a0) at
bio/aio_bio_adapter.c:289
#5  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
#6  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
[Switching to Thread 0x7fffde3f3700 (LWP 821768)]
Hardware watchpoint 4: -location workqueue->futex

Old value = 0
New value = -1
0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
../include/urcu/uatomic.h:490
490     ../include/urcu/uatomic.h: No such file or directory.
#0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
../include/urcu/uatomic.h:490
#1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
#2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
#3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
Hardware watchpoint 4: -location workqueue->futex

Old value = -1
New value = -2
0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
../include/urcu/uatomic.h:490
490     in ../include/urcu/uatomic.h
#0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
../include/urcu/uatomic.h:490
#1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
#2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
#3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
Hardware watchpoint 4: -location workqueue->futex

Old value = -2
New value = -3
0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
../include/urcu/uatomic.h:490
490     in ../include/urcu/uatomic.h
#0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
../include/urcu/uatomic.h:490
#1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
#2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
#3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
Hardware watchpoint 4: -location workqueue->futex
...

After this, things went into wild, workqueue->futex got into bigger negative
value, and workqueue thread eat up the cpu it is using.
This ends only when workqueue->futex down flew into 0.

Do you have any idea why this is happening, and how to fix it?

B.R
Minlan Wang



_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 13, 2022, at 11:55 PM, Minlan Wang wangminlan@szsandstone.com wrote:

> Hi, Mathieu,

Hi Minlan,

Thanks for the detailed bug report. Can I ask more precisely which commit ID
of the userspace-rcu stable-2.12 branch you are using ? Typically a "userspace-rcu-latest-0.12.tar.bz2"
gets generated from a git tree at a given point in time, but it does not give
me enough details to know which commit it refers to.

Thanks,

Mathieu

>	We are running a CentOS 8.2 os on Intel(R) Xeon(R) CPU E5-2630 v4,
> and using the workqueue interfaces in src/workqueue.h in
> userspace-rcu-latest-0.12.tar.bz2.
>	Recently, we found the workqueue thread rushes cpu into 99% usage.
> After some debuging, we found that the futex in struct urcu_workqueue got
> into very big negative value, e.g, -12484; while the qlen, cbs_tail, and
> cbs_head suggest that the workqueue is empty.
> We add a watchpoint of workqueue->futex in workqueue_thread(), and got this
> log when workqueue->futex first get into -2:
> ...
> Old value = -1
> New value = 0
> 0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at workqueue.c:160
> 160     in workqueue.c
> #0  0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at
> workqueue.c:160
> #1  0x00007ffff37c2737 in wake_worker_thread (workqueue=0x55555f74aa00) at
> workqueue.c:324
> #2  0x00007ffff37c29fb in urcu_workqueue_queue_work (workqueue=0x55555f74aa00,
> work=0x555566e05e00, func=0x7ffff7523c90 <write_dirty_finish>) at
> workqueue.c:3
> 67
> #3  0x00007ffff752c520 in aio_complete_cb (ctx=<optimized out>,
> iocb=<optimized out>, res=<optimized out>, res2=<optimized out>) at
> bio/aio_bio_adapter.c:152
> #4  0x00007ffff752c696 in poll_io_complete (arg=0x555562e4f4a0) at
> bio/aio_bio_adapter.c:289
> #5  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #6  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> [Switching to Thread 0x7fffde3f3700 (LWP 821768)]
> Hardware watchpoint 4: -location workqueue->futex
> 
> Old value = 0
> New value = -1
> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> 490     ../include/urcu/uatomic.h: No such file or directory.
> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> Hardware watchpoint 4: -location workqueue->futex
> 
> Old value = -1
> New value = -2
> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> 490     in ../include/urcu/uatomic.h
> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> Hardware watchpoint 4: -location workqueue->futex
> 
> Old value = -2
> New value = -3
> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> 490     in ../include/urcu/uatomic.h
> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> Hardware watchpoint 4: -location workqueue->futex
> ...
> 
> After this, things went into wild, workqueue->futex got into bigger negative
> value, and workqueue thread eat up the cpu it is using.
> This ends only when workqueue->futex down flew into 0.
> 
> Do you have any idea why this is happening, and how to fix it?
> 
> B.R
> Minlan Wang

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 14, 2022, at 9:39 AM, Mathieu Desnoyers mathieu.desnoyers@efficios.com wrote:

> ----- On Jun 13, 2022, at 11:55 PM, Minlan Wang wangminlan@szsandstone.com
> wrote:
> 
>> Hi, Mathieu,
> 
> Hi Minlan,
> 
> Thanks for the detailed bug report. Can I ask more precisely which commit ID
> of the userspace-rcu stable-2.12 branch you are using ? Typically a

I meant "stable-0.12" branch here.

Thanks,

Mathieu

> "userspace-rcu-latest-0.12.tar.bz2"
> gets generated from a git tree at a given point in time, but it does not give
> me enough details to know which commit it refers to.
> 
> Thanks,
> 
> Mathieu
> 
>>	We are running a CentOS 8.2 os on Intel(R) Xeon(R) CPU E5-2630 v4,
>> and using the workqueue interfaces in src/workqueue.h in
>> userspace-rcu-latest-0.12.tar.bz2.
>>	Recently, we found the workqueue thread rushes cpu into 99% usage.
>> After some debuging, we found that the futex in struct urcu_workqueue got
>> into very big negative value, e.g, -12484; while the qlen, cbs_tail, and
>> cbs_head suggest that the workqueue is empty.
>> We add a watchpoint of workqueue->futex in workqueue_thread(), and got this
>> log when workqueue->futex first get into -2:
>> ...
>> Old value = -1
>> New value = 0
>> 0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at workqueue.c:160
>> 160     in workqueue.c
>> #0  0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at
>> workqueue.c:160
>> #1  0x00007ffff37c2737 in wake_worker_thread (workqueue=0x55555f74aa00) at
>> workqueue.c:324
>> #2  0x00007ffff37c29fb in urcu_workqueue_queue_work (workqueue=0x55555f74aa00,
>> work=0x555566e05e00, func=0x7ffff7523c90 <write_dirty_finish>) at
>> workqueue.c:3
>> 67
>> #3  0x00007ffff752c520 in aio_complete_cb (ctx=<optimized out>,
>> iocb=<optimized out>, res=<optimized out>, res2=<optimized out>) at
>> bio/aio_bio_adapter.c:152
>> #4  0x00007ffff752c696 in poll_io_complete (arg=0x555562e4f4a0) at
>> bio/aio_bio_adapter.c:289
>> #5  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
>> #6  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
>> [Switching to Thread 0x7fffde3f3700 (LWP 821768)]
>> Hardware watchpoint 4: -location workqueue->futex
>> 
>> Old value = 0
>> New value = -1
>> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
>> ../include/urcu/uatomic.h:490
>> 490     ../include/urcu/uatomic.h: No such file or directory.
>> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
>> ../include/urcu/uatomic.h:490
>> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
>> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
>> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
>> Hardware watchpoint 4: -location workqueue->futex
>> 
>> Old value = -1
>> New value = -2
>> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
>> ../include/urcu/uatomic.h:490
>> 490     in ../include/urcu/uatomic.h
>> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
>> ../include/urcu/uatomic.h:490
>> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
>> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
>> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
>> Hardware watchpoint 4: -location workqueue->futex
>> 
>> Old value = -2
>> New value = -3
>> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
>> ../include/urcu/uatomic.h:490
>> 490     in ../include/urcu/uatomic.h
>> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
>> ../include/urcu/uatomic.h:490
>> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
>> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
>> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
>> Hardware watchpoint 4: -location workqueue->futex
>> ...
>> 
>> After this, things went into wild, workqueue->futex got into bigger negative
>> value, and workqueue thread eat up the cpu it is using.
>> This ends only when workqueue->futex down flew into 0.
>> 
>> Do you have any idea why this is happening, and how to fix it?
>> 
>> B.R
>> Minlan Wang
> 
> --
> Mathieu Desnoyers
> EfficiOS Inc.
> http://www.efficios.com

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 13, 2022, at 11:55 PM, Minlan Wang wangminlan@szsandstone.com wrote:

> Hi, Mathieu,
>	We are running a CentOS 8.2 os on Intel(R) Xeon(R) CPU E5-2630 v4,

Also, can you provide more information about which exact Linux kernel version
you are using ?

Thanks,

Mathieu

> and using the workqueue interfaces in src/workqueue.h in
> userspace-rcu-latest-0.12.tar.bz2.
>	Recently, we found the workqueue thread rushes cpu into 99% usage.
> After some debuging, we found that the futex in struct urcu_workqueue got
> into very big negative value, e.g, -12484; while the qlen, cbs_tail, and
> cbs_head suggest that the workqueue is empty.
> We add a watchpoint of workqueue->futex in workqueue_thread(), and got this
> log when workqueue->futex first get into -2:
> ...
> Old value = -1
> New value = 0
> 0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at workqueue.c:160
> 160     in workqueue.c
> #0  0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at
> workqueue.c:160
> #1  0x00007ffff37c2737 in wake_worker_thread (workqueue=0x55555f74aa00) at
> workqueue.c:324
> #2  0x00007ffff37c29fb in urcu_workqueue_queue_work (workqueue=0x55555f74aa00,
> work=0x555566e05e00, func=0x7ffff7523c90 <write_dirty_finish>) at
> workqueue.c:3
> 67
> #3  0x00007ffff752c520 in aio_complete_cb (ctx=<optimized out>,
> iocb=<optimized out>, res=<optimized out>, res2=<optimized out>) at
> bio/aio_bio_adapter.c:152
> #4  0x00007ffff752c696 in poll_io_complete (arg=0x555562e4f4a0) at
> bio/aio_bio_adapter.c:289
> #5  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #6  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> [Switching to Thread 0x7fffde3f3700 (LWP 821768)]
> Hardware watchpoint 4: -location workqueue->futex
> 
> Old value = 0
> New value = -1
> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> 490     ../include/urcu/uatomic.h: No such file or directory.
> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> Hardware watchpoint 4: -location workqueue->futex
> 
> Old value = -1
> New value = -2
> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> 490     in ../include/urcu/uatomic.h
> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> Hardware watchpoint 4: -location workqueue->futex
> 
> Old value = -2
> New value = -3
> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> 490     in ../include/urcu/uatomic.h
> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> Hardware watchpoint 4: -location workqueue->futex
> ...
> 
> After this, things went into wild, workqueue->futex got into bigger negative
> value, and workqueue thread eat up the cpu it is using.
> This ends only when workqueue->futex down flew into 0.
> 
> Do you have any idea why this is happening, and how to fix it?
> 
> B.R
> Minlan Wang

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 13, 2022, at 11:55 PM, Minlan Wang wangminlan@szsandstone.com wrote:

> Hi, Mathieu,
>	We are running a CentOS 8.2 os on Intel(R) Xeon(R) CPU E5-2630 v4,
> and using the workqueue interfaces in src/workqueue.h in
> userspace-rcu-latest-0.12.tar.bz2.

Also, I notice that you appear to be using an internal liburcu API (not public)
from outside of the liburcu project, which is not really expected.

If your process forks without exec, make sure you wire up the equivalent of
rculfhash pthread_atfork functions which call urcu_workqueue_pause_worker(),
urcu_workqueue_resume_worker() and urcu_workqueue_create_worker().

Also, can you validate of you have many workqueue worker threads trying to
dequeue from the same workqueue in parallel ? This is unsupported and would
cause the kind of issues you are observing here.

Thanks,

Mathieu

>	Recently, we found the workqueue thread rushes cpu into 99% usage.
> After some debuging, we found that the futex in struct urcu_workqueue got
> into very big negative value, e.g, -12484; while the qlen, cbs_tail, and
> cbs_head suggest that the workqueue is empty.
> We add a watchpoint of workqueue->futex in workqueue_thread(), and got this
> log when workqueue->futex first get into -2:
> ...
> Old value = -1
> New value = 0
> 0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at workqueue.c:160
> 160     in workqueue.c
> #0  0x00007ffff37c1d6d in futex_wake_up (futex=0x55555f74aa40) at
> workqueue.c:160
> #1  0x00007ffff37c2737 in wake_worker_thread (workqueue=0x55555f74aa00) at
> workqueue.c:324
> #2  0x00007ffff37c29fb in urcu_workqueue_queue_work (workqueue=0x55555f74aa00,
> work=0x555566e05e00, func=0x7ffff7523c90 <write_dirty_finish>) at
> workqueue.c:3
> 67
> #3  0x00007ffff752c520 in aio_complete_cb (ctx=<optimized out>,
> iocb=<optimized out>, res=<optimized out>, res2=<optimized out>) at
> bio/aio_bio_adapter.c:152
> #4  0x00007ffff752c696 in poll_io_complete (arg=0x555562e4f4a0) at
> bio/aio_bio_adapter.c:289
> #5  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #6  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> [Switching to Thread 0x7fffde3f3700 (LWP 821768)]
> Hardware watchpoint 4: -location workqueue->futex
> 
> Old value = 0
> New value = -1
> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> 490     ../include/urcu/uatomic.h: No such file or directory.
> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> Hardware watchpoint 4: -location workqueue->futex
> 
> Old value = -1
> New value = -2
> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> 490     in ../include/urcu/uatomic.h
> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> Hardware watchpoint 4: -location workqueue->futex
> 
> Old value = -2
> New value = -3
> 0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> 490     in ../include/urcu/uatomic.h
> #0  0x00007ffff37c2473 in __uatomic_dec (len=4, addr=0x55555f74aa40) at
> ../include/urcu/uatomic.h:490
> #1  workqueue_thread (arg=0x55555f74aa00) at workqueue.c:250
> #2  0x00007ffff72e6ea5 in start_thread () from /usr/lib64/libpthread.so.0
> #3  0x00007ffff415d96d in clone () from /usr/lib64/libc.so.6
> Hardware watchpoint 4: -location workqueue->futex
> ...
> 
> After this, things went into wild, workqueue->futex got into bigger negative
> value, and workqueue thread eat up the cpu it is using.
> This ends only when workqueue->futex down flew into 0.
> 
> Do you have any idea why this is happening, and how to fix it?
> 
> B.R
> Minlan Wang

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

Hi, Mathieu,
The commit on branch stable-0.12 correponds to the tarball we downloaded is this:

commit d5277e807192178ddb79f56ecbbd5ac3c4994f60 (HEAD -> v0.12.1.b, tag: v0.12.1)
Author: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Date:   Wed Apr 22 08:51:41 2020 -0400

    Version 0.12.1

    Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>

The OS we are using is CentOS Linux release 7.9.2009 (Core), not CentOS 8.2
as mentioned before. And the kernel version is: 3.10.0-1160.el7.x86_64.

On Tue, Jun 14, 2022 at 11:53:16AM -0400, Mathieu Desnoyers wrote:
> Also, I notice that you appear to be using an internal liburcu API (not public)
> from outside of the liburcu project, which is not really expected.
We are trying to move some linux kernel module function into userspace, and
found that the urcu internal workqueue.h has all the things we need for a
replace for kernel workqueue, so we decided to give it a try.

> 
> If your process forks without exec, make sure you wire up the equivalent of
> rculfhash pthread_atfork functions which call urcu_workqueue_pause_worker(),
> urcu_workqueue_resume_worker() and urcu_workqueue_create_worker().
There's no fork/exec in the process who is calling alloc_workqueue, and the
threads who are enqueue work into the workqueue is created by calling
pthread_create.

> 
> Also, can you validate of you have many workqueue worker threads trying to
> dequeue from the same workqueue in parallel ? This is unsupported and would
> cause the kind of issues you are observing here.
The workqueue thread is created by calling urcu_workqueue_create in the code
below, and it is the only thread which will dequeue work from the workqueue.
Though, there are multiple threads who will enqueue work by calling
urcu_workqueue_queue_work(wq, work, work->func).
---
static void workqueue_init_fn(struct urcu_workqueue *workqueue, void *priv)
{
	pthread_t tid;
	const char *name;
	char thread_name[16] = {0};

	if (!priv)
		return;

	name = (const char *)priv;
	tid = pthread_self();
	
	memcpy(thread_name, name, 15);
	if (pthread_setname_np(tid, thread_name)) {
		pr_err("failed to set thread name for workqueue %s\n", name);
	}

	urcu_memb_register_thread();
}

static void workqueue_finalize_fn(struct urcu_workqueue *workqueue, void
				  *priv)
{
	urcu_memb_unregister_thread();
	if (priv)
		free(priv);
}

struct workqueue_struct *alloc_workqueue(const char *fmt,
					 unsigned int flags,
					 int max_active, ...)
{
	const char *name;

	name = strdup(fmt);
	if (!name) {
		pr_err("failed to dup name for workqueue %s\n", fmt);
		return NULL;
	}

	return urcu_workqueue_create(0, -1, (void *)name,
			      NULL,			/* grace */
			      workqueue_init_fn,	/* init */
			      workqueue_finalize_fn,	/* finalize */
			      NULL,			/* before wait */
			      NULL,			/* after wake up */
			      NULL,			/* before pasue */
			      NULL);			/* after resume */
}
---

B.R
Minlan


_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 14, 2022, at 11:49 PM, Minlan Wang wangminlan@szsandstone.com wrote:

> Hi, Mathieu,
> The commit on branch stable-0.12 correponds to the tarball we downloaded is
> this:
> 
> commit d5277e807192178ddb79f56ecbbd5ac3c4994f60 (HEAD -> v0.12.1.b, tag:
> v0.12.1)
> Author: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> Date:   Wed Apr 22 08:51:41 2020 -0400
> 
>    Version 0.12.1
> 
>    Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> 
> The OS we are using is CentOS Linux release 7.9.2009 (Core), not CentOS 8.2
> as mentioned before. And the kernel version is: 3.10.0-1160.el7.x86_64.

Can you reproduce with an up-to-date kernel ? AFAIU, kernel version
3.10.0-1160.el7.x86_64 was built on Mon Oct 19 18:34:26 2020 [1], whereas
3.10.0-1160.66.1.el7 was built on Wed May 18 18:19:46 2022 [2].

[1] https://rpmfind.net/linux/RPM/centos/7.9.2009/x86_64/Packages/kernel-3.10.0-1160.el7.x86_64.html
[2] https://rpmfind.net/linux/RPM/centos/updates/7.9.2009/x86_64/Packages/kernel-3.10.0-1160.66.1.el7.x86_64.html

I just want to make sure we are not hitting a bug in the futex system call.

Can you also try to reproduce with an up-to-date Linux kernel ? (5.18.4)

Can you provide a reproducer I could try on my own system ?

Thanks,

Mathieu

> 
> On Tue, Jun 14, 2022 at 11:53:16AM -0400, Mathieu Desnoyers wrote:
>> Also, I notice that you appear to be using an internal liburcu API (not public)
>> from outside of the liburcu project, which is not really expected.
> We are trying to move some linux kernel module function into userspace, and
> found that the urcu internal workqueue.h has all the things we need for a
> replace for kernel workqueue, so we decided to give it a try.
> 
>> 
>> If your process forks without exec, make sure you wire up the equivalent of
>> rculfhash pthread_atfork functions which call urcu_workqueue_pause_worker(),
>> urcu_workqueue_resume_worker() and urcu_workqueue_create_worker().
> There's no fork/exec in the process who is calling alloc_workqueue, and the
> threads who are enqueue work into the workqueue is created by calling
> pthread_create.
> 
>> 
>> Also, can you validate of you have many workqueue worker threads trying to
>> dequeue from the same workqueue in parallel ? This is unsupported and would
>> cause the kind of issues you are observing here.
> The workqueue thread is created by calling urcu_workqueue_create in the code
> below, and it is the only thread which will dequeue work from the workqueue.
> Though, there are multiple threads who will enqueue work by calling
> urcu_workqueue_queue_work(wq, work, work->func).
> ---
> static void workqueue_init_fn(struct urcu_workqueue *workqueue, void *priv)
> {
>	pthread_t tid;
>	const char *name;
>	char thread_name[16] = {0};
> 
>	if (!priv)
>		return;
> 
>	name = (const char *)priv;
>	tid = pthread_self();
>	
>	memcpy(thread_name, name, 15);
>	if (pthread_setname_np(tid, thread_name)) {
>		pr_err("failed to set thread name for workqueue %s\n", name);
>	}
> 
>	urcu_memb_register_thread();
> }
> 
> static void workqueue_finalize_fn(struct urcu_workqueue *workqueue, void
>				  *priv)
> {
>	urcu_memb_unregister_thread();
>	if (priv)
>		free(priv);
> }
> 
> struct workqueue_struct *alloc_workqueue(const char *fmt,
>					 unsigned int flags,
>					 int max_active, ...)
> {
>	const char *name;
> 
>	name = strdup(fmt);
>	if (!name) {
>		pr_err("failed to dup name for workqueue %s\n", fmt);
>		return NULL;
>	}
> 
>	return urcu_workqueue_create(0, -1, (void *)name,
>			      NULL,			/* grace */
>			      workqueue_init_fn,	/* init */
>			      workqueue_finalize_fn,	/* finalize */
>			      NULL,			/* before wait */
>			      NULL,			/* after wake up */
>			      NULL,			/* before pasue */
>			      NULL);			/* after resume */
> }
> ---
> 
> B.R
> Minlan

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 14, 2022, at 11:49 PM, Minlan Wang wangminlan@szsandstone.com wrote:

> Hi, Mathieu,
> The commit on branch stable-0.12 correponds to the tarball we downloaded is
> this:
> 
> commit d5277e807192178ddb79f56ecbbd5ac3c4994f60 (HEAD -> v0.12.1.b, tag:
> v0.12.1)
> Author: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> Date:   Wed Apr 22 08:51:41 2020 -0400
> 
>    Version 0.12.1
> 
>    Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> 
> The OS we are using is CentOS Linux release 7.9.2009 (Core), not CentOS 8.2
> as mentioned before. And the kernel version is: 3.10.0-1160.el7.x86_64.

One more thing: did you apply any changes on top of the v0.12.1 userspace rcu tag ?

Also, can you provide the output of "./configure" on your system ? I'm also interested
in knowing the contents of include/urcu/config.h after building liburcu.

Thanks,

Mathieu


> 
> On Tue, Jun 14, 2022 at 11:53:16AM -0400, Mathieu Desnoyers wrote:
>> Also, I notice that you appear to be using an internal liburcu API (not public)
>> from outside of the liburcu project, which is not really expected.
> We are trying to move some linux kernel module function into userspace, and
> found that the urcu internal workqueue.h has all the things we need for a
> replace for kernel workqueue, so we decided to give it a try.
> 
>> 
>> If your process forks without exec, make sure you wire up the equivalent of
>> rculfhash pthread_atfork functions which call urcu_workqueue_pause_worker(),
>> urcu_workqueue_resume_worker() and urcu_workqueue_create_worker().
> There's no fork/exec in the process who is calling alloc_workqueue, and the
> threads who are enqueue work into the workqueue is created by calling
> pthread_create.
> 
>> 
>> Also, can you validate of you have many workqueue worker threads trying to
>> dequeue from the same workqueue in parallel ? This is unsupported and would
>> cause the kind of issues you are observing here.
> The workqueue thread is created by calling urcu_workqueue_create in the code
> below, and it is the only thread which will dequeue work from the workqueue.
> Though, there are multiple threads who will enqueue work by calling
> urcu_workqueue_queue_work(wq, work, work->func).
> ---
> static void workqueue_init_fn(struct urcu_workqueue *workqueue, void *priv)
> {
>	pthread_t tid;
>	const char *name;
>	char thread_name[16] = {0};
> 
>	if (!priv)
>		return;
> 
>	name = (const char *)priv;
>	tid = pthread_self();
>	
>	memcpy(thread_name, name, 15);
>	if (pthread_setname_np(tid, thread_name)) {
>		pr_err("failed to set thread name for workqueue %s\n", name);
>	}
> 
>	urcu_memb_register_thread();
> }
> 
> static void workqueue_finalize_fn(struct urcu_workqueue *workqueue, void
>				  *priv)
> {
>	urcu_memb_unregister_thread();
>	if (priv)
>		free(priv);
> }
> 
> struct workqueue_struct *alloc_workqueue(const char *fmt,
>					 unsigned int flags,
>					 int max_active, ...)
> {
>	const char *name;
> 
>	name = strdup(fmt);
>	if (!name) {
>		pr_err("failed to dup name for workqueue %s\n", fmt);
>		return NULL;
>	}
> 
>	return urcu_workqueue_create(0, -1, (void *)name,
>			      NULL,			/* grace */
>			      workqueue_init_fn,	/* init */
>			      workqueue_finalize_fn,	/* finalize */
>			      NULL,			/* before wait */
>			      NULL,			/* after wake up */
>			      NULL,			/* before pasue */
>			      NULL);			/* after resume */
> }
> ---
> 
> B.R
> Minlan

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

[-- Attachment #1: Type: text/plain, Size: 1342 bytes --]

Hi, Mathieu,
We updated our kernel as your guide, now it's 3.10.0-1160.66.1.el7.x86_64, and
the issue still exists.

On Wed, Jun 15, 2022 at 10:15:58AM -0400, Mathieu Desnoyers wrote:
> ----- On Jun 14, 2022, at 11:49 PM, Minlan Wang wangminlan@szsandstone.com wrote:
> 
> One more thing: did you apply any changes on top of the v0.12.1 userspace rcu tag ?
We make no change into the userspace-rcu-latest-0.12.tar.bz2 tarball, we just
place the extracted directory into our code repository.

> 
> Also, can you provide the output of "./configure" on your system ? I'm also interested
> in knowing the contents of include/urcu/config.h after building liburcu.
This is the Makefile we use to build urcu:
---
CUR_DIR = $(shell pwd)
TOP_DIR = $(abspath $(CUR_DIR)/../)
URCU_DIR = $(abspath $(TOP_DIR)/thirdparty/usr)

urcu:
	cd $(TOP_DIR)/thirdparty &&	\
	cd userspace-rcu-0.12.1	&& \
	export CFLAGS="-fPIC -g -O0" && \
	./configure --prefix=$(URCU_DIR) && \
	make				&& \
	make install			&& \
	cp src/workqueue.h $(URCU_DIR)/include/urcu/

I put the these things into the attachment config.tar.gz:
1. configure: the configure script under userspace-rcu-0.12.1/
2. config.log: the configure log after urcu build
3. config.h: include/urcu/config.h after building
4. Makefile: the Makefile recipe we use to build urcu

Thanks for your help,
Minlan

[-- Attachment #2: config.tar.gz --]
[-- Type: application/gzip, Size: 136921 bytes --]

[-- Attachment #3: Type: text/plain, Size: 156 bytes --]

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

[-- Attachment #1: Type: text/plain, Size: 4422 bytes --]

Hi, Mathieu,
I tried to write a simple program to reproduce this issue, but failed.
The environment we used to produce this issue is a storage cluster.
It has 3 nodes, each with an NVME and several SATA disks, urcu is part of the
storage cluster software.
The storage software is pretty big, 3+ GB in size. I guess it's hard for you to
build a environment like ours.

Besides, I made some change into workqueue.c to debug this issue today, here's
the patch i used for debuging:

From 18f3fea1436e0c999b346b998b7153150b92e62f Mon Sep 17 00:00:00 2001
From: wangminlan <wangminlan@szsandstone.com>
Date: Wed, 15 Jun 2022 14:28:53 +0800
Subject: [PATCH] <urcu> debug workqueue->futex

---
 .../userspace-rcu-0.12.1/src/workqueue.c           | 49 ++++++++++++++++++----
 1 file changed, 42 insertions(+), 7 deletions(-)

diff --git a/ceph/thirdpart/ascache/thirdparty/userspace-rcu-0.12.1/src/workqueue.c b/ceph/thirdpart/ascache/thirdparty/userspace-rcu-0.12.1/src/workqueue.c
index 59eb21d..eed1e21 100644
--- a/ceph/thirdpart/ascache/thirdparty/userspace-rcu-0.12.1/src/workqueue.c
+++ b/ceph/thirdpart/ascache/thirdparty/userspace-rcu-0.12.1/src/workqueue.c
@@ -132,12 +132,21 @@ static int set_thread_cpu_affinity(struct urcu_workqueue *workqueue)
 
 static void futex_wait(int32_t *futex)
 {
+	int ret;
+	int err;
 	/* Read condition before read futex */
 	cmm_smp_mb();
-	if (uatomic_read(futex) != -1)
+	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__);
+
 		return;
-	while (futex_async(futex, FUTEX_WAIT, -1, NULL, NULL, 0)) {
-		switch (errno) {
+	}
+	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);
+		switch (err) {
 		case EWOULDBLOCK:
 			/* Value already changed. */
 			return;
@@ -146,17 +155,35 @@ static void futex_wait(int32_t *futex)
 			break;	/* Get out of switch. */
 		default:
 			/* Unexpected error. */
-			urcu_die(errno);
+			urcu_die(err);
 		}
 	}
+
+	fprintf(stderr, "%lu: wq %p: %s wait return %d\n",
+		pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__, ret);
+
 }
 
 static void futex_wake_up(int32_t *futex)
 {
 	/* Write to condition before reading/writing futex */
+	int32_t old;
+
 	cmm_smp_mb();
-	if (caa_unlikely(uatomic_read(futex) == -1)) {
-		uatomic_set(futex, 0);
+	old = uatomic_read(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);
+		} else {
+			fprintf(stderr, "%lu: wq %p, wakeup failed: old %d\n",
+				pthread_self(),
+				caa_container_of(futex, struct urcu_workqueue, futex),
+				old);
+		}
 		if (futex_async(futex, FUTEX_WAKE, 1,
 				NULL, NULL, 0) < 0)
 			urcu_die(errno);
@@ -237,8 +264,16 @@ static void *workqueue_thread(void *arg)
 		if (!rt) {
 			if (cds_wfcq_empty(&workqueue->cbs_head,
 					&workqueue->cbs_tail)) {
+				int32_t new;
 				futex_wait(&workqueue->futex);
-				uatomic_dec(&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);
+				} else {
+					fprintf(stderr, "%lu: wq %p dec failed: old %d\n",
+						pthread_self(), workqueue, new + 1);
+				}
 				/*
 				 * Decrement futex before reading
 				 * urcu_work list.
-- 
1.8.3.1

And the instresting log began from here:
---
...
   2097 140196498532096: wq 0x55f69a99ea00, wakeup succeed: old -1	/* enqueue op set futex: -1 -> 0 */
   2098 140196272453376: wq 0x55f69a99ea00: futex_wait wait return 0	/* workqueue_thread wait success */
   2099 140196272453376: wq 0x55f69a99ea00 dec failed: old -1		/* workqueue_thread got futex == -1 ? */
   2100 140196272453376: wq 0x55f69a99ea00: futex_wait futex != -1, don't wait
   2101 140196272453376: wq 0x55f69a99ea00 dec failed: old -2
...
---
In line 2099, how did workqueue_thread got futex as -1? This is wierd.

I put the patch i used to debug, and the complete log of the reproduce into the
attachment, may this helps.

Thanks,
Minlan

[-- Attachment #2: debug.tar.gz --]
[-- Type: application/gzip, Size: 5023 bytes --]

[-- Attachment #3: Type: text/plain, Size: 156 bytes --]

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 16, 2022, at 4:09 AM, Minlan Wang wangminlan@szsandstone.com wrote:

> Hi, Mathieu,
> I tried to write a simple program to reproduce this issue, but failed.
> The environment we used to produce this issue is a storage cluster.
> It has 3 nodes, each with an NVME and several SATA disks, urcu is part of the
> storage cluster software.
> The storage software is pretty big, 3+ GB in size. I guess it's hard for you to
> build a environment like ours.
> 
> Besides, I made some change into workqueue.c to debug this issue today, here's
> the patch i used for debuging:
> 
> From 18f3fea1436e0c999b346b998b7153150b92e62f Mon Sep 17 00:00:00 2001
> From: wangminlan <wangminlan@szsandstone.com>
> Date: Wed, 15 Jun 2022 14:28:53 +0800
> Subject: [PATCH] <urcu> debug workqueue->futex
> 
> ---
> .../userspace-rcu-0.12.1/src/workqueue.c           | 49 ++++++++++++++++++----
> 1 file changed, 42 insertions(+), 7 deletions(-)
> 
> diff --git
> a/ceph/thirdpart/ascache/thirdparty/userspace-rcu-0.12.1/src/workqueue.c
> b/ceph/thirdpart/ascache/thirdparty/userspace-rcu-0.12.1/src/workqueue.c
> index 59eb21d..eed1e21 100644
> --- a/ceph/thirdpart/ascache/thirdparty/userspace-rcu-0.12.1/src/workqueue.c
> +++ b/ceph/thirdpart/ascache/thirdparty/userspace-rcu-0.12.1/src/workqueue.c
> @@ -132,12 +132,21 @@ static int set_thread_cpu_affinity(struct urcu_workqueue
> *workqueue)
> 
> static void futex_wait(int32_t *futex)
> {
> +	int ret;
> +	int err;
> 	/* Read condition before read futex */
> 	cmm_smp_mb();
> -	if (uatomic_read(futex) != -1)
> +	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__);
> +
> 		return;
> -	while (futex_async(futex, FUTEX_WAIT, -1, NULL, NULL, 0)) {
> -		switch (errno) {
> +	}
> +	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);
> +		switch (err) {
> 		case EWOULDBLOCK:
> 			/* Value already changed. */
> 			return;
> @@ -146,17 +155,35 @@ static void futex_wait(int32_t *futex)
> 			break;	/* Get out of switch. */
> 		default:
> 			/* Unexpected error. */
> -			urcu_die(errno);
> +			urcu_die(err);
> 		}
> 	}
> +
> +	fprintf(stderr, "%lu: wq %p: %s wait return %d\n",
> +		pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex),
> __func__, ret);
> +
> }
> 
> static void futex_wake_up(int32_t *futex)
> {
> 	/* Write to condition before reading/writing futex */
> +	int32_t old;
> +
> 	cmm_smp_mb();
> -	if (caa_unlikely(uatomic_read(futex) == -1)) {
> -		uatomic_set(futex, 0);
> +	old = uatomic_read(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);
> +		} else {
> +			fprintf(stderr, "%lu: wq %p, wakeup failed: old %d\n",
> +				pthread_self(),
> +				caa_container_of(futex, struct urcu_workqueue, futex),
> +				old);
> +		}
> 		if (futex_async(futex, FUTEX_WAKE, 1,
> 				NULL, NULL, 0) < 0)
> 			urcu_die(errno);
> @@ -237,8 +264,16 @@ static void *workqueue_thread(void *arg)
> 		if (!rt) {
> 			if (cds_wfcq_empty(&workqueue->cbs_head,
> 					&workqueue->cbs_tail)) {
> +				int32_t new;
> 				futex_wait(&workqueue->futex);
> -				uatomic_dec(&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);
> +				} else {
> +					fprintf(stderr, "%lu: wq %p dec failed: old %d\n",
> +						pthread_self(), workqueue, new + 1);
> +				}
> 				/*
> 				 * Decrement futex before reading
> 				 * urcu_work list.
> --
> 1.8.3.1
> 
> And the instresting log began from here:
> ---
> ...
>   2097 140196498532096: wq 0x55f69a99ea00, wakeup succeed: old -1	/* enqueue op
>   set futex: -1 -> 0 */
>   2098 140196272453376: wq 0x55f69a99ea00: futex_wait wait return 0	/*
>   workqueue_thread wait success */
>   2099 140196272453376: wq 0x55f69a99ea00 dec failed: old -1		/* workqueue_thread
>   got futex == -1 ? */
>   2100 140196272453376: wq 0x55f69a99ea00: futex_wait futex != -1, don't wait
>   2101 140196272453376: wq 0x55f69a99ea00 dec failed: old -2
> ...
> ---
> In line 2099, how did workqueue_thread got futex as -1? This is wierd.
> 
> I put the patch i used to debug, and the complete log of the reproduce into the
> attachment, may this helps.

Here is my current line of investigation:

grep -e wakeup -e "futex_wait wait return 0" 8.osd.mail.log  |tail

shows:

140196498532096: wq 0x55f69a99ea00, wakeup succeed: old -1
140196272453376: wq 0x55f69a99ea00: futex_wait wait return 0
140196498532096: wq 0x55f69a99ea00, wakeup succeed: old -1
140196272453376: wq 0x55f69a99ea00: futex_wait wait return 0
140196498532096: wq 0x55f69a99ea00, wakeup succeed: old -1
140196272453376: wq 0x55f69a99ea00: futex_wait wait return 0
140196498532096: wq 0x55f69a99ea00, wakeup succeed: old -1
140196498532096: wq 0x55f69a99ea00, wakeup succeed: old -1
140196498532096: wq 0x55f69a99ea00, wakeup succeed: old -1
140196272453376: wq 0x55f69a99ea00: futex_wait wait return 0

Which basically shows that shortly before things go awry, many wakeups succeed
(and are thus potentially queued within the kernel) before a single futex_wait
succeeds.

I therefore suspect that this particular last futex_wait success has been caused
by a prior queued wakeup.

This could indeed be the culprit here, because it would cause the futex_wait to
return and proceed with uatomic_add_return(&workqueue->futex, -1); when the state
was not set to 0 by the wakeup side.

We should not rely too much on the ordering of fprintf stderr output between threads,
because those can be interleaved in any order (each fprintf to stderr is unbuffered).
If we want more precision in the order of events I would recommend using LTTng-UST for
fine-grained user-space tracing. This might explain why the futex has an unexpected value
at line 2099.

Can you try the following patch on top of v0.12.1 + your debug patch ?

diff --git a/src/workqueue.c b/src/workqueue.c
index eed1e21e..19fc89c8 100644
--- a/src/workqueue.c
+++ b/src/workqueue.c
@@ -142,6 +142,7 @@ static void futex_wait(int32_t *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",
@@ -161,7 +162,16 @@ static void futex_wait(int32_t *futex)
 
 	fprintf(stderr, "%lu: wq %p: %s wait return %d\n",
 		pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__, 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__);
+		goto wait;
+	}
 }
 
 static void futex_wake_up(int32_t *futex)


Thanks!

Mathieu

> 
> Thanks,
> Minlan

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

[-- Attachment #1: Type: text/plain, Size: 8525 bytes --]

Hi, Mathieu,
On Fri, Jun 17, 2022 at 09:37:23AM -0400, Mathieu Desnoyers wrote:
> Can you try the following patch on top of v0.12.1 + your debug patch ?
> 
> diff --git a/src/workqueue.c b/src/workqueue.c
> index eed1e21e..19fc89c8 100644
> --- a/src/workqueue.c
> +++ b/src/workqueue.c
> @@ -142,6 +142,7 @@ static void futex_wait(int32_t *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",
> @@ -161,7 +162,16 @@ static void futex_wait(int32_t *futex)
>  
>  	fprintf(stderr, "%lu: wq %p: %s wait return %d\n",
>  		pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__, 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__);
> +		goto wait;
> +	}
>  }
>  
>  static void futex_wake_up(int32_t *futex)
> 
I tried this patch on top of my debug patch, the issue disappeared.
The log shows that "futex_wait futex == -1, wait again" did happen several times.
I put the complete log in the attachment.

> 
> We should not rely too much on the ordering of fprintf stderr output between threads,
> because those can be interleaved in any order (each fprintf to stderr is unbuffered).
> If we want more precision in the order of events I would recommend using LTTng-UST for
> fine-grained user-space tracing. This might explain why the futex has an unexpected value
> at line 2099.
I tried this patch on top of previous 2 patches to use lttng_ust_tracepoint in
workqueue.c, but always failed in compile example code with this error:
---
make[5]: Entering directory `/home/mlwang/debug/userspace-rcu/doc/examples/rculfqueue'
  CC       cds_lfq_enqueue.o
  CCLD     cds_lfq_enqueue
../../../src/.libs//liburcu-cds.so: undefined reference to `lttng_ust_tracepoint_provider_workqueue'
---
the patch is as following:

From 2fa8082914da55b6e3815dffd2f749798bf23735 Mon Sep 17 00:00:00 2001
From: root <root@localhost.localdomain>
Date: Tue, 21 Jun 2022 11:42:56 +0800
Subject: [PATCH] add lttng_ust_tracepoint in workqueue.c

---
 src/Makefile.am       |  4 +--
 src/liburcu-cds.pc.in |  2 +-
 src/workqueue.c       |  5 ++++
 src/workqueue.h       |  1 +
 src/workqueue_tp.c    |  4 +++
 src/workqueue_tp.h    | 82 +++++++++++++++++++++++++++++++++++++++++++++++++++
 6 files changed, 95 insertions(+), 3 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..c29c070 100644
--- a/src/workqueue.c
+++ b/src/workqueue.c
@@ -145,6 +145,7 @@ static void futex_wait(int32_t *futex)
 wait:
 	while ((ret = futex_async(futex, FUTEX_WAIT, -1, NULL, NULL, 0))) {
 		err = errno;
+		lttng_ust_tracepoint(workqueue, futex_wait_err, (long)futex, *futex, err);
 		fprintf(stderr, "%lu: wq %p: %s failed, errno %d\n",
 			pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__, err);
 		switch (err) {
@@ -160,6 +161,7 @@ wait:
 		}
 	}
 
+	lttng_ust_tracepoint(workqueue, futex_wait_return, (long)futex, *futex, ret);
 	fprintf(stderr, "%lu: wq %p: %s wait return %d\n",
 		pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__, ret);
 	/*
@@ -168,6 +170,7 @@ wait:
 	 * again.
 	 */
 	if (uatomic_read(futex) == -1) {
+		lttng_ust_tracepoint(workqueue, futex_wait_again, (long)futex, *futex);
 		fprintf(stderr, "%lu: wq %p: %s futex == -1, wait again\n",
 			pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__);
 		goto wait;
@@ -184,11 +187,13 @@ static void futex_wake_up(int32_t *futex)
 	if (caa_unlikely(old == -1)) {
 		old = uatomic_xchg(futex, 0);
 		if (old == -1) {
+			lttng_ust_tracepoint(workqueue, futex_wake_up_success, (long)futex, old);
 			fprintf(stderr, "%lu: wq %p, wakeup succeed: old %d\n",
 				pthread_self(),
 				caa_container_of(futex, struct urcu_workqueue, futex),
 				old);
 		} else {
+			lttng_ust_tracepoint(workqueue, futex_wake_up_fail, (long)futex, old);
 			fprintf(stderr, "%lu: wq %p, wakeup failed: old %d\n",
 				pthread_self(),
 				caa_container_of(futex, struct urcu_workqueue, futex),
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..e2bce31
--- /dev/null
+++ b/src/workqueue_tp.h
@@ -0,0 +1,82 @@
+#undef	LTTNG_UST_TRACEPOINT_PROVIDER
+#define	LTTNG_UST_TRACEPOINT_PROVIVER workqueue
+
+#undef	LTTNG_UST_TRACEPOINT_INCLUDE
+#define	LTTNG_UST_TRACEPOINT_INCLUDE "./workqueue_tp.h"
+
+#if !defined(_WORKQUEUE_TP_H) || defined(LTTNG_USG_TRACEPOINT_HEADER_MULTI_READ)
+#define	_WORKQUEUE_TP_H
+
+#include <lttng/tracepoint.h>
+
+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_p_field, futex_p_arg)
+		lttng_ust_field_integer(int, futex_field, futex_arg)
+		lttng_ust_field_integer(int, err_field, 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_p_field, futex_p_arg)
+		lttng_ust_field_integer(int, futex_field, futex_arg)
+		lttng_ust_field_integer(int, ret_field, 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_p_field, futex_p_arg)
+		lttng_ust_field_integer(int, futex_field, 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_p_field, futex_p_arg)
+		lttng_ust_field_integer(int, futex_field, 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_p_field, futex_p_arg)
+		lttng_ust_field_integer(int, futex_field, futex_arg)
+	)
+)
+
+#endif /* _WORKQUEUE_TP_H */
+#include <lttng/tracepoint-event.h>
-- 
1.8.3.1

Is "perf probe" accurate in tracing the futex event here?  Maybe i can try that.

B.R
Minlan

[-- Attachment #2: log.tar.bz2 --]
[-- Type: application/x-bzip2, Size: 153355 bytes --]

[-- Attachment #3: Type: text/plain, Size: 156 bytes --]

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] ***UNCHECKED*** Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 20, 2022, at 11:52 PM, Minlan Wang wangminlan@szsandstone.com wrote:

> Hi, Mathieu,
> On Fri, Jun 17, 2022 at 09:37:23AM -0400, Mathieu Desnoyers wrote:
>> Can you try the following patch on top of v0.12.1 + your debug patch ?
>> 
>> diff --git a/src/workqueue.c b/src/workqueue.c
>> index eed1e21e..19fc89c8 100644
>> --- a/src/workqueue.c
>> +++ b/src/workqueue.c
>> @@ -142,6 +142,7 @@ static void futex_wait(int32_t *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",
>> @@ -161,7 +162,16 @@ static void futex_wait(int32_t *futex)
>>  
>>  	fprintf(stderr, "%lu: wq %p: %s wait return %d\n",
>>  		pthread_self(), caa_container_of(futex, struct urcu_workqueue, futex), __func__,
>>  		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__);
>> +		goto wait;
>> +	}
>>  }
>>  
>>  static void futex_wake_up(int32_t *futex)
>> 
> I tried this patch on top of my debug patch, the issue disappeared.
> The log shows that "futex_wait futex == -1, wait again" did happen several
> times.
> I put the complete log in the attachment.

This means we appear to be on the right track. Good!

> 
>> 
>> We should not rely too much on the ordering of fprintf stderr output between
>> threads,
>> because those can be interleaved in any order (each fprintf to stderr is
>> unbuffered).
>> If we want more precision in the order of events I would recommend using
>> LTTng-UST for
>> fine-grained user-space tracing. This might explain why the futex has an
>> unexpected value
>> at line 2099.
> I tried this patch on top of previous 2 patches to use lttng_ust_tracepoint in
> workqueue.c, but always failed in compile example code with this error:
> ---
> make[5]: Entering directory
> `/home/mlwang/debug/userspace-rcu/doc/examples/rculfqueue'
>  CC       cds_lfq_enqueue.o
>  CCLD     cds_lfq_enqueue
> ../../../src/.libs//liburcu-cds.so: undefined reference to
> `lttng_ust_tracepoint_provider_workqueue'
> ---
> the patch is as following:
[...]
> --- 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..e2bce31
> --- /dev/null
> +++ b/src/workqueue_tp.h
> @@ -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 ?

If that's not it, it should be something relatively simple with the build dependencies. Let me know
if it still does not work.

[...]

> --
> 1.8.3.1
> 
> Is "perf probe" accurate in tracing the futex event here?  Maybe i can try that.

I would prefer to use lttng-ust here to keep the footprint of the tracer minimal, so we do not
change the behavior too much by calling into the kernel.

Then we'll be able to correlate traces from lttng-ust and lttng-modules (kernel tracer) and
figure out what is happening both in user-space and kernel space, especially around futex and
scheduler activity within the kernel.

Thanks,

Mathieu

> 
> B.R
> Minlan

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] ***UNCHECKED*** Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

[-- Attachment #1: Type: text/plain, Size: 10634 bytes --]

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@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


[-- Attachment #2: trace_0622.tar.bz2 --]
[-- Type: application/x-bzip2, Size: 6277601 bytes --]

[-- Attachment #3: Type: text/plain, Size: 156 bytes --]

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] ***UNCHECKED*** Re: Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 22, 2022, at 3:45 AM, Minlan Wang wangminlan@szsandstone.com wrote:

[...]

Hi Minlan,

> --
> 1.8.3.1
> 
> 
> And the lttng session is configured to trace these events:
> kernel: syscall futex

On the kernel side, in addition to the syscall futex, I would really like to see what
happens in the scheduler, mainly the wait/wakeup tracepoints. This can be added by using:

lttng enable-event -k 'sched_*'

This should help us confirm whether we indeed have a situation where queued wake ups
happen to wake up a wait happening only later, which is unexpected by the current liburcu
userspace code.

[...]

> ---
> 
> 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.

It would be even better if you can share the binary trace, because then it's easy to
load it in trace compass, cut away time ranges that don't matter, and lots of other
useful stuff.

Thanks,

Mathieu

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] ***UNCHECKED*** Re: Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 22, 2022, at 9:19 AM, Mathieu Desnoyers mathieu.desnoyers@efficios.com wrote:

> ----- On Jun 22, 2022, at 3:45 AM, Minlan Wang wangminlan@szsandstone.com wrote:
> 
> [...]
> 
> Hi Minlan,
> 
>> --
>> 1.8.3.1
>> 
>> 
>> And the lttng session is configured to trace these events:
>> kernel: syscall futex
> 
> On the kernel side, in addition to the syscall futex, I would really like to see
> what
> happens in the scheduler, mainly the wait/wakeup tracepoints. This can be added
> by using:
> 
> lttng enable-event -k 'sched_*'
> 
> This should help us confirm whether we indeed have a situation where queued wake
> ups
> happen to wake up a wait happening only later, which is unexpected by the
> current liburcu
> userspace code.
> 
> [...]
> 
>> ---
>> 
>> 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.
> 
> It would be even better if you can share the binary trace, because then it's
> easy to
> load it in trace compass, cut away time ranges that don't matter, and lots of
> other
> useful stuff.

I just found the relevant snippet of documentation in futex(5):

       FUTEX_WAIT
              Returns 0 if the caller was woken up.  Note that a  wake-up  can
              also  be caused by common futex usage patterns in unrelated code
              that happened to have previously used the  futex  word's  memory
              location  (e.g., typical futex-based implementations of Pthreads
              mutexes can cause this under some conditions).  Therefore, call‐
              ers should always conservatively assume that a return value of 0
              can mean a spurious wake-up, and  use  the  futex  word's  value
              (i.e.,  the user-space synchronization scheme) to decide whether
              to continue to block or not.

I'm pretty sure this is what is happening here.

Thanks,

Mathieu


> 
> Thanks,
> 
> Mathieu
> 
> --
> Mathieu Desnoyers
> EfficiOS Inc.
> http://www.efficios.com

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] ***UNCHECKED*** Re: Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 22, 2022, at 4:28 PM, Mathieu Desnoyers mathieu.desnoyers@efficios.com wrote:

> ----- On Jun 22, 2022, at 9:19 AM, Mathieu Desnoyers
> mathieu.desnoyers@efficios.com wrote:
> 
>> ----- On Jun 22, 2022, at 3:45 AM, Minlan Wang wangminlan@szsandstone.com wrote:
>> 
>> [...]
>> 
>> Hi Minlan,
>> 
>>> --
>>> 1.8.3.1
>>> 
>>> 
>>> And the lttng session is configured to trace these events:
>>> kernel: syscall futex
>> 
>> On the kernel side, in addition to the syscall futex, I would really like to see
>> what
>> happens in the scheduler, mainly the wait/wakeup tracepoints. This can be added
>> by using:
>> 
>> lttng enable-event -k 'sched_*'
>> 
>> This should help us confirm whether we indeed have a situation where queued wake
>> ups
>> happen to wake up a wait happening only later, which is unexpected by the
>> current liburcu
>> userspace code.
>> 
>> [...]
>> 
>>> ---
>>> 
>>> 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.
>> 
>> It would be even better if you can share the binary trace, because then it's
>> easy to
>> load it in trace compass, cut away time ranges that don't matter, and lots of
>> other
>> useful stuff.
> 
> I just found the relevant snippet of documentation in futex(5):
> 
>       FUTEX_WAIT
>              Returns 0 if the caller was woken up.  Note that a  wake-up  can
>              also  be caused by common futex usage patterns in unrelated code
>              that happened to have previously used the  futex  word's  memory
>              location  (e.g., typical futex-based implementations of Pthreads
>              mutexes can cause this under some conditions).  Therefore, call‐
>              ers should always conservatively assume that a return value of 0
>              can mean a spurious wake-up, and  use  the  futex  word's  value
>              (i.e.,  the user-space synchronization scheme) to decide whether
>              to continue to block or not.
> 
> I'm pretty sure this is what is happening here.

Here is the series of patches for review on gerrit:

remote:   https://review.lttng.org/c/userspace-rcu/+/8441 Fix: workqueue: futex wait: handle spurious futex wakeups [NEW]        
remote:   https://review.lttng.org/c/userspace-rcu/+/8442 Fix: urcu: futex wait: handle spurious futex wakeups [NEW]        
remote:   https://review.lttng.org/c/userspace-rcu/+/8443 Fix: call_rcu: futex wait: handle spurious futex wakeups [NEW]        
remote:   https://review.lttng.org/c/userspace-rcu/+/8444 Fix: urcu-wait: futex wait: handle spurious futex wakeups [NEW]        
remote:   https://review.lttng.org/c/userspace-rcu/+/8445 Fix: defer_rcu: futex wait: handle spurious futex wakeups [NEW]        
remote:   https://review.lttng.org/c/userspace-rcu/+/8446 Fix: urcu-qsbr: futex wait: handle spurious futex wakeups [NEW] 

Thanks,

Mathieu

> 
> Thanks,
> 
> Mathieu
> 
> 
>> 
>> Thanks,
>> 
>> Mathieu
>> 
>> --
>> Mathieu Desnoyers
>> EfficiOS Inc.
>> http://www.efficios.com
> 
> --
> Mathieu Desnoyers
> EfficiOS Inc.
> http://www.efficios.com

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] ***UNCHECKED*** Re: Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

On Wed, Jun 22, 2022 at 11:45:28PM -0400, Minlan Wang wrote:
> The session output is in attachment: 0623_futex-20220623-112754.tar.bz2
Hi, Mathieu,
There are several workqueues in the process i tracked.
The one used to trigger the issuse is this:
thread with vtid=21054, and futex = 0x5652A1035C40

B.R
Minlan


_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

[lttng-dev] [PART 4/4] Re: ***UNCHECKED*** Re: Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

[-- Attachment #1: Type: text/plain, Size: 35 bytes --]

Hi, Mathieu,
This is the last one.

[-- Attachment #2: 0623_futex-20220623-112754.tar.bz2.ad --]
[-- Type: application/octet-stream, Size: 38903 bytes --]

[-- Attachment #3: Type: text/plain, Size: 156 bytes --]

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] ***UNCHECKED*** Re: Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

On Wed, Jun 22, 2022 at 04:52:00PM -0400, Mathieu Desnoyers wrote:
[...]
> remote:   https://review.lttng.org/c/userspace-rcu/+/8441 Fix: workqueue: futex wait: handle spurious futex wakeups [NEW]        
I tried this patch in our environment, it worked fine, the issue does not appear anymore.

B.R
Minlan


_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] ***UNCHECKED*** Re: Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Mathieu Desnoyers via lttng-dev]

----- On Jun 22, 2022, at 11:57 PM, Minlan Wang wangminlan@szsandstone.com wrote:

> On Wed, Jun 22, 2022 at 11:45:28PM -0400, Minlan Wang wrote:
>> The session output is in attachment: 0623_futex-20220623-112754.tar.bz2
> Hi, Mathieu,
> There are several workqueues in the process i tracked.
> The one used to trigger the issuse is this:
> thread with vtid=21054, and futex = 0x5652A1035C40

By looking at the trace, here is one problematic scenario which end up emitting "workqueue:futex_wait_again":

[23:33:48.060581417] (+0.000006985) localhost.localdomain workqueue:futex_no_wait: { cpu_id = 4 }, { vpid = 19495, vtid = 21054 }, { futex = 0x5652A1035C40, val = 0 }
[23:33:48.060581747] (+0.000000330) localhost.localdomain workqueue:futex_wake_up_success: { cpu_id = 6 }, { vpid = 19495, vtid = 20649 }, { futex = 0x5652A1035C40, val = -1 }
[23:33:48.060581926] (+0.000000179) localhost.localdomain workqueue:futex_dec_success: { cpu_id = 4 }, { vpid = 19495, vtid = 21054 }, { futex = 0x5652A1035C40, old = 0, new = -1 }
[23:33:48.060582826] (+0.000000900) localhost.localdomain syscall_entry_futex: { cpu_id = 6 }, { vpid = 19495, vtid = 20649, pid = 19495, tid = 20649 }, { uaddr = 94912888659008, op = 1, val = 1, utime = 0, uaddr2 = 0, val3 = 0 }
[23:33:48.060582855] (+0.000000029) localhost.localdomain syscall_entry_futex: { cpu_id = 4 }, { vpid = 19495, vtid = 21054, pid = 19495, tid = 21054 }, { uaddr = 94912888659008, op = 0, val = 4294967295, utime = 0, uaddr2 = 0, val3 = 0 }
[23:33:48.060584722] (+0.000001867) localhost.localdomain sched_stat_runtime: { cpu_id = 4 }, { vpid = 19495, vtid = 21054, pid = 19495, tid = 21054 }, { comm = "bcache_writebac", tid = 21054, runtime = 16033, vruntime = 96940983054 }
[23:33:48.060585840] (+0.000001118) localhost.localdomain sched_switch: { cpu_id = 4 }, { vpid = 19495, vtid = 21054, pid = 19495, tid = 21054 }, { prev_comm = "bcache_writebac", prev_tid = 21054, prev_prio = 20, prev_state = 1, next_comm = "swapper/4", next_tid = 0, next_prio = 20 }
[23:33:48.060587680] (+0.000001840) localhost.localdomain sched_stat_sleep: { cpu_id = 6 }, { vpid = 19495, vtid = 20649, pid = 19495, tid = 20649 }, { comm = "bcache_writebac", tid = 21054, delay = 2815 }
[23:33:48.060588560] (+0.000000880) localhost.localdomain sched_wakeup: { cpu_id = 6 }, { vpid = 19495, vtid = 20649, pid = 19495, tid = 20649 }, { comm = "bcache_writebac", tid = 21054, prio = 20, success = 1, target_cpu = 4 }
[23:33:48.060590437] (+0.000001877) localhost.localdomain syscall_exit_futex: { cpu_id = 4 }, { vpid = 19495, vtid = 21054, pid = 19495, tid = 21054 }, { ret = 0, uaddr = 94912888659008, uaddr2 = 0 }
[23:33:48.060591337] (+0.000000900) localhost.localdomain syscall_exit_futex: { cpu_id = 6 }, { vpid = 19495, vtid = 20649, pid = 19495, tid = 20649 }, { ret = 1, uaddr = 94912888659008, uaddr2 = 0 }
[23:33:48.060591385] (+0.000000048) localhost.localdomain workqueue:futex_wait_return: { cpu_id = 4 }, { vpid = 19495, vtid = 21054 }, { futex = 0x5652A1035C40, val = -1, ret = 0 }
[23:33:48.060592205] (+0.000000820) localhost.localdomain workqueue:futex_wait_again: { cpu_id = 4 }, { vpid = 19495, vtid = 21054 }, { futex = 0x5652A1035C40, val = -1 }

Where the wake_up happens right before the dec_success on the waiter, which
leads to the sched_wakeup awakening the waiter when the state is 0.

If we want to dig more into why this scenario can happen, we could also add tracepoints
in urcu_workqueue_queue_work() just before/after cds_wfcq_enqueue(), and in 
workqueue_thread() around each call to cds_wfcq_empty(), and around __cds_wfcq_splice_blocking().

I suspect we end up in a situation where:

* waker:

        cds_wfcq_enqueue(&workqueue->cbs_head, &workqueue->cbs_tail, &work->next); [a]
        uatomic_inc(&workqueue->qlen);
        wake_worker_thread(workqueue);                                             [b]

vs

* waiter:
                splice_ret = __cds_wfcq_splice_blocking(&cbs_tmp_head,             [c]
                        &cbs_tmp_tail, &workqueue->cbs_head, &workqueue->cbs_tail);
[...]
                        if (cds_wfcq_empty(&workqueue->cbs_head,                   [d]
                                        &workqueue->cbs_tail)) {
                                futex_wait(&workqueue->futex);                     [e]
                                uatomic_dec(&workqueue->futex);                    [f]

happen in an order such that 

[a] enqueues an item. Then [c] splices the item out of the queue because it was already awakened
by a prior wakeup. So the queue is observed as empty by [c]. Then [b] sets the futex to 0
(in userspace), which causes [e] to skip waiting on the futex, and [f] brings the value back
to -1. However, in the next loop, the queue is still observed as empty by [d], thus calling
[e] again. This time, the value is -1, so it calls sys_futex FUTEX_WAIT. Unfortunately, we
still have the call to sys_futex FUTEX_WAKE that will eventually be executed, thus awakening
the futex while the futex state is still -1, which is unexpected.

Thanks,

Mathieu

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] ***UNCHECKED*** Re: Re: urcu workqueue thread uses 99% of cpu while workqueue is empty

[Minlan Wang via lttng-dev]

On Thu, Jun 23, 2022 at 10:09:55AM -0400, Mathieu Desnoyers wrote:
> 
> By looking at the trace, here is one problematic scenario which end up emitting "workqueue:futex_wait_again":
> 
> [23:33:48.060581417] (+0.000006985) localhost.localdomain workqueue:futex_no_wait: { cpu_id = 4 }, { vpid = 19495, vtid = 21054 }, { futex = 0x5652A1035C40, val = 0 }
> [23:33:48.060581747] (+0.000000330) localhost.localdomain workqueue:futex_wake_up_success: { cpu_id = 6 }, { vpid = 19495, vtid = 20649 }, { futex = 0x5652A1035C40, val = -1 }
> [23:33:48.060581926] (+0.000000179) localhost.localdomain workqueue:futex_dec_success: { cpu_id = 4 }, { vpid = 19495, vtid = 21054 }, { futex = 0x5652A1035C40, old = 0, new = -1 }
> [23:33:48.060582826] (+0.000000900) localhost.localdomain syscall_entry_futex: { cpu_id = 6 }, { vpid = 19495, vtid = 20649, pid = 19495, tid = 20649 }, { uaddr = 94912888659008, op = 1, val = 1, utime = 0, uaddr2 = 0, val3 = 0 }
> [23:33:48.060582855] (+0.000000029) localhost.localdomain syscall_entry_futex: { cpu_id = 4 }, { vpid = 19495, vtid = 21054, pid = 19495, tid = 21054 }, { uaddr = 94912888659008, op = 0, val = 4294967295, utime = 0, uaddr2 = 0, val3 = 0 }
> [23:33:48.060584722] (+0.000001867) localhost.localdomain sched_stat_runtime: { cpu_id = 4 }, { vpid = 19495, vtid = 21054, pid = 19495, tid = 21054 }, { comm = "bcache_writebac", tid = 21054, runtime = 16033, vruntime = 96940983054 }
> [23:33:48.060585840] (+0.000001118) localhost.localdomain sched_switch: { cpu_id = 4 }, { vpid = 19495, vtid = 21054, pid = 19495, tid = 21054 }, { prev_comm = "bcache_writebac", prev_tid = 21054, prev_prio = 20, prev_state = 1, next_comm = "swapper/4", next_tid = 0, next_prio = 20 }
> [23:33:48.060587680] (+0.000001840) localhost.localdomain sched_stat_sleep: { cpu_id = 6 }, { vpid = 19495, vtid = 20649, pid = 19495, tid = 20649 }, { comm = "bcache_writebac", tid = 21054, delay = 2815 }
> [23:33:48.060588560] (+0.000000880) localhost.localdomain sched_wakeup: { cpu_id = 6 }, { vpid = 19495, vtid = 20649, pid = 19495, tid = 20649 }, { comm = "bcache_writebac", tid = 21054, prio = 20, success = 1, target_cpu = 4 }
> [23:33:48.060590437] (+0.000001877) localhost.localdomain syscall_exit_futex: { cpu_id = 4 }, { vpid = 19495, vtid = 21054, pid = 19495, tid = 21054 }, { ret = 0, uaddr = 94912888659008, uaddr2 = 0 }
> [23:33:48.060591337] (+0.000000900) localhost.localdomain syscall_exit_futex: { cpu_id = 6 }, { vpid = 19495, vtid = 20649, pid = 19495, tid = 20649 }, { ret = 1, uaddr = 94912888659008, uaddr2 = 0 }
> [23:33:48.060591385] (+0.000000048) localhost.localdomain workqueue:futex_wait_return: { cpu_id = 4 }, { vpid = 19495, vtid = 21054 }, { futex = 0x5652A1035C40, val = -1, ret = 0 }
> [23:33:48.060592205] (+0.000000820) localhost.localdomain workqueue:futex_wait_again: { cpu_id = 4 }, { vpid = 19495, vtid = 21054 }, { futex = 0x5652A1035C40, val = -1 }
> 
> Where the wake_up happens right before the dec_success on the waiter, which
> leads to the sched_wakeup awakening the waiter when the state is 0.
Yes, this makes things clear, urcu_workqueue_queue_work did wake up waiters on
futex when the futex is -1.

> 
> If we want to dig more into why this scenario can happen, we could also add tracepoints
> in urcu_workqueue_queue_work() just before/after cds_wfcq_enqueue(), and in 
> workqueue_thread() around each call to cds_wfcq_empty(), and around __cds_wfcq_splice_blocking().
> 
> I suspect we end up in a situation where:
> 
> * waker:
> 
>         cds_wfcq_enqueue(&workqueue->cbs_head, &workqueue->cbs_tail, &work->next); [a]
>         uatomic_inc(&workqueue->qlen);
>         wake_worker_thread(workqueue);                                             [b]
> 
> vs
> 
> * waiter:
>                 splice_ret = __cds_wfcq_splice_blocking(&cbs_tmp_head,             [c]
>                         &cbs_tmp_tail, &workqueue->cbs_head, &workqueue->cbs_tail);
> [...]
>                         if (cds_wfcq_empty(&workqueue->cbs_head,                   [d]
>                                         &workqueue->cbs_tail)) {
>                                 futex_wait(&workqueue->futex);                     [e]
>                                 uatomic_dec(&workqueue->futex);                    [f]
> 
> happen in an order such that 
> 
> [a] enqueues an item. Then [c] splices the item out of the queue because it was already awakened
> by a prior wakeup. So the queue is observed as empty by [c]. Then [b] sets the futex to 0
> (in userspace), which causes [e] to skip waiting on the futex, and [f] brings the value back
> to -1. However, in the next loop, the queue is still observed as empty by [d], thus calling
> [e] again. This time, the value is -1, so it calls sys_futex FUTEX_WAIT. Unfortunately, we
> still have the call to sys_futex FUTEX_WAKE that will eventually be executed, thus awakening
> the futex while the futex state is still -1, which is unexpected.
Yes, i agree with you. We'll add the patch you mentioned into our code to fix this.
Thanks for your help.

Since cds_wfcq_enqueue/__cds_wfcq_splice_blocking do nothing to
workqueue->futex, add debug info to see if workqueue is empty is not so
neccessary to me.
Let me know if you need anything else on this.

Thanks, again.

Minlan


_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev