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
@rismoney
Copy link

could you do something like this:

File.open("c:/test/test.txt").read.scan(/^#{today}._Compiled._in ([[:digit:].]+) seconds$/).count

@rismoney
Copy link

according to the docs, readlines reads the entire file as well but puts each line into an array which you then are iterating.
my example also reads the whole file but into a string. scan is a method for strings, and just and scans it for the specific regex as shown. http://www.ruby-doc.org/core-1.9.3/IO.html#method-c-readlines

@rismoney
Copy link

maybe your until-if could be an antipattern ;)

@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