Pulseeffects: Jamming/stuttering during playback from the Chromium
Usually when I switch work-spaces, refresh web-pages, some other CPU-loading tasks, but sometimes when no activity at all. But resources are OK:
External USB sound-card (more often) and integrated into motherboard (less often).
(UPD: Now for integrated it occurs as often as for external)
Settings (only Bass Enhancer is enabled):
AlexWayfer
All 84 comments
Run PE in debug mode PULSEEFFECTS_DEBUG=1 pulseeffects and paste its output here. Maybe some clues are printed when the stuttering happens
wwmm
on 30 May 2018
~ > env PULSEEFFECTS_DEBUG=1 pulseeffects
17:18:25.199 - PulseEffects - DEBUG - MAIN - debug logging enabled
17:18:25.239 - PulseEffects - DEBUG - PM - pulseaudio context is connecting
17:18:25.240 - PulseEffects - DEBUG - PM - pulseaudio context is authorizing
17:18:25.240 - PulseEffects - DEBUG - PM - pulseaudio context is setting name
17:18:25.241 - PulseEffects - DEBUG - PM - pulseaudio context is ready
17:18:25.241 - PulseEffects - DEBUG - PM - connected to server: unix:/run/user/1000/pulse/native
17:18:25.241 - PulseEffects - DEBUG - PM - server protocol version: 32
17:18:25.242 - PulseEffects - DEBUG - PM - pulseaudio version: 11.1
17:18:25.242 - PulseEffects - DEBUG - PM - default pulseaudio source: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
17:18:25.242 - PulseEffects - DEBUG - PM - default pulseaudio sink: alsa_output.pci-0000_00_1b.0.analog-stereo
17:18:25.242 - PulseEffects - DEBUG - PM - default pulseaudio sink audio format: s16le
17:18:25.242 - PulseEffects - DEBUG - PM - default pulseaudio sink sampling rate: 44100 Hz. We will use the same rate.
17:18:25.243 - PulseEffects - DEBUG - PM - default pulseaudio source audio format: s16le
17:18:25.243 - PulseEffects - DEBUG - PM - default pulseaudio source sampling rate: 44100 Hz. We will use the same rate.
17:18:25.243 - PulseEffects - DEBUG - PM - loading Pulseeffects applications sink...
17:18:25.243 - PulseEffects - DEBUG - PM - Pulseeffects apps sink was successfully loaded
17:18:25.243 - PulseEffects - DEBUG - PM - Pulseeffects apps sink index:3
17:18:25.243 - PulseEffects - DEBUG - PM - Pulseeffects apps sink monitor name: PulseEffects_apps.monitor
17:18:25.243 - PulseEffects - DEBUG - PM - loading Pulseeffects microphone output sink...
17:18:25.244 - PulseEffects - DEBUG - PM - Pulseeffects mic sink was successfully loaded
17:18:25.244 - PulseEffects - DEBUG - PM - Pulseeffects mic sink index:4
17:18:25.244 - PulseEffects - DEBUG - PM - Pulseeffects mic sink monitor name: PulseEffects_mic.monitor
17:18:25.277 - PulseEffects - WARNING - Delay plugin was not found. Disabling it!
17:18:25.282 - PulseEffects - WARNING - Maximizer plugin was not found. Disabling it!
17:18:25.284 - PulseEffects - DEBUG - SIE - limiter wrapper was enabled
17:18:25.284 - PulseEffects - DEBUG - SIE - compressor wrapper was enabled
17:18:25.284 - PulseEffects - DEBUG - SIE - highpass wrapper was enabled
17:18:25.284 - PulseEffects - DEBUG - SIE - lowpass wrapper was enabled
17:18:25.284 - PulseEffects - DEBUG - SIE - equalizer wrapper was enabled
17:18:25.284 - PulseEffects - DEBUG - SIE - bass enhancer wrapper was enabled
17:18:25.285 - PulseEffects - DEBUG - SIE - exciter wrapper was enabled
17:18:25.285 - PulseEffects - DEBUG - SIE - stereo enhancer wrapper was enabled
17:18:25.285 - PulseEffects - DEBUG - SIE - panorama wrapper was enabled
17:18:25.285 - PulseEffects - DEBUG - SIE - stereo spread wrapper was enabled
17:18:25.285 - PulseEffects - DEBUG - SIE - reverb wrapper was enabled
17:18:25.285 - PulseEffects - DEBUG - SIE - crossfeed wrapper was enabled
17:18:25.285 - PulseEffects - DEBUG - SIE - delay wrapper was enabled
17:18:25.286 - PulseEffects - DEBUG - SIE - maximizer wrapper was enabled
17:18:25.286 - PulseEffects - DEBUG - SIE - output limiter wrapper was enabled
17:18:25.286 - PulseEffects - DEBUG - SIE - spectrum wrapper was enabled
17:18:25.291 - PulseEffects - WARNING - Pitch plugin was not found. Disabling it!
17:18:25.302 - PulseEffects - DEBUG - SOE - gate wrapper was enabled
17:18:25.302 - PulseEffects - DEBUG - SOE - webrtc wrapper was enabled
17:18:25.302 - PulseEffects - DEBUG - SOE - limiter wrapper was enabled
17:18:25.302 - PulseEffects - DEBUG - SOE - compressor wrapper was enabled
17:18:25.302 - PulseEffects - DEBUG - SOE - highpass wrapper was enabled
17:18:25.302 - PulseEffects - DEBUG - SOE - lowpass wrapper was enabled
17:18:25.303 - PulseEffects - DEBUG - SOE - equalizer wrapper was enabled
17:18:25.303 - PulseEffects - DEBUG - SOE - deesser wrapper was enabled
17:18:25.303 - PulseEffects - DEBUG - SOE - reverb wrapper was enabled
17:18:25.303 - PulseEffects - DEBUG - SOE - pitch wrapper was enabled
17:18:25.303 - PulseEffects - DEBUG - SOE - spectrum wrapper was enabled
17:18:25.503 - PulseEffects - DEBUG - SIE - bass enhancer bin was enabled
17:18:25.743 - PulseEffects - DEBUG - MAIN - autostart_file created successfully
17:18:25.770 - PulseEffects - DEBUG - MAIN - using default sink
17:18:25.770 - PulseEffects - DEBUG - MAIN - using default source
17:18:26.87 - PulseEffects - DEBUG - MAIN - added sink: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo
17:18:26.88 - PulseEffects - DEBUG - MAIN - added sink: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo.equalizer
17:18:26.88 - PulseEffects - DEBUG - MAIN - added sink: alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1
17:18:26.88 - PulseEffects - DEBUG - MAIN - added sink: alsa_output.pci-0000_00_1b.0.analog-stereo
17:18:26.89 - PulseEffects - DEBUG - MAIN - output device changed: alsa_output.pci-0000_00_1b.0.analog-stereo
17:18:26.89 - PulseEffects - DEBUG - MAIN - added source: alsa_input.pci-0000_00_1b.0.analog-stereo
17:18:26.89 - PulseEffects - DEBUG - MAIN - added source: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo.monitor
17:18:26.90 - PulseEffects - DEBUG - MAIN - added source: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
17:18:26.90 - PulseEffects - DEBUG - MAIN - input device changed: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
17:18:26.90 - PulseEffects - DEBUG - MAIN - added source: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo.equalizer.monitor
17:18:26.91 - PulseEffects - DEBUG - MAIN - input device changed: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
17:18:26.91 - PulseEffects - DEBUG - MAIN - added source: alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1.monitor
17:18:26.91 - PulseEffects - DEBUG - MAIN - input device changed: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
17:18:26.92 - PulseEffects - DEBUG - MAIN - added source: alsa_output.pci-0000_00_1b.0.analog-stereo.monitor
17:18:26.92 - PulseEffects - DEBUG - MAIN - input device changed: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
17:18:26.106 - PulseEffects - DEBUG - SIE - pipeline state: playing
17:18:26.106 - PulseEffects - DEBUG - PM - volume meter stream for app 342 is being created
17:18:26.106 - PulseEffects - DEBUG - PM - volume meter stream for app 342 is ready
17:18:26.108 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
17:18:26.109 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
17:18:26.137 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
17:18:26.137 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
17:18:42.696 - PulseEffects - DEBUG - PM - volume meter stream for app 345 is being created
17:18:42.696 - PulseEffects - DEBUG - PM - volume meter stream for app 345 is ready
17:18:42.707 - PulseEffects - DEBUG - PM - volume meter stream for app 346 is being created
17:18:42.707 - PulseEffects - DEBUG - PM - volume meter stream for app 346 is ready
17:18:42.736 - PulseEffects - DEBUG - PM - volume meter stream for app 346 was terminated
17:18:42.736 - PulseEffects - DEBUG - PM - volume meter stream for app 345 was terminated
17:18:57.10 - PulseEffects - DEBUG - PM - volume meter stream for app 347 is being created
17:18:57.11 - PulseEffects - DEBUG - PM - volume meter stream for app 347 is ready
17:18:57.43 - PulseEffects - DEBUG - PM - volume meter stream for app 348 is being created
17:18:57.43 - PulseEffects - DEBUG - PM - volume meter stream for app 348 is ready
17:18:57.73 - PulseEffects - DEBUG - PM - volume meter stream for app 349 is being created
17:18:57.73 - PulseEffects - DEBUG - PM - volume meter stream for app 349 is ready
17:18:57.83 - PulseEffects - DEBUG - PM - volume meter stream for app 348 was terminated
17:18:57.87 - PulseEffects - DEBUG - PM - volume meter stream for app 347 was terminated
17:18:57.88 - PulseEffects - DEBUG - PM - volume meter stream for app 348 is being created
17:18:57.88 - PulseEffects - DEBUG - PM - volume meter stream for app 348 is ready
17:18:57.117 - PulseEffects - DEBUG - PM - volume meter stream for app 349 was terminated
17:18:57.120 - PulseEffects - DEBUG - PM - volume meter stream for app 348 has failed. Did you disable this app ?
17:18:57.139 - PulseEffects - DEBUG - PM - volume meter stream for app 347 is being created
17:18:57.139 - PulseEffects - DEBUG - PM - volume meter stream for app 347 is ready
17:18:57.147 - PulseEffects - DEBUG - PM - volume meter stream for app 347 was terminated
17:19:36.429 - PulseEffects - DEBUG - PM - volume meter stream for app 351 is being created
17:19:36.429 - PulseEffects - DEBUG - PM - volume meter stream for app 351 is ready
17:19:36.432 - PulseEffects - DEBUG - PM - volume meter stream for app 351 was terminated
17:19:36.478 - PulseEffects - DEBUG - PM - volume meter stream for app 351 is being created
17:19:36.478 - PulseEffects - DEBUG - PM - volume meter stream for app 351 is ready
17:19:36.483 - PulseEffects - DEBUG - PM - volume meter stream for app 351 was terminated
17:19:36.528 - PulseEffects - DEBUG - PM - volume meter stream for app 351 is being created
17:19:36.529 - PulseEffects - DEBUG - PM - volume meter stream for app 351 is ready
17:19:36.534 - PulseEffects - DEBUG - PM - volume meter stream for app 351 was terminated
17:26:48.190 - PulseEffects - DEBUG - PM - volume meter stream for app 353 is being created
17:26:48.191 - PulseEffects - DEBUG - PM - volume meter stream for app 353 is ready
17:26:49.851 - PulseEffects - DEBUG - PM - volume meter stream for app 353 was terminated
17:35:39.290 - PulseEffects - DEBUG - PM - volume meter stream for app 354 is being created
17:35:39.290 - PulseEffects - DEBUG - PM - volume meter stream for app 354 is ready
17:35:39.312 - PulseEffects - DEBUG - PM - volume meter stream for app 355 is being created
17:35:39.312 - PulseEffects - DEBUG - PM - volume meter stream for app 355 is ready
17:35:39.319 - PulseEffects - DEBUG - PM - volume meter stream for app 355 was terminated
17:35:39.321 - PulseEffects - DEBUG - PM - volume meter stream for app 354 was terminated
17:35:44.87 - PulseEffects - DEBUG - PM - volume meter stream for app 354 is being created
17:35:44.88 - PulseEffects - DEBUG - PM - volume meter stream for app 354 is ready
17:35:44.90 - PulseEffects - DEBUG - PM - volume meter stream for app 355 is being created
17:35:44.91 - PulseEffects - DEBUG - PM - volume meter stream for app 355 is ready
17:35:54.94 - PulseEffects - DEBUG - PM - volume meter stream for app 354 was terminated
17:35:54.95 - PulseEffects - DEBUG - PM - volume meter stream for app 355 was terminated
17:36:01.420 - PulseEffects - DEBUG - PM - volume meter stream for app 354 is being created
17:36:01.420 - PulseEffects - DEBUG - PM - volume meter stream for app 354 is ready
17:36:01.435 - PulseEffects - DEBUG - PM - volume meter stream for app 355 is being created
17:36:01.435 - PulseEffects - DEBUG - PM - volume meter stream for app 355 is ready
17:36:02.89 - PulseEffects - DEBUG - PM - volume meter stream for app 355 was terminated
17:36:02.90 - PulseEffects - DEBUG - PM - volume meter stream for app 354 was terminated
17:36:02.748 - PulseEffects - DEBUG - PM - volume meter stream for app 354 is being created
17:36:02.748 - PulseEffects - DEBUG - PM - volume meter stream for app 354 is ready
17:36:02.750 - PulseEffects - DEBUG - PM - volume meter stream for app 355 is being created
17:36:02.751 - PulseEffects - DEBUG - PM - volume meter stream for app 355 is ready
17:36:12.752 - PulseEffects - DEBUG - PM - volume meter stream for app 355 was terminated
17:36:12.754 - PulseEffects - DEBUG - PM - volume meter stream for app 354 was terminated
17:37:10.890 - PulseEffects - DEBUG - PM - volume meter stream for app 356 is being created
17:37:10.890 - PulseEffects - DEBUG - PM - volume meter stream for app 356 is ready
17:37:10.918 - PulseEffects - DEBUG - PM - volume meter stream for app 357 is being created
17:37:10.918 - PulseEffects - DEBUG - PM - volume meter stream for app 357 is ready
17:37:10.920 - PulseEffects - DEBUG - PM - volume meter stream for app 357 was terminated
17:37:10.928 - PulseEffects - DEBUG - PM - volume meter stream for app 356 was terminated
Start at 17:18:25.
Strong lags at 17:18:42, 17:18:57 and 17:19:36. Just intensively switching Chromium tabs, refresh pages and start Atom Editor.
Later there can be small lags during to regular computer usage (and music listening).
AlexWayfer
on 30 May 2018
18:05:37.131 - PulseEffects - DEBUG - PM - pulseaudio version: 11.1
18:05:37.131 - PulseEffects - DEBUG - PM - default pulseaudio source: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
18:05:37.131 - PulseEffects - DEBUG - PM - default pulseaudio sink: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo
18:05:37.132 - PulseEffects - DEBUG - MAIN - output device changed: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo
18:05:37.136 - PulseEffects - DEBUG - PM - volume meter stream for app 364 has failed. Did you disable this app ?
18:05:37.162 - PulseEffects - DEBUG - SIE - pipeline state: null
18:06:43.694 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:06:43.694 - PulseEffects - DEBUG - PM - volume meter stream for app 368 is being created
18:06:43.695 - PulseEffects - DEBUG - PM - volume meter stream for app 368 is ready
18:06:43.703 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:06:43.703 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:06:43.706 - PulseEffects - DEBUG - PM - volume meter stream for app 368 has failed. Did you disable this app ?
18:06:43.718 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:06:43.718 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:06:48.699 - PulseEffects - DEBUG - SIE - pipeline state: null
18:08:58.262 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:08:58.263 - PulseEffects - DEBUG - PM - volume meter stream for app 373 is being created
18:08:58.263 - PulseEffects - DEBUG - PM - volume meter stream for app 373 is ready
18:08:58.263 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:08:58.264 - PulseEffects - DEBUG - PM - volume meter stream for app 372 is being created
18:08:58.264 - PulseEffects - DEBUG - PM - volume meter stream for app 372 is ready
18:08:58.264 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:08:58.264 - PulseEffects - DEBUG - PM - volume meter stream for app 373 was terminated
18:08:58.265 - PulseEffects - DEBUG - PM - volume meter stream for app 372 was terminated
18:08:58.267 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:08:58.267 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:08:58.273 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:08:58.273 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:08:59.402 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:08:59.402 - PulseEffects - DEBUG - PM - volume meter stream for app 372 is being created
18:08:59.402 - PulseEffects - DEBUG - PM - volume meter stream for app 372 is ready
18:08:59.405 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:08:59.418 - PulseEffects - DEBUG - PM - volume meter stream for app 373 is being created
18:08:59.419 - PulseEffects - DEBUG - PM - volume meter stream for app 373 is ready
18:08:59.421 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:08:59.421 - PulseEffects - DEBUG - PM - volume meter stream for app 373 was terminated
18:08:59.421 - PulseEffects - DEBUG - PM - volume meter stream for app 372 was terminated
18:09:00.404 - PulseEffects - DEBUG - PM - volume meter stream for app 372 is being created
18:09:00.406 - PulseEffects - DEBUG - PM - volume meter stream for app 372 is ready
18:09:00.406 - PulseEffects - DEBUG - PM - volume meter stream for app 373 is being created
18:09:00.408 - PulseEffects - DEBUG - PM - volume meter stream for app 373 is ready
18:09:00.596 - PulseEffects - DEBUG - PM - volume meter stream for app 376 is being created
18:09:00.597 - PulseEffects - DEBUG - PM - volume meter stream for app 376 is ready
18:09:00.608 - PulseEffects - DEBUG - PM - volume meter stream for app 377 is being created
18:09:00.609 - PulseEffects - DEBUG - PM - volume meter stream for app 377 is ready
18:09:00.610 - PulseEffects - DEBUG - PM - volume meter stream for app 376 was terminated
18:09:02.200 - PulseEffects - DEBUG - PM - volume meter stream for app 376 is being created
18:09:02.201 - PulseEffects - DEBUG - PM - volume meter stream for app 376 is ready
18:09:02.203 - PulseEffects - DEBUG - PM - volume meter stream for app 377 is being created
18:09:02.203 - PulseEffects - DEBUG - PM - volume meter stream for app 377 is ready
18:09:10.408 - PulseEffects - DEBUG - PM - volume meter stream for app 373 was terminated
18:09:10.411 - PulseEffects - DEBUG - PM - volume meter stream for app 372 was terminated
18:09:12.209 - PulseEffects - DEBUG - PM - volume meter stream for app 377 was terminated
18:09:12.212 - PulseEffects - DEBUG - SIE - pipeline state: null
18:09:12.213 - PulseEffects - DEBUG - PM - volume meter stream for app 376 was terminated
18:09:17.231 - PulseEffects - DEBUG - PM - volume meter stream for app 377 has failed. Did you disable this app ?
18:13:43.794 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:13:43.794 - PulseEffects - DEBUG - PM - volume meter stream for app 378 is being created
18:13:43.795 - PulseEffects - DEBUG - PM - volume meter stream for app 378 is ready
18:13:43.800 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:13:43.800 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:13:43.800 - PulseEffects - DEBUG - PM - volume meter stream for app 379 is being created
18:13:43.800 - PulseEffects - DEBUG - PM - volume meter stream for app 379 is ready
18:13:43.801 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:13:43.802 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:13:43.804 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:13:43.804 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:13:46.810 - PulseEffects - DEBUG - PM - volume meter stream for app 382 is being created
18:13:46.811 - PulseEffects - DEBUG - PM - volume meter stream for app 382 is ready
18:13:46.816 - PulseEffects - DEBUG - PM - volume meter stream for app 383 is being created
18:13:46.816 - PulseEffects - DEBUG - PM - volume meter stream for app 383 is ready
18:13:53.789 - PulseEffects - DEBUG - PM - volume meter stream for app 378 was terminated
18:13:53.812 - PulseEffects - DEBUG - PM - volume meter stream for app 379 was terminated
18:13:55.826 - PulseEffects - DEBUG - PM - volume meter stream for app 378 is being created
18:13:55.827 - PulseEffects - DEBUG - PM - volume meter stream for app 378 is ready
18:13:55.828 - PulseEffects - DEBUG - PM - volume meter stream for app 379 is being created
18:13:55.828 - PulseEffects - DEBUG - PM - volume meter stream for app 379 is ready
18:13:56.809 - PulseEffects - DEBUG - PM - volume meter stream for app 383 was terminated
18:13:56.830 - PulseEffects - DEBUG - PM - volume meter stream for app 382 was terminated
18:14:05.829 - PulseEffects - DEBUG - PM - volume meter stream for app 379 was terminated
18:14:05.833 - PulseEffects - DEBUG - SIE - pipeline state: null
18:14:05.833 - PulseEffects - DEBUG - PM - volume meter stream for app 378 was terminated
18:14:27.855 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:14:27.856 - PulseEffects - DEBUG - PM - volume meter stream for app 384 is being created
18:14:27.856 - PulseEffects - DEBUG - PM - volume meter stream for app 384 is ready
18:14:27.858 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:14:27.858 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:14:27.862 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:14:27.862 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:14:27.919 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:14:27.924 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:14:27.924 - PulseEffects - DEBUG - PM - volume meter stream for app 387 is being created
18:14:27.924 - PulseEffects - DEBUG - PM - volume meter stream for app 387 is ready
18:14:37.857 - PulseEffects - DEBUG - PM - volume meter stream for app 384 was terminated
18:14:37.943 - PulseEffects - DEBUG - SIE - pipeline state: null
18:14:37.943 - PulseEffects - DEBUG - PM - volume meter stream for app 387 was terminated
18:14:51.497 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:14:51.497 - PulseEffects - DEBUG - PM - volume meter stream for app 388 is being created
18:14:51.498 - PulseEffects - DEBUG - PM - volume meter stream for app 388 is ready
18:14:51.501 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:14:51.501 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:14:51.501 - PulseEffects - DEBUG - PM - volume meter stream for app 389 is being created
18:14:51.502 - PulseEffects - DEBUG - PM - volume meter stream for app 389 is ready
18:14:51.508 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:14:51.508 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:14:51.508 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:14:51.508 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:14:51.516 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:14:51.516 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:15:01.487 - PulseEffects - DEBUG - PM - volume meter stream for app 389 was terminated
18:15:01.504 - PulseEffects - DEBUG - SIE - pipeline state: null
18:15:01.505 - PulseEffects - DEBUG - PM - volume meter stream for app 388 was terminated
18:15:06.286 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:15:06.286 - PulseEffects - DEBUG - PM - volume meter stream for app 388 is being created
18:15:06.287 - PulseEffects - DEBUG - PM - volume meter stream for app 388 is ready
18:15:06.289 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:15:06.289 - PulseEffects - DEBUG - PM - volume meter stream for app 389 is being created
18:15:06.289 - PulseEffects - DEBUG - PM - volume meter stream for app 389 is ready
18:15:06.290 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:15:06.290 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:15:06.294 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:15:06.294 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:15:16.303 - PulseEffects - DEBUG - PM - volume meter stream for app 388 was terminated
18:15:16.319 - PulseEffects - DEBUG - SIE - pipeline state: null
18:15:16.320 - PulseEffects - DEBUG - PM - volume meter stream for app 389 was terminated
18:16:27.820 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:16:27.821 - PulseEffects - DEBUG - PM - volume meter stream for app 394 is being created
18:16:27.821 - PulseEffects - DEBUG - PM - volume meter stream for app 394 is ready
18:16:27.824 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:16:27.829 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:16:27.830 - PulseEffects - DEBUG - PM - volume meter stream for app 395 is being created
18:16:27.830 - PulseEffects - DEBUG - PM - volume meter stream for app 395 is ready
18:16:27.831 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:16:27.831 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:16:27.831 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:16:27.831 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:16:37.811 - PulseEffects - DEBUG - PM - volume meter stream for app 395 was terminated
18:16:37.829 - PulseEffects - DEBUG - SIE - pipeline state: null
18:16:37.830 - PulseEffects - DEBUG - PM - volume meter stream for app 394 was terminated
18:29:01.902 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:29:01.902 - PulseEffects - DEBUG - PM - volume meter stream for app 398 is being created
18:29:01.902 - PulseEffects - DEBUG - PM - volume meter stream for app 398 is ready
18:29:01.911 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:29:01.914 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:29:01.932 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:29:01.933 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:29:01.933 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:29:01.936 - PulseEffects - DEBUG - PM - volume meter stream for app 398 was terminated
18:29:03.243 - PulseEffects - DEBUG - PM - volume meter stream for app 398 is being created
18:29:03.243 - PulseEffects - DEBUG - PM - volume meter stream for app 398 is ready
18:29:03.245 - PulseEffects - DEBUG - PM - volume meter stream for app 399 is being created
18:29:03.246 - PulseEffects - DEBUG - PM - volume meter stream for app 399 is ready
18:29:03.247 - PulseEffects - DEBUG - PM - volume meter stream for app 399 was terminated
18:29:03.250 - PulseEffects - DEBUG - SIE - pipeline state: null
18:29:03.259 - PulseEffects - DEBUG - PM - volume meter stream for app 398 was terminated
18:29:04.948 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:29:04.948 - PulseEffects - DEBUG - PM - volume meter stream for app 398 is being created
18:29:04.948 - PulseEffects - DEBUG - PM - volume meter stream for app 398 is ready
18:29:04.950 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:29:04.951 - PulseEffects - DEBUG - PM - volume meter stream for app 399 is being created
18:29:04.951 - PulseEffects - DEBUG - PM - volume meter stream for app 399 is ready
18:29:04.952 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:29:04.952 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:29:04.956 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:29:04.956 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:29:14.963 - PulseEffects - DEBUG - PM - volume meter stream for app 399 was terminated
18:29:14.975 - PulseEffects - DEBUG - SIE - pipeline state: null
18:29:14.975 - PulseEffects - DEBUG - PM - volume meter stream for app 398 was terminated
18:29:38.957 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:29:38.958 - PulseEffects - DEBUG - PM - volume meter stream for app 404 is being created
18:29:38.959 - PulseEffects - DEBUG - PM - volume meter stream for app 404 is ready
18:29:38.983 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:29:38.984 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:29:38.984 - PulseEffects - DEBUG - PM - volume meter stream for app 405 is being created
18:29:38.985 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:29:38.985 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:29:38.985 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:29:38.985 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:29:38.987 - PulseEffects - DEBUG - PM - volume meter stream for app 405 is ready
18:29:38.996 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:29:38.997 - PulseEffects - DEBUG - PM - volume meter stream for app 405 was terminated
18:29:38.997 - PulseEffects - DEBUG - PM - volume meter stream for app 404 was terminated
18:29:43.228 - PulseEffects - DEBUG - PM - volume meter stream for app 404 is being created
18:29:43.228 - PulseEffects - DEBUG - PM - volume meter stream for app 404 is ready
18:29:43.231 - PulseEffects - DEBUG - PM - volume meter stream for app 405 is being created
18:29:43.231 - PulseEffects - DEBUG - PM - volume meter stream for app 405 is ready
18:29:53.231 - PulseEffects - DEBUG - PM - volume meter stream for app 405 was terminated
18:29:53.238 - PulseEffects - DEBUG - SIE - pipeline state: null
18:29:53.238 - PulseEffects - DEBUG - PM - volume meter stream for app 404 was terminated
18:30:20.370 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:30:20.370 - PulseEffects - DEBUG - PM - volume meter stream for app 408 is being created
18:30:20.372 - PulseEffects - DEBUG - PM - volume meter stream for app 408 is ready
18:30:20.374 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:30:20.375 - PulseEffects - DEBUG - PM - volume meter stream for app 409 is being created
18:30:20.375 - PulseEffects - DEBUG - PM - volume meter stream for app 409 is ready
18:30:20.375 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:30:20.381 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:30:20.381 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:30:20.381 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:30:20.381 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:30:21.517 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:30:21.519 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:30:22.135 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:30:22.141 - PulseEffects - DEBUG - PM - volume meter stream for app 409 was terminated
18:30:22.144 - PulseEffects - DEBUG - PM - volume meter stream for app 408 was terminated
18:30:22.667 - PulseEffects - DEBUG - PM - volume meter stream for app 408 is being created
18:30:22.667 - PulseEffects - DEBUG - PM - volume meter stream for app 408 is ready
18:30:22.669 - PulseEffects - DEBUG - PM - volume meter stream for app 409 is being created
18:30:22.670 - PulseEffects - DEBUG - PM - volume meter stream for app 409 is ready
18:30:23.348 - PulseEffects - DEBUG - PM - volume meter stream for app 408 was terminated
18:30:23.354 - PulseEffects - DEBUG - SIE - pipeline state: null
18:30:23.354 - PulseEffects - DEBUG - PM - volume meter stream for app 409 was terminated
18:30:23.849 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:30:23.849 - PulseEffects - DEBUG - PM - volume meter stream for app 408 is being created
18:30:23.849 - PulseEffects - DEBUG - PM - volume meter stream for app 408 is ready
18:30:23.851 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:30:23.851 - PulseEffects - DEBUG - PM - volume meter stream for app 409 is being created
18:30:23.852 - PulseEffects - DEBUG - PM - volume meter stream for app 409 is ready
18:30:23.852 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:30:23.852 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:30:23.856 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:30:23.856 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:30:33.867 - PulseEffects - DEBUG - PM - volume meter stream for app 408 was terminated
18:30:33.881 - PulseEffects - DEBUG - SIE - pipeline state: null
18:30:33.881 - PulseEffects - DEBUG - PM - volume meter stream for app 409 was terminated
18:31:54.73 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:54.73 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:31:54.78 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:31:54.82 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:54.82 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:54.82 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:31:54.83 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:31:54.84 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:31:54.84 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:31:54.84 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:54.85 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:31:54.98 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:31:54.100 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:31:54.100 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:31:54.591 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:54.591 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:31:54.592 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:31:54.594 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:54.594 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:31:54.595 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:31:57.714 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:31:57.718 - PulseEffects - DEBUG - SIE - pipeline state: null
18:31:57.720 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:31:58.230 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:58.230 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:31:58.230 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:31:58.233 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:58.233 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:31:58.234 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:31:58.235 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:31:58.235 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:31:58.240 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:31:58.240 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:31:59.185 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:31:59.194 - PulseEffects - DEBUG - SIE - pipeline state: null
18:31:59.194 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:31:59.694 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:59.695 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:31:59.695 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:31:59.698 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:31:59.698 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:31:59.699 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:31:59.699 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:31:59.699 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:31:59.703 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:31:59.703 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:32:00.282 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:32:00.286 - PulseEffects - DEBUG - SIE - pipeline state: null
18:32:00.286 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:32:00.803 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:00.803 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:32:00.804 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:32:00.806 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:00.806 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:32:00.807 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:32:00.808 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:32:00.808 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:32:00.813 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:32:00.813 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:32:04.714 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:32:04.719 - PulseEffects - DEBUG - SIE - pipeline state: null
18:32:04.719 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:32:05.249 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:05.249 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:32:05.250 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:32:05.252 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:32:05.252 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:32:05.253 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:05.253 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:32:05.253 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:32:05.259 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:32:05.259 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:32:05.847 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:32:05.852 - PulseEffects - DEBUG - SIE - pipeline state: null
18:32:05.852 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:32:06.850 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:06.850 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:32:06.851 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:32:06.853 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:06.853 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:32:06.854 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:32:06.855 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:32:06.855 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:32:06.859 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:32:06.859 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:32:12.664 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:32:12.669 - PulseEffects - DEBUG - SIE - pipeline state: null
18:32:12.669 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:32:13.182 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:13.183 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:32:13.184 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:32:13.185 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:32:13.185 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:32:13.187 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:13.187 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:32:13.187 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:32:13.192 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:32:13.192 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:32:13.439 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:32:13.441 - PulseEffects - DEBUG - SIE - pipeline state: null
18:32:13.442 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:32:14.366 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:14.366 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:32:14.367 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:32:14.369 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:14.369 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:32:14.370 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:32:14.372 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:32:14.373 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:32:14.374 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:14.374 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:32:14.378 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:32:14.383 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:32:14.383 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:32:14.886 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:32:14.886 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:32:14.888 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:32:14.888 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:32:15.198 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:32:15.204 - PulseEffects - DEBUG - SIE - pipeline state: null
18:32:15.204 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
18:32:15.705 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:15.705 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is being created
18:32:15.705 - PulseEffects - DEBUG - PM - volume meter stream for app 414 is ready
18:32:15.707 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
18:32:15.708 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
18:32:15.708 - PulseEffects - DEBUG - SIE - pipeline state: playing
18:32:15.708 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is being created
18:32:15.709 - PulseEffects - DEBUG - PM - volume meter stream for app 415 is ready
18:32:15.711 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
18:32:15.711 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
18:32:25.699 - PulseEffects - DEBUG - PM - volume meter stream for app 415 was terminated
18:32:25.726 - PulseEffects - DEBUG - SIE - pipeline state: null
18:32:25.727 - PulseEffects - DEBUG - PM - volume meter stream for app 414 was terminated
fish: “env PULSEEFFECTS_DEBUG=1 pulsee…” terminated by signal SIGSEGV (Address boundary error)
Switch from integrated card to external at 18:05.
And crash (related to https://github.com/wwmm/pulseeffects/issues/217#issuecomment-390251280, I think).
AlexWayfer
on 30 May 2018
~ > env PULSEEFFECTS_DEBUG=1 pulseeffects
10:50:21.206 - PulseEffects - DEBUG - MAIN - debug logging enabled
10:50:21.245 - PulseEffects - DEBUG - PM - pulseaudio context is connecting
10:50:21.245 - PulseEffects - DEBUG - PM - pulseaudio context is authorizing
10:50:21.246 - PulseEffects - DEBUG - PM - pulseaudio context is setting name
10:50:21.246 - PulseEffects - DEBUG - PM - pulseaudio context is ready
10:50:21.246 - PulseEffects - DEBUG - PM - connected to server: unix:/run/user/1000/pulse/native
10:50:21.246 - PulseEffects - DEBUG - PM - server protocol version: 32
10:50:21.247 - PulseEffects - DEBUG - PM - pulseaudio version: 11.1
10:50:21.247 - PulseEffects - DEBUG - PM - default pulseaudio source: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
10:50:21.247 - PulseEffects - DEBUG - PM - default pulseaudio sink: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo
10:50:21.247 - PulseEffects - DEBUG - PM - default pulseaudio sink audio format: s16le
10:50:21.247 - PulseEffects - DEBUG - PM - default pulseaudio sink sampling rate: 44100 Hz. We will use the same rate.
10:50:21.248 - PulseEffects - DEBUG - PM - default pulseaudio source audio format: s16le
10:50:21.248 - PulseEffects - DEBUG - PM - default pulseaudio source sampling rate: 44100 Hz. We will use the same rate.
10:50:21.248 - PulseEffects - DEBUG - PM - loading Pulseeffects applications sink...
10:50:21.248 - PulseEffects - DEBUG - PM - Pulseeffects apps sink was successfully loaded
10:50:21.248 - PulseEffects - DEBUG - PM - Pulseeffects apps sink index:3
10:50:21.248 - PulseEffects - DEBUG - PM - Pulseeffects apps sink monitor name: PulseEffects_apps.monitor
10:50:21.248 - PulseEffects - DEBUG - PM - loading Pulseeffects microphone output sink...
10:50:21.248 - PulseEffects - DEBUG - PM - Pulseeffects mic sink was successfully loaded
10:50:21.249 - PulseEffects - DEBUG - PM - Pulseeffects mic sink index:4
10:50:21.249 - PulseEffects - DEBUG - PM - Pulseeffects mic sink monitor name: PulseEffects_mic.monitor
10:50:21.280 - PulseEffects - WARNING - Delay plugin was not found. Disabling it!
10:50:21.285 - PulseEffects - WARNING - Maximizer plugin was not found. Disabling it!
10:50:21.287 - PulseEffects - DEBUG - SIE - limiter wrapper was enabled
10:50:21.287 - PulseEffects - DEBUG - SIE - compressor wrapper was enabled
10:50:21.287 - PulseEffects - DEBUG - SIE - highpass wrapper was enabled
10:50:21.287 - PulseEffects - DEBUG - SIE - lowpass wrapper was enabled
10:50:21.287 - PulseEffects - DEBUG - SIE - equalizer wrapper was enabled
10:50:21.287 - PulseEffects - DEBUG - SIE - bass enhancer wrapper was enabled
10:50:21.288 - PulseEffects - DEBUG - SIE - exciter wrapper was enabled
10:50:21.288 - PulseEffects - DEBUG - SIE - stereo enhancer wrapper was enabled
10:50:21.288 - PulseEffects - DEBUG - SIE - panorama wrapper was enabled
10:50:21.288 - PulseEffects - DEBUG - SIE - stereo spread wrapper was enabled
10:50:21.288 - PulseEffects - DEBUG - SIE - reverb wrapper was enabled
10:50:21.288 - PulseEffects - DEBUG - SIE - crossfeed wrapper was enabled
10:50:21.289 - PulseEffects - DEBUG - SIE - delay wrapper was enabled
10:50:21.289 - PulseEffects - DEBUG - SIE - maximizer wrapper was enabled
10:50:21.289 - PulseEffects - DEBUG - SIE - output limiter wrapper was enabled
10:50:21.289 - PulseEffects - DEBUG - SIE - spectrum wrapper was enabled
10:50:21.294 - PulseEffects - WARNING - Pitch plugin was not found. Disabling it!
10:50:21.304 - PulseEffects - DEBUG - SOE - gate wrapper was enabled
10:50:21.304 - PulseEffects - DEBUG - SOE - webrtc wrapper was enabled
10:50:21.304 - PulseEffects - DEBUG - SOE - limiter wrapper was enabled
10:50:21.305 - PulseEffects - DEBUG - SOE - compressor wrapper was enabled
10:50:21.305 - PulseEffects - DEBUG - SOE - highpass wrapper was enabled
10:50:21.305 - PulseEffects - DEBUG - SOE - lowpass wrapper was enabled
10:50:21.305 - PulseEffects - DEBUG - SOE - equalizer wrapper was enabled
10:50:21.305 - PulseEffects - DEBUG - SOE - deesser wrapper was enabled
10:50:21.305 - PulseEffects - DEBUG - SOE - reverb wrapper was enabled
10:50:21.305 - PulseEffects - DEBUG - SOE - pitch wrapper was enabled
10:50:21.306 - PulseEffects - DEBUG - SOE - spectrum wrapper was enabled
10:50:21.491 - PulseEffects - DEBUG - SIE - bass enhancer bin was enabled
10:50:21.710 - PulseEffects - DEBUG - MAIN - autostart_file created successfully
10:50:21.732 - PulseEffects - DEBUG - MAIN - using default sink
10:50:21.732 - PulseEffects - DEBUG - MAIN - using default source
10:50:22.57 - PulseEffects - CRITICAL - PM - context operation failed!
10:50:22.58 - PulseEffects - DEBUG - MAIN - added sink: alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1
10:50:22.59 - PulseEffects - DEBUG - MAIN - added sink: alsa_output.pci-0000_00_1b.0.analog-stereo
10:50:22.59 - PulseEffects - DEBUG - MAIN - added sink: alsa_output.pci-0000_00_1b.0.analog-stereo.equalizer
10:50:22.59 - PulseEffects - DEBUG - MAIN - added sink: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo
10:50:22.60 - PulseEffects - DEBUG - MAIN - output device changed: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo
10:50:22.60 - PulseEffects - DEBUG - MAIN - added source: alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1.monitor
10:50:22.60 - PulseEffects - DEBUG - MAIN - added source: alsa_output.pci-0000_00_1b.0.analog-stereo.monitor
10:50:22.60 - PulseEffects - DEBUG - MAIN - added source: alsa_input.pci-0000_00_1b.0.analog-stereo
10:50:22.60 - PulseEffects - DEBUG - MAIN - added source: alsa_output.pci-0000_00_1b.0.analog-stereo.equalizer.monitor
10:50:22.61 - PulseEffects - DEBUG - MAIN - added source: alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo.monitor
10:50:22.61 - PulseEffects - DEBUG - MAIN - added source: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
10:50:22.61 - PulseEffects - DEBUG - MAIN - input device changed: alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono
10:50:24.571 - PulseEffects - DEBUG - MAIN - autostart_file removed successfully
10:50:44.431 - PulseEffects - DEBUG - SIE - pipeline state: playing
10:50:44.432 - PulseEffects - DEBUG - PM - volume meter stream for app 81 is being created
10:50:44.432 - PulseEffects - DEBUG - PM - volume meter stream for app 81 is ready
10:50:44.462 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
10:50:44.462 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
10:50:44.472 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
10:50:44.472 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
10:51:58.842 - PulseEffects - DEBUG - SIE - pipeline state: null
10:51:58.842 - PulseEffects - DEBUG - PM - volume meter stream for app 81 was terminated
11:02:52.581 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:02:52.581 - PulseEffects - DEBUG - PM - volume meter stream for app 84 is being created
11:02:52.581 - PulseEffects - DEBUG - PM - volume meter stream for app 84 is ready
11:02:52.587 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:02:52.588 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:02:52.593 - PulseEffects - DEBUG - PM - volume meter stream for app 85 is being created
11:02:52.595 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
11:02:52.595 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
11:02:52.597 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
11:02:52.597 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
11:02:52.600 - PulseEffects - DEBUG - PM - volume meter stream for app 85 is ready
11:03:02.570 - PulseEffects - DEBUG - PM - volume meter stream for app 85 was terminated
11:03:02.584 - PulseEffects - DEBUG - SIE - pipeline state: null
11:03:02.584 - PulseEffects - DEBUG - PM - volume meter stream for app 84 was terminated
11:03:20.235 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:03:20.235 - PulseEffects - DEBUG - PM - volume meter stream for app 88 is being created
11:03:20.236 - PulseEffects - DEBUG - PM - volume meter stream for app 88 is ready
11:03:20.239 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:03:20.240 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:03:20.240 - PulseEffects - DEBUG - PM - volume meter stream for app 89 is being created
11:03:20.240 - PulseEffects - DEBUG - PM - volume meter stream for app 89 is ready
11:03:20.245 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
11:03:20.245 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
11:03:20.258 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
11:03:20.259 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
11:03:21.794 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:03:21.799 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:03:24.710 - PulseEffects - DEBUG - PM - volume meter stream for app 89 was terminated
11:03:24.714 - PulseEffects - DEBUG - SIE - pipeline state: null
11:03:24.714 - PulseEffects - DEBUG - PM - volume meter stream for app 88 was terminated
11:03:25.256 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:03:25.256 - PulseEffects - DEBUG - PM - volume meter stream for app 88 is being created
11:03:25.259 - PulseEffects - DEBUG - PM - volume meter stream for app 88 is ready
11:03:25.263 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:03:25.263 - PulseEffects - DEBUG - PM - volume meter stream for app 89 is being created
11:03:25.264 - PulseEffects - DEBUG - PM - volume meter stream for app 89 is ready
11:03:25.272 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
11:03:25.272 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
11:03:25.281 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
11:03:25.281 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
11:03:35.276 - PulseEffects - DEBUG - PM - volume meter stream for app 89 was terminated
11:03:35.287 - PulseEffects - DEBUG - SIE - pipeline state: null
11:03:35.288 - PulseEffects - DEBUG - PM - volume meter stream for app 88 was terminated
11:24:24.392 - PulseEffects - CRITICAL - PM - context operation failed!
11:26:45.990 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:26:45.991 - PulseEffects - DEBUG - PM - volume meter stream for app 97 is being created
11:26:45.993 - PulseEffects - DEBUG - PM - volume meter stream for app 97 is ready
11:26:45.996 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
11:26:45.996 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
11:26:46.5 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
11:26:46.5 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
11:26:46.793 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:26:51.920 - PulseEffects - DEBUG - PM - volume meter stream for app 100 is being created
11:26:51.921 - PulseEffects - DEBUG - PM - volume meter stream for app 100 is ready
11:26:55.977 - PulseEffects - DEBUG - PM - volume meter stream for app 97 was terminated
11:37:11.795 - PulseEffects - DEBUG - SIE - pipeline state: null
11:37:11.795 - PulseEffects - DEBUG - PM - volume meter stream for app 100 was terminated
11:44:53.801 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:44:53.801 - PulseEffects - DEBUG - PM - volume meter stream for app 101 is being created
11:44:53.802 - PulseEffects - DEBUG - PM - volume meter stream for app 101 is ready
11:44:53.811 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
11:44:53.811 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
11:44:53.812 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:44:53.815 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
11:44:53.815 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
11:44:54.125 - PulseEffects - DEBUG - PM - volume meter stream for app 101 was terminated
11:44:59.137 - PulseEffects - DEBUG - SIE - pipeline state: null
11:45:00.53 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:45:00.53 - PulseEffects - DEBUG - PM - volume meter stream for app 104 is being created
11:45:00.53 - PulseEffects - DEBUG - PM - volume meter stream for app 104 is ready
11:45:00.56 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
11:45:00.56 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
11:45:00.63 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
11:45:00.63 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
11:46:26.936 - PulseEffects - DEBUG - SIE - pipeline state: null
11:46:26.937 - PulseEffects - DEBUG - PM - volume meter stream for app 104 was terminated
11:51:07.631 - PulseEffects - DEBUG - SIE - pipeline state: playing
11:51:07.631 - PulseEffects - DEBUG - PM - volume meter stream for app 107 is being created
11:51:07.633 - PulseEffects - DEBUG - PM - volume meter stream for app 107 is ready
11:51:07.634 - PulseEffects - DEBUG - SIE - pulsesrc latency-time [us]: 10000
11:51:07.635 - PulseEffects - DEBUG - SIE - pulsesrc buffer-time [us]: 100000
11:51:07.639 - PulseEffects - DEBUG - SIE - pulsesink latency-time [us]: 10000
11:51:07.639 - PulseEffects - DEBUG - SIE - pulsesink buffer-time [us]: 100000
11:52:12.820 - PulseEffects - DEBUG - PM - volume meter stream for app 110 is being created
11:52:12.821 - PulseEffects - DEBUG - PM - volume meter stream for app 110 is ready
11:52:12.824 - PulseEffects - DEBUG - PM - volume meter stream for app 111 is being created
11:52:12.824 - PulseEffects - DEBUG - PM - volume meter stream for app 111 is ready
11:52:13.670 - PulseEffects - DEBUG - PM - volume meter stream for app 111 was terminated
11:52:13.672 - PulseEffects - DEBUG - PM - volume meter stream for app 110 was terminated
11:52:14.406 - PulseEffects - DEBUG - PM - volume meter stream for app 110 is being created
11:52:14.406 - PulseEffects - DEBUG - PM - volume meter stream for app 110 is ready
11:52:14.407 - PulseEffects - DEBUG - PM - volume meter stream for app 111 is being created
11:52:14.407 - PulseEffects - DEBUG - PM - volume meter stream for app 111 is ready
11:52:15.844 - PulseEffects - DEBUG - PM - volume meter stream for app 111 was terminated
11:52:15.850 - PulseEffects - DEBUG - PM - volume meter stream for app 110 was terminated
11:52:16.404 - PulseEffects - DEBUG - PM - volume meter stream for app 110 is being created
11:52:16.404 - PulseEffects - DEBUG - PM - volume meter stream for app 110 is ready
11:52:16.405 - PulseEffects - DEBUG - PM - volume meter stream for app 111 is being created
11:52:16.405 - PulseEffects - DEBUG - PM - volume meter stream for app 111 is ready
11:52:21.720 - PulseEffects - DEBUG - PM - volume meter stream for app 112 is being created
11:52:21.720 - PulseEffects - DEBUG - PM - volume meter stream for app 112 is ready
11:52:21.727 - PulseEffects - DEBUG - PM - volume meter stream for app 113 is being created
11:52:21.727 - PulseEffects - DEBUG - PM - volume meter stream for app 113 is ready
11:52:23.263 - PulseEffects - DEBUG - PM - volume meter stream for app 113 was terminated
11:52:23.264 - PulseEffects - DEBUG - PM - volume meter stream for app 112 was terminated
11:52:23.769 - PulseEffects - DEBUG - PM - volume meter stream for app 112 is being created
11:52:23.770 - PulseEffects - DEBUG - PM - volume meter stream for app 112 is ready
11:52:23.770 - PulseEffects - DEBUG - PM - volume meter stream for app 113 is being created
11:52:23.770 - PulseEffects - DEBUG - PM - volume meter stream for app 113 is ready
11:52:24.543 - PulseEffects - DEBUG - PM - volume meter stream for app 113 was terminated
11:52:24.546 - PulseEffects - DEBUG - PM - volume meter stream for app 112 was terminated
11:52:25.112 - PulseEffects - DEBUG - PM - volume meter stream for app 112 is being created
11:52:25.113 - PulseEffects - DEBUG - PM - volume meter stream for app 112 is ready
11:52:25.117 - PulseEffects - DEBUG - PM - volume meter stream for app 113 is being created
11:52:25.117 - PulseEffects - DEBUG - PM - volume meter stream for app 113 is ready
11:52:26.412 - PulseEffects - DEBUG - PM - volume meter stream for app 111 was terminated
11:52:26.419 - PulseEffects - DEBUG - PM - volume meter stream for app 110 was terminated
11:52:35.119 - PulseEffects - DEBUG - PM - volume meter stream for app 112 was terminated
11:52:35.128 - PulseEffects - DEBUG - PM - volume meter stream for app 113 was terminated
11:52 — definitely multiple lags without heavy CPU loading.
AlexWayfer
on 31 May 2018
11:55:27.450 - PulseEffects - DEBUG - PM - volume meter stream for app 114 is being created
11:55:27.450 - PulseEffects - DEBUG - PM - volume meter stream for app 114 is ready
11:55:27.455 - PulseEffects - DEBUG - PM - volume meter stream for app 115 is being created
11:55:27.456 - PulseEffects - DEBUG - PM - volume meter stream for app 115 is ready
11:55:29.538 - PulseEffects - DEBUG - PM - volume meter stream for app 116 is being created
11:55:29.538 - PulseEffects - DEBUG - PM - volume meter stream for app 116 is ready
11:55:29.546 - PulseEffects - DEBUG - PM - volume meter stream for app 117 is being created
11:55:29.547 - PulseEffects - DEBUG - PM - volume meter stream for app 117 is ready
11:55:32.366 - PulseEffects - DEBUG - PM - volume meter stream for app 117 was terminated
11:55:32.366 - PulseEffects - DEBUG - PM - volume meter stream for app 116 was terminated
11:55:33.690 - PulseEffects - DEBUG - PM - volume meter stream for app 116 is being created
11:55:33.693 - PulseEffects - DEBUG - PM - volume meter stream for app 117 is being created
11:55:33.694 - PulseEffects - DEBUG - PM - volume meter stream for app 116 is ready
11:55:33.694 - PulseEffects - DEBUG - PM - volume meter stream for app 117 is ready
11:55:37.443 - PulseEffects - DEBUG - PM - volume meter stream for app 114 was terminated
11:55:37.445 - PulseEffects - DEBUG - PM - volume meter stream for app 115 was terminated
11:55:43.701 - PulseEffects - DEBUG - PM - volume meter stream for app 117 was terminated
11:55:43.710 - PulseEffects - DEBUG - PM - volume meter stream for app 116 was terminated
It continues to lag. Without any logs sometimes.
AlexWayfer
on 31 May 2018
100% scenario:
- Google Play Music playing in one tab
- Load Beatport artist page in another tab
Got 2 lags per page loading (audio object initialization?)
13:56:04.86 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is being created
13:56:04.87 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is ready
13:56:05.820 - PulseEffects - DEBUG - PM - volume meter stream for app 36 was terminated
13:56:06.146 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is being created
13:56:06.146 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is ready
13:56:06.667 - PulseEffects - DEBUG - PM - volume meter stream for app 36 was terminated
13:56:10.181 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is being created
13:56:10.182 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is ready
13:56:10.526 - PulseEffects - DEBUG - PM - volume meter stream for app 36 was terminated
13:56:14.128 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is being created
13:56:14.128 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is ready
13:56:18.315 - PulseEffects - DEBUG - PM - volume meter stream for app 36 was terminated
13:56:18.618 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is being created
13:56:18.619 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is ready
13:56:19.799 - PulseEffects - DEBUG - PM - volume meter stream for app 36 was terminated
13:56:20.105 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is being created
13:56:20.105 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is ready
13:56:21.823 - PulseEffects - DEBUG - PM - volume meter stream for app 36 was terminated
13:56:22.156 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is being created
13:56:22.156 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is ready
13:56:27.785 - PulseEffects - DEBUG - PM - volume meter stream for app 36 was terminated
13:56:28.96 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is being created
13:56:28.97 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is ready
13:56:29.672 - PulseEffects - DEBUG - PM - volume meter stream for app 36 was terminated
13:56:29.945 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is being created
13:56:29.946 - PulseEffects - DEBUG - PM - volume meter stream for app 36 is ready
I see nothing wrong in the logs.
In order to save battery PulseEffects pauses its pipeline when no audio app is playing and puts it back online when an app wants to play something. But despite of the many volume meter stream creation and destruction you have in the logs there is no line about pipeline state changes. So this does not seem to be the source of the problem.
Does this happen in other browsers or only in chromium? I use chrome and at least in youtube, netflix and crunchroll I have no problems when switching tabs or doing other stuff
wwmm
on 1 Jun 2018
Does this happen in other browsers or only in chromium? I use chrome and at least in youtube, netflix and crunchroll I have no problems when switching tabs or doing other stuff
YoutTube in Chromium: the same lags for Beatport page.
Google Play Music (GPM) in Firefox: everything is OK, no lags. And no logs from PulseEffects!
GPM in Google Chrome (stable): the same lags, the same logs.
So, where are logs — there are lags, probably.
But despite of the many volume meter stream creation and destruction you have in the logs there is no line about pipeline state changes. So this does not seem to be the source of the problem.
But for what volume meter stream (pipeline?) creating at Beatport (artist) page loading and terminating when page loading is done? It's strange.
AlexWayfer
on 1 Jun 2018
The same in the version 4, but there are no any logs in the debug mode (G_MESSAGES_DEBUG=pulseeffects pulseeffects). :disappointed:
AlexWayfer
on 6 Jun 2018
Can you add please more debug logs? I'll attach them here when these situations occur.
AlexWayfer
on 6 Jun 2018
In version 4 I added a lot of debug messages. I am not sure if there is much more that can be added. Could you try to provide the other info mentioned at Reporting Bugs. Maybe there is some clue there
wwmm
on 6 Jun 2018
Yeah, sure:
Distribution and Desktop Environment.
Arch Linux, GNOME Shell 3.28.2-1
PulseEffects version and how you installed it.
4.0.1-1
Oops, I realized that I have loaded modules from another equalizer:
https://wiki.archlinux.org/index.php/PulseAudio#Load_equalizer_sink_and_dbus-protocol_module
I'll try to use PulseEffects without them.
If I'll have any trouble — I'll write there remain answers.
Sorry, but I have the same troubles for Beatport page, for example. So…
The output of the command pactl list short.
0 module-device-restore
1 module-stream-restore
2 module-card-restore
3 module-augment-properties
4 module-switch-on-port-available
5 module-udev-detect
6 module-alsa-card device_id="1" name="pci-0000_01_00.1" card_name="alsa_card.pci-0000_01_00.1" namereg_fail=false tsched=yes fixed_latency_range=no ignore_dB=no deferred_volume=yes use_ucm=yes card_properties="module-udev-detect.discovered=1"
7 module-alsa-card device_id="0" name="pci-0000_00_1b.0" card_name="alsa_card.pci-0000_00_1b.0" namereg_fail=false tsched=yes fixed_latency_range=no ignore_dB=no deferred_volume=yes use_ucm=yes card_properties="module-udev-detect.discovered=1"
8 module-bluetooth-policy
9 module-bluetooth-discover
10 module-bluez5-discover
11 module-esound-protocol-unix
12 module-native-protocol-unix
13 module-default-device-restore
14 module-rescue-streams
15 module-always-sink
16 module-intended-roles
17 module-suspend-on-idle
18 module-console-kit
19 module-systemd-login
20 module-position-event-sounds
21 module-role-cork
22 module-filter-heuristics
23 module-filter-apply
26 module-x11-publish display=:1
27 module-x11-xsmp display=:1 session_manager=local/alex-workpc-arch:@/tmp/.ICE-unix/4814,unix/alex-workpc-arch:/tmp/.ICE-unix/4814
31 module-alsa-card device_id="2" name="usb-C-Media_Electronics_Inc._USB_Audio_Device-00" card_name="alsa_card.usb-C-Media_Electronics_Inc._USB_Audio_Device-00" namereg_fail=false tsched=yes fixed_latency_range=no ignore_dB=no deferred_volume=yes use_ucm=yes card_properties="module-udev-detect.discovered=1"
32 module-cli-protocol-unix
33 module-null-sink sink_name=PulseEffects_apps sink_properties=device.description="PulseEffects(apps)"device.class="sound" channels=2 rate=48000
34 module-null-sink sink_name=PulseEffects_mic sink_properties=device.description="PulseEffects(mic)"device.class="sound" channels=2 rate=44100
0 alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1 module-alsa-card.c s16le 2ch 44100Hz SUSPENDED
1 alsa_output.pci-0000_00_1b.0.analog-stereo module-alsa-card.c s16le 2ch 44100Hz SUSPENDED
6 alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo module-alsa-card.c s16le 2ch 48000Hz RUNNING
7 PulseEffects_apps module-null-sink.c s16le 2ch 48000Hz RUNNING
8 PulseEffects_mic module-null-sink.c s16le 2ch 44100Hz SUSPENDED
0 alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1.monitor module-alsa-card.c s16le 2ch 44100Hz SUSPENDED
1 alsa_output.pci-0000_00_1b.0.analog-stereo.monitor module-alsa-card.c s16le 2ch 44100Hz SUSPENDED
2 alsa_input.pci-0000_00_1b.0.analog-stereo module-alsa-card.c s16le 2ch 48000Hz SUSPENDED
8 alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo.monitor module-alsa-card.c s16le 2ch 48000Hz IDLE
9 alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono module-alsa-card.c s16le 1ch 44100Hz SUSPENDED
10 PulseEffects_apps.monitor module-null-sink.c s16le 2ch 48000Hz RUNNING
11 PulseEffects_mic.monitor module-null-sink.c s16le 2ch 44100Hz SUSPENDED
417 7 406 protocol-native.c float32le 2ch 44100Hz
419 6 407 protocol-native.c float32le 2ch 48000Hz
115 10 408 protocol-native.c float32le 2ch 48000Hz
0 module-systemd-login.c (null)
1 protocol-native.c gnome-shell
2 protocol-native.c gnome-shell
5 module-x11-xsmp.c (null)
6 protocol-native.c gsd-media-keys
7 protocol-native.c gjs-console
12 protocol-native.c chromium
21 protocol-native.c electron
75 protocol-native.c KeeWeb
405 protocol-native.c pulseeffects
406 protocol-native.c chromium
407 protocol-native.c pulseeffects
408 protocol-native.c pulseeffects
410 protocol-native.c pactl
0 bell-window-system s16le 2ch 44100Hz 0.139
0 alsa_card.pci-0000_01_00.1 module-alsa-card.c
1 alsa_card.pci-0000_00_1b.0 module-alsa-card.c
3 alsa_card.usb-C-Media_Electronics_Inc._USB_Audio_Device-00 module-alsa-card.c
The output of the command pacmd list-sinks.
5 sink(s) available.
index: 0
name: <alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1>
driver: <module-alsa-card.c>
flags: HARDWARE DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: SUSPENDED
suspend cause: IDLE
priority: 9030
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 0.00 ms
max request: 0 KiB
max rewind: 0 KiB
monitor source: 0
sample spec: s16le 2ch 44100Hz
channel map: front-left,front-right
Stereo
used by: 0
linked by: 0
configured latency: 0.00 ms; range is 0.50 .. 1999.82 ms
card: 0 <alsa_card.pci-0000_01_00.1>
module: 6
properties:
alsa.resolution_bits = "16"
device.api = "alsa"
device.class = "sound"
alsa.class = "generic"
alsa.subclass = "generic-mix"
alsa.name = "HDMI 1"
alsa.id = "HDMI 1"
alsa.subdevice = "0"
alsa.subdevice_name = "subdevice #0"
alsa.device = "7"
alsa.card = "1"
alsa.card_name = "HDA NVidia"
alsa.long_card_name = "HDA NVidia at 0xf7080000 irq 17"
alsa.driver_name = "snd_hda_intel"
device.bus_path = "pci-0000:01:00.1"
sysfs.path = "/devices/pci0000:00/0000:00:01.0/0000:01:00.1/sound/card1"
device.bus = "pci"
device.vendor.id = "10de"
device.vendor.name = "NVIDIA Corporation"
device.product.id = "0e1b"
device.product.name = "GK107 HDMI Audio Controller"
device.string = "hdmi:1,1"
device.buffering.buffer_size = "352768"
device.buffering.fragment_size = "176384"
device.access_mode = "mmap+timer"
device.profile.name = "hdmi-stereo-extra1"
device.profile.description = "Digital Stereo (HDMI 2)"
device.description = "GK107 HDMI Audio Controller Digital Stereo (HDMI 2)"
alsa.mixer_name = "Nvidia GPU 42 HDMI/DP"
alsa.components = "HDA:10de0042,104383f3,00100100"
module-udev-detect.discovered = "1"
device.icon_name = "audio-card-pci"
ports:
hdmi-output-1: HDMI / DisplayPort 2 (priority 5800, latency offset 0 usec, available: yes)
properties:
device.icon_name = "video-display"
device.product.name = "DELL U2410
"
active port: <hdmi-output-1>
index: 1
name: <alsa_output.pci-0000_00_1b.0.analog-stereo>
driver: <module-alsa-card.c>
flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: SUSPENDED
suspend cause: IDLE
priority: 9039
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 0.00 ms
max request: 0 KiB
max rewind: 0 KiB
monitor source: 1
sample spec: s16le 2ch 44100Hz
channel map: front-left,front-right
Stereo
used by: 0
linked by: 0
configured latency: 0.00 ms; range is 0.50 .. 2000.00 ms
card: 1 <alsa_card.pci-0000_00_1b.0>
module: 7
properties:
alsa.resolution_bits = "16"
device.api = "alsa"
device.class = "sound"
alsa.class = "generic"
alsa.subclass = "generic-mix"
alsa.name = "ALC892 Analog"
alsa.id = "ALC892 Analog"
alsa.subdevice = "0"
alsa.subdevice_name = "subdevice #0"
alsa.device = "0"
alsa.card = "0"
alsa.card_name = "HDA Intel PCH"
alsa.long_card_name = "HDA Intel PCH at 0xf7430000 irq 39"
alsa.driver_name = "snd_hda_intel"
device.bus_path = "pci-0000:00:1b.0"
sysfs.path = "/devices/pci0000:00/0000:00:1b.0/sound/card0"
device.bus = "pci"
device.vendor.id = "8086"
device.vendor.name = "Intel Corporation"
device.product.id = "1e20"
device.product.name = "7 Series/C216 Chipset Family High Definition Audio Controller"
device.form_factor = "internal"
device.string = "front:0"
device.buffering.buffer_size = "352800"
device.buffering.fragment_size = "176400"
device.access_mode = "mmap+timer"
device.profile.name = "analog-stereo"
device.profile.description = "Analog Stereo"
device.description = "Built-in Audio Analog Stereo"
alsa.mixer_name = "Realtek ALC892"
alsa.components = "HDA:10ec0892,10438436,00100302"
module-udev-detect.discovered = "1"
device.icon_name = "audio-card-pci"
ports:
analog-output-lineout: Line Out (priority 9900, latency offset 0 usec, available: no)
properties:
analog-output-headphones: Headphones (priority 9000, latency offset 0 usec, available: yes)
properties:
device.icon_name = "audio-headphones"
active port: <analog-output-headphones>
* index: 6
name: <alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo>
driver: <module-alsa-card.c>
flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: RUNNING
suspend cause:
priority: 9049
volume: front-left: 55056 / 84% / -4.54 dB, front-right: 55056 / 84% / -4.54 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 50.08 ms
max request: 7 KiB
max rewind: 344 KiB
monitor source: 8
sample spec: s16le 2ch 48000Hz
channel map: front-left,front-right
Stereo
used by: 1
linked by: 1
configured latency: 40.00 ms; range is 0.50 .. 1837.50 ms
card: 3 <alsa_card.usb-C-Media_Electronics_Inc._USB_Audio_Device-00>
module: 31
properties:
alsa.resolution_bits = "16"
device.api = "alsa"
device.class = "sound"
alsa.class = "generic"
alsa.subclass = "generic-mix"
alsa.name = "USB Audio"
alsa.id = "USB Audio"
alsa.subdevice = "0"
alsa.subdevice_name = "subdevice #0"
alsa.device = "0"
alsa.card = "2"
alsa.card_name = "USB Audio Device"
alsa.long_card_name = "C-Media Electronics Inc. USB Audio Device at usb-0000:00:1d.0-1.7, full speed"
alsa.driver_name = "snd_usb_audio"
device.bus_path = "pci-0000:00:1d.0-usb-0:1.7:1.0"
sysfs.path = "/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.7/2-1.7:1.0/sound/card2"
udev.id = "usb-C-Media_Electronics_Inc._USB_Audio_Device-00"
device.bus = "usb"
device.vendor.id = "0d8c"
device.vendor.name = "C-Media Electronics, Inc."
device.product.id = "0014"
device.product.name = "Audio Adapter (Unitek Y-247A)"
device.serial = "C-Media_Electronics_Inc._USB_Audio_Device"
device.string = "front:2"
device.buffering.buffer_size = "352800"
device.buffering.fragment_size = "176400"
device.access_mode = "mmap+timer"
device.profile.name = "analog-stereo"
device.profile.description = "Analog Stereo"
device.description = "Audio Adapter (Unitek Y-247A) Analog Stereo"
alsa.mixer_name = "USB Mixer"
alsa.components = "USB0d8c:0014"
module-udev-detect.discovered = "1"
device.icon_name = "audio-card-usb"
ports:
analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown)
properties:
active port: <analog-output>
index: 7
name: <PulseEffects_apps>
driver: <module-null-sink.c>
flags: DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: RUNNING
suspend cause:
priority: 9000
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 6.26 ms
max request: 1 KiB
max rewind: 1 KiB
monitor source: 10
sample spec: s16le 2ch 48000Hz
channel map: front-left,front-right
Stereo
used by: 1
linked by: 2
configured latency: 10.00 ms; range is 0.50 .. 2000.00 ms
module: 33
properties:
device.description = "PulseEffects(apps)"
device.class = "sound"
device.icon_name = "audio-card"
index: 8
name: <PulseEffects_mic>
driver: <module-null-sink.c>
flags: DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: SUSPENDED
suspend cause: IDLE
priority: 9000
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 0.00 ms
max request: 344 KiB
max rewind: 344 KiB
monitor source: 11
sample spec: s16le 2ch 44100Hz
channel map: front-left,front-right
Stereo
used by: 0
linked by: 0
configured latency: 0.00 ms; range is 0.50 .. 2000.00 ms
module: 34
properties:
device.description = "PulseEffects(mic)"
device.class = "sound"
device.icon_name = "audio-card"
The output of the command pacmd list-sink-inputs.
2 sink input(s) available.
index: 417
driver: <protocol-native.c>
flags: START_CORKED
state: RUNNING
sink: 7 <PulseEffects_apps>
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
muted: no
current latency: 59.66 ms
requested latency: 23.22 ms
sample spec: float32le 2ch 44100Hz
channel map: front-left,front-right
Stereo
resample method: speex-float-1
module: 12
client: 406 <Chromium>
properties:
application.icon_name = "chromium-browser"
media.name = "Playback"
application.name = "Chromium"
native-protocol.peer = "UNIX socket client"
native-protocol.version = "32"
application.process.id = "11844"
application.process.user = "alex"
application.process.host = "alex-workpc-arch"
application.process.binary = "chromium"
application.language = "en_US.UTF-8"
window.x11.display = ":1"
application.process.machine_id = "4c308eb5d77a4e3b8280c9afe3cc533b"
application.process.session_id = "c3"
module-stream-restore.id = "sink-input-by-application-name:Chromium"
index: 419
driver: <protocol-native.c>
flags: START_CORKED
state: RUNNING
sink: 6 <alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo>
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
muted: no
current latency: 54.60 ms
requested latency: 40.00 ms
sample spec: float32le 2ch 48000Hz
channel map: front-left,front-right
Stereo
resample method: copy
module: 12
client: 407 <PulseEffects>
properties:
media.name = "Playback Stream"
application.name = "PulseEffects"
native-protocol.peer = "UNIX socket client"
native-protocol.version = "32"
application.id = "com.github.wwmm.pulseeffects"
application.icon_name = "pulseeffects"
application.process.id = "19356"
application.process.user = "alex"
application.process.host = "alex-workpc-arch"
application.process.binary = "pulseeffects"
application.language = "en_US.UTF-8"
window.x11.display = ":1"
application.process.machine_id = "4c308eb5d77a4e3b8280c9afe3cc533b"
application.process.session_id = "c3"
module-stream-restore.id = "sink-input-by-application-id:com.github.wwmm.pulseeffects"
The output of the command pacmd list-sources.
7 source(s) available.
index: 0
name: <alsa_output.pci-0000_01_00.1.hdmi-stereo-extra1.monitor>
driver: <module-alsa-card.c>
flags: DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: SUSPENDED
suspend cause: IDLE
priority: 1030
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 0.00 ms
max rewind: 0 KiB
sample spec: s16le 2ch 44100Hz
channel map: front-left,front-right
Stereo
used by: 0
linked by: 0
configured latency: 0.00 ms; range is 0.50 .. 1999.82 ms
monitor_of: 0
card: 0 <alsa_card.pci-0000_01_00.1>
module: 6
properties:
device.description = "Monitor of GK107 HDMI Audio Controller Digital Stereo (HDMI 2)"
device.class = "monitor"
alsa.card = "1"
alsa.card_name = "HDA NVidia"
alsa.long_card_name = "HDA NVidia at 0xf7080000 irq 17"
alsa.driver_name = "snd_hda_intel"
device.bus_path = "pci-0000:01:00.1"
sysfs.path = "/devices/pci0000:00/0000:00:01.0/0000:01:00.1/sound/card1"
device.bus = "pci"
device.vendor.id = "10de"
device.vendor.name = "NVIDIA Corporation"
device.product.id = "0e1b"
device.product.name = "GK107 HDMI Audio Controller"
device.string = "1"
module-udev-detect.discovered = "1"
device.icon_name = "audio-card-pci"
index: 1
name: <alsa_output.pci-0000_00_1b.0.analog-stereo.monitor>
driver: <module-alsa-card.c>
flags: DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: SUSPENDED
suspend cause: IDLE
priority: 1030
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 0.00 ms
max rewind: 0 KiB
sample spec: s16le 2ch 44100Hz
channel map: front-left,front-right
Stereo
used by: 0
linked by: 0
configured latency: 0.00 ms; range is 0.50 .. 2000.00 ms
monitor_of: 1
card: 1 <alsa_card.pci-0000_00_1b.0>
module: 7
properties:
device.description = "Monitor of Built-in Audio Analog Stereo"
device.class = "monitor"
alsa.card = "0"
alsa.card_name = "HDA Intel PCH"
alsa.long_card_name = "HDA Intel PCH at 0xf7430000 irq 39"
alsa.driver_name = "snd_hda_intel"
device.bus_path = "pci-0000:00:1b.0"
sysfs.path = "/devices/pci0000:00/0000:00:1b.0/sound/card0"
device.bus = "pci"
device.vendor.id = "8086"
device.vendor.name = "Intel Corporation"
device.product.id = "1e20"
device.product.name = "7 Series/C216 Chipset Family High Definition Audio Controller"
device.form_factor = "internal"
device.string = "0"
module-udev-detect.discovered = "1"
device.icon_name = "audio-card-pci"
index: 2
name: <alsa_input.pci-0000_00_1b.0.analog-stereo>
driver: <module-alsa-card.c>
flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: SUSPENDED
suspend cause: IDLE
priority: 9039
volume: front-left: 31354 / 48% / -19.21 dB, front-right: 31354 / 48% / -19.21 dB
balance 0.00
base volume: 6554 / 10% / -60.00 dB
volume steps: 65537
muted: no
current latency: 0.00 ms
max rewind: 0 KiB
sample spec: s16le 2ch 48000Hz
channel map: front-left,front-right
Stereo
used by: 0
linked by: 0
configured latency: 0.00 ms; range is 0.50 .. 1837.50 ms
card: 1 <alsa_card.pci-0000_00_1b.0>
module: 7
properties:
alsa.resolution_bits = "16"
device.api = "alsa"
device.class = "sound"
alsa.class = "generic"
alsa.subclass = "generic-mix"
alsa.name = "ALC892 Analog"
alsa.id = "ALC892 Analog"
alsa.subdevice = "0"
alsa.subdevice_name = "subdevice #0"
alsa.device = "0"
alsa.card = "0"
alsa.card_name = "HDA Intel PCH"
alsa.long_card_name = "HDA Intel PCH at 0xf7430000 irq 39"
alsa.driver_name = "snd_hda_intel"
device.bus_path = "pci-0000:00:1b.0"
sysfs.path = "/devices/pci0000:00/0000:00:1b.0/sound/card0"
device.bus = "pci"
device.vendor.id = "8086"
device.vendor.name = "Intel Corporation"
device.product.id = "1e20"
device.product.name = "7 Series/C216 Chipset Family High Definition Audio Controller"
device.form_factor = "internal"
device.string = "front:0"
device.buffering.buffer_size = "352800"
device.buffering.fragment_size = "176400"
device.access_mode = "mmap+timer"
device.profile.name = "analog-stereo"
device.profile.description = "Analog Stereo"
device.description = "Built-in Audio Analog Stereo"
alsa.mixer_name = "Realtek ALC892"
alsa.components = "HDA:10ec0892,10438436,00100302"
module-udev-detect.discovered = "1"
device.icon_name = "audio-card-pci"
ports:
analog-input-front-mic: Front Microphone (priority 8500, latency offset 0 usec, available: yes)
properties:
device.icon_name = "audio-input-microphone"
analog-input-rear-mic: Rear Microphone (priority 8200, latency offset 0 usec, available: no)
properties:
device.icon_name = "audio-input-microphone"
analog-input-linein: Line In (priority 8100, latency offset 0 usec, available: no)
properties:
active port: <analog-input-front-mic>
index: 8
name: <alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo.monitor>
driver: <module-alsa-card.c>
flags: DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: IDLE
suspend cause:
priority: 1040
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 0.00 ms
max rewind: 344 KiB
sample spec: s16le 2ch 48000Hz
channel map: front-left,front-right
Stereo
used by: 0
linked by: 0
configured latency: 1837.50 ms; range is 0.50 .. 1837.50 ms
monitor_of: 6
card: 3 <alsa_card.usb-C-Media_Electronics_Inc._USB_Audio_Device-00>
module: 31
properties:
device.description = "Monitor of Audio Adapter (Unitek Y-247A) Analog Stereo"
device.class = "monitor"
alsa.card = "2"
alsa.card_name = "USB Audio Device"
alsa.long_card_name = "C-Media Electronics Inc. USB Audio Device at usb-0000:00:1d.0-1.7, full speed"
alsa.driver_name = "snd_usb_audio"
device.bus_path = "pci-0000:00:1d.0-usb-0:1.7:1.0"
sysfs.path = "/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.7/2-1.7:1.0/sound/card2"
udev.id = "usb-C-Media_Electronics_Inc._USB_Audio_Device-00"
device.bus = "usb"
device.vendor.id = "0d8c"
device.vendor.name = "C-Media Electronics, Inc."
device.product.id = "0014"
device.product.name = "Audio Adapter (Unitek Y-247A)"
device.serial = "C-Media_Electronics_Inc._USB_Audio_Device"
device.string = "2"
module-udev-detect.discovered = "1"
device.icon_name = "audio-card-usb"
* index: 9
name: <alsa_input.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-mono>
driver: <module-alsa-card.c>
flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: SUSPENDED
suspend cause: IDLE
priority: 9049
volume: mono: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 27111 / 41% / -23.00 dB
volume steps: 65537
muted: yes
current latency: 0.00 ms
max rewind: 0 KiB
sample spec: s16le 1ch 44100Hz
channel map: mono
Mono
used by: 0
linked by: 0
configured latency: 0.00 ms; range is 0.50 .. 2000.00 ms
card: 3 <alsa_card.usb-C-Media_Electronics_Inc._USB_Audio_Device-00>
module: 31
properties:
alsa.resolution_bits = "16"
device.api = "alsa"
device.class = "sound"
alsa.class = "generic"
alsa.subclass = "generic-mix"
alsa.name = "USB Audio"
alsa.id = "USB Audio"
alsa.subdevice = "0"
alsa.subdevice_name = "subdevice #0"
alsa.device = "0"
alsa.card = "2"
alsa.card_name = "USB Audio Device"
alsa.long_card_name = "C-Media Electronics Inc. USB Audio Device at usb-0000:00:1d.0-1.7, full speed"
alsa.driver_name = "snd_usb_audio"
device.bus_path = "pci-0000:00:1d.0-usb-0:1.7:1.0"
sysfs.path = "/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.7/2-1.7:1.0/sound/card2"
udev.id = "usb-C-Media_Electronics_Inc._USB_Audio_Device-00"
device.bus = "usb"
device.vendor.id = "0d8c"
device.vendor.name = "C-Media Electronics, Inc."
device.product.id = "0014"
device.product.name = "Audio Adapter (Unitek Y-247A)"
device.serial = "C-Media_Electronics_Inc._USB_Audio_Device"
device.string = "hw:2"
device.buffering.buffer_size = "176400"
device.buffering.fragment_size = "88200"
device.access_mode = "mmap+timer"
device.profile.name = "analog-mono"
device.profile.description = "Analog Mono"
device.description = "Audio Adapter (Unitek Y-247A) Analog Mono"
alsa.mixer_name = "USB Mixer"
alsa.components = "USB0d8c:0014"
module-udev-detect.discovered = "1"
device.icon_name = "audio-card-usb"
ports:
analog-input-mic: Microphone (priority 8700, latency offset 0 usec, available: unknown)
properties:
device.icon_name = "audio-input-microphone"
active port: <analog-input-mic>
index: 10
name: <PulseEffects_apps.monitor>
driver: <module-null-sink.c>
flags: DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: RUNNING
suspend cause:
priority: 1000
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 0.00 ms
max rewind: 1 KiB
sample spec: s16le 2ch 48000Hz
channel map: front-left,front-right
Stereo
used by: 1
linked by: 1
configured latency: 10.00 ms; range is 0.50 .. 2000.00 ms
monitor_of: 7
module: 33
properties:
device.description = "Monitor of PulseEffects(apps)"
device.class = "monitor"
device.icon_name = "audio-input-microphone"
index: 11
name: <PulseEffects_mic.monitor>
driver: <module-null-sink.c>
flags: DECIBEL_VOLUME LATENCY DYNAMIC_LATENCY
state: SUSPENDED
suspend cause: IDLE
priority: 1000
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
base volume: 65536 / 100% / 0.00 dB
volume steps: 65537
muted: no
current latency: 0.00 ms
max rewind: 344 KiB
sample spec: s16le 2ch 44100Hz
channel map: front-left,front-right
Stereo
used by: 0
linked by: 0
configured latency: 0.00 ms; range is 0.50 .. 2000.00 ms
monitor_of: 8
module: 34
properties:
device.description = "Monitor of PulseEffects(mic)"
device.class = "monitor"
device.icon_name = "audio-input-microphone"
The output of the command pacmd list-source-outputs.
1 source output(s) available.
index: 115
driver: <protocol-native.c>
flags: START_CORKED
state: RUNNING
source: 10 <PulseEffects_apps.monitor>
volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
balance 0.00
muted: no
current latency: 2.98 ms
requested latency: 10.00 ms
sample spec: float32le 2ch 48000Hz
channel map: front-left,front-right
Stereo
resample method: copy
owner module: 12
client: 408 <PulseEffects>
properties:
application.id = "com.github.wwmm.pulseeffects.sinkinputs"
media.name = "Record Stream"
application.name = "PulseEffects"
native-protocol.peer = "UNIX socket client"
native-protocol.version = "32"
application.icon_name = "pulseeffects"
application.process.id = "19356"
application.process.user = "alex"
application.process.host = "alex-workpc-arch"
application.process.binary = "pulseeffects"
application.language = "en_US.UTF-8"
window.x11.display = ":1"
application.process.machine_id = "4c308eb5d77a4e3b8280c9afe3cc533b"
application.process.session_id = "c3"
module-stream-restore.id = "source-output-by-application-id:com.github.wwmm.pulseeffects.sinkinputs"
Screenshots of Pavucontrol tabs.
Regular:
When Beatport page loading, and there are some sound lags (the new one appears at the end):
But I have lags also when there is no additional channel.
Other tabs:
AlexWayfer
on 6 Jun 2018
sudo renice -10 -p $(pidof pulseeffects) ?
beckend
on 15 Jul 2018
sudo renice -10 -p $(pidof pulseeffects)?
Thank you, but it didn't help too much. :(
Maybe a little.
AlexWayfer
on 16 Jul 2018
I found that when setting Sound Preferences to use PulseEffects(apps) for all output, there's lots of distortion especially when multiple sound streams happen. (simple sound effects in GNOME/MATE desktop create great amounts of distortion and stuttering.) If you use "Audio Analog Stereo" (or your default output sink itself without PulseEffects), there is no issue. (And then, individually enable PulseEffects for something like YouTube on Chrome.). If I do this, I get the least amount of stuttering. The second that I tell the mixer to use the PulseEffects device for all output, there's lagging, stuttering, distortion, and just the unsettling feeling that doing any little thing on the computer will throw off the audio. I tried screwing around with buffer and block size in dconf, but doesn't seem to change much or just gets worse. I'm trying to get debug logs but nothing at all prints when I type the pulse effects debug command. I'm going to try and figure out why and post anything I can find.
Also, the other issue with using the PulseEffects sink in the volume mixer is that volume control doesn't work or stutters/lags like crazy when the volume is adjusted. It almost seems like there's some sort of feedback loop going on, but I can't tell exactly.
xtknight
on 31 Jul 2018
👍1
@xtknight, thank you!
AlexWayfer
on 31 Jul 2018
After selecting "Built-in audio" it resets everything to use the default device, so you have to go back in PulseEffects and enable for each app individually. (And apparently it resets to default every time a new stream even starts in Chrome...hmm) I haven't yet experimented much beyond just using Chrome with PulseEffects, but let me know if this helps solve the stuttering issue. Then, we can figure out if it's an issue with multiple streams itself, or just an issue with having PulseEffects as the default system-wide sink in Sound Preferences.
xtknight
on 31 Jul 2018
@xtknight you should see log output when running PE as G_MESSAGES_DEBUG=pulseeffects pulseeffects
You should never select PulseEffects(apps) or PulseEffects(mic) as default output device. This will definitely cause troubles. Unfortunately there is no way for me to forbid the user to do this.
Multiple streams should not be an issue as long as you use the limiter as the first plugin in the effects chain. Other plugins may have their input saturated when there is a lot of apps playing audio.
In case you do not want to enable each app individually you can turn on the option Enable All Applications in PE settings menu.
@AlexWayfer does this fix your problem?
wwmm
on 31 Jul 2018
@wwmm: thanks for the insight. Would probably be a good idea to mention in documentation in red letters that using PulseEffects as the default device is bad. The workflow of the system wasn't clear to me at first. (apologies if I happened to miss something). I'm not sure if this was the original poster's problem, but just throwing it out there because that's what gave me similar issues.
In my case, using 'Enable all apps' with two concurrent audio streams from Chrome with the Equalizer enabled results in no discernable stuttering. Audio playback seems fluent; real happy with it. Let's hope the same holds true for the OP. The EQ saved my new headphone purchase.
xtknight
on 31 Jul 2018
👍1
Now that we finally have documentation it is a good idea to tell this there. I will try to remember to do that :-)
wwmm
on 31 Jul 2018
@wwmm I've also discovered some stuttering and jamming, as well as crackling with multiple streams. It doesn't seem to happen on one stream (or perhaps, it just happens a lot less?). I can hear one of the streams start to play a tad faster or slow down all of a sudden. I suppose that because the pulseeffects process is scheduled on the CPU like any other process, this is possible, but I wonder how pulseaudio avoids the issue. I suppose that this could be the same issue the original poster is happening. It's faint, but quite noticeable even when I try to ignore it. Interestingly, the time it takes certain streams to start also seems to be affected, but I haven't been able to measure this objectively. (After I press play on YouTube, it takes longer than I usually remember for the audio to begin actually playing.) There's nothing special printed in the logs about it, and I'm pretty sure it's just a timing-related issue.
Example case:
Turning on the Test Signals triangle wave and then starting any other stream causes a brief crackling. The crackling also sometimes happens at random times during playback. This happens even with no effects enabled.
Example case 2:
Adjust volume on the applications tab inside of PulseEffects when enabling it on that app vs. disabling it on that app. When disabled, volume control is smooth and normal, but when enabled, it sounds like the audio is chopped up and distorted, with portions of it replaying, every time the volume is adjusted. This is even with no effect filters enabled.
pulseeffects CPU usage:
app enabled(EQ filter)+continual volume control adjustment, single stream: ~44%
app enabled(EQ filter)+normal playback, single stream: ~17%
app enabled(no filters)+continual volume control adjustment, single stream: ~36%
app enabled(no filters)+normal playback, single stream: ~11%
app disabled+normal playback, single stream: ~1%
Some logs:
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:30.079: calibration_signals: READY
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:30.084: calibration_signals: PAUSED
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:30.085: calibration_signals: PLAYING
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:30.098: sie: NULL -> READY -> PLAYING
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:30.099: sie: READY -> PAUSED -> PLAYING
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:30.100: sie: pulsesrc latency [us]: 10000
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:30.100: sie: pulsesrc buffer [us]: 200000
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:32.220: sie: pulsesink latency [us]: 10000
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:32.220: sie: pulsesink buffer [us]: 200000
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:32.222: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:1868): pulseeffects-DEBUG: 20:07:35.383: sie: NULL -> VOID_PENDING
A lot of streams take around 2 seconds to start, like you see here. (20:07:30~20:07:32) Is this normal? But it's not always like this. Sometimes they start instantly, sometimes they delay for 2 seconds. I'm not sure what the pattern is.
xtknight
on 2 Aug 2018
You should never select PulseEffects(apps) or PulseEffects(mic) as default output device. This will definitely cause troubles. Unfortunately there is no way for me to forbid the user to do this.
Multiple streams should not be an issue as long as you use the limiter as the first plugin in the effects chain. Other plugins may have their input saturated when there is a lot of apps playing audio.
In case you do not want to enable each app individually you can turn on the option Enable All Applications in PE settings menu.
@AlexWayfer does this fix your problem?
My active output device is sound card, not PulseEffects.
Limiter is the first, but disabled, plugin:
Enable All Applications option is active.
@wwmm I've also discovered some stuttering and jamming, as well as crackling with multiple streams. It doesn't seem to happen on one stream (or perhaps, it just happens a lot less?).
For me it happens also when here is a single stream (screenshot above). :disappointed:
AlexWayfer
on 2 Aug 2018
I can try to programmatically record these lags, but I don't know a good way to do this.
AlexWayfer
on 2 Aug 2018
One of the things that make this kind of problem hard to fix is that they are not easy to describe in words. Specially to non native english speakers like me. So an audio and video recording can help @AlexWayfer.
@xtknight I believe the crackling you hear is caused by audio clipping (the input of something was saturated). I did some tests here with the test signal generator and it seems we can not protect everything with the limiter. We should take care to not saturate the null sinks used by PE (PulseEffects(apps) in this case) because they receive audio before the limiter. In the image below I have noises
We can see clearly that PulseEffects(apps) is saturated. If we turn off all apps in PE we still have noises because the sound card is still saturated
Now if I decrease the test signal volume so that PulseEffects(apps) is not saturated everything is fine
Unfortunately the only thing that can be done in this case is reduce the volume. I can't avoid the null sink saturation from PE. This would have to be done in Pulseaudio.
The delays you see sometimes is normal. PE always checks if there is an audio app actually playing. If there is none our GStreamer pipeline is put in the null state. This is done to save power in laptops and on other machines with weak processors. There is no point in processing silence. Whenever you add a stream while there are others playing the delay will not occur because our GStreamer pipeline do not have to be restarted.
The noises that happen when change volume usually disappears when we set a lower latency in PE settings menu. Like 1000 us. I honestly don't know what happens between GStreamer and Pulseaudio under the hoods that could explain this. But I never heard sections being replayed.
I really doubt that PE logs will show anything useful for all the issues reported here. It seems to me that this problem is at a lower level. Maybe in GStreamer or in Pulseaudio. Maybe we should start to look at their logs. Pulseaudio logs can be taken with the steps in the advanced section of Reporting-Bugs. Gstreamer logs can be taken executing pulseeffects as GST_DEBUG=4 pulseeffects. Higher numbers can be used but GStreamer log can become ridiculously large above 4.
wwmm
on 2 Aug 2018
Some logs at some lags (not every) from G_MESSAGES_DEBUG=pulseeffects GST_DEBUG=4 pulseeffects:
(pulseeffects:6072): pulseeffects-DEBUG: 19:00:27.333: sie: PAUSED -> PLAYING -> VOID_PENDING
0:00:46.747273013 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.062083333, resyncing
0:00:50.419181654 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.060729166, resyncing
0:00:50.419346818 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:00:50.419526565 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:08.436149563 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.077729166, resyncing
0:01:08.436424160 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:08.436567965 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:08.436601483 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:08.436864667 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:08.436994996 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:08.437117525 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:08.437258218 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:08.437585519 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.002083333, resyncing
0:01:19.248652684 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.063791666, resyncing
0:01:19.248762430 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:19.248962091 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:19.249057614 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:28.729155111 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.067187500, resyncing
0:01:28.750936268 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:28.751115821 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:28.751214796 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.000937500, resyncing
0:01:28.751316318 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:28.751414515 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:28.751502619 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:28.751597690 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:31.844479961 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.064125000, resyncing
0:01:31.844691567 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:31.844768895 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:31.844924254 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:31.845078413 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:38.141976104 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.073937500, resyncing
0:01:38.142173989 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:38.142396958 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:38.142414263 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:38.142756047 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:38.142772641 6072 0x56085a70b8f0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:38.143050251 6072 0x7fa9180068a0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.007979166, resyncing
(pulseeffects:6072): pulseeffects-CRITICAL **: 19:01:56.982: pulse_manager: failed to move sink input 134 to PE
(pulseeffects:6072): pulseeffects-CRITICAL **: 19:01:56.985: pulse_manager: failed to move sink input 135 to PE
Output of sudo journalctl -fb | grep -i pulse is empty after any actions.
AlexWayfer
on 2 Aug 2018
If pulseaudio log is empty the step set-log-level 4 did not work for some reason. Even changing volume trigguers lots of output in pulseaudio log.
Your GStreamer log has lots of lines that I usually do not have unless I set the block size to 2048
pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
Which block size do you have?
Try to lower it to 256 and see if it makes any difference. Under flows in pulsesink usually lead to noise.
wwmm
on 2 Aug 2018
The pulse_manager: failed to move sink input 134 to PE are also odd. I never have those. This is a sign that something is not right.
wwmm
on 2 Aug 2018
If pulseaudio log is empty the step set-log-level 4 did not work for some reason. Even changing volume trigguers lots of output in pulseaudio log.
I missed it! Sorry. But it's empty anyway after:
- Run
pacmd
1.1. Enterset-log-level 4(empty output)
1.2. Don't exit - Run
sudo journalctl -fb | grep -i pulsein a new terminal - Run
pulseeffectsin the third terminal
Which block size do you have?
512.
Try to lower it to 256 and see if it makes any difference.
Done. No logs from pulseaudio at change. And there are still lags. Maybe even more. And pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow in logs. Many! Look at frequency:
0:05:13.705523024 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:13.717184295 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:13.728698204 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:14.158251204 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:14.367089496 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:14.378820434 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:14.506716196 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:14.517327842 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:14.588062497 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:14.879620654 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:15.017600082 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:15.168327172 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:15.226513442 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:15.238061746 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:15.667499021 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:15.725685114 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:15.877265201 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:15.887952937 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:16.027511062 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:16.108767685 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:16.317834952 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:16.468748679 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:16.526628844 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:16.747359192 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:17.176938012 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:17.328021853 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:17.385866312 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:05:17.478686673 10924 0x562a6cc87ea0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
Buffer is 200000, latency is 10000.
With 1024 block size there are lags too. :(
AlexWayfer
on 2 Aug 2018
The pulse_manager: failed to move sink input 134 to PE are also odd. I never have those. This is a sign that something is not right.
https://github.com/wwmm/pulseeffects/issues/217#issuecomment-395050149
AlexWayfer
on 2 Aug 2018
At least here I only have under flows if I set the block size too high. It is strange that they increase when you reduce the block. And if you set the buffer to 50000 with a block size of 512 or less?
wwmm
on 2 Aug 2018
And if you set the buffer to 50000 with a block size of 512 or less?
Doesn't affect.
AlexWayfer
on 2 Aug 2018
Here there is an explanation for under flows:
GST_QOS_TYPE_UNDERFLOW: an element is receiving buffers too slowly and has to drop them because they are too late. Upstream should increase the processing rate
So the buffers are take too long to be sent. I wonder if pulseaudio null sinks are having issues in your system. It is from them that GStreamer pipeline is taking audio. Maybe they are not being fast enough.
And it is still strange that you do not have pulseaudio logs. Pulseaudio output is very verbose. Huge amount of lines
wwmm
on 2 Aug 2018
And it is still strange that you do not have pulseaudio logs. Pulseaudio output is very verbose. Huge amount of lines
grep worked for sudo password asking… sorry, I think this is can be clarified in the manual.
> sudo journalctl -fb | grep -i pulse
Job 1, 'sudo journalctl -fb | grep -i p…' has stopped
> sudo journalctl -fb
[sudo] password for alex:
-- Logs begin at Thu 2018-07-05 12:00:44 MSK. --
Some logs from Pulseaudio at single refresh of Beatport artist page with embedded (not playing) player (as I wrote above) while music playing (from Soundcloud in this example, the same Chromium window); yes, there are lags;
Aug 02 20:06:42 alex-workpc-arch pulseaudio[1455]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Aug 02 20:06:42 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Requested to rewind 1920 bytes.
Aug 02 20:06:42 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink.c: Processing rewind...
Aug 02 20:06:42 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: Freeing input 229 "Playback"
Aug 02 20:06:42 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink-input.c: Have to rewind 1652 bytes on render memblockq.
Aug 02 20:06:42 alex-workpc-arch pulseaudio[1455]: D: [null-sink] source.c: Processing rewind...
Aug 02 20:06:42 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Rewound 1652 bytes.
Aug 02 20:06:42 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] client.c: Freed 193 "Chromium"
Aug 02 20:06:42 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] protocol-native.c: Connection died.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] client.c: Created 194 "Native client (UNIX socket client)"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Protocol version: remote 32, local 32
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] protocol-native.c: Got credentials: uid=1000 gid=100 success=1
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: SHM possible: yes
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Negotiated SHM: yes
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Memfd possible: yes
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Negotiated SHM type: shared memfd
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblock.c: Using shared memfd memory pool with 1024 slots of size 64.0 KiB each, total size is 64.0 MiB, maximum usable slot size is 65472
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] srbchannel.c: SHM block is 65472 bytes, ringbuffer capacity is 2 * 32712 bytes
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Enabling srbchannel...
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] module-augment-properties.c: Looking for .desktop file for chromium
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Client enabled srbchannel.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Chromium.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] module-intended-roles.c: Not setting device for stream Playback, because already set.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] sink-input.c: Negotiated format: pcm, format.sample_format = "\"float32le\"" format.rate = "44100" format.channels = "1" format.channel_map = "\"mono\""
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: Trying to change sample rate
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Chromium.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] module-stream-restore.c: Restoring mute state for sink input sink-input-by-application-name:Chromium.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: Resampler:
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: rate 44100 -> 48000 (method speex-float-1)
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: format float32le -> s16le (intermediate float32le)
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: channels 1 -> 2 (resampling 1)
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: Channel matrix:
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: I00
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: +------
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: O00 | 1.000
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: O01 | 1.000
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] remap_sse.c: Using SSE2 mono to stereo remapping
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] speex.c: Choosing speex quality setting 1.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: Created input 230 "Playback" on PulseEffects_apps with sample spec float32le 1ch 44100Hz and channel map mono
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.icon_name = "chromium-browser"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: media.name = "Playback"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.name = "Chromium"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: native-protocol.peer = "UNIX socket client"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: native-protocol.version = "32"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.id = "6263"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.user = "alex"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.host = "alex-workpc-arch"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.binary = "chromium"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.language = "en_US.UTF-8"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: window.x11.display = ":1"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.machine_id = "4c308eb5d77a4e3b8280c9afe3cc533b"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.session_id = "c2"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: module-stream-restore.id = "sink-input-by-application-name:Chromium"
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] protocol-native.c: Requested tlength=69.66 ms, minreq=11.61 ms
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Adjust latency mode enabled, configuring sink latency to half of overall latency.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Requested latency=23.22 ms, Received latency=23.22 ms
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=8192, base=4, prebuf=6148, minreq=2048 maxrewind=0
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=8192, base=4, prebuf=6148, minreq=2048 maxrewind=0
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] protocol-native.c: Final latency 69.66 ms = 23.22 ms + 2*11.61 ms + 23.22 ms
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink-input.c: Requesting rewind due to uncorking
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Requested to rewind 1920 bytes.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink.c: Processing rewind...
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink-input.c: Have to rewind 1248 bytes on render memblockq.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] source.c: Processing rewind...
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Rewound 1248 bytes.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Requested to rewind 1920 bytes.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink.c: Processing rewind...
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink-input.c: Have to rewind 800 bytes on render memblockq.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink-input.c: Have to rewind 1360 bytes on implementor.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] source.c: Processing rewind...
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Rewound 800 bytes.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Aug 02 20:06:44 alex-workpc-arch pulseaudio[1455]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
Aug 02 20:06:49 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Requested to rewind 1920 bytes.
Aug 02 20:06:49 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: Freeing input 230 "Playback"
Aug 02 20:06:49 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink.c: Processing rewind...
Aug 02 20:06:49 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink-input.c: Have to rewind 1732 bytes on render memblockq.
Aug 02 20:06:49 alex-workpc-arch pulseaudio[1455]: D: [null-sink] source.c: Processing rewind...
Aug 02 20:06:49 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Rewound 1732 bytes.
Aug 02 20:06:49 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] client.c: Freed 194 "Chromium"
Aug 02 20:06:49 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] protocol-native.c: Connection died.
Aug 02 20:06:55 alex-workpc-arch pulseaudio[1455]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
Aug 02 20:06:59 alex-workpc-arch pulseaudio[1455]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
Aug 02 20:07:03 alex-workpc-arch pulseaudio[1455]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
Wakeup from ALSA! continues, there are no other logs and no lags after this page reload.
Switch Soundcloud track and lag at 20:09:48:
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] client.c: Created 195 "Native client (UNIX socket client)"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Protocol version: remote 32, local 32
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] protocol-native.c: Got credentials: uid=1000 gid=100 success=1
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: SHM possible: yes
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Negotiated SHM: yes
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Memfd possible: yes
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Negotiated SHM type: shared memfd
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblock.c: Using shared memfd memory pool with 1024 slots of size 64.0 KiB each, total size is 64.0 MiB, maximum usable slot size is 65472
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] srbchannel.c: SHM block is 65472 bytes, ringbuffer capacity is 2 * 32712 bytes
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Enabling srbchannel...
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] module-augment-properties.c: Looking for .desktop file for chromium
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Client enabled srbchannel.
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Chromium.
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] module-intended-roles.c: Not setting device for stream Playback, because already set.
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] sink-input.c: Negotiated format: pcm, format.sample_format = "\"float32le\"" format.rate = "44100" format.channels = "2" format.channel_map = "\"front-left,front-right\""
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: Trying to change sample rate
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Chromium.
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] module-stream-restore.c: Restoring mute state for sink input sink-input-by-application-name:Chromium.
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: Resampler:
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: rate 44100 -> 48000 (method speex-float-1)
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: format float32le -> s16le (intermediate float32le)
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] resampler.c: channels 2 -> 2 (resampling 2)
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] speex.c: Choosing speex quality setting 1.
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: Created input 231 "Playback" on PulseEffects_apps with sample spec float32le 2ch 44100Hz and channel map front-left,front-right
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.icon_name = "chromium-browser"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: media.name = "Playback"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.name = "Chromium"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: native-protocol.peer = "UNIX socket client"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: native-protocol.version = "32"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.id = "6263"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.user = "alex"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.host = "alex-workpc-arch"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.binary = "chromium"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.language = "en_US.UTF-8"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: window.x11.display = ":1"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.machine_id = "4c308eb5d77a4e3b8280c9afe3cc533b"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: application.process.session_id = "c2"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: module-stream-restore.id = "sink-input-by-application-name:Chromium"
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] protocol-native.c: Requested tlength=69.66 ms, minreq=11.61 ms
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Adjust latency mode enabled, configuring sink latency to half of overall latency.
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] protocol-native.c: Requested latency=23.22 ms, Received latency=23.22 ms
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=16384, base=8, prebuf=12296, minreq=4096 maxrewind=0
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=16384, base=8, prebuf=12296, minreq=4096 maxrewind=0
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] protocol-native.c: Final latency 69.66 ms = 23.22 ms + 2*11.61 ms + 23.22 ms
Aug 02 20:09:43 alex-workpc-arch pulseaudio[1455]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Aug 02 20:09:48 alex-workpc-arch pulseaudio[1455]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Aug 02 20:09:48 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Requested to rewind 1920 bytes.
Aug 02 20:09:48 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] sink-input.c: Freeing input 231 "Playback"
Aug 02 20:09:48 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink.c: Processing rewind...
Aug 02 20:09:48 alex-workpc-arch pulseaudio[1455]: D: [null-sink] sink-input.c: Have to rewind 200 bytes on render memblockq.
Aug 02 20:09:48 alex-workpc-arch pulseaudio[1455]: D: [null-sink] source.c: Processing rewind...
Aug 02 20:09:48 alex-workpc-arch pulseaudio[1455]: D: [null-sink] module-null-sink.c: Rewound 200 bytes.
Aug 02 20:09:48 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] client.c: Freed 195 "Chromium"
Aug 02 20:09:48 alex-workpc-arch pulseaudio[1455]: I: [pulseaudio] protocol-native.c: Connection died.
Aug 02 20:09:51 alex-workpc-arch pulseaudio[1455]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
One of the things that make this kind of problem hard to fix is that they are not easy to describe in words. Specially to non native english speakers like me. So an audio and video recording can help @AlexWayfer.
I've got it, I think. Thanks to this guide.
(Oh, I can't attach .ogg or .mp3 file here)
I chose monotone bass track for more clarity. Do you hear these lags? I was reloaded Beatport page at the background every second, I think.
AlexWayfer
on 2 Aug 2018
I can hear the noises. I think that they are related to the under flows. The question is why you always have them.
I think you have too many lines with underrun in your Pulseaudio's logs. I don't know exactly what they are but I don't think it is a good thing. These underruns are happening in the null sink used by PE at the exact moments you say you have the lags.
wwmm
on 3 Aug 2018
under flows
I don't know what is it, sorry.
Without PulseEffects there are no lags (and bass, lol).
But there are some logs at Beatport page reloading, maybe there can be helpful:
Aug 03 12:20:47 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
Aug 03 12:20:49 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to end of underrun.
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Latency set to 16.00ms
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: hwbuf_unused=349980
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: setting avail_min=87848
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested volume: front-left: 48492 / 74% / -7.85 dB, front-right: 48492 / 74% / -7.85 dB
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Got hardware volume: front-left: 50097 / 76% / -7.00 dB, front-right: 50097 / 76% / -7.00 dB
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Calculated software volume: front-left: 63436 / 97% / -0.85 dB, front-right: 63436 / 97% / -0.85 dB (accurate-enough=no)
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] sink.c: Volume not changing
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 2820 bytes.
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 2564 bytes.
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: Freeing input 18 "Playback"
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 641
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 641
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 2564 bytes.
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] sink.c: latency = 8882
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 2564 bytes on render memblockq.
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] client.c: Freed 30 "Chromium"
Aug 03 12:20:52 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] protocol-native.c: Connection died.
Aug 03 12:20:53 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
Aug 03 12:20:56 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] client.c: Created 31 "Native client (UNIX socket client)"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] protocol-native.c: Protocol version: remote 32, local 32
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] protocol-native.c: Got credentials: uid=1000 gid=100 success=1
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] protocol-native.c: SHM possible: yes
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] protocol-native.c: Negotiated SHM: yes
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] protocol-native.c: Memfd possible: yes
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] protocol-native.c: Negotiated SHM type: shared memfd
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] memblock.c: Using shared memfd memory pool with 1024 slots of size 64.0 KiB each, total size is 64.0 MiB, maximum usable slot size is 65472
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] srbchannel.c: SHM block is 65472 bytes, ringbuffer capacity is 2 * 32712 bytes
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] protocol-native.c: Enabling srbchannel...
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] module-augment-properties.c: Looking for .desktop file for chromium
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] protocol-native.c: Client enabled srbchannel.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Chromium.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] module-intended-roles.c: Not setting device for stream Playback, because already set.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] sink-input.c: Negotiated format: pcm, format.sample_format = "\"float32le\"" format.rate = "44100" format.channels = "1" format.channel_map = "\"mono\""
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: Trying to change sample rate
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink.c: Cannot update rate, SINK_IS_RUNNING, will keep using 44100 Hz
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Chromium.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] module-stream-restore.c: Restoring mute state for sink input sink-input-by-application-name:Chromium.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo becomes busy, resuming.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] resampler.c: Forcing resampler 'copy', because of fixed, identical sample rates.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] resampler.c: Resampler:
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] resampler.c: rate 44100 -> 44100 (method copy)
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] resampler.c: format float32le -> s16le (intermediate s16le)
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] resampler.c: channels 1 -> 2 (resampling 1)
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] resampler.c: Channel matrix:
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] resampler.c: I00
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] resampler.c: +------
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] resampler.c: O00 | 1.000
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] resampler.c: O01 | 1.000
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] remap_sse.c: Using SSE2 mono to stereo remapping
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: Created input 19 "Playback" on alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo with sample spec float32le 1ch 44100Hz and channel map mono
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: application.icon_name = "chromium-browser"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: media.name = "Playback"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: application.name = "Chromium"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: native-protocol.peer = "UNIX socket client"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: native-protocol.version = "32"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: application.process.id = "7771"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: application.process.user = "alex"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: application.process.host = "alex-workpc-arch"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: application.process.binary = "chromium"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: application.language = "en_US.UTF-8"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: window.x11.display = ":1"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: application.process.machine_id = "4c308eb5d77a4e3b8280c9afe3cc533b"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: application.process.session_id = "c2"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] sink-input.c: module-stream-restore.id = "sink-input-by-application-name:Chromium"
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] protocol-native.c: Requested tlength=69.66 ms, minreq=11.61 ms
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] protocol-native.c: Adjust latency mode enabled, configuring sink latency to half of overall latency.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] protocol-native.c: Requested latency=23.22 ms, Received latency=23.22 ms
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=8192, base=4, prebuf=6148, minreq=2048 maxrewind=0
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=8192, base=4, prebuf=6148, minreq=2048 maxrewind=0
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: I: [pulseaudio] protocol-native.c: Final latency 69.66 ms = 23.22 ms + 2*11.61 ms + 23.22 ms
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Latency set to 16.00ms
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: hwbuf_unused=349980
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: setting avail_min=87848
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested volume: front-left: 48492 / 74% / -7.85 dB, front-right: 48492 / 74% / -7.85 dB
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Got hardware volume: front-left: 50097 / 76% / -7.00 dB, front-right: 50097 / 76% / -7.00 dB
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Calculated software volume: front-left: 63436 / 97% / -0.85 dB, front-right: 63436 / 97% / -0.85 dB (accurate-enough=no)
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] sink.c: Volume not changing
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to end of underrun.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] sink-input.c: Requesting rewind due to uncorking
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 2820 bytes.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 2564 bytes.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 641
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 641
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 2564 bytes.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] sink.c: latency = 6993
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 2564 bytes on render memblockq.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.usb-C-Media_Electronics_Inc._USB_Audio_Device-00.analog-stereo becomes busy, resuming.
Aug 03 12:21:00 alex-workpc-arch pulseaudio[1532]: D: [alsa-sink-USB Audio] alsa-sink.c: Wakeup from ALSA!
@wwmm thanks for the insight. I wasn't aware you weren't a non-native English speaker. your English is very good :) Anyway, I'm still battling crackling and I even got consistent crackling with a sine wave for a long time. It was just crackling for the entire time. Unfortunately, I can't reproduce such things consistently. And I don't know if it's a pulseaudio or pulseeffects issue. If I can reproduce something consistently with logs and a recording, then I will create a new issue about it because it may not be related to Alex's issue. I get underruns at the beginning of every stream, but this seems to be a pulseaudio thing. Adjusting latency didn't help anything for me as far as I can tell.
xtknight
on 3 Aug 2018
I am brazilian :-)
I took a look at my logs and sometimes I also have the underruns in pulseaudio's logs. So I guess we shouldn't worry about them. But the underflows in GStreamer I do not have.
You can investigate the cracks with the test signals. But always remember to reduce the volumes and check in pavucontrol if something is saturated. Otherwise you will always have noises even if everything is fine.
wwmm
on 4 Aug 2018
During this log there are a total of two cracks during normal audio in the middle of a YouTube music video. Unfortunately that's the best I can provide. I'm getting very similar messages as Alex, but it's happening quite rarely and seems hard to record or debug. I don't think it happens without using PulseEffects. But, it could still be some bug in the PulseAudio internal machinery that PulseEffects uses. Just mainly random rewinds basically.. What do you think is the next step towards identifying and resolving these issues?
D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
D: [null-sink] sink-input.c: Requesting rewind due to uncorking
D: [null-sink] module-null-sink.c: Requested to rewind 11520 bytes.
D: [null-sink] sink.c: Processing rewind...
D: [null-sink] sink-input.c: Have to rewind 5280 bytes on render memblockq.
D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
D: [null-sink] sink-input.c: Have to rewind 5280 bytes on render memblockq.
D: [null-sink] source.c: Processing rewind...
D: [null-sink] module-null-sink.c: Rewound 5280 bytes.
D: [null-sink] sink-input.c: Requesting rewind due to corking
D: [null-sink] module-null-sink.c: Requested to rewind 11520 bytes.
D: [null-sink] sink.c: Processing rewind...
D: [null-sink] sink-input.c: Have to rewind 9966 bytes on render memblockq.
D: [null-sink] sink-input.c: Have to rewind 9966 bytes on render memblockq.
D: [null-sink] sink-input.c: Have to rewind 3168 bytes on implementor.
D: [null-sink] sink-input.c: Have to rewind 9966 bytes on render memblockq.
D: [null-sink] source.c: Processing rewind...
D: [null-sink] module-null-sink.c: Rewound 9966 bytes.
D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
D: [null-sink] module-null-sink.c: Requested to rewind 11520 bytes.
D: [null-sink] sink.c: Processing rewind...
I: [pulseaudio] sink-input.c: Freeing input 237 "Playback"
D: [null-sink] sink-input.c: Have to rewind 7800 bytes on render memblockq.
D: [null-sink] sink-input.c: Have to rewind 7800 bytes on render memblockq.
D: [null-sink] source.c: Processing rewind...
D: [null-sink] module-null-sink.c: Rewound 7800 bytes.
I: [pulseaudio] client.c: Freed 203 "Chrome"
I: [pulseaudio] protocol-native.c: Connection died.
New potential insight:
Happened again. I'm getting cracks as soon as "Connection died" happens. These messages appear all at about the same time as the crack, though.
D: [null-sink] source.c: Processing rewind...
D: [null-sink] module-null-sink.c: Rewound 7926 bytes.
I: [pulseaudio] client.c: Freed 207 "Chrome"
I: [pulseaudio] protocol-native.c: Connection died.
Some other logs from PulseEffects:
0:41:38.553053461 8818 0x7f0050003ca0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
11:38:30.088529057 8818 0x55aa90346370 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
11:40:58.628346955 8818 0x55aa90346630 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
11:44:10.932906045 8818 0x7f0080004050 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
11:44:54.094641114 8818 0x7f0080004050 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
11:45:29.813289189 8818 0x55aa903751e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
36:10:57.586572087 8818 0x55aa90410800 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
36:11:04.125739699 8818 0x55aa90410800 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
36:11:17.401588667 8818 0x55aa90410800 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
36:12:33.638421153 8818 0x55aa90410800 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
36:12:56.801266231 8818 0x55aa90410800 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
37:21:19.949087648 8818 0x7f007c05c8f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
37:30:15.677696099 8818 0x55aa8ff5d5e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:
I have confirmed that some of the cracks are due to "Unexpected discontinuity", but not all.
xtknight
on 5 Aug 2018
Alex also has discontinuity in the audio buffer before the under flows. It makes sense to me to have noises after a discontinuity. The question is if there is something that I can do on my side to fix that.
Was Chrome the only audio app opened at the moment? If yes PulseEffects would put its GStreamer's pipeline in the null state after chrome connection died. The noise could be related to the pipeline restart. I think that sometimes I hear noises when GStreamer's pipeline is restarted. I don't know yet what could be done to improve this.
wwmm
on 5 Aug 2018
Was Chrome the only audio app opened at the moment?
If you're asking me — yes, screenshot is above. But multiple tabs.
AlexWayfer
on 5 Aug 2018
I was listening a song, and after it ended many lines like this continued to appear:
0:06:30.474472804 4344 0x564d4a5b0cf0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
And then some red logs and everything stops. It's too long, so I'm attaching the file: pulseffects_logs.txt
AlexWayfer
on 9 Aug 2018
Hi Guys, I had been experimenting a kind of this issue too.
With web browser streaming, with clementine playing mp3 and streaming too, vlc and any audio or video player.
My enviroment:
Archlinux
Gnome 3.28.2
Pulseeffects 4.2.4
In my case, setting the LATENCY parameter for the output in PE to its minimal value(100 us) the weird noise while adjusting volume almost disapeared...
I'm not sure if this setup is correct or "recomended" but at leats for me got better.
I hope this comment help out to resolve definitely the issue.
PE is a great software. Thanks to the developers!
Sorry about my english.
davidgxxl
on 9 Aug 2018
Hello! I have just released PE 4.2.5 with a few changes in the way that the block size is set. It may help with this issue. Try to play again with the block sizes values and see if there is any change
wwmm
on 9 Aug 2018
❤1
Hi Wellington.
I just updated it and same status in my enviroment!
If you need more detailed info please let me know.. I'll be happy to help.
Obrigado!
davidgxxl
on 9 Aug 2018
@davidgxxl I think that the issue you have with volumes has a different source than the one from the opener. I think we always had this noise when changing app volumes. It seems I have them even changing volumes in pavucontrol while PE is running.
I Looked at GStreamer logs here and it is clear that pulseaudio delays the audio data delivery whenever the app volume is changed. This delay leads to GStreamer buffer underflows that are the ones causing the noise. It makes sense that small latency values help. In this case we will be asking smaller chunks of data to pulseaudio and it will be easier for it to deliver the data in the moment GStreamer needs it. This may be a pulseaudio issue. I am looking at the code I wrote in PulseEffects to change the volumes and there is nothing that is not done by many other programs out there.
wwmm
on 11 Aug 2018
Hi @wwmm, Ok. I see!
Likewise, thanks for this amazing EQ.
Greetings.
davidgxxl
on 11 Aug 2018
@wwmm I've got a reproducible test case. At least for me, some stutters are coming from new gstreamer streams starting and ending. There's a very clear stutter every time it happens. This is with PulseEffects 4.2.2. I tried master branch but PulseEffects doesn't work at all with some "sie: Internal data stream error"? :( I may report a more detailed bug on that later after more investigation.
Crackling Recording (sine wave set to 0% volume): audio_stuttering_gstlaunch.zip
Played this song in the background and then I quickly ran/terminated a sine test using gstreamer several times.
https://www.youtube.com/watch?v=8b-FEaGJG8Y
$ gst-launch-1.0 audiotestsrc ! audioconvert ! audioresample ! pulsesink
Every time you hear cracks It was me starting the command and pressing Ctrl+C, starting the command pressing Ctrl+C, over and over again. An audibly identical crack occurs on both starting and terminating the command with Ctrl+C.
This does not happen when I assign the gstreamer sine test to my Default PulseAudio sink and restart the test command several times. No crackling at all.
The really strange thing is that the delay manifests itself differently depending on the song position. In that video, for the first 10 seconds I can hardly hear any distortion (although it sounds slowed down or sped up). But after that, the crackling gets much worse. Is something getting saturated as the audio gets louder in the video? But this doesn't happen when I don't run the sine test...
Crackling Recording 2 (with sine wave audible): audio_stuttering_gstlaunch2.zip
I'm doing the same thing (as you can hear the sine wave go on and off), yet the effects at the beginning (slight stuttering) are different than the effects as the song goes on (changes to crackling).
Of course, reducing latency to 100us reduces the crackling significantly, but still very noticeable :(
Could you explain what may be going on in Recording 2?
xtknight
on 12 Aug 2018
Try to reset PE after upgrading. This should help with the sie: Internal data stream error. I still don't know why a few users have this problem. It is related to the removal of plugin that is not in PE anymore.
wwmm
on 12 Aug 2018
I am able to reproduce the noise with gst-launch. It can also be reproduced by doing a few seeks in a video open in mpv. There is no special log printed by GStreamer when they happen. It is also not clear if its source is a problem in PulseEffects, GStreamer or Pulseaudio.
wwmm
on 12 Aug 2018
I forgot to say that it can only be noticed in mpv if there is also a second app playing audio. It could be 2 mpv windows for example.
EDIT:
Honestly I do not see yet if there is anything I can do about it. When all audio apps are enabled in PE the output of each of them is sent to a Pulseaudio null sink (PulseEffects(apps) in this case). Up to now my feeling is that something odd happens somewhere in Pulseaudio when a null sink receives more streams when it is in the running state
wwmm
on 12 Aug 2018
I took a look at Pulseaudio's logs when I do seeks in a second mpv window and when gst-launch is executed. In any of these events we have messages like this:
[pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
[null-sink] protocol-native.c: Requesting rewind due to end of underrun.
So whenever we add(or remove) more streams to a null sink its state alternates between idle and running. Maybe noises are introduced in this process.
wwmm
on 12 Aug 2018
In any case this secondary stream start noise and the volume change noise seem to have different sources than the ones faced by @AlexWayfer. My suggestion is that new issues are opened for them. Specially because they may require the help of people from Pulseaudio or GStreamer and it will be confusing for them to find things in this long thread.
wwmm
on 12 Aug 2018
A bit different logs at another computer without new streams creation (I'm just coding with a music in the background):
(pulseeffects:26218): pulseeffects-DEBUG: 00:14:10.732: sie: PAUSED -> PLAYING -> VOID_PENDING
0:26:44.094501646 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1463:gst_audio_base_sink_skew_slaving:<sink> correct clock skew +0:00:00.020025263 > +0:00:00.020000000
0:26:45.122446298 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.040000000, resyncing
0:26:45.928871665 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<sink> correct clock skew -0:00:00.020028930 < -+0:00:00.020000000
0:26:46.919511450 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.040000000, resyncing
0:28:31.145037193 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1463:gst_audio_base_sink_skew_slaving:<sink> correct clock skew +0:00:00.020000105 > +0:00:00.020000000
0:28:32.140904722 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.040000000, resyncing
0:28:33.809431932 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<sink> correct clock skew -0:00:00.020001379 < -+0:00:00.020000000
0:28:34.811962090 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.040000000, resyncing
0:28:34.954175858 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1463:gst_audio_base_sink_skew_slaving:<sink> correct clock skew +0:00:00.020000160 > +0:00:00.020000000
0:28:35.984356948 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.040000000, resyncing
0:28:37.639983622 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<sink> correct clock skew -0:00:00.020000068 < -+0:00:00.020000000
0:28:37.992479481 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1463:gst_audio_base_sink_skew_slaving:<sink> correct clock skew +0:00:00.020000112 > +0:00:00.020000000
0:28:39.620892686 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<sink> correct clock skew -0:00:00.020000581 < -+0:00:00.020000000
0:28:40.643656143 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.040000000, resyncing
0:28:42.373440388 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1463:gst_audio_base_sink_skew_slaving:<sink> correct clock skew +0:00:00.020000937 > +0:00:00.020000000
0:28:43.399281650 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.040000000, resyncing
0:28:45.896715878 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<sink> correct clock skew -0:00:00.020000859 < -+0:00:00.020000000
0:28:46.906865397 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.040000000, resyncing
0:28:46.907551970 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1463:gst_audio_base_sink_skew_slaving:<sink> correct clock skew +0:00:00.020000350 > +0:00:00.020000000
0:28:47.898301969 26218 0x5594de25acf0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.040000000, resyncing
This happened with which PE version? Very rarely I have the Unexpected discontinuity in audio timestamps too. But when they happen there is only one or two of them. GStreamer is able to fix the drift without so many iterations.
wwmm
on 13 Aug 2018
This happened with which PE version?
4.2.6
AlexWayfer
on 13 Aug 2018
Very long (~ 500ms) periodic (~ every 2 sec) lags:
0:11:43.182618092 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:43.182675077 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:44.235923522 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.322834467, resyncing
0:11:44.910647258 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31091823
0:11:44.910712883 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:44.910875947 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:44.910930711 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:44.911003548 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:45.295342934 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31108581
0:11:45.295455535 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:45.295492968 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:45.295546195 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:45.295610773 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:45.630299957 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4851 samples at sample 31123575
0:11:45.630327071 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:45.630333410 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4851 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:45.630345111 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:45.630366199 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:46.620149008 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.325374149, resyncing
0:11:47.291965191 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31196781
0:11:47.291990329 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:47.291995601 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:47.292006233 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:47.292028118 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:47.593820900 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31210011
0:11:47.593851506 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:47.593857631 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:47.593870922 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:47.593897102 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:47.942192173 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4851 samples at sample 31225446
0:11:47.942227434 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:47.942232385 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4851 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:47.942254648 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:47.942284709 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:49.018523846 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.324693877, resyncing
0:11:49.647206243 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31300416
0:11:49.647256773 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:49.647273606 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:49.647298036 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:49.647339897 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:49.892776414 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31311441
0:11:49.892876445 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:49.892901301 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:49.892940341 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:49.892995716 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:50.380257951 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31332609
0:11:50.380325075 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:50.380349895 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:50.380388711 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:50.380450583 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:51.354199934 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.328594104, resyncing
0:11:52.038888742 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4851 samples at sample 31406256
0:11:52.038956067 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:52.039002189 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4851 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:52.039037799 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:52.039094926 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:52.446651496 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31423896
0:11:52.446810613 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:52.446828569 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:52.446855965 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:52.446895606 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:53.845062479 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.224013605, resyncing
0:11:54.907889527 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31532382
0:11:54.907936460 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:54.907954837 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:54.907963740 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:54.907994983 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:56.838999764 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.103174603, resyncing
0:11:57.913536132 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31665123
0:11:57.913558870 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:11:57.913563901 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:11:57.913574257 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:11:57.913591955 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:11:59.830826049 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.107505668, resyncing
0:12:00.666397994 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31786398
0:12:00.666467310 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:12:00.666511844 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:12:00.666548359 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:12:00.666605246 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:12:01.037849940 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31802715
0:12:01.037920588 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:12:01.037946498 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:12:01.037982328 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:12:01.038045503 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:12:02.497635929 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.205895691, resyncing
0:12:03.406193767 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 31907232
0:12:03.406271705 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:12:03.406294675 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:12:03.406329515 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:12:03.406389053 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:12:05.323316534 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.106054421, resyncing
0:12:05.913709376 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 32017923
0:12:05.913779352 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:12:05.913797375 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:12:05.913805290 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:12:05.913821694 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:12:07.829871701 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.106734693, resyncing
0:12:08.421487691 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 32128614
0:12:08.421557656 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:12:08.421580499 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:12:08.421612733 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:12:08.421672814 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:12:08.849460068 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 32147577
0:12:08.849530598 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:12:08.849555808 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:12:08.849593905 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:12:08.849653175 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:12:10.264546302 3887 0x7fe6080020f0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.211655328, resyncing
0:12:10.892813725 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4851 samples at sample 32237541
0:12:10.892878043 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:12:10.892947208 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4851 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:12:10.892986156 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:12:10.893046560 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
0:12:11.194607648 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:844:gst_audio_base_src_create:<source> create DISCONT of 4410 samples at sample 32250771
0:12:11.194671904 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
0:12:11.194697482 3887 0x55a7de4b4a80 WARN audiobasesrc gstaudiobasesrc.c:849:gst_audio_base_src_create:<source> warning: Dropped 4410 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:12:11.194765450 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<source> posting message: Can't record audio fast enough
0:12:11.194989447 3887 0x55a7de4b4a80 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<source> posted warning message: Can't record audio fast enough
There was a regression in version 4.2.6 causing that periodic lag. It doesn't happen here anymore in version 4.2.7
wwmm
on 13 Aug 2018
Thanks.
After upgrade I noticed:
(pulseeffects:13555): pulseeffects-CRITICAL **: 21:28:00.306: pulse_manager: failed to move sink input: telegram-desktop, idx = 303 to PE
(pulseeffects:13555): pulseeffects-CRITICAL **: 21:28:00.315: pulse_manager: failed to move sink input: telegram-desktop, idx = 304 to PE
0:07:40.228123137 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.040839002, resyncing
0:07:54.324142134 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.065351473, resyncing
0:07:54.324474826 13555 0x559e94adec60 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:07:54.324668320 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.009977324, resyncing
0:08:10.786224025 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.050022675, resyncing
0:08:38.524970248 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.056984126, resyncing
0:08:38.525226704 13555 0x559e94adec60 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:08:38.525678464 13555 0x559e94adec60 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:09:02.617164164 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.071836734, resyncing
0:09:02.617518191 13555 0x559e94adec60 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:09:02.617729580 13555 0x559e94adec60 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:09:02.617896553 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.000136054, resyncing
0:09:08.521379778 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.079795918, resyncing
0:09:08.521802797 13555 0x559e94adec60 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:09:23.520850611 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.065600907, resyncing
0:09:23.553663163 13555 0x559e94adec60 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:09:23.554175697 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.001496598, resyncing
0:09:23.554783676 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.003333333, resyncing
0:09:41.953673224 13555 0x559e92cd31e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.063854875, resyncing
0:09:41.953839619 13555 0x559e94adec60 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
(pulseeffects:13555): pulseeffects-CRITICAL **: 21:30:18.657: pulse_manager: failed to move sink input: telegram-desktop, idx = 313 to PE
(pulseeffects:13555): pulseeffects-CRITICAL **: 21:30:18.659: pulse_manager: failed to move sink input: telegram-desktop, idx = 314 to PE
(audible lags at warns)
I have always Telegram Desktop running. Can it affect?
AlexWayfer
on 13 Aug 2018
It was a good thing to improve the logs by adding the app name. Now we know why you have the failed to move sink input errors. As you can see here #188 there is a bug in telegram that affects PE. But I am not so sure that this alone would explain all the problems you have. But it could be the trigger.
Telegram developers are aware of this problem but the issue is still open after 2 years https://github.com/telegramdesktop/tdesktop/issues/2231
wwmm
on 14 Aug 2018
@wwmm, thanks!
Also, maybe this can be helpful: https://github.com/telegramdesktop/tdesktop/issues/4219#issuecomment-411146434
AlexWayfer
on 14 Aug 2018
He is not totally right. There will be some latency introduced of course. But this doesn't mean you can't equalize voip calls. I did this a few times in skype with no problems.
The app role will not make difference in our case. PulseEffects does not use it. It is up to the user to decide if he/she wants to apply or not effects to a given app
wwmm
on 14 Aug 2018
There is a part from v4.3.5 logs:
0:29:31.774442492 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:32.006666154 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:32.203972816 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:32.436142422 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:32.633667256 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:32.703337541 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:33.156121800 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:33.353464894 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:33.864093922 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:34.096584784 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:34.293626655 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:34.792609333 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:35.036434714 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:35.233921427 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:35.466175394 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:35.756440992 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:35.954025969 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:36.406464477 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:36.603670425 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:36.905442799 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:37.102990975 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:37.556068688 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:37.845824809 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:38.264192346 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:38.496005404 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:29:39.436523061 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
(pulseeffects:6687): pulseeffects-DEBUG: 12:00:56.564: pulse_manager: sink input: Chromium, idx = 27 moved to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:00:56.593: pulse_manager: sink input: Chromium, idx = 28 moved to PE
0:35:22.405654120 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.086303854, resyncing
0:35:24.376539244 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.088730158, resyncing
0:35:30.524872458 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.048820861, resyncing
0:35:50.551771223 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.057074829, resyncing
(pulseeffects:6687): pulseeffects-DEBUG: 12:02:43.050: pulse_manager: sink input: Chromium, idx = 29 moved to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:02:43.057: pulse_manager: sink input: Chromium, idx = 30 moved to PE
0:37:13.527467032 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.063990929, resyncing
0:37:24.032078465 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.043469387, resyncing
0:37:30.596520373 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.060861678, resyncing
0:37:30.664857950 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:37:30.665045012 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.003197278, resyncing
0:37:41.056359242 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.043401360, resyncing
(pulseeffects:6687): pulseeffects-DEBUG: 12:04:29.831: pulse_manager: sink input: Chromium, idx = 33 moved to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:04:29.847: pulse_manager: sink input: Chromium, idx = 34 moved to PE
0:39:05.097908760 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.082403628, resyncing
0:39:05.098413955 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
(pulseeffects:6687): pulseeffects-DEBUG: 12:05:35.761: pulse_manager: sink input: Chromium, idx = 37 moved to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:05:35.766: pulse_manager: sink input: Chromium, idx = 38 moved to PE
0:40:01.575814451 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.047868480, resyncing
0:40:15.604773800 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.064036281, resyncing
(pulseeffects:6687): pulseeffects-DEBUG: 12:07:26.027: pulse_manager: sink input: Chromium, idx = 39 moved to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:07:26.039: pulse_manager: sink input: Chromium, idx = 40 moved to PE
0:42:00.905432247 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.085124716, resyncing
0:42:00.905578410 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:42:00.905814484 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:42:00.905974421 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.010022675, resyncing
0:42:06.886892466 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.050000000, resyncing
(pulseeffects:6687): pulseeffects-DEBUG: 12:11:44.258: pulse_manager: sink input: Chromium, idx = 41 moved to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:11:44.263: pulse_manager: sink input: Chromium, idx = 42 moved to PE
0:46:19.742595680 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.091360544, resyncing
0:46:23.717672574 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.048752834, resyncing
0:46:29.657035633 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.092494331, resyncing
0:46:33.097242887 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.067029478, resyncing
0:46:33.180796087 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:46:33.181097263 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.003310657, resyncing
0:46:43.158408320 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.044875283, resyncing
0:47:42.195886552 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.049909297, resyncing
(pulseeffects:6687): pulseeffects-CRITICAL **: 12:13:38.787: pulse_manager: failed to move sink input: telegram-desktop, idx = 44 to PE
(pulseeffects:6687): pulseeffects-CRITICAL **: 12:13:38.798: pulse_manager: failed to move sink input: telegram-desktop, idx = 45 to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:14:18.927: pulse_manager: sink input: Chromium, idx = 46 moved to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:14:18.935: pulse_manager: sink input: Chromium, idx = 47 moved to PE
0:48:53.296916530 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.051723356, resyncing
0:49:03.351530169 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.042380952, resyncing
(pulseeffects:6687): pulseeffects-DEBUG: 12:14:52.107: pulse_manager: sink input: Chromium, idx = 48 moved to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:14:52.115: pulse_manager: sink input: Chromium, idx = 49 moved to PE
0:49:17.968983225 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.043129251, resyncing
0:49:23.117467389 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.060000000, resyncing
0:49:34.109716431 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.048231292, resyncing
0:50:19.668269797 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.049954648, resyncing
(pulseeffects:6687): pulseeffects-DEBUG: 12:18:55.733: pulse_manager: sink input: Chromium, idx = 50 moved to PE
(pulseeffects:6687): pulseeffects-DEBUG: 12:18:55.742: pulse_manager: sink input: Chromium, idx = 51 moved to PE
0:53:21.797294387 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1491:gst_audio_base_sink_skew_slaving:<sink> correct clock skew -0:00:00.020003733 < -+0:00:00.020000000
0:53:30.386580654 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.063424036, resyncing
0:53:30.569834377 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:40.379042679 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.051428571, resyncing
0:53:40.479049001 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:40.559122970 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:40.709012910 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:40.759044289 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:40.838996103 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:45.212476616 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.066439909, resyncing
0:53:45.292399153 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:45.342952214 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:45.482525915 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:45.522449514 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:45.572924742 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:47.254995454 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.093718820, resyncing
0:53:47.333227698 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:47.333492263 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.003242630, resyncing
0:53:47.333802872 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:47.334179680 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:47.334490773 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:48.963325050 6687 0x7f1ab000da30 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.048843537, resyncing
0:53:49.136247092 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:49.182695129 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:49.275146397 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:49.321628510 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:49.427994099 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:49.474508544 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:49.567332806 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:49.614047342 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:49.855758863 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:49.902537255 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:50.041542424 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:50.147525144 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:50.194185271 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:50.286812448 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:53:50.333111428 6687 0x55d7da98e4c0 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
The same problem when I just change the volume of Chromium in PulseEffects:
There are logs:
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.399: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.417: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.423: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.432: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.447: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.463: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.504: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.519: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.543: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.879: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.898: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.903: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.911: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.920: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.927: pulse_manager: changed volume of sink input: Chromium, idx = 186
(pulseeffects:8213): pulseeffects-DEBUG: 16:05:04.944: pulse_manager: changed volume of sink input: Chromium, idx = 186
0:01:00.091021608 8213 0x7f7afc008e80 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.203650793, resyncing
0:01:00.175678460 8213 0x7f7b48019640 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:00.179475405 8213 0x7f7b48019640 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:00.179923044 8213 0x7f7b48019640 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:00.180343713 8213 0x7f7b48019640 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:00.180793249 8213 0x7f7b48019640 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
0:01:00.181075882 8213 0x7f7afc008e80 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of +0:00:00.000884353, resyncing
0:01:00.181247026 8213 0x7f7b48019640 WARN pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<sink> Got underflow
Some logs from sudo journalctl -fb | sudo grep -i pulse at the lag moments:
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1764 bytes on render memblockq.
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 4632 bytes on implementor.
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1764 bytes on render memblockq.
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1764 bytes.
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1296 bytes on render memblockq.
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1864 bytes on implementor.
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1296 bytes.
Oct 30 11:34:56 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to rewrite.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 7392 bytes.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 7392 bytes.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 1848
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 1848
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 7392 bytes.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: latency = 51013
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 7392 bytes on render memblockq.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 14784 bytes on implementor.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Implicit underrun of 'Playback Stream'
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to rewrite.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 5344 bytes.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 5344 bytes.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 1336
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 1336
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 5344 bytes.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: latency = 61744
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 5344 bytes on render memblockq.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 10688 bytes on implementor.
Oct 30 11:34:57 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
...
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 428 bytes on render memblockq.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 856 bytes on implementor.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 428 bytes on render memblockq.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 428 bytes.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1544 bytes on render memblockq.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 2992 bytes on implementor.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1544 bytes.
Oct 30 11:37:53 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to uncorking
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 56 bytes on render memblockq.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 56 bytes on render memblockq.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 56 bytes.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to uncorking
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1224 bytes on render memblockq.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1224 bytes.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to rewrite.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 1300 bytes.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 1300 bytes.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 325
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 325
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 1300 bytes.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: latency = 82329
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 1300 bytes on render memblockq.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 2600 bytes on implementor.
Oct 30 11:37:54 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1764 bytes on render memblockq.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1764 bytes on render memblockq.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 2592 bytes on implementor.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1764 bytes.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 324 bytes on render memblockq.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 4176 bytes on implementor.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 324 bytes on render memblockq.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 324 bytes.
Oct 30 11:38:04 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1500 bytes on render memblockq.
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] sink-input.c: Freeing input 58 "Playback"
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1500 bytes.
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] client.c: Freed 57 "Chromium"
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] protocol-native.c: Connection died.
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] sink-input.c: Freeing input 57 "Playback"
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1764 bytes on render memblockq.
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1764 bytes.
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] client.c: Freed 56 "Chromium"
Oct 30 11:38:09 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] protocol-native.c: Connection died.
...
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1408 bytes on render memblockq.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 4328 bytes on implementor.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1408 bytes on render memblockq.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1408 bytes.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1568 bytes on render memblockq.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 2976 bytes on implementor.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1568 bytes.
Oct 30 11:39:22 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to uncorking
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1244 bytes on render memblockq.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1244 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to uncorking
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1376 bytes on render memblockq.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1376 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to rewrite.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 10864 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 10864 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 2716
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 2716
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 10864 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: latency = 34967
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 10864 bytes on render memblockq.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 21728 bytes on implementor.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Implicit underrun of 'Playback Stream'
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to rewrite.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 8816 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 8816 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 2204
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 2204
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 8816 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: latency = 45963
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 8816 bytes on render memblockq.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 17632 bytes on implementor.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Implicit underrun of 'Playback Stream'
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to rewrite.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 2672 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 2672 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 668
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 668
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 2672 bytes.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: latency = 80609
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 2672 bytes on render memblockq.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 5344 bytes on implementor.
Oct 30 11:39:23 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1764 bytes on render memblockq.
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 4704 bytes on implementor.
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1764 bytes on render memblockq.
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1764 bytes.
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1572 bytes on render memblockq.
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1596 bytes on implementor.
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:39:33 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1572 bytes.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] sink-input.c: Freeing input 59 "Playback"
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 92 bytes on render memblockq.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 92 bytes on render memblockq.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 92 bytes.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] client.c: Freed 58 "Chromium"
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] protocol-native.c: Connection died.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink.c: Processing rewind...
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] sink-input.c: Have to rewind 1460 bytes on render memblockq.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] source.c: Processing rewind...
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] sink-input.c: Freeing input 60 "Playback"
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: D: [null-sink] module-null-sink.c: Rewound 1460 bytes.
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] client.c: Freed 59 "Chromium"
Oct 30 11:39:38 alex-workpc-arch pulseaudio[1685]: I: [pulseaudio] protocol-native.c: Connection died.
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to rewrite.
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 7196 bytes.
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 7196 bytes.
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 1799
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 1799
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 7196 bytes.
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink.c: latency = 54637
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 7196 bytes on render memblockq.
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 14392 bytes on implementor.
Oct 30 11:39:39 alex-workpc-arch pulseaudio[1685]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
Based on the amount of rewinds in your log and the fact that I now know there is a bug in Pulseaudio that causes a similar effect I'd say that what is happening to you has the same source as #350.
wwmm
on 31 Oct 2018
Based on the amount of rewinds in your log and the fact that I now know there is a bug in Pulseaudio that causes a similar effect I'd say that what is happening to you has the same source as #350.
OK, thank you, I'll watch. FYI: I didn't rewind anything.
AlexWayfer
on 31 Oct 2018
No user can do rewinds. Pulseaudio does when it thinks it is necessary. There is no way we can influence its decision
wwmm
on 31 Oct 2018
It's probably related to https://github.com/aleho/gnome-shell-volume-mixer/issues/83
I'll monitor such issues while this extension is disabled.
Previously, I found many errors from journalctl -f /usr/bin/gnome-shell.
AlexWayfer
on 11 Mar 2019
It's probably related to aleho/gnome-shell-volume-mixer#83
Nope, there is something else…
AlexWayfer
on 12 Mar 2019
Version 4.5.6:
0:04:30.305407570 17445 0x5591ea9695e0 WARN audiobasesink gstaudiobasesink.c:1787:gst_audio_base_sink_get_alignment:<sink> Unexpected discontinuity in audio timestamps of -0:00:00.080340136, resyncing
Approximately one time per one minute.
From journalctl:
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: I: [pulseaudio] protocol-native.c: Final latency 69.66 ms = 23.22 ms + 2*11.61 ms + 23.22 ms
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Requesting rewind due to uncorking
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink.c: Processing rewind...
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 800 bytes on render memblockq.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 800 bytes on render memblockq.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] source.c: Processing rewind...
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Rewound 800 bytes.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Requesting rewind due to uncorking
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [pulseaudio] module-suspend-on-idle.c: Sink PulseEffects_apps becomes busy, resuming.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink.c: Processing rewind...
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 1316 bytes on render memblockq.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 1316 bytes on render memblockq.
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] source.c: Processing rewind...
Mar 20 19:52:21 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Rewound 1316 bytes.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink.c: Processing rewind...
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 1580 bytes on render memblockq.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 2424 bytes on implementor.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] source.c: Processing rewind...
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Rewound 1580 bytes.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Requesting rewind due to corking
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink.c: Processing rewind...
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 1404 bytes on render memblockq.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 1404 bytes on render memblockq.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 3232 bytes on implementor.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 1404 bytes on render memblockq.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] source.c: Processing rewind...
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Rewound 1404 bytes.
Mar 20 19:52:31 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] protocol-native.c: Requesting rewind due to rewrite.
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 556 bytes.
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 556 bytes.
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] alsa-sink.c: before: 139
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] alsa-sink.c: after: 139
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 556 bytes.
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] sink.c: Processing rewind...
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] sink.c: latency = 90822
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 556 bytes on render memblockq.
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] sink-input.c: Have to rewind 1112 bytes on implementor.
Mar 20 19:52:32 Alex-ArchMainPC pulseaudio[1118]: D: [alsa-sink-USB Audio] source.c: Processing rewind...
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink.c: Processing rewind...
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: I: [pulseaudio] sink-input.c: Freeing input 252 "Playback"
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 1676 bytes on render memblockq.
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] source.c: Processing rewind...
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Rewound 1676 bytes.
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: I: [pulseaudio] client.c: Freed 193 "Chromium"
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: I: [pulseaudio] protocol-native.c: Connection died.
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] protocol-native.c: Requesting rewind due to end of underrun.
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Requested to rewind 1764 bytes.
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: I: [pulseaudio] sink-input.c: Freeing input 251 "Playback"
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink.c: Processing rewind...
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: I: [pulseaudio] client.c: Freed 192 "Chromium"
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: I: [pulseaudio] protocol-native.c: Connection died.
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] sink-input.c: Have to rewind 1748 bytes on render memblockq.
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] source.c: Processing rewind...
Mar 20 19:52:41 Alex-ArchMainPC pulseaudio[1118]: D: [null-sink] module-null-sink.c: Rewound 1748 bytes.
I don't know if there something bad. I guess, no.
But there is still the issue…
AlexWayfer
on 20 Mar 2019
These rewinds are happening because you paused/unpaused the audio app. Rewinds are known to cause noises when changing the app volume.
I wonder if this could be caused by some problems in the soundcard driver. What is the card's model?
wwmm
on 20 Mar 2019
These rewinds are happening because you paused/unpaused the audio app.
No! It's one stream, unpaused play.
Rewinds are known to cause noises when changing the app volume.
I didn't change for while these logs were collected.
I wonder if this could be caused by some problems in the soundcard driver. What is the card's model?
Orico SC1. It's also reproducible with Sound Blaster Play! 3 (If I remember it right).
AlexWayfer
on 20 Mar 2019
This is odd. The line sink-input.c: Requesting rewind due to uncorking means an audio app was paused and now it is playing. If you did not do that then there is something else playing audio in the system(maybe playing silence) that is alternating between the paused and the playing state. If it is not that then chromium is creating and killing streams under the hood for reasons I do not know.
wwmm
on 21 Mar 2019
If you did not do that then there is something else playing audio in the system(maybe playing silence) that is alternating between the paused and the playing state.
I didn't.
If it is not that then chromium is creating and killing streams under the hood for reasons I do not know.
It's interesting. As I wrorte above, I see only Chromium in PulseEffects applications list, and I don't do anything except browsing, tabs reloading, etc.
Maybe some tabs with audio components (like for support-chat notifications) make these noises on loading while another tab (without reloading) just playing music.
AlexWayfer
on 21 Mar 2019
It could be. Maybe the way chromium handles the creation and destruction of each tab stream is causing a similar effect to change the app volume. Pulseaudio's rewind bug is triggered and noises can be heard.
wwmm
on 21 Mar 2019
Pulseaudio's rewind bug is triggered and noises can be heard.
Do you have any link to this bug? Or it's just a suggestion?
The sad part (for me) here is that I can't collect enough logs of PulseEffects or PulseAudio, and even if I will report to PulseAudio "something is going wrong" there will be the one detail: these noises appear only with PulseEffects, and PulseAudio, I guess, will direct me here.
AlexWayfer
on 21 Mar 2019
https://lists.freedesktop.org/archives/pulseaudio-discuss/2018-October/030553.html
https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/304
https://github.com/wwmm/pulseeffects/issues/350
In order to apply effects we have to record from a Pulseaudio null sink monitor. But accordingly to what one of Pulseaudio's developers told in the first link if a rewind in this sink happens while we are recording from its monitor noises will be produced. As you can see in the second link this bug has been around for a while.
wwmm
on 21 Mar 2019
@wwmm, thank you! The sad story about PulseAudio (for me) :pensive: :
AlexWayfer
on 21 Mar 2019
I found the essence of this problem: change the volume of application (Chromium for me) in PulseEffects:
vokoscreen-2019-05-14_18-48-38.zip
(Sorry for bad quality of video record, but the sound is exact).
Also, I'm playing only one audio (tab), I don't know why there are two applications (streams). At pause (after some time) there is only the first (with playing state):
AlexWayfer
on 14 May 2019
The noises caused by volume changes have the same source as #350. It is a Pulseaudio bug. I have sent some patches to its developers that will help me to workaround this bug as you can see here https://gitlab.freedesktop.org/pulseaudio/pulseaudio/merge_requests/93. They didn't merge them yet but I think that this is probably going to be done before Pulseaudio 13 is released.
I have no idea why chromium created more than one stream. But it did. At first site I thought that PE duplicated the entries but they have different latencies and when you changed the volume of the top stream nothing happened. So it is not a duplicated stream.
wwmm
on 14 May 2019
The noises caused by volume changes have the same source as #350. It is a Pulseaudio bug.
Yes, I remember. I just wanted to share a clear example.
I have sent some patches to its developers that will help me to workaround this bug as you can see here https://gitlab.freedesktop.org/pulseaudio/pulseaudio/merge_requests/93. They didn't merge them yet but I think that this is probably going to be done before Pulseaudio 13 is released.
Thank you very much!
At first site I thought that PE duplicated the entries but they have different latencies and when you changed the volume of the top stream nothing happened. So it is not a duplicated stream.
Yes, maybe it's something like audio element for notifications in some tab, I don't know.
AlexWayfer
on 14 May 2019
👍1
I don't experience this issue with git version of pulseaudio (v12.0.309.geadd987a6-1) and 4.6.3 version of PulseEffects, after #350 resolving. So, I'm closing this issue for now, and I'll re-open if I notice something relevant again.
Thank you very much for work. Now I can enjoy the adjusted (bass-boosted) music finally.
AlexWayfer
on 10 Jun 2019
Was this page helpful?
0 / 5 - 0 ratings
Related issues
marioortizmanero
·
5Comments
zedeus
·
7Comments
BERNARDO31P
·
5Comments
WarpspeedSCP
·
4Comments
Dodjob
·
5Comments