retrace performance impact

riboseinc / retrace

retrace is a versatile security vulnerability / bug discovery tool through monitoring and modifying the behavior of compiled binaries on Linux, OpenBSD/FreeBSD/NetBSD (shared object) and macOS (dynamic library).

Other

61 stars 19 forks source link

retrace performance impact #189

Open catap opened 7 years ago

catap commented 7 years ago

When I run rnp tests without retrace it costs about 7 seconds:

➜  retrace git:(incompleteio_fix) time ../rnp/src/cmocka/.libs/rnp_tests
....
../rnp/src/cmocka/.libs/rnp_tests  6.39s user 0.38s system 87% cpu 7.757 total
➜  retrace git:(incompleteio_fix)

Same test with retrace with config logtofile,/dev/null I interrupted after about 40 minutes.

env RETRACE_CONFIG=../retrace.conf.rnp time ./retrace ../rnp/src/cmocka/.libs/rnp_tests
....
^CCommand terminated abnormally.
     2322.87 real       377.39 user      1279.58 sys
➜  retrace git:(incompleteio_fix) ✗

catap commented 7 years ago

I made small research:

https://github.com/riboseinc/retrace/commit/510c378cecd6533b2aa3029e33abbd680b9b0316 works about 35 seconds
https://github.com/riboseinc/retrace/commit/4a23dda3c4636f084c4e89038f8667514a492b25 works about 3.5 minutes

pablo-mendoza commented 7 years ago

Oh, that's may fault then ...

catap commented 7 years ago

@riataman I've opened a pull request https://github.com/riboseinc/retrace/pull/190 that contains first performance fix.

Performance significant improved, from I waited 40 minutes and interrupt to 164.72 seconds.

But I'm still thinking.

catap commented 7 years ago

Well.. Looks like I found a dead-lock inside retrace if it running with gperftools.

pablo-mendoza commented 7 years ago

Those are fun to track :)

catap commented 7 years ago

@riataman but I will discribe the dead-lock later ;)

pablo-mendoza commented 7 years ago

Sorry closed by mistake.

pablo-mendoza commented 7 years ago

catap I don't think this was a performance fix per see, I don't think opening/closing a file should cause such a huge performance impact, I'm thinking there was a loop in there somewhere that was fixed by this.

Still a good fix :)

catap commented 7 years ago

@riataman but since https://github.com/riboseinc/retrace/commit/4a23dda3c4636f084c4e89038f8667514a492b25 the code calls trace_printf huge numbers of times.

And each time the code open and close the file, and when it close the file, it makes also flush for this file ;)

ronaldtse commented 7 years ago

@riataman perhaps you can have a look to see how we can fix the performance impact of #143 ?

The tests done by @catap are very interesting because we can describe retrace's impact to executables in terms of multiples. Maybe we can even integrate these to CI tests (e.g., "not slower than 40x") and also describe in the README.

catap commented 7 years ago

Found one more possibility to huge performance impact: https://github.com/riboseinc/retrace/issues/208