[BUG] Host-side binder service threads busy-loop at 100% CPU and flood the log when the binder node cannot be opened
Describe the bug
Whenever open() on the binder device fails, every host-side binder service thread that waydroid runs spins without any delay, pegging one CPU core per thread and writing thousands of log lines per second for as long as the process lives.
The services are started in tools/services/{hardware,user,clipboard,notification}_manager.py; all four have the same loop:
def service_thread():
while not stopping:
IHardware.add_service(args, ...)IHardware.add_service() (and the other tools/interfaces/I*.py) opens the binder device through gbinder.ServiceManager(...). If the device cannot be opened, add_presence_handler() returns a falsy value, add_service() logs Failed to add presence handler: None and returns immediately, and the loop calls it again straight away. There is no back-off anywhere, so the failure mode is a tight loop.
Each iteration also produces two log lines: [gbinder] ERROR: Can't open /dev/anbox-binder: ... from libgbinder and Failed to add presence handler: None from waydroid.
This affects:
waydroid container start(the root daemon):hardware_manager→ 1 runaway thread.waydroid session start(the user session):user_managerandnotification_manager→ 2 runaway threads (3 withclipboard_managerifpyclipis installed).
Any condition that makes the binder node un-openable triggers it. Recent example: Arch Linux linux 7.2.3.arch1-3 (rust-bindgen regression, #2411) makes open() on /dev/anbox-binder fail with ESRCH. Older examples with the same symptom are #1661 and #1165. In all of them the visible outcome is "waydroid does not start", but the hidden outcome is that the two waydroid processes stay alive and burn CPU until they are killed.
Impact observed on my machine
I started a session on the affected Arch kernel at 23:16 and did not notice anything until the desktop became sluggish the next afternoon:
waydroid container start (root) |
waydroid session (user) |
|
|---|---|---|
| runaway threads | 1 | 2 |
| CPU time accumulated after ~16 h | 51 303 s (14.3 h) | 49 519 s (13.8 h) |
| per-thread CPU while running | ~90 % of a core | ~43 % of a core each |
- ~1 600 log lines per second into journald: 97 507 lines in a random 60 s window, 4 million lines in the 4 h the journal still had (
journalctl --disk-usagereached 3.9 G, everything older than 4 h had already been rotated out). /var/lib/waydroid/waydroid.logreceived 14.5 GiB (write_bytesof the container process) of the same two lines.systemd-journalditself sat at 4 % CPU handling the stream.- The laptop CPU stayed thermally throttled (package temperature 106 °C,
Package temperature is above threshold, cpu clock is throttledin dmesg all day).
Reproduction without a broken kernel
The same code path can be reproduced on any machine by pointing the services at a non-existent binder node, which fails at open() exactly like the broken node does (ENOENT instead of ESRCH). I used a small harness that monkey-patches tools.helpers.drivers.loadBinderNodes to set args.BINDER_DRIVER = "waydroid-bench-nonexistent-binder", starts hardware_manager and user_manager, and measures process CPU time for 5 s:
tree: /usr/lib/waydroid (1.6.3, unmodified)
threads: 2 (hardware_manager, user_manager)
wall: 5.0 s
process CPU: 5.93 s (119% of one core)
python log recs: 192791 (38557.6/s)
stop latency: 2 msbench_service_loop.py)#!/usr/bin/env python3
"""Reproduce the waydroid service-thread busy loop without touching the kernel.
Points the binder services at a device node that does not exist, so
gbinder fails to open it exactly like it does when the real node is broken,
then measures how much CPU the service threads burn and how fast they stop.
usage: bench_service_loop.py <path-to-waydroid-tree> [--seconds N]
"""
import argparse
import logging
import os
import sys
import tempfile
import threading
import time
ap = argparse.ArgumentParser()
ap.add_argument("tree")
ap.add_argument("--seconds", type=float, default=10)
ap.add_argument("--report", default="/dev/stdout", help="where to write the summary")
opts = ap.parse_args()
sys.path.insert(0, opts.tree)
sys.dont_write_bytecode = True
import tools.helpers.drivers as drivers # noqa: E402
def fake_load_binder_nodes(args):
args.BINDER_DRIVER = "waydroid-bench-nonexistent-binder"
args.VNDBINDER_DRIVER = args.BINDER_DRIVER
args.HWBINDER_DRIVER = args.BINDER_DRIVER
args.BINDER_PROTOCOL = "aidl3"
args.SERVICE_MANAGER_PROTOCOL = "aidl3"
drivers.loadBinderNodes = fake_load_binder_nodes
from tools.services import hardware_manager, user_manager # noqa: E402
class CountingHandler(logging.Handler):
def __init__(self):
super().__init__()
self.count = 0
def emit(self, record):
self.count += 1
counter = CountingHandler()
logging.getLogger().addHandler(counter)
logging.getLogger().setLevel(logging.ERROR)
args = argparse.Namespace()
root = tempfile.mkdtemp(prefix="waydroid-bench-")
session = {key: os.path.join(root, key) for key in
("xdg_data_home", "waydroid_user_state", "waydroid_data")}
for d in session.values():
os.makedirs(d, exist_ok=True)
try:
hardware_manager.start(args)
user_manager.start(args, session, None)
except Exception:
import traceback
traceback.print_exc(file=sys.stdout)
sys.stdout.flush()
os._exit(1)
threads = [args.hardware_manager, args.user_manager]
t0 = time.monotonic()
c0 = time.process_time()
time.sleep(opts.seconds)
wall = time.monotonic() - t0
cpu = time.process_time() - c0
records = counter.count
t_stop = time.monotonic()
hardware_manager.stop(args)
user_manager.stop(args)
for t in threads:
t.join(timeout=30)
stop_ms = (time.monotonic() - t_stop) * 1000
alive = [t.is_alive() for t in threads]
with open(opts.report, "a") as report:
report.write(f"tree: {opts.tree}\n")
report.write(f"threads: {len(threads)} (hardware_manager, user_manager)\n")
report.write(f"wall: {wall:.1f} s\n")
report.write(f"process CPU: {cpu:.2f} s ({cpu / wall * 100:.0f}% of one core)\n")
report.write(f"python log recs: {records} ({records / wall:.1f}/s)\n")
report.write(f"stop latency: {stop_ms:.0f} ms\n")
report.write(f"threads alive: {alive}\n")
sys.stdout.flush()
# libgbinder logs through C stdio on stdout; flush it so line counts are exact
import ctypes
ctypes.CDLL(None).fflush(None)
os._exit(0)Expected behaviour
If the binder node cannot be opened, the service threads should wait a few seconds before trying again, and stopping the session/container should still be immediate. I have a patch for this (interruptible back-off via threading.Event, one retry every few seconds, add_service() reporting failure to its caller) and will open a PR referencing this issue.
Waydroid version
1.6.3
Device
Linux Desktop
Operating System
Arch Linux (x86_64)
Kernel version
7.2.3-arch1-3 (the binder open failure itself is the rust-bindgen regression from #2411; the busy loop reported here is independent of it and reproduces on any kernel, see above)
Desktop Environment
KDE Plasma 6.7.4 (Wayland)
GPU
Intel Arc Graphics (Meteor Lake-P)
Logs
/var/lib/waydroid/waydroid.log had grown to 14.5 GiB and consisted solely of the two lines below repeated, so I truncated it instead of attaching it. Representative excerpt from journalctl -b _PID=<container pid>:
waydroid[704]: [gbinder] ERROR: Can't open /dev/anbox-binder: No such process
waydroid[704]: [15:15:30] Failed to add presence handler: None
waydroid[704]: [gbinder] ERROR: Can't open /dev/anbox-binder: No such process
waydroid[704]: [15:15:30] Failed to add presence handler: None
...Line counts of Can't open /dev/anbox-binder from the container process alone, per hour, from journalctl -b: 11:xx (partial) 439 979 · 12:xx 912 718 · 13:xx 918 352 · 14:xx 1 035 616 · 15:xx (until killed) 485 671.
waydroid status while this was happening:
Session: RUNNING
Container: STOPPED
Vendor type: MAINLINE
IP address: UNKNOWN
Session user: nancunchild(1000)
Wayland display: wayland-0Other files from the template (waydroid.cfg, waydroid.prop, waydroid_base.prop, logcat, dmesg) are not relevant to this loop; happy to attach them on request.
Source: waydroid/waydroid