System call analysis report
Martin Pool
mbp at sourcefrog.net
Thu May 10 03:28:24 BST 2007
On 5/10/07, Ian Clatworthy <ian.clatworthy at internode.on.net> wrote:
>
> All,
>
> Attached is one of the reports I'm putting together for the sprint in
> London next week. The idea is to run a 'user script' containing various
> Use Cases and to measure and report on various things: time taken, disk
> space used, system calls made, network traffic, disk io, etc. The script
> can be run on different source code trees so we can see how well we
> scale or otherwise. As we address bottlenecks over time, we can also
> check we haven't pushed the problem elsewhere - the good ol'
> whack-a-mole tuning challenge. :-)
>
> This particular report shows data from a script that was run on the
> source code tree created using this command in the 0.16 branch:
>
> bzr export bzr0.16.tar.gz
>
> The resulting tree contains 613 files. I'll have reports on much larger
> trees (e.g. 50k files) real soon.
>
> If you have any suggestions on making this report more useful (e.g. by
> filtering the set of system calls to just the 'useful' ones), let me
> know. I'm keen to turn the vast amounts of data being collected by
> strace and other tools into information we can action.
>
That does look pretty interesting -- I guess the real test will be when
someone tries to use it in evaluating a change to the code, or if we catch
some performance regressions by looking at it.
I have a couple of random thoughts -- may or may not be useful so you don't
need to do them:
* I like the way it displays the deltas rather than all absolute values;
you could maybe make them red or green depending.
* strace has a mode (-T) where it can show the time spent in system calls,
or if you used -c to generate this table then you should have the time
already. It might be good to include that as a second row in each cell.
*
If you see anything that looks really weird, let me know (as it may be a
> bug in the report). Getting repeatable, meaningful benchmark results
> isn't simple to say the least though my (perhaps naive) expectation is
> that system call counts ought to be reasonably repeatable over time, at
> least for the io system calls. I hope to confirm that today.
>
> As always, all feedback welcome.
>
> Ian C.
>
> System Call Delta Report Tree:bzr0.16 Test Suite:common When:Wed May 9
> 16:58:02 2007 Run ID:7816
>
> Actions
>
> - InitialImportTask.init <#112736ecb3caec44_initialimporttask-init>
> - InitialImportTask.add <#112736ecb3caec44_initialimporttask-add>
> - InitialImportTask.commit<#112736ecb3caec44_initialimporttask-commit>
> - BranchTask.clone <#112736ecb3caec44_branchtask-clone>
> - AddTask.status <#112736ecb3caec44_addtask-status>
> - AddTask.diff <#112736ecb3caec44_addtask-diff>
> - AddTask.commit <#112736ecb3caec44_addtask-commit>
> - ChangeTask.status <#112736ecb3caec44_changetask-status>
> - ChangeTask.diff <#112736ecb3caec44_changetask-diff>
> - ChangeTask.commit <#112736ecb3caec44_changetask-commit>
> - HelpTask.help <#112736ecb3caec44_helptask-help>
> - HelpTask.helpOnCommand <#112736ecb3caec44_helptask-helponcommand>
>
> InitialImportTask.init <#112736ecb3caec44_id1> System Call bzr0.16
> bzr0.15 bzr0.14 _llseek 31 +2 -11 access 14 brk 29 -3 -7 chmod 24
> +3 close 405 +1 -35 execve 6 exit_group 1 fcntl64 8 -4 fstat64
> 573 -11 -66 ftruncate64 3 +1 -3 futex 3164 -8 -3008 getcwd 2 +1
> getdents64 8 getrlimit 1 gettimeofday 20 +1 +6 ioctl 6 +6
> lstat64 56 -36 mkdir 17 -1 mmap2 261 -9 -28 mprotect 2 munmap 173
> -5 -23 open 1841 -9 -269 read 549 -3 -69 readlink 3 rename 16 +3
> rmdir 5 rt_sigaction 68 -1 rt_sigprocmask 1 sendto 1
> set_thread_area 2 set_tid_address 1 stat64 649 -2 -81 time 1
> uname 6 unlink 4 +1 write 41 +3 +23
> InitialImportTask.add <#112736ecb3caec44_id2> System Call bzr0.16
> bzr0.15 bzr0.14 _llseek 25 -5 access 13 brk 30 -1 +4 chmod 0 +1
> close 421 -3 -27 execve 6 exit_group 1 fcntl64 55 -2 fstat64 587
> -8 -45 ftruncate64 1 -1 futex 8174 -78 -7897 getcwd 2 getdents64 107
> getrlimit 1 gettimeofday 7 ioctl 5 lstat64 646 -18 mkdir
> 1 mmap2 253 -7 -12 mprotect 2 munmap 162 -3 -14 open 1903 -15 -233
> read 523 -5 -50 readlink 3 rename 2 +1 rmdir 1 rt_sigaction 68
> -1 rt_sigprocmask 1 sendto 1 set_thread_area 2
> set_tid_address 1 stat64 641 -4 -72 time 1 uname 2 +1 unlink 1
> write 38 +1
> InitialImportTask.commit <#112736ecb3caec44_id3> System Call bzr0.16
> bzr0.15 bzr0.14 _llseek 600 -1 access 13 brk 134 +36 +67 chmod 1452
> +4 close 2769 -7 -28 execve 6 exit_group 1 fcntl64 6 -2
> fstat64 3517 -12 -43 ftruncate64 1 -1 futex 84083 -10779 -80809 getcwd 1
> getdents64 8 getrlimit 2 gettimeofday 627 +1793 ioctl 6
> lstat64 2388 -632 mkdir 228 mmap2 842 -3 -20 mprotect 2 munmap
> 748 -5 -15 open 5780 -19 -237 read 4475 -11 -61 readlink 3 rename 7
> +4 rmdir 3 rt_sigaction 68 -1 rt_sigprocmask 1 sendto 1
> set_thread_area 2 set_tid_address 1 stat64 1297 -4 -74 time 1
> uname 5 unlink 3 write 3713 +1 +3027
> BranchTask.clone <#112736ecb3caec44_id4> System Call bzr0.16 bzr0.15
> bzr0.14 _llseek 1288 -18 -57 access 14 brk 57 +7 +17 chmod 800
> close 4696 -40 -93 execve 6 exit_group 1 fcntl64 28 -10 -22
> fstat64 7858 -74 -162 ftruncate64 3 +1 -3 futex 92323 -3950 -84949 getcwd
> 2 getdents64 12 getrlimit 1 gettimeofday 659 +2412 ioctl 7
> +8 lstat64 749 -114 mkdir 299 -3 mmap2 3275 -46 -69 mprotect 2
> munmap 3179 -36 -65 open 7741 -186 -443 read 4577 -82 -183 readlink 3
> rename 650 -1 rmdir 14 -3 rt_sigaction 68 -1 rt_sigprocmask 1
> sendto 1 set_thread_area 2 set_tid_address 1 stat64 1290 -52
> -129 time 2 -1 -1 umask 18 uname 15 -3 unlink 23 -10 -13 write 5798
> -37 +4809
> AddTask.status <#112736ecb3caec44_id5> System Call bzr0.16 bzr0.15
> bzr0.14 _llseek 590 -2 +3 access 13 brk 31 -1 -5 close 979 -1 -19
> execve 6 exit_group 1 fcntl64 58 -1 -5 fstat64 1147 -6 -27
> ftruncate64 1 -1 futex 9187 -49 -9068 getcwd 1 getdents64 107
> getrlimit 1 gettimeofday 4 +565 ioctl 5 lstat64 696 -20 mmap2
> 251 -7 -8 mprotect 2 munmap 162 -3 -9 open 2388 -14 -220 read 2210 -3
> -38 readlink 3 rename 0 +1 rt_sigaction 68 -1 rt_sigprocmask 1
> sendto 1 set_thread_area 2 set_tid_address 1 stat64 632 -4 -70
> time 1 uname 1 +1 unlink 1 -1 -1 write 17 -2 +560
> AddTask.diff <#112736ecb3caec44_id6> System Call bzr0.16 bzr0.15
> bzr0.14 _llseek 19 +1 access 13 brk 31 -3 -3 close 407 -1 -78
> execve 6 exit_group 1 fcntl64 61 -57 fstat64 567 -6 -93 futex
> 5575 -44 -5471 getcwd 1 getdents64 107 -99 getrlimit 1
> gettimeofday 5 -1 ioctl 5 lstat64 749 -123 mmap2 244 -6 -13
> mprotect 2 munmap 156 -2 -13 open 1809 -13 -308 read 503 -2 -45
> readlink 3 rt_sigaction 68 -1 rt_sigprocmask 1 sendto 1
> set_thread_area 2 set_tid_address 1 stat64 629 -4 -79 time 1
> uname 1 write 8 +1
> AddTask.commit <#112736ecb3caec44_id7> System Call bzr0.16 bzr0.15
> bzr0.14 _llseek 35 -2 +8 access 13 brk 34 -1 close 405 -7 -22
> execve 6 exit_group 1 fcntl64 7 -1 -3 fstat64 588 -12 -25 futex
> 15060 -164 -14879 getcwd 1 getdents64 8 getrlimit 2
> gettimeofday 14 +1 ioctl 6 lstat64 2388 -632 mkdir 3 mmap2 274
> -4 -13 mprotect 2 munmap 182 -6 -8 open 1942 -20 -227 read 612 -13 -45
> readlink 3 rename 6 rmdir 3 rt_sigaction 68 -1
> rt_sigprocmask 1 sendto 1 set_thread_area 2 set_tid_address 1
> stat64 680 -4 -71 time 1 uname 4 unlink 4 -1 -1 write 637 -1
> +4
> ChangeTask.status <#112736ecb3caec44_id8> System Call bzr0.16 bzr0.15
> bzr0.14 _llseek 23 +5 access 13 brk 31 -1 -5 close 414 -1 -20
> execve 6 exit_group 1 fcntl64 57 -4 fstat64 582 -6 -28
> ftruncate64 1 -1 futex 6116 -45 -6001 getcwd 1 getdents64 107
> getrlimit 1 gettimeofday 5 -1 ioctl 5 lstat64 696 -20 mmap2
> 250 -6 -7 mprotect 2 munmap 161 -2 -8 open 1822 -13 -224 read 519 -2
> -35 readlink 3 rt_sigaction 68 -1 rt_sigprocmask 1 sendto 1
> set_thread_area 2 set_tid_address 1 stat64 632 -4 -71 time 1
> uname 1 write 14 +1 -3
> ChangeTask.diff <#112736ecb3caec44_id9> System Call bzr0.16 bzr0.15
> bzr0.14 _llseek 19 +1 access 13 brk 31 -3 -3 close 407 -1 -78
> execve 6 exit_group 1 fcntl64 61 -57 fstat64 567 -6 -93 futex
> 5575 -44 -5471 getcwd 1 getdents64 107 -99 getrlimit 1
> gettimeofday 5 -1 ioctl 5 lstat64 749 -123 mmap2 244 -6 -13
> mprotect 2 munmap 156 -2 -13 open 1809 -13 -308 read 503 -2 -45
> readlink 3 rt_sigaction 68 -1 rt_sigprocmask 1 sendto 1
> set_thread_area 2 set_tid_address 1 stat64 629 -4 -79 time 1
> uname 1 write 8 +1
> ChangeTask.commit <#112736ecb3caec44_id10> System Call bzr0.16
> bzr0.15 bzr0.14 _llseek 33 +10 access 13 brk 34 +1 -1 close 405 -7
> -22 execve 6 exit_group 1 fcntl64 6 -2 fstat64 588 -12 -25 futex
> 15060 -164 -14879 getcwd 1 getdents64 8 getrlimit 2
> gettimeofday 14 +1 ioctl 6 lstat64 2388 -632 mkdir 3 mmap2 273
> -3 -12 mprotect 2 munmap 181 -5 -7 open 1941 -19 -226 read 612 -13 -45
> readlink 3 rename 6 rmdir 3 rt_sigaction 68 -1
> rt_sigprocmask 1 sendto 1 set_thread_area 2 set_tid_address 1
> stat64 680 -4 -71 time 1 uname 4 unlink 3 write 635 +1 +6
> HelpTask.help <#112736ecb3caec44_id11> System Call bzr0.16 bzr0.15
> bzr0.14 _llseek 6 access 10 +1 brk 19 -2 -6 close 220 -2 -36 execve
> 6 exit_group 1 fcntl64 4 fstat64 316 -3 -55 futex 1721 -42
> -1648 getdents64 8 getrlimit 1 gettimeofday 2 ioctl 5
> lstat64 6 mmap2 157 -5 -18 mprotect 2 munmap 95 -1 -19 open 1040
> -12 -142 read 302 -3 -69 readlink 3 rt_sigaction 68 -1
> rt_sigprocmask 1 sendto 1 set_thread_area 2 set_tid_address 1
> stat64 416 -3 -48 time 1 uname 1 write 9 -1
> HelpTask.helpOnCommand <#112736ecb3caec44_id12> System Call bzr0.16
> bzr0.15 bzr0.14 _llseek 6 access 10 +1 brk 21 -3 -7 close 230 -2
> -36 execve 6 exit_group 1 fcntl64 4 fstat64 331 -3 -55 futex
> 1907 -18 -1822 getdents64 8 getrlimit 1 gettimeofday 2 ioctl 5
> lstat64 6 mmap2 162 -1 -19 mprotect 2 munmap 100 -2 -18 open
> 1084 -12 -142 read 318 -3 -69 readlink 3 rt_sigaction 68 -1
> rt_sigprocmask 1 sendto 1 set_thread_area 2 set_tid_address 1
> stat64 451 -3 -48 time 1 uname 1 write 9 -1
>
>
--
Martin
-------------- next part --------------
An HTML attachment was scrubbed...
URL: https://lists.ubuntu.com/archives/bazaar/attachments/20070510/397aa8af/attachment-0001.htm
More information about the bazaar
mailing list