Re: Possible regression: Packet drops during iptables calls

[Steven Rostedt <srostedt@redhat.com>]

On Thu, 2010-12-16 at 15:04 +0100, Jesper Dangaard Brouer wrote:

> 
> To do some further investigation into the unfortunate behavior of the
> iptables get_counters() function I started to use "ftrace".  This is a
> really useful tool (thanks Steven Rostedt).
> 
>  # Select the tracer "function_graph"
>  echo function_graph > /sys/kernel/debug/tracing/current_tracer
> 
>  # Limit the number of function we look at:
>  echo local_bh_\*  >   /sys/kernel/debug/tracing/set_ftrace_filter
>  echo get_counters >>  /sys/kernel/debug/tracing/set_ftrace_filter
> 
>  # Enable tracing while calling iptables
>  cd /sys/kernel/debug/tracing
>  echo 0 > trace
>  echo 1 > tracing_enabled;
>    taskset 1 iptables -vnL > /dev/null ;
>  echo 0 > tracing_enabled
>  cat trace | less

Just an fyi, you can do the above much easier with trace-cmd:

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

# trace-cmd record -p function_graph -l 'local_bh_*' -l get_counters taskset 1 iptables -vnL > /dev/null
# trace-cmd report

-- Steve

> 
> 
> The reduced output:
> 
> # tracer: function_graph
> #
> # CPU  DURATION                  FUNCTION CALLS
> # |     |   |                     |   |   |   |
>   2)   2.772 us    |  local_bh_disable();
> ....
>   0)   0.228 us    |  local_bh_enable();
>   0)               |  get_counters() {
>   0)   0.232 us    |    local_bh_disable();
>   0)   7.919 us    |    local_bh_enable();
>   0) ! 109467.1 us |  }
>   0)   2.344 us    |  local_bh_disable();
> 
> 
> The output show that we spend no less that 100 ms with local BH
> disabled.  So, no wonder that this causes packet drops in the NIC
> (attached to this CPU).
> 
> My iptables rule set in question is also very large, it contains:
>  Chains: 20929
>  Rules: 81239
> 
> The vmalloc size is approx 19 MB (19.820.544 bytes) (see
> /proc/vmallocinfo).  Looking through vmallocinfo I realized that
> even-though I only have 16 CPUs, there is 32 allocated rulesets
> "xt_alloc_table_info" (for the filter table). Thus, I have approx
> 634MB iptables filter rules in the kernel, half of which is totally
> unused.
> 
> Guess this is because we use: "for_each_possible_cpu" instead of
> "for_each_online_cpu". (Feel free to fix this, or point me to some
> documentation of this CPU hotplug stuff... I see we are missing
> get_cpu() and put_cpu() a lot of places).
> 
> 
> The GOOD NEWS, is that moving the local BH disable section into the
> "for_each_possible_cpu" fixed the problem with packet drops during
> iptables calls.
> 
> I wanted to profile with ftrace on the new code, but I cannot get the
> measurement I want. Perhaps Steven or Acme can help?
> 
> Now I want to measure the time used between the local_bh_disable() and
> local_bh_enable, within the loop.  I cannot figure out howto do that?
> The new trace looks almost the same as before, just a lot of
> local_bh_* inside the get_counters() function call.
> 
>  Guess is that the time spend is: 100 ms / 32 = 3.125 ms.
> 
> Now I just need to calculate, how large a NIC buffer I need to buffer
> 3.125 ms at 1Gbit/s.
> 
>  3.125 ms *  1Gbit/s = 390625 bytes
> 
> Can this be correct?
> 
> How much buffer does each queue have in the 82576 NIC?
> (Hope Alexander Duyck can answer this one?)
>