Hi all,
I have an encountered a long poll delay (~67 sec) in all vswitchd
handler and revalidator threads.
Does someone have any idea what can cause this delay ?
I'm running ovs 2.3.0-1 release on Centos7.0.
No soft-lockups or high CPU load were detected at the time.
Much appreciated,
Ido
2015-12-17T10:05:50.841Z|00054|timeval(revalidator81)|WARN|Unreasonably
long 67345ms poll interval (38787002ms user, 47990452ms system)
2015-12-17T10:05:50.841Z|00055|timeval(revalidator81)|WARN|faults:
213374796 minor, 0 major
2015-12-17T10:05:50.841Z|00056|timeval(revalidator81)|WARN|disk: 0
reads, 1479664 writes
2015-12-17T10:05:50.841Z|00057|timeval(revalidator81)|WARN|context
switches: 1018364539 voluntary, 690112 involuntary
2015-12-17T10:05:50.841Z|00001|timeval(revalidator80)|WARN|Unreasonably
long 67345ms poll interval (38778926ms user, 47984018ms system)
2015-12-17T10:05:50.841Z|00002|timeval(revalidator80)|WARN|faults:
213365678 minor, 0 major
2015-12-17T10:05:50.841Z|00003|timeval(revalidator80)|WARN|disk: 0
reads, 1479664 writes
2015-12-17T10:05:50.841Z|00004|timeval(revalidator80)|WARN|context
switches: 1019037740 voluntary, 690009 involuntary
2015-12-17T10:05:50.841Z|00005|coverage(revalidator80)|INFO|Skipping
details of duplicate event coverage for hash=3f46a6c7
2015-12-17T10:05:50.841Z|00058|coverage(revalidator81)|INFO|Event
coverage, avg rate over last: 5 seconds, last minute, last hour,
hash=3f46a6c7:
2015-12-17T10:05:50.841Z|00059|coverage(revalidator81)|INFO|bridge_reconfigure
0.0/sec 0.000/sec 0.0000/sec total: 485
2015-12-17T10:05:50.841Z|00060|coverage(revalidator81)|INFO|ofproto_flush 0.0/sec
0.000/sec 0.0000/sec total: 4
2015-12-17T10:05:50.841Z|00061|coverage(revalidator81)|INFO|ofproto_recv_openflow
0.0/sec 0.000/sec 1.4550/sec total: 6566619
2015-12-17T10:05:50.841Z|00062|coverage(revalidator81)|INFO|ofproto_update_port
0.0/sec 0.000/sec 0.0000/sec total: 622
2015-12-17T10:05:50.841Z|00063|coverage(revalidator81)|INFO|rev_reconfigure
0.0/sec 0.000/sec 0.0000/sec total: 485
2015-12-17T10:05:50.841Z|00064|coverage(revalidator81)|INFO|rev_bond
0.0/sec 0.000/sec 0.0942/sec total: 306696
2015-12-17T10:05:50.841Z|00065|coverage(revalidator81)|INFO|rev_port_toggled
0.0/sec 0.000/sec 0.0000/sec total: 401
2015-12-17T10:05:50.841Z|00066|coverage(revalidator81)|INFO|rev_flow_table
0.0/sec 0.000/sec 0.0939/sec total: 306514
2015-12-17T10:05:50.841Z|00067|coverage(revalidator81)|INFO|rev_mac_learning
0.0/sec 0.000/sec 1.8539/sec total: 8362402
2015-12-17T10:05:50.841Z|00068|coverage(revalidator81)|INFO|upcall_duplicate_flow
0.0/sec 0.000/sec 0.0000/sec total: 1146
2015-12-17T10:05:50.841Z|00069|coverage(revalidator81)|INFO|revalidate_missed_dp_flow
0.0/sec 0.000/sec 0.0000/sec total: 520
2015-12-17T10:05:50.841Z|00070|coverage(revalidator81)|INFO|xlate_actions 1.8/sec
1.800/sec 586.0772/sec total: 1994317957
2015-12-17T10:05:50.841Z|00071|coverage(revalidator81)|INFO|dpif_port_add 0.0/sec
0.000/sec 0.0000/sec total: 213
2015-12-17T10:05:50.841Z|00072|coverage(revalidator81)|INFO|dpif_port_del 0.0/sec
0.000/sec 0.0000/sec total: 63
2015-12-17T10:05:50.841Z|00073|coverage(revalidator81)|INFO|dpif_flow_flush
0.0/sec 0.000/sec 0.0000/sec total: 5
2015-12-17T10:05:50.841Z|00074|coverage(revalidator81)|INFO|dpif_flow_get 0.0/sec
0.000/sec 0.0000/sec total: 520
2015-12-17T10:05:50.841Z|00075|coverage(revalidator81)|INFO|dpif_flow_put 0.0/sec
0.000/sec 0.0000/sec total: 2
2015-12-17T10:05:50.841Z|00076|coverage(revalidator81)|INFO|dpif_flow_del 0.0/sec
0.000/sec 0.0000/sec total: 1
2015-12-17T10:05:50.841Z|00077|coverage(revalidator81)|INFO|dpif_execute
0.0/sec 0.000/sec 4.0756/sec total: 18391617
2015-12-17T10:05:50.841Z|00078|coverage(revalidator81)|INFO|flow_extract
1.8/sec 1.250/sec 159.6722/sec total: 545357038
2015-12-17T10:05:50.841Z|00079|coverage(revalidator81)|INFO|hmap_pathological
0.0/sec 0.000/sec 0.2308/sec total: 1272572
2015-12-17T10:05:50.841Z|00080|coverage(revalidator81)|INFO|hmap_expand
0.0/sec 0.000/sec 515.4397/sec total: 1684910040
2015-12-17T10:05:50.841Z|00081|coverage(revalidator81)|INFO|mac_learning_learned
0.8/sec 0.067/sec 5.4594/sec total: 33649311
2015-12-17T10:05:50.841Z|00082|coverage(revalidator81)|INFO|mac_learning_expired
0.0/sec 0.000/sec 0.1664/sec total: 532896
2015-12-17T10:05:50.841Z|00083|coverage(revalidator81)|INFO|netdev_get_stats
0.0/sec 0.000/sec 42.0894/sec total: 132152766
2015-12-17T10:05:50.841Z|00084|coverage(revalidator81)|INFO|txn_unchanged 0.0/sec
0.000/sec 2.0317/sec total: 8866306
2015-12-17T10:05:50.841Z|00085|coverage(revalidator81)|INFO|txn_incomplete
0.0/sec 0.000/sec 51.5228/sec total: 165237796
2015-12-17T10:05:50.841Z|00086|coverage(revalidator81)|INFO|txn_success
0.0/sec 0.000/sec 0.1928/sec total: 873437
2015-12-17T10:05:50.841Z|00087|coverage(revalidator81)|INFO|poll_fd_wait
4.2/sec 3.650/sec 1498.3383/sec total: 5116753429
2015-12-17T10:05:50.841Z|00088|coverage(revalidator81)|INFO|poll_zero_timeout
0.8/sec 0.067/sec 10.2508/sec total: 46745736
2015-12-17T10:05:50.841Z|00089|coverage(revalidator81)|INFO|rconn_queued
0.0/sec 0.000/sec 0.9700/sec total: 4377623
2015-12-17T10:05:50.841Z|00090|coverage(revalidator81)|INFO|rconn_sent
0.0/sec 0.000/sec 0.9700/sec total: 4377623
2015-12-17T10:05:50.841Z|00091|coverage(revalidator81)|INFO|pstream_open
0.0/sec 0.000/sec 0.0000/sec total: 7
2015-12-17T10:05:50.841Z|00092|coverage(revalidator81)|INFO|stream_open
0.0/sec 0.000/sec 0.0000/sec total: 1
2015-12-17T10:05:50.841Z|00093|coverage(revalidator81)|INFO|unixctl_received
0.0/sec 0.000/sec 0.0000/sec total: 50
2015-12-17T10:05:50.841Z|00094|coverage(revalidator81)|INFO|unixctl_replied
0.0/sec 0.000/sec 0.0000/sec total: 50
2015-12-17T10:05:50.841Z|00095|coverage(revalidator81)|INFO|util_xalloc
10.0/sec 9.083/sec 17462.8672/sec total: 50451064451
2015-12-17T10:05:50.841Z|00096|coverage(revalidator81)|INFO|vconn_received
0.0/sec 0.000/sec 1.9400/sec total: 8755614
2015-12-17T10:05:50.841Z|00097|coverage(revalidator81)|INFO|vconn_sent
0.0/sec 0.000/sec 1.4550/sec total: 6566618
2015-12-17T10:05:50.841Z|00098|coverage(revalidator81)|INFO|netdev_set_policing
0.0/sec 0.000/sec 0.0000/sec total: 447
2015-12-17T10:05:50.841Z|00099|coverage(revalidator81)|INFO|netdev_get_ifindex
0.0/sec 0.000/sec 0.0000/sec total: 229
2015-12-17T10:05:50.841Z|00100|coverage(revalidator81)|INFO|netdev_get_hwaddr
0.0/sec 0.000/sec 0.0000/sec total: 231
2015-12-17T10:05:50.841Z|00101|coverage(revalidator81)|INFO|netdev_get_ethtool
0.0/sec 0.000/sec 0.0000/sec total: 1192
2015-12-17T10:05:50.841Z|00102|coverage(revalidator81)|INFO|netdev_set_ethtool
0.0/sec 0.000/sec 0.0000/sec total: 211
2015-12-17T10:05:50.841Z|00103|coverage(revalidator81)|INFO|netlink_overflow
0.0/sec 0.000/sec 0.0000/sec total: 3
2015-12-17T10:05:50.841Z|00104|coverage(revalidator81)|INFO|netlink_received
3.8/sec 2.517/sec 465.8917/sec total: 1537982685
2015-12-17T10:05:50.841Z|00105|coverage(revalidator81)|INFO|netlink_recv_jumbo
1.4/sec 0.117/sec 57.8981/sec total: 206257499
2015-12-17T10:05:50.841Z|00106|coverage(revalidator81)|INFO|netlink_sent
3.2/sec 2.833/sec 537.0692/sec total: 1712354725
2015-12-17T10:05:50.841Z|00107|coverage(revalidator81)|INFO|43 events
never hit
2015-12-17T10:05:50.841Z|00001|ofproto_dpif_upcall(revalidator77)|INFO|Spent
an unreasonably long 67346ms dumping flows
2015-12-17T10:05:50.842Z|00002|timeval(handler66)|WARN|Unreasonably long
65983ms poll interval (41111497ms user, 50500060ms system)
2015-12-17T10:05:50.842Z|00003|timeval(handler66)|WARN|faults: 212996880
minor, 0 major
2015-12-17T10:05:50.842Z|00004|timeval(handler66)|WARN|disk: 0 reads,
1479680 writes
2015-12-17T10:05:50.842Z|00005|timeval(handler66)|WARN|context switches:
1134479873 voluntary, 676252 involuntary
2015-12-17T10:05:50.842Z|00006|coverage(handler66)|INFO|Skipping details
of duplicate event coverage for hash=3f46a6c7
2015-12-17T10:05:50.843Z|00001|timeval(handler75)|WARN|Unreasonably long
65669ms poll interval (40702423ms user, 50011568ms system)
2015-12-17T10:05:50.843Z|00002|timeval(handler75)|WARN|faults: 212173367
minor, 0 major
2015-12-17T10:05:50.843Z|00003|timeval(handler75)|WARN|disk: 0 reads,
1479680 writes
2015-12-17T10:05:50.843Z|00004|timeval(handler75)|WARN|context switches:
1117671564 voluntary, 668028 involuntary
2015-12-17T10:05:50.843Z|00005|coverage(handler75)|INFO|Skipping details
of duplicate event coverage for hash=3f46a6c7
2015-12-17T10:05:50.844Z|00001|timeval(handler73)|WARN|Unreasonably long
67731ms poll interval (41629993ms user, 51234226ms system)
2015-12-17T10:05:50.844Z|00002|timeval(handler73)|WARN|faults: 215538525
minor, 0 major
2015-12-17T10:05:50.844Z|00003|timeval(handler73)|WARN|disk: 0 reads,
1479680 writes
2015-12-17T10:05:50.844Z|00004|timeval(handler73)|WARN|context switches:
1147315875 voluntary, 695546 involuntary
2015-12-17T10:05:50.844Z|00001|timeval(handler76)|WARN|Unreasonably long
68150ms poll interval (41375247ms user, 50903226ms system)
2015-12-17T10:05:50.844Z|00002|timeval(handler76)|WARN|faults: 214882885
minor, 0 major
2015-12-17T10:05:50.844Z|00003|timeval(handler76)|WARN|disk: 0 reads,
1479680 writes
2015-12-17T10:05:50.844Z|00004|timeval(handler76)|WARN|context switches:
1141377844 voluntary, 679237 involuntary
2015-12-17T10:05:50.846Z|00001|timeval(handler72)|WARN|Unreasonably long
66542ms poll interval (40630798ms user, 50134533ms system)
2015-12-17T10:05:50.846Z|00002|timeval(handler72)|WARN|faults: 214647871
minor, 0 major
2015-12-17T10:05:50.846Z|00003|timeval(handler72)|WARN|disk: 0 reads,
1479680 writes
2015-12-17T10:05:50.846Z|00004|timeval(handler72)|WARN|context switches:
1106144600 voluntary, 683727 involuntary
2015-12-17T10:05:50.846Z|00109|timeval(handler70)|WARN|Unreasonably long
66838ms poll interval (41364440ms user, 50836918ms system)
2015-12-17T10:05:50.846Z|00110|timeval(handler70)|WARN|faults: 215530701
minor, 0 major
2015-12-17T10:05:50.846Z|00111|timeval(handler70)|WARN|disk: 0 reads,
1479680 writes
2015-12-17T10:05:50.846Z|00112|timeval(handler70)|WARN|context switches:
1137789167 voluntary, 687389 involuntary
2015-12-17T10:05:50.847Z|00001|timeval(handler74)|WARN|Unreasonably long
65946ms poll interval (41561224ms user, 51140624ms system)
2015-12-17T10:05:50.847Z|00002|timeval(handler74)|WARN|faults: 216151264
minor, 0 major
2015-12-17T10:05:50.847Z|00003|timeval(handler74)|WARN|disk: 0 reads,
1479680 writes
2015-12-17T10:05:50.847Z|00004|timeval(handler74)|WARN|context switches:
1145683145 voluntary, 693270 involuntary
2015-12-17T10:05:50.847Z|00002|timeval(handler71)|WARN|Unreasonably long
68534ms poll interval (41099919ms user, 50499309ms system)
2015-12-17T10:05:50.847Z|00003|timeval(handler71)|WARN|faults: 212280225
minor, 0 major
2015-12-17T10:05:50.847Z|00004|timeval(handler71)|WARN|disk: 0 reads,
1479680 writes
2015-12-17T10:05:50.847Z|00005|timeval(handler71)|WARN|context switches:
1137412740 voluntary, 670414 involuntary
2015-12-17T10:05:50.848Z|00001|timeval(handler69)|WARN|Unreasonably long
68666ms poll interval (40792307ms user, 50110576ms system)
2015-12-17T10:05:50.848Z|00002|timeval(handler69)|WARN|faults: 212932774
minor, 0 major
2015-12-17T10:05:50.848Z|00003|timeval(handler69)|WARN|disk: 0 reads,
1479688 writes
2015-12-17T10:05:50.848Z|00004|timeval(handler69)|WARN|context switches:
1125479453 voluntary, 673834 involuntary
2015-12-17T10:05:50.849Z|00001|timeval(handler68)|WARN|Unreasonably long
68743ms poll interval (40350375ms user, 49492076ms system)
2015-12-17T10:05:50.849Z|00002|timeval(handler68)|WARN|faults: 212958735
minor, 0 major
2015-12-17T10:05:50.849Z|00003|timeval(handler68)|WARN|disk: 0 reads,
1479688 writes
2015-12-17T10:05:50.849Z|00004|timeval(handler68)|WARN|context switches:
1113028710 voluntary, 662368 involuntary
2015-12-17T10:05:50.877Z|00007|timeval(handler67)|WARN|Unreasonably long
68805ms poll interval (39577616ms user, 48122529ms system)
2015-12-17T10:05:50.877Z|00008|timeval(handler67)|WARN|faults: 211723762
minor, 0 major
2015-12-17T10:05:50.877Z|00009|timeval(handler67)|WARN|disk: 0 reads,
1479688 writes
2015-12-17T10:05:50.877Z|00010|timeval(handler67)|WARN|context switches:
1103437911 voluntary, 658842 involuntary
2015-12-17T10:05:50.878Z|1256871|timeval|WARN|Unreasonably long 68865ms
poll interval (29351421ms user, 37260291ms system)
2015-12-17T10:05:50.878Z|1256872|timeval|WARN|faults: 118301428 minor, 0
major
2015-12-17T10:05:50.878Z|1256873|timeval|WARN|disk: 0 reads, 1479672 writes
2015-12-17T10:05:50.878Z|1256874|timeval|WARN|context switches:
1119728722 voluntary, 524148 involuntary
_______________________________________________
discuss mailing list
[email protected]
http://openvswitch.org/mailman/listinfo/discuss
