Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jamming/stuttering during playback from the Chromium #222

Closed
AlexWayfer opened this issue May 30, 2018 · 84 comments
Closed

Jamming/stuttering during playback from the Chromium #222

AlexWayfer opened this issue May 30, 2018 · 84 comments

Comments

@AlexWayfer
Copy link
Contributor

AlexWayfer commented May 30, 2018

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:

image

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):

image

@wwmm
Copy link
Owner

wwmm commented May 30, 2018

Run PE in debug mode PULSEEFFECTS_DEBUG=1 pulseeffects and paste its output here. Maybe some clues are printed when the stuttering happens

@AlexWayfer
Copy link
Contributor Author

~ > 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
Copy link
Contributor Author

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 #217 (comment), I think).

@AlexWayfer
Copy link
Contributor Author

~ > 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
Copy link
Contributor Author

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
Copy link
Contributor Author

100% scenario:

  1. Google Play Music playing in one tab
  2. 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

@wwmm
Copy link
Owner

wwmm commented Jun 1, 2018

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

@AlexWayfer
Copy link
Contributor Author

AlexWayfer commented Jun 1, 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
Copy link
Contributor Author

The same in the version 4, but there are no any logs in the debug mode (G_MESSAGES_DEBUG=pulseeffects pulseeffects). 😞

@AlexWayfer
Copy link
Contributor Author

Can you add please more debug logs? I'll attach them here when these situations occur.

@wwmm
Copy link
Owner

wwmm commented Jun 6, 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

@AlexWayfer
Copy link
Contributor Author

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:

image

When Beatport page loading, and there are some sound lags (the new one appears at the end):

image

But I have lags also when there is no additional channel.

Other tabs:

image

image

image

image

@beckend
Copy link

beckend commented Jul 14, 2018

sudo renice -10 -p $(pidof pulseeffects) ?

@AlexWayfer
Copy link
Contributor Author

sudo renice -10 -p $(pidof pulseeffects) ?

Thank you, but it didn't help too much. :(

Maybe a little.

@xtknight
Copy link

xtknight commented Jul 31, 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.

@AlexWayfer
Copy link
Contributor Author

@xtknight, thank you!

@xtknight
Copy link

xtknight commented Jul 31, 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.

@wwmm
Copy link
Owner

wwmm commented Jul 31, 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?

@xtknight
Copy link

@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.

@wwmm
Copy link
Owner

wwmm commented Jul 31, 2018

Now that we finally have documentation it is a good idea to tell this there. I will try to remember to do that :-)

@xtknight
Copy link

xtknight commented Aug 2, 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.

@AlexWayfer
Copy link
Contributor Author

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:

image

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). 😞

@AlexWayfer
Copy link
Contributor Author

I can try to programmatically record these lags, but I don't know a good way to do this.

@wwmm
Copy link
Owner

wwmm commented Aug 2, 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
screenshot from 2018-08-02 11-48-52
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
screenshot from 2018-08-02 11-50-30
Now if I decrease the test signal volume so that PulseEffects(apps) is not saturated everything is fine
screenshot from 2018-08-02 11-51-07

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.

@AlexWayfer
Copy link
Contributor Author

AlexWayfer commented Aug 2, 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.

@wwmm
Copy link
Owner

wwmm commented Aug 2, 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?
screenshot from 2018-08-02 13-11-48
Try to lower it to 256 and see if it makes any difference. Under flows in pulsesink usually lead to noise.

@wwmm
Copy link
Owner

wwmm commented Aug 2, 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.

@AlexWayfer
Copy link
Contributor Author

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:

  1. Run pacmd
    1.1. Enter set-log-level 4 (empty output)
    1.2. Don't exit
  2. Run sudo journalctl -fb | grep -i pulse in a new terminal
  3. Run pulseeffects in the third terminal

Which block size do you have?

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
Copy link
Contributor Author

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.

#217 (comment)

@AlexWayfer
Copy link
Contributor Author

AlexWayfer commented Aug 13, 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?

@wwmm
Copy link
Owner

wwmm commented Aug 14, 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 telegramdesktop/tdesktop#2231

@AlexWayfer
Copy link
Contributor Author

@wwmm, thanks!

Also, maybe this can be helpful: telegramdesktop/tdesktop#4219 (comment)

@wwmm
Copy link
Owner

wwmm commented Aug 14, 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

@AlexWayfer
Copy link
Contributor Author

AlexWayfer commented Sep 26, 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

@AlexWayfer
Copy link
Contributor Author

The same problem when I just change the volume of Chromium in PulseEffects:

image

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

@AlexWayfer
Copy link
Contributor Author

AlexWayfer commented Oct 30, 2018

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...

@wwmm
Copy link
Owner

wwmm commented Oct 30, 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.

@AlexWayfer
Copy link
Contributor Author

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.

@wwmm
Copy link
Owner

wwmm commented Oct 31, 2018

No user can do rewinds. Pulseaudio does when it thinks it is necessary. There is no way we can influence its decision

@AlexWayfer
Copy link
Contributor Author

It's probably related to aleho/gnome-shell-volume-mixer#83

I'll monitor such issues while this extension is disabled.

Previously, I found many errors from journalctl -f /usr/bin/gnome-shell.

@AlexWayfer
Copy link
Contributor Author

It's probably related to aleho/gnome-shell-volume-mixer#83

Nope, there is something else…

@AlexWayfer
Copy link
Contributor Author

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…

@wwmm
Copy link
Owner

wwmm commented Mar 20, 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?

@AlexWayfer
Copy link
Contributor Author

AlexWayfer commented Mar 20, 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).

@wwmm
Copy link
Owner

wwmm commented Mar 21, 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.

@AlexWayfer
Copy link
Contributor Author

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.

@wwmm
Copy link
Owner

wwmm commented Mar 21, 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.

@AlexWayfer
Copy link
Contributor Author

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.

@wwmm
Copy link
Owner

wwmm commented Mar 21, 2019

https://lists.freedesktop.org/archives/pulseaudio-discuss/2018-October/030553.html
https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/304
#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.

@AlexWayfer
Copy link
Contributor Author

@wwmm, thank you! The sad story about PulseAudio (for me) 😔 :

image

@AlexWayfer
Copy link
Contributor Author

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):

image

@wwmm
Copy link
Owner

wwmm commented May 14, 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.

@AlexWayfer
Copy link
Contributor Author

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
Copy link
Contributor Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants