[pulseaudio-discuss] jack module cannot use real-time scheduling errors

Thu Jun 28 19:59:16 UTC 2018

On Thu, Jun 28, 2018 at 11:25 AM, dag dg <dagofthedofg at gmail.com> wrote:
> On Wed, Jun 27, 2018 at 2:19 AM, Tanu Kaskinen <tanuk at iki.fi> wrote:
>> On Thu, 2018-06-21 at 09:58 -0500, dag dg wrote:
>>> I use pulse with jack via jackdbus. I've been trying to narrow down
>>> the cause of a series of errors I've been seeing in my pulseaudio logs
>>> for some time:
>>>
>>> Jun 21 08:43:46 localhost pulseaudio[1988]: W: [pulseaudio]
>>> module-jack-sink.c: JACK error >Cannot use real-time scheduling
>>> (RR/15)(1: Operation not permitted)<
>>> Jun 21 08:43:46 localhost pulseaudio[1988]: W: [pulseaudio]
>>> module-jack-source.c: JACK error >Cannot use real-time scheduling
>>> (RR/15)(1: Operation not permitted)<
>>> Jun 21 08:44:40 localhost pulseaudio[2596]: W: [pulseaudio]
>>> module-jack-sink.c: JACK error >Cannot use real-time scheduling
>>> (RR/15)(1: Operation not permitted)<
>>> Jun 21 08:44:40 localhost pulseaudio[2596]: W: [pulseaudio]
>>> module-jack-source.c: JACK error >Cannot use real-time scheduling
>>> (RR/15)(1: Operation not permitted)<
>>>
>>> Running pulse in a higher verbosity I get:
>>>
>>> I: [pulseaudio] module-jack-sink.c: Successfully connected as
>>> 'PulseAudio JACK Sink'
>>> I: [pulseaudio] module-device-restore.c: Restoring volume for sink
>>> jack_out: front-left: 45922 /  70%,   front-right: 45922 /  70%
>>> I: [pulseaudio] module-device-restore.c: Restoring mute state for sink
>>> jack_out: unmuted
>>> W: [pulseaudio] sink.c: Default and alternate sample rates are the same.
>>> I: [pulseaudio] sink.c: Created sink 3 "jack_out" with sample spec
>>> float32le 2ch 48000Hz and channel map front-left,front-right
>>> I: [pulseaudio] sink.c:     device.api = "jack"
>>> I: [pulseaudio] sink.c:     device.description = "Jack sink
>>> (PulseAudio JACK Sink)"
>>> I: [pulseaudio] sink.c:     jack.client_name = "PulseAudio JACK Sink"
>>> I: [pulseaudio] sink.c:     device.icon_name = "audio-card"
>>> I: [pulseaudio] module-device-restore.c: Restoring volume for source
>>> jack_out.monitor: front-left: 65536 / 100%,   front-right: 65536 /
>>> 100%
>>> I: [pulseaudio] source.c: Created source 5 "jack_out.monitor" with
>>> sample spec float32le 2ch 48000Hz and channel map
>>> front-left,front-right
>>> I: [pulseaudio] source.c:     device.description = "Monitor of Jack
>>> sink (PulseAudio JACK Sink)"
>>> I: [pulseaudio] source.c:     device.class = "monitor"
>>> I: [pulseaudio] source.c:     device.icon_name = "audio-input-microphone"
>>> I: [pulseaudio] module-jack-sink.c: JACK thread starting up.
>>> I: [pulseaudio] core-util.c: Successfully enabled SCHED_RR scheduling
>>> for thread, with priority 9.
>>> I: [jack-sink] core-util.c: Successfully enabled SCHED_RR scheduling
>>> for thread, with priority 5.
>>> I: [pulseaudio] module-jack-sink.c: JACK buffer size changed.
>>> I: [pulseaudio] module-jack-sink.c: JACK thread starting up.
>>> I: [pulseaudio] core-util.c: Successfully enabled SCHED_RR scheduling
>>> for thread, with priority 9.
>>> W: [pulseaudio] module-jack-sink.c: JACK error >Cannot use real-time
>>> scheduling (RR/15)(1: Operation not permitted)<
>>> W: [pulseaudio] module-jack-sink.c: JACK error
>>> > JackClient::AcquireSelfRealTime error<
>>>
>>> I: [pulseaudio] module-jack-sink.c: JACK thread starting up.
>>> I: [pulseaudio] core-util.c: Successfully enabled SCHED_RR scheduling
>>> for thread, with priority 9.
>>> I: [pulseaudio] module.c: Loaded "module-jack-sink" (index: #24;
>>> argument: "connect=no channels=2").
>>> I: [pulseaudio] module-jackdbus-detect.c: Successfully started module-jack-sink.
>>> I: [pulseaudio] module-jack-source.c: Successfully connected as
>>> 'PulseAudio JACK Source'
>>> I: [pulseaudio] module-device-restore.c: Restoring volume for source
>>> jack_in: front-left: 65536 / 100%,   front-right: 65536 / 100%
>>> I: [pulseaudio] module-device-restore.c: Restoring mute state for
>>> source jack_in: unmuted
>>> W: [pulseaudio] source.c: Default and alternate sample rates are the same.
>>> I: [pulseaudio] source.c: Created source 6 "jack_in" with sample spec
>>> float32le 2ch 48000Hz and channel map front-left,front-right
>>> I: [pulseaudio] source.c:     device.api = "jack"
>>> I: [pulseaudio] source.c:     device.description = "Jack source
>>> (PulseAudio JACK Source)"
>>> I: [pulseaudio] source.c:     jack.client_name = "PulseAudio JACK Source"
>>> I: [pulseaudio] source.c:     device.icon_name = "audio-input-microphone"
>>> I: [pulseaudio] module-jack-source.c: JACK thread starting up.
>>> I: [pulseaudio] core-util.c: Successfully enabled SCHED_RR scheduling
>>> for thread, with priority 9.
>>> I: [jack-source] core-util.c: Successfully enabled SCHED_RR scheduling
>>> for thread, with priority 5.
>>> I: [pulseaudio] module-jack-source.c: JACK thread starting up.
>>> I: [pulseaudio] core-util.c: Successfully enabled SCHED_RR scheduling
>>> for thread, with priority 9.
>>> W: [pulseaudio] module-jack-source.c: JACK error >Cannot use real-time
>>> scheduling (RR/15)(1: Operation not permitted)<
>>> W: [pulseaudio] module-jack-source.c: JACK error
>>> > JackClient::AcquireSelfRealTime error<
>>>
>>> I: [pulseaudio] module-jack-source.c: JACK thread starting up.
>>> I: [pulseaudio] core-util.c: Successfully enabled SCHED_RR scheduling
>>> for thread, with priority 9.
>>> I: [pulseaudio] module.c: Loaded "module-jack-source" (index: #25;
>>> argument: "connect=no channels=2").
>>> I: [pulseaudio] module-jackdbus-detect.c: Successfully started
>>> module-jack-source.
>>>
>>> I've played around with ulimit and cgroups but by distro
>>> defaults(Fedora 28) seem to be fine as I can run processes via prlimit
>>>
>>> [user at localhost ~]$ sudo cat /etc/security/limits.d/95-jack.conf
>>> # Default limits for users of jack-audio-connection-kit
>>>
>>> @jackuser - rtprio 70
>>> @jackuser - memlock 4194304
>>>
>>> @pulse-rt - rtprio 20
>>> @pulse-rt - nice -20
>>> [user at localhost ~]$ prlimit --rtprio=70 --rttime=unlimited echo
>>>
>>> [user at localhost ~]$ echo $?
>>> 0
>>> [user at localhost ~]$ prlimit --rtprio=71 --rttime=unlimited echo
>>> prlimit: failed to set the RTPRIO resource limit: Operation not permitted
>>> [user at localhost ~]$ echo $?
>>> 1
>>>
>>> So the settings appear to be correct yet the pulse jack module still
>>> complains about not being able to properly set the RT priority? Any
>>> insight would be appreciated.
>>
>> My guess is that when libjack creates a thread for the pulseaudio
>> process, it tries to set priority 15 for the thread, but the pulseaudio
>> process priority limit is something lower (probably 9, since that's the
>> default). Try setting "rlimit-rtprio = 15" in /etc/pulse/daemon.conf.
>>
>> --
>> Tanu
>>
>> https://liberapay.com/tanuk
>> https://www.patreon.com/tanuk
>
> Changing the rlimit-rtprio doesn't cause it to change the priority it
> attempts to run as, but when I change the real time priority of the
> jack daemon(via qjackctl) the jack pulse modules try to run at a
> priority of 5 less than the priority of the jack daemon. For example
> if I set the realtime priority to 30:
>
> Jun 28 11:11:41 localhost pulseaudio[5920]: W: [pulseaudio] sink.c:
> Default and alternate sample rates are the same.
> Jun 28 11:11:41 localhost pulseaudio[5920]: W: [pulseaudio]
> module-jack-sink.c: JACK error >Cannot use real-time scheduling
> (RR/25)(1: Operation not permitted)<
> Jun 28 11:11:41 localhost pulseaudio[5920]: W: [pulseaudio]
> module-jack-sink.c: JACK error >JackClient::AcquireSelfRealTime error<
> Jun 28 11:11:41 localhost pulseaudio[5920]: W: [pulseaudio] source.c:
> Default and alternate sample rates are the same.
> Jun 28 11:11:41 localhost pulseaudio[5920]: W: [pulseaudio]
> module-jack-source.c: JACK error >Cannot use real-time scheduling
> (RR/25)(1: Operation not permitted)<
> Jun 28 11:11:41 localhost pulseaudio[5920]: W: [pulseaudio]
> module-jack-source.c: JACK error >JackClient::AcquireSelfRealTime
> error<
> Jun 28 11:11:44 localhost pulseaudio[5920]: W: [pulseaudio] module.c:
> After module unload, module 'module-null-sink' was still loaded!
> Jun 28 11:11:49 localhost systemd[1621]: Starting Sound Service...
> Jun 28 11:11:49 localhost rtkit-daemon[1071]: Successfully made thread
> 5973 of process 5973 (/usr/bin/pulseaudio) owned by '1000' high
> priority at nice level -11.
> Jun 28 11:11:49 localhost rtkit-daemon[1071]: Supervising 1 threads of
> 1 processes of 1 users.
> Jun 28 11:11:51 localhost pulseaudio[5973]: W: [pulseaudio] sink.c:
> Default and alternate sample rates are the same.
> Jun 28 11:11:51 localhost pulseaudio[5973]: W: [pulseaudio]
> module-jack-sink.c: JACK error >Cannot use real-time scheduling
> (RR/25)(1: Operation not permitted)<
> Jun 28 11:11:51 localhost pulseaudio[5973]: W: [pulseaudio]
> module-jack-sink.c: JACK error >JackClient::AcquireSelfRealTime error<
> Jun 28 11:11:51 localhost pulseaudio[5973]: W: [pulseaudio] source.c:
> Default and alternate sample rates are the same.
> Jun 28 11:11:51 localhost pulseaudio[5973]: W: [pulseaudio]
> module-jack-source.c: JACK error >Cannot use real-time scheduling
> (RR/25)(1: Operation not permitted)<
> Jun 28 11:11:51 localhost pulseaudio[5973]: W: [pulseaudio]
> module-jack-source.c: JACK error >JackClient::AcquireSelfRealTime
> error<
> Jun 28 11:11:51 localhost systemd[1621]: Started Sound Service.
>
> you can see it attempts to set things at a priority of 25. If I change
> it to 6 in qjackctl:
>
> Jun 28 11:13:30 localhost pulseaudio[5973]: W: [pulseaudio] sink.c:
> Default and alternate sample rates are the same.
> Jun 28 11:13:30 localhost pulseaudio[5973]: W: [pulseaudio]
> module-jack-sink.c: JACK error >Cannot use real-time scheduling
> (RR/1)(1: Operation not permitted)<
> Jun 28 11:13:30 localhost pulseaudio[5973]: W: [pulseaudio]
> module-jack-sink.c: JACK error >JackClient::AcquireSelfRealTime error<
> Jun 28 11:13:30 localhost pulseaudio[5973]: W: [pulseaudio] source.c:
> Default and alternate sample rates are the same.
> Jun 28 11:13:30 localhost pulseaudio[5973]: W: [pulseaudio]
> module-jack-source.c: JACK error >Cannot use real-time scheduling
> (RR/1)(1: Operation not permitted)<
> Jun 28 11:13:30 localhost pulseaudio[5973]: W: [pulseaudio]
> module-jack-source.c: JACK error >JackClient::AcquireSelfRealTime
> error<
> Jun 28 11:13:32 localhost pulseaudio[5973]: W: [pulseaudio] module.c:
> After module unload, module 'module-null-sink' was still loaded!
> Jun 28 11:13:37 localhost systemd[1621]: Starting Sound Service...
> Jun 28 11:13:37 localhost rtkit-daemon[1071]: Successfully made thread
> 6038 of process 6038 (/usr/bin/pulseaudio) owned by '1000' high
> priority at nice level -11.
> Jun 28 11:13:37 localhost rtkit-daemon[1071]: Supervising 1 threads of
> 1 processes of 1 users.
> Jun 28 11:13:40 localhost pulseaudio[6038]: W: [pulseaudio] sink.c:
> Default and alternate sample rates are the same.
> Jun 28 11:13:40 localhost pulseaudio[6038]: W: [pulseaudio]
> module-jack-sink.c: JACK error >Cannot use real-time scheduling
> (RR/1)(1: Operation not permitted)<
> Jun 28 11:13:40 localhost pulseaudio[6038]: W: [pulseaudio]
> module-jack-sink.c: JACK error >JackClient::AcquireSelfRealTime error<
> Jun 28 11:13:40 localhost pulseaudio[6038]: W: [pulseaudio] source.c:
> Default and alternate sample rates are the same.
> Jun 28 11:13:40 localhost pulseaudio[6038]: W: [pulseaudio]
> module-jack-source.c: JACK error >Cannot use real-time scheduling
> (RR/1)(1: Operation not permitted)<
> Jun 28 11:13:40 localhost pulseaudio[6038]: W: [pulseaudio]
> module-jack-source.c: JACK error >JackClient::AcquireSelfRealTime
> error<
> Jun 28 11:13:40 localhost systemd[1621]: Started Sound Service.
>
> you can see it tries to set it to a priority of 1(but I still see an error).
>
> Here is the normal output I usually see:
>
> Jun 28 11:14:29 localhost pulseaudio[6076]: W: [pulseaudio] sink.c:
> Default and alternate sample rates are the same.
> Jun 28 11:14:29 localhost pulseaudio[6076]: W: [pulseaudio]
> module-jack-sink.c: JACK error >Cannot use real-time scheduling
> (RR/15)(1: Operation not permitted)<
> Jun 28 11:14:29 localhost pulseaudio[6076]: W: [pulseaudio]
> module-jack-sink.c: JACK error >JackClient::AcquireSelfRealTime error<
> Jun 28 11:14:29 localhost pulseaudio[6076]: W: [pulseaudio] source.c:
> Default and alternate sample rates are the same.
> Jun 28 11:14:29 localhost pulseaudio[6076]: W: [pulseaudio]
> module-jack-source.c: JACK error >Cannot use real-time scheduling
> (RR/15)(1: Operation not permitted)<
> Jun 28 11:14:29 localhost pulseaudio[6076]: W: [pulseaudio]
> module-jack-source.c: JACK error >JackClient::AcquireSelfRealTime
> error<
> Jun 28 11:14:32 localhost pulseaudio[6076]: W: [pulseaudio] module.c:
> After module unload, module 'module-null-sink' was still loaded!
> Jun 28 11:14:37 localhost systemd[1621]: Starting Sound Service...
> Jun 28 11:14:37 localhost rtkit-daemon[1071]: Successfully made thread
> 6121 of process 6121 (/usr/bin/pulseaudio) owned by '1000' high
> priority at nice level -11.
> Jun 28 11:14:37 localhost rtkit-daemon[1071]: Supervising 1 threads of
> 1 processes of 1 users.
> Jun 28 11:14:40 localhost pulseaudio[6121]: W: [pulseaudio] sink.c:
> Default and alternate sample rates are the same.
> Jun 28 11:14:40 localhost pulseaudio[6121]: W: [pulseaudio]
> module-jack-sink.c: JACK error >Cannot use real-time scheduling
> (RR/15)(1: Operation not permitted)<
> Jun 28 11:14:40 localhost pulseaudio[6121]: W: [pulseaudio]
> module-jack-sink.c: JACK error >JackClient::AcquireSelfRealTime error<
> Jun 28 11:14:40 localhost pulseaudio[6121]: W: [pulseaudio] source.c:
> Default and alternate sample rates are the same.
> Jun 28 11:14:40 localhost pulseaudio[6121]: W: [pulseaudio]
> module-jack-source.c: JACK error >Cannot use real-time scheduling
> (RR/15)(1: Operation not permitted)<
> Jun 28 11:14:40 localhost pulseaudio[6121]: W: [pulseaudio]
> module-jack-source.c: JACK error >JackClient::AcquireSelfRealTime
> error<
> Jun 28 11:14:40 localhost systemd[1621]: Started Sound Service.
>
> Note that this is being done via module-jackdbus-detect and jackdbus

I ran a strace on the command and found the following output:

[pid 10183] recvmsg(30, {msg_name=NULL, msg_namelen=0,
msg_iov=[{iov_base="l\2\1\1\0\0\0\0002\3\0\0%\0\0\0\6\1s\0\6\0\0\0:1.266\0\0"...,
iov_len=2048}], msg_iovlen=1, msg_controllen=0,
msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 56
[pid 10183] recvmsg(30, {msg_namelen=0}, MSG_CMSG_CLOEXEC) = -1 EAGAIN
(Resource temporarily unavailable)
[pid 10183] close(30)                   = 0
[pid 10183] sched_setscheduler(10183, SCHED_FIFO, [15]) = -1 EPERM
(Operation not permitted)
[pid 10183] futex(0x5625cfbb26a8, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 10183] futex(0x7fae139fb000, FUTEX_WAIT, 0, {tv_sec=2147,
tv_nsec=483647000} <unfinished ...>
[pid 10177] <... futex resumed> )       = 0
[pid 10177] futex(0x5625cfbb2650, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 10177] prctl(PR_GET_NAME, "pulseaudio") = 0
[pid 10177] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid 10177] write(2, "W: [pulseaudio] module-jack-sink"..., 125W:
[pulseaudio] module-jack-sink.c: JACK error >Cannot use real-time
scheduling (RR/15)(1: Operation not permitted)<
) = 125
[pid 10177] ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
[pid 10177] write(2, "W: [pulseaudio] module-jack-sink"..., 95W:
[pulseaudio] module-jack-sink.c: JACK error
>JackClient::AcquireSelfRealTime error<
) = 95
[pid 10177] futex(0x5625cfbb26ac, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 10183] <... futex resumed> )       = 0
[pid 10183] futex(0x7fae139fb000, FUTEX_WAIT, 0, {tv_sec=2147,
tv_nsec=483647000} <unfinished ...>

I tried tweaking some things via the user level systemd unit files in
pulse and tweaking some cgroup settings but I get the same error every
time(settings have all been reverted back to defaults).