vallettea commented 8 years ago

The actual version of 6brain/mqtt consums too much because we consume more than 3Mo per day. What I suggest we can do:

log all the outgoing/ingoing messages from 6brain to have metrics about how much the app seeks to send + try to give raw estimate of data needed for wifi, for init etc.
log all the outgoing/ingoing messages at the mqttjs level to see what goes on tcp.
use wireshark to see what goes on the wire.
open wvdial 3G session without sending anything to see if maintaining a connexion actually cost something in terms of data (hearbeat for 3G?)

4rzael commented 8 years ago

I took a look at the data consumption logs: Here they are:

date	hour	data
28/11/2015	17:44:13	866 KiB
28/11/2015	11:31:44	980 KiB
28/11/2015	01:48:09	1.35 MiB
27/11/2015	15:21:45	1 KiB
27/11/2015	15:19:25	1 KiB
27/11/2015	15:16:23	1 KiB
27/11/2015	15:11:04	3 KiB
27/11/2015	14:58:07	60 KiB
27/11/2015	14:52:57	3 KiB
27/11/2015	14:52:07	4 KiB
27/11/2015	14:51:17	3 KiB
27/11/2015	14:51:13	3 KiB
27/11/2015	14:45:28	15 KiB
27/11/2015	14:42:39	5 KiB
27/11/2015	10:56:42	17 KiB
27/11/2015	10:55:26	3 KiB
27/11/2015	10:52:49	7 KiB
27/11/2015	10:41:15	6 KiB
27/11/2015	10:28:19	59 KiB
27/11/2015	10:21:50	4 KiB
27/11/2015	10:16:05	5 KiB

We can see that sometimes we send big amounts of data in a very short time, which is strange:

Between 14:51:13 and 14:51:17 : 3KiB in 4 seconds

The problem is that we only have 6brain logs since the 27/11/2015 at 15:05

Everything in 6brain logs seems fine, except this:

date	hour	message
Nov 28	14:45:07	wifi measurements received
Nov 28	14:50:07	wifi measurements received
Nov 28	14:55:07	wifi measurements received
Nov 27	18:00:43	bluetooth measurements received
Nov 27	18:00:44	wifi measurements received
Nov 27	17:45:43	bluetooth measurements received
Nov 27	17:45:44	wifi measurements received
Nov 27	17:50:43	bluetooth measurements received
Nov 27	17:50:44	wifi measurements received
Nov 27	17:55:43	bluetooth measurements received
Nov 27	17:55:44	wifi measurements received
Nov 27	18:00:43	bluetooth measurements received
Nov 27	18:00:44	wifi measurements received
Nov 27	18:05:43	bluetooth measurements received
Nov 27	18:05:44	wifi measurements received
Nov 27	18:10:43	bluetooth measurements received
Nov 27	18:10:44	wifi measurements received
Nov 27	18:15:43	bluetooth measurements received
Nov 27	18:15:44	wifi measurements received
Nov 27	18:20:43	bluetooth measurements received
Nov 27	18:20:44	wifi measurements received
Nov 27	18:25:43	bluetooth measurements received
Nov 27	18:25:44	wifi measurements received
Nov 27	18:30:43	bluetooth measurements received
Nov 27	18:30:44	wifi measurements received
Nov 27	18:35:43	bluetooth measurements received
Nov 27	18:35:44	wifi measurements received
Nov 27	18:40:43	bluetooth measurements received
Nov 27	18:40:44	wifi measurements received
Nov 27	18:45:43	bluetooth measurements received
Nov 27	18:45:44	wifi measurements received
Nov 27	18:50:43	bluetooth measurements received
Nov 27	18:50:44	wifi measurements received
Nov 27	18:55:44	bluetooth measurements received
Nov 27	18:55:44	wifi measurements received
Nov 27	19:00:00	Pausing measurements.
Nov 27	19:00:00	pausing
Nov 27	19:00:00	Stopping recording...
Nov 27	19:00:00	Exiting recording state
Nov 27	19:00:00	============== monitoring ==============
Nov 27	19:00:10	bluetooth state : uninitialized
Nov 27	20:40:52	offline
Nov 27	20:41:03	connected to the server. ID : 89332401000001798145
Nov 27	21:57:03	offline
Nov 27	21:57:15	connected to the server. ID : 89332401000001798145
Nov 27	23:13:23	offline
Nov 27	23:13:34	connected to the server. ID : 89332401000001798145
Nov 28	00:00:00	trajectories received
Nov 28	00:17:18	offline
Nov 28	00:17:29	connected to the server. ID : 89332401000001798145
Nov 28	01:44:18	offline
Nov 28	01:44:29	connected to the server. ID : 89332401000001798145

Why did the date roll back ? It looks like there is another process using our data connexion.

Note: Every logs after the 28/11/2015 at 17h30 are filled with offline, every 13s. I think we should increase the reconnexion period. It could be dangerous in the future.

4rzael commented 8 years ago

One of the problem seems to be due to messages beeing sent many times.

Examples:

Measurements from the sensor to the server:

mqtt_measurement_duplicate

command results from the sensor to the server:

mqtt_command_result_duplicate

commands from the server to the sensor:

mqtt_command_duplicate

Note: The last one results in a big data usage, since the sensor answers multiple times the duplicate command

I see two possible reasons to this:

MQTT QoS 1
Multiple event listeners/handler spawned

EDIT:

The problem is visible from the logs, so I don't think it's what happened for the 3MiO/day, but it must be fixed anyway.
This problem happened when I used the command changestoptime 17

vallettea commented 8 years ago

With @4rzael we are logging all the incoming and outgoing mqtt packets. What we see from the m2m provider is that we are consuming approximately 125kB/hour which represents a few Mo per day.

Analysing the logs tells us that:

2.5 ko for all mqtt per hour
the trajectories at midnight is a 500ko packet
too much reconnect messages (but this should be corrected by now)

The main point we should solve is the first one and we think it is because other process I trying to connect to the internet.

vallettea commented 8 years ago

using

sudo nethogs wlan0

shows that chromium seems to be the culprit

vallettea commented 8 years ago

for now we are going to see what does https://github.com/anthill/6bin/issues/25

vallettea commented 8 years ago

Since we blocked the access of chromium to update the consumption is much better. My fears are now logged in #71

anthill / 6brain

Bandwidth consumption analysis #53

Note: Every logs after the 28/11/2015 at 17h30 are filled with offline, every 13s. I think we should increase the reconnexion period. It could be dangerous in the future.

Examples:

Measurements from the sensor to the server:

command results from the sensor to the server:

commands from the server to the sensor:

EDIT: