14942 2022-10-20 16:12:45 +0000 externalsrc unusably slow on LARGE NON-git repos with many files due to self.file_checksum_values handling in get_taskhash 2023-02-15 09:18:53 +0000 1 1 7 Build System, Metadata & Runtime BitBake bitbake 4.3 x86 Multiple RESOLVED FIXED Medium normal 4.99 1 Martin.Jansa unassigned poky.bs.watcher poky.watcher randy.macleod --- --- No (bug/feature does not impact docs) oldest_to_newest 94222 0 Martin.Jansa 2022-10-20 16:12:45 +0000 With some big repo, like chromium, there is huge delay at the beginning of the build - 2 hours without any output from bitbake (other than "Bitbake still alive" messages which aren't shown without verbose), even with -DDDD it looks like this: DEBUG: virtual/libgles2 resolved to: mesa (langdale/oe-core/meta/recipes-graphics/mesa/mesa_22.2.0.bb) Bitbake still alive (no events for 600s). Active tasks: Bitbake still alive (no events for 1200s). Active tasks: Bitbake still alive (no events for 1800s). Active tasks: Bitbake still alive (no events for 2400s). Active tasks: Bitbake still alive (no events for 3000s). Active tasks: Bitbake still alive (no events for 3600s). Active tasks: Bitbake still alive (no events for 4200s). Active tasks: Bitbake still alive (no events for 4800s). Active tasks: Bitbake still alive (no events for 5400s). Active tasks: Bitbake still alive (no events for 6000s). Active tasks: DEBUG: Starting bitbake-worker The reason is that externalsrc.bclass adds: d.setVarFlag('do_compile', 'file-checksums', '${@srctree_hash_files(d)}') which in this cases contains 380227 paths. Since this commit: https://git.openembedded.org/bitbake/commit/?id=b4975d2ecf615ac4c240808fbc5a3f879a93846b the get_taskhash() function spends 6448s in the loop and the data variable is 39.241.360 characters long after that. 94225 1 Martin.Jansa 2022-10-20 23:12:09 +0000 The bitbake change made it worse (it was stuck for only ~ 1000 seconds) after reverting it, but the real cause was not using git write-tree after: https://git.openembedded.org/openembedded-core/commit/?id=95fbac8dcad6c93f4c9737e9fe13e92ab6befa09 Patch sent for review: https://patchwork.yoctoproject.org/project/oe-core/patch/20221020230351.2712106-1-Martin.Jansa@gmail.com/ https://lists.openembedded.org/g/openembedded-core/message/172007 94248 2 richard.purdie 2022-10-27 13:45:56 +0000 https://git.yoctoproject.org/poky/commit/?id=9ba58ee035fa23957492dc93863f0e163cf66bfe merged so the issue is now only there for non-git externalsrc trees? 94253 3 Martin.Jansa 2022-10-27 13:59:18 +0000 > so the issue is now only there for non-git externalsrc trees? Yes, I believe so. I don't know how many people could be using externalsrc with such huge non-git trees, but some progress indication from bitbake in such case would be good start (to see if some people report that it's slow for them). I've tried to optimize this loop a bit (I was surprised that it takes that long), but haven't found anything significant enough - I can share .json dump of these file-checksums from chromium and a test script I was using to benchmark it, if someone wants to follow-up on that. 94926 4 Martin.Jansa 2023-02-14 12:23:18 +0000 Small improvement merged in: https://lists.openembedded.org/g/bitbake-devel/message/14364 but I'm testing much faster proposal where my simple test case went down from 512s to 0.7s which should be enough to cover even huge repos. 94928 5 Martin.Jansa 2023-02-15 09:18:53 +0000 > I'm testing much faster proposal where my simple test case went down from 512s to 0.7s which should be enough to cover even huge repos. This won't be really needed, the improvement from Etienne is good enough my testing was affected by python3 3.11 regression (https://github.com/python/cpython/issues/99862 and my test script was using global variable) More details in: https://stackoverflow.com/questions/75313204/correct-way-to-append-to-string-in-python For externalsrc test I was measuring get_taskhash() time and do_compile get_taskhash() went down from 1539.22s to 0.09s with Etienne's change and 0.12s with additional change to use temporary array with extend()/append() and join() at the end. Additional 4s were spent in get_checksums() for 2.4G repo and 43s for 40G repo (with warm disk cache and cache/local_file_checksum_cache.dat removed between runs), so the lack of output between "Initialising tasks..." and "done." isn't too bad now. Both changes as well as the debug script for timing are available in: https://git.openembedded.org/bitbake-contrib/log/?h=jansa/2.0-siggen The fix from Etienne (already queued for backport to 2.2 and 2.0) is good enough for externalsrc, closing this ticket. TL;DR; # Tested with rather big directory in EXTERNALSRC: # $ find src | wc -l # 139261 # $ du -hs src # 1.5G src # with even bigger directory: # $ find | wc -l # 854949 # $ du -hs . # 41G . # I didn't have enough patience as the current bitbake-2.0 didn't finish in 16 hours current bitbake-2.0: Initialising tasks... WARNING: get_taskhash[externalsrc_1.0.bb:do_deploy_source_date_epoch] took 1.1920928955078125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_lic] took 1.1920928955078125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 1.8835067749023438e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_unpack] took 1.9073486328125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 4.601478576660156e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_configure] took 3.0994415283203125e-06 seconds Bitbake still alive (no events for 600s). Active tasks: Bitbake still alive (no events for 1200s). Active tasks: Bitbake still alive (no events for 1800s). Active tasks: WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 1539.2191841602325 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 7.62939453125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_configure_manifest] took 4.76837158203125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 6.4849853515625e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_sysroot] took 4.76837158203125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_packagedata] took 3.814697265625e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 3.457069396972656e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 8.106231689453125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 1.049041748046875e-05 seconds done. Sstate summary: Wanted 107 Local 107 Mirrors 0 Missed 0 Current 843 (100% match, 100% complete) bitbake-2.0 with backported https://git.openembedded.org/bitbake/commit/?id=195750f2ca355e29d51219c58ecb2c1d83692717: Initialising tasks... WARNING: get_taskhash[externalsrc_1.0.bb:do_deploy_source_date_epoch] took 1.1920928955078125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 2.3126602172851562e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_lic] took 1.430511474609375e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_unpack] took 2.86102294921875e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 3.933906555175781e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_configure] took 3.5762786865234375e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 0.09659457206726074 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 6.9141387939453125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_configure_manifest] took 2.6226043701171875e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_sysroot] took 3.814697265625e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 5.6743621826171875e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_packagedata] took 2.86102294921875e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 7.3909759521484375e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 2.765655517578125e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 8.821487426757812e-06 seconds done. Sstate summary: Wanted 107 Local 107 Mirrors 0 Missed 0 Current 843 (100% match, 100% complete) bitbake-2.0 with extend+join Initialising tasks... WARNING: get_taskhash[externalsrc_1.0.bb:do_deploy_source_date_epoch] took 1.6689300537109375e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_lic] took 1.1920928955078125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 8.106231689453125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_unpack] took 1.6689300537109375e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 4.0531158447265625e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_configure] took 4.291534423828125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 0.12246251106262207 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 1.5020370483398438e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_configure_manifest] took 3.0994415283203125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_sysroot] took 3.814697265625e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 6.270408630371094e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_packagedata] took 2.86102294921875e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 6.9141387939453125e-06 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 2.86102294921875e-05 seconds WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 9.775161743164062e-06 seconds done. Sstate summary: Wanted 107 Local 107 Mirrors 0 Missed 0 Current 843 (100% match, 100% complete) I've run it again in reversed order (printing only tasks with get_taskhash times >= 0.01 ms) do_compile get_taskhash 1537328.01 -> 118.51 -> 93.15 ms bitbake-2.0 with extend+join: WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.02 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.04 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 93.15 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.06 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.03 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms bitbake-2.0 with backported https://git.openembedded.org/bitbake/commit/?id=195750f2ca355e29d51219c58ecb2c1d83692717: WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.05 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 118.51 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.02 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.06 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.03 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms current bitbake-2.0: WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.02 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.04 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 1537328.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.05 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.03 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms with whole 40G repo (running only with backport and with extend+join), but this time the much longer time was spent in calculating those checksums (when cache was removed between runs): 138M cache/local_file_checksum_cache.dat with 40G repo (also shows 6 warnings due to broken symlinks like: WARNING: Unable to get checksum for externalsrc SRC_URI entry securegcm: [Errno 2] No such file or directory: '/OE/.../chromium/src/third_party/nearby/src/third_party/ukey2/include/securegcm') chromium/src/third_party/nearby/src/third_party/ukey2/include/securegcm -> ../ukey2/src/main/cpp/include/securegcm WARNING: get_checksums[externalsrc] took 43443.56 ms instead of: WARNING: get_checksums[externalsrc] took 4206.65 ms with 2.4G repo with: 22M cache/local_file_checksum_cache.dat bitbake-2.0 with backported https://git.openembedded.org/bitbake/commit/?id=195750f2ca355e29d51219c58ecb2c1d83692717: WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.02 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.04 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 680.98 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.06 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.03 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms bitbake-2.0 with extend+join: WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.04 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 794.98 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.05 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.04 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms