[mpg123-devel] [ mpg123-Bugs-2996394 ] horrific CPU usage with ALSA, sometimes
Brought to you by:
sobukus
Menu
▾
▴
[mpg123-devel] [ mpg123-Bugs-2996394 ] horrific CPU usage with ALSA, sometimes
|
From: SourceForge.net <no...@so...> - 2011-06-25 18:34:19
|
Bugs item #2996394, was opened at 2010-05-04 07:35 Message generated for change (Comment added) made by nobody You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=733194&aid=2996394&group_id=135704 Please note that this message will contain a full copy of the comment thread, including the initial issue submission, for this request, not just the latest update. Category: mpg123 Group: svn Status: Open Resolution: None Priority: 5 Private: No Submitted By: Thomas Orgis (sobukus) Assigned to: Thomas Orgis (sobukus) Summary: horrific CPU usage with ALSA, sometimes Initial Comment: 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? ---------------------------------------------------------------------- Comment By: Nobody/Anonymous (nobody) Date: 2011-06-25 18:34 Message: lNao5o <a href="http://iggwujybqqmo.com/">iggwujybqqmo</a>, [url=http://sfmbybufljvw.com/]sfmbybufljvw[/url], [link=http://xxbkduqpxlvk.com/]xxbkduqpxlvk[/link], http://yoprzkrdbims.com/ ---------------------------------------------------------------------- Comment By: Thomas Orgis (sobukus) Date: 2010-05-04 14:39 Message: 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)? ---------------------------------------------------------------------- Comment By: Clemens Ladisch (cladisch) Date: 2010-05-04 13:23 Message: 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? ---------------------------------------------------------------------- You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=733194&aid=2996394&group_id=135704 |
