[v2,6/7] batman-adv: ELP - use tp meter to estimate the throughput if otherwise not available

  Signed-off-by: Marek Lindner <mareklindner@neomailbox.ch>
---
 net/batman-adv/bat_v_elp.c | 63 ++++++++++++++++++++++++++++++++++++--
 net/batman-adv/bat_v_elp.h | 21 +++++++++++++
 net/batman-adv/main.h      |  1 +
 net/batman-adv/tp_meter.c  | 37 +++++++++++++++++-----
 net/batman-adv/types.h     | 14 +++++++++
 5 files changed, 126 insertions(+), 10 deletions(-)
  

On Fri, May 18, 2018 at 09:47:53AM +0800, Marek Lindner wrote:
> @@ -251,6 +253,21 @@ static void batadv_tp_caller_notify(struct batadv_priv *bat_priv,
>  
>  		break;
>  	case BATADV_TP_ELP:
> +		if (reason_is_error) {
> +			batadv_v_elp_tp_fail(tp_vars->hardif_neigh);
> +			return;
> +		}
> +
> +		test_time = jiffies_to_msecs(jiffies - tp_vars->start_time);
> +		total_bytes = atomic64_read(&tp_vars->tot_sent);
> +
> +		/* The following calculation includes these steps:
> +		 * - convert bytes to bits
> +		 * - divide bits by the test length (msecs)
> +		 * - convert result from bits/ms to 0.1Mb/s (* 1024 * 10 / 1000)
> +		 */
> +		throughput = total_bytes * 8 >> ilog2(test_time) / 10;
> +		batadv_v_elp_tp_finish(tp_vars->hardif_neigh, throughput);

I find the throughput calculation quite hard to read here, would
it be possible to put this into an extra (inline?) function?

Also the comment for the "convert result..." seems wrong,
"[bits/ms]*1024*10/1000" would be 0.01Mb/s, not 0.1Mb/s?

What is the advantage of using the ilog2 and shift operator here
compared to plain multiplications and divisions?

Also, when trying this in a small C program I get weird results:

-----
#include <stdio.h>
#include <math.h>

int main()
{
        unsigned long test_time = 10000;        // 10s
        unsigned long total_bytes = 20000000;   // 16MBit/s
        unsigned long throughput, throughput2;
        unsigned long log_test_time = log(test_time) / log(2);

        throughput = total_bytes * 8 >> log_test_time / 10;

	// Straightforward approach?
        throughput2 = total_bytes * 8 / test_time * 1000 / 1024 / 100;

        printf("Result: %lu (log_test_time: %lu)\n", throughput, log_test_time);
        printf("Result2: %lu\n", throughput2);

        return 0;
}
-----
$ ./test
Result: 80000000 (log_test_time: 13)
Result2: 156
$ file ./test
./test: ELF 32-bit LSB pie executable ARM, EABI5 version 1 (SYSV), dynamically linked, interpreter /lib/ld-linux-armhf.so.3, for GNU/Linux 3.2.0, BuildID[sha1]=d18f32829cdd2bc42cf744cdcafde7cdbd315cb0, not stripped
-----


Regards, Linus
  

On Fri, May 18, 2018 at 09:47:53AM +0800, Marek Lindner wrote:
> +fallback_throughput:
> +	last_tp_run_jiffies = jiffies - neigh->bat_v.last_tp_meter_run;
> +	last_tp_run_msecs = jiffies_to_msecs(last_tp_run_jiffies);
> +
> +	/* check the tp_meter_running flag before checking the timestamp to
> +	 * avoid a race condition where a new tp meter session is scheduled
> +	 * right after the previous tp meter session has completed
> +	 */
> +	if (!neigh->bat_v.tp_meter_running &&
> +	    last_tp_run_msecs > BATADV_ELP_TP_RUN_INTERVAL)
> +		batadv_v_elp_tp_start(neigh);
> +
> +	/* discard too old tp test results */
> +	if (last_tp_run_msecs > 2 * BATADV_ELP_TP_RUN_INTERVAL)
> +		neigh->bat_v.tp_meter_throughput = 0;
> +

So far we were either using time_before(), time_after_eq() or our
own wrapper batadv_has_timed_out(). Would it make sense to use
some of these here, too?
  

On Fri, May 18, 2018 at 09:47:53AM +0800, Marek Lindner wrote:
> +/**
> + * batadv_v_elp_tp_start() - start a tp meter session for a neighbor
> + * @neigh: neighbor to run tp meter on
> + */
> +static void batadv_v_elp_tp_start(struct batadv_hardif_neigh_node *neigh)
> +{
> +	struct batadv_hard_iface *hard_iface = neigh->if_incoming;
> +	struct batadv_priv *bat_priv = netdev_priv(hard_iface->soft_iface);
> +
> +	neigh->bat_v.tp_meter_running = true;
> +	batadv_tp_start(bat_priv, neigh->addr, neigh, 10, NULL, BATADV_TP_ELP);
> +}

This seems racy here? We have no ordering constraints between
the assigment and batadv_tp_start() which might lead to...

> @@ -152,6 +192,25 @@ static u32 batadv_v_elp_get_throughput(struct batadv_hardif_neigh_node *neigh)
>  			return throughput * 10;
>  	}
>  
> +fallback_throughput:
> +	last_tp_run_jiffies = jiffies - neigh->bat_v.last_tp_meter_run;
> +	last_tp_run_msecs = jiffies_to_msecs(last_tp_run_jiffies);
> +
> +	/* check the tp_meter_running flag before checking the timestamp to
> +	 * avoid a race condition where a new tp meter session is scheduled
> +	 * right after the previous tp meter session has completed
> +	 */
> +	if (!neigh->bat_v.tp_meter_running &&
> +	    last_tp_run_msecs > BATADV_ELP_TP_RUN_INTERVAL)
> +		batadv_v_elp_tp_start(neigh);

...multiple instances potentially being started at the same time here?
  

On Fri, May 18, 2018 at 09:47:53AM +0800, Marek Lindner wrote:
> diff --git a/net/batman-adv/types.h b/net/batman-adv/types.h
> index 0a9bee88..148f23ad 100644
> --- a/net/batman-adv/types.h
> +++ b/net/batman-adv/types.h
> @@ -583,6 +583,20 @@ struct batadv_hardif_neigh_node_bat_v {
>  
>  	/** @metric_work: work queue callback item for metric update */
>  	struct work_struct metric_work;
> +
> +	/**
> +	 * @tp_meter_running: tp meter measurements towards this neighbor in
> +	 * progress
> +	 */
> +	unsigned char tp_meter_running:1;

I'm currently wondering: Would it make sense to prevent parallel
tp meter execution not only to a specific neighbor but parallel
executions on a hard-interface in general?
  

On Freitag, 18. Mai 2018 03:47:53 CEST Marek Lindner wrote:
> Signed-off-by: Marek Lindner <mareklindner@neomailbox.ch>
> ---
>  net/batman-adv/bat_v_elp.c | 63 ++++++++++++++++++++++++++++++++++++--
>  net/batman-adv/bat_v_elp.h | 21 +++++++++++++
>  net/batman-adv/main.h      |  1 +
>  net/batman-adv/tp_meter.c  | 37 +++++++++++++++++-----
>  net/batman-adv/types.h     | 14 +++++++++
>  5 files changed, 126 insertions(+), 10 deletions(-)

This seems to create weird (as in incorrect) looking results. Here the ones 
from Matthias Fritzsche:

[2018-05-21 18:19:41] <txt-file> ordexm, marec, ecsv_: Now I have one router and the its neighbour with batman_V with tp-meter. https://paste.debian.net/1025691/
[2018-05-21 18:24:28] <txt-file> ah … now "batctl n" shows a tp of 16064.1
[2018-05-21 18:29:07] <ecsv_> uhm, isn't this rather... high
[2018-05-21 18:29:53] <txt-file> ecsv_: I think so. This node has an upload of 4 MBit/s
[2018-05-21 18:30:34] <txt-file> now (6 minutes later) tq=2.2
[2018-05-21 18:30:48] <txt-file> which sounds much more realistic.

The setup is using an gluon based router (TP-Link TL-WDR3600 v1) [1] which 
uses a vpn connection (fastd) to a server 
(descartes.routers.chemnitz.freifunk.net) in the internet. The automatic 
throughput test runs between these two devices.

Kind regards,
	Sven

[1] https://meshviewer.chemnitz.freifunk.net/#!v:m;n:c04a00e44be0
  

On Montag, 21. Mai 2018 15:17:11 CEST Linus Lüssing wrote:
> What is the advantage of using the ilog2 and shift operator here
> compared to plain multiplications and divisions?

They most likely ran into the problem that they must do a 64 bit division 
(which cannot be done on 32 bit machines in the kernel directly with C's 
native "x / y" statement ). But in this case, it is most likely a lot better 
to use do_div (or similar function) to avoid a lot of rounding problems which 
this shift approach has.

Kind regards,
	Sven
  

On Montag, 21. Mai 2018 15:17:11 CEST Linus Lüssing wrote:
> > +               throughput = total_bytes * 8 >> ilog2(test_time) / 10;
[...]
> -----
[...]
> 
>         throughput = total_bytes * 8 >> log_test_time / 10;
> 
>         // Straightforward approach?
>         throughput2 = total_bytes * 8 / test_time * 1000 / 1024 / 100;
[...]
> -----
> $ ./test
> Result: 80000000 (log_test_time: 13)
> Result2: 156
> $ file ./test
> ./test: ELF 32-bit LSB pie executable ARM, EABI5 version 1 (SYSV), dynamically linked, interpreter /lib/ld-linux-armhf.so.3, for GNU/Linux 3.2.0, BuildID[sha1]=d18f32829cdd2bc42cf744cdcafde7cdbd315cb0, not stripped
> -----

Thanks for this small example program. Yes, there are parenthesis missing in 
the calculation. Right now, following is calculated:

    (total_bytes * 8) >> (ilog2(test_time) / 10);

But the author most likely wanted following precedence:

    ((total_bytes * 8) >> ilog2(test_time)) / 10;

And together with the fixed unit, you would get:

    (total_bytes * 8 >> ilog2(test_time) / 100;

Your example program would then show following result because the shifting 
stuff is still the wrong approach:

    Result: 195 (log_test_time: 13)
    Result2: 156

The calculation still has to be changed to something like this to get 

    // when 0.1 Mbit/s == 100 kbit/s
    throughput = total_bytes * 5;
	 do_div(throughput, test_time * 64);

    // when 0.1 Mbit/s == 102.4 kbit/s
    throughput = total_bytes * 625;
	 do_div(throughput, test_time * 8192);

    // when 0.1 Mbit/s == 100 kbit/s, and 1kbit/s == 1000 bit (instead of 1024 bit):
    throughput = total_bytes;
    do_div(throughput, test_time * 125);

Please keep in mind that we must do a check of the divisor (for 0) before 
doing this do_div.

Kind regards,
	Sven
  

Hi,

On 21/05/18 23:01, Linus Lüssing wrote:
> On Fri, May 18, 2018 at 09:47:53AM +0800, Marek Lindner wrote:
>> diff --git a/net/batman-adv/types.h b/net/batman-adv/types.h
>> index 0a9bee88..148f23ad 100644
>> --- a/net/batman-adv/types.h
>> +++ b/net/batman-adv/types.h
>> @@ -583,6 +583,20 @@ struct batadv_hardif_neigh_node_bat_v {
>>  
>>  	/** @metric_work: work queue callback item for metric update */
>>  	struct work_struct metric_work;
>> +
>> +	/**
>> +	 * @tp_meter_running: tp meter measurements towards this neighbor in
>> +	 * progress
>> +	 */
>> +	unsigned char tp_meter_running:1;
> 
> I'm currently wondering: Would it make sense to prevent parallel
> tp meter execution not only to a specific neighbor but parallel
> executions on a hard-interface in general?
> 

This flag prevents scheduling new measurements to this neighbour if one
has already been scheduled and has not returned any result yet.

What you are looking for is implemented in patch 1/7: a system-wide
queue prevents concurrent measurements at all. All the measurements are
serialized and performed one after the other.


Cheers,
  

Hi,

On 22/05/18 03:06, Sven Eckelmann wrote:
> On Montag, 21. Mai 2018 15:17:11 CEST Linus Lüssing wrote:
>>> +               throughput = total_bytes * 8 >> ilog2(test_time) / 10;
> [...]
>> -----
> [...]
>>
>>         throughput = total_bytes * 8 >> log_test_time / 10;
>>
>>         // Straightforward approach?
>>         throughput2 = total_bytes * 8 / test_time * 1000 / 1024 / 100;
> [...]
>> -----
>> $ ./test
>> Result: 80000000 (log_test_time: 13)
>> Result2: 156
>> $ file ./test
>> ./test: ELF 32-bit LSB pie executable ARM, EABI5 version 1 (SYSV), dynamically linked, interpreter /lib/ld-linux-armhf.so.3, for GNU/Linux 3.2.0, BuildID[sha1]=d18f32829cdd2bc42cf744cdcafde7cdbd315cb0, not stripped
>> -----
> 
> Thanks for this small example program. Yes, there are parenthesis missing in 
> the calculation. Right now, following is calculated:
> 
>     (total_bytes * 8) >> (ilog2(test_time) / 10);
> 
> But the author most likely wanted following precedence:
> 
>     ((total_bytes * 8) >> ilog2(test_time)) / 10;
> 
> And together with the fixed unit, you would get:
> 
>     (total_bytes * 8 >> ilog2(test_time) / 100;
> 
> Your example program would then show following result because the shifting 
> stuff is still the wrong approach:
> 
>     Result: 195 (log_test_time: 13)
>     Result2: 156
> 
> The calculation still has to be changed to something like this to get 
> 
>     // when 0.1 Mbit/s == 100 kbit/s
>     throughput = total_bytes * 5;
> 	 do_div(throughput, test_time * 64);
> 
>     // when 0.1 Mbit/s == 102.4 kbit/s
>     throughput = total_bytes * 625;
> 	 do_div(throughput, test_time * 8192);
> 
>     // when 0.1 Mbit/s == 100 kbit/s, and 1kbit/s == 1000 bit (instead of 1024 bit):
>     throughput = total_bytes;
>     do_div(throughput, test_time * 125);
> 
> Please keep in mind that we must do a check of the divisor (for 0) before 
> doing this do_div.

Thanks for the code and the correction :-)

Yes, we wanted to avoid 64 bits explicit divisions and we assumed
test_time would have been a power of 2 (otherwise we'd accept a small
error).

Anyway, the last case brought by Sven depicts what we want to implement.
The patch will be changed accordingly.

Cheers,
  

On Monday, 21 May 2018 22:43:04 HKT Linus Lüssing wrote:
> On Fri, May 18, 2018 at 09:47:53AM +0800, Marek Lindner wrote:
> > +fallback_throughput:
> > +       last_tp_run_jiffies = jiffies - neigh->bat_v.last_tp_meter_run;
> > +       last_tp_run_msecs = jiffies_to_msecs(last_tp_run_jiffies);
> > +
> > +       /* check the tp_meter_running flag before checking the timestamp
> > to
> > +        * avoid a race condition where a new tp meter session is
> > scheduled
> > +        * right after the previous tp meter session has completed
> > +        */
> > +       if (!neigh->bat_v.tp_meter_running &&
> > +           last_tp_run_msecs > BATADV_ELP_TP_RUN_INTERVAL)
> > +               batadv_v_elp_tp_start(neigh);
> > +
> > +       /* discard too old tp test results */
> > +       if (last_tp_run_msecs > 2 * BATADV_ELP_TP_RUN_INTERVAL)
> > +               neigh->bat_v.tp_meter_throughput = 0;
> > +
> 
> So far we were either using time_before(), time_after_eq() or our
> own wrapper batadv_has_timed_out(). Would it make sense to use
> some of these here, too?

Good point. That changes has been staged for v3.

Cheers,
Marek
  

Hi Lunus,

On 21/05/18 22:48, Linus Lüssing wrote:
> On Fri, May 18, 2018 at 09:47:53AM +0800, Marek Lindner wrote:
>> +/**
>> + * batadv_v_elp_tp_start() - start a tp meter session for a neighbor
>> + * @neigh: neighbor to run tp meter on
>> + */
>> +static void batadv_v_elp_tp_start(struct batadv_hardif_neigh_node *neigh)
>> +{
>> +	struct batadv_hard_iface *hard_iface = neigh->if_incoming;
>> +	struct batadv_priv *bat_priv = netdev_priv(hard_iface->soft_iface);
>> +
>> +	neigh->bat_v.tp_meter_running = true;
>> +	batadv_tp_start(bat_priv, neigh->addr, neigh, 10, NULL, BATADV_TP_ELP);
>> +}
> 
> This seems racy here? We have no ordering constraints between
> the assigment and batadv_tp_start() which might lead to...
> 
>> @@ -152,6 +192,25 @@ static u32 batadv_v_elp_get_throughput(struct batadv_hardif_neigh_node *neigh)
>>  			return throughput * 10;
>>  	}
>>  
>> +fallback_throughput:
>> +	last_tp_run_jiffies = jiffies - neigh->bat_v.last_tp_meter_run;
>> +	last_tp_run_msecs = jiffies_to_msecs(last_tp_run_jiffies);
>> +
>> +	/* check the tp_meter_running flag before checking the timestamp to
>> +	 * avoid a race condition where a new tp meter session is scheduled
>> +	 * right after the previous tp meter session has completed
>> +	 */
>> +	if (!neigh->bat_v.tp_meter_running &&
>> +	    last_tp_run_msecs > BATADV_ELP_TP_RUN_INTERVAL)
>> +		batadv_v_elp_tp_start(neigh);
> 
> ...multiple instances potentially being started at the same time here?
> 

- batadv_tp_start() is only invoked by batadv_v_elp_get_throughput();
- batadv_v_elp_get_throughput() is only invoked by
batadv_v_elp_throughput_metric_update();
- batadv_v_elp_throughput_metric_update() is a periodic function
executed by a timer and we can't have concurrent executions (unless we
use crazy interval values).

Maybe we should add a comment to make this more clear?