Uploaded image for project: ' AGL Development'
  1. AGL Development
  2. SPEC-3051

Audio popping on RaspberryPi 3/4

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Inactive
    • Icon: Minor Minor
    • None
    • Halibut 8.0.3, Icefish 8.99.2, master
    • Multimedia
    • Raspberry Pi 3, Raspberry Pi 4

      During regular testing on any branch that has working audio on Raspberry boards -  either 3 or 4 - slight popping artefacts are observed while playing either local files using Media Player or streaming music over Bluetooth.

      No crashing services are observed. The logs below are taken from the testing cycle for Icefish RC2.

      Pasting the pipewire@1001.service output from journalctl below since it is a relatively short log: 

      -- Logs begin at Fri 2019-12-06 22:33:25 UTC, end at Thu 2019-12-12 10:54:18 UTC. --
      Dec 12 10:18:58 raspberrypi3 systemd[1]: Started Multimedia Service for user 1001.
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000098.741160][connection.c:151 connection_ensure_size()] connection 0x1ed3898: resize buffer to 30472 4112 65536
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000098.776691][connection.c:151 connection_ensure_size()] connection 0xb7efc0: resize buffer to 28808 4112 65536
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000098.790615][connection.c:151 connection_ensure_size()] connection 0xb7efc0: resize buffer to 32768 2296 65536
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000098.805403][connection.c:151 connection_ensure_size()] connection 0xb7efc0: resize buffer to 61512 4112 98304
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000098.847433][connection.c:151 connection_ensure_size()] connection 0x1ed3898: resize buffer to 32768 208 65536
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000098.886216][connection.c:151 connection_ensure_size()] connection 0x1ed3898: resize buffer to 65536 2488 98304
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000098.932501][connection.c:151 connection_ensure_size()] connection 0xb6c608: resize buffer to 28720 4112 65536
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000098.947805][connection.c:151 connection_ensure_size()] connection 0xb6c608: resize buffer to 61480 4112 98304
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000098.953793][connection.c:151 connection_ensure_size()] connection 0xb7efc0: resize buffer to 94336 4112 131072
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000099.290147][connection.c:151 connection_ensure_size()] connection 0x1ed3898: resize buffer to 98304 264 131072
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000099.318805][connection.c:151 connection_ensure_size()] connection 0xb7efc0: resize buffer to 127264 4112 163840
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000099.321734][connection.c:151 connection_ensure_size()] connection 0xb7efc0: resize buffer to 160136 4112 196608
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000099.337721][connection.c:151 connection_ensure_size()] connection 0x1ed3898: resize buffer to 131072 512 163840
      Dec 12 10:18:59 raspberrypi3 pipewire[931]: [W][000000099.342255][connection.c:151 connection_ensure_size()] connection 0x1ed3898: resize buffer to 163840 512 196608
      Dec 12 10:26:44 raspberrypi3 pipewire[931]: [E][000000563.702744][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 3591 usec 172 0.000000
      Dec 12 10:31:33 raspberrypi3 pipewire[931]: [E][000000852.989500][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 10388 usec 498 0.000000
      Dec 12 10:32:32 raspberrypi3 pipewire[931]: [E][000000912.344254][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 5192 usec 249 0.000000
      Dec 12 10:32:33 raspberrypi3 pipewire[931]: [E][000000913.459685][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 617 usec 29 0.000000
      Dec 12 10:32:38 raspberrypi3 pipewire[931]: [E][000000918.101271][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 2227 usec 106 0.000000
      Dec 12 10:32:42 raspberrypi3 pipewire[931]: [E][000000921.780926][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 1858 usec 89 0.000000
      Dec 12 10:32:42 raspberrypi3 pipewire[931]: [E][000000922.102985][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 3939 usec 189 0.000000
      Dec 12 10:32:43 raspberrypi3 pipewire[931]: [E][000000922.739955][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 902 usec 43 0.000000
      Dec 12 10:34:00 raspberrypi3 pipewire[931]: [E][000000999.709390][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 10301 usec 494 0.000000
      Dec 12 10:34:00 raspberrypi3 pipewire[931]: [E][000001000.539759][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 10704 usec 513 0.000000
      Dec 12 10:34:01 raspberrypi3 pipewire[931]: [E][000001000.718279][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 25 usec 1 0.000000
      Dec 12 10:34:01 raspberrypi3 pipewire[931]: [E][000001001.422155][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 3109 usec 149 0.000000
      Dec 12 10:34:07 raspberrypi3 pipewire[931]: [E][000001007.513351][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 4293 usec 206 0.000000
      Dec 12 10:34:08 raspberrypi3 pipewire[931]: [E][000001007.797653][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 22 usec 1 0.000000
      Dec 12 10:34:08 raspberrypi3 pipewire[931]: [E][000001008.017679][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 25 usec 1 0.000000
      Dec 12 10:34:08 raspberrypi3 pipewire[931]: [E][000001008.237661][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 23 usec 1 0.000000
      Dec 12 10:34:13 raspberrypi3 pipewire[931]: [E][000001012.656994][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 7919 usec 380 0.000000
      Dec 12 10:34:14 raspberrypi3 pipewire[931]: [E][000001013.636899][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 7855 usec 377 0.000000
      Dec 12 10:34:14 raspberrypi3 pipewire[931]: [E][000001013.867612][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 8560 usec 410 0.000000
      Dec 12 10:34:15 raspberrypi3 pipewire[931]: [E][000001014.987092][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 25 usec 1 0.000000
      Dec 12 10:34:15 raspberrypi3 pipewire[931]: [E][000001015.217628][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 8578 usec 411 0.000000
      Dec 12 10:34:15 raspberrypi3 pipewire[931]: [E][000001015.437717][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 27 usec 1 0.000000
      Dec 12 10:34:16 raspberrypi3 pipewire[931]: [E][000001015.657704][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 24 usec 1 0.000000
      Dec 12 10:34:38 raspberrypi3 pipewire[931]: [E][000001037.627012][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 7928 usec 380 0.000000
      Dec 12 10:34:50 raspberrypi3 pipewire[931]: [E][000001050.107038][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 25 usec 1 0.000000
      Dec 12 10:34:50 raspberrypi3 pipewire[931]: [E][000001050.348363][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 9281 usec 445 0.000000
      Dec 12 10:34:53 raspberrypi3 pipewire[931]: [E][000001053.322878][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 23 usec 1 0.000000
      Dec 12 10:34:55 raspberrypi3 pipewire[931]: [E][000001054.634256][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 5207 usec 249 0.000000
      Dec 12 10:35:00 raspberrypi3 pipewire[931]: [E][000001059.756146][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 7078 usec 339 0.000000
      Dec 12 10:35:01 raspberrypi3 pipewire[931]: [E][000001060.747052][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 24 usec 1 0.000000
      Dec 12 10:35:01 raspberrypi3 pipewire[931]: [E][000001060.978316][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 9255 usec 444 0.000000
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.703487][node.c:1328 node_ready()] node 0xba9310: graph not finished
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.703575][node.c:802 dump_states()] node 0xbd39a8 (audio.convert/api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA/Communication): pending:2/3 s:1239673245873 a:1239673300039 f:1239673346706 waiting:54166 process:46667 status:0 sync:0
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.703612][node.c:802 dump_states()] node 0xba9310 (api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA): pending:4/6 s:1239673083373 a:1239673347800 f:1239695868733 waiting:264427 process:22520933 status:3 sync:0
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.703646][node.c:802 dump_states()] node 0xba9310 (api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA): pending:4/6 s:1239673083373 a:1239673347800 f:1239695868733 waiting:264427 process:22520933 status:3 sync:0
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.703681][node.c:802 dump_states()] node 0xccf1e0 (bluealsa-gst-he): pending:0/1 s:1239695872483 a:1239673167748 f:1239673243738 waiting:18446744073686846881 process:75990 status:1 sync:0
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.884496][node.c:1328 node_ready()] node 0xba9310: graph not finished
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.884586][node.c:802 dump_states()] node 0xbd39a8 (audio.convert/api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA/Communication): pending:0/3 s:1239698284716 a:1239698506122 f:1239698528518 waiting:221406 process:22396 status:3 sync:0
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.884624][node.c:802 dump_states()] node 0xba9310 (api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA): pending:-3/6 s:1239698110706 a:1239698361123 f:1239698491695 waiting:250417 process:130572 status:3 sync:0
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.884660][node.c:802 dump_states()] node 0xba9310 (api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA): pending:-3/6 s:1239698110706 a:1239698361123 f:1239698491695 waiting:250417 process:130572 status:3 sync:0
      Dec 12 10:38:00 raspberrypi3 pipewire[931]: [W][000001239.884697][node.c:802 dump_states()] node 0xccf1e0 (bluealsa-gst-he): pending:0/1 s:1239698113363 a:1239698234508 f:1239698283519 waiting:121145 process:49011 status:3 sync:0
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [E][000001539.702876][alsa-pcm.c:568 alsa_recover()] alsa-pcm 0xb96fbc: xrun of 112 usec 5 0.000000
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.703472][node.c:1328 node_ready()] node 0xba9310: graph not finished
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.703529][node.c:802 dump_states()] node 0xbd39a8 (audio.convert/api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA/Communication): pending:2/3 s:1539666893544 a:1539666931617 f:1539666977242 waiting:38073 process:45625 status:0 sync:0
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.703569][node.c:802 dump_states()] node 0xba9310 (api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA): pending:4/6 s:1539666737242 a:1539667026409 f:1539695395395 waiting:289167 process:28368986 status:3 sync:0
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.703602][node.c:802 dump_states()] node 0xba9310 (api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA): pending:4/6 s:1539666737242 a:1539667026409 f:1539695395395 waiting:289167 process:28368986 status:3 sync:0
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.703638][node.c:802 dump_states()] node 0xccf1e0 (bluealsa-gst-he): pending:0/1 s:1539695399353 a:1539666811617 f:1539666891930 waiting:18446744073680963880 process:80313 status:1 sync:0
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.910970][node.c:1328 node_ready()] node 0xba9310: graph not finished
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.911057][node.c:802 dump_states()] node 0xbd39a8 (audio.convert/api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA/Communication): pending:0/3 s:1539697574976 a:1539697792997 f:1539697821799 waiting:218021 process:28802 status:3 sync:0
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.911094][node.c:802 dump_states()] node 0xba9310 (api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA): pending:-3/6 s:1539697359299 a:1539697639716 f:1539697778674 waiting:280417 process:138958 status:3 sync:0
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.911128][node.c:802 dump_states()] node 0xba9310 (api.alsa.pcm.sink/alsa_card.platform-soc:audio/bcm2835 ALSA): pending:-3/6 s:1539697359299 a:1539697639716 f:1539697778674 waiting:280417 process:138958 status:3 sync:0
      Dec 12 10:43:00 raspberrypi3 pipewire[931]: [W][000001539.911163][node.c:802 dump_states()] node 0xccf1e0 (bluealsa-gst-he): pending:0/1 s:1539697362945 a:1539697512372 f:1539697573414 waiting:149427 process:61042 status:3 sync:0
      

       Attaching dmesg and full journal for additional info

        1. dmesg.raspberrypi3.txt
          31 kB
          Edi Feschiyan
        2. journal.raspberrypi3.txt
          311 kB
          Edi Feschiyan
        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

            gkiagia Georgios Kiagiadakis
            edi.feschiyan Edi Feschiyan
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: