Open Bug 1561960 Opened 5 years ago Updated 2 years ago

Debug-build terminal-spew: "ERROR [timestamp]: audio_thread_priority::rt_linux: Could not make thread real-time.

Categories

(Core :: Audio/Video, defect, P2)

Product:
Core
Component:
Audio/Video
Type:
defect

Tracking

()

Status:
REOPENED

People

(Reporter: dholbert, Unassigned)

References

(Regression)

Details

(Keywords: regression)

Starting a few days ago, I've been seeing lots of spam like this to my terminal from my Nightly firefox installation:

ERROR 2019-06-27T16:51:36Z: audio_thread_priority::rt_linux: Could not make thread real-time.
ERROR 2019-06-27T16:51:37Z: audio_thread_priority::rt_linux: Could not make thread real-time.
ERROR 2019-06-27T16:51:37Z: audioipc_client: Could not promote audio threads to real-time during initialization.
ERROR 2019-06-27T16:51:37Z: audio_thread_priority::rt_linux: Could not make thread real-time.
ERROR 2019-06-27T16:51:37Z: audioipc_client: Could not promote audio threads to real-time during initialization.

This happens with a fresh profile. I'm on 64-bit Ubuntu 19.04 linux. My STR:

mkdir /tmp/foo; firefox -no-remote -profile /tmp/foo about:blank

This spams 21 lines of errors like those quoted above, before the Firefox window even shows up.

I'm guessing this might be related to bug 1560720 based on the mention of audio_thread_priority and the timeline matching up (I've only been noticing this issue for a few days)...

See Also: → 1561681

Though, hmm, the logspew seems to have gone away in latest Nightly!

i.e. this nightly is good again:
https://ftp.mozilla.org/pub/firefox/nightly/2019/06/2019-06-27-09-36-36-mozilla-central/firefox-69.0a1.en-US.linux-x86_64.tar.bz2

I'm assuming this was due to the log-level change that :achronop flagged as related. So this is probably a dupe of that bug (i.e. fixed by that bug).

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → DUPLICATE

Yes, this is fixed. However, I'm a bit surprised that it does not work on your machine, on a recent Ubuntu. Are you not running rtkit ?

ps -ef | grep rtkit

should show something.

Flags: needinfo?(dholbert)

Also:

ps -eo rtprio,ni,pri,comm -T | grep AudioIPC

Should show something in the rtprio column (the first one). If it does not work, there should be a dash (-).

ps -ef | grep rtkit turns up:

rtkit     1706     1  0 Jun21 ?        00:00:03 /usr/libexec/rtkit-daemon

And the AudioIPC command turns up:

$ ps -eo rtprio,ni,pri,comm -T | grep AudioIPC
     -   0  19 AudioIPC Callba
     -   0  19 AudioIPC Callba
     -   0  19 AudioIPC Server
     -   0  19 AudioIPC Server
    10   -  50 AudioIPC Callba
     -   0  19 AudioIPC Callba
     -   0  19 AudioIPC Server
     -   0  19 AudioIPC Server
     -   0  19 AudioIPC Client
     -   0  19 AudioIPC0
     -   0  19 AudioIPC1
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
     -   0  19 AudioIPC Client
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
     -   0  19 AudioIPC Client
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
     -   0  19 AudioIPC Client
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
     -   0  19 AudioIPC Client
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
     -   0  19 AudioIPC Client
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
     -   0  19 AudioIPC Client
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
    10   -  50 AudioIPC0
    10   -  50 AudioIPC1
     -   0  19 AudioIPC Callba
     -   0  19 AudioIPC Callba
     -   0  19 AudioIPC Server
     -   0  19 AudioIPC Server
     -   0  19 AudioIPC0
     -   0  19 AudioIPC1
     -   0  19 AudioIPC0
     -   0  19 AudioIPC1
     -   0  19 AudioIPC0
     -   0  19 AudioIPC1
     -   0  19 AudioIPC0
     -   0  19 AudioIPC1
     -   0  19 AudioIPC0
     -   0  19 AudioIPC1
     -   0  19 AudioIPC0
    10   -  50 AudioIPC1

Also, note that our test runners (almost certainly on older Ubuntu) were hitting this as well -- see e.g. bug 1561680.

Flags: needinfo?(dholbert)

Ok this looks good then: some of the AudioIPC threads have an RT priority, I've removed the spew, and will investigate why we still see failures. It's probably because of the number of processes we run, but that's something we'll fix soon.

Thanks!

Thanks for taking a look. BTW, I do still see this terminalspew in debug builds (and it's early on -- it's the 12th line of output that I see).

Here's what it looks like there:

$ ./mach run --temp-profile
 0:00.25 /scratch/work/builds/mozilla-central/obj/dist/bin/firefox -no-remote -profile /scratch/work/builds/mozilla-central/obj/tmp/profile-m1I5Cb
[8899, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /scratch/work/builds/mozilla-central/mozilla/extensions/permissions/nsPermissionManager.cpp, line 2903
1561665523884	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: mozillaAddons
1561665523887	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: telemetry
1561665523891	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: resource://pdf.js/
1561665523893	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: about:reader*
[8899, GMPThread] WARNING: Failed to delete GMP storage directory: file /scratch/work/builds/mozilla-central/mozilla/dom/media/gmp/GMPServiceParent.cpp, line 1571
[8899, Main Thread] WARNING: 'mIndex >= Count()', file /scratch/work/builds/mozilla-central/mozilla/xpcom/ds/nsStringEnumerator.cpp, line 202
[8899, Main Thread] WARNING: Attempting to get a displayport from a content with no primary frame!: file /scratch/work/builds/mozilla-central/mozilla/layout/base/nsLayoutUtils.cpp, line 848
[Parent 8899, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /scratch/work/builds/mozilla-central/mozilla/layout/base/nsCSSFrameConstructor.cpp, line 8679
Couldn't convert chrome URL: chrome://branding/locale/brand.properties
 WARN 2019-06-27T19:58:52Z: audio_thread_priority::rt_linux: Could not make thread real-time.
 WARN 2019-06-27T19:58:52Z: audioipc_client: Could not promote audio threads to real-time during initialization.
 WARN 2019-06-27T19:58:52Z: audio_thread_priority::rt_linux: Could not make thread real-time.
 WARN 2019-06-27T19:58:52Z: audioipc_client: Could not promote audio threads to real-time during initialization.
[Child 8964, Main Thread] WARNING: No active window: file /scratch/work/builds/mozilla-central/mozilla/js/xpconnect/src/XPCJSContext.cpp, line 662
[Parent 8899, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /scratch/work/builds/mozilla-central/mozilla/netwerk/cache/nsCacheService.cpp, line 169
Couldn't convert chrome URL: chrome://branding/locale/brand.properties
 WARN 2019-06-27T19:58:55Z: audio_thread_priority::rt_linux: Could not make thread real-time.
 WARN 2019-06-27T19:58:55Z: audioipc_client: Could not promote audio threads to real-time during initialization.
 WARN 2019-06-27T19:58:55Z: audio_thread_priority::rt_linux: Could not make thread real-time.
 WARN 2019-06-27T19:58:55Z: audioipc_client: Could not promote audio threads to real-time during initialization.

Given comment 8, maybe I'll un-dupe and leave this open (since the noise is still there, it's just debug-only now).

Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---
Summary: Nightly terminal-spew: "ERROR [timestamp]: audio_thread_priority::rt_linux: Could not make thread real-time. → Debug-build terminal-spew: "ERROR [timestamp]: audio_thread_priority::rt_linux: Could not make thread real-time.

Maybe I need to use info! and not warn! in rust if we want this to be silent. Weird, though.

Priority: -- → P2
Has Regression Range: --- → yes
Severity: normal normal → S3 S3
You need to log in before you can comment on or make changes to this bug.