/MDd w/ no syms => _nh_malloc_dbg instrumented as non-heap => perf hit from unaddr exceptions

[derekbruening]

From [email protected] on August 30, 2012 19:40:41

xref issue #977 : yet another -light perf issue from heap header exceptions

this started out w/ me thinking release build wasn't getting the benefit of
the symcache for issue #973 this is HEAD
debug: from 40s first run to 16s in later runs
release: always 37s

adding logging shows it is using symcache. seems to be slow from -light
unaddrs:

ChildEBP RetAddr

00 1b92e898 61a6fa7a dynamorio!instr_destroy+0x4 [d:\derek\dr\git\src\core\x86\instr.c @ 1590]
01 1b92e8b4 61a6faa2 dynamorio!instrlist_clear+0x4a [d:\derek\dr\git\src\core\instrlist.c @ 97]
02 1b92e8cc 61a85492 dynamorio!instrlist_clear_and_destroy+0x12 [d:\derek\dr\git\src\core\instrlist.c @ 106]
03 1b92eba4 61a85539 dynamorio!recreate_app_state_internal+0x6d2 [d:\derek\dr\git\src\core\x86\arch.c @ 3404]
04 1b92ebbc 61abfc4f dynamorio!recreate_app_state+0x19 [d:\derek\dr\git\src\core\x86\arch.c @ 3514]
05 1b92eea4 1b971bff dynamorio!intercept_exception+0x44f [d:\derek\dr\git\src\core\win32\callback.c @ 5079]
WARNING: Frame IP not in any known module. Following frames may be wrong.
06 0018fa70 61c6671f 0x1b971bff
07 0018fa90 61c666cc MSVCR100D!_nh_malloc_dbg+0x7f
08 0018fab8 61c66681 MSVCR100D!_nh_malloc_dbg+0x2c
09 0018fad8 61d32f10 MSVCR100D!_malloc_dbg+0x21
0a 0018fb00 61ce053a MSVCP100D!operator new+0x20
0b 0018fb24 61ce87b1 MSVCP100D!std::ios_base::_Init+0x8a
0c 0018fb30 61ce89e9 MSVCP100D!std::basic_ios<char,std::char_traits >::init+0x11
0d 0018fb58 61d0a7f5 MSVCP100D!std::basic_istream<char,std::char_traits >::basic_istream<char,std::char_traits >+0x99
0e 0018fb84 00625456 MSVCP100D!std::basic_iostream<char,std::char_traits >::basic_iostream<char,std::char_traits >+0x75
0f 0018fbac 023a4a7f unit_tests!std::basic_stringstream<char,std::char_traits,std::allocator >::basic_stringstream<char,std::char_traits,std::allocator >+0x76 [c:\program files (x86)\microsoft visual studio 10.0\vc\include\sstream @ 658]
10 0018fcd4 0062a752 unit_tests!testing::internal::StringStreamToString+0x7f [d:\derek\chromium\src\testing\gtest\src\gtest.cc @ 1723]
11 0018fcec 01160fd8 unit_tests!testing::Message::GetString+0x22 [d:\derek\chromium\src\testing\gtest\include\gtest\gtest-message.h @ 191]
12 0018fdc4 023a6995 unit_tests!testing::internal::ParameterizedTestCaseInfopolicy::ConfigurationPolicyProviderTest::RegisterTests+0x2a8 [d:\derek\chromium\src\testing\gtest\include\gtest\internal\gtest-param-util.h @ 516]
13 0018fddc 023a691d unit_tests!testing::internal::ParameterizedTestCaseRegistry::RegisterTests+0x55 [d:\derek\chromium\src\testing\gtest\include\gtest\internal\gtest-param-util.h @ 603]
0:000> .frame 3
03 1b92eba4 61a85539 dynamorio!recreate_app_state_internal+0x6d2 [d:\derek\dr\git\src\core\x86\arch.c @ 3404]
0:000> ?? mcontext->pc
unsigned char * 0x61c66a8d
"???"
0:000> U 0x61c66a8d
MSVCR100D!_nh_malloc_dbg+0x3ed:

% grep _malloc_dbg logs/symcache/MSVCR100D.dll.txt
_nh_malloc_dbg,0x0
_malloc_dbg_impl,0x0
_malloc_dbg,0x116660

setting bi->check_ignore_unaddr to true for every bb => fixes it: 15s

_nh_malloc_dbg must be called directly earlier and so doesn't have the
check_ignore_unaddr checks: called by initpd after all and suppressed there
for nosyms case

% grep _malloc_dbg ../build_x86_dbg/logs/symcache/MSVCR100D.dll.txt
_nh_malloc_dbg,0x1166a0
_malloc_dbg_impl,0x0
_malloc_dbg,0x116660

03:35 PM ~/drmemory/git/build_x86_rel
% diff logs/symcache/MSVCR100D.dll.txt ../build_x86_dbg/logs/symcache/MSVCR100D.dll.txt
2c2
< 1811,1505104,11320642092621496320,11320642092621496320,1553158,1298074680,1519616

---

1942,1505104,11320642092621496320,11320642092621496320,1553158,1298074680,1519616
7a8
,0x4a801
9a11
,0x116681
10a13
,0x119c5b
16a20
,0x116bfc
43a48,49
,0x45940
,0x81540
48,51c54
< _nh_malloc_dbg,0x0
< _CrtDbgReportWV,0x0
< _CrtDbgReportV,0x0
< _CrtDbgReportW,0x115670

---

_nh_malloc_dbg,0x1166a0
52a56,59
_CrtDbgReportV,0x121610
_CrtDbgReportW,0x115670
,0x1151e0
_CrtDbgReportWV,0x115230
65c72
< operator new,0x475f0

---

operator new,0x45930
66a74,76
,0x81050
,0x475f0
,0x105bc0
91c101
< crtDbgFlag,0x161454

---

crtDbgFlag,0x0
98d107
< _calloc_dbg_impl,0x0
99a109
_calloc_dbg_impl,0x116b50
105a116
_crtDbgFlag,0x161454

enumerate_set_syms_cb: _nh_malloc_dbg 0x1166a0
symcache_symbol_add: MSVCR100D.dll "_nh_malloc_dbg" @ 0x1166a0
intercepting _nh_malloc_dbg @0x616a66a0 type 22 in module MSVCR100D.dll

in debug:
in event_basic_block(tag=0x61826660)
new basic block @0x61826660 == MSVCR100D.dll!malloc_dbg
entering heap routine: adding nop-if-mem-unaddr checks
entering alloc routine 0x61826660 _malloc_dbg type=22 rec=0 adj=0
malloc-pre heap=0x00000069 size=0x69 flags=0x0
in event_basic_block(tag=0x618266a0)
new basic block @0x618266a0 == MSVCR100D.dll!malloc_dbg <== _nh_malloc_dbg
inside heap routine: adding nop-if-mem-unaddr checks

these are really _nh_malloc_dbg (no syms here):
SUPPRESSED Error #0: UNADDRESSABLE ACCESS: writing 0x0e500444-0x0e500448 4 byte(s)
#0 MSVCR100D.dll!malloc_dbg (0x61826a5b <MSVCR100D.dll+0x116a5b>) modid:41
#1 MSVCR100D.dll!malloc_dbg (0x6182671f <MSVCR100D.dll+0x11671f>) modid:41
#2 MSVCR100D.dll!malloc_dbg (0x61826ba4 <MSVCR100D.dll+0x116ba4>) modid:41
#3 MSVCR100D.dll!initptd (0x6175a801 <MSVCR100D.dll+0x4a801>) modid:41
#4 MSVCR100D.dll!getptd (0x6175a88b <MSVCR100D.dll+0x4a88b>) modid:41
#5 MSVCR100D.dll!isalpha_l (0x617c808f <MSVCR100D.dll+0xb808f>) modid:41
#6 MSVCR100D.dll!ismbbkana (0x617cfe73 <MSVCR100D.dll+0xbfe73>) modid:41
#7 MSVCR100D.dll!ismbblead (0x617cfd54 <MSVCR100D.dll+0xbfd54>) modid:41
#8 MSVCR100D.dll!unlock (0x617598f9 <MSVCR100D.dll+0x498f9>) modid:41
#9 MSVCR100D.dll!unlock (0x617597b7 <MSVCR100D.dll+0x497b7>) modid:41
#10 MSVCR100D.dll!_getmainargs (0x61758d96 <MSVCR100D.dll+0x48d96>) modid:41
#11 pre_cpp_init [f:\dd\vctools\crt_bld\self_x86\crt\src\crtexe.c:298](0x04c13d9d <unit_tests.exe
+0x4813d9d) modid:7
Note: @0:00:07.031 in thread 6940
Note: next higher malloc: 0x0e500460-0x0e5004e0
Note: prev lower malloc: 0x0e5003b0-0x0e500430
Note: instruction: mov %ecx -> 0x04(%eax)
error end
in event_basic_block(tag=0x61826a69)
new basic block @0x61826a69 == MSVCR100D.dll!malloc_dbg
in event_basic_block(tag=0x6178d1d0)

this jives w/ the fault above:
0:001> U 0x6a0b0000+116a60 L20
MSVCR100D!_nh_malloc_dbg+0x3c0:
6a1c6a60 8b55dc mov edx,[ebp-0x24]
6a1c6a63 89150836216a mov [MSVCR100D!__pInvalidArgHandler+0x8 (6a213608)],edx
6a1c6a69 8b45dc mov eax,[ebp-0x24]
6a1c6a6c 8b0d1436216a mov ecx,[MSVCR100D!__pInvalidArgHandler+0x14 (6a213614)]
6a1c6a72 8908 mov [eax],ecx
6a1c6a74 8b55dc mov edx,[ebp-0x24]
6a1c6a77 c7420400000000 mov dword ptr [edx+0x4],0x0
6a1c6a7e 8b45dc mov eax,[ebp-0x24]
6a1c6a81 8b4d10 mov ecx,[ebp+0x10]
6a1c6a84 894808 mov [eax+0x8],ecx
6a1c6a87 8b55dc mov edx,[ebp-0x24]
6a1c6a8a 8b4514 mov eax,[ebp+0x14]
6a1c6a8d 89420c mov [edx+0xc],eax

removing logs/symbols/* => debug is slow now too (45s)

so we have two action items:

1. treat _initptd (actually need _getptd) as heap layer to get all
   _nh_malloc_dbg bbs w/ in-heap checks
   XXX: calls lots of stuff: so only do if don't have _nh_malloc_dbg?
2. why didn't release build use logs/symbols/* while debug did?

in event_basic_block(tag=0x6169a690)
new basic block @0x6169a690 == MSVCR100D.dll!initptd+0x0
entering heap routine: adding nop-if-mem-unaddr checks

I implemented #1 and the speed is back but at the end of unit_tests w/ no
test we have:

Dr.M Error #1: INVALID HEAP ARGUMENT to _free_dbg() 0x0e4d3110
Dr.M # 0 MSVCR100D.dll!freefls +0x1ea (0x6a0faa9b <MSVCR100D.dll+0x4aa9b>)
Dr.M # 1 ntdll.dll!RtlIsCurrentThreadAttachExempt +0x5e (0x77649ab1 <ntdll.dll+0x39ab1>)
Dr.M # 2 ntdll.dll!LdrShutdownProcess +0x96 (0x7765d608 <ntdll.dll+0x4d608>)
Dr.M # 3 ntdll.dll!RtlExitUserProcess +0x73 (0x7765d554 <ntdll.dll+0x4d554>)
Dr.M # 4 KERNEL32.dll!ExitProcess +0x14 (0x757f79f5 <KERNEL32.dll+0x179f5>)
Dr.M # 5 MSVCR100D.dll!amsg_exit +0x49a (0x6a0f859b <MSVCR100D.dll+0x4859b>)
Dr.M # 6 MSVCR100D.dll!amsg_exit +0x346 (0x6a0f8447 <MSVCR100D.dll+0x48447>)
Dr.M # 7 MSVCR100D.dll!exit +0x11 (0x6a0f8092 <MSVCR100D.dll+0x48092>)
Dr.M # 8 __tmainCRTStartup [f:\dd\vctools\crt_bld\self_x86\crt\src\crtexe.c:566]
Dr.M # 9 mainCRTStartup [f:\dd\vctools\crt_bld\self_x86\crt\src\crtexe.c:370]
Dr.M #10 KERNEL32.dll!BaseThreadInitTh...

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

[derekbruening]

From [email protected] on August 31, 2012 10:43:42

This issue was closed by revision r1000 .

Status: Fixed