Poor performance of handle leak check

[derekbruening]

From zhao...@google.com on November 12, 2013 17:46:11

The handle leak check cause more than 30sec slowdown

time ~/Workspace/DrMemory/builds/build_x86_drm_dbg.git/bin/drmemory.exe -debug -light -callstack_max_frames 40 -- ./out/Debug/unit_tests.exe --gtest_filter=AutofillDialogControllerTest*

[----------] Global test environment tear-down [==========] 77 tests from 1 test case ran. (207310 ms total) [ PASSED ] 77 tests.

real 5m42.338s user 0m0.016s sys 0m0.031s

time ~/Workspace/DrMemory/builds/build_x86_drm_dbg.git/bin/drmemory.exe -debug -light -check_handle_leaks -callstack_max_frames 40 -- ./out/Debug/unit_tests.exe --gtest_filter=AutofillDialogControllerTest*

[----------] Global test environment tear-down [==========] 77 tests from 1 test case ran. (213795 ms total) [ PASSED ] 77 tests.

real 6m17.887s user 0m0.015s sys 0m0.031s

Original issue: http://code.google.com/p/drmemory/issues/detail?id=1379

[derekbruening]

From zhao...@google.com on November 12, 2013 14:59:55

The handle_leaks_only option is a bit faster than -light.

time ~/Workspace/DrMemory/builds/build_x86_drm_dbg.git/bin/drmemory.exe -debug -handle_leaks_only -callstack_max_frames 40 -- ./out/Debug/unit_tests.exe --gtest_filter=AutofillDialogControllerTest* [----------] Global test environment tear-down [==========] 77 tests from 1 test case ran. (80239 ms total) [ PASSED ] 77 tests. real 4m58.846s user 0m0.000s sys 0m0.031s

[derekbruening]

From zhao...@google.com on November 12, 2013 15:40:48

DR only: [==========] 77 tests from 1 test case ran. (155063 ms total) [ PASSED ] 77 tests. real 4m30.966s user 0m0.015s sys 0m0.015s

All debug builds.

[derekbruening]

From zhao...@google.com on November 12, 2013 21:56:03

./out/Debug/unit_tests.exe --gtest_filter=AutofillDialogControllerTest*

release build: native: 0m6.974s, 77 tests: 6451 ms dr: 0m30.709s, 77 tests: 24304 ms dr-notrace: 0m15.918s, 77 tests: 13826 ms drm-light, 12 callstack frames: 0m24.152s, 77 tests: 17868 ms drm-light, 40 callstack frames: 1m49.306s, 77 tests: 102441 ms drm-light-handle, 12 callstack frames: 1m49.594, 77 tests: 17817 ms drm-light-handle, 40 callstack frames: 2m7.940s, 77 tests: 106944 ms drm-handle-only, 12 callstack frames: 1m52.098s, 77 tests: 15732 ms drm-handle-only, 40 callstack frames: 2m3.432s, 77 tests: 15167 ms drm-handle-only, 12 callstack frames, no_filter: 1m55.190s, 77 tests: 15377 ms drm-handle-only, 40 callstack frames, no_filter: 2m17.554s, 77 tests: 18409 ms

1. the more callstack frames, the more slowdown
2. the handle table iteration seems takes really long time

[derekbruening]

From bruen...@google.com on November 13, 2013 07:53:05

1. the more callstack frames, the more slowdown

Yes, this is why I have been reluctant to increase the default -callstack_max_frames from 12. Although the degree of slowdown here is higher than expected. How many handle opens happen in this test?