Hi Serge,
Unfortunately I don't have any news about spikes. I have tried couple options but that didn't help to enable debugging symbols in alsa-lib. Tried to ask for help on the github project:
Compile with debugging symbols * Issue #71 * alsa-project/alsa-lib * GitHub
no reply yet. Probably it's the wrong place to ask.
Good to know that you were able to build working version of the peppyalsa plugin. When you say 'no spikes', do you mean that there is data in the pipe and you don't run player as sudo/root? What's the size of the library which you built? What's the output of the command 'uname -a'? Do you have a graphical desktop? There is 64-bit beta Raspberry OS:
Raspberry Pi OS (64 bit) beta test version - Raspberry Pi Forums
If it really works without spikes in your environment if would be interesting to understand why
Unfortunately I don't have any news about spikes. I have tried couple options but that didn't help to enable debugging symbols in alsa-lib. Tried to ask for help on the github project:
Compile with debugging symbols * Issue #71 * alsa-project/alsa-lib * GitHub
no reply yet. Probably it's the wrong place to ask.
Good to know that you were able to build working version of the peppyalsa plugin. When you say 'no spikes', do you mean that there is data in the pipe and you don't run player as sudo/root? What's the size of the library which you built? What's the output of the command 'uname -a'? Do you have a graphical desktop? There is 64-bit beta Raspberry OS:
Raspberry Pi OS (64 bit) beta test version - Raspberry Pi Forums
If it really works without spikes in your environment if would be interesting to understand why
> I have tried couple options but that didn't help to enable debugging symbols in alsa-lib.
Maybe there is a way to match hex-es in the profiling results to function names manually, one-by-one using the nm tool? Or how it’s called, the tool to show hex offsets of all the exported functions.
>When you say 'no spikes', do you mean that there is data in the pipe and you don't run player as sudo/root?
As mpd, but we concluded that the user is not meaningful.
So running the 52600 and the fresh build gave the same: no spikes and the expected pipe output.
>What's the size of the library which you built?
Much lower, a half size probably, but it was my
gcc -shared meter.c peppyalsa.c spectrum.c -lfftw3 -lasound -o libpeppyalsa.so
not the default make, Looks like the make links more libraries to libpeppyalsa.so
>What's the output of the command 'uname> -a'?
When I switch to my image again I will check/report.
Not sure I remember correctly, but I already compared them, the both uname-s were equal.
In my records there is
Linux raspberrypi 4.19.118-v7l+ #1311 SMP Mon Apr 27 14:26:42 BST 2020 armv7l GNU/Linux
(repeated twice), so for the both systems
>Do you have a graphical desktop?
Yes.
>There is 64-bit beta Raspberry OS:
It's recommended 32-bit (as shown Raspberry Pi Imager). As I was making a player I didn’t want any betas (to test) ;-)
>If it really works without spikes in your environment if would be interesting to understand why
Sure! I’m planing to compare some files between the images
Reviewing the alsa and the plugin codes I found that
snd_pcm_scope_s16_open adds
list_add_tail(&scope->list, &meter->scopes);
a new scope and effectively starts (not sure of the correct name) a host s16 plugin (inside alsa, \src\pcm\pcm_meter.c), and there are some loops as list_for_each(pos, &meter→scopes), including the separate thread. I’m thinking of that at the moment
My weak hypothesis is the conversion the pcm_meter.c must do to convert the stream to 16 bit (to be metered). The larger buffer – the more data to convert, the more spikes.
If the default buffer size (who determines that?) is smaller on my system, everything could be explained. Is there a curl global configuration? Looks like all the players use curl.
Maybe there is a way to match hex-es in the profiling results to function names manually, one-by-one using the nm tool? Or how it’s called, the tool to show hex offsets of all the exported functions.
>When you say 'no spikes', do you mean that there is data in the pipe and you don't run player as sudo/root?
As mpd, but we concluded that the user is not meaningful.
So running the 52600 and the fresh build gave the same: no spikes and the expected pipe output.
>What's the size of the library which you built?
Much lower, a half size probably, but it was my
gcc -shared meter.c peppyalsa.c spectrum.c -lfftw3 -lasound -o libpeppyalsa.so
not the default make, Looks like the make links more libraries to libpeppyalsa.so
>What's the output of the command 'uname> -a'?
When I switch to my image again I will check/report.
Not sure I remember correctly, but I already compared them, the both uname-s were equal.
In my records there is
Linux raspberrypi 4.19.118-v7l+ #1311 SMP Mon Apr 27 14:26:42 BST 2020 armv7l GNU/Linux
(repeated twice), so for the both systems
>Do you have a graphical desktop?
Yes.
>There is 64-bit beta Raspberry OS:
It's recommended 32-bit (as shown Raspberry Pi Imager). As I was making a player I didn’t want any betas (to test) ;-)
>If it really works without spikes in your environment if would be interesting to understand why
Sure! I’m planing to compare some files between the images
Reviewing the alsa and the plugin codes I found that
snd_pcm_scope_s16_open adds
list_add_tail(&scope->list, &meter->scopes);
a new scope and effectively starts (not sure of the correct name) a host s16 plugin (inside alsa, \src\pcm\pcm_meter.c), and there are some loops as list_for_each(pos, &meter→scopes), including the separate thread. I’m thinking of that at the moment
My weak hypothesis is the conversion the pcm_meter.c must do to convert the stream to 16 bit (to be metered). The larger buffer – the more data to convert, the more spikes.
If the default buffer size (who determines that?) is smaller on my system, everything could be explained. Is there a curl global configuration? Looks like all the players use curl.
Yes, with 'frequency 5' I don't see the spikes. Now it's time to understand what that means
BTW, building the library using your command didn't help in my case. The library file size was almost two times less - 24304. The spikes are still there (w/o that 'frequency' parameter)
There are spikes with frequency > 5 (e,g, 10, 15, 20).
BTW, building the library using your command didn't help in my case. The library file size was almost two times less - 24304. The spikes are still there (w/o that 'frequency' parameter)
There are spikes with frequency > 5 (e,g, 10, 15, 20).
Last edited:
That parameter is used to configure meter->delay alsa-lib/pcm_meter.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub which is used in the loop of the meter thread alsa-lib/pcm_meter.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub . My 2 cents the problem is somewhere in the loop. Perhaps a few debug printfs would reveal the problem. Maybe around this check alsa-lib/pcm_meter.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub - the SND_PCM_STATE_PAUSED may not be correctly supported by this while loop (IMO the status used when waiting for the cache fill).
>building the library using your command didn't help in my case
I didn’t say it helps. It just confirms the standard build links a lot of redundant
>There are spikes with frequency > 5 (e,g, 10, 15, 20).
For me 15 is still noticeably better. A puzzle again.
BTW if you are able to recompile alsa, did you install the new alsa build (even without debug info)
and check the spikes? The results could be curious
>Now it's time to understand what that means
So as far I could realize it’s in src\pcm\pcm_meter.c
It’s in snd_pcm_meter_thread
where there is the main loop
while (!meter->closed) {
……
nanosleep(&meter->delay, NULL);
}
where meter→ delay is
meter->delay.tv_sec = 0;
meter->delay.tv_nsec = 1000000000 / frequency;
So the lower frequency, the more sleep and so the less spikes
Here is the puzzle.
While logging inside alsaplugin, when the spikes happen, I saw significant delays
between calling peppyalsa.c/level_start and level_update
they are called from the main loop above nearly
if (!meter->running) {
list_for_each(pos, &meter->scopes) {
scope = list_entry(pos, snd_pcm_scope_t, list);
if (scope->enabled)
scope->ops->start(scope);
}
meter->running = 1;
(1)
}
list_for_each(pos, &meter→scopes) (2) {
scope = list_entry(pos, snd_pcm_scope_t, list); (2)
if (scope->enabled)
scope->ops->update(scope);
}
The only (imho) delay could be given by the (1) and (2) marked positions.
So we should realize how and where those list_* are implemented.
Are there any thread scheduling method configurations in the kernel?
Edit: With htop I often see CPU is switched for the thread, so the kernel decides doing that. Why?
I didn’t say it helps. It just confirms the standard build links a lot of redundant
>There are spikes with frequency > 5 (e,g, 10, 15, 20).
For me 15 is still noticeably better. A puzzle again.
BTW if you are able to recompile alsa, did you install the new alsa build (even without debug info)
and check the spikes? The results could be curious
>Now it's time to understand what that means
So as far I could realize it’s in src\pcm\pcm_meter.c
It’s in snd_pcm_meter_thread
where there is the main loop
while (!meter->closed) {
……
nanosleep(&meter->delay, NULL);
}
where meter→ delay is
meter->delay.tv_sec = 0;
meter->delay.tv_nsec = 1000000000 / frequency;
So the lower frequency, the more sleep and so the less spikes
Here is the puzzle.
While logging inside alsaplugin, when the spikes happen, I saw significant delays
between calling peppyalsa.c/level_start and level_update
they are called from the main loop above nearly
if (!meter->running) {
list_for_each(pos, &meter->scopes) {
scope = list_entry(pos, snd_pcm_scope_t, list);
if (scope->enabled)
scope->ops->start(scope);
}
meter->running = 1;
(1)
}
list_for_each(pos, &meter→scopes) (2) {
scope = list_entry(pos, snd_pcm_scope_t, list); (2)
if (scope->enabled)
scope->ops->update(scope);
}
The only (imho) delay could be given by the (1) and (2) marked positions.
So we should realize how and where those list_* are implemented.
Are there any thread scheduling method configurations in the kernel?
Edit: With htop I often see CPU is switched for the thread, so the kernel decides doing that. Why?
Last edited:
The spikes are still there if I install alsa-lib by following these steps:
Updating ALSA on Raspbian Stretch
I'll try to add 'fprintf' in that file pcm_meter.c later today.
Updating ALSA on Raspbian Stretch
I'll try to add 'fprintf' in that file pcm_meter.c later today.
Yes! To the points above with something like below (to get timestamps)
#define LOG writelog
void writelog(char *template,...)
{
time_t current_time;
va_list argptr;
va_start (argptr, template);
FILE *f=fopen("/home/pi/peppyalsa/src/__log__.log","a+b");
current_time = time(NULL);
fprintf(f,"\n %s ",ctime(¤t_time));
vfprintf(f,template,argptr);
fclose(f);
va_end(argptr);
}
#define LOG writelog
void writelog(char *template,...)
{
time_t current_time;
va_list argptr;
va_start (argptr, template);
FILE *f=fopen("/home/pi/peppyalsa/src/__log__.log","a+b");
current_time = time(NULL);
fprintf(f,"\n %s ",ctime(¤t_time));
vfprintf(f,template,argptr);
fclose(f);
va_end(argptr);
}
I've added
#include <stdio.h>
#include <stdlib.h>
and 'fprintf(stdout, "test")' to the functions snd_pcm_meter_open and _snd_pcm_meter_open in the pcm_meter.c. But there is no any output. Either I update wrong place (/usr/lib) after running 'sudo make install' or ALSA is using controlled output. For example in the pcm_meter.c I found:
alsa-lib/pcm_meter.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub
Also:
alsa-lib/output.h at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub
The same 'fprintf' works in peppyalsa plugin in the function snd_pcm_scope_peppyalsa_open - when I run 'aplay' I see the output in the terminal.
Any idea how to proceed? Thanks!
#include <stdio.h>
#include <stdlib.h>
and 'fprintf(stdout, "test")' to the functions snd_pcm_meter_open and _snd_pcm_meter_open in the pcm_meter.c. But there is no any output. Either I update wrong place (/usr/lib) after running 'sudo make install' or ALSA is using controlled output. For example in the pcm_meter.c I found:
alsa-lib/pcm_meter.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub
Also:
alsa-lib/output.h at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub
The same 'fprintf' works in peppyalsa plugin in the function snd_pcm_scope_peppyalsa_open - when I run 'aplay' I see the output in the terminal.
Any idea how to proceed? Thanks!
> Either I update wrong place (/usr/lib) after running 'sudo make install'
Can be checked with ‘sudo htop’, find the process, ‘l’ (a kind of lsof), F4 (filter) for libasound and check the full path in the use.
Looks like pcm_meter.c should be in libasound, but not sure.
>or ALSA is using controlled output.
I was not able to find any logic in the ALSA native logging, but saw some ALSA messages in mpd.log. So the output is controlled by mpd at least.
Anyway if you use file (not stdout/stderror) the process would be much more straightforward
Can be checked with ‘sudo htop’, find the process, ‘l’ (a kind of lsof), F4 (filter) for libasound and check the full path in the use.
Looks like pcm_meter.c should be in libasound, but not sure.
>or ALSA is using controlled output.
I was not able to find any logic in the ALSA native logging, but saw some ALSA messages in mpd.log. So the output is controlled by mpd at least.
Anyway if you use file (not stdout/stderror) the process would be much more straightforward
Phofman: Thank you for navigating me to the list-for-each implementation.
I did hope that the list operations should be synchronized in the multi thread environment.
The ALSA guys are “brave” enough to omit that. Actually list_add_tail and list-for-each can be called concurrently.
Anyway, if there no synchronization is made, list_for_each for calling start() and list_for_each for calling update can’t be interrupted by the thread switching. So our problem is the pure snd_pcm_meter_thread behavior.
I went deeper and found that there 2 scopes actually.
The first one is for “s16” embedded scope (inserted by snd_pcm_scope_s16_open) and the second is the peppyalsa scope.
pcm_meter.c/s16_update is called always before (it’s the first scope) calling peppyalsa.c/level_update and does a lot of conversion related job.
The latter explains huge delay (about 10 seconds) between list_for_each for calling start() and list_for_each for calling level_update.
This perfectly correlates with what was found by Rpi - the less buffer size (in the streams) to process, the less spikes.
It’s the theory though. What to do is still open
I did hope that the list operations should be synchronized in the multi thread environment.
The ALSA guys are “brave” enough to omit that. Actually list_add_tail and list-for-each can be called concurrently.
Anyway, if there no synchronization is made, list_for_each for calling start() and list_for_each for calling update can’t be interrupted by the thread switching. So our problem is the pure snd_pcm_meter_thread behavior.
I went deeper and found that there 2 scopes actually.
The first one is for “s16” embedded scope (inserted by snd_pcm_scope_s16_open) and the second is the peppyalsa scope.
pcm_meter.c/s16_update is called always before (it’s the first scope) calling peppyalsa.c/level_update and does a lot of conversion related job.
The latter explains huge delay (about 10 seconds) between list_for_each for calling start() and list_for_each for calling level_update.
This perfectly correlates with what was found by Rpi - the less buffer size (in the streams) to process, the less spikes.
It’s the theory though. What to do is still open
A curious experiment.
If I switch to snd-dummy driver, there are no spikes
Switching back to bcm2835 brings the spikes back.
So if the spikes are just conversion of a large buffer, why it happens with one card but does not with another. The buffers are of the same size.
Maybe sound card parameters (supported format, bitrates, etc)?
If there are no reasons to convert the conversion is not applied, so no spikes.
Actually I observed that not every radio station switching produces the spikes.
Different format again?
So more matching formats the less spikes.
Where could I check/tune the sound driver/card capabilities?
I could then compare it with my system where the spikes don’t happen
If I switch to snd-dummy driver, there are no spikes
Switching back to bcm2835 brings the spikes back.
So if the spikes are just conversion of a large buffer, why it happens with one card but does not with another. The buffers are of the same size.
Maybe sound card parameters (supported format, bitrates, etc)?
If there are no reasons to convert the conversion is not applied, so no spikes.
Actually I observed that not every radio station switching produces the spikes.
Different format again?
So more matching formats the less spikes.
Where could I check/tune the sound driver/card capabilities?
I could then compare it with my system where the spikes don’t happen
In kernel.log found
raspberrypi kernel: [ 0.000000] Kernel command line: ... snd_bcm2835.enable_compat_alsa=0
Tried to set =1
No chance
raspberrypi kernel: [ 0.000000] Kernel command line: ... snd_bcm2835.enable_compat_alsa=0 ….. snd_bcm2835.enable_compat_alsa=1
So not sure the flag was applied
But in the log
raspberrypi kernel: [ 4.198791] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
Actually /boot/issue.txt differs between two systems
Rpi’s one is
Raspberry Pi reference 2020-05-27
Generated using pi-gen, GitHub - RPi-Distro/pi-gen: Tool used to create the raspberrypi.org Raspbian images, 825107f04027269db77426046f5085475b1ea22f, stage2
My one
Raspberry Pi reference 2020-02-13
Generated using pi-gen, GitHub - RPi-Distro/pi-gen: Tool used to create the raspberrypi.org Raspbian images, 5f884374b6ac6e155330c58caa1fb7249b8badf1, stage4
Is it something to catch at?
raspberrypi kernel: [ 0.000000] Kernel command line: ... snd_bcm2835.enable_compat_alsa=0
Tried to set =1
No chance
raspberrypi kernel: [ 0.000000] Kernel command line: ... snd_bcm2835.enable_compat_alsa=0 ….. snd_bcm2835.enable_compat_alsa=1
So not sure the flag was applied
But in the log
raspberrypi kernel: [ 4.198791] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
Actually /boot/issue.txt differs between two systems
Rpi’s one is
Raspberry Pi reference 2020-05-27
Generated using pi-gen, GitHub - RPi-Distro/pi-gen: Tool used to create the raspberrypi.org Raspbian images, 825107f04027269db77426046f5085475b1ea22f, stage2
My one
Raspberry Pi reference 2020-02-13
Generated using pi-gen, GitHub - RPi-Distro/pi-gen: Tool used to create the raspberrypi.org Raspbian images, 5f884374b6ac6e155330c58caa1fb7249b8badf1, stage4
Is it something to catch at?
Hi Serge, thank you for the tip with htop. It helped to understand that libasound.so.2.0.0 is taken from /usr/lib/arm-linux-gnueabihf/ not from /usr/lib where I installed it. It will be easier to debug with 'fprintf' as it works now.
Before adding debugging 'fprinf' I rerun 'perf' command with new libasound library. Here is the output of the 'perf report' which was taken during CPU spike (vlc is under python here):
The same report for CPU spike with 'mpd':
Before adding debugging 'fprinf' I rerun 'perf' command with new libasound library. Here is the output of the 'perf report' which was taken during CPU spike (vlc is under python here):
Code:
Overhead Command Shared Object Symbol
90.48% python3 libasound.so.2.0.0 [.] snd1_pcm_linear_convert
1.03% python3 libasound.so.2.0.0 [.] snd_pcm_area_copy
0.96% python3 libsamplerate.so.0.1.8 [.] 0x00002f9c
0.63% python3 libm-2.28.so [.] __lrintl
0.52% python3 libsamplerate.so.0.1.8 [.] 0x00003130
Code:
Overhead Command Shared Object Symbol
98.45% output:My ALSA libasound.so.2.0.0 [.] snd1_pcm_linear_convert
0.80% rtio libasound.so.2.0.0 [.] snd_pcm_area_copy
0.06% rtio libasound.so.2.0.0 [.] snd1_pcm_linear_convert
0.05% rtio libarmmem-v7l.so [.] memmove
0.05% decoder:mad mpd [.] 0x000a6db4
0.04% decoder:mad libmad.so.0.2.1 [.] 0x000071f0
Last edited:
Very good. I would suggest to printf the src_step, dst_step and frames parameters alsa-lib/pcm_linear.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub
Also I would check what pcm state the stream is when the CPU load is high - printf at the beginning of alsa-lib/pcm_meter.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub . My 2 cents the PCM state is SND_PCM_PAUSED, yet the conversion is being called, with the steps not advancing at alsa-lib/pcm_linear.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub
The conversions at alsa-lib/plugin_ops.h at master * alsa-project/alsa-lib * GitHub should never load CPU to max unless the pointer in the buffer is not advancing, causing infinite loop untill the pointer starts advancing.
Also I would check what pcm state the stream is when the CPU load is high - printf at the beginning of alsa-lib/pcm_meter.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub . My 2 cents the PCM state is SND_PCM_PAUSED, yet the conversion is being called, with the steps not advancing at alsa-lib/pcm_linear.c at 3ec6dce5198f100fa8dd2abfc1258fa4138ceb1a * alsa-project/alsa-lib * GitHub
The conversions at alsa-lib/plugin_ops.h at master * alsa-project/alsa-lib * GitHub should never load CPU to max unless the pointer in the buffer is not advancing, causing infinite loop untill the pointer starts advancing.