Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

check_thread_vm_area consistency checks very slow on AArch64 and OSX #4257

Open
derekbruening opened this issue Apr 17, 2020 · 0 comments
Open

check_thread_vm_area consistency checks very slow on AArch64 and OSX #4257

derekbruening opened this issue Apr 17, 2020 · 0 comments
Assignees
@derekbruening
Labels
OpSys-AArch64 Performance

Comments

@derekbruening
Copy link
Contributor

The app in #3956 and #4256 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.
@derekbruening derekbruening self-assigned this Apr 17, 2020
derekbruening added a commit that referenced this issue Apr 17, 2020
@derekbruening
i#4257 slow memquery: Avoid slow vmarea check on AArch64
20e3be9 
Raises the consistency check at the end of check_thread_vm_area to
default to checklevel 3 on AArch64, matching Mac64 where it is also
observed to be quite slow.

Issue: #4257
@derekbruening derekbruening mentioned this issue Apr 17, 2020
Merged
derekbruening added a commit that referenced this issue Apr 17, 2020
@derekbruening
i#4257 slow memquery: Avoid slow vmarea check on AArch64 (#4258)
4f9b460 
Raises the consistency check at the end of check_thread_vm_area to
default to checklevel 3 on AArch64, matching Mac64 where it is also
observed to be quite slow.

Issue: #4257
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@derekbruening derekbruening

Labels
OpSys-AArch64 Performance
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@derekbruening