bassmaster187 / TeslaLogger

TeslaLogger is a self hosted data logger for your Tesla Model S/3/X/Y. Actually it supports RaspberryPi 3B, 3B+, 4B, Docker and Synology NAS.
https://www.teslalogger.de
GNU General Public License v3.0
505 stars 167 forks source link

CPU usage increasing after a few hours #158

Closed pbertra closed 4 years ago

pbertra commented 4 years ago

I run the lastest version of Tesla Logger in docker (updated from the admin page) and every time, after a few hours, the teslalogger container starts using cpu constantly (20% of my cpu).

If I restart it, it drops to less than 5% until some unknown problem that causes it to use more CPU. The log doesn't give any information when this triggers.

Other containers don't use more than a few % CPU.

Car Version: | 2020.8.2 Last Update: | 27/03/2020 à 19:18:56 Teslalogger: | 1.39.0.0

bassmaster187 commented 4 years ago

During a restart, there are a couple of maintainance things to do and can take some minutes. After that there is just one thread and asyncron calls, so basically if you had 20% CPU before you restart the logger, it would help me to see in what state of the statemachine it was, so I can search for potentially infinite loop.

could you please send me the whole logfile? It is located in /etc/teslalogger/nohup.out And please tell me, when to high CPU usage occurs before restart.

pbertra commented 4 years ago

Hi, I noticed the increased CPU usage at startup, which is of course normal but settles very quickly. You will find the complete log attached. nohup.txt The last restarts were all due to high CPU usage. I don't have the exact timestamp of the last occurence: It occured during the evening. I will monitor CPU more closely for next events.

bassmaster187 commented 4 years ago

I don't know what happen to your Docker, but the time seems to jump back in past. I really cant say, what teslalogger will do, if that happen.

27.03.2020 18:24:17 : GeocodeCache:Insert 27.03.2020 18:24:17 : Reverse geocoding by Nominatim6 27.03.2020 18:24:20 : asleep 27.03.2020 18:24:20 : Reverse geocoding by Cache 27.03.2020 18:24:20 : state: asleep 27.03.2020 18:18:46 : Reboot request! 27.03.2020 18:18:46 : --------------------------------------------

27.03.2020 18:18:46 : Docker detected 27.03.2020 19:18:49 : Restart Request! 27.03.2020 19:18:50 : TeslaLogger Version: 1.39.0.0

pbertra commented 4 years ago

That's strange indeed. I will check this also. However this doesn't seem to be the case for all cases where the CPU usage increased

pbertra commented 4 years ago

I monitored the CPU usage in continuous and CPU usage increase is... continuous: see attached graph kern1 1day

pbertra commented 4 years ago

kern1 1week Here is a longer term monitoring. You can see the restart of TeslaLogger when the CPU usage drops. status

bassmaster187 commented 4 years ago

Did you make a reboot on 30 March. I'm asking because of the drop.

I'll ask the other Docker users if they have the same problem.

pbertra commented 4 years ago

Yes I did a restart of the teslalogger container

bassmaster187 commented 4 years ago

I tried to run the docker on my synology NAS Docker, but after a couple of days the cpu was at 5%. I try to figure out, what the difference is between regular install and docker.

Adminius commented 4 years ago

same here :/ image image Docker/TeslaLogger 1.40.1.0

pbertra commented 4 years ago

kern1 1month This really is limited to teslalogger container but the issue is prefectly reproducible on my setup. You clearly see each time I force a restart to repair things... Without action it already went up to 40% CPU. It seems strange that this wouldn't appear on non docker installations.

DariBer commented 4 years ago

I can look into my docker installation, what software do you use to get the graphs and info so that I can present same info as you do

pbertra commented 4 years ago

I use monitorix, really easy to use as a docker container (erikmroll/monitorix) Adminius used htop

DariBer commented 4 years ago

I have installed it now, just waiting to collect some data now. Will get back when I have some more to show

Adminius commented 4 years ago

after 25h image

1129MB RAM?!

bassmaster187 commented 4 years ago

Docker on Synology running 3 Days. Just 69MB Ram and 3% CPU.

image

DariBer commented 4 years ago

been running Monitorix since 09:00 this morning and can't see anything that's unusual.

Screenshot 2020-04-10 at 00 23 59 Screenshot 2020-04-10 at 00 26 15
pbertra commented 4 years ago

@DariBer Your CPU usage has increased, going from almost nothing to 5%... Let's see if it increases more. @Adminius "VIRT" Memory is probably not representative of the real memory used by the process. The "RES" column (in kB?) is more representative of the physical memory used (75 MB, which seems realistic). In my case the process stays around 100 MB.

The absolute value of the CPU usage should not be compared between users. My docker containers are running in a VM on an ESXI server and this VM is assigned 1 core of an Intel(R) Core(TM) i3-3250 CPU @ 3.50GHz. If you run your docker with 4 more powerful cores, the CPU usage will maybe reach 5% when mine may be at 20%... But you you see the trend anyway: CPU usage will increase.

TeslaLogger
DariBer commented 4 years ago

It has soon been up for 24h and I had a peak at 8% the average is 6,8% and current is 3,6%

pbertra commented 4 years ago

@DariBer What hardware does it run on? 6,8% average is quite high for just polling periodically the car...

bassmaster187 commented 4 years ago

I turned on long term cpu statistics on my Synology and no increasing of cpu is visible.

image

bassmaster187 commented 4 years ago

I did a lot of optimisations in "sleep" mode, so I drop the CPU on my Synology from 5% to 0,5%.

image

Changeset: https://github.com/bassmaster187/TeslaLogger/commit/26ed34726d00e11820f5b9b4be2dfb116f3fea7c

bassmaster187 commented 4 years ago

Please update to 1.40.3.0

pbertra commented 4 years ago

Nice optimisation indeed! I upgraded and will continue monitoring to see if it improves things on my side.

pbertra commented 4 years ago

That's better, but still not ok: usage goes from 0.5% to 10% in one day. kern1z 1week Car has been asleep without a single transition during more than 24h and since the upgrade (and restart). Logfile silent since restart: 13.04.2020 17:51:16 : ScanMyTesla FastMode: False 13.04.2020 17:51:16 : Distance: 9.63633805240727 - Radius: 20 - Domicile 13.04.2020 17:51:16 : Reverse geocoding by Geofence 13.04.2020 17:51:16 : 13.04.2020 17:51:16 : MqttClient Version: 1.5.0.0 13.04.2020 17:51:16 : MqttClient Version: 1.5.0.0 13.04.2020 17:51:16 : GeocodeCache Items: 163 13.04.2020 17:51:16 : 13.04.2020 17:51:16 : Connecting without credentials: 192.168.2.7 13.04.2020 17:51:16 : Connecting without credentials: 192.168.2.7 13.04.2020 17:51:16 : Connected! 13.04.2020 17:51:16 : 13.04.2020 17:51:16 : Connected! 13.04.2020 17:51:17 : asleep 13.04.2020 17:51:46 : Distance: 9.63633805240727 - Radius: 20 - Domicile 13.04.2020 17:51:46 : Reverse geocoding by Geofence 13.04.2020 17:51:46 : UpdateTripElevation start:28335 ende:28467 13.04.2020 17:51:46 : UpdateTripElevation finished start:28335 ende:28467 13.04.2020 17:51:46 : UpdateAllPOIAddresses start 13.04.2020 17:51:46 : UpdateAllPOIAddresses Select 12ms 13.04.2020 17:51:47 : UpdateAllPOIAddresses end 356ms count:0 13.04.2020 17:51:47 : ShareData: Your charging data / degradation data will be shared anonymously to the community. Thank you! 13.04.2020 17:51:47 : ShareData: SendAllChargingData start 13.04.2020 17:51:47 : ShareData: SELECT chargingstate ms: 4 13.04.2020 17:51:47 : ShareData: SendAllChargingData finished 13.04.2020 17:51:47 : ShareData: SendDegradationData start 13.04.2020 17:51:47 : ShareData: SELECT degradation Data ms: 8 13.04.2020 17:51:47 : ShareData: OK 13.04.2020 17:51:47 : ShareData: SendDegradationData end

pbertra commented 4 years ago

kern1 1week (1) It now takes nearly for days to go from 0.5% to 20%... but the leakage is still there

Adminius commented 4 years ago

RasPi, 1.40.3.0: image

pbertra commented 4 years ago

image My docker installation is not on a raspberry. It seems like the CPU usage increases faster when the car is online (sentinel mode) than when asleep.

bassmaster187 commented 4 years ago

I could rule out, there is a bug in the code with profiling the code over 8 hours with all states except "unknown" and "offline". At least with my config there is nothing draining the cpu.

image

Some users reported also high CPU usage in Raspberry, so i changed the topic of this issue.

So I started to compare my Raspberry Image with my Synology Docker. Same config, same car, same credentials. Raspberry has 0% avg, Docker 5% after one day.

image

So the only difference between my enviroment is Mono Version. I'll try to use a newer mono version in docker.

blauracke commented 4 years ago

also ich denke schon, dass auch ohne Docker das mono recht viel CPU Zeit braucht. (bei mir zumindest) grafik ich hab aktuell mono version 6.8.0.105 drauf bei mir am Raspberry laufen aber noch paar andere Sachen (influxDBs), die auch CPU brauchen, aber halt auch währenddessen was tun. mono wird aber sonst von nix anderem verwendet. Ich hatte früher auch das Problem, dass das ganze System dann irgendwann sehr zäh wurde und die Gesamt CPU zu hoch war, das lag aber an "wa" (iowait) trotz super schneller SD Karte. Ich hab nun die SD Karte durch eine kleine SSD ersetzt - jetzt flutschts.

bassmaster187 commented 4 years ago

image

It seems like, I found the Problem: FileSystemWatcher used by Geofencing. The question is: is it caused by the new Mono Version or by the Docker subsystem?

rowich commented 4 years ago

I have an updated "Raspberry Pi 3B" (with latest Mono), so could be interessting to cross check with a docker image. If you like me to test something, I happy to do so. Just tell a windows guy what todo - I am used to managed my Windows infrastructure using command line, so any SSH commands and/or sudo stuff is no issue ;-) just need the details what to do.

Am 28/04/2020 um 14:50 schrieb Christian P.:

image https://user-images.githubusercontent.com/6816385/80488838-43c36a00-895f-11ea-9e19-96ccf560c105.png

It seems like, I found the Problem: FileSystemWatcher used by Geofencing. The question is: is it caused by the new Mono Version or by the Docker subsystem?

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/bassmaster187/TeslaLogger/issues/158#issuecomment-620585729, or unsubscribe https://github.com/notifications/unsubscribe-auth/AL4L3BCONXOJPKYR4MQJ2J3RO3GJXANCNFSM4LVS7IXA.

bassmaster187 commented 4 years ago

I have an updated "Raspberry Pi 3B" (with latest Mono), so could be interessting to cross check with a docker image. If you like me to test something, I happy to do so. Just tell a windows guy what todo - I am used to managed my Windows infrastructure using command line, so any SSH commands and/or sudo stuff is no issue ;-) just need the details what to do.

please make a screenshot of "top" command in ssh. I need the uptime (top left corner) and "time+" of the mono.

rowich commented 4 years ago

Here you go:

Am 28/04/2020 um 16:31 schrieb Christian P.:

I have an updated "Raspberry Pi 3B" (with latest Mono), so could
be interessting to cross check with a docker image. If you like me
to test something, I happy to do so. Just tell a windows guy what
todo - I am used to managed my Windows infrastructure using
command line, so any SSH commands and/or sudo stuff is no issue
;-) just need the details what to do.

please make a screenshot of "top" command in ssh. I need the uptime (top left corner) and "time+" of the mono.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/bassmaster187/TeslaLogger/issues/158#issuecomment-620644344, or unsubscribe https://github.com/notifications/unsubscribe-auth/AL4L3BBWOUS6AD72WHUPSDDRO3SCXANCNFSM4LVS7IXA.

endurance1968 commented 4 years ago

Tried some settings that might be relevant for FileSystemwatcher ala /proc/sys/fs/inotify/max_user_watches to 16384 or export MONO_MANAGED_WATCHER=disabled

both both had no effect after ~12h mono is up to approx 30%CPU again on a RPI3b with latest mono installed.

bassmaster187 commented 4 years ago

Here you go: Am 28/04/2020 um 16:31 schrieb Christian P.: I have an updated "Raspberry Pi 3B" (with latest Mono), so could be interessting to cross check with a docker image. If you like me to test something, I happy to do so. Just tell a windows guy what todo - I am used to managed my Windows infrastructure using command line, so any SSH commands and/or sudo stuff is no issue ;-) just need the details what to do. please make a screenshot of "top" command in ssh. I need the uptime (top left corner) and "time+" of the mono. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#158 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/AL4L3BBWOUS6AD72WHUPSDDRO3SCXANCNFSM4LVS7IXA.

there is no screenshot in your reply

rowich commented 4 years ago

2nd try with an attachement. 1st try was an inplace picture in an html email.

Am 29/04/2020 um 09:09 schrieb Christian P.:

Here you go: Am 28/04/2020 um 16:31 schrieb Christian P.:
… <#>
I have an updated "Raspberry Pi 3B" (with latest Mono), so could
be interessting to cross check with a docker image. If you like me
to test something, I happy to do so. Just tell a windows guy what
todo - I am used to managed my Windows infrastructure using
command line, so any SSH commands and/or sudo stuff is no issue
;-) just need the details what to do. please make a screenshot of
"top" command in ssh. I need the uptime (top left corner) and
"time+" of the mono. — You are receiving this because you
commented. Reply to this email directly, view it on GitHub <#158
(comment)
<https://github.com/bassmaster187/TeslaLogger/issues/158#issuecomment-620644344>>,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AL4L3BBWOUS6AD72WHUPSDDRO3SCXANCNFSM4LVS7IXA.

there is no screenshot in your reply

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/bassmaster187/TeslaLogger/issues/158#issuecomment-621028223, or unsubscribe https://github.com/notifications/unsubscribe-auth/AL4L3BDEJSOH6JWZEXN4GQDRO7HD7ANCNFSM4LVS7IXA.

fibsmaster commented 4 years ago

I also noticed the cpu load increase using docker. Started monitoring the mono process now. One sample every 60 sec with average over the last 10 sec. Is there anything we can monitor regarding the mono process itself? Some sort of debug mode that can be enabled?

bassmaster187 commented 4 years ago

Please update to the latest version. I made a lot of performance impovements and caching.

CPU is below 1% and I hope it's not raising.

image

pbertra commented 4 years ago

I upgraded to the latest version and will continue to monitor.

pbertra commented 4 years ago

Not OK yet :-(

kern1 1day (1)

fibsmaster commented 4 years ago

Try changing mono version for teslalogger container to 5.20.1.34. It worked for me.

bassmaster187 commented 4 years ago

On Raspberry 4 with Mono 5.8.0.240 everything is ok:

image

image

So I think it is caused by Mono V6

endurance1968 commented 4 years ago

Compatibility Issue with Mono 6, was confirmed now by minimum 3 users. Can we nail it down to a specifc code change in Mono, so it can be fixed there, or does the TeslaLogger need to be adapted.

bassmaster187 commented 4 years ago

It really seems like it is caused by Mono 6.

After 14 hours with Mono 5.4.1.34 with Docker on my Synology I'm way below 1%

image

Is anybody out there with Mono 5.4.1.34 with increasing CPU usage? I think I'm gonna open an issue in Mono Repository.

pbertra commented 4 years ago

Opening an issue is certainly a good idea. However in the meantime you could maybe use a previous version of mono in the container?

pbertra commented 4 years ago

Now running downgraded mono version... Going on with monitoring

pbertra commented 4 years ago

kern1z 1day Yes! :-) Completely stable eventually on 5.20.1.34

bassmaster187 commented 4 years ago

Same here, so I think we could close this issue and Mono V6 is causing this Problem.

image

image

Likemike24 commented 1 year ago

Has this issue ever been solved? I`m running teslalogger with Docker on a Lenovo ThinkCentre M900 an Teslalogger/Mono eats up 1 CPU core permanently.

Mono Version: 6.8.0.105 Teslalogger: Latest

grafik