100% CPU usage, possible threading problem

[pavelgeiger]

Hi, I run lms on Rpi4 in docker. From time to time, lms starts to use 100% of cpu. and doesnt stop until restart Htop looks like this

and strace log

strace: Process 3250 attached futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0xb54efdb8, FUTEX_WAIT_PRIVATE, 2, NULL) = 0

[epoupon]

Really strange. What recommendation engine do you use ? What do the logs say?

[epoupon]

And do you use transcoding?

[pavelgeiger]

I have transcoding turned off, recommendation engine set to tags based and I listen through subsonic API with latest release of Strawberry as a client. All streamed music is in FLAC format.

Strange is that lms seems to be working OK at that moment. Web works, music streams. I have no way to reproduce it reliably. I can try something when it happens again. I was thinking about sending it SIGSEGV signal to force it to crash and produce stack trace or something

[pavelgeiger]

Logs doesnt contain anything abnormal.

[epoupon]

Can you tell if using the subsonic API is a prerequisite to trigger the bug?

Making the program crash to have a dump would be great. Note sure that's easy in a running docker container though, I guess you will have to configure it to output in a volume or in a bound directory.

[epoupon]

Does this occur while scanning new files or just after a scan? It reminds me a bug I already fixed in the past. The database is being optimized once the the scan is complete, but it you connect just before the optimize pass is done, the db requests for tag similarities are so slow that it takes hours to complete.

[epoupon]

And could you please paste the last lines of the log file just to make sure?

[pavelgeiger]

Hi, I have encountered the issue again. This time with full logging enabled. This is part of the output. It is being logged repeatedly

[2020-Aug-14 07:22:42.596] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED [2020-Aug-14 07:22:42.596] 1 - [debug] - [TRANSCODE] [10] - nb bytes = 0, total = 0 [2020-Aug-14 07:22:42.596] 1 - [debug] - [API_SUBSONIC] Request 325533 'stream' handled! [2020-Aug-14 07:22:42.596] 1 - [debug] - [API_SUBSONIC] Handling request 325534 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-1128}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-14 07:22:42.607] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED 2 [2020-Aug-14 07:22:42.608] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED [2020-Aug-14 07:22:42.608] 1 - [debug] - [TRANSCODE] [10] - nb bytes = 0, total = 0 [2020-Aug-14 07:22:42.608] 1 - [debug] - [API_SUBSONIC] Request 325534 'stream' handled! [2020-Aug-14 07:22:42.609] 1 - [debug] - [API_SUBSONIC] Handling request 325535 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-1128}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-14 07:22:42.619] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED 2 [2020-Aug-14 07:22:42.620] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED [2020-Aug-14 07:22:42.620] 1 - [debug] - [TRANSCODE] [10] - nb bytes = 0, total = 0 [2020-Aug-14 07:22:42.620] 1 - [debug] - [API_SUBSONIC] Request 325535 'stream' handled! [2020-Aug-14 07:22:42.621] 1 - [debug] - [API_SUBSONIC] Handling request 325536 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-1128}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-14 07:22:42.632] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED 2 [2020-Aug-14 07:22:42.632] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED [2020-Aug-14 07:22:42.632] 1 - [debug] - [TRANSCODE] [10] - nb bytes = 0, total = 0 [2020-Aug-14 07:22:42.632] 1 - [debug] - [API_SUBSONIC] Request 325536 'stream' handled! [2020-Aug-14 07:22:42.633] 1 - [debug] - [API_SUBSONIC] Handling request 325537 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-1128}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-14 07:22:42.644] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED 2 [2020-Aug-14 07:22:42.644] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED [2020-Aug-14 07:22:42.644] 1 - [debug] - [TRANSCODE] [10] - nb bytes = 0, total = 0 [2020-Aug-14 07:22:42.645] 1 - [debug] - [API_SUBSONIC] Request 325537 'stream' handled! [2020-Aug-14 07:22:42.645] 1 - [debug] - [API_SUBSONIC] Handling request 325538 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-1128}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-14 07:22:42.656] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED 2 [2020-Aug-14 07:22:42.656] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED [2020-Aug-14 07:22:42.657] 1 - [debug] - [TRANSCODE] [10] - nb bytes = 0, total = 0 [2020-Aug-14 07:22:42.657] 1 - [debug] - [API_SUBSONIC] Request 325538 'stream' handled! [2020-Aug-14 07:22:42.657] 1 - [debug] - [API_SUBSONIC] Handling request 325539 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-1128}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-14 07:22:42.668] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED 2 [2020-Aug-14 07:22:42.669] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED [2020-Aug-14 07:22:42.669] 1 - [debug] - [TRANSCODE] [10] - nb bytes = 0, total = 0 [2020-Aug-14 07:22:42.669] 1 - [debug] - [API_SUBSONIC] Request 325539 'stream' handled! [2020-Aug-14 07:22:42.669] 1 - [debug] - [API_SUBSONIC] Handling request 325540 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-1128}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-14 07:22:42.680] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED 2 [2020-Aug-14 07:22:42.681] 1 - [debug] - [TRANSCODE] [10] - Stdout FAILED [2020-Aug-14 07:22:42.681] 1 - [debug] - [TRANSCODE] [10] - nb bytes = 0, total = 0 [2020-Aug-14 07:22:42.681] 1 - [debug] - [API_SUBSONIC] Request 325540 'stream' handled! [2020-Aug-14 07:22:42.681] 1 - [debug] - [API_SUBSONIC] Handling request 325541 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-1128}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0},

[pavelgeiger]

It continues even when the subsonic client (Strawberry) is closed

[epoupon]

Thanks for this valuable information!

[epoupon]

@GeryEmreis , would you mind testing if epoupon/lms:arm-cb0fe96 solves the problem?

[pavelgeiger]

Hi, I've tested it and it doesn't seem to be fixed copletely. Now the log contains these lines. Reproduction is simple. I have removed file (from filesystem) which was previously scanned by lms and now whenever I try to play that file (through subsonic api) issue happens

[2020-Aug-18 06:09:34.957] 1 - [debug] - [API_SUBSONIC] Request 949 'stream' handled! [2020-Aug-18 06:09:34.957] 1 - [debug] - [API_SUBSONIC] Handling request 951 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:34.957] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:34.967] 1 - [debug] - [API_SUBSONIC] Request 950 'stream' handled! [2020-Aug-18 06:09:34.967] 1 - [debug] - [API_SUBSONIC] Handling request 952 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:34.968] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:34.968] 1 - [debug] - [API_SUBSONIC] Request 951 'stream' handled! [2020-Aug-18 06:09:34.968] 1 - [debug] - [API_SUBSONIC] Handling request 953 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:34.968] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:34.978] 1 - [debug] - [API_SUBSONIC] Request 952 'stream' handled! [2020-Aug-18 06:09:34.978] 1 - [debug] - [API_SUBSONIC] Handling request 954 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:34.979] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:34.979] 1 - [debug] - [API_SUBSONIC] Request 953 'stream' handled! [2020-Aug-18 06:09:34.980] 1 - [debug] - [API_SUBSONIC] Handling request 955 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:34.980] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:34.989] 1 - [debug] - [API_SUBSONIC] Request 954 'stream' handled! [2020-Aug-18 06:09:34.989] 1 - [debug] - [API_SUBSONIC] Handling request 956 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:34.990] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:34.991] 1 - [debug] - [API_SUBSONIC] Request 955 'stream' handled! [2020-Aug-18 06:09:34.991] 1 - [debug] - [API_SUBSONIC] Handling request 957 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:34.991] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:35.001] 1 - [debug] - [API_SUBSONIC] Request 956 'stream' handled! [2020-Aug-18 06:09:35.001] 1 - [debug] - [API_SUBSONIC] Handling request 958 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:35.001] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:35.002] 1 - [debug] - [API_SUBSONIC] Request 957 'stream' handled! [2020-Aug-18 06:09:35.002] 1 - [debug] - [API_SUBSONIC] Handling request 959 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:35.002] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:35.012] 1 - [debug] - [API_SUBSONIC] Request 958 'stream' handled! [2020-Aug-18 06:09:35.012] 1 - [debug] - [API_SUBSONIC] Handling request 960 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0}, [2020-Aug-18 06:09:35.013] 1 - [debug] - [AUTH] Checking internal password for user 'music' [2020-Aug-18 06:09:35.013] 1 - [debug] - [API_SUBSONIC] Request 959 'stream' handled! [2020-Aug-18 06:09:35.013] 1 - [debug] - [API_SUBSONIC] Handling request 961 'stream.view', continuation = true, params = {c=Strawberry}, {f=json}, {id=tr-2580}, {p=SENSIBLE DATA}, {u=music}, {v=1.11.0},

[epoupon]

Ah, I am glad you have found a way to reproduce this 👍 Thanks I will investigate.

[epoupon]

Ok I guess it should be OK now: epoupon/lms:arm-09f5ea5b

[pavelgeiger]

It seems to be working correctly now. Thanks