For a while now, I've noticed Portage hanging when unpacking GCC: ``` portage 1495795 2.6 1.5 1178528 1014644 pts/27 SNl+ 22:31 0:04 | | \_ xz -T32 -d -c -- /var/tmp/portage/cross-aarch64_be-unknown-linux-gnu/gcc-14.0.1_pre20240218/distdir/gcc-14-20240218.tar.xz portage 1495796 83.5 0.0 8400 3376 pts/27 RN+ 22:31 2:11 | | \_ tar xof - ``` It often takes several minutes. Running things manually: ``` (no pipes) # time xz -T32 -d -c /var/tmp/portage/cross-aarch64_be-unknown-linux-gnu/gcc-14.0.1_pre20240218/distdir/gcc-14-20240218.tar.xz > /var/tmp/portage/test real 0m3.926s user 0m2.937s sys 0m3.603s # time tar xof /var/tmp/portage/test > /var/tmp/portage/test2 real 0m10.285s user 0m0.357s sys 0m8.036s ``` ``` (pipe) /var/tmp/portage # time xz -T32 -d -c -- /var/tmp/portage/cross-aarch64_be-unknown-linux-gnu/gcc-14.0.1_pre20240218/distdir/gcc-14-20240218.tar.xz | tar xof - real 0m7.706s user 0m3.364s sys 0m7.865s ``` Then finally: ``` (pipe + sandbox) /var/tmp/portage # time xz -T32 -d -c -- /var/tmp/portage/cross-aarch64_be-unknown-linux-gnu/gcc-14.0.1_pre20240218/distdir/gcc-14-20240218.tar.xz | tar xof - real 0m25.906s user 0m5.380s sys 0m23.741s ``` Running perf (perf record --call-graph dwarf -g -- sandbox 'xz -T32 -d -c -- /var/tmp/portage/cross-aarch64_be-unknown-linux-gnu/gcc-14.0.1_pre20240218/distdir/gcc-14-20240218.tar.xz | tar xof -'), the third entry in the profile is: ``` 47.03% 0.22% tar libsandbox.so [.] before_syscall.localalias --46.81%--before_syscall.localalias | |--12.71%--free.localalias [...] |--11.95%--realpath | | | |--10.94%--readlink | | | | | |--10.17%--entry_SYSCALL_64_after_hwframe | | | | | | | --10.04%--do_syscall_64 | | | | | | | --9.66%--__x64_sys_readlink | | | | | | | --9.55%--do_readlinkat | | | | | | | --9.13%--user_path_at_empty | | | | | | | |--6.44%--filename_lookup | | | | | | | | | --6.22%--path_lookupat [...] |--11.81%--__xmalloc | | | --11.80%--malloc.localalias | | | |--6.74%--__mmap | | | | | --6.14%--entry_SYSCALL_64_after_hwframe | | | | | --6.09%--do_syscall_64 | | | | | --5.91%--vm_mmap_pgoff | | | | | --5.61%--do_mmap | | | | | --5.33%--mmap_region [...] --9.20%--canonicalize_filename_mode.localalias | |--6.04%--fstatat64 | | | --5.63%--entry_SYSCALL_64_after_hwframe | | | --5.57%--do_syscall_64 | | | --5.35%--__do_sys_newfstatat | | | --5.04%--vfs_fstatat | | | |--3.67%--vfs_statx [...] ```
With /var/tmp/portage on zram (w/ zstd), I get: ``` $ hyperfine "sandbox 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -" 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -' hyperfine \ "sandbox 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -'" \ 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -' Benchmark 1: sandbox 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -' Time (mean ± σ): 36.998 s ± 23.093 s [User: 5.517 s, System: 33.107 s] Range (min … max): 27.402 s … 102.629 s 10 runs Warning: The first benchmarking run for this command was significantly slower than the rest (102.629 s). This could be caused by (filesystem) caches that were not filled until after the first run. You should consider using the '--warmup' option to fill those caches before the actual benchmark. Alternatively, use the '--prepare' option to clear the caches before each timing run. Benchmark 2: xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof - Time (mean ± σ): 9.193 s ± 1.781 s [User: 3.641 s, System: 9.261 s] Range (min … max): 8.366 s … 14.213 s 10 runs Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet system without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options. Summary xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof - ran 4.02 ± 2.63 times faster than sandbox 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -' ``` The first run was much slower, which is consistent with what I've seen in-the-wild, presumably because of caches (I could use the hyperfine options for it blah blah but I don't really think it would demonstrate anything here).
While I appreciate that some slowdown is kind of unavoidable for what sandbox does, it feels like a huge waste and for the overhead to be ~2-4x (in reality, it's really 4, given nobody is unpacking and then unpacking repeatedly, and it seems to consistently be around that for me on cold runs) to be excessive.
Created attachment 885479 [details] emerge --info
I think I might be hitting two distinct issues here, actually. 1. sandbox adds some not-insignificant amount of time to tar extraction 2. ext4 on zram tmpfs has some sort of pathological inode allocation problem? When the profile is good, the hot paths are all in liblzma, as you'd expect. When it's bad, it's in tar in ext4's find_inode_bit/find_get_block/ext4_create/ext4_new_inode. If I change the zram tmpfs to xfs, things become way happier, the peak is way lower, but I also can't reproduce the serious spikes either. So, I think we might be able to put 2. down to a kernel bug? But for 1., it's still there, just less significant than before: ``` # hyperfine "sandbox 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -'" 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -' Benchmark 1: sandbox 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -' Time (mean ± σ): 12.101 s ± 1.613 s [User: 4.886 s, System: 9.578 s] Range (min … max): 7.578 s … 13.040 s 10 runs Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet system without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options. Benchmark 2: xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof - Time (mean ± σ): 4.271 s ± 0.095 s [User: 3.430 s, System: 3.210 s] Range (min … max): 4.158 s … 4.514 s 10 runs Summary xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof - ran 2.83 ± 0.38 times faster than sandbox 'xz -T32 -d -c -- /var/cache/distfiles/gcc-14-20240218.tar.xz | tar xof -' ``` 2x is still a pretty big differnce, but there's not this huge range of several minutes anymore.
Also, the profile w/ the xfs zram tmpfs is way more like you'd expect - some in the kernel, but a healthy mix of liblzma + tar + sandbox in tar.
