#137 horrific CPU usage with ALSA, sometimes

svn
closed-invalid
mpg123 (104)
5
2017-05-30
2010-05-04
No

There is some frikkin' strangeness with the ALSA output going on. Sometimes, you can get over 20% CPU load where the normal load would be around 2 or 3 %. Someone suggested that it's about triggering ALSA's resampling by some imprecise sample rate computation related to pitch change, but that seems rather unlikely as I verified that the rate given to ALSA doesn't have that influence.
Indeed, the normal resampling of ALSA does not eat _that_ much CPU. It is something else.

That is how you trigger it rather reliably:

1. Run mpg123 -C some_file
2. Pause/unpause playback some times and watch CPU usage.
3. At some point, restarting playback will get CPU usage high.
4. Observe how pausing/unpausing again might drop the CPU usage.

I guess a workaround might be to close/open the device instead of just not writing to it ... but then, there are also reports of large CPU usage to begin with. I did some profiling:

Excl. Incl. Name
User CPU User CPU
sec. sec.
58,047 58,047 <Total>
38,207 38,207 ioctl
3,860 3,860 III_dequantize_sample
2,475 3,805 synth_1to1
2,442 2,442 poll
1,705 1,705 mix_areas_32_smp
1,331 1,331 dct64
1,111 1,111 dct36
0,770 0,770 input_frames
0,693 1,089 softvol_convert_stereo_vol
0,517 39,164 snd_pcm_dmix_sync_ptr
0,462 14,297 snd_pcm_rate_avail_update
0,429 38,504 snd_pcm_hw_hwsync
0,407 13,802 snd_pcm_rate_hwsync
0,319 0,319 III_antialias
0,319 0,319 snd_pcm_format_little_endian
0,264 9,612 do_layer3
0,242 22,447 snd1_pcm_wait_nocheck
0,187 19,895 snd_pcm_plugin_avail_update
0,176 0,176 linear_expand
0,176 0,176 snd_pcm_hwsync
0,176 16,475 snd_pcm_rate_sync_playback_area
0,154 0,154 snd_pcm_avail_update
0,154 26,362 snd_pcm_dmix_avail_update
0,143 1,254 III_hybrid
0,143 47,852 snd1_pcm_write_areas
0,110 6,731 snd1_pcm_direct_poll_revents
0,088 0,088 snd_pcm_hw_state
0,077 0,077 III_get_scale_factors_1
0,077 1,815 snd_pcm_dmix_sync_area
0,077 0,077 snd_pcm_format_cpu_endian
0,066 0,066 snd_pcm_poll_descriptors_count
0,066 0,066 snd_pcm_poll_descriptors_revents
0,066 12,758 snd_pcm_rate_poll_revents
0,055 0,055 snd_pcm_poll_descriptors
0,044 0,176 snd_ctl_hw_elem_read
0,044 0,044 snd_pcm_dmix_hwsync
0,044 0,044 snd_pcm_wait
0,033 0,033 __read_nocancel
0,033 0,033 semop
0,033 0,033 snd1_pcm_generic_poll_descriptors

Well, one sees that the normal ALSA routines for resampling/mixing nicely competing for CPU time with the actual MPEG decoding, but they're not using ten times the CPU... that does ioctl() ... to see where from it's called:

Callers and callees sorted by metric: Attributed User CPU Time

Attr. Excl. Incl. Name
User CPU User CPU User CPU
sec. sec. sec.
38,075 0,429 38,504 snd_pcm_hw_hwsync
0,132 0,044 0,176 snd_ctl_hw_elem_read
38,207 38,207 38,207 *ioctl

So, the main caller is snd_pcm_hw_hwsync . Is this one expected to cause excessive CPU load? Is it going into overdrive mode because we introduced some undetermined pause between snd_pcm_write calls?

Discussion

  • Clemens Ladisch

    Clemens Ladisch - 2010-05-04

    What is the meaning of those numbers?

    snd_pcm_hw_hwsync is just a wrapper about a ioctl that reads the current sample position. How often is it called?

     
  • Thomas Orgis

    Thomas Orgis - 2010-05-04

    The first listing is a ranking of functions with their exclusive/inclusive CPU time in seconds. So, 65% of CPU time was spent inside this ioctl().

    The second shows the end of the call graph to that ioctl(). I am tracing it a bit further, taking the path that spent the most CPU time:

    ioctl() <- snd_pcm_hwsync() <- snd_pcm_dmix_sync_ptr()

    Hm... here there's 26 seconds for snd_pcm_dmix_avail_update() and 13 seconds for snd_pcm_rate_hwsync() ... it goes up through the ALSA infrastructure with one obvious point of entry:

    snd1_pcm_write_areas() <- snd_pcm_mmap_writei() <- write_alsa()

    mpg123's write_alsa() actually calls snd_pcm_writei(), which I assume to be mapped to snd_pcm_mmap_writei().

    I cannot extract a call count with this profiler, apparently. Well, mpg123 only calls write_alsa() for about each MPEG frame, so 1152 samples out of 44100 per second.

    I confirm that one can trigger this situation by repeatedly pausing/unpausing playback for some time. Once the high load is triggered, you apparently cannot un-trigger it (easily?) -- except for closing/reopening the ALSA output. Which, incidentally, is done when pressing 'w' which resets the hardware pitch (because of that someone suspected sample rate conversion being to blame).
    So I guess a workaround should be to really close/open the audio device on pause/unpause, but that shouldn't really be needed, or should it (as it also can cause disturbances in output, generally)?

     
  • Thomas Orgis

    Thomas Orgis - 2017-05-30
    • status: open --> closed-invalid
     
  • Thomas Orgis

    Thomas Orgis - 2017-05-30

    This is outside our realm and I didn't notice it for a long time. Closing.

     

Log in to post a comment.

Get latest updates about Open Source Projects, Conferences and News.

Sign up for the SourceForge newsletter:

JavaScript is required for this form.





No, thanks