Bug 9929

Summary: pseudo 1.8.1: potential performance regression
Product: [Yocto Project Subprojects] Pseudo Reporter: Patrick Ohly <patrick.ohly>
Component: pseudoAssignee: Joshua Lock <joshuagloe>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: High CC: jose.perez.carranza, mark.hatle, randy.macleod, seebs, sgw, yp.pseudo.watcher, yp.watcher
Version: unspecified   
Target Milestone: 2.2 M3   
Hardware: x86   
OS: Multiple   
Whiteboard:
OS type for building Yocto: --- Type of Regression: ---
Verified: Documentation change: No (bug/feature does not impact docs)
Bug Depends on:    
Bug Blocks: 9858, 9857    

Description Patrick Ohly 2016-07-13 18:43:34 UTC 
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.
Comment 1 Patrick Ohly 2016-07-13 18:45:58 UTC 
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
Comment 2 Patrick Ohly 2016-07-13 20:38:47 UTC 
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
Comment 3 Joshua Lock 2016-07-13 21:09:37 UTC 
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)
Comment 4 Joshua Lock 2016-07-15 14:38:33 UTC 
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.
Comment 5 Seebs 2016-07-15 15:20:30 UTC 
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.
Comment 6 Joshua Lock 2016-07-15 16:09:35 UTC 
(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.
Comment 7 Seebs 2016-07-15 16:11:38 UTC 
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.
Comment 8 Patrick Ohly 2016-07-18 10:33:00 UTC 
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.
Comment 9 Joshua Lock 2016-07-28 12:52:50 UTC 
(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
Comment 10 Joshua Lock 2016-07-28 13:00:55 UTC 
(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.
Comment 11 Joshua Lock 2016-08-01 11:07:31 UTC 
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