search

ValentinBELYN / icmplib

Easily forge ICMP packets and make your own ping and traceroute.
GNU Lesser General Public License v3.0
267 stars 45 forks source link

Ping times are slightly off on loaded systems #15

Closed bdraco closed 3 years ago

bdraco commented 3 years ago

recvmsg(3, {msg_name={sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("192.168.208.1")}, msg_namelen=128->16, msg_iov=[{iov_base="E\0\0T\220\242\0\0@\1\310\256\300\250\320\1\300\250\320\5\0\0a\251 D\0\1\230\ff_"..., iov_len=192}], msg_iovlen=1, msg_control=[{cmsg_len=32, cmsg_level=SOL_SOCKET, cmsg_type=SCM_TIMESTAMP, cmsg_data={tv_sec=1600523416, tv_usec=512848}}], msg_controllen=32, msg_flags=0}, 0) = 84

It looks like the ping binary looks at the cmsg_type and retrieves the timestamp from cmsg_data to give a more accurate time.

icmplib currently gets time using time() which is subject to fluctuations due to cpu load.

ValentinBELYN commented 3 years ago

It's strange. Even though time() is a little less accurate, I'm not sure that the problem is there. I have to do some tests. Are other users impacted or have you noticed this same behavior?

Otherwise the solution would be as follows:

import socket
from struct import unpack

# SO_TIMESTAMP = 29
SO_TIMESTAMPNS = 35

s = socket.socket(socket.AF_INET, socket.SOCK_RAW, socket.IPPROTO_ICMP)
s.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMPNS, 1)

data, ancdata, msg_flags, address = s.recvmsg(1024, 1024)
timestamp_parts = unpack('4i', ancdata[2])
timestamp = timestamp_parts[0] + timestamp_parts[2] * 1e-10

However, this solution only works on Linux, excluding macOS and Windows. So I would prefer to find another solution.

https://www.kernel.org/doc/Documentation/networking/timestamping.txt https://man7.org/linux/man-pages/man7/socket.7.html https://docs.python.org/3/library/socket.html#socket.socket.recvmsg

bdraco commented 3 years ago

Right now we only have the one linked report, and I have noticed the timing are a bit difference vs ping.

ValentinBELYN commented 3 years ago

OK, I will see what I can do :) On the other hand, if indeed the problem comes from the time function, it will probably be necessary to wait for version 2.0 which will bring a new architecture https://github.com/ValentinBELYN/icmplib/issues/6#issuecomment-694517448.

ValentinBELYN commented 3 years ago

Hi @bdraco,

I performed several tests to locate the source of the problem. Here are the results I got.

Before starting, I would like to detail the conditions of the tests. I performed 4 different tests. I used two separate virtual machines (Ubuntu 20.04, Python 3.8) with 1 and 2 cores respectively.

I performed a first test on the first machine by executing a simple ping with icmplib (100 pings with an interval of 100 ms). I noted the results obtained with the time function currently used and the time taken on the sockets (https://github.com/ValentinBELYN/icmplib/issues/15#issuecomment-695332733). I then used the command stress -c 1 to stress the CPU and check if there was more differences between the time function and the socket time.

Finally, I repeated the same operations on the second machine but with the command stress -c 2 to stress the CPU. As I thought, the results were the same as for the previous tests. Therefore, I will not detail them.

Here is an overview of the results:

Click here to show the test result: normal conditions
```console PING 1.1.1.1: 56 data bytes ICMP REPLY 1: time func: 1601665594.0571342 sock timestamp: 1601665594.005699 delta: 0.051435232162475586 ICMP REPLY 2: time func: 1601665594.1615314 sock timestamp: 1601665594.016149 delta: 0.14538240432739258 ICMP REPLY 3: time func: 1601665594.2671223 sock timestamp: 1601665594.0267065 delta: 0.2404158115386963 ICMP REPLY 4: time func: 1601665594.3724377 sock timestamp: 1601665594.0372376 delta: 0.33520007133483887 ICMP REPLY 5: time func: 1601665594.4765751 sock timestamp: 1601665594.0476537 delta: 0.4289214611053467 ICMP REPLY 6: time func: 1601665594.5815346 sock timestamp: 1601665594.0581493 delta: 0.5233852863311768 ICMP REPLY 7: time func: 1601665594.6864913 sock timestamp: 1601665594.0686455 delta: 0.6178457736968994 ICMP REPLY 8: time func: 1601665594.7918456 sock timestamp: 1601665594.079174 delta: 0.7126715183258057 ICMP REPLY 9: time func: 1601665594.8974817 sock timestamp: 1601665594.0897446 delta: 0.8077371120452881 ICMP REPLY 10: time func: 1601665595.0035264 sock timestamp: 1601665595.0003493 delta: 0.003177165985107422 ICMP REPLY 11: time func: 1601665595.1093967 sock timestamp: 1601665595.0109363 delta: 0.09846043586730957 ICMP REPLY 12: time func: 1601665595.215447 sock timestamp: 1601665595.0215416 delta: 0.19390535354614258 ICMP REPLY 13: time func: 1601665595.3200548 sock timestamp: 1601665595.0320022 delta: 0.2880525588989258 ICMP REPLY 14: time func: 1601665595.4254026 sock timestamp: 1601665595.0425355 delta: 0.38286709785461426 ICMP REPLY 15: time func: 1601665595.5303907 sock timestamp: 1601665595.053036 delta: 0.4773547649383545 ICMP REPLY 16: time func: 1601665595.636003 sock timestamp: 1601665595.063597 delta: 0.5724060535430908 ICMP REPLY 17: time func: 1601665595.7425618 sock timestamp: 1601665595.0742528 delta: 0.6683089733123779 ICMP REPLY 18: time func: 1601665595.8461523 sock timestamp: 1601665595.0846112 delta: 0.7615411281585693 ICMP REPLY 19: time func: 1601665595.9511569 sock timestamp: 1601665595.0951128 delta: 0.8560440540313721 ICMP REPLY 20: time func: 1601665596.0567386 sock timestamp: 1601665596.0056708 delta: 0.05106782913208008 ICMP REPLY 21: time func: 1601665596.1614237 sock timestamp: 1601665596.0161393 delta: 0.14528441429138184 ICMP REPLY 22: time func: 1601665596.266539 sock timestamp: 1601665596.0266507 delta: 0.23988842964172363 ICMP REPLY 23: time func: 1601665596.372436 sock timestamp: 1601665596.03724 delta: 0.33519601821899414 ICMP REPLY 24: time func: 1601665596.4790747 sock timestamp: 1601665596.0479033 delta: 0.4311714172363281 ICMP REPLY 25: time func: 1601665596.5846937 sock timestamp: 1601665596.0584655 delta: 0.5262281894683838 ICMP REPLY 26: time func: 1601665596.6899621 sock timestamp: 1601665596.0689864 delta: 0.6209757328033447 ICMP REPLY 27: time func: 1601665596.7957044 sock timestamp: 1601665596.0795672 delta: 0.716137170791626 ICMP REPLY 28: time func: 1601665596.9010136 sock timestamp: 1601665596.090098 delta: 0.8109157085418701 ICMP REPLY 29: time func: 1601665597.0059078 sock timestamp: 1601665597.000588 delta: 0.005319833755493164 ICMP REPLY 30: time func: 1601665597.1113806 sock timestamp: 1601665597.0111344 delta: 0.10024619102478027 ICMP REPLY 31: time func: 1601665597.2179108 sock timestamp: 1601665597.0217874 delta: 0.19612336158752441 ICMP REPLY 32: time func: 1601665597.3228278 sock timestamp: 1601665597.032279 delta: 0.29054880142211914 ICMP REPLY 33: time func: 1601665597.429444 sock timestamp: 1601665597.0429366 delta: 0.386507511138916 ICMP REPLY 34: time func: 1601665597.5339758 sock timestamp: 1601665597.0533931 delta: 0.48058271408081055 ICMP REPLY 35: time func: 1601665597.6382308 sock timestamp: 1601665597.0638192 delta: 0.5744116306304932 ICMP REPLY 36: time func: 1601665597.7456331 sock timestamp: 1601665597.074552 delta: 0.6710810661315918 ICMP REPLY 37: time func: 1601665597.8522785 sock timestamp: 1601665597.085217 delta: 0.7670614719390869 ICMP REPLY 38: time func: 1601665597.9583511 sock timestamp: 1601665597.0958254 delta: 0.8625257015228271 ICMP REPLY 39: time func: 1601665598.0652425 sock timestamp: 1601665598.0065157 delta: 0.05872678756713867 ICMP REPLY 40: time func: 1601665598.1701972 sock timestamp: 1601665598.0170095 delta: 0.15318775177001953 ICMP REPLY 41: time func: 1601665598.276092 sock timestamp: 1601665598.0276053 delta: 0.24848675727844238 ICMP REPLY 42: time func: 1601665598.38203 sock timestamp: 1601665598.038186 delta: 0.343843936920166 ICMP REPLY 43: time func: 1601665598.4873042 sock timestamp: 1601665598.0487187 delta: 0.4385855197906494 ICMP REPLY 44: time func: 1601665598.5939722 sock timestamp: 1601665598.059387 delta: 0.5345852375030518 ICMP REPLY 45: time func: 1601665598.6997778 sock timestamp: 1601665598.0699673 delta: 0.6298105716705322 ICMP REPLY 46: time func: 1601665598.8046868 sock timestamp: 1601665598.0804515 delta: 0.7242352962493896 ICMP REPLY 47: time func: 1601665598.9105628 sock timestamp: 1601665598.091052 delta: 0.8195106983184814 ICMP REPLY 48: time func: 1601665599.0151002 sock timestamp: 1601665599.0015056 delta: 0.013594627380371094 ICMP REPLY 49: time func: 1601665599.119236 sock timestamp: 1601665599.0119178 delta: 0.10731816291809082 ICMP REPLY 50: time func: 1601665599.2247121 sock timestamp: 1601665599.0224662 delta: 0.20224595069885254 ICMP REPLY 51: time func: 1601665599.3298733 sock timestamp: 1601665599.0329843 delta: 0.296889066696167 ICMP REPLY 52: time func: 1601665599.435721 sock timestamp: 1601665599.043562 delta: 0.39215898513793945 ICMP REPLY 53: time func: 1601665599.540849 sock timestamp: 1601665599.0540814 delta: 0.4867675304412842 ICMP REPLY 54: time func: 1601665599.6458905 sock timestamp: 1601665599.064586 delta: 0.5813045501708984 ICMP REPLY 55: time func: 1601665599.750742 sock timestamp: 1601665599.0750701 delta: 0.6756718158721924 ICMP REPLY 56: time func: 1601665599.855028 sock timestamp: 1601665599.0854988 delta: 0.7695291042327881 ICMP REPLY 57: time func: 1601665599.959212 sock timestamp: 1601665599.095918 delta: 0.8632941246032715 ICMP REPLY 58: time func: 1601665600.0650518 sock timestamp: 1601665600.0065012 delta: 0.05855059623718262 ICMP REPLY 59: time func: 1601665600.1738884 sock timestamp: 1601665600.017385 delta: 0.15650343894958496 ICMP REPLY 60: time func: 1601665600.279644 sock timestamp: 1601665600.02796 delta: 0.25168395042419434 ICMP REPLY 61: time func: 1601665600.3868554 sock timestamp: 1601665600.0386791 delta: 0.3481762409210205 ICMP REPLY 62: time func: 1601665600.4950128 sock timestamp: 1601665600.0494952 delta: 0.44551753997802734 ICMP REPLY 63: time func: 1601665600.5999625 sock timestamp: 1601665600.0599928 delta: 0.5399696826934814 ICMP REPLY 64: time func: 1601665600.705999 sock timestamp: 1601665600.0705945 delta: 0.6354043483734131 ICMP REPLY 65: time func: 1601665600.8113072 sock timestamp: 1601665600.0811267 delta: 0.7301805019378662 ICMP REPLY 66: time func: 1601665600.9171467 sock timestamp: 1601665600.0917115 delta: 0.8254351615905762 ICMP REPLY 67: time func: 1601665601.0259082 sock timestamp: 1601665601.0025864 delta: 0.023321866989135742 ICMP REPLY 68: time func: 1601665601.1334646 sock timestamp: 1601665601.0133433 delta: 0.12012124061584473 ICMP REPLY 69: time func: 1601665601.2379942 sock timestamp: 1601665601.0237865 delta: 0.21420764923095703 ICMP REPLY 70: time func: 1601665601.3458874 sock timestamp: 1601665601.0345852 delta: 0.31130218505859375 ICMP REPLY 71: time func: 1601665601.44946 sock timestamp: 1601665601.0449374 delta: 0.4045226573944092 ICMP REPLY 72: time func: 1601665601.5578923 sock timestamp: 1601665601.0557854 delta: 0.5021069049835205 ICMP REPLY 73: time func: 1601665601.661897 sock timestamp: 1601665601.0661867 delta: 0.595710277557373 ICMP REPLY 74: time func: 1601665601.7685866 sock timestamp: 1601665601.0768547 delta: 0.6917319297790527 ICMP REPLY 75: time func: 1601665601.8760967 sock timestamp: 1601665601.087605 delta: 0.7884917259216309 ICMP REPLY 76: time func: 1601665601.9818857 sock timestamp: 1601665601.098185 delta: 0.8837006092071533 ICMP REPLY 77: time func: 1601665602.0890408 sock timestamp: 1601665602.0088995 delta: 0.08014130592346191 ICMP REPLY 78: time func: 1601665602.1947649 sock timestamp: 1601665602.0194728 delta: 0.1752920150756836 ICMP REPLY 79: time func: 1601665602.3018923 sock timestamp: 1601665602.0301855 delta: 0.27170681953430176 ICMP REPLY 80: time func: 1601665602.4074318 sock timestamp: 1601665602.040739 delta: 0.36669278144836426 ICMP REPLY 81: time func: 1601665602.5122986 sock timestamp: 1601665602.0512261 delta: 0.4610724449157715 ICMP REPLY 82: time func: 1601665602.6168346 sock timestamp: 1601665602.06168 delta: 0.55515456199646 ICMP REPLY 83: time func: 1601665602.72058 sock timestamp: 1601665602.0720546 delta: 0.6485254764556885 ICMP REPLY 84: time func: 1601665602.8259172 sock timestamp: 1601665602.082587 delta: 0.7433302402496338 ICMP REPLY 85: time func: 1601665602.9307954 sock timestamp: 1601665602.0930762 delta: 0.837719202041626 ICMP REPLY 86: time func: 1601665603.0360024 sock timestamp: 1601665603.003596 delta: 0.03240633010864258 ICMP REPLY 87: time func: 1601665603.140935 sock timestamp: 1601665603.0140896 delta: 0.1268453598022461 ICMP REPLY 88: time func: 1601665603.2473805 sock timestamp: 1601665603.0247345 delta: 0.22264599800109863 ICMP REPLY 89: time func: 1601665603.352693 sock timestamp: 1601665603.0352662 delta: 0.3174269199371338 ICMP REPLY 90: time func: 1601665603.4605384 sock timestamp: 1601665603.0456934 delta: 0.41484498977661133 ICMP REPLY 91: time func: 1601665603.565218 sock timestamp: 1601665603.0565164 delta: 0.5087015628814697 ICMP REPLY 92: time func: 1601665603.6706827 sock timestamp: 1601665603.0670645 delta: 0.6036181449890137 ICMP REPLY 93: time func: 1601665603.774863 sock timestamp: 1601665603.0774832 delta: 0.6973798274993896 ICMP REPLY 94: time func: 1601665603.8796594 sock timestamp: 1601665603.0879626 delta: 0.7916967868804932 ICMP REPLY 95: time func: 1601665603.9837067 sock timestamp: 1601665603.0983675 delta: 0.8853392601013184 ICMP REPLY 96: time func: 1601665604.088973 sock timestamp: 1601665604.0088942 delta: 0.0800788402557373 ICMP REPLY 97: time func: 1601665604.1935961 sock timestamp: 1601665604.0193565 delta: 0.1742396354675293 ICMP REPLY 98: time func: 1601665604.2994933 sock timestamp: 1601665604.029946 delta: 0.2695472240447998 ICMP REPLY 99: time func: 1601665604.404172 sock timestamp: 1601665604.040414 delta: 0.363757848739624 ICMP REPLY 100: time func: 1601665604.5098972 sock timestamp: 1601665604.0509858 delta: 0.4589114189147949 TOTAL: deltas avg: 0.43329845428466796 ```
Click here to show the test result: stress test
```console PING 1.1.1.1: 56 data bytes ICMP REPLY 1: time func: 1601665671.6962817 sock timestamp: 1601665671.069623 delta: 0.6266586780548096 ICMP REPLY 2: time func: 1601665671.801813 sock timestamp: 1601665671.0801783 delta: 0.7216346263885498 ICMP REPLY 3: time func: 1601665671.9058857 sock timestamp: 1601665671.0905852 delta: 0.815300464630127 ICMP REPLY 4: time func: 1601665672.0115848 sock timestamp: 1601665672.0011556 delta: 0.010429143905639648 ICMP REPLY 5: time func: 1601665672.117897 sock timestamp: 1601665672.0117862 delta: 0.10611081123352051 ICMP REPLY 6: time func: 1601665672.2232735 sock timestamp: 1601665672.0223234 delta: 0.20095014572143555 ICMP REPLY 7: time func: 1601665672.329907 sock timestamp: 1601665672.0329869 delta: 0.2969200611114502 ICMP REPLY 8: time func: 1601665672.4378948 sock timestamp: 1601665672.0437858 delta: 0.39410901069641113 ICMP REPLY 9: time func: 1601665672.5427144 sock timestamp: 1601665672.054267 delta: 0.4884474277496338 ICMP REPLY 10: time func: 1601665672.6479423 sock timestamp: 1601665672.064789 delta: 0.583153247833252 ICMP REPLY 11: time func: 1601665672.7538888 sock timestamp: 1601665672.075385 delta: 0.6785037517547607 ICMP REPLY 12: time func: 1601665672.8578966 sock timestamp: 1601665672.0857859 delta: 0.7721107006072998 ICMP REPLY 13: time func: 1601665672.9625826 sock timestamp: 1601665672.0962543 delta: 0.866328239440918 ICMP REPLY 14: time func: 1601665673.0698953 sock timestamp: 1601665673.0069861 delta: 0.06290912628173828 ICMP REPLY 15: time func: 1601665673.1775384 sock timestamp: 1601665673.01775 delta: 0.1597883701324463 ICMP REPLY 16: time func: 1601665673.2858915 sock timestamp: 1601665673.0285854 delta: 0.2573060989379883 ICMP REPLY 17: time func: 1601665673.389888 sock timestamp: 1601665673.0389853 delta: 0.350902795791626 ICMP REPLY 18: time func: 1601665673.4944396 sock timestamp: 1601665673.0494406 delta: 0.44499897956848145 ICMP REPLY 19: time func: 1601665673.6004126 sock timestamp: 1601665673.0600379 delta: 0.540374755859375 ICMP REPLY 20: time func: 1601665673.7058823 sock timestamp: 1601665673.070585 delta: 0.6352972984313965 ICMP REPLY 21: time func: 1601665673.8103938 sock timestamp: 1601665673.081036 delta: 0.7293577194213867 ICMP REPLY 22: time func: 1601665673.916672 sock timestamp: 1601665673.091664 delta: 0.8250079154968262 ICMP REPLY 23: time func: 1601665674.0218787 sock timestamp: 1601665674.0021849 delta: 0.019693851470947266 ICMP REPLY 24: time func: 1601665674.1267443 sock timestamp: 1601665674.0126712 delta: 0.11407303810119629 ICMP REPLY 25: time func: 1601665674.2338872 sock timestamp: 1601665674.0233855 delta: 0.21050167083740234 ICMP REPLY 26: time func: 1601665674.3387868 sock timestamp: 1601665674.033875 delta: 0.30491185188293457 ICMP REPLY 27: time func: 1601665674.445885 sock timestamp: 1601665674.0445852 delta: 0.40129971504211426 ICMP REPLY 28: time func: 1601665674.55136 sock timestamp: 1601665674.0551317 delta: 0.4962282180786133 ICMP REPLY 29: time func: 1601665674.6578968 sock timestamp: 1601665674.0657856 delta: 0.5921111106872559 ICMP REPLY 30: time func: 1601665674.7628226 sock timestamp: 1601665674.0762792 delta: 0.6865434646606445 ICMP REPLY 31: time func: 1601665674.8698795 sock timestamp: 1601665674.0869844 delta: 0.7828950881958008 ICMP REPLY 32: time func: 1601665674.9743726 sock timestamp: 1601665674.0974345 delta: 0.8769381046295166 ICMP REPLY 33: time func: 1601665675.0811062 sock timestamp: 1601665675.0081074 delta: 0.0729987621307373 ICMP REPLY 34: time func: 1601665675.1856155 sock timestamp: 1601665675.0185583 delta: 0.16705727577209473 ICMP REPLY 35: time func: 1601665675.2907135 sock timestamp: 1601665675.0290673 delta: 0.2616462707519531 ICMP REPLY 36: time func: 1601665675.3978858 sock timestamp: 1601665675.0397851 delta: 0.35810065269470215 ICMP REPLY 37: time func: 1601665675.502618 sock timestamp: 1601665675.050259 delta: 0.4523589611053467 ICMP REPLY 38: time func: 1601665675.6098702 sock timestamp: 1601665675.0609844 delta: 0.5488858222961426 ICMP REPLY 39: time func: 1601665675.7179136 sock timestamp: 1601665675.0717862 delta: 0.646127462387085 ICMP REPLY 40: time func: 1601665675.8249693 sock timestamp: 1601665675.0824926 delta: 0.7424767017364502 ICMP REPLY 41: time func: 1601665675.9299119 sock timestamp: 1601665675.0929863 delta: 0.8369255065917969 ICMP REPLY 42: time func: 1601665676.035383 sock timestamp: 1601665676.003534 delta: 0.031848907470703125 ICMP REPLY 43: time func: 1601665676.1415956 sock timestamp: 1601665676.0141554 delta: 0.1274402141571045 ICMP REPLY 44: time func: 1601665676.2475038 sock timestamp: 1601665676.0247474 delta: 0.22275638580322266 ICMP REPLY 45: time func: 1601665676.353875 sock timestamp: 1601665676.0353847 delta: 0.31849026679992676 ICMP REPLY 46: time func: 1601665676.4587152 sock timestamp: 1601665676.0458674 delta: 0.41284775733947754 ICMP REPLY 47: time func: 1601665676.565901 sock timestamp: 1601665676.056586 delta: 0.509315013885498 ICMP REPLY 48: time func: 1601665676.6717372 sock timestamp: 1601665676.0671709 delta: 0.6045663356781006 ICMP REPLY 49: time func: 1601665676.777881 sock timestamp: 1601665676.077785 delta: 0.7000958919525146 ICMP REPLY 50: time func: 1601665676.885886 sock timestamp: 1601665676.0885851 delta: 0.7973008155822754 ICMP REPLY 51: time func: 1601665676.9902775 sock timestamp: 1601665676.0990245 delta: 0.8912529945373535 ICMP REPLY 52: time func: 1601665677.0963418 sock timestamp: 1601665677.0096304 delta: 0.08671140670776367 ICMP REPLY 53: time func: 1601665677.205886 sock timestamp: 1601665677.020585 delta: 0.1853008270263672 ICMP REPLY 54: time func: 1601665677.3114045 sock timestamp: 1601665677.031123 delta: 0.28028154373168945 ICMP REPLY 55: time func: 1601665677.417123 sock timestamp: 1601665677.0417085 delta: 0.3754146099090576 ICMP REPLY 56: time func: 1601665677.5246878 sock timestamp: 1601665677.0524652 delta: 0.47222256660461426 ICMP REPLY 57: time func: 1601665677.629896 sock timestamp: 1601665677.0629861 delta: 0.5669097900390625 ICMP REPLY 58: time func: 1601665677.7378953 sock timestamp: 1601665677.0737855 delta: 0.6641097068786621 ICMP REPLY 59: time func: 1601665677.8456247 sock timestamp: 1601665677.0845592 delta: 0.7610654830932617 ICMP REPLY 60: time func: 1601665677.9535182 sock timestamp: 1601665677.0953493 delta: 0.8581688404083252 ICMP REPLY 61: time func: 1601665678.0619192 sock timestamp: 1601665678.0061862 delta: 0.05573296546936035 ICMP REPLY 62: time func: 1601665678.169915 sock timestamp: 1601665678.0169857 delta: 0.15292930603027344 ICMP REPLY 63: time func: 1601665678.274663 sock timestamp: 1601665678.027461 delta: 0.24720191955566406 ICMP REPLY 64: time func: 1601665678.3819268 sock timestamp: 1601665678.0381866 delta: 0.34374022483825684 ICMP REPLY 65: time func: 1601665678.4864163 sock timestamp: 1601665678.0486372 delta: 0.43777918815612793 ICMP REPLY 66: time func: 1601665678.5919297 sock timestamp: 1601665678.0591893 delta: 0.5327403545379639 ICMP REPLY 67: time func: 1601665678.697887 sock timestamp: 1601665678.0697856 delta: 0.6281013488769531 ICMP REPLY 68: time func: 1601665678.8032944 sock timestamp: 1601665678.0803268 delta: 0.7229676246643066 ICMP REPLY 69: time func: 1601665678.9098802 sock timestamp: 1601665678.090985 delta: 0.8188951015472412 ICMP REPLY 70: time func: 1601665679.0165927 sock timestamp: 1601665679.0016553 delta: 0.014937400817871094 ICMP REPLY 71: time func: 1601665679.1218755 sock timestamp: 1601665679.0121841 delta: 0.10969138145446777 ICMP REPLY 72: time func: 1601665679.2281656 sock timestamp: 1601665679.0228124 delta: 0.2053532600402832 ICMP REPLY 73: time func: 1601665679.3339117 sock timestamp: 1601665679.0333874 delta: 0.3005242347717285 ICMP REPLY 74: time func: 1601665679.4390407 sock timestamp: 1601665679.0439007 delta: 0.3951399326324463 ICMP REPLY 75: time func: 1601665679.543828 sock timestamp: 1601665679.054379 delta: 0.48944902420043945 ICMP REPLY 76: time func: 1601665679.649813 sock timestamp: 1601665679.0649774 delta: 0.5848355293273926 ICMP REPLY 77: time func: 1601665679.7559545 sock timestamp: 1601665679.0755923 delta: 0.6803622245788574 ICMP REPLY 78: time func: 1601665679.8618932 sock timestamp: 1601665679.086186 delta: 0.7757072448730469 ICMP REPLY 79: time func: 1601665679.9674888 sock timestamp: 1601665679.0967448 delta: 0.870743989944458 ICMP REPLY 80: time func: 1601665680.0738428 sock timestamp: 1601665680.0073802 delta: 0.06646251678466797 ICMP REPLY 81: time func: 1601665680.1795418 sock timestamp: 1601665680.0179482 delta: 0.16159367561340332 ICMP REPLY 82: time func: 1601665680.2858427 sock timestamp: 1601665680.0285797 delta: 0.2572629451751709 ICMP REPLY 83: time func: 1601665680.3938398 sock timestamp: 1601665680.0393798 delta: 0.3544600009918213 ICMP REPLY 84: time func: 1601665680.5018475 sock timestamp: 1601665680.05018 delta: 0.45166754722595215 ICMP REPLY 85: time func: 1601665680.6093845 sock timestamp: 1601665680.0609324 delta: 0.5484521389007568 ICMP REPLY 86: time func: 1601665680.7138405 sock timestamp: 1601665680.07138 delta: 0.6424605846405029 ICMP REPLY 87: time func: 1601665680.8175335 sock timestamp: 1601665680.0817506 delta: 0.7357828617095947 ICMP REPLY 88: time func: 1601665680.9228055 sock timestamp: 1601665680.0922759 delta: 0.8305296897888184 ICMP REPLY 89: time func: 1601665681.0298495 sock timestamp: 1601665681.0029807 delta: 0.026868820190429688 ICMP REPLY 90: time func: 1601665681.1350183 sock timestamp: 1601665681.013498 delta: 0.1215202808380127 ICMP REPLY 91: time func: 1601665681.2400692 sock timestamp: 1601665681.0240037 delta: 0.2160654067993164 ICMP REPLY 92: time func: 1601665681.3458664 sock timestamp: 1601665681.0345807 delta: 0.31128573417663574 ICMP REPLY 93: time func: 1601665681.45365 sock timestamp: 1601665681.0453615 delta: 0.40828847885131836 ICMP REPLY 94: time func: 1601665681.5578704 sock timestamp: 1601665681.055784 delta: 0.5020864009857178 ICMP REPLY 95: time func: 1601665681.6620328 sock timestamp: 1601665681.0661998 delta: 0.5958330631256104 ICMP REPLY 96: time func: 1601665681.7669132 sock timestamp: 1601665681.0766883 delta: 0.6902248859405518 ICMP REPLY 97: time func: 1601665681.8728924 sock timestamp: 1601665681.0871851 delta: 0.7857072353363037 ICMP REPLY 98: time func: 1601665681.9778426 sock timestamp: 1601665681.0977805 delta: 0.8800621032714844 ICMP REPLY 99: time func: 1601665682.0829911 sock timestamp: 1601665682.008295 delta: 0.07469606399536133 ICMP REPLY 100: time func: 1601665682.19385 sock timestamp: 1601665682.0193808 delta: 0.1744692325592041 TOTAL: deltas avg: 0.4520708417892456 ```

As we can see, the stress of the CPU has no impact on the time function (so the problem does not come from the time function). On the other hand, we can see that this function returns a value less accurate than that returned by the socket. In the worst case, there is a difference of 800 ms.

However, we also see another behavior of the time function. The difference between the two times increases linearly until reaching a difference of 800 ms. After that, this difference/inaccuracy back to zero. Given that the send method also calls the time function (it is not possible to get the time at the socket level), the difference/inaccuracy between sending and receiving is almost zero. In other words, if the time function adds an inaccuracy of 400 ms during sending for example, it also adds it on reception which cancels it.

So, the problem comes from elsewhere and I may have an idea. When you ping several times with a low interval or in parallel, the operating system or the routers seem to prioritize the ICMP flow and consequently reduce the round-trip times.

You can test this behavior with the following Python code:

from icmplib import ping

print(ping('1.1.1.1', count=10).avg_rtt)
print(ping('1.1.1.1', count=10, interval=0.1).avg_rtt)

This also happens with your system's ping command:

ping 1.1.1.1
ping -i 0.1 1.1.1.1

Since it is possible to perform checks / ping at different times with Home Assistant, this can create variations in round-trip times (depending on the number of simultaneous checks). I don't understand, however, why this phenomenon was not happening before on your side, before migrating to icmplib.

bdraco commented 3 years ago

@andriej (https://github.com/home-assistant/core/issues/40222)

@shirou93 @Misiu @blair287 (https://github.com/home-assistant/core/issues/40232)

Can you give @ValentinBELYN 's steps above a try and post the results?

andriej commented 3 years ago

Sure. Both of these commands differ from HA graph. They give constans 1-2ms while graphs are going up to 15-20ms

ValentinBELYN commented 3 years ago

I need more information to continue my investigations. I just ran some other tests with Wireshark and the times seem to match as well.

@bdraco Otherwise I just updated the library to fix the problem found in issue #21.

bdraco commented 3 years ago

I need more information to continue my investigations. I just ran some other tests with Wireshark and the times seem to match as well.

Unfortunately I can't replicate the issue on my local network, so its going to be up to @andriej @shirou93 @Misiu or @blair287 to provide the detail needed.

@bdraco Otherwise I just updated the library to fix the problem found in issue #21.

Perfect, TYVM. I'll get Home Assistant updated.

ValentinBELYN commented 3 years ago

OK, thanks for the information :)

blair287 commented 3 years ago

I need more information to continue my investigations. I just ran some other tests with Wireshark and the times seem to match as well.

Unfortunately I can't replicate the issue on my local network, so its going to be up to @andriej @shirou93 @Misiu or @blair287 to provide the detail needed.

@bdraco Otherwise I just updated the library to fix the problem found in issue #21.

Perfect, TYVM. I'll get Home Assistant updated.

After update to 0.116.2 I am no longer seeing the ping errors I will test further to check issue is gone maybe they were related to the other fix?

ValentinBELYN commented 3 years ago

Thank you for your feedback 👍

It's possible. I don't think it's related to recent fixes to this library. Maybe it was related to a problem in Home Assistant? Keep me informed if you still have any errors.

bdraco commented 3 years ago

@nerdosity Since you filed https://github.com/home-assistant/core/issues/42468 , can you try the testing that ValentinBELYN described above?

nerdosity commented 3 years ago

Hi.

bash-5.0# python                                                                                                                                         
Python 3.8.5 (default, Sep 10 2020, 14:23:57)                                                                                                            
[GCC 9.3.0] on linux                                                                                                                                     
Type "help", "copyright", "credits" or "license" for more information.                                                                                   
>>> from icmplib import ping                                                                                                                             
>>>                                                                                                                                                      
>>> print(ping('fast.com', count=10).avg_rtt)                                                                                                            
19.439                                                                                                                                                   
>>> print(ping('fast.com', count=10, interval=0.1).avg_rtt)                                                                                              
18.501    
bash-5.0# ping fast.com                                                                                                                                  
PING fast.com (23.1.71.125): 56 data bytes                                                                                                               
64 bytes from 23.1.71.125: seq=0 ttl=59 time=6.907 ms                                                                                                    
64 bytes from 23.1.71.125: seq=1 ttl=59 time=6.751 ms                                                                                                    
64 bytes from 23.1.71.125: seq=2 ttl=59 time=7.149 ms                                                                                                    
64 bytes from 23.1.71.125: seq=3 ttl=59 time=6.816 ms                                                                                                    
64 bytes from 23.1.71.125: seq=4 ttl=59 time=6.736 ms                                                                                                    
64 bytes from 23.1.71.125: seq=5 ttl=59 time=7.415 ms                                                                                                    
64 bytes from 23.1.71.125: seq=6 ttl=59 time=7.061 ms                                                                                                    
64 bytes from 23.1.71.125: seq=7 ttl=59 time=7.003 ms                                                                                                    
64 bytes from 23.1.71.125: seq=8 ttl=59 time=7.236 ms                                                                                                    
64 bytes from 23.1.71.125: seq=9 ttl=59 time=7.020 ms                                                                                                    
64 bytes from 23.1.71.125: seq=10 ttl=59 time=7.108 ms                                                                                                   
64 bytes from 23.1.71.125: seq=11 ttl=59 time=7.055 ms                                                                                                   
^C                                                                                                                                                       
--- fast.com ping statistics ---                                                                                                                         
12 packets transmitted, 12 packets received, 0% packet loss                                                                                              
round-trip min/avg/max = 6.736/7.021/7.415 ms
bash-5.0# ping -i 0.1 fast.com                                                                                                                           
PING fast.com (23.1.71.125): 56 data bytes                                                                                                               
64 bytes from 23.1.71.125: seq=0 ttl=59 time=7.058 ms                                                                                                    
64 bytes from 23.1.71.125: seq=1 ttl=59 time=6.667 ms                                                                                                    
64 bytes from 23.1.71.125: seq=2 ttl=59 time=6.590 ms                                                                                                    
64 bytes from 23.1.71.125: seq=3 ttl=59 time=6.824 ms                                                                                                    
64 bytes from 23.1.71.125: seq=4 ttl=59 time=6.997 ms                                                                                                    
64 bytes from 23.1.71.125: seq=5 ttl=59 time=7.551 ms                                                                                                    
64 bytes from 23.1.71.125: seq=6 ttl=59 time=6.918 ms                                                                                                    
64 bytes from 23.1.71.125: seq=7 ttl=59 time=25.922 ms                                                                                                   
64 bytes from 23.1.71.125: seq=8 ttl=59 time=6.864 ms                                                                                                    
64 bytes from 23.1.71.125: seq=9 ttl=59 time=7.050 ms                                 
-----------CUT---------------
64 bytes from 23.1.71.125: seq=64 ttl=59 time=6.715 ms                                                                                                   
64 bytes from 23.1.71.125: seq=65 ttl=59 time=6.854 ms                                                                                                   
^C                                                                                                                                                       
--- fast.com ping statistics ---                                                                                                                         
66 packets transmitted, 66 packets received, 0% packet loss                                                                                              
round-trip min/avg/max = 6.558/7.405/25.922 ms

We have: 19ms / 18ms in python. 7ms in bash.

image

And 34ms in HASS. The latter one seems totally off.

ValentinBELYN commented 3 years ago

Hi @nerdosity 👋

Thank you for taking the time to test and post your results! I am quite surprised of the results you get with my library and the ping command. Can you try to run these two commands again by doing a tcpdump or a Wireshark capture at the same time? The objective is to compare the timestamps and the contents of the ICMP packets.

Thanks in advance 👍

nerdosity commented 3 years ago

Hi, this morning I did upgrade Home assistant to latest version (0.117), and the bug seems squashed.

image

ValentinBELYN commented 3 years ago

It's weird. The tests you performed in Python with icmplib were unrelated to Home Assistant. Maybe Home Assistant has updated your version of icmplib. However, I haven't made a major change recently. If you encounter the same problem later, feel free to update this issue :)

nerdosity commented 3 years ago

I don't know, I made the tests inside the docker prompt. Now the sensor seems much more stable.

ValentinBELYN commented 3 years ago

Hi! 👋

@nerdosity Have you encountered this problem again with the latest version of Home Assistant? @bdraco @andriej Can we close this issue? The problem encountered by @andriej does not seem to come from this library.

bdraco commented 3 years ago

Not sure if its still an issue. I asked in the Home Assistant issue as well.

I have not seen any other reports

shirou93 commented 3 years ago

For me is working now.

ValentinBELYN commented 3 years ago

Great news! Therefore I am closing this issue for the moment. If there is again a problem of this kind, we can open a new one.

Thanks for giving me feedback 👍