two poll() per main loop iter.

[vitalyvch]

Currently we do two poll() syscalls per main loop iter with same args and result. I have have discovered it by using regular system strace. And it prevent me from reaching 1500000 syscalls per second.

I will be happy if somebody fixes it.

[markdrayton]

Can you show how to reproduce this and your strace output?

[vitalyvch]

I have discovered it by running sudo strace ./opensnoop.py -p XXX on some application which does one open() syscall per sec, and I got two libbcc's poll() syscalls per one application's open(). I plan to investigate it in details it in one month but it will be excellent if somebody will have done it before.

[markdrayton]

It doesn't repro for me (using HEAD on Ubuntu 14.04/4.6.0-040600rc2-generic):

$ cat /tmp/open.py 
import time

while True:
    print time.strftime('%H:%M:%S')
    with open('/proc/self/status') as f:
        pass
    time.sleep(1)

In one window:

$ python /tmp/open.py 
11:05:31
11:05:32
11:05:33
11:05:34

In another:

$ sudo strace -tt /usr/share/bcc/tools/opensnoop -p $(pgrep python)
(snip)
11:05:31.170160 poll([{fd=10, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}, {fd=6, events=POLLIN}], 4, -1) = 1 ([{fd=9, revents=POLLIN}]) <0.690309>
11:05:31.860707 write(1, "2407   python              3   0"..., 51) = 51 <0.000030>
11:05:31.860833 poll([{fd=10, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}, {fd=6, events=POLLIN}], 4, -1) = 1 ([{fd=9, revents=POLLIN}]) <1.001876>
11:05:32.862882 write(1, "2407   python              3   0"..., 51) = 51 <0.000024>
11:05:32.862981 poll([{fd=10, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}, {fd=6, events=POLLIN}], 4, -1) = 1 ([{fd=9, revents=POLLIN}]) <1.001378>
11:05:33.864482 write(1, "2407   python              3   0"..., 51) = 51 <0.000026>
11:05:33.864576 poll([{fd=10, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}, {fd=6, events=POLLIN}], 4, -1) = 1 ([{fd=9, revents=POLLIN}]) <1.001511>
11:05:34.866225 write(1, "2407   python              3   0"..., 51) = 51 <0.000034>

One write from my test script triggers one poll call returning to BCC.

[vitalyvch]

Hm... Ok. Let's keep it open until I re-investigate it one-time more.

PS: I used ubuntu 16.04 and libbcc actual at the begin of August.