Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

CPU usage increasing after a few hours #158

Closed
pbertra opened this issue Mar 28, 2020 · 59 comments
Closed

CPU usage increasing after a few hours #158

pbertra opened this issue Mar 28, 2020 · 59 comments
Labels
bug Something isn't working

Comments

@pbertra
Copy link

pbertra commented Mar 28, 2020

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
Copy link
Owner

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
Copy link
Author

pbertra commented Mar 29, 2020

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
Copy link
Owner

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
Copy link
Author

pbertra commented Mar 29, 2020

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
Copy link
Author

pbertra commented Mar 30, 2020

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

@pbertra
Copy link
Author

pbertra commented Apr 1, 2020

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

@bassmaster187
Copy link
Owner

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
Copy link
Author

pbertra commented Apr 1, 2020

Yes I did a restart of the teslalogger container

@bassmaster187
Copy link
Owner

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
Copy link
Contributor

Adminius commented Apr 8, 2020

same here :/
image
image
Docker/TeslaLogger 1.40.1.0

@pbertra
Copy link
Author

pbertra commented Apr 9, 2020

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
Copy link

DariBer commented Apr 9, 2020

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
Copy link
Author

pbertra commented Apr 9, 2020

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

@DariBer
Copy link

DariBer commented Apr 9, 2020

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

@Adminius
Copy link
Contributor

Adminius commented Apr 9, 2020

after 25h
image

1129MB RAM?!

@bassmaster187
Copy link
Owner

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

image

@DariBer
Copy link

DariBer commented Apr 9, 2020

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
Copy link
Author

pbertra commented Apr 10, 2020

@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
Copy link

DariBer commented Apr 10, 2020

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
Copy link
Author

pbertra commented Apr 10, 2020

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

@bassmaster187
Copy link
Owner

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

image

@bassmaster187
Copy link
Owner

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

image

Changeset:
26ed347

@bassmaster187
Copy link
Owner

Please update to 1.40.3.0

@pbertra
Copy link
Author

pbertra commented Apr 13, 2020

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

@pbertra
Copy link
Author

pbertra commented Apr 14, 2020

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
Copy link
Author

pbertra commented Apr 17, 2020

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

@Adminius
Copy link
Contributor

RasPi, 1.40.3.0:
image

@pbertra
Copy link
Author

pbertra commented Apr 23, 2020

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 bassmaster187 changed the title High CPU usage in docker after a few hours High CPU usage (in docker?) after a few hours Apr 23, 2020
@bassmaster187
Copy link
Owner

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.

@endurance1968
Copy link
Contributor

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
Copy link
Owner

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
Copy link
Contributor

rowich commented Apr 29, 2020 via email

@fibsmaster
Copy link
Contributor

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
Copy link
Owner

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
Copy link
Author

pbertra commented Apr 30, 2020

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

@pbertra
Copy link
Author

pbertra commented May 1, 2020

Not OK yet :-(

kern1 1day (1)

@fibsmaster
Copy link
Contributor

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

@bassmaster187
Copy link
Owner

On Raspberry 4 with Mono 5.8.0.240 everything is ok:

image

image

So I think it is caused by Mono V6

@endurance1968
Copy link
Contributor

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
Copy link
Owner

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
Copy link
Author

pbertra commented May 4, 2020

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

@bassmaster187 bassmaster187 changed the title High CPU usage (in docker?) after a few hours CPU usage increasing after a few hours May 4, 2020
@pbertra
Copy link
Author

pbertra commented May 4, 2020

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

@pbertra
Copy link
Author

pbertra commented May 5, 2020

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

@bassmaster187
Copy link
Owner

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

image

image

@Likemike24
Copy link

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

@bassmaster187
Copy link
Owner

No Problems with Mono 6.12.0.182

image

As far as I can remember, the problem was creating a new WebClient caused this problem. Now we are reusing the WebClient Class.
Please try to update to the mentioned version. Otherwise we have to check if we have a different problem.

@Likemike24
Copy link

Likemike24 commented Sep 4, 2023

Updated the version of Mono to the latest 6.12.0.200, sadly the problem still persists.
grafik

A few seconds after the start of Teslalogger it eats up 100% of one core.

@bassmaster187
Copy link
Owner

After the start of Teslalogger it is common to use a lot of CPU to update the database and do some housekeeping. But if after lets say 1 hour the problem still persists, we have a problem.

Please run Teslalogger for at least one day.

Get the PID of teslalogger:
image

Use the PID in following command:

top -H -p 487

Post a screenshot like this:
image

@Likemike24
Copy link

I let it run for about one day, but it stays at 100%.

Here´s the output you requested:
grafik

@superfloh247
Copy link
Contributor

Looks like it's generating maps for the timeline.

@bassmaster187
Copy link
Owner

Could you please post a logfile, so we can see if it's a endless loop or really generating maps for the timeline

@Likemike24
Copy link

Logfile Teil 1
logfile1.zip

@Likemike24
Copy link

Logfile Teil 2
logfile2.zip

@Likemike24
Copy link

Could you please post a logfile, so we can see if it's a endless loop or really generating maps for the timeline

Did you see my post?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

10 participants