search

aabc / ipt-netflow

Netflow iptables module for Linux kernel (official)
https://github.com/aabc/ipt-netflow
502 stars 129 forks source link

Active flows -> maxflows #8

Closed hotid closed 10 years ago

hotid commented 10 years ago

Возникла проблема — при включении сбора netflow с ядром 3.12-0.bpo.1-amd64 (debian) наблюдаем странную картину — количество активных потоков быстро доходит до значения Maxflows (независимо от того что прописываем в Maxflows - если 2млн, то будет около 2млн active flows, если 5 - то около 5... и hashsize), при этом все ядра CPU загружаются на 100%.

Без включения модуля загрузка сервера около 45-55%. Пробовал собирать gcc-4.6 и 4.7, версию из гита и пропатченую под 3.12 ядро версию 1.8 sf.net — поведение одинаковое.

filename:       /lib/modules/3.12-0.bpo.1-amd64/extra/ipt_NETFLOW.ko
alias:          ip6t_NETFLOW
version:        v1.8-88-g3d95a40
description:    iptables NETFLOW target module
author:         <abc@telekom.ru>
license:        GPL
srcversion:     BB81820A4B072ABC44F32FF
depends:        x_tables,nf_conntrack
vermagic:       3.12-0.bpo.1-amd64 SMP mod_unload modversions
parm:           destination:export destination ipaddress:port (charp)
parm:           inactive_timeout:inactive flows timeout in seconds (int)
parm:           active_timeout:active flows timeout in seconds (int)
parm:           debug:debug verbosity level (int)
parm:           sndbuf:udp socket SNDBUF size (int)
parm:           protocol:netflow protocol version (5, 9, 10) (int)
parm:           refresh_rate:NetFlow v9/IPFIX refresh rate (packets) (uint)
parm:           timeout_rate:NetFlow v9/IPFIX timeout rate (minutes) (uint)
parm:           natevents:send NAT Events (int)
parm:           hashsize:hash table size (int)
parm:           maxflows:maximum number of flows (int)
parm:           aggregation:aggregation ruleset (charp)

Через пару минут после включения сбора netflow:

cat /proc/net/stat/ipt_netflow
ipt_NETFLOW version v1.8-88-g3d95a40, srcversion BB81820A4B072ABC44F32FF
Flows: active 2097152 (peak 2097154 reached 0d0h0m ago), mem 344064K, worker delay 1/250.
Hash: size 2097152 (mem 16384K), metric 1.80 [1.38, 1.06, 1.00]. MemTraf: 59360950 pkt, 43921086 K (pdu 47, 16777), Out 21793 pkt, 5661 K.
Rate: 8319109422 bits/sec, 1330298 packets/sec; Avg 1 min: 6033292747 bps, 997744 pps; 5 min: 1889587881 bps, 313228 pps
cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
Total stat: 29079737 57272837 2898410 [1.48],    0    0    0 788547, sock:    846 0 35, 1209 K, traffic: 59382696, 42897 MB, drop: 788547, 319615 K
cpu0  stat: 2406612 4955822 199760 [1.46],    0    0    0 61611, sock:      0 0 35, 0 K, traffic: 5093970, 4580 MB, drop: 61611, 42631 K
cpu1  stat: 2454484 4977685 201735 [1.47],    0    0    0 63587, sock:      0 0 0, 0 K, traffic: 5115833, 4571 MB, drop: 63587, 45853 K
cpu2  stat: 2422489 4989779 193239 [1.46],    0    0    0 61672, sock:      0 0 0, 0 K, traffic: 5121346, 4473 MB, drop: 61672, 43263 K
cpu3  stat: 2500132 4978297 195012 [1.48],    0    0    0 63033, sock:      0 0 0, 0 K, traffic: 5110276, 4603 MB, drop: 63033, 45550 K
cpu4  stat: 2500892 4993194 195650 [1.48],    0    0    0 63398, sock:      0 0 0, 0 K, traffic: 5125446, 4433 MB, drop: 63398, 45671 K
cpu5  stat: 2356626 4989722 197091 [1.45],    0    0    0 63508, sock:      0 0 0, 0 K, traffic: 5123304, 4812 MB, drop: 63508, 45162 K
cpu6  stat: 2429022 4574374 292711 [1.49],    0    0    0 67261, sock:      0 0 0, 0 K, traffic: 4799824, 2545 MB, drop: 67261, 8198 K
cpu7  stat: 2416686 4612401 280267 [1.49],    0    0    0 67481, sock:      0 0 0, 0 K, traffic: 4825187, 2509 MB, drop: 67481, 8199 K
cpu8  stat: 2410662 4534426 281994 [1.50],    0    0    0 65065, sock:      0 0 0, 0 K, traffic: 4751354, 2539 MB, drop: 65065, 7733 K
cpu9  stat: 2311269 4485719 278285 [1.48],    0    0    0 66667, sock:      0 0 0, 0 K, traffic: 4697337, 2573 MB, drop: 66667, 8430 K
cpu10  stat: 2421223 4594682 288828 [1.49],    0    0    0 74741, sock:    846 0 0, 1209 K, traffic: 4808769, 2646 MB, drop: 74741, 9488 K
cpu11  stat: 2449659 4586758 293838 [1.50],    0    0    0 70524, sock:      0 0 0, 0 K, traffic: 4810071, 2606 MB, drop: 70524, 9433 K
Protocol version 5 (netflow). Timeouts: active 1800, inactive 15. Maxflows 2097152
Natevents disabled, count start 0, stop 0.
sock0: xxxx:9996, sndbuf 212992, filled 1, peak 11521; err: sndbuf reached 0, connect 0, other 0
sock1: xxxx:10008, sndbuf 212992, filled 1, peak 11521; err: sndbuf reached 0, connect 0, other 0

c hashsize=4194304 maxflows=8388608, времени проходит несколько больше, не стал дожидаться пока дойдёт до maxflows, но суть та же:

cat /proc/net/stat/ipt_netflow
ipt_NETFLOW version v1.8-88-g3d95a40, srcversion BB81820A4B072ABC44F32FF
Flows: active 4359473 (peak 4359473 reached 0d0h0m ago), mem 715226K, worker delay 1/250.
Hash: size 4194304 (mem 32768K), metric 1.73 [1.52, 1.13, 1.00]. MemTraf: 129754830 pkt, 95334258 K (pdu 35, 2702), Out 19258 pkt, 4153 K.
Rate: 8006027836 bits/sec, 1326686 packets/sec; Avg 1 min: 7662537184 bps, 1271420 pps; 5 min: 3652303220 bps, 606691 pps
cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
Total stat: 55858373 125403065 4370993 [1.43],    0    0    0    0, sock:    766 0 93, 1095 K, traffic: 129774053, 93103 MB, drop: 0, 0 K
cpu0  stat: 4946433 10808378 287580 [1.44],    0    0    0    0, sock:      0 0 93, 0 K, traffic: 11095958, 9828 MB, drop: 0, 0 K
cpu1  stat: 4512064 10867387 286588 [1.40],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 11153974, 10018 MB, drop: 0, 0 K
cpu2  stat: 4621263 10871584 272504 [1.41],    0    0    0    0, sock:    766 0 0, 1095 K, traffic: 11144088, 9558 MB, drop: 0, 0 K
cpu3  stat: 4465696 10886852 274333 [1.40],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 11161184, 9814 MB, drop: 0, 0 K
cpu4  stat: 4925458 10884990 274303 [1.44],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 11159293, 9793 MB, drop: 0, 0 K
cpu5  stat: 4529192 10837435 279523 [1.40],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 11116957, 10287 MB, drop: 0, 0 K
cpu6  stat: 4387833 10047587 459515 [1.41],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 10507101, 5687 MB, drop: 0, 0 K
cpu7  stat: 4674387 10104007 444188 [1.44],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 10548194, 5463 MB, drop: 0, 0 K
cpu8  stat: 4472014 9978629 447215 [1.42],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 10425843, 5608 MB, drop: 0, 0 K
cpu9  stat: 4882551 9907934 445192 [1.47],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 10353126, 5548 MB, drop: 0, 0 K
cpu10  stat: 4711265 10093532 441876 [1.44],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 10535408, 5660 MB, drop: 0, 0 K
cpu11  stat: 4730233 10114770 458177 [1.44],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 10572946, 5836 MB, drop: 0, 0 K
Protocol version 5 (netflow). Timeouts: active 1800, inactive 15. Maxflows 8388608
Natevents disabled, count start 0, stop 0.

При этом

conntrack -S
entries                 979862
searched                474526113
found                   3928426135
new                     341025794
invalid                 4273569
ignore                  11428
delete                  375566856
delete_list             70045157
insert                  19763147
insert_failed           125
drop                    0
early_drop              0
icmp_error              1132658
expect_new              4921
expect_create           22802
expect_delete           4952
search_restart          2

perf top с netflow:

 55.87%  [kernel]                  [k] _raw_spin_lock
  4.65%  [kernel]                  [k] netflow_target
  4.45%  [kernel]                  [k] ____nf_conntrack_find
  3.13%  [kernel]                  [k] _raw_read_unlock_bh
  3.08%  [kernel]                  [k] fib_table_lookup
  1.70%  [kernel]                  [k] _raw_read_lock_bh
  1.62%  [kernel]                  [k] ixgbe_clean_rx_irq
  1.45%  [kernel]                  [k] ipt_do_table
  1.18%  [kernel]                  [k] ixgbe_xmit_frame_ring
  0.90%  [kernel]                  [k] ip_route_input_noref
  0.83%  [kernel]                  [k] nf_nat_setup_info
  0.77%  [kernel]                  [k] __netif_receive_skb_core
  0.73%  [kernel]                  [k] tcp_packet
  0.72%  [kernel]                  [k] memcmp
  0.67%  [kernel]                  [k] nf_iterate
  0.54%  [kernel]                  [k] kmem_cache_free

perf top без netflow:

  9.57%  [kernel]             [k] ____nf_conntrack_find
  7.78%  [kernel]             [k] fib_table_lookup
  6.09%  [kernel]             [k] _raw_spin_lock
  4.42%  [kernel]             [k] ixgbe_clean_rx_irq
  3.19%  [kernel]             [k] ixgbe_xmit_frame_ring
  3.18%  libc-2.13.so         [.] 0x000000000011aee9
  2.72%  [kernel]             [k] ipt_do_table
  2.27%  [kernel]             [k] ip_route_input_noref
  2.09%  [kernel]             [k] _raw_spin_lock_bh
  2.03%  [kernel]             [k] __netif_receive_skb_core

В контреке около 900 тыс записей, суммарный трафик проходящий через сервер — около 10гбит.

Подскажите, куда копать?

aabc commented 10 years ago

10гбит мы не тестировали. Подумаю над вашими данными. Как я понял Natevents вы не используете (эту фичу я хочу удалить в будущем). Интересно "55.87% [kernel] [k] _raw_spin_lock" какой там stack trace.

В git версии уже есть оптимизация для лучшего распараллеливания, но может её недостаточно, надо думать и смотреть, но к сожалению у меня настолько загруженного сервера нет.

hotid commented 10 years ago

10Гбит - это суммарный траффик проходящий в обе стороны, т.е. на сервер с одной стороны пришло около 7-8 гбит, с другой стороны - 2-3.

natevents не используем, пока руки не доходили до них.

Если подскажете как посмотреть stack trace - с радостью покажу.

Насколько я понял - до какого-то момента всё работало нормально, включение netflow добавляло процентов 10 нагрузки, однако при достижении 5,5-6Гбит, по мере дальнейшего роста полосы - загрузка в течение часа выросла с 40% до 100%, после чего netflow отключили.

Попробую позже посмотреть не вернётся ли всё в норму при уменьшении количества трафика.

aabc commented 10 years ago

Насчет perf, наилучших команд не скажу, но там на период, скажем пара сек, надо запустить perf record с опциями -a и -g (скажем perf record -ag sleep 1), а потом кажется perf report -g, и нажмите там ентер на верхнюю строку где максимальная нагрузка cpu, скорее всего это будет _raw_spin_lock и оно должно показать call graph, надеюсь. К сожалению не гуру по perf.

hotid commented 10 years ago

Хм, сейчас совсем подругому выглядит:

 57.46%  [kernel]            [k] memcmp
  6.32%  [kernel]            [k] _raw_spin_lock
  5.76%  [kernel]            [k] netflow_target
  3.19%  [kernel]            [k] ____nf_conntrack_find
  2.45%  [kernel]            [k] fib_table_lookup
  1.44%  [kernel]            [k] ixgbe_clean_rx_irq
  1.34%  [kernel]            [k] ipt_do_table
  1.31%  [kernel]            [k] _raw_read_unlock_bh
ipt_NETFLOW version v1.8-88-g3d95a40, srcversion BB81820A4B072ABC44F32FF
Flows: active 2000000 (peak 2000002 reached 0d0h0m ago), mem 328125K, worker delay 1/250.
Hash: size 8192 (mem 64K), metric 17.24 [7.75, 3.56, 1.92]. MemTraf: 70248134 pkt, 54304017 K (pdu 1, 189), Out 34594222 pkt, 27525952 K.
Rate: 2835581474 bits/sec, 480407 packets/sec; Avg 1 min: 4216948022 bps, 687468 pps; 5 min: 2712760945 bps, 427786 pps
cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
Total stat: 9387348410 101565070 4166237 [89.78],    0    0    0 888952, sock:  42577 0 42577, 60870 K, traffic: 104842355, 79912 MB, drop: 888952, 240889 K
cpu0  stat: 852666637 9372715 285911 [89.28],    0    0    0 65531, sock:      0 0 0, 0 K, traffic: 9593095, 9442 MB, drop: 65531, 28532 K
cpu1  stat: 897818441 9721017 288348 [90.69],    0    0    0 66900, sock:      0 0 0, 0 K, traffic: 9942465, 9752 MB, drop: 66900, 30428 K
cpu2  stat: 877686146 9538646 283028 [90.36],    0    0    0 73717, sock:  42577 0 42577, 60870 K, traffic: 9747957, 9413 MB, drop: 73717, 36984 K
cpu3  stat: 814788436 9052993 275921 [88.34],    0    0    0 64737, sock:      0 0 0, 0 K, traffic: 9264177, 9104 MB, drop: 64737, 29957 K
cpu4  stat: 855500216 9405668 275731 [89.36],    0    0    0 64674, sock:      0 0 0, 0 K, traffic: 9616725, 9192 MB, drop: 64674, 29273 K
cpu5  stat: 821964211 9118140 278366 [88.47],    0    0    0 66208, sock:      0 0 0, 0 K, traffic: 9330298, 8943 MB, drop: 66208, 31206 K
cpu6  stat: 715233252 7604971 420738 [90.11],    0    0    0 83596, sock:      0 0 0, 0 K, traffic: 7942113, 4044 MB, drop: 83596, 9426 K
cpu7  stat: 716161731 7650890 426104 [89.66],    0    0    0 81765, sock:      0 0 0, 0 K, traffic: 7995229, 4083 MB, drop: 81765, 9237 K
cpu8  stat: 706144068 7515407 403255 [90.17],    0    0    0 80142, sock:      0 0 0, 0 K, traffic: 7838520, 3790 MB, drop: 80142, 8843 K
cpu9  stat: 701037384 7393608 406882 [90.87],    0    0    0 79944, sock:      0 0 0, 0 K, traffic: 7720546, 3746 MB, drop: 79944, 8934 K
cpu10  stat: 719802766 7639043 413498 [90.38],    0    0    0 80464, sock:      0 0 0, 0 K, traffic: 7972077, 4248 MB, drop: 80464, 8976 K
cpu11  stat: 708546679 7551983 408456 [90.00],    0    0    0 81275, sock:      0 0 0, 0 K, traffic: 7879164, 4148 MB, drop: 81275, 9086 K
Protocol version 5 (netflow). Timeouts: active 1800, inactive 15. Maxflows 2000000
Natevents disabled, count start 0, stop 0.
 conntrack -S
entries                 682135

Ерунда какая-то....

Сходу perf record/report не осилил, завтра попробую разобраться.

hotid commented 10 years ago

А, так и должно быть - это я hashsize не указал. С hashsize=4194304 и maxflows=8388608:

 55.66%  [kernel]            [k] _raw_spin_lock
  4.83%  [kernel]            [k] netflow_target
  3.42%  [kernel]            [k] _raw_read_unlock_bh
  3.26%  [kernel]            [k] ____nf_conntrack_find
  3.12%  [kernel]            [k] fib_table_lookup
  1.86%  [kernel]            [k] _raw_read_lock_bh
  1.84%  [kernel]            [k] ixgbe_clean_rx_irq
ipt_NETFLOW version v1.8-88-g3d95a40, srcversion BB81820A4B072ABC44F32FF
Flows: active 694574 (peak 694574 reached 0d0h0m ago), mem 113953K, worker delay 1/250.
Hash: size 4194304 (mem 32768K), metric 1.10 [1.02, 1.00, 1.00]. MemTraf: 24291802 pkt, 19788720 K (pdu 4, 1306), Out 180155 pkt, 96702 K.
Rate: 9031966964 bits/sec, 1357789 packets/sec; Avg 1 min: 3582392219 bps, 539248 pps; 5 min: 840100402 bps, 126448 pps
cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
Total stat: 1910956 23724670 747287 [1.07],    0    0    0    0, sock:   1757 0 1757, 2511 K, traffic: 24471953, 19419 MB, drop: 0, 0 K
cpu0  stat: 156316 2236968  47682 [1.06],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 2284650, 2208 MB, drop: 0, 0 K
cpu1  stat: 169840 2119845  48078 [1.07],    0    0    0    0, sock:   1757 0 1757, 2511 K, traffic: 2167923, 2085 MB, drop: 0, 0 K
cpu2  stat: 169281 2216891  46060 [1.07],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 2262950, 2113 MB, drop: 0, 0 K
cpu3  stat: 197828 2084334  45961 [1.09],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 2130294, 1985 MB, drop: 0, 0 K
cpu4  stat: 165905 2224882  45317 [1.07],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 2270199, 2133 MB, drop: 0, 0 K
cpu5  stat: 176012 2131268  46070 [1.08],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 2177337, 2033 MB, drop: 0, 0 K
cpu6  stat: 154856 1768044  80337 [1.08],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1848381, 1094 MB, drop: 0, 0 K
cpu7  stat: 132896 1812823  79400 [1.07],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1892223, 1197 MB, drop: 0, 0 K
cpu8  stat: 151756 1826928  74875 [1.07],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1901803, 1150 MB, drop: 0, 0 K
cpu9  stat: 136049 1765338  77044 [1.07],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1842381, 1130 MB, drop: 0, 0 K
cpu10  stat: 164152 1814062  77730 [1.08],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1891791, 1169 MB, drop: 0, 0 K
cpu11  stat: 136068 1723311  78733 [1.07],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1802044, 1115 MB, drop: 0, 0 K
Protocol version 5 (netflow). Timeouts: active 1800, inactive 15. Maxflows 8388608
Natevents disabled, count start 0, stop 0.
hotid commented 10 years ago

Трафика около 8Гбит in+out:

hashsize=65536 maxflows=2097152

ipt_NETFLOW version v1.8-88-g3d95a40, srcversion BB81820A4B072ABC44F32FF
Flows: active 642281 (peak 728124 reached 0d0h0m ago), mem 105374K, worker delay 1/250.
Hash: size 65536 (mem 512K), metric 0.95 [1.49, 1.27, 1.06]. MemTraf: 75415987 pkt, 62174669 K (pdu 21, 3196), Out 17107434 pkt, 12803364 K.
Rate: 8640058316 bits/sec, 1310139 packets/sec; Avg 1 min: 7957648532 bps, 1198162 pps; 5 min: 3093867760 bps, 465881 pps
cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
Total stat: 681223419 90110325 2413075 [8.36],    0    0    0    0, sock:  59026 0 59026, 84388 K, traffic: 92523400, 73220 MB, drop: 0, 0 K
cpu0  stat: 63097902 8650482 159769 [8.16],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 8810251, 8461 MB, drop: 0, 0 K
cpu1  stat: 59519206 8058667 160552 [8.24],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 8219219, 7695 MB, drop: 0, 0 K
cpu2  stat: 59397169 8276020 154270 [8.04],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 8430290, 8015 MB, drop: 0, 0 K
cpu3  stat: 56066397 7788994 154406 [8.05],    0    0    0    0, sock:  59026 0 59026, 84388 K, traffic: 7943400, 7374 MB, drop: 0, 0 K
cpu4  stat: 58904684 8092779 153793 [8.14],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 8246572, 7527 MB, drop: 0, 0 K
cpu5  stat: 60202854 8155008 155004 [8.24],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 8310012, 7498 MB, drop: 0, 0 K
cpu6  stat: 53777419 6903694 245469 [8.52],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 7149163, 4270 MB, drop: 0, 0 K
cpu7  stat: 55395644 7025451 259551 [8.60],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 7285002, 4700 MB, drop: 0, 0 K
cpu8  stat: 53865338 6902496 239330 [8.54],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 7141826, 4322 MB, drop: 0, 0 K
cpu9  stat: 56497530 6998797 240218 [8.80],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 7239015, 4646 MB, drop: 0, 0 K
cpu10  stat: 52643151 6745101 246548 [8.52],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 6991649, 4418 MB, drop: 0, 0 K
cpu11  stat: 51856272 6512859 244165 [8.67],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 6757024, 4290 MB, drop: 0, 0 K
Protocol version 5 (netflow). Timeouts: active 1800, inactive 15. Maxflows 2097152
Natevents disabled, count start 0, stop 0.
 32.71%  [kernel]            [k] _raw_spin_lock
  6.67%  [kernel]            [k] memcmp
  5.92%  [kernel]            [k] netflow_target
  4.48%  [kernel]            [k] ____nf_conntrack_find
  4.38%  [kernel]            [k] fib_table_lookup
  3.60%  [kernel]            [k] _raw_read_unlock_bh
  2.69%  [kernel]            [k] _raw_read_lock_bh
  2.68%  [kernel]            [k] ixgbe_clean_rx_irq

Количество flow НЕ растёт, кушает при этом под 20-25% процессора.

Перезагрузил модуль с hashsize=16384 maxflows=2097152

cat /proc/net/stat/ipt_netflow
ipt_NETFLOW version v1.8-88-g3d95a40, srcversion BB81820A4B072ABC44F32FF
Flows: active 840218 (peak 840218 reached 0d0h0m ago), mem 137848K, worker delay 1/250.
Hash: size 16384 (mem 128K), metric 5.74 [3.26, 1.58, 1.19]. MemTraf: 37830296 pkt, 30713039 K (pdu 25, 4006), Out 1310476 pkt, 861183 K.
Rate: 8735688900 bits/sec, 1320059 packets/sec; Avg 1 min: 5073089904 bps, 767700 pps; 5 min: 1349770158 bps, 204233 pps
cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
Total stat: 1043391651 38050382 1090365 [27.65],    0    0    0    0, sock:   8338 0 8338, 11920 K, traffic: 39140747, 30834 MB, drop: 0, 0 K
cpu0  stat: 88436760 3343694  71466 [26.89],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3415160, 3114 MB, drop: 0, 0 K
cpu1  stat: 92034484 3494683  71948 [26.80],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3566631, 3273 MB, drop: 0, 0 K
cpu2  stat: 92954705 3485238  68434 [27.15],    0    0    0    0, sock:   8338 0 8338, 11920 K, traffic: 3553672, 3266 MB, drop: 0, 0 K
cpu3  stat: 86071362 3279349  68498 [26.70],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3347847, 3077 MB, drop: 0, 0 K
cpu4  stat: 97564701 3655245  68285 [27.20],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3723530, 3480 MB, drop: 0, 0 K
cpu5  stat: 89335051 3353691  69391 [27.09],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3423082, 3116 MB, drop: 0, 0 K
cpu6  stat: 80567394 2817967 112057 [28.49],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 2930024, 1804 MB, drop: 0, 0 K
cpu7  stat: 88945647 3073324 115415 [28.89],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3188739, 2142 MB, drop: 0, 0 K
cpu8  stat: 83963234 2958628 109424 [28.36],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3068052, 1885 MB, drop: 0, 0 K
cpu9  stat: 80447957 2801303 109741 [28.63],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 2911044, 1789 MB, drop: 0, 0 K
cpu10  stat: 81121932 2889989 113137 [28.01],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3003126, 1901 MB, drop: 0, 0 K
cpu11  stat: 81948996 2897292 112569 [28.22],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3009861, 1982 MB, drop: 0, 0 K
Protocol version 5 (netflow). Timeouts: active 1800, inactive 15. Maxflows 2097152
Natevents disabled, count start 0, stop 0.
19.85%  [kernel]                  [k] _raw_spin_lock
 10.95%  [kernel]                  [k] memcmp
  6.44%  [kernel]                  [k] netflow_target
  5.16%  [kernel]                  [k] ____nf_conntrack_find
  4.91%  [kernel]                  [k] fib_table_lookup
  3.48%  [kernel]                  [k] _raw_read_unlock_bh

И active растёт дальше...

Снова загрузил с hashsize=65536 maxflows=2097152 - Flows: active 625117, грузит примерно 20% CPU и НЕ растёт, зараза.

Загружаю с hashsize=4194304 maxflows=8388608 (параметры, с которыми сегодня в ЧНН начался неконтролируемый рост active flows. В принципе - значения явно завышены, надо поделить как минимум на 2...исторически сложилось), получаю Flows: active 605657, не растут, при этом CPU нагружает где-то на 10%. perf top:

 29.44%  [kernel]              [k] _raw_spin_lock
  5.76%  [kernel]              [k] netflow_target
  4.84%  [kernel]              [k] fib_table_lookup
  4.77%  [kernel]              [k] ____nf_conntrack_find
  3.69%  [kernel]              [k] _raw_read_unlock_bh
  2.94%  [kernel]              [k] ixgbe_clean_rx_irq
aabc commented 10 years ago

Предполагаю, что у вас статистика правильная.

Total stat: 29079737 57272837 2898410  traffic: 59382696, 42897 MB, active 2097152, 1330298 packets/sec
Total stat: 55858373 125403065 4370993 traffic: 129774053, 93103 MB, active 4359473, 1326686 packets/sec

Согласно вашей статистике, у вас средняя длинна потока 19.7 и 28.6 пакетов, что, на мой взгляд, является нормальным для небольшого промежутка времени. MemTraf X pkt деленный на эту длину и даёт примерно столько потоков в памяти в данный момент. Rate X packets/sec деленная на эту длину дает сколько новых потоков у вас приходит в секунду (до 65к), при этом flow сидит в памяти минимум 15 (inactive timeout) секунд, то есть все это реально накапливается, до таких чисел. Большой трафик, плюс пиковая нагрузка.

Эмпирически советую вам поставить hashsize от 10000000 и выше. И не снижать при последующих тестах.

Total stat: 1043391651 38050382 1090365 [27.65],
Total stat: 681223419 90110325 2413075 [8.36],

27 и 8 значит хэш таблица используется крайне не эффективно - надо увеличивать пока не станет 1.

hotid commented 10 years ago 
27 и 8 значит хэш таблица используется не эффективно надо увеличивать пока не станет 1

Это я для теста значения брал, в порядке бреда. В нормальной работе у нас получается что-то около [1.10].

Не понятно почему при разных hashsize отличается количество active flow на сотни тысяч. Модуль перезагружал с интервалом в пару минут, так что трафик не сильно отличался.

Четыре теста:

hashsize=65536 maxflows=2097152 Flows: active 642281 (peak 728124 reached 0d0h0m ago)

hashsize=16384 maxflows=2097152 Flows: active 840218 (peak 840218 reached 0d0h0m ago) ( active ПРОДОЛЖАЕТ УВЕЛИЧИВАТЬСЯ пока не достигнет maxflows)

hashsize=65536 maxflows=2097152 Flows: active 625117

hashsize=4194304 maxflows=8388608 Flows: active 605657 (трафик постепенно снижается, так что и количество flow падает).

aabc commented 10 years ago

Насчет почему в conntrac -S меньше entries - другая логика хранения потоков - другие тайм-ауты. Можете поиграться с active/inactive timeouts, скажем сделать одинаковые по несколько сек (вплоть до 1) - количество потоков должно сократиться, но возрастёт трафик экспорта.

aabc commented 10 years ago

hashsize не может влиять на кол-во active Flows, тут и думать не над чем. Это флуктуация. Маленькие значения hashsize зато сильно влияют на загрузку процессора. (Вы как-то сто проблем одновременно обсуждаете.)

hotid commented 10 years ago

Хорошо, не буду упоминать про процессор. Причины различий между контреком и netflow понятны.

Проблема в том, что в какой-то момент по непонятной причине active flow начинает расти вплоть до maxflows. АНАЛОГИЧНОГО поведения я сейчас добился поставив неадекватно маленький hashsize:

ipt_NETFLOW version v1.8-88-g3d95a40, srcversion BB81820A4B072ABC44F32FF
Flows: active 2097152 (peak 2097153 reached 0d0h0m ago), mem 344064K, worker delay 1/250.
Hash: size 8192 (mem 64K), metric 6.96 [5.86, 3.15, 1.82]. MemTraf: 89379489 pkt, 70885981 K (pdu 46, 5323), Out 1352333 pkt, 921521 K.
Rate: 3661956546 bits/sec, 580407 packets/sec; Avg 1 min: 4913953117 bps, 770426 pps; 5 min: 2708083367 bps, 418930 pps
cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
Total stat: 9163822354 88397001 2637498 [101.66],    0    0    0 302723, sock:   7920 0 7920, 11323 K, traffic: 90731776, 70124 MB, drop: 302723, 111698 K
cpu0  stat: 817565152 8097808 180498 [99.75],    0    0    0 22821, sock:      0 0 0, 0 K, traffic: 8255485, 7889 MB, drop: 22821, 13347 K
cpu1  stat: 807990686 8002625 183459 [99.70],    0    0    0 25306, sock:      0 0 0, 0 K, traffic: 8160778, 7645 MB, drop: 25306, 16503 K
cpu2  stat: 862131676 8603346 175451 [99.20],    0    0    0 25171, sock:      0 0 0, 0 K, traffic: 8753626, 8614 MB, drop: 25171, 17407 K
cpu3  stat: 810021754 7916901 174071 [101.11],    0    0    0 23693, sock:      0 0 0, 0 K, traffic: 8067279, 7552 MB, drop: 23693, 15409 K
cpu4  stat: 826733116 8097270 173358 [100.96],    0    0    0 22941, sock:      0 0 0, 0 K, traffic: 8247687, 7768 MB, drop: 22941, 13766 K
cpu5  stat: 838330485 8105367 175389 [102.23],    0    0    0 25153, sock:      0 0 0, 0 K, traffic: 8255603, 7726 MB, drop: 25153, 16567 K
cpu6  stat: 700600358 6739183 261834 [101.07],    0    0    0 25105, sock:      0 0 0, 0 K, traffic: 6975912, 3743 MB, drop: 25105, 2986 K
cpu7  stat: 705832849 6690712 266086 [102.45],    0    0    0 26803, sock:      0 0 0, 0 K, traffic: 6929995, 4195 MB, drop: 26803, 3146 K
cpu8  stat: 683179280 6471292 255738 [102.55],    0    0    0 26220, sock:      0 0 0, 0 K, traffic: 6700810, 3379 MB, drop: 26220, 3040 K
cpu9  stat: 694848441 6508912 261937 [103.62],    0    0    0 25060, sock:      0 0 0, 0 K, traffic: 6745789, 3791 MB, drop: 25060, 3002 K
cpu10  stat: 714223664 6631487 260218 [104.63],    0    0    0 26316, sock:      0 0 0, 0 K, traffic: 6865389, 3999 MB, drop: 26316, 3161 K
cpu11  stat: 702367053 6532102 269462 [104.26],    0    0    0 28137, sock:   7920 0 7920, 11323 K, traffic: 6773427, 3817 MB, drop: 28137, 3359 K
Protocol version 5 (netflow). Timeouts: active 1800, inactive 15. Maxflows 2097152

Это тот же самый сервер что упомянут выше, с тем же самым трафиком.

hotid commented 10 years ago

И ещё раз тот же сервер, но с другими параметрами hashsize:

ipt_NETFLOW version v1.8-88-g3d95a40, srcversion BB81820A4B072ABC44F32FF
Flows: active 523870 (peak 533546 reached 0d0h0m ago), mem 85947K, worker delay 1/250.
Hash: size 4194304 (mem 32768K), metric 1.10 [1.03, 1.00, 1.00]. MemTraf: 35855502 pkt, 29528943 K (pdu 65, 20065), Out 3968213 pkt, 2787687 K.
Rate: 7445914378 bits/sec, 1130918 packets/sec; Avg 1 min: 5163497979 bps, 776994 pps; 5 min: 1507080029 bps, 226688 pps
cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
Total stat: 3345901 38747277 1076374 [1.08],    0    0    0    0, sock:  36832 0 26, 52658 K, traffic: 39823650, 31559 MB, drop: 0, 0 K
cpu0  stat: 250421 3582739  71554 [1.06],    0    0    0    0, sock:      0 0 26, 0 K, traffic: 3654292, 3317 MB, drop: 0, 0 K
cpu1  stat: 282411 3436690  71899 [1.08],    0    0    0    0, sock:  36832 0 0, 52658 K, traffic: 3508589, 3065 MB, drop: 0, 0 K
cpu2  stat: 269415 3398486  68479 [1.07],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3466965, 3246 MB, drop: 0, 0 K
cpu3  stat: 239421 3518530  68606 [1.06],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3587136, 3138 MB, drop: 0, 0 K
cpu4  stat: 224305 3408363  68434 [1.06],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3476796, 3136 MB, drop: 0, 0 K
cpu5  stat: 454002 3683836  67934 [1.12],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3751770, 3448 MB, drop: 0, 0 K
cpu6  stat: 304396 3192465 112586 [1.09],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3305051, 2128 MB, drop: 0, 0 K
cpu7  stat: 281691 3107588 111742 [1.08],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3219330, 2315 MB, drop: 0, 0 K
cpu8  stat: 234757 2931332 108503 [1.07],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3039835, 2035 MB, drop: 0, 0 K
cpu9  stat: 287941 2822256 108350 [1.09],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 2930605, 1830 MB, drop: 0, 0 K
cpu10  stat: 224213 2916398 109040 [1.07],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 3025438, 2061 MB, drop: 0, 0 K
cpu11  stat: 292930 2748625 109247 [1.10],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 2857872, 1836 MB, drop: 0, 0 K
Protocol version 5 (netflow). Timeouts: active 1800, inactive 15. Maxflows 8388608
Natevents disabled, count start 0, stop 0.

Как можно заметить - в первом случае Flows: active 2097152 Во втором - Flows: active 523870 На флуктуации, к сожалению, совсем не похоже.

aabc commented 10 years ago

Сервер тот же самый, но есть же колебания трафика. Обратите внимание, что у вас в первом случае packets/sec 580407, а во втором 1130918 в два раза больше. Очень много погрешности в данных - все равно что гадать по кофейной гуще.

АНАЛОГИЧНОГО поведения я сейчас добился поставив неадекватно маленький hashsize

Это интересно.

hotid commented 10 years ago

Да, я обратил внимание и на различия в кол-ве пакетов. Уверяю вас, трафик при этом через сервер бегает примерно одинаковый +-100мбит, и реальное количество пакетов не меняется.

hotid commented 10 years ago

Графики загрузки за день одного из ядер (остальные примерно одинаковы) http://igorsd.ru/graph_image_cpu.png и интерфеса http://igorsd.ru/graph_image.php.png

Рост загрузки cpu примерно совпадает с началом роста кол-ва active flows, пики - попытки включить сбор netflow с разными параметрами.

aabc commented 10 years ago

Подумаю на досуге как может hashsize влиять на кол-во потоков в памяти. По идее никак. Может быть там связь косвенная - маленький hashsize увеличивает нагрузку на процы, увеличивается latency, а это влияет на что-то ещё.

aabc commented 10 years ago

На флуктуации, к сожалению, совсем не похоже.

Похоже. В первом traffic stat 90731776 пакетов во втором 39823650 - разница в два-три раза. Соотв., в первом в памяти учтено 89379489 пакетов, во втором 35855502. В обоих случаях средняя длинна потока ~35 пакетов.

89379489 / 33.51 = 2667248.25, реальная цифра 4194304 ~ в два раза больше. 35855502 / 35.99 = 996262.90, реальная цифра 2097152 - в два раза больше. (Почему в два раза больше - не важно, главное, что почти совпадает.)

Природа IP трафика, что он очень неравномерный (там далеко не гауссово распределение и даже не пуассон). Плюс, кроме просто объема, у нас ещё играет роль длина потоков, что усложняет картину.

ps. То что вы показываете какие-то картинки, это все усреднение по 5-15 минут. Если у вас будет огромная пила, но с циклом меньше 5 минут, то вы увидите на таком графике прямую линию.

aabc commented 10 years ago

Я попробовал сделать hashsize меньше разумного (в версии 1.8), это не повлияло на кол-во активных потоков:

Flows: active 28398 (peak 134700 reached 4d6h18m ago), mem 2440K
Hash: size 80000 (mem 625K), metric 1.1, 1.0, 1.0, 1.0. MemTraf: 10954023 pkt, 5296876 K (pdu 33, 4005).

Flows: active 28389 (peak 134700 reached 4d6h20m ago), mem 2439K
Hash: size 200 (mem 1K), metric 117.9, 104.6, 42.3, 16.6. MemTraf: 10236885 pkt, 4925863 K (pdu 95, 8499).
hotid commented 10 years ago

Давайте уже исключим неравномерность трафика?

cat test.sh
#!/bin/bash

for id in `seq 0 10`;
    do
        iptables-restore < iptables-config_no_netflow
        rmmod ipt_NETFLOW
        modprobe ipt_NETFLOW hashsize=256 maxflows=2097152
        iptables-restore < iptables-config
        sleep 30
        echo "$id hashsize=256 maxflows=2097152" >> test.log
        cat /proc/net/stat/ipt_netflow >> test.log
        iptables-restore < iptables-config_no_netflow
        rmmod ipt_NETFLOW
        modprobe ipt_NETFLOW hashsize=32768 maxflows=2097152
        iptables-restore < iptables-config
        sleep 30
        echo "$id hashsize=32768 maxflows=2097152" >> test.log
        cat /proc/net/stat/ipt_netflow >> test.log
    done;

Трафика стало заметно меньше (около 3гбит), так что при hashsize=8192 работает адекватно, так что пришлось взять ещё более неадекватное значение hashsize=256. Вывод (позволил себе немного отформатировать):

 cat test.log | grep -E "hashsize|Flows"
0 hashsize=256 maxflows=2097152
Flows: active 353799 (peak 353841 reached 0d0h0m ago), mem 58045K, worker delay 1/250.
0 hashsize=32768 maxflows=2097152
Flows: active 253874 (peak 268530 reached 0d0h0m ago), mem 41651K, worker delay 1/250.

1 hashsize=256 maxflows=2097152
Flows: active 370128 (peak 370128 reached 0d0h0m ago), mem 60724K, worker delay 1/250.
1 hashsize=32768 maxflows=2097152
Flows: active 254897 (peak 268558 reached 0d0h0m ago), mem 41819K, worker delay 1/250.

2 hashsize=256 maxflows=2097152
Flows: active 356686 (peak 356726 reached 0d0h0m ago), mem 58518K, worker delay 1/250.
2 hashsize=32768 maxflows=2097152
Flows: active 248645 (peak 266193 reached 0d0h0m ago), mem 40793K, worker delay 1/250.

3 hashsize=256 maxflows=2097152
Flows: active 357725 (peak 357725 reached 0d0h0m ago), mem 58689K, worker delay 1/250.
3 hashsize=32768 maxflows=2097152
Flows: active 248832 (peak 266820 reached 0d0h0m ago), mem 40824K, worker delay 1/250.

4 hashsize=256 maxflows=2097152
Flows: active 347253 (peak 347253 reached 0d0h0m ago), mem 56971K, worker delay 1/250.
4 hashsize=32768 maxflows=2097152
Flows: active 254756 (peak 267575 reached 0d0h0m ago), mem 41795K, worker delay 1/250.

5 hashsize=256 maxflows=2097152
Flows: active 338089 (peak 338089 reached 0d0h0m ago), mem 55467K, worker delay 1/250.
5 hashsize=32768 maxflows=2097152
Flows: active 248498 (peak 265136 reached 0d0h0m ago), mem 40769K, worker delay 1/250.

6 hashsize=256 maxflows=2097152
Flows: active 339434 (peak 339512 reached 0d0h0m ago), mem 55688K, worker delay 1/250.
6 hashsize=32768 maxflows=2097152
Flows: active 247400 (peak 266166 reached 0d0h0m ago), mem 40589K, worker delay 1/250.

7 hashsize=256 maxflows=2097152
Flows: active 340501 (peak 340501 reached 0d0h0m ago), mem 55863K, worker delay 1/250.
7 hashsize=32768 maxflows=2097152
Flows: active 247904 (peak 259526 reached 0d0h0m ago), mem 40671K, worker delay 1/250.

8 hashsize=256 maxflows=2097152
Flows: active 323601 (peak 323601 reached 0d0h0m ago), mem 53090K, worker delay 1/250.
8 hashsize=32768 maxflows=2097152
Flows: active 245044 (peak 264838 reached 0d0h0m ago), mem 40202K, worker delay 1/250.

9 hashsize=256 maxflows=2097152
Flows: active 322460 (peak 322494 reached 0d0h0m ago), mem 52903K, worker delay 1/250.
9 hashsize=32768 maxflows=2097152
Flows: active 241722 (peak 256677 reached 0d0h0m ago), mem 39657K, worker delay 1/250.

10 hashsize=256 maxflows=2097152
Flows: active 327830 (peak 327830 reached 0d0h0m ago), mem 53784K, worker delay 1/250.
10 hashsize=32768 maxflows=2097152
Flows: active 245530 (peak 260191 reached 0d0h0m ago), mem 40282K, worker delay 1/250.

Я охотно верю что у вас при небольшом количестве трафика проблема не проявляется, мы с ней тоже до данного момента ни разу не встречались. Однако - закономерность присутствует, и я совершенно не могу представить себе механизм, благодаря которому что-то может начинать неверно отрабатывать при малом значении hashsize.

Как мне кажется, дело тут даже совершенно не в нём, однако при неадекватном значении оного, что-то начинает неверно отрабатывать и пакеты из одного потока перестают "склеиваться" в один flow в памяти. Собственно это видно по выводу данных из коллектора и tcpdump(точнее, вывода tcpdump там нету, поверьте на слово): http://forum.nag.ru/forum/index.php?showtopic=53979&st=200&gopid=928350&#entry928350 где один реальный поток пользователя виден в экспорте netflow как куча потоков с малым количеством пакетов.

hotid commented 10 years ago

Взял последнюю версию из Git:

 modinfo ipt_NETFLOW
filename:       /lib/modules/3.12-0.bpo.1-amd64/extra/ipt_NETFLOW.ko
alias:          ip6t_NETFLOW
version:        v1.8-89-gac34a2d
description:    iptables NETFLOW target module
author:         <abc@telekom.ru>
license:        GPL
srcversion:     E2C8F720F147CA785FD22CB
depends:        x_tables,nf_conntrack
vermagic:       3.12-0.bpo.1-amd64 SMP mod_unload modversions
parm:           destination:export destination ipaddress:port (charp)
parm:           inactive_timeout:inactive flows timeout in seconds (int)
parm:           active_timeout:active flows timeout in seconds (int)
parm:           debug:debug verbosity level (int)
parm:           sndbuf:udp socket SNDBUF size (int)
parm:           protocol:netflow protocol version (5, 9, 10) (int)
parm:           refresh_rate:NetFlow v9/IPFIX refresh rate (packets) (uint)
parm:           timeout_rate:NetFlow v9/IPFIX timeout rate (minutes) (uint)
parm:           natevents:send NAT Events (int)
parm:           hashsize:hash table size (int)
parm:           maxflows:maximum number of flows (int)
parm:           aggregation:aggregation ruleset (charp)
0 hashsize=256 maxflows=2097152
Flows: active 379864 (peak 379864 reached 0d0h0m ago), mem 62321K, worker delay 1/250.
0 hashsize=32768 maxflows=2097152
Flows: active 237551 (peak 249589 reached 0d0h0m ago), mem 38973K, worker delay 1/250.

Т.е. закономерность та же.

Попробуем для текущего трафика (3гбита) найти hashsize при котором начинается неадекват:

cat test2.sh
#!/bin/bash

for hashsize in 64 128 256 512 1024;
    do
        iptables-restore < iptables-config_no_netflow
        rmmod ipt_NETFLOW
        modprobe ipt_NETFLOW hashsize=$hashsize maxflows=2097152
        iptables-restore < iptables-config
        sleep 30
        echo "$hashsize hashsize=$hashsize maxflows=2097152" >> test2.log
        cat /proc/net/stat/ipt_netflow >> test2.log
    done;
cat test2.log | grep -E "hashsize|Flows"
64 hashsize=64 maxflows=2097152
Flows: active 293412 (peak 293412 reached 0d0h0m ago), mem 48137K, worker delay 1/250.
128 hashsize=128 maxflows=2097152
Flows: active 366444 (peak 366468 reached 0d0h0m ago), mem 60119K, worker delay 1/250.
256 hashsize=256 maxflows=2097152
Flows: active 327060 (peak 327060 reached 0d0h0m ago), mem 53658K, worker delay 1/250.
512 hashsize=512 maxflows=2097152
Flows: active 332980 (peak 332980 reached 0d0h0m ago), mem 54629K, worker delay 1/250.
1024 hashsize=1024 maxflows=2097152
Flows: active 225648 (peak 226516 reached 0d0h0m ago), mem 37020K, worker delay 1/250.

При hashsize=64 загрузка CPU 100%, при этом за 30 секунд просто не успело создаться более 293412 записей.

aabc commented 10 years ago

Cпасибо за тест. Сколько была нагрузка на проц во время тестов? (Мне интересно было ли стабильно 100% при hashsize 256, если да, то причина может быть косвенной - максимальная нагрузка как-то влияет). "Поверьте на слово" - дело-то не в вере, а в сужении области поиска возможных проблем. У flowа много параметров, а по ссылке на nag отображены не все параметры, следовательно, никаких выводов сделать нельзя. "Реальный поток пользователя виден в экспорте netflow как куча потоков с малым количеством пакетов" - я такое наблюдал при низких значения таймаутов.

"hashsize при котором начинается неадекват" - можете так же вывести значения нагрузки на проц(ы)?

aabc commented 10 years ago

А вы не могли бы для этих тестов прислать мне полный лог статистики (ваш test.log с cat /proc/net/stat/ipt_netflow)? Можно на е-майл (он указан в README). Хочу посмотреть как меняется статистика MemTraf и остальная per CPU.

hotid commented 10 years ago 
я такое наблюдал при низких значения таймаутов.

Таймауты были дефолтные - "active 1800, inactive 15". К сожалению более подробных логов не сохранилось. В принципе могу завтра попробовать повторить экперимент с tcpdump и отдельно взятым потоком.

Такс, про процессор при hashsize=256. Загрузил модуль, подождал несколько минут:

ipt_NETFLOW version v1.8-89-gac34a2d, srcversion E2C8F720F147CA785FD22CB
Flows: active 903511 (peak 903576 reached 0d0h0m ago), mem 148232K, worker delay 1/250.
Hash: size 256 (mem 2K), metric 81.65 [67.82, 35.19, 15.70]. MemTraf: 15416756 pkt, 9678868 K (pdu 18, 2133), Out 2663099 pkt, 1311869 K.
Rate: 60109150 bits/sec, 44081 packets/sec; Avg 1 min: 135851562 bps, 55457 pps; 5 min: 273233334 bps, 60628 pps
cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
Total stat: 17957852073 16570467 1509370 [994.25],    0    0    0    0, sock:  20195 0 20195, 28872 K, traffic: 18079837, 10733 MB, drop: 0, 0 K
cpu0  stat: 1631670181 1589494 109328 [961.47],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1698822, 1355 MB, drop: 0, 0 K
cpu1  stat: 1628389333 1527139 109344 [996.05],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1636483, 1241 MB, drop: 0, 0 K
cpu2  stat: 1698644055 1559235 104215 [1022.15],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1663450, 1252 MB, drop: 0, 0 K
cpu3  stat: 1467466119 1342845 103698 [1015.46],    0    0    0    0, sock:  20195 0 20195, 28872 K, traffic: 1446543, 1027 MB, drop: 0, 0 K
cpu4  stat: 1554085916 1415295 104200 [1023.76],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1519495, 1095 MB, drop: 0, 0 K
cpu5  stat: 1398679198 1318246 104565 [984.03],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1422811, 1044 MB, drop: 0, 0 K
cpu6  stat: 1485161855 1365761 148512 [981.77],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1514273, 681 MB, drop: 0, 0 K
cpu7  stat: 1511349465 1363109 147957 [1001.18],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1511066, 638 MB, drop: 0, 0 K
cpu8  stat: 1426712212 1292361 143387 [994.70],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1435748, 520 MB, drop: 0, 0 K
cpu9  stat: 1541185153 1389588 147000 [1003.99],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1536588, 689 MB, drop: 0, 0 K
cpu10  stat: 1354871106 1257261 144150 [967.79],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1401411, 614 MB, drop: 0, 0 K
cpu11  stat: 1259639407 1150134 143014 [975.08],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 1293148, 571 MB, drop: 0, 0 K
Protocol version 5 (netflow). Timeouts: active 1800, inactive 15. Maxflows 2097152

mpstat -P ALL 2 5
Linux 3.12-0.bpo.1-amd64 (nat-10g-3)    03/27/2014      _x86_64_        (12 CPU)

04:10:24 AM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
04:10:26 AM  all    0.00    0.00    0.10    0.00    0.00   89.41    0.00    0.00   10.50
04:10:26 AM    0    0.00    0.00    0.00    0.00    0.00   75.19    0.00    0.00   24.81
04:10:26 AM    1    0.00    0.00    0.00    0.00    0.00   77.93    0.00    0.00   22.07
04:10:26 AM    2    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:26 AM    3    0.00    0.00    0.50    0.00    0.00   82.91    0.00    0.00   16.58
04:10:26 AM    4    0.00    0.00    0.00    0.00    0.00   85.82    0.00    0.00   14.18
04:10:26 AM    5    0.00    0.00    0.83    0.00    0.00   73.33    0.00    0.00   25.83
04:10:26 AM    6    0.00    0.00    0.00    0.00    0.00   94.90    0.00    0.00    5.10
04:10:26 AM    7    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:26 AM    8    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:26 AM    9    0.00    0.00    0.00    0.00    0.00   98.48    0.00    0.00    1.52
04:10:26 AM   10    0.00    0.00    0.00    0.00    0.00   83.52    0.00    0.00   16.48
04:10:26 AM   11    0.00    0.00    0.00    0.00    0.00   83.62    0.00    0.00   16.38

04:10:26 AM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
04:10:28 AM  all    0.00    0.00    0.05    0.00    0.00   91.66    0.00    0.00    8.29
04:10:28 AM    0    0.00    0.00    0.00    0.00    0.00   86.90    0.00    0.00   13.10
04:10:28 AM    1    0.00    0.00    0.00    0.00    0.00   83.66    0.00    0.00   16.34
04:10:28 AM    2    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:28 AM    3    0.00    0.00    0.00    0.00    0.00   87.06    0.00    0.00   12.94
04:10:28 AM    4    0.00    0.00    0.00    0.00    0.00   92.52    0.00    0.00    7.48
04:10:28 AM    5    0.84    0.00    0.00    0.00    0.00   74.79    0.00    0.00   24.37
04:10:28 AM    6    0.00    0.00    0.00    0.00    0.00   96.97    0.00    0.00    3.03
04:10:28 AM    7    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:28 AM    8    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:28 AM    9    0.00    0.00    0.00    0.00    0.00   94.85    0.00    0.00    5.15
04:10:28 AM   10    0.00    0.00    0.56    0.00    0.00   87.01    0.00    0.00   12.43
04:10:28 AM   11    0.00    0.00    0.00    0.00    0.00   85.14    0.00    0.00   14.86

04:10:28 AM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
04:10:30 AM  all    0.00    0.00    0.09    0.09    0.00   90.35    0.00    0.00    9.47
04:10:30 AM    0    0.00    0.00    0.00    0.00    0.00   85.21    0.00    0.00   14.79
04:10:30 AM    1    0.00    0.00    0.00    0.00    0.00   85.62    0.00    0.00   14.38
04:10:30 AM    2    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:30 AM    3    0.00    0.00    0.51    0.00    0.00   87.76    0.00    0.00   11.73
04:10:30 AM    4    0.00    0.00    0.00    0.00    0.00   97.83    0.00    0.00    2.17
04:10:30 AM    5    0.00    0.00    0.00    0.00    0.00   78.95    0.00    0.00   21.05
04:10:30 AM    6    0.00    0.00    0.00    0.00    0.00   91.71    0.00    0.00    8.29
04:10:30 AM    7    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:30 AM    8    0.00    0.00    0.00    0.00    0.00   93.00    0.00    0.00    7.00
04:10:30 AM    9    0.00    0.00    0.51    0.00    0.00   89.23    0.00    0.00   10.26
04:10:30 AM   10    0.00    0.00    0.00    0.63    0.00   80.50    0.00    0.00   18.87
04:10:30 AM   11    0.00    0.00    0.00    0.00    0.00   86.13    0.00    0.00   13.87

04:10:30 AM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
04:10:32 AM  all    0.00    0.00    0.05    0.00    0.00   89.73    0.00    0.00   10.22
04:10:32 AM    0    0.00    0.00    0.00    0.00    0.00   80.74    0.00    0.00   19.26
04:10:32 AM    1    0.00    0.00    0.00    0.00    0.00   86.33    0.00    0.00   13.67
04:10:32 AM    2    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:32 AM    3    0.00    0.00    0.00    0.00    0.00   90.05    0.00    0.00    9.95
04:10:32 AM    4    0.00    0.00    0.00    0.00    0.00   93.51    0.00    0.00    6.49
04:10:32 AM    5    0.00    0.00    0.00    0.00    0.00   84.55    0.00    0.00   15.45
04:10:32 AM    6    0.00    0.00    0.00    0.00    0.00   87.98    0.00    0.00   12.02
04:10:32 AM    7    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:32 AM    8    0.00    0.00    0.00    0.00    0.00   89.01    0.00    0.00   10.99
04:10:32 AM    9    0.00    0.00    0.00    0.00    0.00   93.75    0.00    0.00    6.25
04:10:32 AM   10    0.00    0.00    0.00    0.00    0.00   81.60    0.00    0.00   18.40
04:10:32 AM   11    0.00    0.00    0.64    0.00    0.00   80.89    0.00    0.00   18.47

04:10:32 AM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
04:10:34 AM  all    0.00    0.00    0.00    0.00    0.00   91.90    0.00    0.00    8.10
04:10:34 AM    0    0.00    0.00    0.00    0.00    0.00   86.21    0.00    0.00   13.79
04:10:34 AM    1    0.00    0.00    0.00    0.00    0.00   93.10    0.00    0.00    6.90
04:10:34 AM    2    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:34 AM    3    0.00    0.00    0.00    0.00    0.00   89.39    0.00    0.00   10.61
04:10:34 AM    4    0.00    0.00    0.00    0.00    0.00   90.26    0.00    0.00    9.74
04:10:34 AM    5    0.00    0.00    0.00    0.00    0.00   87.25    0.00    0.00   12.75
04:10:34 AM    6    0.00    0.00    0.00    0.00    0.00   93.75    0.00    0.00    6.25
04:10:34 AM    7    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
04:10:34 AM    8    0.00    0.00    0.00    0.00    0.00   92.39    0.00    0.00    7.61
04:10:34 AM    9    0.00    0.00    0.00    0.00    0.00   94.87    0.00    0.00    5.13
04:10:34 AM   10    0.00    0.00    0.00    0.00    0.00   88.89    0.00    0.00   11.11
04:10:34 AM   11    0.00    0.00    0.00    0.00    0.00   80.90    0.00    0.00   19.10

Average:     CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest   %idle
Average:     all    0.00    0.00    0.06    0.02    0.00   90.63    0.00    0.00    9.30
Average:       0    0.00    0.00    0.00    0.00    0.00   83.05    0.00    0.00   16.95
Average:       1    0.00    0.00    0.00    0.00    0.00   85.60    0.00    0.00   14.40
Average:       2    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
Average:       3    0.00    0.00    0.20    0.00    0.00   87.44    0.00    0.00   12.36
Average:       4    0.00    0.00    0.00    0.00    0.00   92.37    0.00    0.00    7.63
Average:       5    0.16    0.00    0.16    0.00    0.00   80.12    0.00    0.00   19.57
Average:       6    0.00    0.00    0.00    0.00    0.00   93.14    0.00    0.00    6.86
Average:       7    0.00    0.00    0.00    0.00    0.00  100.00    0.00    0.00    0.00
Average:       8    0.00    0.00    0.00    0.00    0.00   94.99    0.00    0.00    5.01
Average:       9    0.00    0.00    0.10    0.00    0.00   94.24    0.00    0.00    5.65
Average:      10    0.00    0.00    0.12    0.12    0.00   84.44    0.00    0.00   15.33
Average:      11    0.00    0.00    0.12    0.00    0.00   83.37    0.00    0.00   16.51
лог статистики (ваш test.log с cat /proc/net/stat/ipt_netflow).

http://igorsd.ru/ipt_netflow/test.log http://igorsd.ru/ipt_netflow/test2.log

aabc commented 10 years ago

Благодарю.

hotid commented 10 years ago

Да это вам спасибо за помощь :)

Попробую на завтра оставить с hashsize=8388608 maxflows=4194304, посмотрим, может поможет. Впрочем, в любом случае, было бы здорово понять в результате чего получается рост количества потоков и отловить это дело...

hotid commented 10 years ago

Да, на всякий случай: 2хE5649 @ 2.53GHz, ядро загружено с intel_idle.max_cstate=0 processor.max_cstate=0 idle=mwait, процессоры жёстко загнаны в 2.53

Карточки

lspci  | grep -i eth
03:00.0 Ethernet controller: Intel Corporation 82599EB 10-Gigabit SFI/SFP+ Network Connection (rev 01)
09:00.0 Ethernet controller: Intel Corporation 82599EB 10-Gigabit SFI/SFP+ Network Connection (rev 01)

по 6 прерываний на карту, каждое висит на своём ядре.

modinfo ixgbe
filename:       /lib/modules/3.12-0.bpo.1-amd64/kernel/drivers/net/ethernet/intel/ixgbe/ixgbe.ko
version:        3.19.1
license:        GPL
description:    Intel(R) 10 Gigabit PCI Express Network Driver
author:         Intel Corporation, <linux.nics@intel.com>
....

Даж не знаю что ещё может пригодиться.... От версии ixgbe вроде как не зависит, во всяком случае, с версией 3.13.10-k и ядром 3.11.8 я наблюдал похожую картинку.

aabc commented 10 years ago

Судя по test.log, когда hashsize=256, то приходит в два раза меньше пакетов (8440214 vs 16866613). Модуль физически видит меньше пакетов. Видимо они дропаются по нагрузке (видно по mpstat что нагрузка доходит до 100%). Возможно, это потери на интерфейсах, посмотрите ifconfig -s, ethtool -S и netstat -s.

Дальше, но даже с меньшим трафиком, при hashsize=256, flows больше на 100000. При этом видно, что Out X pkt как раз различаются на 100000. То есть при меньшей нагрузке на CPU (когда hashsize=32768) пакеты быстрее пересылаются на экспорт (уходят из хэша). Это понятно - если система перенагружена, то и экспорт происходит тоже медленнее.

Вот одну проблему выяснили: при слишком маленьком hashsize выходит нагрузка cpu 100% и экспорт замедляется увеличивая кол-во active flows.

Решение тут - не допускать перенагрузки системы, чтоб никогда не было cpu 100%. Что полезно и чтоб избежать packet drops.

aabc commented 10 years ago

Насчет вот этого

Судя по tcpdump - пользователь просто что-то заливал на сервер гугла, заливка у него не прерывалась, порты не менялись и т.п. - по идее, это должен быть один поток.

Логика экспорта отработана, наверняка там была нормальная ситуация, когда должен происходить экспорт по стандарту netflow. Условия такие:

  1. сработали таймауты
  2. объем flowа скоро превысит 4Г
  3. для TCP пришел RST пакет.

Больше ни в каких случаях.

hotid commented 10 years ago 
Видимо они дропаются по нагрузке

Скорее всего так и есть. Ещё одно наблюдение - при включении netflow с малым значением hashsize загрузка не сразу доходит до 100%, а растёт постепенно по мере накопления flow:

05:18:29 AM  all    0.00    0.00    1.56    0.00    0.00    6.92    0.00    0.00   91.52
05:18:30 AM  all    0.00    0.00    0.00    0.00    0.00    6.20    0.00    0.00   93.80
05:18:31 AM  all    0.00    0.00    0.09    0.00    0.00    6.51    0.00    0.00   93.40
добавляем -j NETFLOW
05:18:32 AM  all    0.61    0.00    0.44    0.00    0.00    7.67    0.00    0.00   91.28
05:18:33 AM  all    0.00    0.00    0.00    0.00    0.00   12.27    0.00    0.00   87.73
05:18:34 AM  all    0.00    0.00    0.09    0.55    0.00   16.50    0.00    0.00   82.86
05:18:35 AM  all    0.00    0.00    0.00    0.00    0.00   18.65    0.00    0.00   81.35
05:18:36 AM  all    0.00    0.00    0.00    0.00    0.00   23.34    0.00    0.00   76.66
05:18:37 AM  all    0.00    0.00    0.00    0.00    0.00   27.57    0.00    0.00   72.43
05:18:38 AM  all    0.00    0.00    0.10    0.00    0.00   34.66    0.00    0.00   65.24
05:18:39 AM  all    0.00    0.00    0.00    0.00    0.00   41.96    0.00    0.00   58.04
05:18:40 AM  all    0.00    0.00    0.10    0.10    0.00   45.64    0.00    0.00   54.15
05:18:41 AM  all    0.00    0.00    0.00    0.00    0.00   52.87    0.00    0.00   47.13
05:18:42 AM  all    0.00    0.00    0.11    0.00    0.00   60.34    0.00    0.00   39.55
05:18:43 AM  all    0.00    0.00    0.00    0.00    0.00   68.24    0.00    0.00   31.76
05:18:44 AM  all    0.00    0.00    0.00    0.00    0.00   78.64    0.00    0.00   21.36
05:18:45 AM  all    0.00    0.00    0.10    0.00    0.00   80.21    0.00    0.00   19.69
05:18:46 AM  all    0.00    0.00    0.10    0.00    0.00   86.62    0.00    0.00   13.28
05:18:47 AM  all    0.00    0.00    0.00    0.00    0.00   87.76    0.00    0.00   12.24
05:18:48 AM  all    0.00    0.00    0.00    0.00    0.00   88.10    0.00    0.00   11.90
05:18:49 AM  all    0.00    0.00    0.00    0.00    0.00   87.71    0.00    0.00   12.29
05:18:50 AM  all    0.66    0.00    1.03    0.00    0.00   89.37    0.00    0.00    8.94
удаляем -j NETFLOW
05:18:51 AM  all    0.00    0.00    0.35    0.00    0.00   15.79    0.00    0.00   83.86
05:18:52 AM  all    0.00    0.00    0.44    0.00    0.00    6.97    0.00    0.00   92.60

В целом оно так и должно быть по идее...

Про дропы при 100% загрузке всё понятно, тут вопросов быть не может. Не понятно что причина, а что следствие. Я выше прикладывал графики, где виден значительный рост загрузки CPU при незначительном росте трафика. Ну и при выключении ipt_netflow видно, что загрузка ядер около 45-55%. Учитывая что, как правило, netflow у нас добавлял к загрузке 10-15% вроде как производительности должно хватать за глаза, однако не хватает...

Пока мне кажется наиболее вероятным сценарием что при некотором стечении обстоятельств (недостаточный размер hashsize для текущего количества потоков), модуль в некоторых случаях генерит новые flow записи вместо использования существующих, в результате чего начинает расти нагрузка на CPU. С другой стороны не очень понятно как может быть несколько записей для одного потока, хотя, каюсь, я не программист, реализацию полностью не осилил.

aabc commented 10 years ago

Ещё одно наблюдение - при включении netflow с малым значением hashsize загрузка не сразу доходит до 100%, а растёт постепенно по мере накопления flow

Это уже не важно. Таблица потоков постепенно увеличивается. Это увеличивает нагрузку, увеличение нагрузки замедляет экспорт, от этого таблица еще больше, а это еще сильнее увеличивает нагрузку. Порочный цикл. И так пока нагрузка не станет 100% и не начнутся дропы.

Я выше прикладывал графики

К сожалению я там ничего не понял что вы хотели ими сказать - на одном графике часы, на другом дни.

Учитывая что, как правило, netflow у нас добавлял к загрузке 10-15% вроде как производительности должно хватать за глаза, однако не хватает...

Может быть закон не линейный.

модуль в некоторых случаях генерит новые flow записи вместо использования существующих

Новая запись возможна только если старая экспортнулась.

в результате чего начинает расти нагрузка на CPU.

Нагрузка цпу из-за маленькой хэш таблицы, это закон природы. Желательно, чтоб хэш таблица была не менее двух раз больше кол-ва активных потоков.

hotid commented 10 years ago

С другой стороны, всё может быть проще - при росте количества потоков в какой-то момент hashsize оказывается слишком маленьким, в результате чего растёт использование CPU. В какой-то момент появляются дропы + не успевает отрабатывать контрек. В результате - рестрансмиты и прочяя ерундистика, типа попыток ответить на уже закрытый\ещё не открытый порт и как следствие рост количества записей.

aabc commented 10 years ago

Ретрансмиты попадают в тот-же поток. Разве что в конце трансфера когда пришел rst, но это мизер пакетов.

hotid commented 10 years ago 
К сожалению я там ничего не понял, что вы хотели ими сказать, на одном графике часы, на другом дни.

А я и внимание не обратил что шкала по разному отображается.... И тот и другой графики - за последние сутки.

Я ориентировался на значение entries из conntrack -S, обычно +- сотня другая тысяч оно равно количество активных flow, сейчас к примеру - entries 179312, при Flows: active 164022.

В момент когда начались проблемы - hashsize стоял 2097152, а кол-во записей в conntrack - около 1 млн.

Итого. Завтра попробую увеличить hashsize до 8388608 под нагрузкой, посмотрим как будет себя вести.

aabc commented 10 years ago

У меня на тестовой машине кол-во flows примерно равно pps.

Flows: active 18499 (peak 134700 reached 4d9h35m ago), mem 1589K Hash: size 800000 (mem 6250K), metric 1.0, 1.0, 1.0, 1.0. MemTraf: 7071257 pkt, 4980080 K (pdu 8, 1540). Rate: 67251026 bits/sec, 12752 packets/sec; Avg 1 min: 82004611 bps, 12943 pps; 5 min: 85992023 bps, 13073 pps

hotid commented 10 years ago

У нас не очень... Flows: active 177924 266472 packets/sec

hotid commented 10 years ago

При 8 гбитах практически ровно в два раза меньше получалось: Flows: active 642281 1310139 packets/sec

xaionaro commented 10 years ago

Уверяю вас, трафик при этом через сервер бегает примерно одинаковый +-100мбит, и реальное количество пакетов не меняется.

Чисто гипотетически, пакеты могут быть маленькими, а могут быть большими. Например, я могу nmap-ом сканировать весь Интернет, и это создаст относительно много пакетов и "соединений".

aabc commented 10 years ago

@hotid Мне рекомендуют посоветовать вам — поставить большой hashsize и maxflows, похоже у вас сервер уходит в спираль по нагрузке.

hotid commented 10 years ago

Hash: size 33554432 не особо помогает....

aabc commented 10 years ago

От чего? Вы же приводили доказательство, что изменение hashsize "помогает".

hotid commented 10 years ago

Я приводил доказательство того, что при маленьком hashsize можно иммитировать поведение модуля под высокой нагрузкой на CPU.

Будем считать что больше 8Гбит с netflow на данном железе не вытянуть. Спасибо.

hotid commented 10 years ago

С модулем\без модуля.

08:53:03 PM  all    1.65    0.00    0.41    0.00    0.00   96.53    0.00    0.00    1.40
08:53:04 PM  all    1.25    0.00    0.33    0.08    0.00   96.92    0.00    0.00    1.41
...
08:53:09 PM  all    3.64    0.00    0.08    0.00    0.00   43.73    0.00    0.00   52.54
08:53:10 PM  all    4.76    0.00    0.08    0.08    0.00   42.99    0.00    0.00   52.08

Видимо, порядка около 1млн flow - предел, после которого начинается лавинообразный рост нагрузки.

aabc commented 10 years ago

Если будет возможность по-prof-айлить, то попробуйте.

У вас выходит, что модуль удваивает нагрузку по softirq, как-то это многовато.

55.87%  [kernel]                  [k] _raw_spin_lock

Это дает надежду, что можно ускорить, если разобраться в чем тут дело. То есть основное время тратится на lockи, а не на полезную работу.

hotid commented 10 years ago

perf report в segfault падает как только символы из ipt_NETFLOW подгружаешь...

aabc commented 10 years ago

Там как-то можно это обойти... Попробуйте perf report -g | cat.

hotid commented 10 years ago

Не, так я пробовал - не помогает :(

dazgluk commented 10 years ago

Подключусь к дискуссии. Я - коллега hotid, вместе тестируем модуль под нагрузкой. К сожалению больше возможности экспериментировать на коммерческом трафике, поэтому с сервера сняли часть нагрузки и запустили Netflow.

При трафике 3.47+5.28=8.75Gb/s и 688k в Conntrack загрузка CPU была 59% При трафике 3.57+5.53=9.10Gb/s и 696k в Conntrack загрузка CPU была 100% Видимо где-то здесь предел модуля, это два соседних интервала Cacti статистики точнее к сожалению нет.

Хотим попробовать снять трафик SPANом на такой же сервер и попробовать снять Netflow для фиктивного трафика, если проблему удастся воспроизвести - появится тестовая площадка не деградирующая сервис.

Есть ли у вас предположения, почему такая проблема может возникать? Может быть имеет смысл собрать модуль без оптимизации или с -o 1? Возможно в модуле есть какие то внутренние счетчики которые переполняются?

hotid commented 10 years ago

Я думаю что при превышения какого-то уровня PPS, который для каждого железа свой - ipt_NETFLOW бОльшую часть времени начинает тратить на ожидание локов таблицы с flow, и в итоге просто не успевает обрабатывать весь трафик.

dazgluk commented 10 years ago

PPS в первом случае 1350,35k (726+624) PPS во втором случае 1392,98k (753+639)

aabc commented 10 years ago

Спасибо за помощь. Я не против что-нибудь оптимизировать, чтоб не было такого роста нагрузки.

Для начала надо понять где bottleneck - это может быть сложная задача. (Если появится тестовая площадка, то может быть debug+lock_stat ядро, или ядро с debuginfo+perf, perf lock, или ядро c ftrace function profiler сможет помочь понять какой именно lock перегружен, если дело в локах.)

"На ожидание локов таблицы с flow" - по идее эта таблица локов (htable_locks) и есть оптимизации для снижения нагрузки. Раньше был global lock на всю таблицу, а сейчас 256 локов выбираемых в зависимости от заголовка пакета. То есть один flow должен попадать на один и тот же лок, в то время как для одного лока другие flows маловероятны (1/256). Если у вас включен RPS, то потоки должны попадать на разные CPU, а следовательно lock contention между процессорами не будет, а следовательно spin_lock(htable_locks) не должен грузить процессор. Если RPS отключено, то возможна ситуация, что пакеты от одного потока попадают на разные процессоры параллельно и тогда spin_lock грузит процессор. Попробуйте поэкспериментировать с RPS.

Вот, для примера, были под рукой скрипты которые включают и отключают RPS:

root@z1:~# cat rps_on
#!/bin/sh
for i in /sys/class/net/eth?/queues/rx-?/rps_cpus; do
  echo fff > $i
  echo $i = `cat $i`
done

root@z1:~# cat rps_off
#!/bin/sh
for i in /sys/class/net/eth?/queues/rx-?/rps_cpus; do
  echo 000 > $i
  echo $i = `cat $i`
done

Проверить изменения можно watch -n 1 cat /proc/softirqs. (iptables обрабатывается в softirq, а не в обычных irq, поэтому смотреть надо в /proc/softirqs, а не в /proc/interrupts.)