Suricata

The http.log output module uses inefficient locking logic. It does expensive operations while holding a global output lock, resulting in lots of contention and very long lock wait times:

Lock                                               Cnt        Avg ticks Max ticks    Total ticks  Cont    Func
------------------                                 ---------- --------- ------------ ------------ ------- ---------
(spn) util-time.c:64                               1354508    171       53268714     232090559    229     TimeSet
(mtx) flow-hash.c:472                              1194641    183       966909       219697223    59      FlowGetFlowFromHash
(mtx) flow-queue.c:102                             113779     208       1045617      23695346     241     FlowDequeue
(mtx) flow-hash.c:447                              113779     211       254574       24076608     0       FlowGetNew
(mtx) flow-hash.c:565                              1076846    843       23373348     908027030    28698   FlowGetFlowFromHash
(mtx) stream-tcp.c:3862                            1157722    195       490731       226138454    1500    StreamTcp
(mtx) app-layer.c:302                              69661      105       36936        7326968      854     AppLayerHandleUdp
(mtx) detect.c:1305                                1241588    107       614838       133392733    2051    SigMatchSignatures
(mtx) flow.c:156                                   224755     98        226128       22054860     301     FlowSetIPOnlyFlag
(mtx) detect.c:1491                                2992100    105       1133352      315282467    3091    SigMatchSignatures
(mtx) detect.c:1750                                1240758    126       1151304      157380520    1524    SigMatchSignatures
(mtx) log-httplog.c:195                            1169267    137       1524858      161234681    948     LogHttpLogIPWrapper
(mtx) stream-tcp.c:534                             111311     338       1521714      37732819     616     StreamTcpNewSession
(mtx) stream-tcp-reassemble.c:3430                 321967     307       1183113      99030345     1300    StreamTcpGetSegment
(mtx) stream.c:124                                 196090     802       3297693      157384769    3365    StreamMsgGetFromPool
(mtx) detect-engine-state.c:246                    521619     100       508158       52521199     541     DeStateUpdateInspectTransactionId
(mtx) detect-engine-state.c:372                    521619     149       790554       78087585     0       DeStateFlowHasState
(mtx) stream-tcp-reassemble.c:226                  254658     183       1273503      46692354     613     StreamTcpSegmentReturntoPool
(mtx) detect-uricontent.c:317                      111167     114       237045       12706080     148     DetectUricontentInspectMpm
(mtx) detect-engine-uri.c:77                       946406     98        813807       93107755     3009    DetectEngineInspectPacketUris
(mtx) detect-engine-state.c:664                    110817     93        226845       10405282     0       DeStateDetectStartDetection
(mtx) detect-engine-state.c:680                    110729     98        322347       10927978     141     DeStateDetectStartDetection
(mtx) flow-bit.c:104                               4192       173       172854       728879       7       FlowBitSet
(mtx) flow-bit.c:140                               361557     87        257055       31761224     543     FlowBitIsset
(mtx) detect-engine-state.c:713                    120687     112       99153        13608805     0       DeStateDetectContinueDetection
(mtx) detect-engine-state.c:1198                   120687     102       443679       12407687     381     DeStateResetFileInspection
(mtx) alert-fastlog.c:133                          14376      3893      6380001      55969980     739     AlertFastLogIPv4
(mtx) alert-unified2-alert.c:1041                  15019      3226      6454671      48459354     569     Unified2IPv4TypeAlert
(mtx) alert-unified2-alert.c:1070                  14376      2655      658050       38170657     522     Unified2IPv4TypeAlert
(mtx) flow-bit.c:153                               2351       146       62103        345374       1       FlowBitIsnotset
(mtx) flow-hash.c:555                              3076       268       117348       827157       53      FlowGetFlowFromHash
(mtx) stream.c:133                                 166263     3005      21084432     499720323    3440    StreamMsgReturnToPool
(mtx) detect.c:1372                                3073       126       18873        387968       0       SigMatchSignatures
(mtx) log-httplog.c:273                            12787      123459    49227804     1578680930   2454    LogHttpLogIPWrapper
(mtx) stream-tcp.c:4615                            11545      197       26960        2281110      0       StreamTcpPseudoSetup
(mtx) host.c:394                                   259187     3457      26751192     896253818    9272    HostGetHostFromHash
(mtx) host-queue.c:100                             3435       207       14304        713442       3       HostDequeue
(mtx) host.c:359                                   3435       340       70605        1169114      0       HostGetNew
(mtx) detect.c:1716                                15987      112       95958        1793534      0       SigMatchSignatures
(mtx) host.c:473                                   255752     350       1854843      89589401     5097    HostGetHostFromHash
(mtx) stream-tcp.c:4742                            117        227       708          26640        0       StreamTcpSegmentForEach
(mtx) app-layer-parser.c:135                       769        165       3414         127233       0       AlpGetResultElmt
(mtx) app-layer-parser.c:157                       769        100       1173         77193        0       AlpReturnResultElmt
(mtx) detect-engine-alert.c:233                    3254       150       1641         489302       2       PacketAlertFinalize
(mtx) detect-engine-tag.c:470                      28928      105       64092        3042952      46      TagHandlePacket
(mtx) host.c:493                                   58104      654       2965407      38042690     583     HostLookupHostFromHash
(mtx) host.c:542                                   25434      298       2772434      7602540      199     HostLookupHostFromHash
(mtx) detect-engine-tag.c:105                      356        119       393          42507        0       TagFlowAdd
(mtx) flow-bit.c:115                               2          163       225          327          0       FlowBitUnset

Overall: locks 16661305, average cost 381, contentions 73140, total ticks 6351313756

The line of interest is this:

(mtx) log-httplog.c:273                            12787      123459    49227804     1578680930   2454    LogHttpLogIPWrapper

It shows that the average time to get the lock is extremely high vs the rest of the locks in use.

On this line the output file mutex lock is requested:

SCMutexLock(&hlog->file_ctx->fp_mutex);

Possible solutions:
- first buffer the full log record before writing to disk
- different output system altogether (see #352)