At first I thought that Jon was right and the problem
was in the naming service, but now I am not so sure.
It is true that you get exactly this effect with name
service delays. Ping sends a icmp packet each second
and records the timestamp when it was sent. It reads
the replies as quickly as it can, but the process is
single threaded. Since it immediately does a reverse
lookup to get the hostname to print out, it stops
reading the responses until the getnameinfo returns.
However, the sending of packets is done asynchronously
in a signal handler, so that keeps right on going.
Thus a backlog of packets waiting to be read will queue
up on the socket. Once the getnameinfo returns, it
prints the round trip time, as of that moment, so even
though the packet only took a fraction of a second to
arrive, the getnameinfo lookup time is also added.
Ping then reads the next packet. Since this next
packet is likely going to be from the same host, it
doesn't do the lookup again since it already has the
answer. But this next packet was sent one second later
than the previous one, so its round trip time is printed
as one second less. This continues on until all the packets
have been read, each appearing to have a ping time one
second less than the one before it.
I have seen this numerous times because of name service
delays. However, the thing that is odd in this case is that
the first packet is printed normally (or actually after a
two second delay. Can't tell if that is noramal or not).
So, after that, ping should have had the lookup cached and
would not delay printing the rest of the addresses.
I have seen this in another case, when the ARP and IRE tables
were so big that the table flush (which is done periodically)
took a significant length of time. During that time the IP
module was locked and the incoming packets were queued. Oddly
enough, out going packets still were processed. Anyway, once
the tabel flush finished, all the packets were sent through.
By the way, I believe that the Firengine project re-wrote all
of the flush logic so that this no longer happens in OpenSolaris.
Anyway, it sounds like the packets are getting queued somwhere and
then processed as a bunch. Since you are working on a driver, that
seems the logical place to start from. Try using dtrace to see what is
going on.
Tom Chen wrote:
Hi,
I am using Solaris Nevada v56. I find "ping" some times get stuck. Sometimes, it took a long time to ping next time. But, from snoop, I can see a lot of packets exchange between two PCs.
Can somebody explain why?
Tom
# ping -s 192.168.0.10
PING 192.168.0.10: 56 data bytes
64 bytes from 192.168.0.10: icmp_seq=0. time=1.915 ms
64 bytes from 192.168.0.10: icmp_seq=1. time=161000.388 ms
64 bytes from 192.168.0.10: icmp_seq=2. time=160000.505 ms
64 bytes from 192.168.0.10: icmp_seq=3. time=159000.573 ms
64 bytes from 192.168.0.10: icmp_seq=4. time=158000.636 ms
64 bytes from 192.168.0.10: icmp_seq=5. time=157000.714 ms
64 bytes from 192.168.0.10: icmp_seq=6. time=156000.791 ms
64 bytes from 192.168.0.10: icmp_seq=7. time=155000.862 ms
64 bytes from 192.168.0.10: icmp_seq=8. time=154000.942 ms
64 bytes from 192.168.0.10: icmp_seq=9. time=153000.990 ms
64 bytes from 192.168.0.10: icmp_seq=10. time=152001.089 ms
64 bytes from 192.168.0.10: icmp_seq=11. time=151001.166 ms
64 bytes from 192.168.0.10: icmp_seq=12. time=150001.123 ms
64 bytes from 192.168.0.10: icmp_seq=13. time=149001.274 ms
64 bytes from 192.168.0.10: icmp_seq=14. time=148001.362 ms
64 bytes from 192.168.0.10: icmp_seq=15. time=147001.440 ms
64 bytes from 192.168.0.10: icmp_seq=16. time=146001.520 ms
64 bytes from 192.168.0.10: icmp_seq=17. time=145001.572 ms
64 bytes from 192.168.0.10: icmp_seq=18. time=144001.658 ms
64 bytes from 192.168.0.10: icmp_seq=19. time=143001.755 ms
64 bytes from 192.168.0.10: icmp_seq=20. time=142001.824 ms
64 bytes from 192.168.0.10: icmp_seq=21. time=141001.898 ms
64 bytes from 192.168.0.10: icmp_seq=22. time=140001.962 ms
64 bytes from 192.168.0.10: icmp_seq=23. time=139002.039 ms
64 bytes from 192.168.0.10: icmp_seq=24. time=138002.097 ms
64 bytes from 192.168.0.10: icmp_seq=25. time=137002.170 ms
64 bytes from 192.168.0.10: icmp_seq=26. time=136002.244 ms
64 bytes from 192.168.0.10: icmp_seq=27. time=135002.317 ms
64 bytes from 192.168.0.10: icmp_seq=28. time=134002.371 ms
64 bytes from 192.168.0.10: icmp_seq=29. time=133002.445 ms
64 bytes from 192.168.0.10: icmp_seq=30. time=132002.514 ms
64 bytes from 192.168.0.10: icmp_seq=31. time=131002.584 ms
64 bytes from 192.168.0.10: icmp_seq=32. time=130002.498 ms
64 bytes from 192.168.0.10: icmp_seq=33. time=129002.592 ms
64 bytes from 192.168.0.10: icmp_seq=34. time=128002.736 ms
64 bytes from 192.168.0.10: icmp_seq=35. time=127002.842 ms
64 bytes from 192.168.0.10: icmp_seq=36. time=126002.843 ms
64 bytes from 192.168.0.10: icmp_seq=37. time=125003.008 ms
64 bytes from 192.168.0.10: icmp_seq=38. time=124003.077 ms
64 bytes from 192.168.0.10: icmp_seq=39. time=123003.143 ms
64 bytes from 192.168.0.10: icmp_seq=40. time=122003.236 ms
64 bytes from 192.168.0.10: icmp_seq=41. time=121003.299 ms
64 bytes from 192.168.0.10: icmp_seq=42. time=120003.374 ms
64 bytes from 192.168.0.10: icmp_seq=43. time=119003.439 ms
64 bytes from 192.168.0.10: icmp_seq=44. time=118003.510 ms
64 bytes from 192.168.0.10: icmp_seq=45. time=117003.566 ms
64 bytes from 192.168.0.10: icmp_seq=46. time=116003.643 ms
64 bytes from 192.168.0.10: icmp_seq=47. time=115003.734 ms
64 bytes from 192.168.0.10: icmp_seq=48. time=114003.796 ms
64 bytes from 192.168.0.10: icmp_seq=49. time=113003.868 ms
64 bytes from 192.168.0.10: icmp_seq=50. time=112003.942 ms
64 bytes from 192.168.0.10: icmp_seq=51. time=111004.008 ms
64 bytes from 192.168.0.10: icmp_seq=52. time=110004.078 ms
64 bytes from 192.168.0.10: icmp_seq=53. time=109004.151 ms
64 bytes from 192.168.0.10: icmp_seq=54. time=108004.212 ms
64 bytes from 192.168.0.10: icmp_seq=55. time=107004.287 ms
64 bytes from 192.168.0.10: icmp_seq=56. time=106004.345 ms
64 bytes from 192.168.0.10: icmp_seq=57. time=105004.429 ms
64 bytes from 192.168.0.10: icmp_seq=58. time=104004.501 ms
64 bytes from 192.168.0.10: icmp_seq=59. time=103004.571 ms
64 bytes from 192.168.0.10: icmp_seq=60. time=102004.546 ms
64 bytes from 192.168.0.10: icmp_seq=61. time=101004.708 ms
64 bytes from 192.168.0.10: icmp_seq=62. time=100004.789 ms
64 bytes from 192.168.0.10: icmp_seq=63. time=99004.862 ms
64 bytes from 192.168.0.10: icmp_seq=64. time=98004.941 ms
64 bytes from 192.168.0.10: icmp_seq=65. time=97005.018 ms
64 bytes from 192.168.0.10: icmp_seq=66. time=96005.090 ms
64 bytes from 192.168.0.10: icmp_seq=67. time=95005.167 ms
64 bytes from 192.168.0.10: icmp_seq=68. time=94005.244 ms
64 bytes from 192.168.0.10: icmp_seq=69. time=93005.302 ms
64 bytes from 192.168.0.10: icmp_seq=70. time=92005.375 ms
64 bytes from 192.168.0.10: icmp_seq=71. time=91005.469 ms
64 bytes from 192.168.0.10: icmp_seq=72. time=90005.549 ms
64 bytes from 192.168.0.10: icmp_seq=73. time=89005.630 ms
64 bytes from 192.168.0.10: icmp_seq=74. time=88005.715 ms
64 bytes from 192.168.0.10: icmp_seq=75. time=87005.797 ms
64 bytes from 192.168.0.10: icmp_seq=76. time=86005.870 ms
64 bytes from 192.168.0.10: icmp_seq=77. time=85005.954 ms
64 bytes from 192.168.0.10: icmp_seq=78. time=84006.032 ms
64 bytes from 192.168.0.10: icmp_seq=79. time=83006.100 ms
64 bytes from 192.168.0.10: icmp_seq=80. time=82006.204 ms
64 bytes from 192.168.0.10: icmp_seq=81. time=81006.288 ms
64 bytes from 192.168.0.10: icmp_seq=82. time=80006.345 ms
64 bytes from 192.168.0.10: icmp_seq=83. time=79006.442 ms
64 bytes from 192.168.0.10: icmp_seq=84. time=78006.543 ms
64 bytes from 192.168.0.10: icmp_seq=85. time=77006.620 ms
64 bytes from 192.168.0.10: icmp_seq=86. time=76006.704 ms
64 bytes from 192.168.0.10: icmp_seq=87. time=75006.786 ms
64 bytes from 192.168.0.10: icmp_seq=88. time=74006.850 ms
64 bytes from 192.168.0.10: icmp_seq=89. time=73006.941 ms
64 bytes from 192.168.0.10: icmp_seq=90. time=72007.025 ms
64 bytes from 192.168.0.10: icmp_seq=91. time=71007.111 ms
64 bytes from 192.168.0.10: icmp_seq=92. time=70007.195 ms
64 bytes from 192.168.0.10: icmp_seq=93. time=69007.271 ms
64 bytes from 192.168.0.10: icmp_seq=94. time=68007.362 ms
64 bytes from 192.168.0.10: icmp_seq=95. time=67007.362 ms
64 bytes from 192.168.0.10: icmp_seq=96. time=66007.512 ms
64 bytes from 192.168.0.10: icmp_seq=97. time=65007.598 ms
64 bytes from 192.168.0.10: icmp_seq=98. time=64007.702 ms
64 bytes from 192.168.0.10: icmp_seq=99. time=63007.793 ms
64 bytes from 192.168.0.10: icmp_seq=100. time=62007.869 ms
64 bytes from 192.168.0.10: icmp_seq=101. time=61007.947 ms
64 bytes from 192.168.0.10: icmp_seq=102. time=60008.040 ms
64 bytes from 192.168.0.10: icmp_seq=103. time=59008.116 ms
64 bytes from 192.168.0.10: icmp_seq=104. time=58008.190 ms
64 bytes from 192.168.0.10: icmp_seq=105. time=57008.252 ms
64 bytes from 192.168.0.10: icmp_seq=106. time=56008.335 ms
64 bytes from 192.168.0.10: icmp_seq=107. time=55008.412 ms
64 bytes from 192.168.0.10: icmp_seq=108. time=54008.473 ms
64 bytes from 192.168.0.10: icmp_seq=109. time=53008.535 ms
64 bytes from 192.168.0.10: icmp_seq=110. time=52008.606 ms
64 bytes from 192.168.0.10: icmp_seq=111. time=51008.671 ms
64 bytes from 192.168.0.10: icmp_seq=112. time=50008.738 ms
64 bytes from 192.168.0.10: icmp_seq=113. time=49008.816 ms
64 bytes from 192.168.0.10: icmp_seq=114. time=48008.870 ms
64 bytes from 192.168.0.10: icmp_seq=115. time=47008.949 ms
64 bytes from 192.168.0.10: icmp_seq=116. time=46009.020 ms
64 bytes from 192.168.0.10: icmp_seq=117. time=45009.106 ms
64 bytes from 192.168.0.10: icmp_seq=118. time=44009.129 ms
64 bytes from 192.168.0.10: icmp_seq=119. time=43009.208 ms
64 bytes from 192.168.0.10: icmp_seq=120. time=42009.266 ms
64 bytes from 192.168.0.10: icmp_seq=121. time=41009.317 ms
64 bytes from 192.168.0.10: icmp_seq=122. time=40009.385 ms
64 bytes from 192.168.0.10: icmp_seq=123. time=39009.444 ms
64 bytes from 192.168.0.10: icmp_seq=124. time=38009.481 ms
64 bytes from 192.168.0.10: icmp_seq=125. time=37009.568 ms
64 bytes from 192.168.0.10: icmp_seq=126. time=36009.620 ms
64 bytes from 192.168.0.10: icmp_seq=127. time=35009.660 ms
64 bytes from 192.168.0.10: icmp_seq=128. time=34009.708 ms
64 bytes from 192.168.0.10: icmp_seq=129. time=33009.755 ms
64 bytes from 192.168.0.10: icmp_seq=130. time=32009.797 ms
64 bytes from 192.168.0.10: icmp_seq=131. time=31009.843 ms
64 bytes from 192.168.0.10: icmp_seq=132. time=30009.889 ms
64 bytes from 192.168.0.10: icmp_seq=133. time=29009.921 ms
64 bytes from 192.168.0.10: icmp_seq=134. time=28009.976 ms
64 bytes from 192.168.0.10: icmp_seq=135. time=27010.022 ms
64 bytes from 192.168.0.10: icmp_seq=136. time=26010.055 ms
64 bytes from 192.168.0.10: icmp_seq=137. time=25010.098 ms
64 bytes from 192.168.0.10: icmp_seq=138. time=24010.132 ms
64 bytes from 192.168.0.10: icmp_seq=139. time=23010.171 ms
64 bytes from 192.168.0.10: icmp_seq=140. time=22010.211 ms
64 bytes from 192.168.0.10: icmp_seq=141. time=21010.256 ms
64 bytes from 192.168.0.10: icmp_seq=142. time=20010.293 ms
64 bytes from 192.168.0.10: icmp_seq=143. time=19015.189 ms
64 bytes from 192.168.0.10: icmp_seq=144. time=18015.281 ms
64 bytes from 192.168.0.10: icmp_seq=145. time=17015.343 ms
64 bytes from 192.168.0.10: icmp_seq=146. time=16015.427 ms
64 bytes from 192.168.0.10: icmp_seq=147. time=15015.499 ms
64 bytes from 192.168.0.10: icmp_seq=148. time=14015.544 ms
64 bytes from 192.168.0.10: icmp_seq=149. time=13015.628 ms
64 bytes from 192.168.0.10: icmp_seq=150. time=12015.690 ms
64 bytes from 192.168.0.10: icmp_seq=151. time=11015.748 ms
64 bytes from 192.168.0.10: icmp_seq=152. time=10015.823 ms
64 bytes from 192.168.0.10: icmp_seq=153. time=9015.896 ms
64 bytes from 192.168.0.10: icmp_seq=154. time=8015.970 ms
64 bytes from 192.168.0.10: icmp_seq=155. time=7016.046 ms
64 bytes from 192.168.0.10: icmp_seq=156. time=6016.118 ms
64 bytes from 192.168.0.10: icmp_seq=157. time=5016.197 ms
64 bytes from 192.168.0.10: icmp_seq=158. time=4016.266 ms
64 bytes from 192.168.0.10: icmp_seq=159. time=3016.337 ms
64 bytes from 192.168.0.10: icmp_seq=160. time=2016.366 ms
64 bytes from 192.168.0.10: icmp_seq=161. time=1016.474 ms
64 bytes from 192.168.0.10: icmp_seq=162. time=16.538 ms
64 bytes from 192.168.0.10: icmp_seq=163. time=2.186 ms
64 bytes from 192.168.0.10: icmp_seq=165. time=1.384 ms
64 bytes from 192.168.0.10: icmp_seq=166. time=2.142 ms
64 bytes from 192.168.0.10: icmp_seq=167. time=1.030 ms
64 bytes from 192.168.0.10: icmp_seq=168. time=2.067 ms
64 bytes from 192.168.0.10: icmp_seq=169. time=1.191 ms
64 bytes from 192.168.0.10: icmp_seq=170. time=2.381 ms
64 bytes from 192.168.0.10: icmp_seq=171. time=2.912 ms
64 bytes from 192.168.0.10: icmp_seq=172. time=2.091 ms
64 bytes from 192.168.0.10: icmp_seq=173. time=6.059 ms
64 bytes from 192.168.0.10: icmp_seq=174. time=1.129 ms
64 bytes from 192.168.0.10: icmp_seq=175. time=1.856 ms
64 bytes from 192.168.0.10: icmp_seq=176. time=1.140 ms
64 bytes from 192.168.0.10: icmp_seq=177. time=2.141 ms
64 bytes from 192.168.0.10: icmp_seq=178. time=1.145 ms
64 bytes from 192.168.0.10: icmp_seq=179. time=1.935 ms
64 bytes from 192.168.0.10: icmp_seq=180. time=0.904 ms
This message posted from opensolaris.org
_______________________________________________
networking-discuss mailing list
[email protected]
--
blu
"Remember 'A Thousand Points of Light'? With a network, we now have
a thousand points of failure."
----------------------------------------------------------------------
Brian Utterback - Solaris RPE, Sun Microsystems, Inc.
Ph:877-259-7345, Em:brian.utterback-at-ess-you-enn-dot-kom
_______________________________________________
networking-discuss mailing list
[email protected]
