On Fri, Sep 12, 2014 at 5:52 PM, Panagiotis Atmatzidis
<atma / convalesco.org> wrote:

> Run a °∆dtruss°«. I didn°«t look at it carefully yet. I°«m not familiar with
> this kind of things, it will probably take me some time to figure out what°«s
> happening. Please take a look and let me know if there°«s anythingthat jumps
> out directly. What I found odd are the path errors are every call. I don°«t
> see those on my MacOSX system. NOTE: that°«s a 'dtruss -a°«output.
>
> https://gist.github.com/atmosx/93e7f202539d8d8a0d47

Some preliminary analysis:

$ awk 'NR<=3 || ($3 ~ /^[0-9]*$/ && $3>1000) {print}' gistfile1.pytb.txt
$ sudo dtruss -a ./test.rb
dtrace: 3387 dynamic variable drops with non-empty dirty list
PID/LWP    RELATIVE  ELAPSD    CPU SYSCALL(args) = return
 91089/100320:   1980466 1019754     11 kevent(0xD, 0x7FFFFFFFB6A8, 0x1) = 0 0
 91089/100320:   1980595  369752     15 kevent(0xD, 0x7FFFFFFFB6A8, 0x1) = 1 0
 91089/100320:   1980764 1609894     12 kevent(0xD, 0x7FFFFFFFB6A8, 0x1) = 1 0
 91089/100320:   1980894 1019483     12 kevent(0xD, 0x7FFFFFFFB6A8, 0x1) = 0 0
 91089/100320:   1981020   53532     16 kevent(0xD, 0x7FFFFFFFB6A8, 0x1) = 1 0
 91089/100320:   1981447   53020     65 connect(0xD, 0x804B01FB0, 0x10) =0 0
 91089/100320:   1997891   57567     12 select(0xE, 0x805E4BB00, 0x0) = 10
 91089/100320:   1999566   53752      7 select(0xE, 0x805E8E100, 0x0) = 10
 91089/100320:   2000819   59065     12 select(0xE, 0x805F2DB80, 0x0) = 10
 91089/100320:   2003865 2992714     21 kevent(0xD, 0x7FFFFFFFB778, 0x1) = 1 0
 91089/100320:   2003989 1019412      8 kevent(0xD, 0x7FFFFFFFB778, 0x1) = 0 0
 91089/100320:   2004089   53489     14 kevent(0xD, 0x7FFFFFFFB778, 0x1) = 1 0
 91089/100320:   2004251 1926141     12 kevent(0xD, 0x7FFFFFFFB778, 0x1) = 1 0
 91089/100320:   2004372 1019526      8 kevent(0xD, 0x7FFFFFFFB778, 0x1) = 0 0
 91089/100320:   2004674 15598747     31 connect(0xD, 0x8055EC3B0,
0x1C) = -1 Err#64
 91089/100320:   2004812   49906     65 connect(0xD, 0x805D5F9F0, 0x10) =0 0
 91089/100320:   2023067   50707     13 select(0xE, 0x807A12B00, 0x0) = 10
 91089/100320:   2024124  142633     15 select(0xE, 0x807A95400, 0x0) = 10
 91089/100320:   2031193 1009502     11 kevent(0xD, 0x7FFFFFFFB778, 0x1) = 0 0
 91089/100320:   2031321   78420     19 kevent(0xD, 0x7FFFFFFFB778, 0x1) = 1 0
 91089/100320:   2031505 1911222     17 kevent(0xD, 0x7FFFFFFFB778, 0x1) = 1 0
 91089/100320:   2031684 1019338     12 kevent(0xD, 0x7FFFFFFFB778, 0x1) = 0 0
 91089/100320:   2032104   50128     82 connect(0xD, 0x808E30570, 0x10) =0 0
 91089/100320:   2032683  389215     13 select(0xE, 0x807A95F80, 0x0) = 10

There are quite a few kevent calls that take more than one second (unit is us).

Then I did

ruby -nae 'printf("%d;%d;%s\n", Integer($F[1]), Integer($F[2]),
$F[4][/^\w+/]) rescue 1' gistfile1.pytb.txt

and imported the data into a spreadsheet. You can find it here:

https://drive.google.com/file/d/0B7Q7WZzdIMlIUzhnUGxyWXY1WlU/edit?usp=sharing

The two entries which account for almost all the time:

kevent Sum - ELAPSED 15.102.889
Average - ELAPSED 943.931
Count - ELAPSED 16

connect Sum - ELAPSED 15.752.179
Average - ELAPSED 656.341
Count - ELAPSED 24

Total Sum - ELAPSED 31.673.152
Total Average - ELAPSED 5.364
Total Count - ELAPSED 5905

Kind regards

robert

-- 
[guy, jim].each {|him| remember.him do |as, often| as.you_can - without end}
http://blog.rubybestpractices.com/