When running a local experiment with e.g.:
make run-honggfuzz-proj4-2017-08-14
The following process tree (inside docker) is created
root 31517 1.8 0.9 2108508 79024 ? Ssl 16:07 8:08 /usr/sbin/dockerd -H fd://
root 31529 0.3 0.2 1912212 22624 ? Ssl 16:07 1:35 \_ docker-containerd --config /var/run/docker/containerd/containerd.toml --log-level info
root 8625 0.0 0.1 773488 10964 ? Sl 23:29 0:00 \_ docker-containerd-shim -namespace moby -workdir /var/lib/docker/containerd/daemon/io.containerd.runtime.v1.linux/moby/13b1d8df9fcfacc96627cc5d8c6906aa5793fad0b8b5e78935ced70f8c911db4 -address /var/run/docker/containerd/containerd.sock -containerd-binary /usr/bin/docker-containerd -runtime-root /var/run/docker/runtime-runc
root 8642 0.0 0.0 4504 748 pts/0 Ss+ 23:29 0:00 \_ /bin/sh -c $ROOT_DIR/docker/benchmark-runner/startup-runner.sh
root 8677 0.0 0.0 18068 2904 pts/0 S+ 23:29 0:00 \_ /bin/bash -e /src/docker/benchmark-runner/startup-runner.sh
root 8685 96.4 0.5 730840 44724 pts/0 S<l+ 23:29 6:54 \_ python3 /src/experiment/runner.py
root 8698 0.0 0.1 44380 9592 ? Ss 23:29 0:00 \_ python3 -u -c import fuzzer; fuzzer.fuzz('/out/seeds', '/out/corpus', '/out/fuzz-target')
root 8706 198 0.1 730584 10024 ? Sl 23:29 14:12 \_ ./honggfuzz --sanitizers --persistent --input /out/seeds --output /out/corpus -na -- /out/fuzz-target
root 8716 62.9 4.8 21475465676 398192 ? Rs 23:29 4:29 \_ /out/fuzz-target
root 8717 63.1 4.8 21475465676 398116 ? Rs 23:29 4:30 \_ /out/fuzz-target
root 8718 62.8 4.8 21475465676 395052 ? Rs 23:29 4:29 \_ /out/fuzz-target
root 8719 63.0 4.8 21475465676 398308 ? Rs 23:29 4:29 \_ /out/fuzz-target
root 8720 62.4 4.8 21475465676 398640 ? Rs 23:29 4:27 \_ /out/fuzz-target
root 8721 62.8 4.8 21475465676 396120 ? Rs 23:29 4:28 \_ /out/fuzz-target
root 8722 62.5 4.8 21475465676 398292 ? Rs 23:29 4:27 \_ /out/fuzz-target
root 8723 63.0 4.8 21475465676 396276 ? Rs 23:29 4:30 \_ /out/fuzz-target
And the process python3 /src/experiment/runner.py
eats 1 core of CPU time on a 8-core machine. If I'm not mistaken, you're running experiments on 1-core machines (or, maybe forcing experiments to 1 core by using sched_affinity), so the effects might be bigger there, and I'm worried that the runner.py is using, say 50% of a single CPU time on a single fuzz-machine.
It could be something related to my setup, or to the fact that the host machine is 8-cores, but would be glad if you could check it on your side as well. BTW, I'm using a regular GCE VM (8-core).
I've done a quick check on this process (here PID=8685), and it's its thread TID=8694 - you can find that by using key H
in top) is the thread which actually fetches the data from the honggfuzz output and writes them to the output file. But, it's just a guess from a quick gdb session.
# gdb
(gdb) attach 8694
Attaching to process 8694
...
PyTuple_New (size=size@entry=0) at Objects/tupleobject.c:135
135 Objects/tupleobject.c: No such file or directory.
(gdb) bt
#0 PyTuple_New (size=size@entry=0) at Objects/tupleobject.c:135
#1 0x000000000043cac4 in _PyStack_AsTuple (stack=stack@entry=0x0, nargs=nargs@entry=0) at Objects/call.c:1284
#2 0x000000000043f47f in _PyObject_FastCallDict (callable=callable@entry=0x7f2663098b90, args=args@entry=0x0, nargs=nargs@entry=0, kwargs=kwargs@entry=0x0) at Objects/call.c:115
#3 0x0000000000424d51 in _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:2906
#4 0x00000000004ebf28 in PyEval_EvalFrameEx (throwflag=0, f=0x7f263c005d50) at Python/ceval.c:547
#5 _PyEval_EvalCodeWithName (_co=0x7f265c2806f0, globals=<optimized out>, locals=locals@entry=0x0, args=<optimized out>, argcount=1, kwnames=0x7f265c2924a8, kwargs=0x7f265b9c56d8, kwcount=1, kwstep=1, defs=0x7f265c2a8a68, defcount=2, kwdefs=0x0,
closure=0x0, name=0x7f266313d170, qualname=0x7f265c27f130) at Python/ceval.c:3930
#6 0x000000000043c9c6 in _PyFunction_FastCallKeywords (func=<optimized out>, stack=<optimized out>, nargs=<optimized out>, kwnames=<optimized out>) at Objects/call.c:433
#7 0x000000000042880b in call_function (kwnames=0x7f265c292490, oparg=<optimized out>, pp_stack=<synthetic pointer>) at Python/ceval.c:4616
#8 _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3139
#9 0x0000000000420668 in function_code_fastcall (co=<optimized out>, args=<optimized out>, nargs=1, globals=<optimized out>) at Objects/call.c:283
#10 0x000000000043ca9f in _PyFunction_FastCallKeywords (func=<optimized out>, stack=<optimized out>, nargs=<optimized out>, kwnames=<optimized out>) at Objects/call.c:415
#11 0x0000000000429aa3 in call_function (kwnames=0x0, oparg=<optimized out>, pp_stack=<synthetic pointer>) at Python/ceval.c:4616
#12 _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3110
#13 0x0000000000420668 in function_code_fastcall (co=<optimized out>, args=<optimized out>, nargs=2, globals=<optimized out>) at Objects/call.c:283
#14 0x000000000043ca9f in _PyFunction_FastCallKeywords (func=<optimized out>, stack=<optimized out>, nargs=<optimized out>, kwnames=<optimized out>) at Objects/call.c:415
#15 0x000000000042997c in call_function (kwnames=0x0, oparg=<optimized out>, pp_stack=<synthetic pointer>) at Python/ceval.c:4616
#16 _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3124
#17 0x00000000004ebf28 in PyEval_EvalFrameEx (throwflag=0, f=0x231c480) at Python/ceval.c:547
#18 _PyEval_EvalCodeWithName (_co=0x7f265ba576f0, globals=<optimized out>, locals=locals@entry=0x0, args=<optimized out>, argcount=1, kwnames=0x7f266224fb48, kwargs=0x231b0d0, kwcount=4, kwstep=1, defs=0x0, defcount=0, kwdefs=0x7f265ba4cfa0,
closure=0x0, name=0x7f26622246f0, qualname=0x7f26622246f0) at Python/ceval.c:3930
#19 0x000000000043c9c6 in _PyFunction_FastCallKeywords (func=<optimized out>, stack=<optimized out>, nargs=<optimized out>, kwnames=<optimized out>) at Objects/call.c:433
#20 0x000000000042880b in call_function (kwnames=0x7f266224fb30, oparg=<optimized out>, pp_stack=<synthetic pointer>) at Python/ceval.c:4616
#21 _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3139
#22 0x0000000000420668 in function_code_fastcall (co=co@entry=0x7f2662221930, args=<optimized out>, args@entry=0x7f265ba528d8, nargs=nargs@entry=2, globals=globals@entry=0x7f26630ddb90) at Objects/call.c:283
#23 0x000000000043c90e in _PyFunction_FastCallDict (func=0x7f265b9efc20, args=0x7f265ba528d8, nargs=2, kwargs=0x7f265b9fa5a0) at Objects/call.c:322
#24 0x0000000000424ea7 in do_call_core (kwdict=0x7f265b9fa5a0, callargs=0x7f265ba528c0, func=0x7f265b9efc20) at Python/ceval.c:4645
#25 _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3191
#26 0x0000000000420668 in function_code_fastcall (co=<optimized out>, args=<optimized out>, nargs=1, globals=<optimized out>) at Objects/call.c:283
#27 0x000000000043ca9f in _PyFunction_FastCallKeywords (func=<optimized out>, stack=<optimized out>, nargs=<optimized out>, kwnames=<optimized out>) at Objects/call.c:415
#28 0x0000000000429aa3 in call_function (kwnames=0x0, oparg=<optimized out>, pp_stack=<synthetic pointer>) at Python/ceval.c:4616
#29 _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3110
#30 0x0000000000420668 in function_code_fastcall (co=<optimized out>, args=<optimized out>, nargs=1, globals=<optimized out>) at Objects/call.c:283
#31 0x000000000043ca9f in _PyFunction_FastCallKeywords (func=<optimized out>, stack=<optimized out>, nargs=<optimized out>, kwnames=<optimized out>) at Objects/call.c:415
#32 0x0000000000429aa3 in call_function (kwnames=0x0, oparg=<optimized out>, pp_stack=<synthetic pointer>) at Python/ceval.c:4616
#33 _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3110
#34 0x0000000000420668 in function_code_fastcall (co=co@entry=0x7f2661fdb780, args=<optimized out>, args@entry=0x7f2643ffee60, nargs=nargs@entry=1, globals=globals@entry=0x7f2661fcaaa0) at Objects/call.c:283
#35 0x000000000043c90e in _PyFunction_FastCallDict (func=func@entry=0x7f2661f954d0, args=args@entry=0x7f2643ffee60, nargs=nargs@entry=1, kwargs=kwargs@entry=0x0) at Objects/call.c:322
#36 0x000000000043fac9 in _PyObject_FastCallDict (kwargs=0x0, nargs=1, args=0x7f2643ffee60, callable=0x7f2661f954d0) at Objects/call.c:98
#37 _PyObject_Call_Prepend (callable=0x7f2661f954d0, obj=<optimized out>, args=0x7f2663127050, kwargs=0x0) at Objects/call.c:908
#38 0x000000000043de50 in PyObject_Call (callable=0x7f266311e320, args=0x7f2663127050, kwargs=0x0) at Objects/call.c:245
#39 0x000000000057c783 in t_bootstrap (boot_raw=boot_raw@entry=0x7f265ba0a300) at ./Modules/_threadmodule.c:994
#40 0x0000000000532797 in pythread_wrapper (arg=<optimized out>) at Python/thread_pthread.h:174
#41 0x00007f2662d646ba in start_thread () from target:/lib/x86_64-linux-gnu/libpthread.so.0
#42 0x00007f266238a41d in clone () from target:/lib/x86_64-linux-gnu/libc.so.6
(gdb) detach
Also from strace
which suggest it's the thread which is reading/writing data from honggfuzz's stderr
# strace -p 8694
strace: Process 8694 attached
strace: [ Process PID=8694 runs in x32 mode. ]
strace: [ Process PID=8694 runs in 64 bit mode. ]
futex(0x918930, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x918934, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x918930, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1) = 1
futex(0x918960, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x918934, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 2421, {tv_sec=1583365283, tv_nsec=630654000}, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x918960, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f2638002f30, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x918934, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x918930, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1) = 1
futex(0x918960, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f2638002f30, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
write(8, "Size:5756 (i,b,hw,ed,ip,cmp): 0/"..., 69) = 69
write(1, "Size:5756 (i,b,hw,ed,ip,cmp): 0/"..., 69) = 69
futex(0x918930, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x918934, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x918930, FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1) = 1
futex(0x918960, FUTEX_WAKE_PRIVATE, 1) = 1
write(8, "Size:5949 (i,b,hw,ed,ip,cmp): 0/"..., 69) = 69
write(1, "Size:5949 (i,b,hw,ed,ip,cmp): 0/"..., 69) = 69