9929 2016-07-13 18:43:34 +0000 pseudo 1.8.1: potential performance regression 2017-12-06 17:03:04 +0000 1 1 6 Yocto Project Subprojects Pseudo pseudo unspecified x86 Multiple RESOLVED FIXED High normal 2.2 M3 9858 9857 1 patrick.ohly joshuagloe jose.perez.carranza mark.hatle randy.macleod seebs sgw yp.pseudo.watcher yp.watcher --- --- No (bug/feature does not impact docs) oldest_to_newest 63939 0 patrick.ohly 2016-07-13 18:43:34 +0000 I am trying to get Ostro OS working with latest OE-core master. The latest attempt finally managed to avoid compile errors, but got stuck for >12 hours in meta-swupd do_image: https://ostroproject.org/jenkins/job/build_edison/2210/console 01:07:01.313 NOTE: recipe ostro-image-swupd-1.0-r0: task do_image: Started 02:28:34.546 NOTE: recipe bundle-ostro-image-swupd-qa-bundle-a-1.0-r0: task do_copy_bundle_contents: Succeeded 02:39:17.033 NOTE: recipe bundle-ostro-image-swupd-world-dev-1.0-r0: task do_copy_bundle_contents: Succeeded 02:48:38.112 NOTE: recipe bundle-ostro-image-swupd-qa-bundle-b-1.0-r0: task do_copy_bundle_contents: Succeeded 11:24:23.795 NOTE: recipe ostro-image-swupd-1.0-r0: task do_image: Succeeded What happens here is basically copying a 1.9GB rootfs with a pair of two tar commands in meta-swupd. That was in our CI system. Olev Kartau did some analysis there and noticed >28k/s memset() calls inside pseudo. I've now reproduced that branch locally. My current state: 0: bundle-ostro-image-swupd-world-dev-1.0-r0 do_image_complete (pid 8854) 1: ostro-image-swupd-1.0-r0 do_rootfs (pid 27298) 2: bundle-ostro-image-swupd-qa-bundle-a-1.0-r0 do_copy_bundle_contents (pid 27299) 3: bundle-ostro-image-swupd-qa-bundle-b-1.0-r0 do_copy_bundle_contents (pid 27300) pseudo takes 100% CPU time in userspace: top - 11:33:32 up 60 days, 18:52, 3 users, load average: 0.96, 0.86, 1.53 Tasks: 275 total, 2 running, 273 sleeping, 0 stopped, 0 zombie %Cpu(s): 6.1 us, 0.2 sy, 0.0 ni, 93.4 id, 0.3 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem: 67114720 total, 64790088 used, 2324636 free, 1662060 buffers KiB Swap: 16777212 total, 82312 used, 16694900 free. 60554816 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3564 pohly 20 0 173388 165676 2240 R 98.013 0.247 104:17.36 pseudo 27887 pohly 20 0 13332 3488 2400 S 0.993 0.005 0:01.10 du 517 pohly 20 0 1668028 300344 7576 S 0.331 0.448 1:24.68 python3 28421 pohly 20 0 15456 2776 2168 R 0.331 0.004 0:00.05 top 1 root 20 0 32948 4788 3296 S 0.000 0.007 7:13.05 systemd strace on pseudo: 0.000049 write(17, "\4\0\0\0\27\0\0\0\1\0\0\0\0\0\0\0\v\0\0\0\f\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000049 write(17, "_", 1) = 1 0.000058 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000040 gettimeofday({1468434878, 344245}, NULL) = 0 0.000032 gettimeofday({1468434878, 344277}, NULL) = 0 0.000031 read(19, "\3\0\0\0\30\0\0\0\0\0\0\0\0\0\0\0\"l\0\0\n\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000039 read(19, "/data2/yocto/build/ostro/intel-c"..., 180) = 180 0.000055 rt_sigaction(SIGPIPE, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000042 write(19, "\4\0\0\0\30\0\0\0\1\0\0\0\0\0\0\0\r\0\0\0\n\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000042 write(19, "security.SMACK64\0security.ima\0", 30) = 30 0.000083 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000044 gettimeofday({1468434878, 344618}, NULL) = 0 0.000038 gettimeofday({1468434878, 344651}, NULL) = 0 0.000031 read(20, "\6\0\0\0\32\0\0\0\0\0\0\0\0\0\0\0\32l\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000042 read(20, "/data2/yocto/build/ostro/intel-c"..., 206) = 206 0.001016 gettimeofday({1468434878, 345746}, NULL) = 0 0.000040 select(22, [4 7 8 9 10 11 12 13 14 15 17 18 19 20 21], [], [4 7 8 9 10 11 12 13 14 15 17 18 19 20 21], {2, 0}) = 6 (in [11 14 17 19 20 21], left {1, 999995}) 0.000055 gettimeofday({1468434878, 345835}, NULL) = 0 0.000033 read(11, "\6\0\0\0\25\0\0\0\0\0\0\0\0\0\0\0;k\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000039 read(11, "/data2/yocto/build/ostro/intel-c"..., 151) = 151 0.267144 gettimeofday({1468434878, 613082}, NULL) = 0 0.000077 gettimeofday({1468434878, 613129}, NULL) = 0 0.000033 read(14, "\3\0\0\0\20\0\0\0\0\0\0\0\0\0\0\0\357l\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000051 read(14, "/data2/yocto/build/ostro/intel-c"..., 188) = 188 0.000077 rt_sigaction(SIGPIPE, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000050 write(14, "\4\0\0\0\20\0\0\0\1\0\0\0\0\0\0\0\10\0\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000133 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000039 gettimeofday({1468434878, 613512}, NULL) = 0 0.000035 gettimeofday({1468434878, 613550}, NULL) = 0 0.000035 read(17, "\3\0\0\0\27\0\0\0\0\0\0\0\0\0\0\0\31l\0\0\f\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000045 read(17, "/data2/yocto/build/ostro/intel-c"..., 211) = 211 0.000067 rt_sigaction(SIGPIPE, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000041 write(17, "\4\0\0\0\27\0\0\0\1\0\0\0\0\0\0\0\v\0\0\0\f\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000049 write(17, "\3\2\2Rbec\0\200O\254\224\t\317G\224\10\22\356b\35\213\323\264'\336\232\374\205\353\6\334"..., 137) = 137 0.000104 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000039 gettimeofday({1468434878, 613926}, NULL) = 0 0.000032 gettimeofday({1468434878, 613959}, NULL) = 0 0.000033 read(19, "\3\0\0\0\27\0\0\0\0\0\0\0\0\0\0\0\"l\0\0\n\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000047 read(19, "/data2/yocto/build/ostro/intel-c"..., 197) = 197 0.000060 rt_sigaction(SIGPIPE, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000046 write(19, "\4\0\0\0\27\0\0\0\1\0\0\0\0\0\0\0\r\0\0\0\n\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000048 write(19, "_", 1) = 1 0.000064 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000037 gettimeofday({1468434878, 614294}, NULL) = 0 0.000034 gettimeofday({1468434878, 614327}, NULL) = 0 0.000031 read(20, "\6\0\0\0\32\0\0\0\0\0\0\0\0\0\0\0\32l\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000046 read(20, "/data2/yocto/build/ostro/intel-c"..., 338) = 338 0.001033 gettimeofday({1468434878, 615443}, NULL) = 0 0.000039 gettimeofday({1468434878, 615477}, NULL) = 0 0.000034 read(21, "\6\0\0\0\32\0\0\0\0\0\0\0\0\0\0\0#l\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000042 read(21, "/data2/yocto/build/ostro/intel-c"..., 207) = 207 0.001009 gettimeofday({1468434878, 616567}, NULL) = 0 0.000040 select(22, [4 7 8 9 10 11 12 13 14 15 17 18 19 20 21], [], [4 7 8 9 10 11 12 13 14 15 17 18 19 20 21], {2, 0}) = 6 (in [11 14 17 19 20 21], left {1, 999990}) 0.000062 gettimeofday({1468434878, 616663}, NULL) = 0 0.000031 read(11, "\3\0\0\0\24\0\0\0\0\0\0\0\0\0\0\0;k\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000045 read(11, "/data2/yocto/build/ostro/intel-c"..., 148) = 148 0.000985 rt_sigaction(SIGPIPE, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000042 write(11, "\4\0\0\0\24\0\0\0\1\0\0\0\0\0\0\0\5\0\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000225 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000037 gettimeofday({1468434878, 618029}, NULL) = 0 0.000034 gettimeofday({1468434878, 618062}, NULL) = 0 0.000031 read(14, "\3\0\0\0\20\0\0\0\0\0\0\0\0\0\0\0\357l\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000039 read(14, "/data2/yocto/build/ostro/intel-c"..., 199) = 199 0.000053 rt_sigaction(SIGPIPE, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000039 write(14, "\4\0\0\0\20\0\0\0\1\0\0\0\0\0\0\0\10\0\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000067 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000037 gettimeofday({1468434878, 618329}, NULL) = 0 0.000032 gettimeofday({1468434878, 618360}, NULL) = 0 0.000032 read(17, "\3\0\0\0\n\0\0\0\0\0\0\0\0\0\0\0\31l\0\0\f\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000038 read(17, "/data2/yocto/build/ostro/intel-c"..., 198) = 198 0.000049 rt_sigaction(SIGPIPE, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000040 write(17, "\4\0\0\0\n\0\0\0\1\0\0\0\0\0\0\0\v\0\0\0\f\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000079 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000037 gettimeofday({1468434878, 618635}, NULL) = 0 0.000031 gettimeofday({1468434878, 618669}, NULL) = 0 0.000034 read(19, "\3\0\0\0\27\0\0\0\0\0\0\0\0\0\0\0\"l\0\0\n\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000041 read(19, "/data2/yocto/build/ostro/intel-c"..., 193) = 193 0.000054 rt_sigaction(SIGPIPE, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000042 write(19, "\4\0\0\0\27\0\0\0\1\0\0\0\0\0\0\0\r\0\0\0\n\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000043 write(19, "\3\2\2Rbec\0\200f\255\210\343<\254\356\\\256$p\355T\301~\262{=\262TO4D"..., 137) = 137 0.000062 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000037 gettimeofday({1468434878, 618979}, NULL) = 0 0.000032 gettimeofday({1468434878, 619011}, NULL) = 0 0.000030 read(20, "\3\0\0\0\n\0\0\0\0\0\0\0\0\0\0\0\32l\0\0\4\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000041 read(20, "/data2/yocto/build/ostro/intel-c"..., 187) = 187 0.000050 rt_sigaction(SIGPIPE, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000043 write(20, "\4\0\0\0\n\0\0\0\1\0\0\0\0\0\0\0\16\0\0\0\4\0\0\0\5\312\0\0\0\0\0\0"..., 76) = 76 0.000188 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, {0x40dc00, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6af4b9120}, 8) = 0 0.000038 gettimeofday({1468434878, 619402}, NULL) = 0 0.000032 gettimeofday({1468434878, 619433}, NULL) = 0 0.000032 read(21, "\6\0\0\0\32\0\0\0\0\0\0\0\0\0\0\0#l\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000052 read(21, "/data2/yocto/build/ostro/intel-c"..., 339) = 339 0.001001 gettimeofday({1468434878, 620533}, NULL) = 0 0.000050 select(22, [4 7 8 9 10 11 12 13 14 15 17 18 19 20 21], [], [4 7 8 9 10 11 12 13 14 15 17 18 19 20 21], {2, 0}) = 5 (in [11 14 17 20 21], left {1, 999996}) 0.000064 gettimeofday({1468434878, 620633}, NULL) = 0 0.000034 read(11, "\6\0\0\0\25\0\0\0\0\0\0\0\0\0\0\0;k\0\0\377\377\377\377\5\312\0\0\0\0\0\0"..., 76) = 76 0.000040 read(11, "/data2/yocto/build/ostro/intel-c"..., 148) = 148 Note the long delays after several of the second read() calls. The memset() calls seem to happen inside sqlite: (gdb) b memset Breakpoint 1 at 0x7fc6af508c70 (gdb) c Continuing. Breakpoint 1, 0x00007fc6af508c70 in memset () from /lib64/libc.so.6 (gdb) where #0 0x00007fc6af508c70 in memset () from /lib64/libc.so.6 #1 0x00000000004365c0 in createAggContext.isra.393 () #2 0x0000000000436665 in countStep () #3 0x00000000004774d2 in sqlite3VdbeExec () #4 0x000000000047e051 in sqlite3_step () #5 0x000000000040f533 in pdb_clear_unused_xattrs () at pseudo_db.c:1484 #6 0x0000000000411836 in pdb_did_unlink_file ( path=path@entry=0x1ca46bc "/data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/work/intel_corei7_64-ostro-linux/ostro-image-swupd/1.0-r0/ostro-image-swupd-1.0/copy/original/56/15", deleting=27451) at pseudo_db.c:1885 #7 0x0000000000407aa3 in pseudo_op (msg=0x1ca4670, program=0x32645b0 "rm", tag=0x47490e0 "", response_path=0x7fff9ab97778, response_len=0x7fff9ab977a0) at pseudo.c:933 #8 0x00000000004087d1 in pseudo_server_response (msg=msg@entry=0x1ca4670, program=<optimized out>, tag=<optimized out>, response_path=response_path@entry=0x7fff9ab97778, response_len=response_len@entry=0x7fff9ab977a0) at pseudo.c:1053 #9 0x000000000040935f in serve_client (i=5) at pseudo_server.c:499 #10 pseudo_server_loop () at pseudo_server.c:645 #11 pseudo_server_start (daemonize=<optimized out>) at pseudo_server.c:365 #12 0x0000000000406489 in main (argc=2, argv=0x7fff9ab98d48) at pseudo.c:431 (gdb) c Continuing. Breakpoint 1, 0x00007fc6af508c70 in memset () from /lib64/libc.so.6 (gdb) where #0 0x00007fc6af508c70 in memset () from /lib64/libc.so.6 #1 0x00000000004365c0 in createAggContext.isra.393 () #2 0x0000000000436665 in countStep () #3 0x00000000004774d2 in sqlite3VdbeExec () #4 0x000000000047e051 in sqlite3_step () #5 0x000000000040f533 in pdb_clear_unused_xattrs () at pseudo_db.c:1484 #6 0x0000000000411836 in pdb_did_unlink_file ( path=path@entry=0x1ca46bc "/data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/work/intel_corei7_64-ostro-linux/ostro-image-swupd/1.0-r0/ostro-image-swupd-1.0/copy/original/56/15", deleting=27451) at pseudo_db.c:1885 #7 0x0000000000407aa3 in pseudo_op (msg=0x1ca4670, program=0x32645b0 "rm", tag=0x47490e0 "", response_path=0x7fff9ab97778, response_len=0x7fff9ab977a0) at pseudo.c:933 #8 0x00000000004087d1 in pseudo_server_response (msg=msg@entry=0x1ca4670, program=<optimized out>, tag=<optimized out>, response_path=response_path@entry=0x7fff9ab97778, response_len=response_len@entry=0x7fff9ab977a0) at pseudo.c:1053 #9 0x000000000040935f in serve_client (i=5) at pseudo_server.c:499 #10 pseudo_server_loop () at pseudo_server.c:645 #11 pseudo_server_start (daemonize=<optimized out>) at pseudo_server.c:365 #12 0x0000000000406489 in main (argc=2, argv=0x7fff9ab98d48) at pseudo.c:431 (gdb) c Continuing. Breakpoint 1, 0x00007fc6af508c70 in memset () from /lib64/libc.so.6 (gdb) where #0 0x00007fc6af508c70 in memset () from /lib64/libc.so.6 #1 0x00000000004365c0 in createAggContext.isra.393 () #2 0x0000000000436665 in countStep () #3 0x00000000004774d2 in sqlite3VdbeExec () #4 0x000000000047e051 in sqlite3_step () #5 0x000000000040f533 in pdb_clear_unused_xattrs () at pseudo_db.c:1484 #6 0x0000000000411836 in pdb_did_unlink_file ( path=path@entry=0x1ca46bc "/data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/work/intel_corei7_64-ostro-linux/ostro-image-swupd/1.0-r0/ostro-image-swupd-1.0/copy/original/56/15", deleting=27451) at pseudo_db.c:1885 #7 0x0000000000407aa3 in pseudo_op (msg=0x1ca4670, program=0x32645b0 "rm", tag=0x47490e0 "", response_path=0x7fff9ab97778, response_len=0x7fff9ab977a0) at pseudo.c:933 #8 0x00000000004087d1 in pseudo_server_response (msg=msg@entry=0x1ca4670, program=<optimized out>, tag=<optimized out>, response_path=response_path@entry=0x7fff9ab97778, response_len=response_len@entry=0x7fff9ab977a0) at pseudo.c:1053 #9 0x000000000040935f in serve_client (i=5) at pseudo_server.c:499 #10 pseudo_server_loop () at pseudo_server.c:645 #11 pseudo_server_start (daemonize=<optimized out>) at pseudo_server.c:365 #12 0x0000000000406489 in main (argc=2, argv=0x7fff9ab98d48) at pseudo.c:431 (gdb) d 1 (gdb) b read Breakpoint 2 at 0x7fc6af55cc60 (2 locations) (gdb) c Continuing. Breakpoint 2, 0x00007fc6afa3ea50 in read () from /lib64/libpthread.so.0 (gdb) c Continuing. Breakpoint 2, 0x00007fc6afa3ea50 in read () from /lib64/libpthread.so.0 (gdb) where #0 0x00007fc6afa3ea50 in read () from /lib64/libpthread.so.0 #1 0x000000000040e10b in pseudo_msg_receive (fd=14) at pseudo_ipc.c:155 #2 0x00000000004092cf in serve_client (i=8) at pseudo_server.c:454 #3 pseudo_server_loop () at pseudo_server.c:645 #4 pseudo_server_start (daemonize=<optimized out>) at pseudo_server.c:365 #5 0x0000000000406489 in main (argc=2, argv=0x7fff9ab98d48) at pseudo.c:431 (gdb) b memset Breakpoint 3 at 0x7fc6af508c70 (gdb) c Continuing. Breakpoint 3, 0x00007fc6af508c70 in memset () from /lib64/libc.so.6 (gdb) where #0 0x00007fc6af508c70 in memset () from /lib64/libc.so.6 #1 0x00000000004719ae in sqlite3VdbeHalt () #2 0x00000000004724d1 in sqlite3VdbeReset () #3 0x000000000047429c in sqlite3_reset () #4 0x00000000004124d4 in pdb_find_file_exact (msg=msg@entry=0x1ca4670) at pseudo_db.c:2285 #5 0x0000000000407798 in pseudo_op (msg=0x1ca4670, program=0x14a7670 "du", tag=0xf427a0 "", response_path=0x7fff9ab97778, response_len=0x7fff9ab977a0) at pseudo.c:539 #6 0x00000000004087d1 in pseudo_server_response (msg=msg@entry=0x1ca4670, program=<optimized out>, tag=<optimized out>, response_path=response_path@entry=0x7fff9ab97778, response_len=response_len@entry=0x7fff9ab977a0) at pseudo.c:1053 #7 0x000000000040935f in serve_client (i=8) at pseudo_server.c:499 #8 pseudo_server_loop () at pseudo_server.c:645 #9 pseudo_server_start (daemonize=<optimized out>) at pseudo_server.c:365 #10 0x0000000000406489 in main (argc=2, argv=0x7fff9ab98d48) at pseudo.c:431 ltrace -c -p 3564 ^C% time seconds usecs/call calls function ------ ----------- ----------- --------- -------------------- 100.00 11.284055 114 98550 memset ------ ----------- ----------- --------- -------------------- 100.00 11.284055 98550 total I'll let the build run; let's see whether it reaches ostro-image-swupd' task do_image (not there yet). Any suggestions what I should check would be very welcome. This is now the issue which blocks Ostro OS from using OE-core master. 63940 1 patrick.ohly 2016-07-13 18:45:58 +0000 If someone wants to reproduce: - git clone git@github.com:pohly/ostro-os.git - git checkout pseudo-performance - . oe-init-build-env - bitbake ostro-image-swupd 63947 2 patrick.ohly 2016-07-13 20:38:47 +0000 Update: build is still running, still busy copying files, with pseudo as the bottleneck. 0: ostro-image-swupd-1.0-r0 do_rootfs (pid 27298) 81% |###################################################################### | ETA: 0:23:51 1: bundle-ostro-image-swupd-qa-bundle-a-1.0-r0 do_copy_bundle_contents (pid 27299) 2: bundle-ostro-image-swupd-qa-bundle-b-1.0-r0 do_copy_bundle_contents (pid 27300) 3: bundle-ostro-image-swupd-world-dev-1.0-r0 do_copy_bundle_contents (pid 28530) 21109 pts/1 Ss 0:01 \_ -bash 508 pts/1 S+ 0:18 | \_ python3 /data2/yocto/ostro-os/bitbake/bin/bitbake ostro-image-swupd 517 pts/1 Sl+ 1:58 | \_ python3 /data2/yocto/ostro-os/bitbake/bin/bitbake ostro-image-swupd 669 pts/1 S+ 0:09 | \_ python3 /data2/yocto/ostro-os/bitbake/bin/bitbake-worker decafbad 739 pts/1 S+ 0:00 | \_ /data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/sysroots/x86_64-linux/usr/bin/pseudo bitbake-worker decafbadbee 740 pts/1 S+ 0:10 | \_ python3 /data2/yocto/ostro-os/bitbake/bin/bitbake-worker decafbadbeef 27298 ? Ss 0:01 | \_ python3 /data2/yocto/ostro-os/bitbake/bin/bitbake-worker decafbadbeef 29579 ? S 0:23 | | \_ /data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/sysroots/x86_64-linux/usr/bin/opkg --volatile-cache 27299 ? Ss 0:02 | \_ python3 /data2/yocto/ostro-os/bitbake/bin/bitbake-worker decafbadbeef 27672 ? S 0:00 | | \_ /bin/sh -c tar --xattrs --xattrs-include='*' -cf - -C /data2/yocto/build/ostro/intel-corei7-64/tmp-gli 27673 ? S 0:11 | | \_ tar --xattrs --xattrs-include=* -cf - -C /data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/work/i 27674 ? S 0:19 | | \_ tar -p --xattrs --xattrs-include=* -xf - -C /data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/dep 27300 ? Ss 0:02 | \_ python3 /data2/yocto/ostro-os/bitbake/bin/bitbake-worker decafbadbeef 27681 ? S 0:00 | | \_ /bin/sh -c tar --xattrs --xattrs-include='*' -cf - -C /data2/yocto/build/ostro/intel-corei7-64/tmp-gli 27682 ? S 0:09 | | \_ tar --xattrs --xattrs-include=* -cf - -C /data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/work/i 27683 ? S 0:18 | | \_ tar -p --xattrs --xattrs-include=* -xf - -C /data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/dep 28530 ? Ss 0:02 | \_ python3 /data2/yocto/ostro-os/bitbake/bin/bitbake-worker decafbadbeef 29116 ? S 0:00 | \_ /bin/sh -c tar --xattrs --xattrs-include='*' -cf - -C /data2/yocto/build/ostro/intel-corei7-64/tmp-gli 29117 ? S 0:10 | \_ tar --xattrs --xattrs-include=* -cf - -C /data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/work/i 29118 ? S 0:17 | \_ tar -p --xattrs --xattrs-include=* -xf - -C /data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/dep 7329 pts/4 Ss+ 0:00 \_ -bash 32666 ? Ss 0:00 \_ /usr/lib/ssh/sftp-server 3564 ? Rs 220:59 /data2/yocto/build/ostro/intel-corei7-64/tmp-glibc/sysroots/x86_64-linux/usr/bin/pseudo -d 63948 3 joshuagloe 2016-07-13 21:09:37 +0000 Thanks for the in-depth analysis Patrick! It's worth explicitly stating, for anyone reading along, that Ostro OS makes heavy use of extended attributes (for SMACK and IMA) and that it's pseudo_db calls related to xattr handling which are most implicated in the traces. The meta-swupd tar usage is a tar-pipe to copy files preserving their various attributes and extended attributes: "tar --xattrs --xattrs-include='*' -cf - -C %s -p . | tar -p --xattrs --xattrs-include='*' -xf - -C %s" % (src, dst) 64043 4 joshuagloe 2016-07-15 14:38:33 +0000 Because this slowness is in xattr handling code we can't introduce new xattr consuming features (#9857, #9858) until the slow down is resolved — adding those two issues to the Blocks field. 64048 5 seebs 2016-07-15 15:20:30 +0000 Okay, so, clear_unused_xattrs() is slow. It looks like we have two cases for did_unlink_file, and in some of them, we should be able to use an exact match (which would be way faster). I suspect that if I had two did_unlink_file, one of which specifies the device and inode, and can use the faster xattr clear, that'd work better. 64056 6 joshuagloe 2016-07-15 16:09:35 +0000 (In reply to comment #5) > Okay, so, clear_unused_xattrs() is slow. It looks like we have two cases for > did_unlink_file, and in some of them, we should be able to use an exact > match (which would be way faster). > > I suspect that if I had two did_unlink_file, one of which specifies the > device and inode, and can use the faster xattr clear, that'd work better. That sounds about right. I've been playing around with changes which might help and whilst I was uncertain as to the full detail behind the following comment in pdb_did_unlink_file() /* we have to clean everything because we don't know for sure the * device/inode... */ I decided to try a build with a dirty hack that tries to find the ino and dev of the unlinked file: https://github.com/incandescant/pseudo/commit/c50711e5d5ab85d4dd23e99565ac9ce1b56b743b With that patch applied a build which makes heavy use of xattr and I had to kill after >20hours is proceeding along and almost done after only a "few" hours. 64057 7 seebs 2016-07-15 16:11:38 +0000 I'm guessing that the bulk of the problem comes from DID_UNLINK messages -- where we could have passed in the full message to did_unlink, and in that case we could do the faster/simpler xattr clean. The xattr sharing is sort of annoying, and I would much like to have a cleaner solution, but I haven't thought of one yet. 64095 8 patrick.ohly 2016-07-18 10:33:00 +0000 Joshua, if slow delete handling is the root cause of the problem, then why does it affect the tar copy pipeline? That should only create files, not delete them. About tar itself: I found that bsdtar had much saner behavior (as in, "less system calls") than GNU tar when dealing with xattrs. It may be worthwhile to investigate using bsdtar instead of GNU tar. Another reason for that is that (presumably, haven't checked) you are using the host's GNU tar. That version may be too old to support xattrs properly, while a bsdtar-native compiled by bitbake is guaranteed to have it. 64577 9 joshuagloe 2016-07-28 12:52:50 +0000 (In reply to comment #7) > I'm guessing that the bulk of the problem comes from DID_UNLINK messages -- > where we could have passed in the full message to did_unlink, and in that > case we could do the faster/simpler xattr clean. Thanks Peter. Following this comment I wrote a patch to do just that, you can see it here (warning, transient URL): https://github.com/incandescant/pseudo/commit/ee9d967fb7114ba5a9d16f89977f720e74530d2d Running some test builds of Ostro OS using that patch I see significant speed improvements, i.e: ostro-image-swupd-1.0-r0: do_image: Elapsed time: 2880.87 seconds 64578 10 joshuagloe 2016-07-28 13:00:55 +0000 (In reply to comment #8) > Joshua, if slow delete handling is the root cause of the problem, then why > does it affect the tar copy pipeline? That should only create files, not > delete them. > > About tar itself: I found that bsdtar had much saner behavior (as in, "less > system calls") than GNU tar when dealing with xattrs. It may be worthwhile > to investigate using bsdtar instead of GNU tar. > > Another reason for that is that (presumably, haven't checked) you are using > the host's GNU tar. That version may be too old to support xattrs properly, > while a bsdtar-native compiled by bitbake is guaranteed to have it. Indeed, investigating bsdtar is high on my list as I've found GNU tar to be increasingly problematic as I've tried to include better xattr support on OE-Core (i.e. in sstate objects). I need to take a discussion to the OE-Arch list on this topic, I think. 64719 11 joshuagloe 2016-08-01 11:07:31 +0000 Peter came up with a more complete version of my change which is in pseudo master[1] and has been submitted for include in the OE-Core recipe as a backport[2]. 1. http://git.yoctoproject.org/clean/cgit.cgi/pseudo/commit/?id=0d9071f3090bbd7880558f3b488b236ac19b44fc 2. http://lists.openembedded.org/pipermail/openembedded-core/2016-August/124557.html 64874 12 joshuagloe 2016-08-04 14:59:15 +0000 Fix landed in master: http://git.openembedded.org/openembedded-core/commit/?id=75627af164f027de0036b91854e9b926de786bcd