ServerCommunicator.runCommand() in lib/bb/server/process.py (https://github.com/openembedded/bitbake/blob/62be9113d98fccb347c6aa0a10d5c4ee2857f8b6/lib/bb/server/process.py#L476) enforces a hardcoded 30s + 30s reply timeout. On large image builds the server can legitimately be busy longer than 60s inside a single GIL-holding operation, so an otherwise-healthy build is sporadically aborted with: ``` NOTE: No reply from server in 30s (for command ping at ...) Timeout while waiting for a reply from the bitbake server (60s at ...) ``` There is currently no way to raise this threshold, not via a variable and not via a command-line option. I would like to propose making it configurable via an environment variable (e.g. `BB_COMMAND_TIMEOUT`), keeping the current 30s/60s as the default. Note that `BB_SERVER_TIMEOUT` does not help here: it only controls how long the resident server stays alive when idle, which is unrelated to the command reply poll. Affected code (still present on master, bitbake 2.19.1): ```python # lib/bb/server/process.py class ServerCommunicator(): def runCommand(self, command): ... if not self.recv.poll(30): logger.info("No reply from server in 30s (for command %s at %s)" % (command[0], currenttime())) if not self.recv.poll(30): raise ProcessTimeout( "Timeout while waiting for a reply from the bitbake " "server (60s at %s)" % currenttime()) ``` Why the server exceeds 60s ========================== I traced this to the runqueue's per-task dispatch. Live py-spy stack of the server process at the moment the UI reported "No reply", captured on bitbake 2.8.0 / Python 3.12.10. The idle thread was in state "active+gil" and was still in the same frame 10 seconds later: ``` Thread (active+gil): "Thread-1 (idle_thread)" __getnewargs__ (collections/__init__.py:476) send_pickled_data (bb/runqueue.py:1359) # pickle.dumps(data) execute (bb/runqueue.py:2403) # send_pickled_data(w, runtask, "runtask") _execute_runqueue (bb/runqueue.py:1620) execute_runqueue (bb/runqueue.py:1654) buildTargetsIdle (bb/cooker.py:1488) idle_thread_internal (bb/server/process.py:435) Thread (idle): "MainThread" idle_commands (bb/server/process.py:505) # cannot reply: GIL is held ``` Probable mechanism: - `execute()` builds a per-task runtask dict containing 'taskdepdata': `self.build_taskdepdata(task)`. - `build_taskdepdata()` walks the task's entire transitive dependency closure and returns `{tid: bb.TaskData(...)}`. `bb.TaskData` is a namedtuple, so pickling each entry calls `__getnewargs__`, matching the captured frame. - For late image tasks (`do_image_complete`, `do_rootfs`, `do_flush_pseudodb`, `do_image_ext4/cpio`) that closure is effectively the whole build (thousands of tasks). `pickle.dumps()` of that structure runs for tens of seconds on the server's idle thread while holding the GIL, starving the MainThread that answers the ping. The `build_taskdepdata_cache` optimisation (commit c4519b542) helps building the dict, but the full taskdepdata is still pickled per task on the GIL thread, unchanged on master (runqueue.py:2405 / 2422). Observed impact =============== Intermittent CI failures on a large Yocto image build (~7900 tasks), roughly 30-45% of builds, always in the final image-assembly phase, and reproducible across different build machines. The machine is otherwise idle at the stall: no I/O pressure, no memory pressure, no OOM, and no process in D state. That is consistent with a pure CPU/GIL stall in userspace Python rather than any resource exhaustion. Precedent ========= This class of failure has been addressed twice before by raising the hardcoded literal: - 131d4b8a5 (2017) "server/process: Increase runCommand timeout", 5s -> 30s: "We were seeing cases where we could hit the 5s timeout on large/fast machines running many different tasks at once." [YOCTO #12116] - e567743e7 (2020) "server/process: Increase timeout for commands", added the second 30s poll: "We're running into this timeout on loaded autobuilders in situations where things should otherwise succeed." This is the third occurrence of the same pattern as builds continue to grow. Rather than bumping the constant a third time, I suggest making it tunable. Proposed change =============== Make the poll interval configurable, defaulting to the current 30s so existing behaviour is unchanged: ```python class ServerCommunicator(): def __init__(self, connection, recv): self.connection = connection self.recv = recv try: self.timeout = float(os.environ.get("BB_COMMAND_TIMEOUT", 30)) except ValueError: logger.warning("Ignoring invalid BB_COMMAND_TIMEOUT, using 30s") self.timeout = 30 def runCommand(self, command): ... if not self.recv.poll(self.timeout): logger.info("No reply from server in %ss (for command %s at %s)" % (self.timeout, command[0], currenttime())) if not self.recv.poll(self.timeout): raise ProcessTimeout( "Timeout while waiting for a reply from the bitbake " "server (%ss at %s)" % (2 * self.timeout, currenttime())) ``` Let me know what you think. I could, probably, submit a patch as well.
Please don't send such a patch. The issue is likely to be too much over the IPC rather than the timeout and that should be fixed instead. 8000 tasks is normal and shouldn't be an issue and our systems run this regularly. Is this machine heavily resource constrained.
Hi, I have to be honest, I have no idea what IPC is. The machines are not resource constrained, they are virtual machines with 16 CPU (1 thread per core) / 32 GB RAM (32GB swap), otherwise idle during the failures. We are also running the yocto build on k9s pods where disk swap isn't available, so I am applying these settings in CI for all builds: ``` # Deriving Yocto parallelism: available_cpus=16, available_memory_gib=31.30, gib_per_thread=3.00, memory_threads=10 -> BB_NUMBER_THREADS=10, PARALLEL_MAKE=-j 10 # Use conservative no-swap Kubernetes parallelism capped by both the cgroup-aware CPU count # and the available memory (roughly 3.0 GiB per BitBake thread). BB_NUMBER_THREADS:forcevariable = "10" PARALLEL_MAKE:forcevariable = "-j 10" # Dynamically throttle BitBake task scheduling when Linux memory PSI pressure is high. BB_PRESSURE_MAX_MEMORY = "50000" ``` At the moment of "No reply from server": - PSI cpu/io/memory "full" ~0% (no stall or queueing) - No processes in D state (no I/O block) - No OOM (cgroup memory.events oom=0), GBs of RAM free - Reproduces on multiple different hosts, with cache on and off, and at two different BB_NUMBER_THREADS/PARALLEL_MAKE settings - The stall lands on different tasks between runs (do_flush_pseudodb, do_image_complete, do_rootfs, do_packagedata, ...), i.e. not always one slow task So, as much as I can tell, it isn't disk, memory pressure or host contention since the machine is pretty much idle while the server goes quiet. attaching py-spy to the live bitbake-server at the exact "No reply" moment (and again 10s later) shows the idle_thread in the same frame both times, holding the GIL: ```python __getnewargs__ (collections/__init__.py:476) send_pickled_data (bb/runqueue.py:1359) # pickle.dumps(data) execute (bb/runqueue.py:2403) # send_pickled_data(worker, runtask, "runtask") buildTargetsIdle (bb/cooker.py:1488) ``` That's what led me to point at the per-task taskdepdata pickle. I don't have visibility into how large that taskdepdata payload is for our image, so we may well be hitting a scaling edge on that side. If there's a specific thing you'd like me to measure or instrument to better diagnose this issue, let me know. A colleague applied a patch to the bitbake code, increasing the timeout to 120s and we're not seeing issues so far, but we may as well just be covering up the symptoms instead of actually fixing the root cause.
The 120s is almost certainly masking some other issue. I'd have a look at the size of the data being transferred by send_pickled_data(), maybe log that somewhere. IPC is "Inter Process Communication", i.e. how bitbake communicates between it's workers, the server (cooker) and the UI (knotty) which are all separate processes. My suspicion is there is a large chunk of data unintentionally being transferred between them and this is what is taking up the time, if you profile shows it in this function.
Created attachment 5250 [details] Instrumented bitbake server patch for timeout diagnosis I (and when I say "I", I mean my AI companion) instrumented send_pickled_data() to time the pickle and the pipe write separately, and also profiled the taskdepdata entries individually when the payload is large. I am building this image: https://github.com/nxp-auto/meta-grayvip/blob/release/GrayVIP-1.0.6.4/recipes-fsl/images/fsl-image-grayvip.bb Well, an internal unreleased version, not the exact one from the url. We're on poky scarthgap (BB 2.8.0, Python 3.12). There are ~7900 tasks, 10 consecutive builds on the same code/image. The data size is normal, but pickle.dumps() non-deterministically degenerates on it. The runtask payload for late image tasks (do_rootfs, do_image_*, do_flush_pseudodb) is ~6.6 MiB with ~7800-7900 taskdepdata entries. The pipe write is consistently fast (0.01-0.02s). The pickle is where all the time goes: Build Result Stalling task entries pickle_time ----- ------ ------------------- ------- ------------------- 37 FAIL do_image_cpio 7840 146.37s 38 PASS (none) 7826 max 0.98s 39 FAIL do_flush_pseudodb 7827 136.04s 40 PASS (none) 7826 max 2.28s 44 FAIL do_image_tar 7830 154.08s 45 PASS (none) 7826 max 0.27s 46 PASS (none) 7826 max 0.33s 47 FAIL do_image_qa 7828 >120s (killed) 48 PASS (none) 7826 max 1.21s 49 PASS (none) 7826 max 0.80s Builds 47 shows '>120s (killed)' because the 60s heartbeat timeout terminated the server before pickle.dumps() returned. The build_taskdepdata log (emitted before the pickle call) appeared ~2 minutes before the kill. Also seems like different tasks hit the pickle stall each time, it's not consistently halting in one place. When pickling each taskdepdata entry separately, the sum is ~0.6-0.9s for all ~7800 entries, with the slowest single entry at 0.015s. But pickling the same entries as a single dict takes 2-146s (or hangs). From build 48 (passing): - Pickle 7826 entries one by one: 0.46s total - Pickle the same entries as one dict: 1.21s From build 39 (failing): - Pickle 7826 entries one by one: 0.93s total - Pickle the same entries as one dict: 136.04s
Hi, What's the full list of layers you have included in the build? For public layers could you share the specific commits used? I wonder if this is reproducible without third party BSP layers. If you take just poky and try `bitbake core-image-full-cmdline core-image-sato core-image-weston`, that should exercise the same do_image* tasks a few times. You could collect the pickle time for that and see if it significantly different. There are a couple of possible causes for the stall - either something on your build infrastructure or something in the layers you're using. Trying to reproduce with just the core layers would help to determine which is the likely culprit.
Set to NEEDINFO state so we don't loose track of this issue.
You're not gonna make this easy on me are you :))? The layer list: BBLAYERS ?= " \ {yocto_workspace_dir}/sources/poky/meta \ {yocto_workspace_dir}/sources/poky/meta-poky \ {yocto_workspace_dir}/sources/poky/meta-yocto-bsp \ {yocto_workspace_dir}/sources/meta-openembedded/meta-oe \ {yocto_workspace_dir}/sources/meta-openembedded/meta-multimedia \ {yocto_workspace_dir}/sources/meta-openembedded/meta-python \ {yocto_workspace_dir}/sources/meta-openembedded/meta-networking \ {yocto_workspace_dir}/sources/meta-openembedded/meta-gnome \ {yocto_workspace_dir}/sources/meta-openembedded/meta-filesystems \ {yocto_workspace_dir}/sources/meta-openembedded/meta-webserver \ {yocto_workspace_dir}/sources/meta-openembedded/meta-perl \ {yocto_workspace_dir}/sources/meta-openembedded/meta-xfce \ {yocto_workspace_dir}/sources/meta-virtualization \ {yocto_workspace_dir}/sources/meta-security \ {yocto_workspace_dir}/sources/meta-freescale \ {yocto_workspace_dir}/sources/meta-rust-bin \ {yocto_workspace_dir}/sources/meta-alb/meta-alb-bsp \ {yocto_workspace_dir}/sources/meta-alb/meta-alb-sdk \ {yocto_workspace_dir}/sources/meta-alb-dev \ {yocto_workspace_dir}/sources/meta-alb-url-proxy \ {yocto_workspace_dir}/sources/meta-aws \ {yocto_workspace_dir}/sources/meta-vip \ {yocto_workspace_dir}/sources/meta-grayvip \ {yocto_workspace_dir}/sources/meta-grayvip-dev \ {yocto_workspace_dir}/sources/meta-eiqa \ {yocto_workspace_dir}/sources/meta-carv \ {yocto_workspace_dir}/sources/meta-alb/hw-partitions/hw-partition-1.2/meta-alb-hw-partition-1.2.1 \ " The public layers: Layer Remote Revision ----- ----- -------- poky (scarthgap) git.yoctoproject.org 077627338ac18aeca34bfe0c52777fab38e2e0c0 meta-openembedded git.openembedded.org e621da947048842109db1b4fd3917a02e0501aa2 meta-freescale git.yoctoproject.org 62423c69631d7f7cffe2bd20997412d76caa94ef meta-security git.yoctoproject.org bc865c5276c2ab4031229916e8d7c20148dfbac3 meta-virtualization git.yoctoproject.org af1db2042caf8021d767dce1b26c08b59b96f3d1 meta-rust-bin github.com/rust-embedded 63d677de912551b8f5606ce459748532c6ae529d meta-qoriq github.com/nxp-qoriq 533e78f92774326d48f15adb5982a516fe114ee7 meta-aws (upstream: scarthgap) git.yoctoproject.org d82f0cdbda398d3fbab92318ced32c37b6c1d0d4 Reran 10 builds with a minimal config, as you suggested (`bitbake core-image-full-cmdline core-image-sato core-image-weston`): BBLAYERS ?= " \ {yocto_workspace_dir}/sources/poky/meta \ {yocto_workspace_dir}/sources/poky/meta-poky \ {yocto_workspace_dir}/sources/poky/meta-yocto-bsp \ " This is how it looks like: Build Host Max pickle_time Task Entries Size ----- ----------- --------------- ---------------------- ------- ------- 1 Host 1 55.978s do_create_runtime_spdx 2848 2.11 MiB 2 Host 2 8.288s do_package 2763 1.67 MiB 3 Host 3 47.200s do_write_qemuboot_conf 5141 4.28 MiB 4 Host 2 25.588s do_packagedata 2764 1.67 MiB 5 Host 1 50.977s do_package_write_rpm 3030 1.97 MiB 6 Host 4 9.121s do_rootfs 7935 6.82 MiB 7 Host 3 54.986s do_image 5144 4.28 MiB 8 Host 1 49.595s do_image 5144 4.28 MiB 9 Host 4 9.568s do_package_write_rpm 3129 2.09 MiB 10 Host 2 23.789s do_package 2715 1.65 MiB Some of them are pretty close to the 60s timeout threshold. Should I try anything else, send some of my collected data or what's the next step?
That is good data! Being that close to the 60s timeout with only the core layers is unexpected. With more layers and more to pickle it's no surprise that it is pushed over the timeout. So I don't think there is likely to be a specific issue in the other layers you're using. What's interesting is that the max pickle duration doesn't correlate with the size of the data being pickled. The remaining possibilities: - Poor/inconsistent pickle performance in oe-core/bitbake - Issue in your infrastructure causing stalls Could you share the instrumentation code you used to create that table?
Check the attachment of this bug, there is a patch called "Instrumented bitbake server patch for timeout diagnosis" Or check comment No. 4 https://bugzilla.yoctoproject.org/show_bug.cgi?id=16429#c4
Hi, I applied the instrumentation patch to poky (scarthgap commit 104772c5fd0653290cbb5e4b77813343957939cc) and ran `bitbake core-image-base core-image-full-cmdline core-image-weston core-image-sato` to generate lots of samples. Looking at the resulting bitbake-send-pickled-data.csv file, and sorting by pickle time (4th column), the maximum value I see is around 185 ms to pickle 168 kB for zstd:do_populate_sysroot. Only the top 4 entries took longer than 100 ms. The largest amount of data (6.76 MB for core-image-sato:do_populate_lic_deploy) took around 18ms. I suspect the issue here is your build environment. Do you have a non-kubernetes environment you can test in?
OK, thanks for testing. I was actually hitting this issue on static virtual machines, not in kubernetes. I will try to test in a different environment and see how it goes.