Skip to content

Instantly share code, notes, and snippets.

@jumanjiman

jumanjiman/puppet-compilation-time.rb

Created August 15, 2012 18:32
Show Gist options
  • Save jumanjiman/3362180 to your computer and use it in GitHub Desktop.
Save jumanjiman/3362180 to your computer and use it in GitHub Desktop.
Download ZIP
read /var/log/messages in ruby 3 different ways for performance profiling
Raw
puppet-compilation-time.rb
#!/usr/bin/env ruby
require 'fileutils'
require 'net/smtp'
today = %x!date +'%Y-%m-%d'!.chomp
counter = 0
sum = 0.0
# see summary 1
#begin
# File.open('/var/log/messages').each_line do |line|
# if m = /^#{today}.*Compiled.*in ([[:digit:]\.]+) seconds$/.match(line)
# counter += 1
# sum += m[1].to_f
# end
# end
#end
#puts "average catalog compilation time in seconds: #{sum/counter}"
# see summary 2
#begin
# File.open('/var/log/messages').readlines.each do |line|
# if m = /^#{today}.*Compiled.*in ([[:digit:]\.]+) seconds$/.match(line)
# counter += 1
# sum += m[1].to_f
# end
# end
#end
#puts "average catalog compilation time in seconds: #{sum/counter}"
# see summary 3
begin
File.open('/var/log/messages') do |f|
until f.eof? do
if m = /^#{today}.*Compiled.*in ([[:digit:]\.]+) seconds$/.match(f.readline)
counter += 1
sum += m[1].to_f
end
end
end
end
puts "average catalog compilation time in seconds: #{sum/counter}"
Raw
summary1
Process 25689 attached
Process 25689 detached
average catalog compilation time in seconds: 11.06875
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
72.22 0.000104 0 42065 rt_sigprocmask
6.94 0.000010 0 697 read
5.56 0.000008 0 79 mmap
4.86 0.000007 0 316 253 close
4.17 0.000006 0 232 209 stat
3.47 0.000005 5 1 wait4
2.78 0.000004 0 95 brk
0.00 0.000000 0 2 write
0.00 0.000000 0 58 open
0.00 0.000000 0 38 fstat
0.00 0.000000 0 2 1 lseek
0.00 0.000000 0 32 mprotect
0.00 0.000000 0 14 munmap
0.00 0.000000 0 33 rt_sigaction
0.00 0.000000 0 12 4 access
0.00 0.000000 0 1 pipe
0.00 0.000000 0 1 dup2
0.00 0.000000 0 1 getpid
0.00 0.000000 0 1 clone
0.00 0.000000 0 8 4 execve
0.00 0.000000 0 5 uname
0.00 0.000000 0 1 fcntl
0.00 0.000000 0 3 getrlimit
0.00 0.000000 0 2 getuid
0.00 0.000000 0 2 getgid
0.00 0.000000 0 3 geteuid
0.00 0.000000 0 3 getegid
0.00 0.000000 0 1 getppid
0.00 0.000000 0 1 getpgrp
0.00 0.000000 0 4 arch_prctl
0.00 0.000000 0 3 futex
0.00 0.000000 0 2 set_tid_address
0.00 0.000000 0 1 clock_gettime
0.00 0.000000 0 2 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.000144 43721 471 total
Raw
summary2
Process 25669 attached
Process 25669 detached
average catalog compilation time in seconds: 11.06875
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
80.00 0.000136 0 42059 rt_sigprocmask
14.12 0.000024 0 316 253 close
2.94 0.000005 0 232 209 stat
2.94 0.000005 5 1 wait4
0.00 0.000000 0 697 read
0.00 0.000000 0 2 write
0.00 0.000000 0 58 open
0.00 0.000000 0 38 fstat
0.00 0.000000 0 2 1 lseek
0.00 0.000000 0 81 mmap
0.00 0.000000 0 32 mprotect
0.00 0.000000 0 14 munmap
0.00 0.000000 0 203 brk
0.00 0.000000 0 33 rt_sigaction
0.00 0.000000 0 12 4 access
0.00 0.000000 0 1 pipe
0.00 0.000000 0 1 dup2
0.00 0.000000 0 1 getpid
0.00 0.000000 0 1 clone
0.00 0.000000 0 8 4 execve
0.00 0.000000 0 5 uname
0.00 0.000000 0 1 fcntl
0.00 0.000000 0 3 getrlimit
0.00 0.000000 0 2 getuid
0.00 0.000000 0 2 getgid
0.00 0.000000 0 3 geteuid
0.00 0.000000 0 3 getegid
0.00 0.000000 0 1 getppid
0.00 0.000000 0 1 getpgrp
0.00 0.000000 0 4 arch_prctl
0.00 0.000000 0 3 futex
0.00 0.000000 0 2 set_tid_address
0.00 0.000000 0 1 clock_gettime
0.00 0.000000 0 2 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.000170 43825 471 total
Raw
summary3
Process 26120 attached
Process 26120 detached
average catalog compilation time in seconds: 11.06875
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
57.53 0.000042 0 697 read
20.55 0.000015 0 316 253 close
15.07 0.000011 0 58 open
6.85 0.000005 5 1 wait4
0.00 0.000000 0 2 write
0.00 0.000000 0 232 209 stat
0.00 0.000000 0 38 fstat
0.00 0.000000 0 2 1 lseek
0.00 0.000000 0 79 mmap
0.00 0.000000 0 32 mprotect
0.00 0.000000 0 14 munmap
0.00 0.000000 0 102 brk
0.00 0.000000 0 33 rt_sigaction
0.00 0.000000 0 888 rt_sigprocmask
0.00 0.000000 0 12 4 access
0.00 0.000000 0 1 pipe
0.00 0.000000 0 1 dup2
0.00 0.000000 0 1 getpid
0.00 0.000000 0 1 clone
0.00 0.000000 0 8 4 execve
0.00 0.000000 0 5 uname
0.00 0.000000 0 1 fcntl
0.00 0.000000 0 3 getrlimit
0.00 0.000000 0 2 getuid
0.00 0.000000 0 2 getgid
0.00 0.000000 0 3 geteuid
0.00 0.000000 0 3 getegid
0.00 0.000000 0 1 getppid
0.00 0.000000 0 1 getpgrp
0.00 0.000000 0 4 arch_prctl
0.00 0.000000 0 3 futex
0.00 0.000000 0 2 set_tid_address
0.00 0.000000 0 1 clock_gettime
0.00 0.000000 0 2 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.000073 2551 471 total
@jumanjiman
Copy link
Author

@rismoney your approach is better than the 1st two but not quite as good as 3rd loop, and suffers from the same flaw as 1st two: reads whole file at once

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment