<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(&current_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>