There is a very nice example on the O’reilly ‘Linux Under The Hood’ training about using strace to compare performance of two commands that provide the same output but with different calls. The two different commands were: ls and echo *, that they both provide the listing of the current directory.
First using the strace with ls:
kosmas:$ strace -c ls abi-4.13.0-45-generic config-4.4.0-31-generic initrd.img-4.4.0-31-generic System.map-4.15.0-123-generic vmlinuz-4.15.0-123-generic abi-4.13.0-46-generic efi memtest86+.bin System.map-4.15.0-124-generic vmlinuz-4.15.0-124-generic abi-4.4.0-31-generic grub memtest86+.elf System.map-4.15.0-126-generic vmlinuz-4.15.0-126-generic config-4.13.0-45-generic initrd.img-4.13.0-45-generic memtest86+_multiboot.bin System.map-4.4.0-31-generic vmlinuz-4.4.0-31-generic config-4.13.0-46-generic initrd.img-4.13.0-46-generic retpoline-4.13.0-45-generic vmlinuz-4.13.0-45-generic vmlinuz-4.4.0-31-generic.efi.signed config-4.15.0-123-generic initrd.img-4.15.0-123-generic retpoline-4.13.0-46-generic vmlinuz-4.13.0-45-generic.efi.signed config-4.15.0-124-generic initrd.img-4.15.0-124-generic System.map-4.13.0-45-generic vmlinuz-4.13.0-46-generic config-4.15.0-126-generic initrd.img-4.15.0-126-generic System.map-4.13.0-46-generic vmlinuz-4.13.0-46-generic.efi.signed % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 15.81 0.000095 12 8 write 14.64 0.000088 7 12 mprotect 13.48 0.000081 5 17 mmap 9.98 0.000060 7 9 openat 7.82 0.000047 4 11 close 7.32 0.000044 22 2 getdents 6.82 0.000041 6 7 read 5.66 0.000034 3 10 fstat 4.99 0.000030 4 8 8 access 3.16 0.000019 10 2 2 statfs 2.00 0.000012 12 1 munmap 1.83 0.000011 4 3 brk 1.66 0.000010 5 2 ioctl 1.50 0.000009 5 2 rt_sigaction 0.67 0.000004 4 1 rt_sigprocmask 0.67 0.000004 4 1 arch_prctl 0.67 0.000004 4 1 set_tid_address 0.67 0.000004 4 1 set_robust_list 0.67 0.000004 4 1 prlimit64 0.00 0.000000 0 1 execve ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000601 100 10 total
And using the same with echo *
kosmas:$ strace -c echo * abi-4.13.0-45-generic abi-4.13.0-46-generic abi-4.4.0-31-generic config-4.13.0-45-generic config-4.13.0-46-generic config-4.15.0-123-generic config-4.15.0-124-generic config-4.15.0-126-generic config-4.4.0-31-generic efi grub initrd.img-4.13.0-45-generic initrd.img-4.13.0-46-generic initrd.img-4.15.0-123-generic initrd.img-4.15.0-124-generic initrd.img-4.15.0-126-generic initrd.img-4.4.0-31-generic memtest86+.bin memtest86+.elf memtest86+_multiboot.bin retpoline-4.13.0-45-generic retpoline-4.13.0-46-generic System.map-4.13.0-45-generic System.map-4.13.0-46-generic System.map-4.15.0-123-generic System.map-4.15.0-124-generic System.map-4.15.0-126-generic System.map-4.4.0-31-generic vmlinuz-4.13.0-45-generic vmlinuz-4.13.0-45-generic.efi.signed vmlinuz-4.13.0-46-generic vmlinuz-4.13.0-46-generic.efi.signed vmlinuz-4.15.0-123-generic vmlinuz-4.15.0-124-generic vmlinuz-4.15.0-126-generic vmlinuz-4.4.0-31-generic vmlinuz-4.4.0-31-generic.efi.signed % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 1 read 0.00 0.000000 0 1 write 0.00 0.000000 0 5 close 0.00 0.000000 0 4 fstat 0.00 0.000000 0 6 mmap 0.00 0.000000 0 4 mprotect 0.00 0.000000 0 1 munmap 0.00 0.000000 0 3 brk 0.00 0.000000 0 3 3 access 0.00 0.000000 0 1 execve 0.00 0.000000 0 1 arch_prctl 0.00 0.000000 0 3 openat ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 33 3 total
So the difference in time is 0.00000 for the echo and 0.000601 for the ls.
Similarly the number of calls for the echo is 33, but ls is using 100.