Subject: large idle time during ipsec
To: None <tech-net@netbsd.org>
From: Adolf Hohl <adolf.hohl@security.kpnqwest.com>
List: tech-net
Date: 08/10/2000 11:28:39
Hi,

i was interested in time consumption of some kern procedures processing IP
and handle network io. I made a kernel profile and noticed that the cpu is
nearly idle half the time during ipsec-processing.
My environment looks like this:

        host-----ipsec-gate---------ipsec-gate------host
                           3des,tunnel-mode,esp

1.5_ALPHA is running on all machines. The gateways are P3/450 with 2 or 3
3C905-100Mbit interfaces (no pci-interrupt sharing). Hosts are Celeron 500
with same interfaces.

I made kernel profiles on the right gateway. I produced load on the net by
pinging from host to host with the -f option. After that i used different
icmp packet sizes ( -s 2000, 4000, 8000).

With ping-f the cpu has 18 % idle, with ping -f -s 2000 the cpu has 60 % idle
time. With sizes of 4000 and 8000 bytes the cpu is only 45 % idle.

I don't know where the bottleneck is. I supposed that the kern is out of mbufs,
but no console message appeared.  

Does anybody know more?

Here's a short output of gprof.

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  us/call  us/call  name
 46.35    642.83   642.83                             idle
 26.70   1013.23   370.40 298030802     1.24     1.24  des_encrypt
  4.55   1076.36    63.13  1302430    48.47   332.86  des_cbc_encrypt
  2.61   1112.58    36.22  7916541     4.58     8.05  ex_intr
  2.39   1145.68    33.10                             Xspllower
  1.94   1172.53    26.85                             Xintr10
  1.55   1194.03    21.50  4506991     4.77     4.77  crc32_a
  1.36   1212.94    18.91                             Xdoreti
  0.65   1221.99     9.05  3935768     2.30     3.98  ex_start
  0.61   1230.52     8.53 17189287     0.50     0.50  _pool_get
  0.52   1237.69     7.17 17189264     0.42     0.42  _pool_put
  0.48   1244.38     6.69  5158206     1.30   107.69  ip_input
  0.44   1250.47     6.09  3792472     1.61    73.67  ip_output
  0.41   1256.13     5.66  7584944     0.75     0.75  ipsec_setspidx_mbuf
  0.40   1261.61     5.48  1305894     4.20     4.20  microtime
  0.38   1266.83     5.22  1302430     4.01     4.01  des_set_key
  0.37   1272.01     5.18  4506736     1.15     5.01  ether_output
  0.36   1276.98     4.97  7584944     0.66     2.07  ipsec4_getpolicybyaddr
  0.30   1281.10     4.12  4507043     0.91     2.52  ex_add_rxbuf
  0.28   1284.94     3.84 16331290     0.24     0.41  _bus_dmamap_load_buffer
  0.27   1288.67     3.73  3792574     0.98     1.04  rn_match
  0.26   1292.26     3.58                             loop_128
  0.26   1295.83     3.57  3792472     0.94    78.59  icmp_input
  0.23   1299.01     3.18  4507043     0.71     1.13  ether_input
  0.20   1301.81     2.80 15480051     0.18     0.18  pmap_extract
  0.18   1304.36     2.55  7584944     0.34     0.67  key_allocsp
  0.18   1306.88     2.52  3792472     0.66    74.79  icmp_reflect
  0.17   1309.18     2.31  4507047     0.51     2.02  m_freem
  0.14   1311.08     1.89   651215     2.90   348.89  esp4_input
  0.13   1312.91     1.84   651215     2.83   347.56  esp_output
  0.13   1314.72     1.81  3792472     0.48     0.66  key_cmpspidx_withmask
  0.13   1316.52     1.79  4506728     0.40     1.46  _bus_dmamap_load_mbuf
  0.11   1318.06     1.54   651215     2.36   355.43  ipsec4_output
  0.10   1319.51     1.45  4428150     0.33   125.78  ipintr
  0.10   1320.86     1.35  5952325     0.23     0.23  m_adj
  0.09   1322.12     1.26  3141257     0.40     0.92  m_prepend
  0.08   1323.28     1.16  3792609     0.31     0.31  in_broadcast
  0.08   1324.42     1.15                             Xsoftnet
  0.08   1325.56     1.14                             finished_8
  0.08   1326.66     1.10  4506734     0.24     0.38  arpresolve