Difference between revisions of "Performance research"

From CRIU
Jump to navigation Jump to search
(added perf info)
Line 34: Line 34:
 
     11 openat(AT_FDCWD, "/proc/$pid/map_files", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4
 
     11 openat(AT_FDCWD, "/proc/$pid/map_files", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4
  
=== <code>parasite_fuxup_vdso</code> ===
+
=== setns ===
  
The 2nd longest routine. It takes ~ 0.07 seconds on dump.
+
Starting from the 2nd call, setns() calls synchronize_rcu in kernel. Result -- 4 setns are 6% of 4 tests dump time.
 
 
=== Too many readlink-s ===
 
 
 
Some files are readlinked 3-4 times in a row.
 
  
  

Revision as of 19:21, 15 September 2014

Written here are performance issues found.

Timing stats of live migration of a small container with 11 tasks is

  • Total time ~3.5 seconds
  • Frozen time ~3.0 seconds
    • Pre-dump stages ~0.5 seconds each
    • Restore time ~1.9 seconds
    • Images transfer time ~0.3 seconds

Below is the list of issues found

Images IO

Too many write-s and read-s. Each small object issues a write/read request into file. Need to improve.

Dump

Surprisingly, but the mem-drain time is not the biggest. It's "only" ~0.02 seconds. There are places in code that take longer.

parse_smaps

Time spent in this routine is up to 0.2 seconds on dump. This one exploits /proc heavily. For a container with 11 tasks the syscall stats look like

   834 read
  1451 fstat
  1462 close
  1642 openat

while opens and stats happen on

   193 openat(4, "map-symlink", O_RDONLY) = -1 ENOENT (No such file or directory)
  1438 openat(4, "map-symlink", O_RDONLY) = 5
    11 openat(AT_FDCWD, "/proc/$pid/map_files", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4

setns

Starting from the 2nd call, setns() calls synchronize_rcu in kernel. Result -- 4 setns are 6% of 4 tests dump time.


Restore

Fork vs VMA restore

We restore task's mappings before it goes forking to handle COW. This effectively serializes forking.

Restoring VMAs

There are 4 stages in VMA restore. Relative times of each are below

  • Reading images 1%
  • Mapping huuge premap area << 1%
  • (Re-)mapping sub-areas 73%
  • Filling area with data 26%

The 3rd stage has two parts. With timings:

  • Opening filemap fd 85%
  • Maping vma 15%

Parse maps instead of smaps

When parsing self maps for restorer hint, it's enough to read smaller /proc/self/maps

Perf stats

Here's how perf tree looks like

10.69%     criu  [.] pb_write_one                        
              |
              --- pb_write_one
                 |          
                 |--18.74%-- dump_task_rlims
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                 |--18.63%-- dump_task_mappings
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                 |--18.51%-- parasite_dump_sigacts_seized
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                 |--9.51%-- dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                 |--9.30%-- dump_one_reg_file
                 |          dump_task_exe_link
                 |          dump_task_mm
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                 |--9.20%-- dump_task_mm
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                 |--8.57%-- dump_task_fs
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                  --7.54%-- write_pagemap_loc
                            page_xfer_dump_pages
                            __parasite_dump_pages_seized
                            parasite_dump_pages_seized
                            dump_one_task
                            cr_dump_tasks
                            main
                            __libc_start_main
    8.86%     criu  [.] generate_iovs                       
              |
              --- generate_iovs
                  __parasite_dump_pages_seized
                  parasite_dump_pages_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    8.59%     criu  [.] should_dump_page                    
              |
              --- should_dump_page
                 |          
                 |--81.22%-- generate_iovs
                 |          __parasite_dump_pages_seized
                 |          parasite_dump_pages_seized
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                  --18.78%-- __parasite_dump_pages_seized
                            parasite_dump_pages_seized
                            dump_one_task
                            cr_dump_tasks
                            main
                            __libc_start_main
    5.01%     criu  [.] is_vma_range_fmt                    
              |
              --- is_vma_range_fmt
                 |          
                 |--80.15%-- parse_smaps
                 |          collect_mappings
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                  --19.85%-- collect_mappings
                            dump_one_task
                            cr_dump_tasks
                            main
                            __libc_start_main
    3.04%     criu  [.] print_on_level                      
              |
              --- print_on_level
                 |          
                 |--33.73%-- parasite_wait_ack
                 |          __parasite_wait_daemon_ack
                 |          parasite_execute_daemon
                 |          parasite_fixup_vdso
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                 |--33.28%-- parasite_start_daemon
                 |          parasite_infect_seized
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                  --32.99%-- __parasite_wait_daemon_ack
                            parasite_drain_fds_seized
                            dump_task_files_seized
                            dump_one_task
                            cr_dump_tasks
                            main
                            __libc_start_main
    3.03%     criu  [.] open_image_at                       
              |
              --- open_image_at
                 |          
                 |--66.87%-- cr_fdset_open_range
                 |          cr_task_fdset_open
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                  --33.13%-- dump_task_files_seized
                            dump_one_task
                            cr_dump_tasks
                            main
                            __libc_start_main
    3.00%     criu  [.] parse_vmflags                       
              |
              --- parse_vmflags
                 |          
                 |--66.59%-- parse_smaps
                 |          collect_mappings
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                  --33.41%-- collect_mappings
                            dump_one_task
                            cr_dump_tasks
                            main
                            __libc_start_main
    3.00%     criu  [.] vma_opt_str                         
              |
              --- vma_opt_str
                 |          
                 |--66.31%-- pr_vma
                 |          |          
                 |          |--50.06%-- dump_task_mappings
                 |          |          dump_one_task
                 |          |          cr_dump_tasks
                 |          |          main
                 |          |          __libc_start_main
                 |          |          
                 |           --49.94%-- collect_mappings
                 |                     dump_one_task
                 |                     cr_dump_tasks
                 |                     main
                 |                     __libc_start_main
                 |          
                  --33.69%-- collect_mappings
                            dump_one_task
                            cr_dump_tasks
                            main
                            __libc_start_main
    2.19%     criu  [.] do_open_proc                        
              |
              --- do_open_proc
                 |          
                 |--36.18%-- parse_pid_stat_small
                 |          seize_task
                 |          get_children
                 |          collect_task
                 |          collect_pstree
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                 |--31.99%-- parse_threads
                 |          collect_threads
                 |          collect_task
                 |          get_children
                 |          collect_task
                 |          collect_pstree
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                  --31.84%-- seize_task
                            get_children
                            collect_task
                            collect_pstree
                            cr_dump_tasks
                            main
                            __libc_start_main
    2.03%     criu  [.] parse_smaps                         
              |
              --- parse_smaps
                  collect_mappings
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    2.02%     criu  [.] try_add_page_to                     
              |
              --- try_add_page_to
                  try_add_page
                  page_pipe_add_page
                  generate_iovs
                  __parasite_dump_pages_seized
                  parasite_dump_pages_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    2.02%     criu  [.] ptrace_peek_area                    
              |
              --- ptrace_peek_area
                  ptrace_swap_area
                  __parasite_execute_syscall
                  syscall_seized
                  mmap_seized
                  parasite_map_exchange
                  parasite_infect_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    2.01%     criu  [.] collect_mappings                    
              |
              --- collect_mappings
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    2.01%     criu  [.] __parasite_dump_pages_seized        
              |
              --- __parasite_dump_pages_seized
                  parasite_dump_pages_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    2.00%     criu  [.] get_task_regs                       
              |
              --- get_task_regs
                  parasite_start_daemon
                  parasite_infect_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    2.00%     criu  [.] parasite_args_s                     
              |
              --- parasite_args_s
                 |          
                 |--50.05%-- parasite_dump_pages_seized
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                  --49.95%-- dump_one_task
                            cr_dump_tasks
                            main
                            __libc_start_main
    2.00%     criu  [.] parasite_stop_on_syscall            
              |
              --- parasite_stop_on_syscall
                  parasite_unmap
                  parasite_cure_remote
                  parasite_cure_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    1.97%     criu  [.] open_pid_proc                       
              |
              --- open_pid_proc
                 |          
                 |--51.54%-- parasite_fixup_vdso
                 |          dump_one_task
                 |          cr_dump_tasks
                 |          main
                 |          __libc_start_main
                 |          
                  --48.46%-- do_open_proc
                            dump_task_fs
                            dump_one_task
                            cr_dump_tasks
                            main
                            __libc_start_main
    1.55%     criu  [.] dump_one_file                       
              |
              --- dump_one_file
                  dump_task_files_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    1.13%     criu  [.] alloc_cr_fdset                      
              |
              --- alloc_cr_fdset
                  cr_task_fdset_open
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    1.03%     criu  [.] unseize_task_and_threads            
              |
              --- unseize_task_and_threads
                  pstree_switch_state
                  cr_dump_tasks
                  main
                  __libc_start_main
    1.02%     criu  [.] timeval_accumulate                  
              |
              --- timeval_accumulate
                  timing_stop
                  __parasite_dump_pages_seized
                  parasite_dump_pages_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    1.01%     criu  [.] parasite_dump_misc_seized           
              |
              --- parasite_dump_misc_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    1.01%     criu  [.] parse_posix_timers                  
              |
              --- parse_posix_timers
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main
    1.01%     criu  [.] INIT_LIST_HEAD                      
              |
              --- INIT_LIST_HEAD
                  __parasite_dump_pages_seized
                  parasite_dump_pages_seized
                  dump_one_task
                  cr_dump_tasks
                  main
                  __libc_start_main