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

Discussion:

dag dg

2018-06-21 14:58:40 UTC

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

[***@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
[***@localhost ~]$ prlimit --rtprio=70 --rttime=unlimited echo

[***@localhost ~]$ echo $?
0
[***@localhost ~]$ prlimit --rtprio=71 --rttime=unlimited echo
prlimit: failed to set the RTPRIO resource limit: Operation not permitted
[***@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.

Tanu Kaskinen

2018-06-27 07:19:02 UTC

Permalink

Post by dag dg
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
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)<
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-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
# Default limits for users of jack-audio-connection-kit
@jackuser - rtprio 70
@jackuser - memlock 4194304
@pulse-rt - rtprio 20
@pulse-rt - nice -20
0
prlimit: failed to set the RTPRIO resource limit: Operation not permitted
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

dag dg

2018-06-28 16:25:54 UTC

Permalink

Post by Tanu Kaskinen

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
# Default limits for users of jack-audio-connection-kit
@jackuser - rtprio 70
@jackuser - memlock 4194304
@pulse-rt - rtprio 20
@pulse-rt - nice -20
0
prlimit: failed to set the RTPRIO resource limit: Operation not permitted
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.

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

dag dg

2018-06-28 19:59:16 UTC

Permalink

Post by dag dg

Post by Tanu Kaskinen

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
# Default limits for users of jack-audio-connection-kit
@jackuser - rtprio 70
@jackuser - memlock 4194304
@pulse-rt - rtprio 20
@pulse-rt - nice -20
0
prlimit: failed to set the RTPRIO resource limit: Operation not permitted
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.

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

Post by dag dg
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).

Tanu Kaskinen

2018-07-04 09:09:50 UTC

Permalink

Post by dag dg
Changing the rlimit-rtprio doesn't cause it to change the priority it
attempts to run as,

Yes, but it changes the allowed priority limit of the process. The
default limit is 9, so that would explain why libjack can't set the
priority to 15.

However, you showed that libjack can't set the priority to even 1, so
the rlimit-rtprio doesn't seem to be the problem (assuming that you
didn't change rlimit-rtprio to 0 when testing).

I don't know what the problem might be, since in your first email the
verbose log showed that pulseaudio itself was able to set a realtime
priority of 9. Maybe it was because pulseaudio is using rtkit and
libjack is calling the kernel directly? There's probably some way of
checking what the real rlimits are for a running process (probably some
file under /proc).

--
Tanu

https://liberapay.com/tanuk
https://www.patreon.com/tanuk

dag dg

2018-07-05 17:45:42 UTC

Permalink

Thanks Tanu.

I ran strace and dug through looking for relevant errors or warnings
and found the following:

19914 openat(AT_FDCWD,
"/usr/share/locale/en_US.utf8/LC_MESSAGES/pulseaudio.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
19914 openat(AT_FDCWD,
"/usr/share/locale/en_US/LC_MESSAGES/pulseaudio.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
19914 openat(AT_FDCWD,
"/usr/share/locale/en.utf8/LC_MESSAGES/pulseaudio.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
19914 openat(AT_FDCWD,
"/usr/share/locale/en/LC_MESSAGES/pulseaudio.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
19914 futex(0x7fff7b7142a4, FUTEX_UNLOCK_PI) = -1 EPERM (Operation not
permitted)
19914 openat(AT_FDCWD, "/dev/urandom", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 6
19914 fcntl(6, F_GETFD) = 0x1 (flags FD_CLOEXEC)
19914 read(6, "\260\374\227f", 4) = 4
19914 close(6) = 0

19919 mprotect(0x7f9acc000000, 135168, PROT_READ|PROT_WRITE) = 0
19919 sendto(22, "\1\0\0\0\0\0\0\0", 8, MSG_NOSIGNAL, NULL, 0) = -1
ENOTSOCK (Socket operation on non-socket)
19919 write(22, "\1\0\0\0\0\0\0\0", 8) = 8
19918 <... ppoll resumed> ) = 1 ([{fd=22, revents=POLLIN}])
19919 sched_setscheduler(19919, 0x40000002 /* SCHED_??? */, [9] <unfinished ...>
19918 read(22, <unfinished ...>
19919 <... sched_setscheduler resumed> ) = 0
19918 <... read resumed> "\1\0\0\0\0\0\0\0", 8) = 8
19919 sched_setscheduler(19919, SCHED_FIFO, [15] <unfinished ...>
19918 ppoll([{fd=22, events=POLLIN}, {fd=18, events=POLLIN}, {fd=19,
events=POLLIN}], 3, NULL, NULL, 8 <unfinished ...>
19919 <... sched_setscheduler resumed> ) = -1 EPERM (Operation not permitted)
19919 futex(0x55a3a6754948, FUTEX_WAKE_PRIVATE, 1) = 1
19916 <... futex resumed> ) = 0
19919 futex(0x7f9af893e000, FUTEX_WAIT, 0, {tv_sec=2147,
tv_nsec=483647000} <unfinished ...>
19916 futex(0x55a3a67548f0, FUTEX_WAKE_PRIVATE, 1) = 0
19916 mmap(NULL, 134217728, PROT_NONE,
MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f9ac4000000
19916 munmap(0x7f9ac8000000, 67108864) = 0

19921 prctl(PR_SET_NAME, "jack-source" <unfinished ...>
19914 mprotect(0x7f9ade062000, 524288, PROT_READ|PROT_WRITE <unfinished ...>
19921 <... prctl resumed> ) = 0
19914 <... mprotect resumed> ) = 0
19914 clone( <unfinished ...>
19921 sched_setscheduler(19921, 0x40000002 /* SCHED_??? */, [5]) = 0
19914 <... clone resumed> child_stack=0x7f9ade0e0d70,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
pare
nt_tidptr=0x7f9ade0e19d0, tls=0x7f9ade0e1700,
child_tidptr=0x7f9ade0e19d0) = 19922
19922 set_robust_list(0x7f9ade0e19e0, 24 <unfinished ...>
19914 nanosleep({tv_sec=0, tv_nsec=1000000}, <unfinished ...>
19922 <... set_robust_list resumed> ) = 0
19921 ppoll([{fd=35, events=POLLIN}, {fd=31, events=POLLIN}, {fd=32,
events=POLLIN}], 3, NULL, NULL, 8 <unfinished ...>
19922 sched_setscheduler(19922, 0x40000002 /* SCHED_??? */, [9]) = 0
19922 sched_setscheduler(19922, SCHED_FIFO, [15]) = -1 EPERM
(Operation not permitted)
19922 mmap(NULL, 134217728, PROT_NONE,
MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f9abc000000
19922 munmap(0x7f9ac0000000, 67108864) = 0
19922 mprotect(0x7f9abc000000, 135168, PROT_READ|PROT_WRITE) = 0
19922 futex(0x55a3a675494c, FUTEX_WAKE_PRIVATE, 1) = 1
19916 <... futex resumed> ) = 0
19922 futex(0x7f9af893d000, FUTEX_WAIT, 0, {tv_sec=2147,
tv_nsec=483647000} <unfinished ...>
19916 futex(0x55a3a67548f0, FUTEX_WAKE_PRIVATE, 1) = 0
19916 ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
19916 write(2, "W: [pulseaudio] module-jack-sour"..., 127) = 127
19916 ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
19916 write(2, "W: [pulseaudio] module-jack-sour"..., 97) = 97
19916 futex(0x55a3a6754948, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
19914 <... nanosleep resumed> NULL) = 0

Earlier I had noticed an error when it was trying to set RLIMIT_NICE
during startup:

prlimit64(0, RLIMIT_NOFILE, {rlim_cur=256, rlim_max=256}, NULL) = 0
prlimit64(0, RLIMIT_NICE, {rlim_cur=31, rlim_max=31}, NULL) = -1 EPERM
(Operation not permitted)
openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2997, ...}) = 0
read(3, "# Locale name alias data base.\n#"..., 4096) = 2997
read(3, "", 4096) = 0
close(3) = 0
openat(AT_FDCWD, "/usr/share/locale/en_US.utf8/LC_MESSAGES/libc.mo",
O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en_US/LC_MESSAGES/libc.mo",
O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en.utf8/LC_MESSAGES/libc.mo",
O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/libc.mo", O_RDONLY)
= -1 ENOENT (No such file or directory)
prlimit64(0, RLIMIT_RTPRIO, {rlim_cur=9, rlim_max=9}, NULL) = 0
prlimit64(0, RLIMIT_RTTIME, {rlim_cur=200000, rlim_max=200000}, NULL) = 0

I double checked my /etc/security/limits.d/95-jack.conf had an entry
for the @jackuser and @pulse-rt groups which my user was a member of
both. As soon as I removed myself from pulse-rt things began to work
as expected regarding the RLIMIT-NICE

19914 prlimit64(0, RLIMIT_NOFILE, {rlim_cur=256, rlim_max=256}, NULL) = 0
19914 prlimit64(0, RLIMIT_NICE, {rlim_cur=31, rlim_max=31}, NULL) = 0
19914 prlimit64(0, RLIMIT_RTPRIO, {rlim_cur=9, rlim_max=9}, NULL) = 0
19914 prlimit64(0, RLIMIT_RTTIME, {rlim_cur=200000, rlim_max=200000}, NULL) = 0

But the other errors still persist. I'm not sure if it's a scheduler
permission issue or if I'm missing a dependency somewhere.

Post by Tanu Kaskinen

Post by dag dg
Changing the rlimit-rtprio doesn't cause it to change the priority it
attempts to run as,

Yes, but it changes the allowed priority limit of the process. The
default limit is 9, so that would explain why libjack can't set the
priority to 15.
However, you showed that libjack can't set the priority to even 1, so
the rlimit-rtprio doesn't seem to be the problem (assuming that you
didn't change rlimit-rtprio to 0 when testing).
I don't know what the problem might be, since in your first email the
verbose log showed that pulseaudio itself was able to set a realtime
priority of 9. Maybe it was because pulseaudio is using rtkit and
libjack is calling the kernel directly? There's probably some way of
checking what the real rlimits are for a running process (probably some
file under /proc).
--
Tanu
https://liberapay.com/tanuk
https://www.patreon.com/tanuk
_______________________________________________
pulseaudio-discuss mailing list
https://lists.freedesktop.org/mailman/listinfo/pulseaudio-discuss