<div dir="ltr"><div><div><div><div><div><br></div>OS: Solaris 11 x86<br></div>Box: X4600 with 16 AMD8220 CPUs, 128GB RAM<br></div>Suricata: master copy as at 2013-12-02<br><br></div>The issue is there is a whole lot of dropped packets on one specific interface - the busy one.<br>
<br></div>The four threads on it:<br><div><span style="font-family:courier new,monospace">capture.kernel_packets | RxPcapnet121 | 31752019<br>capture.kernel_drops | RxPcapnet121 | 22262851<br>
capture.kernel_ifdrops | RxPcapnet121 | 0<br>capture.kernel_packets | RxPcapnet122 | 31751876<br>capture.kernel_drops | RxPcapnet122 | 21957313<br>capture.kernel_ifdrops | RxPcapnet122 | 0<br>
capture.kernel_packets | RxPcapnet123 | 31751474<br>capture.kernel_drops | RxPcapnet123 | 22119310<br>capture.kernel_ifdrops | RxPcapnet123 | 0<br>capture.kernel_packets | RxPcapnet124 | 31751149<br>
capture.kernel_drops | RxPcapnet124 | 21967330<br>capture.kernel_ifdrops | RxPcapnet124 | 0</span><br><br></div><div>If I use dtrace to profile the running sniffer, it's doing these syscalls (about 90 seconds or less of monitoring):<br>
<br><span style="font-family:courier new,monospace"> lwp_mutex_timedlock 1<br> lwp_mutex_wakeup 1<br> yield 40<br>
brk 56<br> write 3730<br> read 3860<br> nanosleep 9923<br>
ioctl 1337265<br> lwp_park 2462619</span><br><br></div><div>with some lively time spend doing the thread parking:<br>
<span style="font-family:courier new,monospace"><br> time in ioctl <br> value ------------- Distribution ------------- count <br> 0 | 0 <br>
1 |@ 40335 <br> 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1120796 <br> 4 | 7852 <br> 8 | 2026 <br>
16 | 1212 <br> 32 | 30 <br> 64 | 13 <br> 128 | 1 <br>
256 | 1 <br> 512 | 0 <br><br> time in lwp_park <br> value ------------- Distribution ------------- count <br>
0 | 0 <br> 1 | 1145 <br> 2 | 2463 <br> 4 |@@@@@@@@@@@@@@@@@@@@ 1102965 <br>
8 |@@@@@@@ 402356 <br> 16 |@@@@ 248113 <br> 32 |@@ 130450 <br> 64 |@@ 87946 <br>
128 |@@ 114933 <br> 256 |@@ 108908 <br> 512 | 24145 <br> 1024 | 6694 <br>
2048 | 4080 <br> 4096 | 1058 <br> 8192 | 266 <br> 16384 | 11 <br>
32768 | 0 <br> 65536 | 0 <br> 131072 | 0 <br> 262144 | 0 <br>
524288 | 94 <br> 1048576 | 0 <br> 2097152 | 30 <br> 4194304 | 0 <br>
8388608 | 8 <br> 16777216 | 0 <br> 33554432 | 0 <br> 67108864 | 0 <br>
134217728 | 0 <br> 268435456 | 0 <br> 536870912 | 0 <br> 1073741824 | 0 <br>
2147483648 | 0 <br> 4294967296 | 0 <br> 8589934592 | 0 <br> 17179869184 | 0 <br>
34359738368 | 0 <br> 68719476736 | 0 <br> 137438953472 | 0 <br> 274877906944 | 3 <br>
549755813888 | 0 </span><br><br></div><div>If I look at the ustack counts and summarise, here's the most busiest workflows that the binary is doing. You read it bottom to top, the one at the bottom had that workflow 5060 times during the 30 second scan. The stack at the top ran 2843 times.<br>
<br><span style="font-family:courier new,monospace"> suricata`PrintList+0x4e4<br> suricata`StreamTcpReassembleAppLayer+0x301<br> suricata`StreamTcpReassembleHandleSegmentUpdateACK+0x17b<br>
suricata`StreamTcpReassembleHandleSegment+0x1a0<br> suricata`HandleEstablishedPacketToServer+0x1888<br> suricata`StreamTcpPacketStateEstablished+0x20c6<br> suricata`StreamTcpPacket+0x82a<br>
suricata`StreamTcp+0x461<br> suricata`TmThreadsSlotVarRun+0xada<br> suricata`TmThreadsSlotProcessPkt+0x61<br> suricata`PcapCallbackLoop+0xd0b<br> libpcap.so.1.5.2`pcap_read_bpf+0x13d<br>
2843<br><br> suricata`PrintList+0x128<br> suricata`StreamTcpReassembleAppLayer+0x301<br> suricata`StreamTcpReassembleHandleSegmentUpdateACK+0x17b<br> suricata`StreamTcpReassembleHandleSegment+0x1a0<br>
suricata`HandleEstablishedPacketToServer+0x1888<br> suricata`StreamTcpPacketStateEstablished+0x20c6<br> suricata`StreamTcpPacket+0x82a<br> suricata`StreamTcp+0x461<br>
suricata`TmThreadsSlotVarRun+0xada<br>
suricata`TmThreadsSlotProcessPkt+0x61<br> suricata`PcapCallbackLoop+0xd0b<br> libpcap.so.1.5.2`pcap_read_bpf+0x13d<br> 2857<br><br> suricata`PrintList+0x132<br>
suricata`StreamTcpReassembleInsertSegment+0xe33<br> suricata`StreamTcpReassembleHandleSegmentHandleData+0x845<br> suricata`StreamTcpReassembleHandleSegment+0x417<br> suricata`HandleEstablishedPacketToClient+0x11bc<br>
suricata`StreamTcpPacketStateEstablished+0x227f<br> suricata`StreamTcpPacket+0x82a<br> suricata`StreamTcp+0x461<br> suricata`TmThreadsSlotVarRun+0xada<br> suricata`TmThreadsSlotProcessPkt+0x61<br>
suricata`PcapCallbackLoop+0xd0b<br> libpcap.so.1.5.2`pcap_read_bpf+0x13d<br> 2888<br><br> suricata`PrintList+0x4e4<br> suricata`StreamTcpReassembleInsertSegment+0xe33<br>
suricata`StreamTcpReassembleHandleSegmentHandleData+0x845<br> suricata`StreamTcpReassembleHandleSegment+0x417<br> suricata`HandleEstablishedPacketToClient+0x11bc<br> suricata`StreamTcpPacketStateEstablished+0x227f<br>
suricata`StreamTcpPacket+0x82a<br> suricata`StreamTcp+0x461<br> suricata`TmThreadsSlotVarRun+0xada<br> suricata`TmThreadsSlotProcessPkt+0x61<br> suricata`PcapCallbackLoop+0xd0b<br>
libpcap.so.1.5.2`pcap_read_bpf+0x13d<br> 2908<br><br> suricata`PrintList+0x4f0<br> suricata`StreamTcpReassembleInsertSegment+0xe33<br> suricata`StreamTcpReassembleHandleSegmentHandleData+0x845<br>
suricata`StreamTcpReassembleHandleSegment+0x417<br> suricata`HandleEstablishedPacketToClient+0x11bc<br> suricata`StreamTcpPacketStateEstablished+0x227f<br> suricata`StreamTcpPacket+0x82a<br>
suricata`StreamTcp+0x461<br> suricata`TmThreadsSlotVarRun+0xada<br> suricata`TmThreadsSlotProcessPkt+0x61<br> suricata`PcapCallbackLoop+0xd0b<br> libpcap.so.1.5.2`pcap_read_bpf+0x13d<br>
2976<br><br> libc.so.1`__lwp_unpark+0xb<br> suricata`StreamTcp+0x478<br> suricata`TmThreadsSlotVarRun+0xada<br> suricata`TmThreadsSlotProcessPkt+0x61<br> suricata`PcapCallbackLoop+0xd0b<br>
libpcap.so.1.5.2`pcap_read_bpf+0x13d<br> 3092<br><br> libc.so.1`mutex_trylock_adaptive+0x128<br> libc.so.1`mutex_lock_impl+0x14a<br> libc.so.1`mutex_lock+0x16<br>
suricata`SCProfilingAddPacketLocks+0x45<br> suricata`TmThreadsSlotVarRun+0xdbe<br> suricata`TmThreadsSlotProcessPkt+0x61<br> suricata`PcapCallbackLoop+0xd0b<br> libpcap.so.1.5.2`pcap_read_bpf+0x13d<br>
3236<br><br> libc.so.1`ioctl+0x7<br> suricata`PcapCallbackLoop+0xd4f<br> libpcap.so.1.5.2`pcap_read_bpf+0x13d<br> 5060</span><br><br></div><div>If I look at the PcapCallbackLoop process in source-pcap.c, it's not apparent which ioctl is being done.<br>
<br>Here's the ioctl arguments (there's thousands of these):<br><font><span style="font-family:courier new,monospace"><br>ioctl:entry ioctl arg0: 13 arg1: 1082147439 arg2: fd9ff4b0<br>ioctl:entry ioctl arg0: 13 arg1: 1082147439 arg2: fd9ff4b0<br>
ioctl:entry ioctl arg0: 13 arg1: 1082147439 arg2: fd9ff4b0<br>ioctl:entry ioctl arg0: 13 arg1: 1082147439 arg2: fd9ff4b0<br>ioctl:entry ioctl arg0: 13 arg1: 1082147439 arg2: fd9ff4b0<br>ioctl:entry ioctl arg0: 21 arg1: 1082147439 arg2: fd2074b0<br>
ioctl:entry ioctl arg0: 21 arg1: 1082147439 arg2: fd2074b0<br>ioctl:entry ioctl arg0: 21 arg1: 1082147439 arg2: fd2074b0<br>ioctl:entry ioctl arg0: 21 arg1: 1082147439 arg2: fd2074b0<br>ioctl:entry ioctl arg0: 21 arg1: 1082147439 arg2: fd2074b0<br>
ioctl:entry ioctl arg0: 21 arg1: 1082147439 arg2: fd2074b0<br>ioctl:entry ioctl arg0: 21 arg1: 1082147439 arg2: fd2074b0</span></font><br><br></div><div>The file descriptors are easy, from /proc/pid/path:<br><span style="font-family:courier new,monospace"><br>
lrwxrwxrwx 1 root root 0 Dec 17 21:34 13 -> /devices/pseudo/bpf@0:bpf<br>lrwxrwxrwx 1 root root 0 Dec 17 21:34 21 -> /devices/pseudo/bpf@0:bpf</span><br><br><br>4080426F is the hex value for <font><span style="font-family:courier new,monospace">1082147439. <br>
<span style="font-family:arial,helvetica,sans-serif"><br></span></span></font></div><div><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">The BPF ioctls for Solaris are:</span><br>
<br>#define BIOCGBLEN _IOR('B', 102, uint_t)<br>#define BIOCSBLEN _IOWR('B', 102, uint_t)<br>#define BIOCSETF _IOW('B', 103, struct bpf_program)<br>#define BIOCFLUSH _IO('B', 104)<br>
#define BIOCPROMISC _IO('B', 105)<br>#define BIOCGDLT _IOR('B', 106, uint_t)<br>#define BIOCGETIF _IOR('B', 107, struct ifreq)<br>#define BIOCGETLIF _IOR('B', 107, struct lifreq)<br>
#define BIOCSETIF _IOW('B', 108, struct ifreq)<br>#define BIOCSETLIF _IOW('B', 108, struct lifreq)<br>#define BIOCGSTATS _IOR('B', 111, struct bpf_stat)<br>#define BIOCGSTATSOLD _IOR('B', 111, struct bpf_stat_old)<br>
#define BIOCIMMEDIATE _IOW('B', 112, uint_t)<br>#define BIOCVERSION _IOR('B', 113, struct bpf_version)<br>#define BIOCSTCPF _IOW('B', 114, struct bpf_program)<br>#define BIOCSUDPF _IOW('B', 115, struct bpf_program)<br>
#define BIOCGHDRCMPLT _IOR('B', 116, uint_t)<br>#define BIOCSHDRCMPLT _IOW('B', 117, uint_t)<br>#define BIOCSDLT _IOW('B', 118, uint_t)<br>#define BIOCGDLTLIST _IOWR('B', 119, struct bpf_dltlist)<br>
#define BIOCGSEESENT _IOR('B', 120, uint_t)<br>#define BIOCSSEESENT _IOW('B', 121, uint_t)<br>#define BIOCSRTIMEOUT _IOW('B', 122, struct timeval)<br>#define BIOCGRTIMEOUT _IOR('B', 123, struct timeval)<br>
<br>#define BIOCSETF32 _IOW('B', 103, struct bpf_program32)<br>#define BIOCGDLTLIST32 _IOWR('B', 119, struct bpf_dltlist32)<br>#define BIOCSRTIMEOUT32 _IOW('B', 122, struct timeval32)<br>#define BIOCGRTIMEOUT32 _IOR('B', 123, struct timeval32)<br>
<span style="font-family:arial,helvetica,sans-serif"><br></span></span></font></div><div><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">I'll assume it's a read-only operation so I'll print out the _IOR ones:</span><br>
<br>#include <net/bpf.h><br>#include <net/if.h><br>#include <stdio.h><br><br>main() {<br><br> printf("BIOCGBLEN is %lx\n", BIOCGBLEN);<br> printf("BIOCGDLT is %lx\n", BIOCGDLT);<br>
printf("BIOCGETIF is %lx\n", BIOCGETIF);<br> printf("BIOCGETLIF is %lx\n", BIOCGETLIF);<br> printf("BIOCGSTATS is %lx\n", BIOCGSTATS);<br> printf("BIOCGSTATSOLD is %lx\n", BIOCGSTATSOLD);<br>
printf("BIOCVERSION is %lx\n", BIOCVERSION);<br> printf("BIOCGHDRCMPLT is %lx\n", BIOCGHDRCMPLT);<br> printf("BIOCGSEESENT is %lx\n", BIOCGSEESENT);<br> printf("BIOCGRTIMEOUT is %lx\n", BIOCGRTIMEOUT);<br>
printf("BIOCGRTIMEOUT32 is %lx\n", BIOCGRTIMEOUT32);<br>}<br><span style="font-family:arial,helvetica,sans-serif"><br></span></span></font></div><div><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">This gives:</span><br>
<br># ./bpf_decode <br>BIOCGBLEN is 40044266<br>BIOCGDLT is 4004426a<br>BIOCGETIF is 4020426b<br>BIOCGETLIF is 4078426b<br>BIOCGSTATS is 4080426f<br>BIOCGSTATSOLD is 4008426f<br>BIOCVERSION is 40044271<br>BIOCGHDRCMPLT is 40044274<br>
BIOCGSEESENT is 40044278<br>BIOCGRTIMEOUT is 4008427b<br>BIOCGRTIMEOUT32 is 4008427b<span style="font-family:arial,helvetica,sans-serif"><br><br></span></span></font></div><div><span style="font-family:arial,helvetica,sans-serif"><font>and that tells us </font></span><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">BIOCGSTATS is being called repeatedly. That's in libpcap-1.5.2:pcap-bpf.c:811:pcap_stats_bpf() routine. It's called via the </span></span></font><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif"><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">libpcap-1.5.2:</span></span></font>pcap.c:1595:pcap_stats() function and that gets called from suricata:source-pcap.c:151:PcapDumpCounters().<br>
<br>This code in source-pcap.c:PcapCallbackLoop() is doing it:<br><br><span style="font-family:courier new,monospace"> 278 /* Trigger one dump of stats every second */<br> 279 TimeGet(¤t_time);<br>
280 if (current_time.tv_sec != last_dump) {<br> 281 PcapDumpCounters(ptv);<br> 282 last_dump = current_time.tv_sec;<br> 283 }</span><br><br></span></span></font></div><div><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">I'm thinking last_dump should be a global long-lived variable, that survives _outside_ of the </span></span></font><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">PcapCallbackLoop() function.<br>
<br><span style="font-family:courier new,monospace">--- ../../suricata-master.orig/src/source-pcap.c Sun Dec 1 21:37:52 2013<br>+++ source-pcap.c Wed Dec 18 00:01:05 2013<br>@@ -224,12 +224,13 @@<br> <br> #endif<br>
<br>+time_t last_dump = 0;<br>+<br> void PcapCallbackLoop(char *user, struct pcap_pkthdr *h, u_char *pkt) {<br> SCEnter();<br> <br> PcapThreadVars *ptv = (PcapThreadVars *)user;<br> Packet *p = PacketGetFromQueueOrAlloc();<br>
- time_t last_dump = 0;<br> struct timeval current_time;<br> <br> if (unlikely(p == NULL)) {</span><br><br><br></span></span></font></div><div><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">It hasn't noticably affected my packet dropping rate (I need to code something to analyse the % per second) but the bpf stats are actually happening once a second now, and not 10000's of times a second, each time a packet was scanned. Down from over a million ioctls to just a few hundred.<br>
<br></span></span></font></div><div><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">Bug <a href="https://redmine.openinfosecfoundation.org/issues/1071">https://redmine.openinfosecfoundation.org/issues/1071</a> has been logged.<br>
<br></span></span></font></div><div><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif">ta,<br>Mark.<br></span></span></font></div><div><font><span style="font-family:courier new,monospace"><span style="font-family:arial,helvetica,sans-serif"><br>
</span><br></span></font></div></div>