check_thread_vm_area consistency checks very slow on AArch64 and OSX
The app in #3956 (closed) and #4256 (closed) is very slow in debug build. The culprit seems to be what was also seen on OSX, where the consistency checks at the bottom of check_thread_vm_area are very slow. Interrupting the app in gdb multiple times while its running slowly shows this. Raising the level of that check to 3, to match OSX, makes the slowness go away.
^C
Program received signal SIGINT, Interrupt.
0x0000fffff7d45e68 in d_r_sscanf (str=0xfffff7fde520 <buf_scratch+1176> "ffffa8440000-ffffa8450000 rwxp 00000000 00:00 0 ",
fmt=0xfffff7f38c90 "%016lx-%016lx %s %016lx %*s %lu %4096[^\n]") at dynamorio/core/io.c:727
727 dynamorio/core/io.c: No such file or directory.
(gdb) bt
#0 0x0000fffff7d45e68 in d_r_sscanf (str=0xfffff7fde520 <buf_scratch+1176> "ffffa8440000-ffffa8450000 rwxp 00000000 00:00 0 ",
fmt=0xfffff7f38c90 "%016lx-%016lx %s %016lx %*s %lu %4096[^\n]") at dynamorio/core/io.c:727
#1 0x0000fffff7ea309c in memquery_iterator_next (iter=0xffff2818f770) at dynamorio/core/unix/memquery_linux.c:254
#2 0x0000fffff7ea344c in memquery_from_os (
pc=0xffffed7b4e38 "\001\034\240N\240\003\332<\270:N\225a\002\300=\002\034\240N \034\241NA\034\242Nc7N\225\210\305\002\360\340#\200=\b\201\070\221\b\375\337\b\223\305\002\360sB4\221\250\213", info=0xffff2818f898, have_type=0xffff2818f85e)
at dynamorio/core/unix/memquery_linux.c:340
#3 0x0000fffff7e7e7c0 in query_memory_ex_from_os (
pc=0xffffed7b4e38 "\001\034\240N\240\003\332<\270:N\225a\002\300=\002\034\240N \034\241NA\034\242Nc7N\225\210\305\002\360\340#\200=\b\201\070\221\b\375\337\b\223\305\002\360sB4\221\250\213", info=0xffff2818f898) at dynamorio/core/unix/os.c:9458
#4 0x0000fffff7e7e8b0 in get_memory_info_from_os (
pc=0xffffed7b4e38 "\001\034\240N\240\003\332<\270:N\225a\002\300=\002\034\240N \034\241NA\034\242Nc7N\225\210\305\002\360\340#\200=\b\201\070\221\b\375\337\b\223\305\002\360sB4\221\250\213", base_pc=0xffff2818f928, size=0xffff2818f920, prot=0xffff2818f91c)
at dynamorio/core/unix/os.c:9491
#5 0x0000fffff7ea52e0 in memcache_query_memory (
pc=0xffffed7b4e38 "\001\034\240N\240\003\332<\270:N\225a\002\300=\002\034\240N \034\241NA\034\242Nc7N\225\210\305\002\360\340#\200=\b\201\070\221\b\375\337\b\223\305\002\360sB4\221\250\213", out_info=0xffff2818f9a8) at dynamorio/core/unix/memcache.c:378
#6 0x0000fffff7e7e668 in query_memory_ex (
pc=0xffffed7b4e38 "\001\034\240N\240\003\332<\270:N\225a\002\300=\002\034\240N \034\241NA\034\242Nc7N\225\210\305\002\360\340#\200=\b\201\070\221\b\375\337\b\223\305\002\360sB4\221\250\213", out_info=0xffff2818f9a8) at dynamorio/core/unix/os.c:9418
#7 0x0000fffff7e7e71c in get_memory_info (
pc=0xffffed7b4e38 "\001\034\240N\240\003\332<\270:N\225a\002\300=\002\034\240N \034\241NA\034\242Nc7N\225\210\305\002\360\340#\200=\b\201\070\221\b\375\337\b\223\305\002\360sB4\221\250\213", base_pc=0x0, size=0x0, prot=0xffff2818fa24) at dynamorio/core/unix/os.c:9438
#8 0x0000fffff7cfbca4 in check_thread_vm_area (dcontext=0xffff280f8660,
pc=0xffffed7b4e38 "\001\034\240N\240\003\332<\270:N\225a\002\300=\002\034\240N \034\241NA\034\242Nc7N\225\210\305\002\360\340#\200=\b\201\070\221\b\375\337\b\223\305\002\360sB4\221\250\213",
tag=0xffffed7b4e38 "\001\034\240N\240\003\332<\270:N\225a\002\300=\002\034\240N \034\241NA\034\242Nc7N\225\210\305\002\360\340#\200=\b\201\070\221\b\375\337\b\223\305\002\360sB4\221\250\213", vmlist=0xffff2818fe10, flags=0xffff2818fe08, stop=0xffff2818fe58, xfer=false)
at dynamorio/core/vmareas.c:8313
#9 0x0000fffff7e360b0 in check_new_page_start (dcontext=0xffff280f8660, bb=0xffff2818fdd0)
at dynamorio/core/arch/interp.c:720
#10 0x0000fffff7e3a734 in build_bb_ilist (dcontext=0xffff280f8660, bb=0xffff2818fdd0)
at dynamorio/core/arch/interp.c:3315
#11 0x0000fffff7e41b88 in build_basic_block_fragment (dcontext=0xffff280f8660,
start=0xffffed7b4e38 "\001\034\240N\240\003\332<\270:N\225a\002\300=\002\034\240N \034\241NA\034\242Nc7N\225\210\305\002\360\340#\200=\b\201\070\221\b\375\337\b\223\305\002\360sB4\221\250\213", initial_flags=0, link=true, visible=true, for_trace=false, unmangled_ilist=0x0)
at dynamorio/core/arch/interp.c:5129
(gdb) shell wc /proc/247908/maps
144 748 8499 /proc/247908/maps
(gdb) c
Continuing.
^C
Program received signal SIGINT, Interrupt.
0x0000fffff7d450f8 in d_r_parse_int (sp=0xfffff7fdeaba <buf_scratch+2610> "ffffa85c0000 ---p 00000000 00:00 0 ", res_out=0xffff2818f550, base=16, width=16,
is_signed=false) at dynamorio/core/io.c:444
444 in dynamorio/core/io.c
(gdb) bt
#0 0x0000fffff7d450f8 in d_r_parse_int (sp=0xfffff7fdeaba <buf_scratch+2610> "ffffa85c0000 ---p 00000000 00:00 0 ", res_out=0xffff2818f550, base=16,
width=16, is_signed=false) at dynamorio/core/io.c:444
#1 0x0000fffff7d459bc in d_r_vsscanf (str=0xfffff7fdeaad <buf_scratch+2597> "ffffa85a0000-ffffa85c0000 ---p 00000000 00:00 0 ",
fmt=0xfffff7f38c90 "%016lx-%016lx %s %016lx %*s %lu %4096[^\n]", ap=...) at dynamorio/core/io.c:669
#2 0x0000fffff7d45ea0 in d_r_sscanf (str=0xfffff7fdeaad <buf_scratch+2597> "ffffa85a0000-ffffa85c0000 ---p 00000000 00:00 0 ",
fmt=0xfffff7f38c90 "%016lx-%016lx %s %016lx %*s %lu %4096[^\n]") at dynamorio/core/io.c:728
#3 0x0000fffff7ea309c in memquery_iterator_next (iter=0xffff2818f770) at dynamorio/core/unix/memquery_linux.c:254
#4 0x0000fffff7ea344c in memquery_from_os (pc=0xffffef7d0f4c "\362\377\377\027", info=0xffff2818f898, have_type=0xffff2818f85e)
at dynamorio/core/unix/memquery_linux.c:340
#5 0x0000fffff7e7e7c0 in query_memory_ex_from_os (pc=0xffffef7d0f4c "\362\377\377\027", info=0xffff2818f898)
at dynamorio/core/unix/os.c:9458
#6 0x0000fffff7e7e8b0 in get_memory_info_from_os (pc=0xffffef7d0f4c "\362\377\377\027", base_pc=0xffff2818f928, size=0xffff2818f920, prot=0xffff2818f91c)
at dynamorio/core/unix/os.c:9491
#7 0x0000fffff7ea52e0 in memcache_query_memory (pc=0xffffef7d0f4c "\362\377\377\027", out_info=0xffff2818f9a8)
at dynamorio/core/unix/memcache.c:378
#8 0x0000fffff7e7e668 in query_memory_ex (pc=0xffffef7d0f4c "\362\377\377\027", out_info=0xffff2818f9a8)
at dynamorio/core/unix/os.c:9418
#9 0x0000fffff7e7e71c in get_memory_info (pc=0xffffef7d0f4c "\362\377\377\027", base_pc=0x0, size=0x0, prot=0xffff2818fa24)
at dynamorio/core/unix/os.c:9438
#10 0x0000fffff7cfbca4 in check_thread_vm_area (dcontext=0xffff280f8660, pc=0xffffef7d0f4c "\362\377\377\027", tag=0xffffef7d0f4c "\362\377\377\027",
vmlist=0xffff2818fe10, flags=0xffff2818fe08, stop=0xffff2818fe58, xfer=false) at dynamorio/core/vmareas.c:8313
#11 0x0000fffff7e360b0 in check_new_page_start (dcontext=0xffff280f8660, bb=0xffff2818fdd0)
at dynamorio/core/arch/interp.c:720
#12 0x0000fffff7e3a734 in build_bb_ilist (dcontext=0xffff280f8660, bb=0xffff2818fdd0)
at dynamorio/core/arch/interp.c:3315
#13 0x0000fffff7e41b88 in build_basic_block_fragment (dcontext=0xffff280f8660, start=0xffffef7d0f4c "\362\377\377\027", initial_flags=0, link=true,
visible=true, for_trace=false, unmangled_ilist=0x0) at dynamorio/core/arch/interp.c:5129
#14 0x0000fffff7c178bc in d_r_dispatch (dcontext=0xffff280f8660) at dynamorio/core/disp
Breakpoint 2 at 0xfffff7c35c94: file dynamorio/core/utils.c, line 2141.
(gdb) bt
#0 0x0000fffff7d45088 in d_r_parse_int (sp=0xfffff7fde5e4 <buf_scratch+1372> "ffffa95e0000-ffffa95f0000 rwxp 00000000 00:00 0 ", res_out=0xffff2818f550,
base=16, width=16, is_signed=false) at dynamorio/core/io.c:448
#1 0x0000fffff7d459bc in d_r_vsscanf (str=0xfffff7fde5e4 <buf_scratch+1372> "ffffa95e0000-ffffa95f0000 rwxp 00000000 00:00 0 ",
fmt=0xfffff7f38c90 "%016lx-%016lx %s %016lx %*s %lu %4096[^\n]", ap=...) at dynamorio/core/io.c:669
#2 0x0000fffff7d45ea0 in d_r_sscanf (str=0xfffff7fde5e4 <buf_scratch+1372> "ffffa95e0000-ffffa95f0000 rwxp 00000000 00:00 0 ",
fmt=0xfffff7f38c90 "%016lx-%016lx %s %016lx %*s %lu %4096[^\n]") at dynamorio/core/io.c:728
#3 0x0000fffff7ea309c in memquery_iterator_next (iter=0xffff2818f770) at dynamorio/core/unix/memquery_linux.c:254
#4 0x0000fffff7ea344c in memquery_from_os (pc=0xfffff24e9bc8 "(A@\271\037\005", info=0xffff2818f898, have_type=0xffff2818f85e)
at dynamorio/core/unix/memquery_linux.c:340
#5 0x0000fffff7e7e7c0 in query_memory_ex_from_os (pc=0xfffff24e9bc8 "(A@\271\037\005", info=0xffff2818f898)
at dynamorio/core/unix/os.c:9458
#6 0x0000fffff7e7e8b0 in get_memory_info_from_os (pc=0xfffff24e9bc8 "(A@\271\037\005", base_pc=0xffff2818f928, size=0xffff2818f920, prot=0xffff2818f91c)
at dynamorio/core/unix/os.c:9491
#7 0x0000fffff7ea52e0 in memcache_query_memory (pc=0xfffff24e9bc8 "(A@\271\037\005", out_info=0xffff2818f9a8)
at dynamorio/core/unix/memcache.c:378
#8 0x0000fffff7e7e668 in query_memory_ex (pc=0xfffff24e9bc8 "(A@\271\037\005", out_info=0xffff2818f9a8)
at dynamorio/core/unix/os.c:9418
#9 0x0000fffff7e7e71c in get_memory_info (pc=0xfffff24e9bc8 "(A@\271\037\005", base_pc=0x0, size=0x0, prot=0xffff2818fa24)
at dynamorio/core/unix/os.c:9438
#10 0x0000fffff7cfbca4 in check_thread_vm_area (dcontext=0xffff280f8660, pc=0xfffff24e9bc8 "(A@\271\037\005", tag=0xfffff24e9bc8 "(A@\271\037\005",
vmlist=0xffff2818fe10, flags=0xffff2818fe08, stop=0xffff2818fe58, xfer=false) at dynamorio/core/vmareas.c:8313
#11 0x0000fffff7e360b0 in check_new_page_start (dcontext=0xffff280f8660, bb=0xffff2818fdd0)
at dynamorio/core/arch/interp.c:720
#12 0x0000fffff7e3a734 in build_bb_ilist (dcontext=0xffff280f8660, bb=0xffff2818fdd0)
at dynamorio/core/arch/interp.c:3315
#13 0x0000fffff7e41b88 in build_basic_block_fragment (dcontext=0xffff280f8660, start=0xfffff24e9bc8 "(A@\271\037\005", initial_flags=0, link=true,
visible=true, for_trace=false, unmangled_ilist=0x0) at dynamorio/core/arch/interp.c:5129
#14 0x0000fffff7c178bc in d_r_dispatch (dcontext=0xffff280f8660) at dynamorio/core/dispatch.c:214
#15 0x0000fffff24e9740 in ?? ()
#16 0x0000ffffffffef00 in ?? ()
#17 0x0000fffff24ee748 in ?? ()
#18 0x000004bcbfd377b8 in ?? ()
Backtrace stopped: previous frame inner to this frame (corrupt stack?)
(gdb) p d_r_stats->num_fragments_pair.value
$4 = 96710
(gdb)
(gdb) c
Continuing.
^C
Program received signal SIGINT, Interrupt.
dynamorio_syscall () at dynamorio/core/drlibc/drlibc_aarch64.asm:67
67 dynamorio/core/drlibc/drlibc_aarch64.asm: No such file or directory.
(gdb) p d_r_stats->num_fragments_pair.value
$5 = 118441
(gdb) bt
#0 dynamorio_syscall () at dynamorio/core/drlibc/drlibc_aarch64.asm:67
#1 0x0000fffff7eb403c in read_syscall (fd=3, buf=0xfffff7fde0ac <buf_scratch+36>, nbytes=4067)
at dynamorio/core/drlibc/drlibc_unix.c:297
#2 0x0000fffff7eb41c8 in os_read (f=3, buf=0xfffff7fde0ac <buf_scratch+36>, count=4067)
at dynamorio/core/drlibc/drlibc_unix.c:374
#3 0x0000fffff7ea2e54 in memquery_iterator_next (iter=0xffff2818f770) at dynamorio/core/unix/memquery_linux.c:233
#4 0x0000fffff7ea344c in memquery_from_os (pc=0xfffff15c1c1c "\365\003", info=0xffff2818f898, have_type=0xffff2818f85e)
at dynamorio/core/unix/memquery_linux.c:340
#5 0x0000fffff7e7e7c0 in query_memory_ex_from_os (pc=0xfffff15c1c1c "\365\003", info=0xffff2818f898)
at dynamorio/core/unix/os.c:9458
#6 0x0000fffff7e7e8b0 in get_memory_info_from_os (pc=0xfffff15c1c1c "\365\003", base_pc=0xffff2818f928, size=0xffff2818f920, prot=0xffff2818f91c)
at dynamorio/core/unix/os.c:9491
#7 0x0000fffff7ea52e0 in memcache_query_memory (pc=0xfffff15c1c1c "\365\003", out_info=0xffff2818f9a8)
at dynamorio/core/unix/memcache.c:378
#8 0x0000fffff7e7e668 in query_memory_ex (pc=0xfffff15c1c1c "\365\003", out_info=0xffff2818f9a8)
at dynamorio/core/unix/os.c:9418
#9 0x0000fffff7e7e71c in get_memory_info (pc=0xfffff15c1c1c "\365\003", base_pc=0x0, size=0x0, prot=0xffff2818fa24)
at dynamorio/core/unix/os.c:9438
#10 0x0000fffff7cfbca4 in check_thread_vm_area (dcontext=0xffff280f8660, pc=0xfffff15c1c1c "\365\003", tag=0xfffff15c1c1c "\365\003",
vmlist=0xffff2818fe10, flags=0xffff2818fe08, stop=0xffff2818fe58, xfer=false) at dynamorio/core/vmareas.c:8313
#11 0x0000fffff7e360b0 in check_new_page_start (dcontext=0xffff280f8660, bb=0xffff2818fdd0)
at dynamorio/core/arch/interp.c:720
#12 0x0000fffff7e3a734 in build_bb_ilist (dcontext=0xffff280f8660, bb=0xffff2818fdd0)
at dynamorio/core/arch/interp.c:3315
#13 0x0000fffff7e41b88 in build_basic_block_fragment (dcontext=0xffff280f8660, start=0xfffff15c1c1c "\365\003", initial_flags=0, link=true, visible=true,
for_trace=false, unmangled_ilist=0x0) at dynamorio/core/arch/interp.c:5129
#14 0x0000fffff7c178bc in d_r_dispatch (dcontext=0xffff280f8660) at dynamorio/core/dispatch.c:214
#15 0x0000fffff15c1c14 in ?? ()
#16 0x0000fffff15c6d68 in ?? ()
Backtrace stopped: previous frame inner to this frame (corrupt stack?)Xref #1979 where that vmareas checklevel=1 check is very slow on Mac too.