app1.log

% 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

app2.log

% 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

calc.rb

#!/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 }