[OE-core] long (never ending?) do_install for adwaita-icon-theme
Richard Purdie
richard.purdie at linuxfoundation.org
Sun Aug 27 16:01:07 UTC 2017
On Wed, 2017-08-23 at 15:46 +0300, Alexander Kanavin wrote:
> On 08/22/2017 09:46 PM, Trevor Woerner wrote:
> >
> > >
> > > Do you have any kind of logs for when it happens?
> >
> > Unfortunately not, I'll try to keep some the next time it happens.
> >
> > But I have a suspicion it might be related to a build failure.
> > Earlier
> > today I was doing a build which failed in a recipe that wasn't
> > adwaita-icon-theme, nor related to it. When I checked on my build
> > later I could see the tail of the error message from the failed
> > recipe, but the overall build was still waiting for
> > adwaita-icon-theme's do_install to finish (hours after the
> > failure).
> >
> > Maybe adwaita-icon-theme's do_install would have succeeded if
> > everything had gone well? Maybe to reproduce, it might be necessary
> > to
> > time it such that another recipe fails while adwaita-icon-theme is
> > building?
> We can certainly revert my patch that speeds up the do_install(), but
> I
> would prefer not to do it blindly: it's much better to first firmly
> establish that the patch is indeed the reason for the never ending
> do_install (I can't imagine why, but it certainly could be). So
> please
> do try to get some logs, or a stable way to reproduce.
The autobuilder hung with this issue on the debian8 worker:
https://autobuilder.yocto.io/builders/nightly-rpm-non-rpm/builds/435
I was able to ssh in and take a look at what was going on. Basically
its hung in connecting to pseudo. I did a little debugging whilst it
was hung:
The process list is a long list of forked off copies of install-sh
which in turn call chmod and cp of which there are a ton of jammed
processes.
$ ps ax | grep "cp " | wc
272 1903 81859
$ ps ax | grep "chmod " | wc
99 692 22472
$ ps ax | grep "install-sh " | wc
508 5638 252481
$ grep 33196 /home/rpurdie/pslog33196 ? SN 0:00 chmod 644 /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/image/usr/share/icons/Adwaita//./32x32/status/_inst.29542_
$ strace -p 33196
Process 33196 attached
connect(22, {sa_family=AF_LOCAL, sun_path="pseudo.socket"}, 110
$ grep 29542 /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/pseudo/pseudo.log
[i.e. no match]
$ grep 33208 /home/rpurdie/pslog
33208 ? SN 0:00 chmod 644 /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/image/usr/share/icons/Adwaita//./32x32/mimetypes/_inst.29870_
$ strace -p 33208
Process 33208 attached
connect(22, {sa_family=AF_LOCAL, sun_path="pseudo.socket"}, 110
$ ps ax | grep pseudo
19251 ? S 0:00 /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/sysroots-components/x86_64/pseudo-native/usr/bin/pseudo bitbake-worker decafbadbeef
43675 ? Ss 0:13 /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/sysroots-components/x86_64/pseudo-native/usr/bin/pseudo -d
$ strace -p 43675
Process 43675 attached
read(1025,
$ ls -la /proc/43675/fd | grep socket | wc
486 5346 34471
$ ls -la /proc/43675/fd | grep -v socket
total 0
dr-x------ 2 pokybuild users 0 Aug 27 15:12 .
dr-xr-xr-x 9 pokybuild users 0 Aug 27 08:47 ..
lrwx------ 1 pokybuild users 64 Aug 27 15:12 0 -> /dev/null
lrwx------ 1 pokybuild users 64 Aug 27 15:12 1 -> /dev/null
l-wx------ 1 pokybuild users 64 Aug 27 15:12 2 -> /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/pseudo/pseudo.log
l-wx------ 1 pokybuild users 64 Aug 27 15:12 3 -> /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/pseudo/pseudo.log
lrwx------ 1 pokybuild users 64 Aug 27 15:12 4 -> /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/pseudo/pseudo.lock
lrwx------ 1 pokybuild users 64 Aug 27 15:12 6 -> /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/pseudo/logs.db
lrwx------ 1 pokybuild users 64 Aug 27 15:12 7 -> /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/pseudo/files.db
So it has 486 sockets connected and very little else open as fds.
$ ls -la /proc/43675/fd | grep 1025
lrwx------ 1 pokybuild users 64 Aug 27 15:12 1025 -> socket:[111861392]
$ ss -p | grep 1392
u_str ESTAB 0 0 pseudo.socket 111861392 * 111831542 users:(("pseudo",pid=43675,fd=1025))
u_str ESTAB 0 0 * 111831542 * 111861392 users:(("bash",pid=32133,fd=22))
$ strace -p 32133
Process 32133 attached
read(3,
$ ls -la /proc/32133/fd
total 0
dr-x------ 2 pokybuild users 0 Aug 27 15:15 .
dr-xr-xr-x 9 pokybuild users 0 Aug 27 08:51 ..
lr-x------ 1 pokybuild users 64 Aug 27 15:16 0 -> /dev/null
l-wx------ 1 pokybuild users 64 Aug 27 15:16 1 -> pipe:[111501676]
l-wx------ 1 pokybuild users 64 Aug 27 15:16 2 -> pipe:[111501676]
lr-x------ 1 pokybuild users 64 Aug 27 15:16 20 -> /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/sysroots-components/x86_64/pseudo-native/usr
lr-x------ 1 pokybuild users 64 Aug 27 15:16 21 -> /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/pseudo
lrwx------ 1 pokybuild users 64 Aug 27 15:16 22 -> socket:[111831542]
lr-x------ 1 pokybuild users 64 Aug 27 15:16 255 -> /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/adwaita-icon-theme-3.24.0/install-sh
lr-x------ 1 pokybuild users 64 Aug 27 15:16 3 -> pipe:[111853934]
$ ls -la /proc/*/fd/ | grep 111853934
leads to process 33197
$ ps ax | grep 33197
33197 ? SN 0:00 /bin/bash /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/adwaita-icon-theme-3.24.0/install-sh -c -m 644 ../../../adwaita-icon-theme-3.24.0/Adwaita//./32x32/actions/media-eject.png /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-rpm-non-rpm/build/build/tmp/work/all-poky-linux/adwaita-icon-theme/3.24.0-r0/image/usr/share/icons/Adwaita//./32x32/actions/media-eject.png
$ strace -p 33197
Process 33197 attached
connect(22, {sa_family=AF_LOCAL, sun_path="pseudo.socket"}, 110
I then decided I couldn't really get much more from this and ran strace
against the pseudo server whilst I killed 32133. This gave:
read(1025, "\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\205}\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 76) = 76
read(1025, "/bin/bash\0", 10) = 10
rt_sigaction(SIGPIPE, {0x40f420, [PIPE], SA_RESTORER|SA_RESTART, 0x7f2a17a18060}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f2a17a18060}, 8) = 0
write(1025, "\4\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\372\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 76) = 76
rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f2a17a18060}, {0x40f420, [PIPE], SA_RESTORER|SA_RESTART, 0x7f2a17a18060}, 8) = 0
accept(5, {sa_family=AF_LOCAL, NULL}, [2]) = 22
select(1026, [5 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 27 30 31 32 34 35 37 42 43 45 47 52 53 54 56 58 59 60 89 92 94 95 99 100 131 138 141 143 144 145 146 148 149 152 156 159 160 165 166 170 171 173 185 186 187 188 190 191 192 194 197 199 200 201 202 204 206 207 208 209 211 212 213 215 216 219 220 221 222 223 224 227 228 230 231 234 236 238 241 243 244 245 246 248 249 252 253 254 259 260 261 262 263 264 265 272 273 274 279 280 281 282 284 285 286 287 288 289 290 291 293 295 296 297 299 300 301 302 303 304 309 311 314 315 318 320 321 322 323 324 325 326 327 328 330 331 332 333 334 339 340 341 343 345 347 348 350 354 355 356 357 360 361 362 364 365 366 367 368 369 372 373 374 375 376 378 379 381 382 383 388 389 390 391 393 394 395 400 403 409 410 411 417 420 425 431 434 443 455 460 467 485 556 577 578 581 590 593 594 595 596 597 598 599 600 601 602 603 604 605 606 607 608 609 610 611 612 613 614 615 616 617 618 619 620 621 622 623 624 625 626 627 629 631 635 637 638 639 640 641 642 646 647 650 652 653 654 655 656 659 661 662 664 666 667 669 670 671 674 675 676 681 682 683 685 687 688 691 692 693 694 695 696 698 702 703 704 705 706 709 710 711 712 713 714 715 716 718 719 721 722 724 728 736 738 751 752 754 755 756 757 758 759 760 761 763 764 765 766 767 768 769 770 771 772 773 774 775 776 777 778 780 781 782 783 784 785 786 787 788 790 792 793 794 795 796 798 799 800 802 803 804 805 806 807 811 813 814 815 817 818 819 820 821 823 826 827 829 832 836 838 839 840 841 842 843 844 845 846 847 848 849 850 851 852 853 854 855 856 857 858 859 860 861 862 863 864 865 866 867 868 869 870 871 873 875 878 879 881 882 884 885 886 888 889 890 891 892 893 894 895 896 897 898 899 905 906 907 908 909 910 911 912 913 914 915 916 917 918 919 923 925 928 929 930 931 932 934 935 937 939 942 943 951 955 957 959 960 961 962 963 964 965 966 968 970 971 972 973 974 990 995 997 1005 1013 1017 1020 1022 1023 1025], [1], [5 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 27 30 31 32 34 35 37 42 43 45 47 52 53 54 56 58 59 60 89 92 94 95 99 100 131 138 141 143 144 145 146 148 149 152 156 159 160 165 166 170 171 173 185 186 187 188 190 191 192 194 197 199 200 201 202 204 206 207 208 209 211 212 213 215 216 219 220 221 222 223 224 227 228 230 231 234 236 238 241 243 244 245 246 248 249 252 253 254 259 260 261 262 263 264 265 272 273 274 279 280 281 282 284 285 286 287 288 289 290 291 293 295 296 297 299 300 301 302 303 304 309 311 314 315 318 320 321 322 323 324 325 326 327 328 330 331 332 333 334 339 340 341 343 345 347 348 350 354 355 356 357 360 361 362 364 365 366 367 368 369 372 373 374 375 376 378 379 381 382 383 388 389 390 391 393 394 395 400 403 409 410 411 417 420 425 431 434 443 455 460 467 485 556 577 578 581 590 593 594 595 596 597 598 599 600 601 602 603 604 605 606 607 608 609 610 611 612 613 614 615 616 617 618 619 620 621 622 623 624 625 626 627 629 631 635 637 638 639 640 641 642 646 647 650 652 653 654 655 656 659 661 662 664 666 667 669 670 671 674 675 676 681 682 683 685 687 688 691 692 693 694 695 696 698 702 703 704 705 706 709 710 711 712 713 714 715 716 718 719 721 722 724 728 736 738 751 752 754 755 756 757 758 759 760 761 763 764 765 766 767 768 769 770 771 772 773 774 775 776 777 778 780 781 782 783 784 785 786 787 788 790 792 793 794 795 796 798 799 800 802 803 804 805 806 807 811 813 814 815 817 818 819 820 821 823 826 827 829 832 836 838 839 840 841 842 843 844 845 846 847 848 849 850 851 852 853 854 855 856 857 858 859 860 861 862 863 864 865 866 867 868 869 870 871 873 875 878 879 881 882 884 885 886 888 889 890 891 892 893 894 895 896 897 898 899 905 906 907 908 909 910 911 912 913 914 915 916 917 918 919 923 925 928 929 930 931 932 934 935 937 939 942 943 951 955 957 959 960 961 962 963 964 965 966 968 970 971 972 973 974 990 995 997 1005 1013 1017 1020 1022 1023 1025], {2, 0}) = 31 (in [5 15 17 18 19 20 22 89 131 149 159 187 434 460 467 485 556 635 654 675 696 990 995 997 1013 1017 1020 1022 1023 1025], out [1], left {1, 999780})
read(15, "\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0;a\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 76) = 76
read(15, "cp\0", 3)
and it then closed the connection on 1025 shortly thereafter.
I was thinking it might have been stuck with a large pseudo request,
maybe bigger than page size but that doesn't seem to be the case.
seebs: Any idea why pseudo could end up blocking in a read()?
Cheers,
Richard
More information about the Openembedded-core
mailing list