alsa-devel.alsa-project.org archive mirror
 help / color / mirror / Atom feed
* pcm_meter.c issue at s16_update
@ 2020-07-26 18:20 Pavel Hofman
  2020-07-28 16:46 ` Pavel Hofman
  0 siblings, 1 reply; 16+ messages in thread
From: Pavel Hofman @ 2020-07-26 18:20 UTC (permalink / raw)
  To: alsa-devel, Takashi Iwai

Hi,

I am debugging the following problem with the PCM METER API:

An application with meter/scope configured in .asoundrc hits a high CPU
load sometimes when a new playback stream is opened. E.g. in MPD when
opening a new radio stream. The 100% CPU core load takes tens of seconds.

Debugging the issue revealed this:


TL;DR: at decrease of [status.appl_ptr - status.delay] between
consequent runs the size of buffer to convert by the built-in s16 scope
is set from usual 100s to huge value of pcm->boundary (1.5G), causing a
very long processing at 100% core load.

Details:

Every scope setup uses a default s16 scope defined in alsa-lib, which
converts samples to s16 so that the user-provided scopes can access data
via snd_pcm_scope_s16_get_channel_buffer buffers with converted samples.

The s16 scope converts samples in a loop, in frames chunks, decrementing
size variable by frames until zero. The value of size is hundreds
samples max at each s16_update call, calculated in
https://github.com/alsa-project/alsa-lib/blob/master/src/pcm/pcm_meter.c#L1100
. A debug added after that line shows this:

@@ -1098,14 +1103,18 @@ static void s16_update(snd_pcm_scope_t *scope)
        snd_pcm_sframes_t size;
        snd_pcm_uframes_t offset;
        size = meter->now - s16->old;
+       fprintf(stderr, "s16_update 1: meter->now %ld, s16->old %ld,
size %ld\n", meter->now, s16->old, size);
        if (size < 0)
                size += spcm->boundary;
        offset = s16->old % meter->buf_size;




s16_update 1: meter->now 2154673, s16->old 2153771, size 902
s16_update 1: meter->now 2155579, s16->old 2154673, size 906
s16_update 1: meter->now 2156487, s16->old 2155579, size 908
s16_update 1: meter->now 2157391, s16->old 2156487, size 904
s16_update 1: meter->now 2158298, s16->old 2157391, size 907
s16_update 1: meter->now 2159203, s16->old 2158298, size 905
s16_update 1: meter->now 2160091, s16->old 2159203, size 888
s16_update 1: meter->now 2160976, s16->old 2160091, size 885
s16_update 1: meter->now 2161924, s16->old 2160976, size 948
s16_update 1: meter->now 2162829, s16->old 2161924, size 905
s16_update 1: meter->now 2163733, s16->old 2162829, size 904
s16_update 1: meter->now 2164594, s16->old 2163733, size 861
s16_update 1: meter->now 2165542, s16->old 2164594, size 948
s16_update 1: meter->now 2166448, s16->old 2165542, size 906
s16_update 1: meter->now 2167352, s16->old 2166448, size 904
s16_update 1: meter->now 2168259, s16->old 2167352, size 907
s16_update 1: meter->now 2169165, s16->old 2168259, size 906
s16_update 1: meter->now 2170050, s16->old 2169165, size 885
s16_update 1: meter->now 2170936, s16->old 2170050, size 886
s16_update 1: meter->now 2171877, s16->old 2170936, size 941
s16_update 1: meter->now 2172783, s16->old 2171877, size 906
s16_update 1: meter->now 2173690, s16->old 2172783, size 907
s16_update 1: meter->now 2174596, s16->old 2173690, size 906
s16_update 1: meter->now 2175502, s16->old 2174596, size 906
s16_update 1: meter->now 2176407, s16->old 2175502, size 905
s16_update 1: meter->now 2177311, s16->old 2176407, size 904
s16_update 1: meter->now 2178215, s16->old 2177311, size 904


However, sometimes meter->now < s16->old, causing size < 0, for which
this line applies
https://github.com/alsa-project/alsa-lib/blob/master/src/pcm/pcm_meter.c#L1102

size += spcm->boundary

and size becomes a huge number, because hw:0 pcm -> boundary is
1445068800. The loop at
https://github.com/alsa-project/alsa-lib/blob/master/src/pcm/pcm_meter.c#L1104
takes tens of seconds, untill the huge buffer is converted to s16.

Usually the negative difference is quite small:

s16_update 1: meter->now 988, s16->old 21139, size -20151
s16_update 1: meter->now 870, s16->old 18865, size -17995
s16_update 1: meter->now 1065, s16->old 20786, size -19721
s16_update 1: meter->now 701, s16->old 24839, size -24138
s16_update 1: meter->now 782, s16->old 869, size -87
s16_update 1: meter->now 763, s16->old 841, size -78
s16_update 1: meter->now 963, s16->old 22525, size -21562
s16_update 1: meter->now 665, s16->old 832, size -167
s16_update 1: meter->now 745, s16->old 865, size -120
s16_update 1: meter->now 859, s16->old 1002, size -143
s16_update 1: meter->now 935, s16->old 117452, size -116517


Yet in all these cases the size variable is incremented by 1445068800,
which clearly does not make sense.

Now the question is how it happens that meter->now < s16->old, when
meter->now is calculated by now = status.appl_ptr - status.delay
https://github.com/alsa-project/alsa-lib/blob/master/src/pcm/pcm_meter.c#L219
and s16->old is set to meter->now at the end of each s16_update call
https://github.com/alsa-project/alsa-lib/blob/master/src/pcm/pcm_meter.c#L1142
.

The debug around the event looks like this, suddenly meter->now drops down:

s16_update 1: meter->now 2567498, s16->old 2566593, size 905
s16_update 1: meter->now 2568401, s16->old 2567498, size 903
s16_update 1: meter->now 20786, s16->old 20786, size 0
s16_update 1: meter->now 1065, s16->old 20786, size -19721
s16_update 1: meter->now 24839, s16->old 24838, size 1
s16_update 1: meter->now 701, s16->old 24839, size -24138
s16_update 1: meter->now 1253162, s16->old 701, size 1252461
s16_update 1: meter->now 1255148, s16->old 1253162, size 1986

..........

s16_update 1: meter->now 11136, s16->old 10261, size 875
s16_update 1: meter->now 22525, s16->old 22524, size 1
s16_update 1: meter->now 963, s16->old 22525, size -21562
s16_update 1: meter->now 1270914, s16->old 963, size 1269951
s16_update 1: meter->now 1272917, s16->old 1270914, size 2003


Could it perhaps be an XRUN, causing the difference (status.appl_ptr -
status.delay)  to actually decrease compared to the previous run? I
really do not know how/when such decrease can happen. But if it is a
standard situation, than IMO the size of to-be converted buffer by the
s16 scope  should not be set to the huge pcm->boundary.

Thanks a lot for help.

Best regards,

Pavel.

^ permalink raw reply	[flat|nested] 16+ messages in thread
* pcm_meter.c issue at s16_update
@ 2020-09-15  3:40 Go Peppy
  2020-09-17 19:13 ` Pavel Hofman
  0 siblings, 1 reply; 16+ messages in thread
From: Go Peppy @ 2020-09-15  3:40 UTC (permalink / raw)
  To: alsa-devel

Hi,

It would be great to have a fix/patch from Pavel in the main codebase. I've
tested his fix and it worked fine.

Just to remind what the issue is - while switching from one web radio
station to another there is a high CPU usage for about 20 seconds. Because
of that high CPU consumption almost all other processes are blocked. The
fix from Pavel helps to avoid this situation.

Without the ALSA patch I need to make a custom ALSA build every time I
release my software. This is very annoying.

Thanks in advance!

^ permalink raw reply	[flat|nested] 16+ messages in thread

end of thread, other threads:[~2020-10-15  4:00 UTC | newest]

Thread overview: 16+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-07-26 18:20 pcm_meter.c issue at s16_update Pavel Hofman
2020-07-28 16:46 ` Pavel Hofman
2020-07-28 17:04   ` Takashi Iwai
2020-07-28 18:04     ` Pavel Hofman
2020-07-28 18:54       ` Pavel Hofman
2020-08-02 17:50         ` Pavel Hofman
2020-08-03  6:17           ` Takashi Iwai
2020-08-03  7:22             ` Jaroslav Kysela
2020-08-03 10:48               ` Pavel Hofman
2020-08-09  7:05                 ` Pavel Hofman
2020-08-09 20:29                   ` Jaroslav Kysela
2020-08-09 21:05                     ` Pavel Hofman
2020-09-15  3:40 Go Peppy
2020-09-17 19:13 ` Pavel Hofman
2020-10-13 17:35   ` Jaroslav Kysela
2020-10-15  3:59     ` Go Peppy

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).