Skip to content

Instantly share code, notes, and snippets.

@udzura udzura/app1.log Secret
Last active Dec 4, 2019

Embed
What would you like to do?
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
62.77 7.969380 2656459 3 poll
8.40 1.066430 41 25462 160 lstat
8.36 1.061165 224 4735 2 read
6.81 0.864902 26209 33 1 futex
5.39 0.683872 117 5833 1680 openat
1.42 0.180468 43 4157 close
1.26 0.159701 39 4000 fstat
1.25 0.159272 63 2490 350 stat
0.61 0.077590 37 2046 fcntl
0.60 0.076069 37 2030 2026 ioctl
0.57 0.072337 39 1811 getuid
0.55 0.070334 38 1812 geteuid
0.54 0.068577 37 1811 getgid
0.54 0.068374 37 1812 getegid
0.36 0.045740 106 428 getdents64
0.22 0.027461 56 485 brk
0.09 0.011636 46 248 mmap
0.07 0.009388 391 24 20 newfstatat
0.05 0.005871 36 163 lseek
0.03 0.004065 48 83 mprotect
0.03 0.003762 752 5 3 execve
0.02 0.002569 107 24 munmap
0.01 0.001761 35 50 chdir
0.01 0.001192 39 30 getcwd
0.01 0.001047 58 18 getpid
0.00 0.000606 33 18 rt_sigaction
0.00 0.000298 149 2 clone
0.00 0.000271 90 3 mremap
0.00 0.000242 60 4 2 access
0.00 0.000237 33 7 getrandom
0.00 0.000235 78 3 set_robust_list
0.00 0.000233 232 1 sysinfo
0.00 0.000135 67 2 pipe2
0.00 0.000135 67 2 sigaltstack
0.00 0.000128 64 2 prctl
0.00 0.000100 49 2 umask
0.00 0.000099 32 3 rt_sigprocmask
0.00 0.000092 92 1 madvise
0.00 0.000087 43 2 sched_getaffinity
0.00 0.000081 26 3 prlimit64
0.00 0.000071 35 2 sched_yield
0.00 0.000060 60 1 write
0.00 0.000057 28 2 arch_prctl
0.00 0.000048 48 1 writev
0.00 0.000037 36 1 uname
0.00 0.000030 29 1 clock_gettime
0.00 0.000027 27 1 set_tid_address
------ ----------- ----------- --------- --------- ----------------
100.00 12.696271 59657 4244 total
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
62.77 8.491337 2122834 4 poll
9.34 1.263400 49 25462 160 lstat
8.16 1.104500 233 4738 4 read
6.73 0.910059 23334 39 futex
4.54 0.613952 105 5833 1680 openat
1.41 0.191409 46 4157 close
1.37 0.185370 46 4000 fstat
1.17 0.158181 63 2490 350 stat
0.69 0.093207 51 1811 getuid
0.64 0.086426 42 2046 fcntl
0.63 0.084956 41 2030 2026 ioctl
0.59 0.079498 43 1811 getgid
0.56 0.076364 42 1812 getegid
0.56 0.075975 41 1812 geteuid
0.30 0.040745 95 428 getdents64
0.20 0.026497 56 469 brk
0.09 0.012775 51 249 mmap
0.06 0.008687 361 24 20 newfstatat
0.05 0.007035 43 163 lseek
0.03 0.004295 51 83 mprotect
0.02 0.002683 536 5 3 execve
0.02 0.002540 101 25 munmap
0.02 0.002253 45 50 chdir
0.01 0.001304 43 30 getcwd
0.01 0.000930 51 18 rt_sigaction
0.01 0.000844 42 20 getpid
0.00 0.000386 55 7 getrandom
0.00 0.000301 100 3 rt_sigprocmask
0.00 0.000299 149 2 clone
0.00 0.000297 98 3 set_robust_list
0.00 0.000269 53 5 mremap
0.00 0.000266 88 3 prlimit64
0.00 0.000228 57 4 2 access
0.00 0.000204 102 2 prctl
0.00 0.000163 163 1 writev
0.00 0.000116 57 2 sigaltstack
0.00 0.000109 109 1 sysinfo
0.00 0.000092 45 2 write
0.00 0.000083 41 2 pipe2
0.00 0.000076 76 1 madvise
0.00 0.000066 32 2 sched_yield
0.00 0.000065 32 2 sched_getaffinity
0.00 0.000061 30 2 umask
0.00 0.000055 27 2 arch_prctl
0.00 0.000040 40 1 set_tid_address
0.00 0.000035 35 1 clock_gettime
0.00 0.000030 30 1 uname
------ ----------- ----------- --------- --------- ----------------
100.00 13.528462 59658 4245 total
#!/usr/bin/env ruby
# Usage:
# ruby /calc.rb <app's root> <times>
# e.g. ruby /calc.rb /app1 50
wd = ARGV[0]
cnt = ARGV[1] || 1000
cnt = cnt.to_i
res = Hash.new {|h, k| h[k] = Array.new }
Dir.chdir wd do
cnt.times do |i|
unless system "echo 3 > /mysys/vm/drop_caches"
raise "Failed clear kernel cache"
end
sleep 0.2
out = `strace -cfw -eopenat,read,lstat,getdents64 bin/rails runner 'puts Rails::VERSION::STRING' 2>&1`
unless out.empty?
out.lines.each do |l|
row = l.split
#p row
if %w(openat read lstat getdents64).include? row.last
res[row.last] << row[1]
end
end
end
print("Progress: #{i+1}/#{cnt} (%.2f%%)\r" % ((i+1).to_f / cnt * 100))
end
end
puts
puts "-" * 24
puts " %-10s %-10s %-10s %-10s" % %w(openat read lstat getdents64)
puts "AVG: %0.8f %0.8f %0.8f %0.8f" % %w(openat read lstat getdents64).map{|k| res[k].map(&:to_f).sum / cnt }
puts "MAX: %0.8f %0.8f %0.8f %0.8f" % %w(openat read lstat getdents64).map{|k| res[k].map(&:to_f).max }
puts "MIN: %0.8f %0.8f %0.8f %0.8f" % %w(openat read lstat getdents64).map{|k| res[k].map(&:to_f).min }
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.