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

Regression in next11: resampling does not work with alsa #203

Closed
Wang-Yue opened this issue May 13, 2022 · 42 comments
Closed

Regression in next11: resampling does not work with alsa #203

Wang-Yue opened this issue May 13, 2022 · 42 comments
Labels
bug Something isn't working linux Only affects Linux

Comments

@Wang-Yue
Copy link
Contributor

Wang-Yue commented May 13, 2022

tested with the following

---
devices:
  samplerate: 48000
  chunksize: 4096
  enable_resampling: true
  resampler_type: Synchronous
  capture_samplerate: 192000
  playback:
    type: File
    filename: "/dev/null"
    channels: 2
    format: S16LE
  capture:
    type: ALSA
    device: "hw:CARD=UAC2Gadget"
    channels: 2
    format: S32LE

log

2022-05-13 10:13:01.489446 DEBUG [src/filedevice.rs:130] starting playback loop
2022-05-13 10:13:01.489749 INFO [src/alsadevice.rs:722] Capture device supports rate adjust
2022-05-13 10:13:01.489814 DEBUG [src/alsadevice.rs:245] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2022-05-13 10:13:01.501898 WARN [src/alsadevice.rs:263] Capture device failed while waiting for available frames, error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 10:13:01.502089 ERROR [src/bin.rs:362] Capture error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 10:13:01.502269 DEBUG [src/bin.rs:367] Wait for playback thread to exit..
2022-05-13 10:13:01.502697 DEBUG [src/bin.rs:915] Restarting with new config
2022-05-13 10:13:01.502772 DEBUG [src/bin.rs:857] Wait for config

turning src off works.

@Wang-Yue
Copy link
Contributor Author

this is a bug in next11 . 1.0 release does not have the bug.
this applies to non-gadgets as well, such as a normal usb audio interface.

@HEnquist
Copy link
Owner

Which commit are you on, before or after this was merged?
#201

@Wang-Yue
Copy link
Contributor Author

latest. I just synced a moment ago

@HEnquist
Copy link
Owner

If you have time, can you check if the problem already is there on next11 from just before the merge?
That would be this commit: 519956e

@HEnquist HEnquist added bug Something isn't working linux Only affects Linux labels May 13, 2022
@Wang-Yue
Copy link
Contributor Author

here's the test file. This bug is not related to gadget. My USB audio interface has the same issue.
replace the XXXX below with your device name. (I hid the name in config and logs as the name contains my device serial number)

---
devices:
  samplerate: 44100
  chunksize: 4096
  enable_resampling: true
  resampler_type: Synchronous
  capture_samplerate: 192000
  playback:
    type: File
    filename: "/dev/null"
    channels: 2
    format: S16LE
  capture:
    type: ALSA
    device: "hw:CARD=XXXX"
    channels: 2
    format: S32LE

here's 1.0 release

➜ camilladsp test.yml -v                                                    
2022-05-13 14:16:58.040536 INFO [src/bin.rs:711] CamillaDSP version 1.0.0
2022-05-13 14:16:58.040703 INFO [src/bin.rs:712] Running on linux, arm
2022-05-13 14:16:58.040949 DEBUG [src/bin.rs:754] Read config file Some("test.yml")
2022-05-13 14:16:58.042327 DEBUG [src/bin.rs:773] Config is valid
2022-05-13 14:16:58.042476 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 14:16:58.042604 DEBUG [src/bin.rs:890] Config ready
2022-05-13 14:16:58.043217 DEBUG [src/bin.rs:213] Using channels [true, true]
2022-05-13 14:16:58.043520 DEBUG [src/alsadevice.rs:903] Buffer frames 32768
2022-05-13 14:16:58.043660 DEBUG [src/filters.rs:450] Build new pipeline
2022-05-13 14:16:58.043827 DEBUG [src/processing.rs:19] build filters, waiting to start processing loop
2022-05-13 14:16:58.043976 DEBUG [src/bin.rs:323] Playback thread ready to start
2022-05-13 14:16:58.044129 DEBUG [src/alsadevice.rs:918] Creating resampler
2022-05-13 14:16:58.088961 DEBUG [src/alsadevice.rs:406] Capture: supported channels, min: 2, max: 2, list: [2]
2022-05-13 14:16:58.089117 DEBUG [src/alsadevice.rs:407] Capture: setting channels to 2
2022-05-13 14:16:58.089818 DEBUG [src/alsadevice.rs:411] Capture: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000, 352800, 384000, 705600, 768000])
2022-05-13 14:16:58.089952 DEBUG [src/alsadevice.rs:412] Capture: setting rate to 192000
2022-05-13 14:16:58.090266 DEBUG [src/alsadevice.rs:416] Capture: supported sample formats: [S32LE]
2022-05-13 14:16:58.090434 DEBUG [src/alsadevice.rs:417] Capture: setting format to S32LE
2022-05-13 14:16:58.587342 DEBUG [src/alsadevice.rs:448] Opening audio device "hw:CARD=XXXX" with parameters: HwParams { channels: Ok(2), rate: "Ok(192000) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(8192) frames", buffer_size: "Ok(65536) frames" }, SwParams(avail_min: Ok(8192) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(65536) frames)
2022-05-13 14:16:58.587555 DEBUG [src/alsadevice.rs:453] Audio device "hw:CARD=XXXX" successfully opened
2022-05-13 14:16:58.587735 DEBUG [src/bin.rs:333] Capture thread ready to start
2022-05-13 14:16:58.587870 DEBUG [src/bin.rs:336] Both capture and playback ready, release barrier
2022-05-13 14:16:58.588008 DEBUG [src/bin.rs:338] Supervisor loop starts now!
2022-05-13 14:16:58.588132 DEBUG [src/processing.rs:21] Processing loop starts now!
2022-05-13 14:16:58.588165 DEBUG [src/filedevice.rs:135] starting playback loop
2022-05-13 14:16:58.588223 DEBUG [src/alsadevice.rs:944] Starting captureloop
2022-05-13 14:16:58.589055 DEBUG [src/alsadevice.rs:244] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start

here's e45d230

➜  camilladsp test.yml -v
2022-05-13 14:17:41.807261 INFO [src/bin.rs:711] CamillaDSP version 1.0.0
2022-05-13 14:17:41.807463 INFO [src/bin.rs:712] Running on linux, arm
2022-05-13 14:17:41.807752 DEBUG [src/bin.rs:754] Read config file Some("test.yml")
2022-05-13 14:17:41.809257 DEBUG [src/bin.rs:773] Config is valid
2022-05-13 14:17:41.809440 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 14:17:41.809556 DEBUG [src/bin.rs:890] Config ready
2022-05-13 14:17:41.810363 DEBUG [src/bin.rs:213] Using channels [true, true]
2022-05-13 14:17:41.810440 DEBUG [src/filters.rs:450] Build new pipeline
2022-05-13 14:17:41.810617 DEBUG [src/processing.rs:19] build filters, waiting to start processing loop
2022-05-13 14:17:41.810703 DEBUG [src/alsadevice.rs:1097] Buffer frames 32768
2022-05-13 14:17:41.811182 DEBUG [src/bin.rs:323] Playback thread ready to start
2022-05-13 14:17:41.811300 DEBUG [src/alsadevice.rs:1113] Creating resampler
2022-05-13 14:17:41.856138 DEBUG [src/alsadevice.rs:431] Capture: supported channels, min: 2, max: 2, list: [2]
2022-05-13 14:17:41.856301 DEBUG [src/alsadevice.rs:432] Capture: setting channels to 2
2022-05-13 14:17:41.857043 DEBUG [src/alsadevice.rs:436] Capture: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000, 352800, 384000, 705600, 768000])
2022-05-13 14:17:41.857177 DEBUG [src/alsadevice.rs:437] Capture: setting rate to 192000
2022-05-13 14:17:41.857579 DEBUG [src/alsadevice.rs:441] Capture: supported sample formats: [S32LE]
2022-05-13 14:17:41.857716 DEBUG [src/alsadevice.rs:442] Capture: setting format to S32LE
2022-05-13 14:17:42.367038 DEBUG [src/alsadevice.rs:466] Opening audio device "hw:CARD=XXXX" with parameters: HwParams { channels: Ok(2), rate: "Ok(192000) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(1024) frames", buffer_size: "Ok(8192) frames" }, SwParams(avail_min: Ok(4096) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(8192) frames)
2022-05-13 14:17:42.367248 DEBUG [src/alsadevice.rs:471] Audio device "hw:CARD=XXXX" successfully opened
2022-05-13 14:17:42.367430 DEBUG [src/bin.rs:333] Capture thread ready to start
2022-05-13 14:17:42.367596 DEBUG [src/bin.rs:336] Both capture and playback ready, release barrier
2022-05-13 14:17:42.367769 DEBUG [src/processing.rs:21] Processing loop starts now!
2022-05-13 14:17:42.367921 DEBUG [src/filedevice.rs:135] starting playback loop
2022-05-13 14:17:42.367953 DEBUG [src/alsadevice.rs:1138] Starting captureloop
2022-05-13 14:17:42.368130 DEBUG [src/bin.rs:338] Supervisor loop starts now!
2022-05-13 14:17:42.368574 DEBUG [src/alsadevice.rs:255] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2022-05-13 14:17:42.412749 WARN [src/alsadevice.rs:273] Capture device failed while waiting for available frames, error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 14:17:42.413136 ERROR [src/bin.rs:362] Capture error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 14:17:42.413293 DEBUG [src/bin.rs:367] Wait for playback thread to exit..
2022-05-13 14:17:42.413798 DEBUG [src/bin.rs:915] Restarting with new config
2022-05-13 14:17:42.413931 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 14:17:42.414311 DEBUG [src/bin.rs:860] No config and not in wait mode, exiting!

here's 519956e

➜  camilladsp test.yml -v                                    
2022-05-13 14:23:24.844528 INFO [src/bin.rs:711] CamillaDSP version 1.0.0-rc2
2022-05-13 14:23:24.844698 INFO [src/bin.rs:712] Running on linux, arm
2022-05-13 14:23:24.845022 DEBUG [src/bin.rs:754] Read config file Some("test.yml")
2022-05-13 14:23:24.846503 DEBUG [src/bin.rs:773] Config is valid
2022-05-13 14:23:24.846659 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 14:23:24.846801 DEBUG [src/bin.rs:890] Config ready
2022-05-13 14:23:24.847529 DEBUG [src/bin.rs:213] Using channels [true, true]
2022-05-13 14:23:24.847810 DEBUG [src/alsadevice.rs:1051] Buffer frames 32768
2022-05-13 14:23:24.848013 DEBUG [src/filters.rs:450] Build new pipeline
2022-05-13 14:23:24.848178 DEBUG [src/bin.rs:323] Playback thread ready to start
2022-05-13 14:23:24.848265 DEBUG [src/alsadevice.rs:1067] Creating resampler
2022-05-13 14:23:24.854224 DEBUG [src/processing.rs:19] build filters, waiting to start processing loop
2022-05-13 14:23:24.986293 DEBUG [src/alsadevice.rs:418] Capture: supported channels, min: 2, max: 2, list: [2]
2022-05-13 14:23:24.986410 DEBUG [src/alsadevice.rs:419] Capture: setting channels to 2
2022-05-13 14:23:24.986701 DEBUG [src/alsadevice.rs:423] Capture: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000, 352800, 384000, 705600, 768000])
2022-05-13 14:23:24.986797 DEBUG [src/alsadevice.rs:424] Capture: setting rate to 192000
2022-05-13 14:23:24.986922 DEBUG [src/alsadevice.rs:428] Capture: supported sample formats: [S32LE]
2022-05-13 14:23:24.987013 DEBUG [src/alsadevice.rs:429] Capture: setting format to S32LE
2022-05-13 14:23:25.527039 DEBUG [src/alsadevice.rs:453] Opening audio device "hw:CARD=XXXX" with parameters: HwParams { channels: Ok(2), rate: "Ok(192000) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(1024) frames", buffer_size: "Ok(8192) frames" }, SwParams(avail_min: Ok(4096) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(8192) frames)
2022-05-13 14:23:25.527318 DEBUG [src/alsadevice.rs:458] Audio device "hw:CARD=XXXX" successfully opened
2022-05-13 14:23:25.527524 DEBUG [src/bin.rs:333] Capture thread ready to start
2022-05-13 14:23:25.527679 DEBUG [src/bin.rs:336] Both capture and playback ready, release barrier
2022-05-13 14:23:25.527835 DEBUG [src/bin.rs:338] Supervisor loop starts now!
2022-05-13 14:23:25.527863 DEBUG [src/filedevice.rs:130] starting playback loop
2022-05-13 14:23:25.527937 DEBUG [src/processing.rs:21] Processing loop starts now!
2022-05-13 14:23:25.528046 DEBUG [src/alsadevice.rs:1092] Starting captureloop
2022-05-13 14:23:25.528690 DEBUG [src/alsadevice.rs:245] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2022-05-13 14:23:25.572927 WARN [src/alsadevice.rs:263] Capture device failed while waiting for available frames, error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 14:23:25.573820 ERROR [src/bin.rs:362] Capture error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 14:23:25.573998 DEBUG [src/bin.rs:367] Wait for playback thread to exit..
2022-05-13 14:23:25.574182 DEBUG [src/bin.rs:915] Restarting with new config
2022-05-13 14:23:25.574330 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 14:23:25.574462 DEBUG [src/bin.rs:860] No config and not in wait mode, exiting!

@Wang-Yue
Copy link
Contributor Author

You don't really need gadget to repro the bug. any audio usb interface with inputs would do.

@HEnquist
Copy link
Owner

Thanks for all the details! This saves me a ton of investigation time.

@HEnquist HEnquist changed the title resampler does not work with gadgets Regression in next11: resampling does not work with alsa May 13, 2022
@pavhofman
Copy link
Contributor

EPIPE of snd_pcm_wait could be result of an xrun. Period 1024 at 192kHz is only 5ms, IMO quite susceptible to xruns. A debug with TRACE log would show the timing, the pcm_pcm_wait times etc. Thanks.

@Wang-Yue
Copy link
Contributor Author

Wang-Yue commented May 13, 2022

I believed I tried 10240 and it failed too. while trying 1024 with no src succeeds. lemme find my setup and get the log.

@Wang-Yue
Copy link
Contributor Author

➜  camilladsp cat test.yml 
---
devices:
  samplerate: 44100
  chunksize: 65536
  enable_resampling: true
  resampler_type: Synchronous
  capture_samplerate: 192000
  playback:
    type: File
    filename: "/dev/null"
    channels: 2
    format: S16LE
  capture:
    type: ALSA
    device: "hw:CARD=XXXX"
    channels: 2
    format: S32LE

➜  camilladsp ~/src/target/release/camilladsp test.yml -l trace
2022-05-13 16:04:35.371960 INFO [src/bin.rs:711] CamillaDSP version 1.0.0-rc2
2022-05-13 16:04:35.372104 INFO [src/bin.rs:712] Running on linux, arm
2022-05-13 16:04:35.372325 DEBUG [src/bin.rs:754] Read config file Some("test.yml")
2022-05-13 16:04:35.373369 DEBUG [src/bin.rs:773] Config is valid
2022-05-13 16:04:35.373494 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 16:04:35.373592 DEBUG [src/bin.rs:890] Config ready
2022-05-13 16:04:35.374152 DEBUG [src/bin.rs:213] Using channels [true, true]
2022-05-13 16:04:35.374381 DEBUG [src/alsadevice.rs:1051] Buffer frames 524288
2022-05-13 16:04:35.374378 DEBUG [src/filters.rs:450] Build new pipeline
2022-05-13 16:04:35.374503 DEBUG [src/processing.rs:19] build filters, waiting to start processing loop
2022-05-13 16:04:35.374829 DEBUG [src/alsadevice.rs:1067] Creating resampler
2022-05-13 16:04:35.375143 DEBUG [src/bin.rs:323] Playback thread ready to start
2022-05-13 16:04:35.557962 DEBUG [src/alsadevice.rs:418] Capture: supported channels, min: 2, max: 2, list: [2]
2022-05-13 16:04:35.558066 DEBUG [src/alsadevice.rs:419] Capture: setting channels to 2
2022-05-13 16:04:35.558438 DEBUG [src/alsadevice.rs:423] Capture: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000, 352800, 384000, 705600, 768000])
2022-05-13 16:04:35.558514 DEBUG [src/alsadevice.rs:424] Capture: setting rate to 192000
2022-05-13 16:04:35.558709 DEBUG [src/alsadevice.rs:428] Capture: supported sample formats: [S32LE]
2022-05-13 16:04:35.558787 DEBUG [src/alsadevice.rs:429] Capture: setting format to S32LE
2022-05-13 16:04:36.034854 DEBUG [src/alsadevice.rs:453] Opening audio device "hw:CARD=XXXX" with parameters: HwParams { channels: Ok(2), rate: "Ok(192000) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(16384) frames", buffer_size: "Ok(131072) frames" }, SwParams(avail_min: Ok(65536) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(131072) frames)
2022-05-13 16:04:36.034981 DEBUG [src/alsadevice.rs:458] Audio device "hw:CARD=XXXX" successfully opened
2022-05-13 16:04:36.035074 DEBUG [src/bin.rs:333] Capture thread ready to start
2022-05-13 16:04:36.035129 DEBUG [src/bin.rs:336] Both capture and playback ready, release barrier
2022-05-13 16:04:36.035229 DEBUG [src/bin.rs:338] Supervisor loop starts now!
2022-05-13 16:04:36.035254 DEBUG [src/processing.rs:21] Processing loop starts now!
2022-05-13 16:04:36.035309 DEBUG [src/filedevice.rs:130] starting playback loop
2022-05-13 16:04:36.035560 DEBUG [src/alsadevice.rs:1092] Starting captureloop
2022-05-13 16:04:36.035962 TRACE [src/alsadevice.rs:796] Updating capture bytes from 524288 to 2283520, and frames from 65536 to 285440
2022-05-13 16:04:36.036054 DEBUG [src/alsadevice.rs:245] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2022-05-13 16:04:36.720640 WARN [src/alsadevice.rs:263] Capture device failed while waiting for available frames, error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 16:04:36.721078 TRACE [src/processing.rs:34] AudioMessage::EndOfStream received
2022-05-13 16:04:36.721253 ERROR [src/bin.rs:362] Capture error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 16:04:36.724260 DEBUG [src/bin.rs:367] Wait for playback thread to exit..
2022-05-13 16:04:36.724486 TRACE [src/bin.rs:373] All threads stopped, returning
2022-05-13 16:04:36.724610 DEBUG [src/bin.rs:915] Restarting with new config
2022-05-13 16:04:36.724716 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 16:04:36.724814 DEBUG [src/bin.rs:860] No config and not in wait mode, exiting!

@pavhofman
Copy link
Contributor

Please post the trace log, not just debug. It shows the actual timing. Thanks

@Wang-Yue
Copy link
Contributor Author

I did run it with '-l trace', and you can find 'TRACE' in the logs...

@Wang-Yue
Copy link
Contributor Author

Wang-Yue commented May 13, 2022

If change trunk size to 2048. here's next11(519956e) 's log:

2022-05-13 16:19:23.430374 INFO [src/bin.rs:711] CamillaDSP version 1.0.0-rc2
2022-05-13 16:19:23.430562 INFO [src/bin.rs:712] Running on linux, arm
2022-05-13 16:19:23.430835 DEBUG [src/bin.rs:754] Read config file Some("test.yml")
2022-05-13 16:19:23.431902 DEBUG [src/bin.rs:773] Config is valid
2022-05-13 16:19:23.432064 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 16:19:23.432207 DEBUG [src/bin.rs:890] Config ready
2022-05-13 16:19:23.432831 DEBUG [src/bin.rs:213] Using channels [true, true]
2022-05-13 16:19:23.433073 DEBUG [src/alsadevice.rs:1051] Buffer frames 16384
2022-05-13 16:19:23.433070 DEBUG [src/filters.rs:450] Build new pipeline
2022-05-13 16:19:23.433529 DEBUG [src/alsadevice.rs:1067] Creating resampler
2022-05-13 16:19:23.433710 DEBUG [src/bin.rs:323] Playback thread ready to start
2022-05-13 16:19:23.434056 DEBUG [src/processing.rs:19] build filters, waiting to start processing loop
2022-05-13 16:19:23.467985 DEBUG [src/alsadevice.rs:418] Capture: supported channels, min: 2, max: 2, list: [2]
2022-05-13 16:19:23.468130 DEBUG [src/alsadevice.rs:419] Capture: setting channels to 2
2022-05-13 16:19:23.468490 DEBUG [src/alsadevice.rs:423] Capture: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000, 352800, 384000, 705600, 768000])
2022-05-13 16:19:23.468618 DEBUG [src/alsadevice.rs:424] Capture: setting rate to 192000
2022-05-13 16:19:23.468770 DEBUG [src/alsadevice.rs:428] Capture: supported sample formats: [S32LE]
2022-05-13 16:19:23.468883 DEBUG [src/alsadevice.rs:429] Capture: setting format to S32LE
2022-05-13 16:19:24.004830 DEBUG [src/alsadevice.rs:453] Opening audio device "hw:CARD=XXX" with parameters: HwParams { channels: Ok(2), rate: "Ok(192000) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(512) frames", buffer_size: "Ok(4096) frames" }, SwParams(avail_min: Ok(2048) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(4096) frames)
2022-05-13 16:19:24.005059 DEBUG [src/alsadevice.rs:458] Audio device "hw:CARD=XXX" successfully opened
2022-05-13 16:19:24.005273 DEBUG [src/bin.rs:333] Capture thread ready to start
2022-05-13 16:19:24.005402 DEBUG [src/bin.rs:336] Both capture and playback ready, release barrier
2022-05-13 16:19:24.005533 DEBUG [src/bin.rs:338] Supervisor loop starts now!
2022-05-13 16:19:24.005570 DEBUG [src/alsadevice.rs:1092] Starting captureloop
2022-05-13 16:19:24.005735 DEBUG [src/filedevice.rs:130] starting playback loop
2022-05-13 16:19:24.005940 DEBUG [src/processing.rs:21] Processing loop starts now!
2022-05-13 16:19:24.006227 TRACE [src/alsadevice.rs:796] Updating capture bytes from 16384 to 71680, and frames from 2048 to 8960
2022-05-13 16:19:24.006382 DEBUG [src/alsadevice.rs:245] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2022-05-13 16:19:24.029452 WARN [src/alsadevice.rs:263] Capture device failed while waiting for available frames, error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 16:19:24.029646 ERROR [src/bin.rs:362] Capture error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-13 16:19:24.029787 DEBUG [src/bin.rs:367] Wait for playback thread to exit..
2022-05-13 16:19:24.029965 TRACE [src/processing.rs:34] AudioMessage::EndOfStream received
2022-05-13 16:19:24.030464 TRACE [src/bin.rs:373] All threads stopped, returning
2022-05-13 16:19:24.030611 DEBUG [src/bin.rs:915] Restarting with new config
2022-05-13 16:19:24.030723 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 16:19:24.030840 DEBUG [src/bin.rs:860] No config and not in wait mode, exiting!

here's 1.0.0

 ./camilladsp test.yml -l trace                   
2022-05-13 16:20:53.504686 INFO [src/bin.rs:711] CamillaDSP version 1.0.0
2022-05-13 16:20:53.504877 INFO [src/bin.rs:712] Running on linux, arm
2022-05-13 16:20:53.505103 DEBUG [src/bin.rs:754] Read config file Some("test.yml")
2022-05-13 16:20:53.506107 DEBUG [src/bin.rs:773] Config is valid
2022-05-13 16:20:53.506269 DEBUG [src/bin.rs:857] Wait for config
2022-05-13 16:20:53.506412 DEBUG [src/bin.rs:890] Config ready
2022-05-13 16:20:53.507059 DEBUG [src/bin.rs:213] Using channels [true, true]
2022-05-13 16:20:53.507139 DEBUG [src/filters.rs:450] Build new pipeline
2022-05-13 16:20:53.507294 DEBUG [src/processing.rs:19] build filters, waiting to start processing loop
2022-05-13 16:20:53.507382 DEBUG [src/alsadevice.rs:903] Buffer frames 16384
2022-05-13 16:20:53.507751 DEBUG [src/bin.rs:323] Playback thread ready to start
2022-05-13 16:20:53.507812 DEBUG [src/alsadevice.rs:918] Creating resampler
2022-05-13 16:20:53.542447 DEBUG [src/alsadevice.rs:406] Capture: supported channels, min: 2, max: 2, list: [2]
2022-05-13 16:20:53.542594 DEBUG [src/alsadevice.rs:407] Capture: setting channels to 2
2022-05-13 16:20:53.542946 DEBUG [src/alsadevice.rs:411] Capture: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000, 352800, 384000, 705600, 768000])
2022-05-13 16:20:53.543067 DEBUG [src/alsadevice.rs:412] Capture: setting rate to 192000
2022-05-13 16:20:53.543217 DEBUG [src/alsadevice.rs:416] Capture: supported sample formats: [S32LE]
2022-05-13 16:20:53.543331 DEBUG [src/alsadevice.rs:417] Capture: setting format to S32LE
2022-05-13 16:20:54.035113 DEBUG [src/alsadevice.rs:448] Opening audio device "hw:CARD=XXX" with parameters: HwParams { channels: Ok(2), rate: "Ok(192000) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(4096) frames", buffer_size: "Ok(32768) frames" }, SwParams(avail_min: Ok(4096) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(32768) frames)
2022-05-13 16:20:54.035394 DEBUG [src/alsadevice.rs:453] Audio device "hw:CARD=XXX" successfully opened
2022-05-13 16:20:54.035785 DEBUG [src/bin.rs:333] Capture thread ready to start
2022-05-13 16:20:54.036223 DEBUG [src/bin.rs:336] Both capture and playback ready, release barrier
2022-05-13 16:20:54.036568 DEBUG [src/filedevice.rs:135] starting playback loop
2022-05-13 16:20:54.036649 DEBUG [src/bin.rs:338] Supervisor loop starts now!
2022-05-13 16:20:54.036859 DEBUG [src/alsadevice.rs:944] Starting captureloop
2022-05-13 16:20:54.042048 DEBUG [src/processing.rs:21] Processing loop starts now!
2022-05-13 16:20:54.042906 TRACE [src/alsadevice.rs:656] Updating capture bytes from 16384 to 71680, and frames from 2048 to 8960
2022-05-13 16:20:54.043365 DEBUG [src/alsadevice.rs:244] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2022-05-13 16:20:54.109850 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.118204 TRACE [src/filedevice.rs:163] Playback signal RMS: [-113.58461, -113.71522], peak: [-101.78752, -101.26918]
2022-05-13 16:20:54.151777 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.157584 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.32817, -112.3732], peak: [-102.05817, -101.44899]
2022-05-13 16:20:54.194781 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.200464 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.47594, -112.20241], peak: [-102.10235, -100.75134]
2022-05-13 16:20:54.237824 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.245066 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.33205, -112.10204], peak: [-102.15118, -100.755035]
2022-05-13 16:20:54.279824 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.287273 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.51126, -112.30585], peak: [-100.84634, -101.874886]
2022-05-13 16:20:54.343812 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.350248 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.2961, -112.411766], peak: [-101.67136, -100.15752]
2022-05-13 16:20:54.386810 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.393174 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.3833, -112.495186], peak: [-99.80754, -102.00473]
2022-05-13 16:20:54.429816 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.437049 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.1704, -112.207275], peak: [-101.629326, -100.66]
2022-05-13 16:20:54.471880 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.479089 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.34885, -111.98764], peak: [-101.698044, -101.49682]
2022-05-13 16:20:54.514844 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.522044 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.1911, -112.40241], peak: [-101.86578, -100.00716]
2022-05-13 16:20:54.578838 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.585260 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.61855, -112.004074], peak: [-102.436584, -101.15204]
2022-05-13 16:20:54.621837 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.628220 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.3631, -112.34534], peak: [-102.00723, -102.16185]
2022-05-13 16:20:54.663898 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.671098 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.33372, -112.33398], peak: [-101.45713, -102.039734]
2022-05-13 16:20:54.706872 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.714156 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.38232, -112.446625], peak: [-101.29948, -101.87903]
2022-05-13 16:20:54.749861 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.756286 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.40017, -111.97715], peak: [-101.619576, -101.00116]
2022-05-13 16:20:54.791858 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.798251 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.32849, -112.27702], peak: [-100.6931, -100.41904]
2022-05-13 16:20:54.855903 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.863156 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.23358, -112.0013], peak: [-101.281395, -101.067245]
2022-05-13 16:20:54.898907 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.906149 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.16653, -112.338806], peak: [-99.887115, -101.64914]
2022-05-13 16:20:54.941888 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.948263 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.08765, -112.38014], peak: [-100.591385, -102.384865]
2022-05-13 16:20:54.983911 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:54.990242 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.50946, -112.458374], peak: [-101.355965, -102.70947]
2022-05-13 16:20:55.026895 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.033234 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.44491, -112.452194], peak: [-100.41934, -102.22973]
2022-05-13 16:20:55.090986 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.091272 TRACE [src/alsadevice.rs:686] Measured sample rate is 188020.08419627504 Hz
2022-05-13 16:20:55.091389 TRACE [src/alsadevice.rs:716] Measured sample rate is 187996.90947653633 Hz
2022-05-13 16:20:55.098110 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.322525, -112.19947], peak: [-101.354294, -101.36231]
2022-05-13 16:20:55.133969 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.139918 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.44091, -112.40593], peak: [-100.806625, -101.379395]
2022-05-13 16:20:55.175911 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.181634 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.4329, -112.45472], peak: [-101.41025, -101.38879]
2022-05-13 16:20:55.218897 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.224658 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.34245, -112.30811], peak: [-99.54814, -101.218575]
2022-05-13 16:20:55.261922 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.268368 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.467995, -112.171364], peak: [-100.76523, -101.17089]
2022-05-13 16:20:55.325934 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.332337 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.27845, -112.46955], peak: [-100.546036, -100.56979]
2022-05-13 16:20:55.367949 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.375221 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.21177, -112.11822], peak: [-101.45489, -100.21554]
2022-05-13 16:20:55.410960 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.418264 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.37111, -112.251434], peak: [-100.97767, -101.83788]
2022-05-13 16:20:55.453985 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.461234 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.160934, -112.2749], peak: [-98.56059, -101.78949]
^C2022-05-13 16:20:55.495987 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.503271 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.48989, -112.3653], peak: [-101.27476, -101.632996]
2022-05-13 16:20:55.539085 TRACE [src/alsadevice.rs:254] Capture waited, ready
2022-05-13 16:20:55.543463 DEBUG [src/bin.rs:289] Exit requested...
2022-05-13 16:20:55.543613 TRACE [src/bin.rs:294] Wait for pb..
2022-05-13 16:20:55.546951 TRACE [src/filedevice.rs:163] Playback signal RMS: [-112.3889, -112.17415], peak: [-100.11974, -100.668365]
2022-05-13 16:20:55.547431 DEBUG [src/alsadevice.rs:614] Exit message received, sending EndOfStream
2022-05-13 16:20:55.547632 TRACE [src/processing.rs:34] AudioMessage::EndOfStream received
2022-05-13 16:20:55.548020 TRACE [src/bin.rs:296] Wait for cap..
2022-05-13 16:20:55.564937 TRACE [src/bin.rs:299] All threads stopped, exiting
2022-05-13 16:20:55.565075 DEBUG [src/bin.rs:909] Exiting

@HEnquist
Copy link
Owner

It looks like it fails on the first call to snd_pcm_wait. I'm guessing that something is wrong with the buffer size or threshold. Does it only happen with capture_samplerate > samplerate??

@pavhofman
Copy link
Contributor

I would suggest to add a patch for tracing the snd_pcm_wait timeout:

Index: src/alsadevice.rs
===================================================================
diff --git a/src/alsadevice.rs b/src/alsadevice.rs
--- a/src/alsadevice.rs	(revision c1329c076b73a26fa44a7b355b6cf5e6445d8c87)
+++ b/src/alsadevice.rs	(date 1652464356926)
@@ -18,7 +18,7 @@
 use std::sync::{Arc, Barrier, RwLock};
 use std::sync::mpsc::Receiver;
 use std::thread;
-use std::time::Duration;
+use std::time::{Duration, Instant};
 
 use crate::CommandMessage;
 use crate::PrcFmt;
@@ -173,10 +173,11 @@
     let frames_to_write = buffer.len() / bytes_per_frame;
     loop {
         let timeout_millis = (2.0 * millis_per_frame * frames_to_write as f32) as u32;
-        trace!("PB: pcmdevice.wait timeout is {} ms", timeout_millis);
+        trace!("PB: pcmdevice.wait with timeout {} ms", timeout_millis);
+        let start = if log_enabled!(log::Level::Trace) {Some(Instant::now())} else {None};
         match pcmdevice.wait(Some(timeout_millis)) {
             Ok(true) => {
-                trace!("PB: device waited, ready");
+                trace!("PB: device waited for {:?}, ready", start.map(|s| s.elapsed()));
             }
             Ok(false) => {
                 trace!("PB: Wait timed out, playback device takes too long to drain buffer");
@@ -251,9 +252,12 @@
     let millis_per_chunk = 1000 * frames_to_read / samplerate;
 
     loop {
-        match pcmdevice.wait(Some(2 * millis_per_chunk as u32)) {
+        let timeout_millis = 2 * millis_per_chunk as u32;
+        let start = if log_enabled!(log::Level::Trace) {Some(Instant::now())} else {None};
+        trace!("Capture pcmdevice.wait with timeout {} ms", timeout_millis);
+        match pcmdevice.wait(Some(timeout_millis)) {
             Ok(true) => {
-                trace!("Capture waited, ready");
+                trace!("Capture waited for {:?}, ready", start.map(|s| s.elapsed()));
             }
             Ok(false) => {
                 trace!("Wait timed out, capture device takes too long to capture frames");

@pavhofman
Copy link
Contributor

Maybe also tracing the buffer manager parameters at each capture/playback_buffer call:

Index: src/alsadevice.rs
===================================================================
diff --git a/src/alsadevice.rs b/src/alsadevice.rs
--- a/src/alsadevice.rs	(revision c1329c076b73a26fa44a7b355b6cf5e6445d8c87)
+++ b/src/alsadevice.rs	(date 1652466191495)
@@ -523,6 +523,7 @@
                     params.playback_status.write().unwrap().clipped_samples += conversion_result.1;
                 }
 
+                trace!("PB: {:?}", buf_manager);
                 let playback_res =
                     play_buffer(&buffer, pcmdevice, &io, millis_per_frame, params.bytes_per_frame, buf_manager);
                 device_stalled = match playback_res {
@@ -805,6 +806,7 @@
             // updating sw avail_min for snd_pcm_delay threshold
             update_avail_min(pcmdevice, new_capture_frames, buf_manager).unwrap_or(());
         }
+        trace!("Capture: {:?}", buf_manager);
         let capture_res = capture_buffer(
             &mut buffer[0..capture_bytes],
             pcmdevice,
@@ -1179,6 +1181,7 @@
     }
 }
 
+#[derive(Debug)]
 struct DeviceBufferData {
     bufsize: Frames,
     period: Frames,
@@ -1187,6 +1190,7 @@
     io_size: Frames,    /* size of read/write block */
 }
 
+#[derive(Debug)]
 struct CaptureBufferManager {
     data: DeviceBufferData,
 }
@@ -1219,6 +1223,7 @@
     }
 }
 
+#[derive(Debug)]
 struct PlaybackBufferManager {
     data: DeviceBufferData,
     target_level: Frames,

@Wang-Yue
Copy link
Contributor Author

Wang-Yue commented May 14, 2022

@HEnquist true. only happens when samplerate < capture sample rate

@pavhofman here's the log

➜  camilladsp ~/src/target/release/camilladsp test.yml -l trace
2022-05-14 01:56:44.191215 INFO [src/bin.rs:711] CamillaDSP version 1.0.0
2022-05-14 01:56:44.191381 INFO [src/bin.rs:712] Running on linux, arm
2022-05-14 01:56:44.191639 DEBUG [src/bin.rs:754] Read config file Some("test.yml")
2022-05-14 01:56:44.192821 DEBUG [src/bin.rs:773] Config is valid
2022-05-14 01:56:44.192967 DEBUG [src/bin.rs:857] Wait for config
2022-05-14 01:56:44.193089 DEBUG [src/bin.rs:890] Config ready
2022-05-14 01:56:44.193750 DEBUG [src/bin.rs:213] Using channels [true, true]
2022-05-14 01:56:44.193958 DEBUG [src/filters.rs:450] Build new pipeline
2022-05-14 01:56:44.194035 DEBUG [src/alsadevice.rs:1103] Buffer frames 16384
2022-05-14 01:56:44.194135 DEBUG [src/processing.rs:19] build filters, waiting to start processing loop
2022-05-14 01:56:44.194400 DEBUG [src/bin.rs:323] Playback thread ready to start
2022-05-14 01:56:44.194463 DEBUG [src/alsadevice.rs:1119] Creating resampler
2022-05-14 01:56:44.230968 DEBUG [src/alsadevice.rs:435] Capture: supported channels, min: 2, max: 2, list: [2]
2022-05-14 01:56:44.231082 DEBUG [src/alsadevice.rs:436] Capture: setting channels to 2
2022-05-14 01:56:44.231322 DEBUG [src/alsadevice.rs:440] Capture: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000, 352800, 384000, 705600, 768000])
2022-05-14 01:56:44.231406 DEBUG [src/alsadevice.rs:441] Capture: setting rate to 192000
2022-05-14 01:56:44.231511 DEBUG [src/alsadevice.rs:445] Capture: supported sample formats: [S32LE]
2022-05-14 01:56:44.231589 DEBUG [src/alsadevice.rs:446] Capture: setting format to S32LE
2022-05-14 01:56:44.765427 DEBUG [src/alsadevice.rs:470] Opening audio device "hw:CARD=XXX" with parameters: HwParams { channels: Ok(2), rate: "Ok(192000) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(512) frames", buffer_size: "Ok(4096) frames" }, SwParams(avail_min: Ok(2048) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(4096) frames)
2022-05-14 01:56:44.765640 DEBUG [src/alsadevice.rs:475] Audio device "hw:CARD=XXX" successfully opened
2022-05-14 01:56:44.765816 DEBUG [src/bin.rs:333] Capture thread ready to start
2022-05-14 01:56:44.766214 DEBUG [src/bin.rs:336] Both capture and playback ready, release barrier
2022-05-14 01:56:44.766416 DEBUG [src/processing.rs:21] Processing loop starts now!
2022-05-14 01:56:44.766502 DEBUG [src/filedevice.rs:135] starting playback loop
2022-05-14 01:56:44.766557 DEBUG [src/bin.rs:338] Supervisor loop starts now!
2022-05-14 01:56:44.766608 DEBUG [src/alsadevice.rs:1144] Starting captureloop
2022-05-14 01:56:44.767224 TRACE [src/alsadevice.rs:831] Updating capture bytes from 16384 to 71680, and frames from 2048 to 8960
2022-05-14 01:56:44.767367 TRACE [src/alsadevice.rs:843] PB: CaptureBufferManager { data: DeviceBufferData { bufsize: 4096, period: 512, threshold: 0, avail_min: 8960, io_size: 8960 } }
2022-05-14 01:56:44.767501 DEBUG [src/alsadevice.rs:256] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2022-05-14 01:56:44.767893 TRACE [src/alsadevice.rs:267] Capture pcmdevice.wait with timeout 92 ms
2022-05-14 01:56:44.790996 WARN [src/alsadevice.rs:277] Capture device failed while waiting for available frames, error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-14 01:56:44.791198 TRACE [src/processing.rs:34] AudioMessage::EndOfStream received
2022-05-14 01:56:44.791229 ERROR [src/bin.rs:362] Capture error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-14 01:56:44.791553 DEBUG [src/bin.rs:367] Wait for playback thread to exit..
2022-05-14 01:56:44.791831 TRACE [src/bin.rs:373] All threads stopped, returning
2022-05-14 01:56:44.792127 DEBUG [src/bin.rs:915] Restarting with new config
2022-05-14 01:56:44.792432 DEBUG [src/bin.rs:857] Wait for config
2022-05-14 01:56:44.792685 DEBUG [src/bin.rs:860] No config and not in wait mode, exiting!

based on your patch

diff --git a/src/alsadevice.rs b/src/alsadevice.rs
index 127a2f3..3da268e 100644
--- a/src/alsadevice.rs
+++ b/src/alsadevice.rs
@@ -18,7 +18,7 @@ use std::sync::mpsc;
 use std::sync::mpsc::Receiver;
 use std::sync::{Arc, Barrier, RwLock};
 use std::thread;
-use std::time::Duration;
+use std::time::{Duration, Instant};
 
 use crate::CommandMessage;
 use crate::PrcFmt;
@@ -173,10 +173,11 @@ fn play_buffer(
     let frames_to_write = buffer.len() / bytes_per_frame;
     loop {
         let timeout_millis = (2.0 * millis_per_frame * frames_to_write as f32) as u32;
-        trace!("PB: pcmdevice.wait timeout is {} ms", timeout_millis);
+        trace!("PB: pcmdevice.wait with timeout {} ms", timeout_millis);
+        let start = if log_enabled!(log::Level::Trace) {Some(Instant::now())} else {None};
         match pcmdevice.wait(Some(timeout_millis)) {
             Ok(true) => {
-                trace!("PB: device waited, ready");
+                trace!("PB: device waited for {:?}, ready", start.map(|s| s.elapsed()));
             }
             Ok(false) => {
                 trace!("PB: Wait timed out, playback device takes too long to drain buffer");
@@ -261,9 +262,12 @@ fn capture_buffer(
     let millis_per_chunk = 1000 * frames_to_read / samplerate;
 
     loop {
-        match pcmdevice.wait(Some(2 * millis_per_chunk as u32)) {
+        let timeout_millis = 2 * millis_per_chunk as u32;
+        let start = if log_enabled!(log::Level::Trace) {Some(Instant::now())} else {None};
+        trace!("Capture pcmdevice.wait with timeout {} ms", timeout_millis);
+        match pcmdevice.wait(Some(timeout_millis)) {
             Ok(true) => {
-                trace!("Capture waited, ready");
+                trace!("Capture waited for {:?}, ready", start.map(|s| s.elapsed()));
             }
             Ok(false) => {
                 trace!("Wait timed out, capture device takes too long to capture frames");
@@ -537,6 +541,7 @@ fn playback_loop_bytes(
                     params.playback_status.write().unwrap().clipped_samples += conversion_result.1;
                 }
 
+                trace!("PB: {:?}", buf_manager);
                 let playback_res = play_buffer(
                     &buffer,
                     pcmdevice,
@@ -835,6 +840,7 @@ fn capture_loop_bytes(
             // updating sw avail_min for snd_pcm_delay threshold
             update_avail_min(pcmdevice, new_capture_frames, buf_manager).unwrap_or(());
         }
+        trace!("PB: {:?}", buf_manager);
         let capture_res = capture_buffer(
             &mut buffer[0..capture_bytes],
             pcmdevice,
@@ -1225,6 +1231,7 @@ trait DeviceBufferManager {
     }
 }
 
+#[derive(Debug)]
 struct DeviceBufferData {
     bufsize: Frames,
     period: Frames,
@@ -1233,6 +1240,7 @@ struct DeviceBufferData {
     io_size: Frames, /* size of read/write block */
 }
 
+#[derive(Debug)]
 struct CaptureBufferManager {
     data: DeviceBufferData,
 }
@@ -1265,6 +1273,7 @@ impl DeviceBufferManager for CaptureBufferManager {
     }
 }
 
+#[derive(Debug)]
 struct PlaybackBufferManager {
     data: DeviceBufferData,
     target_level: Frames,

rebased to e45d230

@pavhofman
Copy link
Contributor

pavhofman commented May 14, 2022

Thanks a lot.

IMO the problem is this:

2022-05-14 01:56:44.767224 TRACE [src/alsadevice.rs:831] Updating capture bytes from 16384 to 71680, and frames from 2048 to 8960
2022-05-14 01:56:44.767367 TRACE [src/alsadevice.rs:843] PB: CaptureBufferManager { data: DeviceBufferData { bufsize: 4096, period: 512, threshold: 0, avail_min: 8960, io_size: 8960 } }

The resampler radically changes the required capture_frames which gets outside of the pre-configured device parameters: device bufsize (calculated before the resampler kicks in) ends up lower than avail_min = io_size = capture bytes.

@HEnquist please do you see any way out of this? Maybe the resampler should be consulted prior to setting the device hw params.

Also I would suggest to include the two debug patches, I will send a PR.

@HEnquist
Copy link
Owner

This should be pretty easy to fix. There is already a calculation to give a suitable buffer size:

let buffer_frames = 2.0f32.powf(

In 1.0.0 this value is used by open_pcm to set the buffer, but not (yet) in next11. Instead it uses values from the Buffer manager that doesn't know about the resampling settings.

@HEnquist
Copy link
Owner

This simple fix seems to do the trick: b313257

@pavhofman
Copy link
Contributor

Thanks, it really looks like a regression bugfix, considering the DeviceBufferManager just consolidated all device-related data and did not introduce any new functionality.

@HEnquist
Copy link
Owner

@Wang-Yue can you check that it also works for you?

@Wang-Yue
Copy link
Contributor Author

It works for the above test config. however, it breaks the gadget code with no SRC

➜  camilladsp cat test.yml 
---
devices:
  samplerate: 44100
  chunksize: 2048
  capture:
    type: ALSA
    device: "gadget"
    channels: 2
    format: S32LE
  playback:
    type: ALSA
    channels: 2
    device: "hw:CARD=XXX"
    format: S32LE


➜  camilladsp camilladsp test.yml -l trace
2022-05-15 01:24:06.146337 INFO [src/bin.rs:711] CamillaDSP version 1.0.0
2022-05-15 01:24:06.146483 INFO [src/bin.rs:712] Running on linux, arm
2022-05-15 01:24:06.146710 DEBUG [src/bin.rs:754] Read config file Some("test.yml")
2022-05-15 01:24:06.147795 DEBUG [src/bin.rs:773] Config is valid
2022-05-15 01:24:06.147923 DEBUG [src/bin.rs:857] Wait for config
2022-05-15 01:24:06.148028 DEBUG [src/bin.rs:890] Config ready
2022-05-15 01:24:06.148598 DEBUG [src/bin.rs:213] Using channels [true, true]
2022-05-15 01:24:06.148847 DEBUG [src/alsadevice.rs:1114] Buffer frames 4096
2022-05-15 01:24:06.149286 DEBUG [src/filters.rs:450] Build new pipeline
2022-05-15 01:24:06.149648 DEBUG [src/processing.rs:19] build filters, waiting to start processing loop
2022-05-15 01:24:06.181366 DEBUG [src/alsadevice.rs:446] Playback: supported channels, min: 2, max: 2, list: [2]
2022-05-15 01:24:06.182184 DEBUG [src/alsadevice.rs:447] Playback: setting channels to 2
2022-05-15 01:24:06.182607 DEBUG [src/alsadevice.rs:451] Playback: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000, 352800, 384000, 705600, 768000])
2022-05-15 01:24:06.182740 DEBUG [src/alsadevice.rs:452] Playback: setting rate to 44100
2022-05-15 01:24:06.182902 DEBUG [src/alsadevice.rs:456] Playback: supported sample formats: [S32LE]
2022-05-15 01:24:06.183050 DEBUG [src/alsadevice.rs:457] Playback: setting format to S32LE
2022-05-15 01:24:06.183626 DEBUG [src/alsadevice.rs:446] Capture: supported channels, min: 2, max: 2, list: [2]
2022-05-15 01:24:06.183785 DEBUG [src/alsadevice.rs:447] Capture: setting channels to 2
2022-05-15 01:24:06.184210 DEBUG [src/alsadevice.rs:451] Capture: supported samplerates: Discrete([44100])
2022-05-15 01:24:06.184406 DEBUG [src/alsadevice.rs:481] Opening audio device "hw:CARD=XXX" with parameters: HwParams { channels: Ok(2), rate: "Ok(44100) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(512) frames", buffer_size: "Ok(4096) frames" }, SwParams(avail_min: Ok(2048) frames, start_threshold: Ok(1) frames, stop_threshold: Ok(4096) frames)
2022-05-15 01:24:06.184386 DEBUG [src/alsadevice.rs:452] Capture: setting rate to 44100
2022-05-15 01:24:06.184577 DEBUG [src/alsadevice.rs:486] Audio device "hw:CARD=XXX" successfully opened
2022-05-15 01:24:06.184739 DEBUG [src/bin.rs:323] Playback thread ready to start
2022-05-15 01:24:06.184950 DEBUG [src/alsadevice.rs:456] Capture: supported sample formats: [S32LE]
2022-05-15 01:24:06.185266 DEBUG [src/alsadevice.rs:457] Capture: setting format to S32LE
2022-05-15 01:24:06.185786 DEBUG [src/alsadevice.rs:481] Opening audio device "gadget" with parameters: HwParams { channels: Ok(2), rate: "Ok(44100) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(512) frames", buffer_size: "Ok(2048) frames" }, SwParams(avail_min: Ok(4096) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(2048) frames)
2022-05-15 01:24:06.185967 DEBUG [src/alsadevice.rs:486] Audio device "gadget" successfully opened
2022-05-15 01:24:06.186147 DEBUG [src/bin.rs:333] Capture thread ready to start
2022-05-15 01:24:06.186263 DEBUG [src/bin.rs:336] Both capture and playback ready, release barrier
2022-05-15 01:24:06.186394 DEBUG [src/bin.rs:338] Supervisor loop starts now!
2022-05-15 01:24:06.186454 DEBUG [src/alsadevice.rs:1155] Starting captureloop
2022-05-15 01:24:06.186673 DEBUG [src/alsadevice.rs:1053] Starting playback loop
2022-05-15 01:24:06.186685 DEBUG [src/processing.rs:21] Processing loop starts now!
2022-05-15 01:24:06.187828 INFO [src/alsadevice.rs:768] Capture device supports rate adjust
2022-05-15 01:24:06.191083 TRACE [src/alsadevice.rs:854] Capture: CaptureBufferManager { data: DeviceBufferData { bufsize: 2048, period: 512, threshold: 0, avail_min: 4096, io_size: 4096 } }
2022-05-15 01:24:06.191273 DEBUG [src/alsadevice.rs:263] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2022-05-15 01:24:06.191721 TRACE [src/alsadevice.rs:278] Capture pcmdevice.wait with timeout 92 ms
2022-05-15 01:24:06.240514 WARN [src/alsadevice.rs:288] Capture device failed while waiting for available frames, error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-15 01:24:06.240959 ERROR [src/bin.rs:362] Capture error: ALSA function 'snd_pcm_wait' failed with error 'EPIPE: Broken pipe'
2022-05-15 01:24:06.240958 TRACE [src/processing.rs:34] AudioMessage::EndOfStream received
2022-05-15 01:24:06.241432 DEBUG [src/bin.rs:367] Wait for playback thread to exit..
2022-05-15 01:24:06.242126 TRACE [src/bin.rs:373] All threads stopped, returning
2022-05-15 01:24:06.242232 DEBUG [src/bin.rs:915] Restarting with new config
2022-05-15 01:24:06.242308 DEBUG [src/bin.rs:857] Wait for config
2022-05-15 01:24:06.242383 DEBUG [src/bin.rs:860] No config and not in wait mode, exiting!

@HEnquist
Copy link
Owner

This looks very odd:

2022-05-15 01:24:06.185786 DEBUG [src/alsadevice.rs:481] Opening audio device "gadget" with parameters: HwParams { channels: Ok(2), rate: "Ok(44100) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(512) frames", buffer_size: "Ok(2048) frames" }, SwParams(avail_min: Ok(4096) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(2048) frames)

The avail_min should not be larger than the buffer_size. They should get the same value. It should have requested a buffer_size of 8192, but somehow got 2048 instead.

@pavhofman
Copy link
Contributor

pavhofman commented May 15, 2022

Max buffer size is defined in https://elixir.bootlin.com/linux/v5.18-rc6/source/drivers/usb/gadget/function/u_audio.c#L26 - 16 * 4k page = 64kB -> 8192 frames at 2ch/32bit. And indeed it is the case on my RPi4 aarch64 :

arecord -v --dump-hw-params -D hw:UAC2Gadget -c 2 -f S32_LE --buffer-size=8192 -r 44100 /dev/null
Recording WAVE '/dev/null' : Signed 32 bit Little Endian, Rate 44100 Hz, Stereo
HW Params of device "hw:UAC2Gadget":
--------------------
ACCESS:  MMAP_INTERLEAVED RW_INTERLEAVED
FORMAT:  S32_LE
SUBFORMAT:  STD
SAMPLE_BITS: 32
FRAME_BITS: 64
CHANNELS: 2
RATE: 44100
PERIOD_TIME: (1451 11610)
PERIOD_SIZE: [64 512]
PERIOD_BYTES: [512 4096]
PERIODS: [4 16]
BUFFER_TIME: (5804 185760)
BUFFER_SIZE: [256 8192]
BUFFER_BYTES: [2048 65536]
TICK_TIME: ALL
--------------------
Hardware PCM card 3 'UAC2_Gadget' device 0 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S32_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 32
  buffer_size  : 8192
  period_size  : 512
  period_time  : 11609
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 512
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 8192
  silence_threshold: 0
  silence_size : 0
  boundary     : 4611686018427387904
  appl_ptr     : 0
  hw_ptr       : 0

@Wang-Yue What BUFFER_SIZE range does your arecord --dump-hw-params report?

@HEnquist Still I am afraid we cannot assume that soundcard will use whatever buffer size we request. That's why the set_xxx_near versions are being called. The code should respect the actual buffer_size value. It may have an impact on chunksize (chunksize = actual buffer_size /4). Also io_size (and subsequenty avail_min) should be adjusted AFTER the actual buffer_size is determined by the soundcard, probably directly in DeviceBufferManager::apply_buffer_size. Maybe the io_size param in the DeviceBufferManager constructor is wrong, and io_size/avail_min should be set in apply_buffer_size. Maybe the method apply_buffer_size should be renamed to sth like init_buffer_period(hw_params, requested io_size=chunksize (playback)/buffer_frames (capture)) which would:

  • ask the soundcard to set the actual buffer size based on 2 x io_size (being method param)
  • update io_size, avail_min based on the actual buffer size
  • set/apply period
  • return - new io_size = chunksize (playback)/buffer_frames (capture)

My intention is to keep all actual device parameters and their calculations within the DeviceBufferManager objects so that they are not spread throughout the calling code and values can be monitored and calculations modified easily.

@Wang-Yue
Copy link
Contributor Author

Wang-Yue commented May 15, 2022

@pavhofman I think we found out the cause: on my rpi4 the BUFFER_SIZE is correct for hw:UAC2Gadget (8192) but wrong for dsnoop (2048). here the gadget is a dsnoop slave created for hw:UAC2Gadget (see the end of the comment for asoundrc)

 arecord -v --dump-hw-params -D gadget -c 2 -f S32_LE --buffer-size=8192 -r 44100 /dev/null
Recording WAVE '/dev/null' : Signed 32 bit Little Endian, Rate 44100 Hz, Stereo
HW Params of device "gadget":
--------------------
ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED RW_INTERLEAVED RW_NONINTERLEAVED
FORMAT:  S32_LE
SUBFORMAT:  STD
SAMPLE_BITS: 32
FRAME_BITS: 64
CHANNELS: 2
RATE: 192000
PERIOD_TIME: (2666 2667)
PERIOD_SIZE: 512
PERIOD_BYTES: 4096
PERIODS: [2 4]
BUFFER_TIME: (5333 10667)
BUFFER_SIZE: [1024 2048]
BUFFER_BYTES: [8192 16384]
TICK_TIME: ALL
--------------------
Warning: rate is not accurate (requested = 44100Hz, got = 192000Hz)
         please, try the plug plugin (-Dplug:gadget)
Direct Snoop PCM
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S32_LE
  subformat    : STD
  channels     : 2
  rate         : 192000
  exact rate   : 192000 (192000/1)
  msbits       : 32
  buffer_size  : 2048
  period_size  : 512
  period_time  : 2666
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 512
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 2048
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
Hardware PCM card 2 'UAC2_Gadget' device 0 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : MMAP_INTERLEAVED
  format       : S32_LE
  subformat    : STD
  channels     : 2
  rate         : 192000
  exact rate   : 192000 (192000/1)
  msbits       : 32
  buffer_size  : 2048
  period_size  : 512
  period_time  : 2666
  tstamp_mode  : ENABLE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 512
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 1073741824
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
^CAborted by signal Interrupt...
arecord: pcm_read:2145: read error: Interrupted system call
arecord -v --dump-hw-params -D hw:UAC2Gadget -c 2 -f S32_LE --buffer-size=8192 -r 44100 /dev/null

Recording WAVE '/dev/null' : Signed 32 bit Little Endian, Rate 44100 Hz, Stereo
HW Params of device "hw:UAC2Gadget":
--------------------
ACCESS:  MMAP_INTERLEAVED RW_INTERLEAVED
FORMAT:  S32_LE
SUBFORMAT:  STD
SAMPLE_BITS: 32
FRAME_BITS: 64
CHANNELS: 2
RATE: 44100
PERIOD_TIME: (1451 11610)
PERIOD_SIZE: [64 512]
PERIOD_BYTES: [512 4096]
PERIODS: [4 16]
BUFFER_TIME: (5804 185760)
BUFFER_SIZE: [256 8192]
BUFFER_BYTES: [2048 65536]
TICK_TIME: ALL
--------------------
Hardware PCM card 2 'UAC2_Gadget' device 0 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S32_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 32
  buffer_size  : 8192
  period_size  : 512
  period_time  : 11609
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 512
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 8192
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
^CAborted by signal Interrupt...
^C

I'm using 32bit raspbian.

uname -a
Linux rpi4 5.18.0-rc6-v7l+ #1 SMP Tue May 10 06:00:59 UTC 2022 armv7l GNU/Linux

here's the gadget setup:

 cat /etc/modprobe.d/usb_g_audio.conf
#load the USB audio gadget module with the following options
options g_audio c_srate=44100,48000,88200,96000,176400,192000,352800,384000,705600,768000 c_ssize=4 p_chmask=0 function_name="CamillaDSP"

here's the dsnoop setup:

cat /etc/asound.conf 
pcm.gadget {
    type dsnoop
    ipc_key 1201
    ipc_key_add_uid yes
    slave {
        pcm "hw:CARD=UAC2Gadget"
    }
}

@Wang-Yue
Copy link
Contributor Author

Wang-Yue commented May 15, 2022

@pavhofman

I tested the following config with camilladsp. using device hw:UAC2Gadget works but gadget doesn't work


cat test.yml 
---
devices:
  samplerate: 44100
  chunksize: 2048
  enable_rate_adjust: true
  capture:
    type: ALSA
    device: "gadget"    <- this doesn't work
    device: "hw:UAC2Gadget"   <- this works
    channels: 2
    format: S32LE
  playback:
    type: ALSA
    channels: 2
    device: "hw:CARD=XXX"
    format: S32LE

So how can I create the dsnoop device correctly? my asoundrc is in the end of the previous comment.

@pavhofman
Copy link
Contributor

You can try setting the buffer_size param in the slave config of https://www.alsa-project.org/alsa-doc/alsa-lib/pcm_plugins.html#pcm_plugins_dsnoop . Still the code should be able to self-adjust to the actual buffer size used, or maybe just fail with textual explanation.

@HEnquist
Copy link
Owner

Yes it needs to a bit more clever when setting up buffer size and avail_min etc. I started by just breaking the alsadevice into several files, it had gotten too long so this should make it easier to work with.
#205

@HEnquist
Copy link
Owner

@HEnquist
Copy link
Owner

How is the possible values of avail_min connected to buffer and period sizes? The alsa documentation isn't helping much.
I'm unsure of what to put here: https://github.com/HEnquist/camilladsp/blob/alsa_init_fix/src/alsadevice_buffermanager.rs#L37

@pavhofman
Copy link
Contributor

@HEnquist Thanks a lot for the changes. Splitting the long file is very useful indeed.

I am not sure about introducing the resampling ratio and the chunksize to the device manager, as it is not related to the device, and it would end up keeping it in two places, having to be updated etc. Or maybe I have missed something.

How about moving the buffer_frames calculation 80dbb76#diff-97d4c24d5bc14dadbff0f198ddabe43bb729daea8df2988266a047a0a4f680caL17 to a separate function, used by both the device manager and alsadevice.rs? IMO proper naming the function would explain a lot about the purpose of the calculation, especially if it's used on two places in the source.

IIUC this change 80dbb76#diff-97d4c24d5bc14dadbff0f198ddabe43bb729daea8df2988266a047a0a4f680caL22 changes the period size - originally it was io_size/4 which was bufsize/8, now it's bufsize/4 . Is that an intention?

Thanks!

@pavhofman
Copy link
Contributor

pavhofman commented May 16, 2022

How is the possible values of avail_min connected to buffer and period sizes?

IIUC at period-elapsed time the driver checks delay (i.e. buffer fill) and if bufsize - delay (i.e. the unfilled available part of the buffer) is larger than avail_min, it unblocks pcm_wait . IMO we want more periods to make the filling timing more granular.

CDSP_timing

@Wang-Yue
Copy link
Contributor Author

I am totally confused on how to set correct chunksize in the YML to make camilladsp able to run.

Suppose I have hw:UAC2Gadget, and a dsnoop device gadget. I want two or more camilladsp processes to capture from "gadget" and do processing. Referring to this (https://github.com/Wang-Yue/CamillaDSP-Monitor) project for instance, which has two processes running simultanousely: https://github.com/Wang-Yue/CamillaDSP-Monitor/blob/main/spectrum.yml#L3 and https://github.com/Wang-Yue/CamillaDSP-Monitor/blob/main/setting.yml#L4 .

let's say output device's sample rate is samplerate, and gadget's sample rate is capture_samplerate.
what's the chunk size to be used?

On Mac I just use 4096 and it works for all rates and devices, from 44.1khz to 768khz.

On Linux I run into all kinds of issues ... sometimes bufsize is < available min. sometimes it's larger than the upper boundary of BUFFER_SIZE. even if i tune /etc/asoundrc to make gadget having size of 262,144 it fails as well...

Is there a general rule to tune the chunksize depending on capture_samplerate and samplerate?

@HEnquist
Copy link
Owner

I made some updates to clean things up. I exposed the buffer size calculation as a function of the buffermanager trait, and use that in both places.
The change of period size wasn't intentional, I was trying to get the logic right first and didn't pay attention to the exact numbers.

@Wang-Yue things work a bit different in the Alsa and CoreAudio backends. In the CoreAudio device (and Wasapi), CamillaDSP doesn't change the device buffer and period sizes. Instead it uses what is given by the system, and buffers the data so it can be split into chunksize-sized chunks. The Alsa backend instead sets desired buffer and period sizes, and then reads/writes chunksize frames from/to the device. This means the device must support the selected chunksize. This hasn't really been a problem before, but I have never tried the dsnoop plugin.
When resampling is enabled, the effective chunksize used by the capture device is scaled by the resampling ratio. Let's say you resample 192kHz -> 48 kHz and run with a chunksize of 1024. Since 192/48 = 4, this means that the capture device runs with a larger chunksize of 4096.

@Wang-Yue
Copy link
Contributor Author

tried the latest alsa_init_fix. finally everything works, including gadgets and dsnoop.

@pavhofman
Copy link
Contributor

pavhofman commented May 17, 2022

@Wang-Yue Did you set the buffer_size param to your gadget device prior to the test?

@HEnquist Thanks for the changes!

https://github.com/HEnquist/camilladsp/blob/alsa_init_fix/src/alsadevice_buffermanager.rs#L58 - that looks like a reason to exit with error, IMO an io operation larger than bufsize cannot work by principle, IIUC.

https://github.com/HEnquist/camilladsp/blob/alsa_init_fix/src/alsadevice_buffermanager.rs#L53 + https://github.com/HEnquist/camilladsp/blob/alsa_init_fix/src/alsadevice_buffermanager.rs#L58 - since both the checks are against io_size, perhaps should the check be in update_io_size(requested io_size) instead of the subsequently called apply_avail_min?

https://github.com/HEnquist/camilladsp/blob/alsa_init_fix/src/alsadevice.rs#L1006 - could buf_manager.get_data().bufsize be called instead of the buffer_frames calculated in https://github.com/HEnquist/camilladsp/blob/alsa_init_fix/src/alsadevice.rs#L953 ? IMO allocating a buffer for io operations sized as the actual device bufsize makes sense. The final device bufsize can end up being larger than buffer_frames (xx_near call). The variable buffer_frames is not used anywhere else and could be removed alltogether then.

Thanks a lot for your great work.

@Wang-Yue
Copy link
Contributor Author

yes. i set it to 8192.

@HEnquist
Copy link
Owner

@pavhofman All good points! Thanks! I'll update the PR.

@HEnquist
Copy link
Owner

Updated!

https://github.com/HEnquist/camilladsp/blob/alsa_init_fix/src/alsadevice_buffermanager.rs#L53 + https://github.com/HEnquist/camilladsp/blob/alsa_init_fix/src/alsadevice_buffermanager.rs#L58 - since both the checks are against io_size, perhaps should the check be in update_io_size(requested io_size) instead of the subsequently called apply_avail_min?

I think it's better to keep the checks where they are. That way it also applies the checks when applying the avail_min during the device setup.

@pavhofman
Copy link
Contributor

You are right, let's keep the check in apply_avail_min. io_size is set in the device manager constructor too, not only in update_io_size() call. Moving the check to update_io_size() would be a bug. The check cannot be performed in the constructor because no period info is available at that moment. Thanks.

@HEnquist
Copy link
Owner

I think we are done with this one, closing!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working linux Only affects Linux
Projects
None yet
Development

No branches or pull requests

3 participants